puppetdb org.postgresql.util.PSQLException

[Fabio Sangiovanni]

Hi everybody, I'm incurring in an issue with puppetdb.
I keep on seeing this in /var/log/puppetdb/puppetdb.log:

2014-12-19 10:45:55,957 WARN  [c.p.jdbc] Caught exception. Last attempt, throwing exception.
2014-12-19 10:45:55,961 ERROR [c.p.p.command] [f74061b8-1350-4b9e-9b77-b52f6d919ef9] [replace facts] Retrying after attempt 9, due to: org.postgresql.util.PSQLException: This connection has been closed.
org.postgresql.util.PSQLException: This connection has been closed.
    at org.postgresql.jdbc2.AbstractJdbc2Connection.checkClosed(AbstractJdbc2Connection.java:822) ~[puppetdb.jar:na]
    at org.postgresql.jdbc2.AbstractJdbc2Connection.setAutoCommit(AbstractJdbc2Connection.java:769) ~[puppetdb.jar:na]
    at com.jolbox.bonecp.ConnectionHandle.setAutoCommit(ConnectionHandle.java:1063) ~[puppetdb.jar:na]
    at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:222) ~[na:na]
    at com.puppetlabs.jdbc$with_transacted_connection_fn$fn__6761$fn__6762.invoke(jdbc.clj:290) ~[na:na]
    at clojure.java.jdbc.internal$with_connection_STAR_.invoke(internal.clj:186) ~[na:na]
    at com.puppetlabs.jdbc$with_transacted_connection_fn$fn__6761.invoke(jdbc.clj:287) ~[na:na]
    at com.puppetlabs.jdbc$eval6739$retry_sql_STAR___6740$fn__6741$fn__6742.invoke(jdbc.clj:259) ~[na:na]
    at com.puppetlabs.jdbc$eval6739$retry_sql_STAR___6740$fn__6741.invoke(jdbc.clj:258) ~[na:na]
    at com.puppetlabs.jdbc$eval6739$retry_sql_STAR___6740.invoke(jdbc.clj:250) ~[na:na]
    at com.puppetlabs.jdbc$with_transacted_connection_fn.invoke(jdbc.clj:286) ~[na:na]
    at com.puppetlabs.puppetdb.command$eval11543$fn__11546.invoke(command.clj:379) ~[na:na]
    at clojure.lang.MultiFn.invoke(MultiFn.java:231) ~[puppetdb.jar:na]
    at com.puppetlabs.puppetdb.command$produce_message_handler$fn__11715.invoke(command.clj:647) ~[na:na]
    at com.puppetlabs.puppetdb.command$wrap_with_discard$fn__11664$fn__11668.invoke(command.clj:554) ~[na:na]
    at com.puppetlabs.puppetdb.command.proxy$java.lang.Object$Callable$7da976d4.call(Unknown Source) ~[na:na]
    at com.yammer.metrics.core.Timer.time(Timer.java:91) ~[puppetdb.jar:na]
    at com.puppetlabs.puppetdb.command$wrap_with_discard$fn__11664.invoke(command.clj:553) ~[na:na]
    at com.puppetlabs.puppetdb.command$wrap_with_exception_handling$fn__11649$fn__11650.invoke(command.clj:507) ~[na:na]
    at com.puppetlabs.puppetdb.command.proxy$java.lang.Object$Callable$7da976d4.call(Unknown Source) ~[na:na]
    at com.yammer.metrics.core.Timer.time(Timer.java:91) ~[puppetdb.jar:na]
    at com.puppetlabs.puppetdb.command$wrap_with_exception_handling$fn__11649.invoke(command.clj:506) ~[na:na]
    at com.puppetlabs.puppetdb.command$wrap_with_command_parser$fn__11659.invoke(command.clj:529) [na:na]
    at com.puppetlabs.puppetdb.command$wrap_with_meter$fn__11639.invoke(command.clj:467) [na:na]
    at com.puppetlabs.puppetdb.command$wrap_with_thread_name$fn__11673.invoke(command.clj:569) [na:na]
    at com.puppetlabs.mq$create_message_listener$reify__10820.onMessage(mq.clj:270) [na:na]
    at org.springframework.jms.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:560) [puppetdb.jar:na]
    at org.springframework.jms.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:498) [puppetdb.jar:na]
    at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:467) [puppetdb.jar:na]
    at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:325) [puppetdb.jar:na]
    at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:263) [puppetdb.jar:na]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058) [puppetdb.jar:na]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050) [puppetdb.jar:na]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947) [puppetdb.jar:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_71]


