Yesterday I downgraded both puppet to 3.5.1 and pupetdb to 1.6.3, and the problem disappeared. Unfortunately this is production infrastructure and I don't have an ability to test it further :(
On May 21, 2014, at 11:54 PM, Ken Barber <[email protected]> wrote: > Phil and I have been conversing offline ... we found that downgrading > the terminus to 1.6.3 (not PuppetDB) fixes the issue. So far we can > see that a submission occurs but the server does not respond. This is > synonymous with a bad Content-Length, and certainly I'm able to > replicate this with some basic tests ... but we're still looking for > the ultimate cause of this. > > For now can everyone who is seeing this issue, try downgrading their > puppetdb-terminus package to 1.6.3, and see if it solves it? > > ken. > > On Wed, May 21, 2014 at 6:41 PM, Ken Barber <[email protected]> wrote: >> Phil, >> >> Do you happen to have a tcpdump I can look at, one where this problem >> is replicated? I know its SSL - but I'm primarily interested in seeing >> when (and _IF_) the network connection goes idle - so packet timing is >> more important to me then content. I'm trying to prove/disprove that >> idletimeout is doing the correct thing here or not. It could be that >> the idling is caused by something else, and the timeout is valid - or >> it could be that the idletimeout is not actually paying attention to >> traffic (which I can't prove locally at least for cleartext - it seems >> fine). >> >> There is also a chance the idling could be after traffic is submitted, >> which would make things even more interesting. Either way I'd like >> some external confirmation of this reported 'idling' and the best way >> is probably via tcpdump's. If we can prove the idle timeout is correct >> in its behaviour, we can stop looking at Jetty as the cause, which >> helps us a lot. >> >> If you want to chat I'm on Freenode in #puppet (ken_barber). >> >> My colleague in the meantime is trying to upgrade us to Jetty 9.1.5 >> (from 9.1.0), its a non-trivial upgrade though, which sucks when under >> duress. We're also looking at introducing the idle-timeout setting so >> we can play with that also, potentially as a work-around for now. >> >> ken. >> >> On Wed, May 21, 2014 at 5:29 PM, Ken Barber <[email protected]> wrote: >>> So one thing I'm sure about - is that there was no idle timeout >>> defined in 1.6.3 at all. I can connect idle for quite some time for >>> example. Its quite possible that there is another delay/lag somewhere >>> causing the connection to be idle in the first place - but with 1.6.3 >>> this would not have surfaced for example as a server error, because >>> there was no idle handling. >>> >>> ken. >>> >>> On Wed, May 21, 2014 at 5:01 PM, Phil Fenstermacher >>> <[email protected]> wrote: >>>> Running tcpdump filtering on port 8081 renders a pcap file of about ~350K. >>>> The template is only 20K, so large here is probably somewhat relative. >>>> >>>> Any other thoughts? >>>> >>>> Just for reference, I'm running the same version of Java as Sergey: >>>> java version "1.7.0_55" >>>> OpenJDK Runtime Environment (IcedTea 2.4.7) (7u55-2.4.7-1ubuntu1~0.12.04.2) >>>> OpenJDK 64-Bit Server VM (build 24.51-b03, mixed mode) >>>> >>>> >>>> >>>> On Wednesday, May 21, 2014 9:53:42 AM UTC-4, Ken Barber wrote: >>>>> >>>>> Catalogue size might be a factor, as templates get stored in the >>>>> catalogue. >>>>> >>>>> On Wed, May 21, 2014 at 2:45 PM, Phil Fenstermacher >>>>> <[email protected]> wrote: >>>>>> I encountered this same issue yesterday, and unfortunately haven't found >>>>>> a >>>>>> fix either. >>>>>> >>>>>> The error seems to be happening whenever I use the php::fpm::conf >>>>>> resource >>>>>> (with ensure => present) from https://forge.puppetlabs.com/thias/php. >>>>>> Removing that resource, or setting ensure to abset makes everything work >>>>>> fine. That resource is essentially only creating a file resource from a >>>>>> large template >>>>>> (https://github.com/thias/puppet-php/blob/master/manifests/fpm/conf.pp). >>>>>> >>>>>> I tried setting max-threads to 200 as well without any luck. >>>>>> >>>>>> On Tuesday, May 20, 2014 11:27:05 AM UTC-4, Sergey Arlashin wrote: >>>>>>> >>>>>>> Unfortunately setting max-threads to 200 did not help. >>>>>>> >>>>>>> # java -version >>>>>>> java version "1.7.0_55" >>>>>>> OpenJDK Runtime Environment (IcedTea 2.4.7) >>>>>>> (7u55-2.4.7-1ubuntu1~0.12.04.2) >>>>>>> OpenJDK 64-Bit Server VM (build 24.51-b03, mixed mode) >>>>>>> >>>>>>> # dpkg -l |grep -i java >>>>>>> ii ca-certificates-java 20110912ubuntu6 >>>>>>> Common CA certificates (JKS keystore) >>>>>>> ii java-common 0.43ubuntu2 >>>>>>> Base of all Java packages >>>>>>> ii libjs-jquery 1.7.1-1ubuntu1 >>>>>>> JavaScript library for dynamic web applications >>>>>>> ii openjdk-7-jre-headless 7u55-2.4.7-1ubuntu1~0.12.04.2 >>>>>>> OpenJDK Java runtime, using Hotspot JIT (headless) >>>>>>> ii tzdata-java 2014c-0ubuntu0.12.04 >>>>>>> time zone and daylight-saving time data for use by java runtimes >>>>>>> >>>>>>> >>>>>>> This is a fresh output in logs: >>>>>>> >>>>>>> 2014-05-20 15:21:52,331 INFO [p.t.s.w.jetty9-service] Initializing web >>>>>>> server. >>>>>>> 2014-05-20 15:21:52,403 INFO [p.t.s.w.jetty9-service] Starting web >>>>>>> server. >>>>>>> 2014-05-20 15:21:52,406 INFO [o.e.j.s.Server] jetty-9.1.z-SNAPSHOT >>>>>>> 2014-05-20 15:21:52,436 INFO [o.e.j.s.ServerConnector] Started >>>>>>> ServerConnector@2557ce03{HTTP/1.1}{localhost:8080} >>>>>>> 2014-05-20 15:21:52,504 INFO [o.e.j.s.ServerConnector] Started >>>>>>> ServerConnector@253e73c6{SSL-HTTP/1.1}{puppet.site:8081} >>>>>>> >>>>>>> 2014-05-20 15:21:52,563 INFO [c.p.p.c.services] PuppetDB version 2.0.0 >>>>>>> 2014-05-20 15:21:52,704 INFO [c.p.p.c.services] Starting broker >>>>>>> 2014-05-20 15:21:53,581 WARN [o.a.a.b.BrokerService] Store limit is >>>>>>> 100000 mb, whilst the data directory: >>>>>>> /var/lib/puppetdb/mq/localhost/KahaDB >>>>>>> only has 63697 mb of usable space >>>>>>> 2014-05-20 15:21:53,582 INFO [c.p.p.c.services] Starting 4 command >>>>>>> processor threads >>>>>>> 2014-05-20 15:21:53,602 INFO [c.p.p.c.services] Starting query server >>>>>>> 2014-05-20 15:21:53,605 WARN [o.e.j.s.h.ContextHandler] Empty >>>>>>> contextPath >>>>>>> 2014-05-20 15:21:53,617 INFO [o.e.j.s.h.ContextHandler] Started >>>>>>> o.e.j.s.h.ContextHandler@31771aa1{/,null,AVAILABLE} >>>>>>> 2014-05-20 15:21:53,643 INFO [c.p.p.c.services] Starting sweep of >>>>>>> stale >>>>>>> reports (threshold: 14 days) >>>>>>> 2014-05-20 15:21:53,667 INFO [c.p.p.c.services] Finished sweep of >>>>>>> stale >>>>>>> reports (threshold: 14 days) >>>>>>> 2014-05-20 15:21:53,667 INFO [c.p.p.c.services] Starting database >>>>>>> garbage >>>>>>> collection >>>>>>> 2014-05-20 15:21:53,698 INFO [c.p.p.c.services] Finished database >>>>>>> garbage >>>>>>> collection >>>>>>> 2014-05-20 15:22:05,832 INFO [c.p.p.command] >>>>>>> [ce2e1e6e-5bc8-4f0a-bb20-e1edd153038d] [replace facts] prod1.site >>>>>>> 2014-05-20 15:22:36,859 WARN [o.e.j.s.HttpChannel] >>>>>>> /v3/commands?checksum=7b886250b6f4ff03643ca1a82ff38476b015ec02 >>>>>>> java.io.IOException: java.util.concurrent.TimeoutException: Idle >>>>>>> timeout >>>>>>> expired: 30000/30000 ms >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.util.BlockingCallback.block(BlockingCallback.java:101) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.server.HttpInputOverHTTP.blockForContent(HttpInputOverHTTP.java:62) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> org.eclipse.jetty.server.HttpInput$1.waitForContent(HttpInput.java:392) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:161) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283) >>>>>>> ~[na:1.7.0_55] >>>>>>> at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325) >>>>>>> ~[na:1.7.0_55] >>>>>>> at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177) >>>>>>> ~[na:1.7.0_55] >>>>>>> at java.io.InputStreamReader.read(InputStreamReader.java:184) >>>>>>> ~[na:1.7.0_55] >>>>>>> at java.io.BufferedReader.fill(BufferedReader.java:154) >>>>>>> ~[na:1.7.0_55] >>>>>>> at java.io.BufferedReader.read(BufferedReader.java:175) >>>>>>> ~[na:1.7.0_55] >>>>>>> at clojure.core$slurp.doInvoke(core.clj:6396) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at clojure.lang.RestFn.invoke(RestFn.java:410) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at ring.util.request$eval10113$fn__10114.invoke(request.clj:30) >>>>>>> ~[na:na] >>>>>>> at clojure.lang.MultiFn.invoke(MultiFn.java:227) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.middleware$payload_to_body_string$fn__10429.invoke(middleware.clj:273) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.middleware$verify_content_type$fn__10379.invoke(middleware.clj:128) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> com.puppetlabs.puppetdb.http.v3$v3_app$fn__11827.invoke(v3.clj:23) >>>>>>> ~[na:na] >>>>>>> at com.puppetlabs.puppetdb.http.v3$v3_app.invoke(v3.clj:21) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.puppetdb.http.server$routes$fn__12370.invoke(server.clj:47) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> net.cgrand.moustache$alter_request$fn__10771.invoke(moustache.clj:54) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> com.puppetlabs.puppetdb.http.server$routes.invoke(server.clj:47) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> ring.middleware.resource$wrap_resource$fn__12339.invoke(resource.clj:24) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> ring.middleware.params$wrap_params$fn__10714.invoke(params.clj:58) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.middleware$wrap_with_authorization$fn__10346.invoke(middleware.clj:40) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.middleware$wrap_with_certificate_cn$fn__10350.invoke(middleware.clj:55) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.middleware$wrap_with_default_body$fn__10354.invoke(middleware.clj:62) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.middleware$wrap_with_metrics_STAR_$fn__10401$fn__10410.invoke(middleware.clj:207) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.utils.metrics$multitime_BANG__STAR_$fn__10068$fn__10069$fn__10070.invoke(metrics.clj:14) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.utils.metrics.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.utils.metrics$multitime_BANG__STAR_$fn__10068$fn__10069.invoke(metrics.clj:14) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.utils.metrics$multitime_BANG__STAR_$fn__10068$fn__10069$fn__10070.invoke(metrics.clj:14) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.utils.metrics.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.utils.metrics$multitime_BANG__STAR_$fn__10068$fn__10069.invoke(metrics.clj:14) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.utils.metrics$multitime_BANG__STAR_.invoke(metrics.clj:17) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.middleware$wrap_with_metrics_STAR_$fn__10401.invoke(middleware.clj:206) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.middleware$wrap_with_globals$fn__10358.invoke(middleware.clj:73) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> com.puppetlabs.middleware$wrap_with_debug_logging$fn__10342.invoke(middleware.clj:27) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> puppetlabs.trapperkeeper.services.webserver.jetty9_core$proxy_handler$fn__16765.invoke(jetty9_core.clj:66) >>>>>>> ~[na:na] >>>>>>> at >>>>>>> >>>>>>> puppetlabs.trapperkeeper.services.webserver.jetty9_core.proxy$org.eclipse.jetty.server.handler.AbstractHandler$ff19274a.handle(Unknown >>>>>>> Source) ~[na:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1112) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1048) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:199) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.servlets.gzip.GzipHandler.handle(GzipHandler.java:325) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at org.eclipse.jetty.server.Server.handle(Server.java:459) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:280) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:229) >>>>>>> [puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.io.AbstractConnection$1.run(AbstractConnection.java:505) >>>>>>> [puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:607) >>>>>>> [puppetdb.jar:na] >>>>>>> at >>>>>>> >>>>>>> org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:536) >>>>>>> [puppetdb.jar:na] >>>>>>> at java.lang.Thread.run(Thread.java:744) [na:1.7.0_55] >>>>>>> Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: >>>>>>> 30000/30000 ms >>>>>>> at >>>>>>> org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:153) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50) >>>>>>> ~[puppetdb.jar:na] >>>>>>> at >>>>>>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) >>>>>>> ~[na:1.7.0_55] >>>>>>> at java.util.concurrent.FutureTask.run(FutureTask.java:262) >>>>>>> ~[na:1.7.0_55] >>>>>>> at >>>>>>> >>>>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) >>>>>>> ~[na:1.7.0_55] >>>>>>> at >>>>>>> >>>>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) >>>>>>> ~[na:1.7.0_55] >>>>>>> at >>>>>>> >>>>>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) >>>>>>> ~[na:1.7.0_55] >>>>>>> at >>>>>>> >>>>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) >>>>>>> ~[na:1.7.0_55] >>>>>>> ... 1 common frames omitted >>>>>>> >>>>>>> >>>>>>> Also I noticed that it happens only to some particular hosts. Some of >>>>>>> our >>>>>>> puppet agents run without any problems. So may be this is a client >>>>>>> related >>>>>>> issue? >>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>>> On May 20, 2014, at 5:19 PM, Ken Barber <[email protected]> wrote: >>>>>>> >>>>>>>> Also ... I'd be curious to know what exact version of the JVM you are >>>>>>>> running. >>>>>>>> >>>>>>>> I'm cautious this is a jetty bug of some kind, perhaps we can ship a >>>>>>>> new Jar with a later version of Jetty to you and see if that helps. >>>>>>>> >>>>>>>> ken. >>>>>>>> >>>>>>>> On Tue, May 20, 2014 at 2:03 PM, Ken Barber <[email protected]> >>>>>>>> wrote: >>>>>>>>> We don't expose the idle timeout parameter for users to modify. >>>>>>>>> >>>>>>>>> I am curious though, what happens when you increase max-threads in >>>>>>>>> your jetty.ini to something like 200? >>>>>>>>> >>>>>>>>> ken. >>>>>>>>> >>>>>>>>> On Tue, May 20, 2014 at 12:41 PM, Sergey Arlashin >>>>>>>>> <[email protected]> wrote: >>>>>>>>>> Here is described >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> http://www.eclipse.org/jetty/documentation/current/configuring-connectors.html >>>>>>>>>> how idle timeout for jetty cat be configured . But I don't know how >>>>>>>>>> to >>>>>>>>>> apply >>>>>>>>>> this for puppetdb :( >>>>>>>>>> >>>>>>>>>> Does anybody have any ideas ? >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> On May 20, 2014, at 9:43 AM, Sergey Arlashin >>>>>>>>>> <[email protected]> >>>>>>>>>> wrote: >>>>>>>>>> >>>>>>>>>> 2014-05-20 05:34:36,684 INFO [c.p.p.command] >>>>>>>>>> [e806b0a2-7703-4a4a-8107-65cd2c0db9a8] [replace facts] prod1.site >>>>>>>>>> 2014-05-20 05:34:44,112 INFO [c.p.p.command] >>>>>>>>>> [e8cb3511-9734-4ba7-b040-96f663404c00] [replace facts] redmine.site >>>>>>>>>> 2014-05-20 05:34:45,387 INFO [c.p.p.command] >>>>>>>>>> [9026d779-3a43-4c06-a23d-aeefd4eb6e1f] [replace catalog] >>>>>>>>>> redmine.site >>>>>>>>>> 2014-05-20 05:34:47,487 INFO [c.p.p.command] >>>>>>>>>> [1234e95c-e254-4b1d-b46f-8ef5b07e9158] [replace facts] >>>>>>>>>> www-node1.site >>>>>>>>>> 2014-05-20 05:34:48,350 INFO [c.p.p.command] >>>>>>>>>> [56be0dc9-03b9-45b8-8b8a-527f1c25e057] [replace facts] dev01.site >>>>>>>>>> 2014-05-20 05:34:48,404 INFO [c.p.p.command] >>>>>>>>>> [17474841-6043-46cf-98a1-122f116d5cd6] [replace facts] parser1.site >>>>>>>>>> 2014-05-20 05:34:48,634 INFO [c.p.p.command] >>>>>>>>>> [44da2889-811f-4e80-8190-ad7313f0ca81] [replace facts] dev02.site >>>>>>>>>> 2014-05-20 05:34:48,942 INFO [c.p.p.command] >>>>>>>>>> [4080aa24-23c7-4f16-9011-2104a457e201] [replace catalog] >>>>>>>>>> www-node1.site >>>>>>>>>> 2014-05-20 05:34:51,429 INFO [c.p.p.command] >>>>>>>>>> [6b62c283-f306-44e7-8101-4948110e3d78] [replace catalog] dev01.site >>>>>>>>>> 2014-05-20 05:34:51,437 INFO [c.p.p.command] >>>>>>>>>> [55fb7348-3b36-4c5a-9265-61ca3c1f55c3] [replace catalog] dev02.site >>>>>>>>>> 2014-05-20 05:34:52,925 INFO [c.p.p.command] >>>>>>>>>> [9ace137e-f708-4656-829a-92de7722b388] [replace facts] >>>>>>>>>> lb-node1.site >>>>>>>>>> 2014-05-20 05:34:55,017 INFO [c.p.p.command] >>>>>>>>>> [0b6e6592-97f2-4b8a-8cc7-6d321793d2ed] [replace catalog] >>>>>>>>>> lb-node1.site >>>>>>>>>> 2014-05-20 05:34:58,285 INFO [c.p.p.command] >>>>>>>>>> [971285dd-b141-4f44-a6d0-375aa3af830a] [replace facts] >>>>>>>>>> lb-node2.site >>>>>>>>>> 2014-05-20 05:34:59,333 INFO [c.p.p.command] >>>>>>>>>> [3977fc34-aa41-43e7-8eb9-ef5398dc3567] [replace facts] >>>>>>>>>> www-node2.site >>>>>>>>>> 2014-05-20 05:35:01,625 INFO [c.p.p.command] >>>>>>>>>> [f095ef50-4b71-41d6-ba83-6dd4a0030fe2] [replace facts] parser2.site >>>>>>>>>> 2014-05-20 05:35:02,107 INFO [c.p.p.command] >>>>>>>>>> [539a78de-1743-4135-adeb-c5ed3b43cc24] [replace catalog] >>>>>>>>>> lb-node2.site >>>>>>>>>> 2014-05-20 05:35:02,379 INFO [c.p.p.command] >>>>>>>>>> [f4b7fc4d-cccd-4fb9-881e-da4007d57f6e] [replace facts] monitor.site >>>>>>>>>> 2014-05-20 05:35:03,945 INFO [c.p.p.command] >>>>>>>>>> [f49a6fcd-ca63-49eb-bbec-7712ba590675] [replace catalog] >>>>>>>>>> www-node2.site >>>>>>>>>> 2014-05-20 05:35:05,350 INFO [c.p.p.command] >>>>>>>>>> [6913aceb-0d60-4701-9d31-d84af8f92374] [replace facts] >>>>>>>>>> db-node1.site >>>>>>>>>> 2014-05-20 05:35:05,587 INFO [c.p.p.command] >>>>>>>>>> [bd9796df-e989-4788-addc-d31f2d2dda3a] [replace catalog] >>>>>>>>>> monitor.site >>>>>>>>>> 2014-05-20 05:35:05,848 INFO [c.p.p.command] >>>>>>>>>> [f9215b15-f646-403a-b4d3-21fd532e1c06] [replace facts] puppet.site >>>>>>>>>> 2014-05-20 05:35:05,871 INFO [c.p.p.command] >>>>>>>>>> [7820d545-1c5f-4b0f-a2e8-0dcbc12d4571] [replace facts] >>>>>>>>>> db-node2.site >>>>>>>>>> 2014-05-20 05:35:07,642 WARN [o.e.j.s.HttpChannel] >>>>>>>>>> /v3/commands?checksum=e51aa526e2236306cff22ef33c8cb4467166f9c0 >>>>>>>>>> java.io.IOException: java.util.concurrent.TimeoutException: Idle >>>>>>>>>> timeout >>>>>>>>>> expired: 30002/30000 ms >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.util.BlockingCallback.block(BlockingCallback.java:101) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.server.HttpInputOverHTTP.blockForContent(HttpInputOverHTTP.java:62) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.server.HttpInput$1.waitForContent(HttpInput.java:392) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:161) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at java.io.InputStreamReader.read(InputStreamReader.java:184) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at java.io.BufferedReader.fill(BufferedReader.java:154) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at java.io.BufferedReader.read(BufferedReader.java:175) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at clojure.core$slurp.doInvoke(core.clj:6396) ~[puppetdb.jar:na] >>>>>>>>>> at clojure.lang.RestFn.invoke(RestFn.java:410) ~[puppetdb.jar:na] >>>>>>>>>> at ring.util.request$eval10113$fn__10114.invoke(request.clj:30) >>>>>>>>>> ~[na:na] >>>>>>>>>> at clojure.lang.MultiFn.invoke(MultiFn.java:227) ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.middleware$payload_to_body_string$fn__10429.invoke(middleware.clj:273) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.middleware$verify_content_type$fn__10379.invoke(middleware.clj:128) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> com.puppetlabs.puppetdb.http.v3$v3_app$fn__11827.invoke(v3.clj:23) >>>>>>>>>> ~[na:na] >>>>>>>>>> at com.puppetlabs.puppetdb.http.v3$v3_app.invoke(v3.clj:21) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.puppetdb.http.server$routes$fn__12370.invoke(server.clj:47) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> net.cgrand.moustache$alter_request$fn__10771.invoke(moustache.clj:54) >>>>>>>>>> ~[na:na] >>>>>>>>>> at com.puppetlabs.puppetdb.http.server$routes.invoke(server.clj:47) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> ring.middleware.resource$wrap_resource$fn__12339.invoke(resource.clj:24) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> ring.middleware.params$wrap_params$fn__10714.invoke(params.clj:58) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.middleware$wrap_with_authorization$fn__10346.invoke(middleware.clj:40) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.middleware$wrap_with_certificate_cn$fn__10350.invoke(middleware.clj:55) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.middleware$wrap_with_default_body$fn__10354.invoke(middleware.clj:62) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.middleware$wrap_with_metrics_STAR_$fn__10401$fn__10410.invoke(middleware.clj:207) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.utils.metrics$multitime_BANG__STAR_$fn__10068$fn__10069$fn__10070.invoke(metrics.clj:14) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.utils.metrics.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.utils.metrics$multitime_BANG__STAR_$fn__10068$fn__10069.invoke(metrics.clj:14) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.utils.metrics$multitime_BANG__STAR_$fn__10068$fn__10069$fn__10070.invoke(metrics.clj:14) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.utils.metrics.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.utils.metrics$multitime_BANG__STAR_$fn__10068$fn__10069.invoke(metrics.clj:14) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> com.puppetlabs.utils.metrics$multitime_BANG__STAR_.invoke(metrics.clj:17) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.middleware$wrap_with_metrics_STAR_$fn__10401.invoke(middleware.clj:206) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.middleware$wrap_with_globals$fn__10358.invoke(middleware.clj:73) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> com.puppetlabs.middleware$wrap_with_debug_logging$fn__10342.invoke(middleware.clj:27) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> puppetlabs.trapperkeeper.services.webserver.jetty9_core$proxy_handler$fn__16765.invoke(jetty9_core.clj:66) >>>>>>>>>> ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> puppetlabs.trapperkeeper.services.webserver.jetty9_core.proxy$org.eclipse.jetty.server.handler.AbstractHandler$ff19274a.handle(Unknown >>>>>>>>>> Source) ~[na:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1112) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1048) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:199) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.servlets.gzip.GzipHandler.handle(GzipHandler.java:325) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at org.eclipse.jetty.server.Server.handle(Server.java:459) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:280) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:229) >>>>>>>>>> [puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.io.AbstractConnection$1.run(AbstractConnection.java:505) >>>>>>>>>> [puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:607) >>>>>>>>>> [puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:536) >>>>>>>>>> [puppetdb.jar:na] >>>>>>>>>> at java.lang.Thread.run(Thread.java:744) [na:1.7.0_55] >>>>>>>>>> Caused by: java.util.concurrent.TimeoutException: Idle timeout >>>>>>>>>> expired: >>>>>>>>>> 30002/30000 ms >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:153) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50) >>>>>>>>>> ~[puppetdb.jar:na] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at java.util.concurrent.FutureTask.run(FutureTask.java:262) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> at >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) >>>>>>>>>> ~[na:1.7.0_55] >>>>>>>>>> ... 1 common frames omitted >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> On May 20, 2014, at 9:38 AM, Spencer Krum <[email protected]> >>>>>>>>>> wrote: >>>>>>>>>> >>>>>>>>>> This looks like a puppetdb error. Can you check the PuppetDB logs >>>>>>>>>> and >>>>>>>>>> post >>>>>>>>>> any relevant errors? >>>>>>>>>> >>>>>>>>>> Thanks, >>>>>>>>>> Spencer >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> On Mon, May 19, 2014 at 10:02 PM, Sergey Arlashin >>>>>>>>>> <[email protected]> wrote: >>>>>>>>>>> >>>>>>>>>>> Hi! >>>>>>>>>>> >>>>>>>>>>> Every now and then I get the following error while running puppet >>>>>>>>>>> agent. >>>>>>>>>>> >>>>>>>>>>> Error: Could not retrieve catalog from remote server: Error 400 on >>>>>>>>>>> SERVER: >>>>>>>>>>> Failed to submit 'replace catalog' command for prod2.site to >>>>>>>>>>> PuppetDB >>>>>>>>>>> at >>>>>>>>>>> puppet.site:8081: [500 java.util.concurrent.TimeoutException: Idle >>>>>>>>>>> timeout >>>>>>>>>>> expired: 30000/30000 ms] <html><head><meta >>>>>>>>>>> http-equiv="Content-Type" >>>>>>>>>>> content="text/html;charset=ISO-8859-1"/><title>Error 500 >>>>>>>>>>> </title></head><body><h2>HTTP ERROR: 500</h2><p>Problem accessing >>>>>>>>>>> /v3/commands. Reason:<pre> >>>>>>>>>>> java.util.concurrent.TimeoutException: >>>>>>>>>>> Idle >>>>>>>>>>> timeout expired: 30000/30000 ms</pre></p><hr /><i><small>Powered >>>>>>>>>>> by >>>>>>>>>>> Jetty://</small></i></body></html> >>>>>>>>>>> >>>>>>>>>>> Does anybody know how I can get rid of this error? >>>>>>>>>>> >>>>>>>>>>> Thanks in advance! >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> -- >>>>>>>>>>> Best regards, >>>>>>>>>>> Sergey Arlashin >>>>>>>>>>> >>>>>>>>>>> -- >>>>>>>>>>> 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 [email protected]. >>>>>>>>>>> To view this discussion on the web visit >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> https://groups.google.com/d/msgid/puppet-users/8A2FC518-6B42-42D5-8524-12D39B94DBD4%40gmail.com. >>>>>>>>>>> For more options, visit https://groups.google.com/d/optout. >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> -- >>>>>>>>>> Spencer Krum >>>>>>>>>> (619)-980-7820 >>>>>>>>>> >>>>>>>>>> -- >>>>>>>>>> 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 [email protected]. >>>>>>>>>> To view this discussion on the web visit >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> https://groups.google.com/d/msgid/puppet-users/CADt6FWNbXASsOh6_hzcSQAeJjzu8cZYTPG4qkYxTBoe%2B6heLtw%40mail.gmail.com. >>>>>>>>>> For more options, visit https://groups.google.com/d/optout. >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> -- >>>>>>>>>> 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 [email protected]. >>>>>>>>>> To view this discussion on the web visit >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> https://groups.google.com/d/msgid/puppet-users/FFF9F6EE-8B3A-48E4-A78B-42932EF41A3B%40gmail.com. >>>>>>>>>> >>>>>>>>>> For more options, visit https://groups.google.com/d/optout. >>>>>>>> >>>>>>>> -- >>>>>>>> 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 [email protected]. >>>>>>>> To view this discussion on the web visit >>>>>>>> >>>>>>>> https://groups.google.com/d/msgid/puppet-users/CAE4bNT%3D0SGVVbO%2Bevm6f3HYBx0RZSZMdmW1UYALHc-6Xk1isqA%40mail.gmail.com. >>>>>>>> For more options, visit https://groups.google.com/d/optout. >>>>>>> >>>>>> -- >>>>>> 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 [email protected]. >>>>>> To view this discussion on the web visit >>>>>> >>>>>> https://groups.google.com/d/msgid/puppet-users/779715c6-471a-4540-b641-18900ec235d5%40googlegroups.com. >>>>>> >>>>>> For more options, visit https://groups.google.com/d/optout. >>>> >>>> -- >>>> 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 [email protected]. >>>> To view this discussion on the web visit >>>> https://groups.google.com/d/msgid/puppet-users/17ac6a1b-5803-4e7a-b2b5-1a5d43261802%40googlegroups.com. >>>> >>>> For more options, visit https://groups.google.com/d/optout. > > -- > 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 [email protected]. > To view this discussion on the web visit > https://groups.google.com/d/msgid/puppet-users/CAE4bNTk%3D4drjWmY_q_VxX%3DXLeXxU3Z3BJgPJSeeavMEHF7r13A%40mail.gmail.com. > For more options, visit https://groups.google.com/d/optout. -- 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 [email protected]. To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-users/4FE1FBB9-D7CC-4525-946B-2838A9EF1E3E%40gmail.com. For more options, visit https://groups.google.com/d/optout.
