Jira (PDB-3273) Timeout during pull-changes sync test

Russell Mull (JIRA) Wed, 25 Jan 2017 13:25:25 -0800

Title: Message Title

Russell Mull created an issue

PDB-3273

Issue Type:	Bug
Assignee:	Unassigned
Created:	2017/01/25 1:23 PM
Priority:	Normal
Reporter:	Russell Mull

From the log:

11:30:19 lein test puppetlabs.pe-puppetdb-extensions.sync.pull-changes-test

11:31:55 =====v instance log: /tmp/pdb-suppressed1485372663593-1980528105.log

11:31:55 751935 [async-dispatch-5] INFO  p.t.s.webserver.jetty9-service - Initializing web server(s).

11:31:55 751945 [async-dispatch-5] WARN  p.pe-puppetdb-extensions.config - Allowing unsafe sync triggers

11:31:55 751945 [async-dispatch-5] WARN  p.pe-puppetdb-extensions.config - Allowing unsafe cleartext sync

11:31:55 751949 [async-dispatch-5] INFO  p.p.sync.pe-routing - Starting PuppetDB, entering maintenance mode

11:31:55 751953 [async-dispatch-5] INFO  p.t.services.status.status-service - Registering status callback function for puppetdb-status service

11:31:55 751953 [async-dispatch-5] INFO  p.t.s.webserver.jetty9-service - Starting web server(s).

11:31:55 751981 [async-dispatch-5] INFO  p.t.services.webserver.jetty9-core - Starting web server.

11:31:55 751982 [async-dispatch-5] INFO  org.eclipse.jetty.server.Server - jetty-9.2.10.v20150310

11:31:55 752012 [async-dispatch-5] INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.h.ContextHandler@5912b410{/metrics,null,AVAILABLE}

11:31:55 752012 [async-dispatch-5] INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.h.ContextHandler@43525510{/pdb,null,AVAILABLE}

11:31:55 752023 [async-dispatch-5] INFO  o.e.jetty.server.ServerConnector - Started ServerConnector@40001e45{HTTP/1.1}{localhost:38492}

11:31:55 752023 [async-dispatch-5] INFO  org.eclipse.jetty.server.Server - Started @803312ms

11:31:55 752024 [async-dispatch-5] INFO  puppetlabs.puppetdb.dashboard - Redirecting / to the PuppetDB dashboard

11:31:55 752026 [async-dispatch-5] INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.h.ContextHandler@47e31efa{/,null,AVAILABLE}

11:31:55 752026 [async-dispatch-5] INFO  p.t.services.status.status-service - Registering status callback function for status-service service

11:31:55 752027 [async-dispatch-5] INFO  p.t.services.status.status-service - Registering status service HTTP API at /status

11:31:55 752030 [async-dispatch-5] INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.h.ContextHandler@147953ce{/status,null,AVAILABLE}

11:31:55 752031 [async-dispatch-5] INFO  com.zaxxer.hikari.HikariDataSource - PDBWritePool - is starting.

11:31:55 752032 [async-dispatch-5] INFO  com.zaxxer.hikari.HikariDataSource - PDBReadPool - is starting.

11:31:55 752034 [async-dispatch-5] INFO  puppetlabs.puppetdb.cli.services - PuppetDB version 4.2.6-20170110_133808-g0ba07dd

11:31:55 752036 [async-dispatch-5] INFO  com.zaxxer.hikari.HikariDataSource - PDBMigrationsPool - is starting.

11:31:55 752099 [async-dispatch-5] INFO  puppetlabs.puppetdb.scf.migrate - There are no pending migrations

11:31:55 752117 [async-dispatch-5] INFO  puppetlabs.puppetdb.scf.migrate - Creating additional index `fact_paths_path_trgm`

11:31:55 752152 [async-dispatch-5] INFO  puppetlabs.puppetdb.scf.migrate - Creating additional index `fact_values_string_trgm`