Some details about my setup:

- it's a single host installation on CentOS 6.5, along with puppet master (Passenger/Apache)

- puppetdb installation method: puppetdb module

- manifest applied to the puppetmaster host:
class mycompany::role::puppetmaster {

  class { 'puppetdb':
    listen_address       => '0.0.0.0',
    ssl_listen_address => '0.0.0.0',
  }
  class { 'puppetdb::master::config':
    puppet_service_name => 'httpd',
  }
}


- puppet versions:
# rpm -qa|grep puppet
puppet-server-3.7.3-1.el6.noarch
puppetdb-terminus-2.2.2-1.el6.noarch
puppet-3.7.3-1.el6.noarch
puppet-dashboard-1.2.23-1.el6.noarch
puppetlabs-release-6-11.noarch
puppetdb-2.2.2-1.el6.noarch

- postgresql
# rpm -qa|grep postgresql
postgresql-libs-8.4.20-1.el6_5.x86_64
postgresql-server-8.4.20-1.el6_5.x86_64
postgresql-8.4.20-1.el6_5.x86_64



The agents on all the client nodes are version 3.7.3; facter version 2.3.0.



Any clues?

Thank you very much!

[Fabio Sangiovanni]

Hi, any advice on this issue, please? I'm really stuck here... thanks!

On Friday, December 19, 2014 11:15:13 AM UTC+1, Fabio Sangiovanni wrote:

Hi everybody, I'm incurring in an issue with puppetdb.

[...]

[Wyatt Alt]

Hey Fabio,

Got a few questions:

Did you have PuppetDB running properly before you started seeing this
issue or are you still setting it up?

Does it persist after postgres and PuppetDB are restarted?

When you restart PDB and use it, does it immediately produce this error
or does it work for some time first? If it works for some time, is there
some event can can correlate the error to?

Is there anything in your postgres log that indicates why the connection
is being closed?

Finally, this could be your db connections timing out. Any chance you
see some improvement by setting conn-keep-alive to a small number like 1?

https://docs.puppetlabs.com/puppetdb/master/configure.html#conn-keep-alive

If none of that sheds light you can send me your postgres and PDB logs
and we can troubleshoot from there.

Wyatt

> --
> You received this message because you are subscribed to the Google
> Groups "Puppet Users" group.
> To unsubscribe from this group and stop receiving emails from it, send
> an email to puppet-users...@googlegroups.com
> <mailto:puppet-users...@googlegroups.com>.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/puppet-users/9a508d2b-babc-4839-8acf-d6120d5cca56%40googlegroups.com
> <https://groups.google.com/d/msgid/puppet-users/9a508d2b-babc-4839-8acf-d6120d5cca56%40googlegroups.com?utm_medium=email&utm_source=footer>.
> For more options, visit https://groups.google.com/d/optout.

[Fabio Sangiovanni]

On Monday, December 22, 2014 11:36:13 PM UTC+1, Wyatt Alt wrote:

Hey Fabio,

hi!

 

Got a few questions:

Did you have PuppetDB running properly before you started seeing this
issue or are you still setting it up?

Still setting the whole thing up.
 

Does it persist after postgres and PuppetDB are restarted?

Yes. I've also tried to move to postgresql 9.4, with no success.
 

When you restart PDB and use it, does it immediately produce this error
or does it work for some time first? If it works for some time, is there
some event can can correlate the error to?

It does work AND raise the exception in an interleaved manner: I see regular log entries and stack traces
like the one I posted. I tried to figure out what triggered the exeptions but really couldn't correlate anything
special to the issue.
 

Is there anything in your postgres log that indicates why the connection
is being closed?

Yes, actually: I get several messages like these in postgresql log a few seconds before puppetdb exception:

 LOG:  incomplete message from client

Finally, this could be your db connections timing out. Any chance you
see some improvement by setting conn-keep-alive to a small number like 1?

https://docs.puppetlabs.com/puppetdb/master/configure.html#conn-keep-alive

I'll try and let you know!

Further information that might be of some use:

- my single host configuration was inside an OpenVZ container - I wonder if this may have some weird interaction with postgres or the JVM...
- I've also tried with a two hosts configuration: puppet master + puppetdb in one OpenVZ container and postgresql in a Hyper-V VM -> same results as before

 

If none of that sheds light you can send me your postgres and PDB logs

and we can troubleshoot from there.

Wyatt

Thank you very much!

Fabio

> <mailto:puppet-users+unsub...@googlegroups.com>.