11:31:55 752170 [async-dispatch-5] INFO  com.zaxxer.hikari.pool.HikariPool - PDBMigrationsPool - is closing down.

11:31:55 752181 [async-dispatch-5] INFO  puppetlabs.puppetdb.cli.services - Starting broker

11:31:55 752344 [async-dispatch-5] WARN  o.a.activemq.broker.BrokerService - Store limit is 102400 mb (current store usage is 0 mb). The data directory: /tmp/tu-tmpdir1485372661539-2908219707/mq/localhost/KahaDB only has 10006 mb of usable space. - resetting to maximum available disk space: 10006 mb

11:31:55 752344 [async-dispatch-5] WARN  o.a.activemq.broker.BrokerService - Temporary Store limit is 51200 mb (current store usage is 0 mb). The data directory: /tmp/tu-tmpdir1485372661539-2908219707/mq/localhost only has 10006 mb of usable space. - resetting to maximum available disk space: 10006 mb

11:31:55 752344 [async-dispatch-5] WARN  o.a.activemq.broker.BrokerService - Job Scheduler Store limit is 51200 mb, whilst the data directory: /tmp/tu-tmpdir1485372661539-2908219707/mq/localhost/scheduler only has 10006 mb of usable space - resetting to 10006 mb.

11:31:55 752354 [pool-224-thread-2] INFO  puppetlabs.puppetdb.cli.services - Starting sweep of stale reports (threshold: 14 days)

11:31:55 752390 [pool-224-thread-2] INFO  puppetlabs.puppetdb.cli.services - Finished sweep of stale reports (threshold: 14 days)

11:31:55 752390 [pool-224-thread-2] INFO  puppetlabs.puppetdb.cli.services - Starting database garbage collection

11:31:55 752418 [pool-224-thread-2] INFO  puppetlabs.puppetdb.cli.services - Finished database garbage collection

11:31:55 752430 [async-dispatch-5] WARN  p.p.sync.services - No remotes specified, sync disabled

11:31:55 752433 [async-dispatch-5] INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.h.ContextHandler@16016b7e{/stub,null,AVAILABLE}

11:31:55 752433 [async-dispatch-5] WARN  p.p.sync.services - No remotes specified, sync disabled

11:31:55 752434 [async-dispatch-5] INFO  p.p.sync.pe-routing - PuppetDB finished starting, disabling maintenance mode

11:31:55 755598 [command-proc-2634] INFO  puppetlabs.puppetdb.command - [e16fc79f-69fd-4329-9c60-15b0f9f38ba4] [replace facts] a.local

11:31:55 759417 [command-proc-2634] INFO  puppetlabs.puppetdb.command - [ed3c4787-a6a5-4ab9-a7c9-381c6834b437] [replace facts] b.local

11:31:55 763163 [command-proc-2634] INFO  puppetlabs.puppetdb.command - [f0843a0e-50c0-4e24-9e16-fcecb8bda551] [replace facts] c.local

11:31:55 771917 [command-proc-2636] INFO  puppetlabs.puppetdb.command - [250fe049-2965-4f0f-bfec-335362f2e723] [replace facts] d.local

11:31:55 783632 [command-proc-2636] INFO  puppetlabs.puppetdb.command - [362780a8-4e01-438b-841c-920ab8a7a7c2] [replace facts] e.local

11:31:55 786301 [command-proc-2636] INFO  puppetlabs.puppetdb.command - [44d37219-20cb-4c87-994f-b088bf164583] [replace facts] f.local

11:31:55 786397 [qtp275226671-2597] INFO  sync - Performing blocking sync with timeout of 15000.0 ms

11:31:55 786398 [async-dispatch-8] INFO  sync - syncing with http://localhost:38492/stub/pdb-x/query/v4

11:31:55 786399 [async-dispatch-8] INFO  sync -   syncing reports from http://localhost:38492/stub/pdb-x/query/v4/reports

11:31:55 786423 [async-dispatch-8] INFO  sync -   --> transferred reports (0) from http://localhost:38492/stub/pdb-x/query/v4/reports in 21 ms

11:31:55 786424 [async-dispatch-8] INFO  sync -   syncing factsets from http://localhost:38492/stub/pdb-x/query/v4/factsets

11:31:55 786517 [async-dispatch-8] INFO  sync -   --> transferred factsets (3) from http://localhost:38492/stub/pdb-x/query/v4/factsets in 92 ms

11:31:55 786519 [async-dispatch-8] INFO  sync -   syncing catalogs from http://localhost:38492/stub/pdb-x/query/v4/catalogs

11:31:55 786570 [async-dispatch-8] INFO  sync -   --> transferred catalogs (0) from http://localhost:38492/stub/pdb-x/query/v4/catalogs in 51 ms

11:31:55 786571 [async-dispatch-8] INFO  sync -   syncing nodes from http://localhost:38492/stub/pdb-x/query/v4/nodes

11:31:55 786629 [async-dispatch-8] INFO  sync -   --> transferred nodes (0) from http://localhost:38492/stub/pdb-x/query/v4/nodes in 59 ms

11:31:55 786630 [async-dispatch-8] INFO  sync - --> synced with http://localhost:38492/stub/pdb-x/query/v4

11:31:55 796633 [blocking-sync-1] INFO  puppetlabs.puppetdb.command - [56c8fc00-26d8-4792-abc4-d146afceafe7] [replace facts] a.local

11:31:55 796635 [blocking-sync-2] INFO  puppetlabs.puppetdb.command - [f4f0eb2c-e3c6-475f-94f9-fbc360c4c922] [replace facts] e.local

11:31:55 801508 [main] ERROR p.p.sync.sync-test-utils - Failed to perform blocking sync, response is:

11:31:55  {:opts

11:31:55  {:headers {"content-type" "application/json"},

11:31:55   :body

11:31:55   "{\"remote_host_path\":\"http://localhost:38492/stub/pdb-x/query/v4\"}",

11:31:55   :decompress-body true,

11:31:55   :as :text,

11:31:55   :url "http://localhost:38492/pdb/sync/v1/trigger-sync",

11:31:55   :method :post,

11:31:55   :query-params {"secondsToWaitForCompletion" "15"}},

11:31:55  :orig-content-encoding nil,

11:31:55  :status 503,

11:31:55  :headers

11:31:55  {"date" "Wed, 25 Jan 2017 19:31:38 GMT",

11:31:55   "content-type" "application/json; charset=utf-8",

11:31:55   "content-length" "24",

11:31:55   "server" "Jetty(9.2.10.v20150310)"},

11:31:55  :content-type

11:31:55  {:mime-type "application/json",

11:31:55   :charset #object[sun.nio.cs.UTF_8 0x64472ece "UTF-8"]},

11:31:55  :body "{\n  \"timed_out\" : true\n}"}

11:31:55

11:31:55 801509 [main] INFO  puppetlabs.trapperkeeper.internal - Beginning shutdown sequence

11:31:55 801523 [async-dispatch-40] INFO  puppetlabs.puppetdb.cli.services - Shutdown request received; puppetdb exiting.

11:31:55 801523 [async-dispatch-40] INFO  puppetlabs.puppetdb.cli.services - Shutting down the messsage queues.

11:31:55 801637 [async-dispatch-8] WARN  puppetlabs.puppetdb.threadpool - Threadpool not stopped after 5,000 milliseconds, forcibly shutting it down

11:31:55 801638 [async-dispatch-8] WARN  puppetlabs.puppetdb.threadpool - Threadpool forcibly shutdown

11:31:55 802135 [blocking-sync-1] INFO  puppetlabs.puppetdb.command - [75d83529-035b-4bb1-aecb-f26ae921f1b6] [replace facts] f.local

11:31:55 802239 [blocking-sync-1] ERROR puppetlabs.puppetdb.threadpool - Error processing command on thread blocking-sync-1

11:31:55 clojure.lang.ExceptionInfo: Output of update-for-command does not match schema: {:entity-status {:factsets {:phase missing-required-key}}}

11:31:55 	at puppetlabs.pe_puppetdb_extensions.sync.status$eval53970$update_for_command__53975.invoke(status.clj:46)

11:31:55 	at clojure.lang.Atom.swap(Atom.java:51)

11:31:55 	at clojure.core$swap_BANG_.invokeStatic(core.clj:2261)

11:31:55 	at clojure.core$swap_BANG_.invoke(core.clj:2253)

11:31:55 	at puppetlabs.pe_puppetdb_extensions.sync.services$blocking_sync$fn__54301$process_command_for_initial_sync__54304.invoke(services.clj:159)

11:31:55 	at puppetlabs.puppetdb.threadpool$dochan$fn__54151$fn__54152.invoke(threadpool.clj:117)

11:31:55 	at puppetlabs.puppetdb.threadpool$call_on_threadpool$fn__54146.invoke(threadpool.clj:95)

11:31:55 	at clojure.lang.AFn.run(AFn.java:22)

11:31:55 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

11:31:55 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

11:31:55 	at java.lang.Thread.run(Thread.java:745)

11:31:55 803995 [async-dispatch-40] INFO  com.zaxxer.hikari.pool.HikariPool - PDBWritePool - is closing down.

11:31:55 803998 [async-dispatch-40] INFO  com.zaxxer.hikari.pool.HikariPool - PDBReadPool - is closing down.

11:31:55 804004 [async-dispatch-40] INFO  p.t.s.webserver.jetty9-service - Shutting down web server(s).

11:31:55 804004 [async-dispatch-40] INFO  p.t.services.webserver.jetty9-core - Shutting down web server.

11:31:55 804005 [async-dispatch-40] INFO  o.e.jetty.server.ServerConnector - Stopped ServerConnector@40001e45{HTTP/1.1}{localhost:38492}

11:31:55 804005 [async-dispatch-40] INFO  o.e.j.server.handler.ContextHandler - Stopped o.e.j.s.h.ContextHandler@16016b7e{/stub,null,UNAVAILABLE}

11:31:55 804006 [async-dispatch-40] INFO  o.e.j.server.handler.ContextHandler - Stopped o.e.j.s.h.ContextHandler@147953ce{/status,null,UNAVAILABLE}

11:31:55 804006 [async-dispatch-40] INFO  o.e.j.server.handler.ContextHandler - Stopped o.e.j.s.h.ContextHandler@47e31efa{/,null,UNAVAILABLE}

11:31:55 804006 [async-dispatch-40] INFO  o.e.j.server.handler.ContextHandler - Stopped o.e.j.s.h.ContextHandler@43525510{/pdb,null,UNAVAILABLE}

11:31:55 804006 [async-dispatch-40] INFO  o.e.j.server.handler.ContextHandler - Stopped o.e.j.s.h.ContextHandler@5912b410{/metrics,null,UNAVAILABLE}

11:31:55 804007 [async-dispatch-40] INFO  p.t.services.webserver.jetty9-core - Web server shutdown

11:31:55 804008 [main] INFO  puppetlabs.trapperkeeper.internal - Finished shutdown sequence

11:31:55 =====^ instance log: /tmp/pdb-suppressed1485372663593-1980528105.log

Add Comment

This message was sent by Atlassian JIRA

--
You received this message because you are subscribed to the Google Groups "Puppet Bugs" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].
To post to this group, send email to [email protected].
Visit this group at https://groups.google.com/group/puppet-bugs.
For more options, visit https://groups.google.com/d/optout.

Jira (PDB-3273) Timeout during pull-changes sync test

Reply via email to