Puppetserver crashes when using Code-Manager and file sync

[mike r]

env: PE2016.1, puppet 4.4.2 on Centos7x64 (VM), monolithic

PuppetMaster VM has 6GB of RAM with 4 CPUs

I recently setup and enabled Code Manager (Code Manager autoconfigure = True)

I am seeing lots of puppetserver crashes, cant startup my puppetserver due to java errors

[root@puppetmaster3 ~]# tail -f /var/log/puppetlabs/puppetserver/puppetserver.log

at clojure.lang.AFn.run(AFn.java:22) [puppet-server-release.jar:na]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]

at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]

2016-05-13 12:54:37,715 INFO  [main] [p.t.internal] Beginning shutdown sequence

2016-05-13 12:54:37,722 INFO  [async-dispatch-2] [p.e.s.j.pe-jruby-metrics-service] PE JRuby Metrics Service: stopping metrics sampler job

2016-05-13 12:54:37,731 INFO  [async-dispatch-2] [p.e.s.j.pe-jruby-metrics-service] PE JRuby Metrics Service: stopped metrics sampler job

2016-05-13 12:54:37,738 INFO  [async-dispatch-2] [p.e.s.f.file-sync-client-service] Stopping file sync client service

2016-05-13 13:24:20,006 INFO  [main] [o.e.j.u.log] Logging initialized @149083ms

2016-05-13 14:25:48,102 INFO  [main] [o.e.j.u.log] Logging initialized @71630ms

2016-05-13 14:26:01,476 INFO  [async-dispatch-2] [p.t.s.w.jetty9-service] Initializing web server(s).

2016-05-13 14:26:01,781 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-core] Initializing file sync server data dir: /opt/puppetlabs/server/data/puppetserver/filesync/storage

2016-05-13 14:26:01,817 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-core] Initializing Git repository at /opt/puppetlabs/server/data/puppetserver/filesync/storage/puppet-code.git

2016-05-13 14:26:02,117 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-service] File sync storage service mounting repositories at /file-sync-git

2016-05-13 14:26:03,455 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-service] Registering file sync storage HTTP API

2016-05-13 14:26:03,461 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for file-sync-storage-service service

2016-05-13 14:26:03,481 INFO  [async-dispatch-2] [p.c.services] Starting code-manager v1 API...

2016-05-13 14:26:03,520 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for code-manager-service service

2016-05-13 14:26:03,931 INFO  [async-dispatch-2] [p.c.config] Writing r10k config to "/opt/puppetlabs/server/data/code-manager/r10k.yaml"

2016-05-13 14:26:04,124 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for pe-puppet-profiler service

2016-05-13 14:26:04,178 INFO  [async-dispatch-2] [p.s.j.jruby-puppet-service] Initializing the JRuby service

2016-05-13 14:26:04,244 INFO  [async-dispatch-2] [p.s.p.puppet-admin-service] Starting Puppet Admin web app

2016-05-13 14:26:04,367 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-internal] Creating JRuby instance with id 1.

2016-05-13 14:26:32,728 WARN  [clojure-agent-send-pool-0] [puppet-server] Puppet Setting 'pluginsync' is deprecated.

   (at /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/defaults.rb:1623:in `handle')

2016-05-13 14:26:32,824 INFO  [clojure-agent-send-pool-0] [puppet-server] Puppet Puppet settings initialized; run mode: master

2016-05-13 14:26:36,743 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-agents] Finished creating JRubyPuppet instance 1 of 3

2016-05-13 14:26:36,744 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-internal] Creating JRuby instance with id 2.

2016-05-13 14:26:36,831 INFO  [async-dispatch-2] [p.s.c.puppet-server-config-core] Not overriding webserver settings with values from core Puppet

2016-05-13 14:26:36,872 INFO  [async-dispatch-2] [p.e.s.f.file-sync-client-service] Initializing file sync client service

2016-05-13 14:26:36,908 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for file-sync-client-service service

2016-05-13 14:26:36,922 INFO  [async-dispatch-2] [p.e.s.f.file-sync-client-service] Registering file sync client HTTP API

2016-05-13 14:26:38,560 ERROR [async-dispatch-2] [p.t.internal] Error during service init!!!

java.lang.NullPointerException: null

at org.eclipse.jgit.internal.storage.file.UnpackedObjectCache$Table.index(UnpackedObjectCache.java:146) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.UnpackedObjectCache$Table.contains(UnpackedObjectCache.java:109) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.UnpackedObjectCache.isUnpacked(UnpackedObjectCache.java:64) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openObject(ObjectDirectory.java:373) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.WindowCursor.open(WindowCursor.java:142) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.treewalk.CanonicalTreeParser.reset(CanonicalTreeParser.java:202) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.jgit_utils$eval31263$get_diff__31268$fn__31269.invoke(jgit_utils.clj:583) ~[na:na]

at puppetlabs.enterprise.jgit_utils$eval31263$get_diff__31268.invoke(jgit_utils.clj:577) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33128$dirty_submodules__33133$fn__33134$fn__33135.invoke(file_sync_client_core.clj:693) ~[na:na]

at clojure.core.protocols$iter_reduce.invoke(protocols.clj:49) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6512.invoke(protocols.clj:117) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6452$G__6447__6465.invoke(protocols.clj:13) ~[puppet-server-release.jar:na]

at clojure.core$reduce.invoke(core.clj:6519) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33128$dirty_submodules__33133$fn__33134.invoke(file_sync_client_core.clj:676) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33128$dirty_submodules__33133.invoke(file_sync_client_core.clj:668) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33157$live_dir_diff__33162$fn__33163.invoke(file_sync_client_core.clj:710) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33157$live_dir_diff__33162.invoke(file_sync_client_core.clj:701) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33181$live_dir_rev__33186$fn__33187.invoke(file_sync_client_core.clj:724) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33181$live_dir_rev__33186.invoke(file_sync_client_core.clj:718) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33748$get_live_dir_status__33753$fn__33754.invoke(file_sync_client_core.clj:1261) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33748$get_live_dir_status__33753.invoke(file_sync_client_core.clj:1249) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_service$reify__33985$service_fnk__5254__auto___positional$reify__34004.get_live_dir_status(file_sync_client_service.clj:101) ~[na:na]

at puppetlabs.enterprise.services.protocols.file_sync_client$eval33896$fn__33933$G__33884__33936.invoke(file_sync_client.clj:3) ~[na:na]

at puppetlabs.enterprise.services.protocols.file_sync_client$eval33896$fn__33933$G__33883__33940.invoke(file_sync_client.clj:3) ~[na:na]

at clojure.core$partial$fn__4527.invoke(core.clj:2493) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_service$reify__37962$service_fnk__5254__auto___positional$reify__37973$get_working_dir_commits__37974.invoke(file_sync_versioned_code_service.clj:33) ~[na:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_core$eval35420$live_dir_commits__35425$fn__35426$fn__35427.invoke(file_sync_versioned_code_core.clj:66) ~[na:na]

at clojure.core.protocols$iter_reduce.invoke(protocols.clj:49) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6510.invoke(protocols.clj:112) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6452$G__6447__6465.invoke(protocols.clj:13) ~[puppet-server-release.jar:na]

at clojure.core$reduce.invoke(core.clj:6519) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_core$eval35420$live_dir_commits__35425$fn__35426.invoke(file_sync_versioned_code_core.clj:64) ~[na:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_core$eval35420$live_dir_commits__35425.invoke(file_sync_versioned_code_core.clj:54) ~[na:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_service$reify__37962$service_fnk__5254__auto___positional$reify__37973.init(file_sync_versioned_code_service.clj:39) ~[na:na]

at puppetlabs.trapperkeeper.services$eval5060$fn__5061$G__5048__5064.invoke(services.clj:8) ~[na:na]

at puppetlabs.trapperkeeper.services$eval5060$fn__5061$G__5047__5068.invoke(services.clj:8) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13729$run_lifecycle_fn_BANG___13736$fn__13737.invoke(internal.clj:175) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13729$run_lifecycle_fn_BANG___13736.invoke(internal.clj:158) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13758$run_lifecycle_fns__13763$fn__13764.invoke(internal.clj:209) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13758$run_lifecycle_fns__13763.invoke(internal.clj:186) [na:na]

at puppetlabs.trapperkeeper.internal$eval14229$build_app_STAR___14238$fn$reify__14248.init(internal.clj:559) [na:na]

at puppetlabs.trapperkeeper.internal$eval14275$boot_services_for_app_STAR__STAR___14282$fn__14283$fn__14285.invoke(internal.clj:585) [na:na]

at puppetlabs.trapperkeeper.internal$eval14275$boot_services_for_app_STAR__STAR___14282$fn__14283.invoke(internal.clj:584) [na:na]

at puppetlabs.trapperkeeper.internal$eval14275$boot_services_for_app_STAR__STAR___14282.invoke(internal.clj:578) [na:na]

at clojure.core$partial$fn__4529.invoke(core.clj:2499) [puppet-server-release.jar:na]

at puppetlabs.trapperkeeper.internal$eval13797$initialize_lifecycle_worker__13808$fn__13809$fn__13896$state_machine__11795__auto____13897$fn__13899.invoke(internal.clj:226) [na:na]

at puppetlabs.trapperkeeper.internal$eval13797$initialize_lifecycle_worker__13808$fn__13809$fn__13896$state_machine__11795__auto____13897.invoke(internal.clj:226) [na:na]

at clojure.core.async.impl.ioc_macros$run_state_machine.invoke(ioc_macros.clj:1011) [na:na]

at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invoke(ioc_macros.clj:1015) [na:na]

at clojure.core.async$ioc_alts_BANG_$fn__11963.invoke(async.clj:378) [na:na]

at clojure.core.async$do_alts$fn__11909$fn__11912.invoke(async.clj:247) [na:na]

at clojure.core.async.impl.channels.ManyToManyChannel$fn__6730$fn__6731.invoke(channels.clj:95) [na:na]

at clojure.lang.AFn.run(AFn.java:22) [puppet-server-release.jar:na]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]

at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]

2016-05-13 14:26:38,620 INFO  [main] [p.t.internal] Beginning shutdown sequence

2016-05-13 14:26:38,685 INFO  [async-dispatch-3] [p.e.s.j.pe-jruby-metrics-service] PE JRuby Metrics Service: stopping metrics sampler job

2016-05-13 14:26:38,695 INFO  [async-dispatch-3] [p.e.s.j.pe-jruby-metrics-service] PE JRuby Metrics Service: stopped metrics sampler job

2016-05-13 14:26:38,706 INFO  [async-dispatch-3] [p.e.s.f.file-sync-client-service] Stopping file sync client service

2016-05-13 14:28:07,416 INFO  [main] [o.e.j.u.log] Logging initialized @79607ms

2016-05-13 14:28:26,144 INFO  [async-dispatch-2] [p.t.s.w.jetty9-service] Initializing web server(s).

2016-05-13 14:28:27,455 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-core] Initializing file sync server data dir: /opt/puppetlabs/server/data/puppetserver/filesync/storage

2016-05-13 14:28:27,505 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-core] Initializing Git repository at /opt/puppetlabs/server/data/puppetserver/filesync/storage/puppet-code.git

2016-05-13 14:28:28,096 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-service] File sync storage service mounting repositories at /file-sync-git

2016-05-13 14:28:30,332 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-service] Registering file sync storage HTTP API

2016-05-13 14:28:30,341 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for file-sync-storage-service service

2016-05-13 14:28:30,419 INFO  [async-dispatch-2] [p.c.services] Starting code-manager v1 API...

2016-05-13 14:28:30,447 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for code-manager-service service

2016-05-13 14:28:30,995 INFO  [async-dispatch-2] [p.c.config] Writing r10k config to "/opt/puppetlabs/server/data/code-manager/r10k.yaml"

2016-05-13 14:28:31,152 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for pe-puppet-profiler service

2016-05-13 14:28:31,200 INFO  [async-dispatch-2] [p.s.j.jruby-puppet-service] Initializing the JRuby service

2016-05-13 14:28:31,255 INFO  [async-dispatch-2] [p.s.p.puppet-admin-service] Starting Puppet Admin web app

2016-05-13 14:28:31,369 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-internal] Creating JRuby instance with id 1.

2016-05-13 14:29:06,232 INFO  [Thread-2] [p.t.internal] Shutting down due to JVM shutdown hook.

2016-05-13 14:29:06,278 INFO  [Thread-2] [p.t.internal] Beginning shutdown sequence

2016-05-13 14:29:17,206 WARN  [clojure-agent-send-pool-0] [puppet-server] Puppet Setting 'pluginsync' is deprecated.

   (at /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/defaults.rb:1623:in `handle')

2016-05-13 14:29:17,422 INFO  [clojure-agent-send-pool-0] [puppet-server] Puppet Puppet settings initialized; run mode: master

2016-05-13 14:29:23,211 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-agents] Finished creating JRubyPuppet instance 1 of 3

2016-05-13 14:29:23,260 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-internal] Creating JRuby instance with id 2.

2016-05-13 14:29:23,421 INFO  [async-dispatch-2] [p.s.c.puppet-server-config-core] Not overriding webserver settings with values from core Puppet

2016-05-13 14:29:23,482 INFO  [async-dispatch-2] [p.e.s.f.file-sync-client-service] Initializing file sync client service

2016-05-13 14:29:23,537 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for file-sync-client-service service

2016-05-13 14:29:23,576 INFO  [async-dispatch-2] [p.e.s.f.file-sync-client-service] Registering file sync client HTTP API

2016-05-13 14:29:24,922 ERROR [async-dispatch-2] [p.t.internal] Error during service init!!!

java.lang.NullPointerException: null

at org.eclipse.jgit.internal.storage.file.UnpackedObjectCache$Table.index(UnpackedObjectCache.java:146) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.UnpackedObjectCache$Table.contains(UnpackedObjectCache.java:109) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.UnpackedObjectCache.isUnpacked(UnpackedObjectCache.java:64) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openObject(ObjectDirectory.java:373) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.WindowCursor.open(WindowCursor.java:142) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.treewalk.CanonicalTreeParser.reset(CanonicalTreeParser.java:202) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.jgit_utils$eval31263$get_diff__31268$fn__31269.invoke(jgit_utils.clj:583) ~[na:na]

at puppetlabs.enterprise.jgit_utils$eval31263$get_diff__31268.invoke(jgit_utils.clj:577) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33128$dirty_submodules__33133$fn__33134$fn__33135.invoke(file_sync_client_core.clj:693) ~[na:na]

at clojure.core.protocols$iter_reduce.invoke(protocols.clj:49) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6512.invoke(protocols.clj:117) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6452$G__6447__6465.invoke(protocols.clj:13) ~[puppet-server-release.jar:na]

at clojure.core$reduce.invoke(core.clj:6519) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33128$dirty_submodules__33133$fn__33134.invoke(file_sync_client_core.clj:676) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33128$dirty_submodules__33133.invoke(file_sync_client_core.clj:668) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33157$live_dir_diff__33162$fn__33163.invoke(file_sync_client_core.clj:710) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33157$live_dir_diff__33162.invoke(file_sync_client_core.clj:701) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33181$live_dir_rev__33186$fn__33187.invoke(file_sync_client_core.clj:724) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33181$live_dir_rev__33186.invoke(file_sync_client_core.clj:718) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33748$get_live_dir_status__33753$fn__33754.invoke(file_sync_client_core.clj:1261) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33748$get_live_dir_status__33753.invoke(file_sync_client_core.clj:1249) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_service$reify__33985$service_fnk__5254__auto___positional$reify__34004.get_live_dir_status(file_sync_client_service.clj:101) ~[na:na]

at puppetlabs.enterprise.services.protocols.file_sync_client$eval33896$fn__33933$G__33884__33936.invoke(file_sync_client.clj:3) ~[na:na]

at puppetlabs.enterprise.services.protocols.file_sync_client$eval33896$fn__33933$G__33883__33940.invoke(file_sync_client.clj:3) ~[na:na]

at clojure.core$partial$fn__4527.invoke(core.clj:2493) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_service$reify__37962$service_fnk__5254__auto___positional$reify__37973$get_working_dir_commits__37974.invoke(file_sync_versioned_code_service.clj:33) ~[na:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_core$eval35420$live_dir_commits__35425$fn__35426$fn__35427.invoke(file_sync_versioned_code_core.clj:66) ~[na:na]

at clojure.core.protocols$iter_reduce.invoke(protocols.clj:49) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6510.invoke(protocols.clj:112) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6452$G__6447__6465.invoke(protocols.clj:13) ~[puppet-server-release.jar:na]

at clojure.core$reduce.invoke(core.clj:6519) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_core$eval35420$live_dir_commits__35425$fn__35426.invoke(file_sync_versioned_code_core.clj:64) ~[na:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_core$eval35420$live_dir_commits__35425.invoke(file_sync_versioned_code_core.clj:54) ~[na:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_service$reify__37962$service_fnk__5254__auto___positional$reify__37973.init(file_sync_versioned_code_service.clj:39) ~[na:na]

at puppetlabs.trapperkeeper.services$eval5060$fn__5061$G__5048__5064.invoke(services.clj:8) ~[na:na]

at puppetlabs.trapperkeeper.services$eval5060$fn__5061$G__5047__5068.invoke(services.clj:8) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13729$run_lifecycle_fn_BANG___13736$fn__13737.invoke(internal.clj:175) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13729$run_lifecycle_fn_BANG___13736.invoke(internal.clj:158) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13758$run_lifecycle_fns__13763$fn__13764.invoke(internal.clj:209) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13758$run_lifecycle_fns__13763.invoke(internal.clj:186) [na:na]

at puppetlabs.trapperkeeper.internal$eval14229$build_app_STAR___14238$fn$reify__14248.init(internal.clj:559) [na:na]

at puppetlabs.trapperkeeper.internal$eval14275$boot_services_for_app_STAR__STAR___14282$fn__14283$fn__14285.invoke(internal.clj:585) [na:na]

at puppetlabs.trapperkeeper.internal$eval14275$boot_services_for_app_STAR__STAR___14282$fn__14283.invoke(internal.clj:584) [na:na]

at puppetlabs.trapperkeeper.internal$eval14275$boot_services_for_app_STAR__STAR___14282.invoke(internal.clj:578) [na:na]

at clojure.core$partial$fn__4529.invoke(core.clj:2499) [puppet-server-release.jar:na]

at puppetlabs.trapperkeeper.internal$eval13797$initialize_lifecycle_worker__13808$fn__13809$fn__13896$state_machine__11795__auto____13897$fn__13899.invoke(internal.clj:226) [na:na]

at puppetlabs.trapperkeeper.internal$eval13797$initialize_lifecycle_worker__13808$fn__13809$fn__13896$state_machine__11795__auto____13897.invoke(internal.clj:226) [na:na]

at clojure.core.async.impl.ioc_macros$run_state_machine.invoke(ioc_macros.clj:1011) [na:na]

at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invoke(ioc_macros.clj:1015) [na:na]

at clojure.core.async$ioc_alts_BANG_$fn__11963.invoke(async.clj:378) [na:na]

at clojure.core.async$do_alts$fn__11909$fn__11912.invoke(async.clj:247) [na:na]

at clojure.core.async.impl.channels.ManyToManyChannel$fn__6730$fn__6731.invoke(channels.clj:95) [na:na]

at clojure.lang.AFn.run(AFn.java:22) [puppet-server-release.jar:na]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]

at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]

2016-05-13 14:29:25,042 INFO  [main] [p.t.internal] Beginning shutdown sequence

2016-05-13 14:29:25,110 INFO  [async-dispatch-2] [p.e.s.j.pe-jruby-metrics-service] PE JRuby Metrics Service: stopping metrics sampler job

2016-05-13 14:29:25,173 INFO  [async-dispatch-2] [p.e.s.j.pe-jruby-metrics-service] PE JRuby Metrics Service: stopped metrics sampler job

2016-05-13 14:29:25,178 INFO  [async-dispatch-2] [p.e.s.f.file-sync-client-service] Stopping file sync client service

2016-05-13 14:29:42,831 WARN  [clojure-agent-send-pool-0] [puppet-server] Puppet Setting 'pluginsync' is deprecated.

   (at /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/defaults.rb:1623:in `handle')

2016-05-13 14:29:42,924 INFO  [clojure-agent-send-pool-0] [puppet-server] Puppet Puppet settings initialized; run mode: master

2016-05-13 14:29:46,329 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-agents] Finished creating JRubyPuppet instance 2 of 3

2016-05-13 14:29:46,330 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-internal] Creating JRuby instance with id 3.

2016-05-13 14:30:01,036 WARN  [clojure-agent-send-pool-0] [puppet-server] Puppet Setting 'pluginsync' is deprecated.

   (at /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/defaults.rb:1623:in `handle')

2016-05-13 14:30:01,114 INFO  [clojure-agent-send-pool-0] [puppet-server] Puppet Puppet settings initialized; run mode: master

2016-05-13 14:32:10,539 INFO  [main] [o.e.j.u.log] Logging initialized @124204ms

2016-05-13 14:32:25,439 INFO  [async-dispatch-2] [p.t.s.w.jetty9-service] Initializing web server(s).

2016-05-13 14:32:25,865 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-core] Initializing file sync server data dir: /opt/puppetlabs/server/data/puppetserver/filesync/storage

2016-05-13 14:32:25,877 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-core] Initializing Git repository at /opt/puppetlabs/server/data/puppetserver/filesync/storage/puppet-code.git

2016-05-13 14:32:26,083 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-service] File sync storage service mounting repositories at /file-sync-git

2016-05-13 14:32:27,238 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-service] Registering file sync storage HTTP API

2016-05-13 14:32:27,244 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for file-sync-storage-service service

2016-05-13 14:32:27,263 INFO  [async-dispatch-2] [p.c.services] Starting code-manager v1 API...

2016-05-13 14:32:27,307 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for code-manager-service service

2016-05-13 14:32:27,733 INFO  [async-dispatch-2] [p.c.config] Writing r10k config to "/opt/puppetlabs/server/data/code-manager/r10k.yaml"

2016-05-13 14:32:27,926 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for pe-puppet-profiler service

2016-05-13 14:32:27,967 INFO  [async-dispatch-2] [p.s.j.jruby-puppet-service] Initializing the JRuby service

2016-05-13 14:32:28,047 INFO  [async-dispatch-2] [p.s.p.puppet-admin-service] Starting Puppet Admin web app

2016-05-13 14:32:28,188 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-internal] Creating JRuby instance with id 1.

2016-05-13 14:32:31,413 INFO  [Thread-2] [p.t.internal] Shutting down due to JVM shutdown hook.

2016-05-13 14:32:31,432 INFO  [Thread-2] [p.t.internal] Beginning shutdown sequence

2016-05-13 14:33:10,576 WARN  [clojure-agent-send-pool-0] [puppet-server] Puppet Setting 'pluginsync' is deprecated.

   (at /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/defaults.rb:1623:in `handle')

2016-05-13 14:33:10,773 INFO  [clojure-agent-send-pool-0] [puppet-server] Puppet Puppet settings initialized; run mode: master

2016-05-13 14:33:17,444 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-agents] Finished creating JRubyPuppet instance 1 of 3

2016-05-13 14:33:17,446 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-internal] Creating JRuby instance with id 2.

2016-05-13 14:33:17,594 INFO  [async-dispatch-2] [p.s.c.puppet-server-config-core] Not overriding webserver settings with values from core Puppet

2016-05-13 14:33:17,615 INFO  [async-dispatch-2] [p.e.s.f.file-sync-client-service] Initializing file sync client service

2016-05-13 14:33:17,652 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for file-sync-client-service service

2016-05-13 14:33:17,667 INFO  [async-dispatch-2] [p.e.s.f.file-sync-client-service] Registering file sync client HTTP API

2016-05-13 14:33:19,157 ERROR [async-dispatch-2] [p.t.internal] Error during service init!!!

java.lang.NullPointerException: null

at org.eclipse.jgit.internal.storage.file.UnpackedObjectCache$Table.index(UnpackedObjectCache.java:146) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.UnpackedObjectCache$Table.contains(UnpackedObjectCache.java:109) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.UnpackedObjectCache.isUnpacked(UnpackedObjectCache.java:64) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.ObjectDirectory.openObject(ObjectDirectory.java:373) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.internal.storage.file.WindowCursor.open(WindowCursor.java:142) ~[puppet-server-release.jar:na]

at org.eclipse.jgit.treewalk.CanonicalTreeParser.reset(CanonicalTreeParser.java:202) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.jgit_utils$eval31263$get_diff__31268$fn__31269.invoke(jgit_utils.clj:583) ~[na:na]

at puppetlabs.enterprise.jgit_utils$eval31263$get_diff__31268.invoke(jgit_utils.clj:577) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33128$dirty_submodules__33133$fn__33134$fn__33135.invoke(file_sync_client_core.clj:693) ~[na:na]

at clojure.core.protocols$iter_reduce.invoke(protocols.clj:49) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6512.invoke(protocols.clj:117) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6452$G__6447__6465.invoke(protocols.clj:13) ~[puppet-server-release.jar:na]

at clojure.core$reduce.invoke(core.clj:6519) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33128$dirty_submodules__33133$fn__33134.invoke(file_sync_client_core.clj:676) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33128$dirty_submodules__33133.invoke(file_sync_client_core.clj:668) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33157$live_dir_diff__33162$fn__33163.invoke(file_sync_client_core.clj:710) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33157$live_dir_diff__33162.invoke(file_sync_client_core.clj:701) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33181$live_dir_rev__33186$fn__33187.invoke(file_sync_client_core.clj:724) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33181$live_dir_rev__33186.invoke(file_sync_client_core.clj:718) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33748$get_live_dir_status__33753$fn__33754.invoke(file_sync_client_core.clj:1261) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_core$eval33748$get_live_dir_status__33753.invoke(file_sync_client_core.clj:1249) ~[na:na]

at puppetlabs.enterprise.services.file_sync_client.file_sync_client_service$reify__33985$service_fnk__5254__auto___positional$reify__34004.get_live_dir_status(file_sync_client_service.clj:101) ~[na:na]

at puppetlabs.enterprise.services.protocols.file_sync_client$eval33896$fn__33933$G__33884__33936.invoke(file_sync_client.clj:3) ~[na:na]

at puppetlabs.enterprise.services.protocols.file_sync_client$eval33896$fn__33933$G__33883__33940.invoke(file_sync_client.clj:3) ~[na:na]

at clojure.core$partial$fn__4527.invoke(core.clj:2493) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_service$reify__37962$service_fnk__5254__auto___positional$reify__37973$get_working_dir_commits__37974.invoke(file_sync_versioned_code_service.clj:33) ~[na:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_core$eval35420$live_dir_commits__35425$fn__35426$fn__35427.invoke(file_sync_versioned_code_core.clj:66) ~[na:na]

at clojure.core.protocols$iter_reduce.invoke(protocols.clj:49) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6510.invoke(protocols.clj:112) ~[puppet-server-release.jar:na]

at clojure.core.protocols$fn__6452$G__6447__6465.invoke(protocols.clj:13) ~[puppet-server-release.jar:na]

at clojure.core$reduce.invoke(core.clj:6519) ~[puppet-server-release.jar:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_core$eval35420$live_dir_commits__35425$fn__35426.invoke(file_sync_versioned_code_core.clj:64) ~[na:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_core$eval35420$live_dir_commits__35425.invoke(file_sync_versioned_code_core.clj:54) ~[na:na]

at puppetlabs.enterprise.services.file_sync.file_sync_versioned_code_service$reify__37962$service_fnk__5254__auto___positional$reify__37973.init(file_sync_versioned_code_service.clj:39) ~[na:na]

at puppetlabs.trapperkeeper.services$eval5060$fn__5061$G__5048__5064.invoke(services.clj:8) ~[na:na]

at puppetlabs.trapperkeeper.services$eval5060$fn__5061$G__5047__5068.invoke(services.clj:8) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13729$run_lifecycle_fn_BANG___13736$fn__13737.invoke(internal.clj:175) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13729$run_lifecycle_fn_BANG___13736.invoke(internal.clj:158) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13758$run_lifecycle_fns__13763$fn__13764.invoke(internal.clj:209) ~[na:na]

at puppetlabs.trapperkeeper.internal$eval13758$run_lifecycle_fns__13763.invoke(internal.clj:186) [na:na]

at puppetlabs.trapperkeeper.internal$eval14229$build_app_STAR___14238$fn$reify__14248.init(internal.clj:559) [na:na]

at puppetlabs.trapperkeeper.internal$eval14275$boot_services_for_app_STAR__STAR___14282$fn__14283$fn__14285.invoke(internal.clj:585) [na:na]

at puppetlabs.trapperkeeper.internal$eval14275$boot_services_for_app_STAR__STAR___14282$fn__14283.invoke(internal.clj:584) [na:na]

at puppetlabs.trapperkeeper.internal$eval14275$boot_services_for_app_STAR__STAR___14282.invoke(internal.clj:578) [na:na]

at clojure.core$partial$fn__4529.invoke(core.clj:2499) [puppet-server-release.jar:na]

at puppetlabs.trapperkeeper.internal$eval13797$initialize_lifecycle_worker__13808$fn__13809$fn__13896$state_machine__11795__auto____13897$fn__13899.invoke(internal.clj:226) [na:na]

at puppetlabs.trapperkeeper.internal$eval13797$initialize_lifecycle_worker__13808$fn__13809$fn__13896$state_machine__11795__auto____13897.invoke(internal.clj:226) [na:na]

at clojure.core.async.impl.ioc_macros$run_state_machine.invoke(ioc_macros.clj:1011) [na:na]

at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invoke(ioc_macros.clj:1015) [na:na]

at clojure.core.async$ioc_alts_BANG_$fn__11963.invoke(async.clj:378) [na:na]

at clojure.core.async$do_alts$fn__11909$fn__11912.invoke(async.clj:247) [na:na]

at clojure.core.async.impl.channels.ManyToManyChannel$fn__6730$fn__6731.invoke(channels.clj:95) [na:na]

at clojure.lang.AFn.run(AFn.java:22) [puppet-server-release.jar:na]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]

at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]

2016-05-13 14:33:19,309 INFO  [main] [p.t.internal] Beginning shutdown sequence

2016-05-13 14:33:19,345 INFO  [async-dispatch-2] [p.e.s.j.pe-jruby-metrics-service] PE JRuby Metrics Service: stopping metrics sampler job

2016-05-13 14:33:19,354 INFO  [async-dispatch-2] [p.e.s.j.pe-jruby-metrics-service] PE JRuby Metrics Service: stopped metrics sampler job

2016-05-13 14:33:19,360 INFO  [async-dispatch-2] [p.e.s.f.file-sync-client-service] Stopping file sync client service

2016-05-13 14:35:41,814 INFO  [main] [o.e.j.u.log] Logging initialized @129671ms

2016-05-13 14:35:57,678 INFO  [Thread-2] [p.t.internal] Shutting down due to JVM shutdown hook.

2016-05-13 14:35:57,728 INFO  [Thread-2] [p.t.internal] Beginning shutdown sequence

2016-05-13 14:36:00,609 INFO  [async-dispatch-2] [p.t.s.w.jetty9-service] Initializing web server(s).

2016-05-13 14:36:01,302 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-core] Initializing file sync server data dir: /opt/puppetlabs/server/data/puppetserver/filesync/storage

2016-05-13 14:36:01,317 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-core] Initializing Git repository at /opt/puppetlabs/server/data/puppetserver/filesync/storage/puppet-code.git

2016-05-13 14:36:01,813 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-service] File sync storage service mounting repositories at /file-sync-git

2016-05-13 14:36:04,046 INFO  [async-dispatch-2] [p.e.s.f.file-sync-storage-service] Registering file sync storage HTTP API

2016-05-13 14:36:04,052 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for file-sync-storage-service service

2016-05-13 14:36:04,097 INFO  [async-dispatch-2] [p.c.services] Starting code-manager v1 API...

2016-05-13 14:36:04,179 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for code-manager-service service

2016-05-13 14:36:04,869 INFO  [async-dispatch-2] [p.c.config] Writing r10k config to "/opt/puppetlabs/server/data/code-manager/r10k.yaml"

2016-05-13 14:36:05,141 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for pe-puppet-profiler service

2016-05-13 14:36:05,191 INFO  [async-dispatch-2] [p.s.j.jruby-puppet-service] Initializing the JRuby service

2016-05-13 14:36:05,296 INFO  [async-dispatch-2] [p.s.p.puppet-admin-service] Starting Puppet Admin web app

2016-05-13 14:36:05,379 INFO  [clojure-agent-send-pool-0] [p.s.j.jruby-puppet-internal] Creating JRuby instance with id 1.

running 'top' shows all 4 CPUs maxed out. Killing individual 'java' threads is useless, theres aprocess called 'ezbake' that just respawns them. WOndering if anyone is seeing something similar.

[Joe Pinsonault]

Mike,

A few things I can think of off the top of my head

It sounds as if a git repo that file-sync uses internally has become corrupted, though it's hard to tell from the error message. Would you be able to post the complete puppetserver.log (maybe to a gist)? It might help to see how far code manager has managed to get and where things first started going wrong. 

I'd be curious to know where code-manager is deploying code to, to the code-dir or the code-staging dir. I don't think this is the kind of error you'd be seeing if it was deploying to the code-dir though.

Is this a clean VM that you've just set up and immediately enabled code manager on? Or have you been using PE on it prior to enabling code manager?

[Kevin Corcoran]

Mike,

To add a bit more to the info that Joe already provided, I would encourage you to open a support ticket if you have a Puppet Enterprise license.  That'll be the easiest way for us to collaboratively get to the bottom of this issue.

In terms of simply getting it working, I'd try following steps:

• `rm -rf /opt/puppetlabs/server/data/puppetserver/filesync` - this will delete file sync's history of your code, which has probably become corrupt (based on the error you've encountered)
  
• Restart puppet server - i.e. `service pe-puppetserver restart`
  
• deploy the latest version of your code again.  The easiest way to do this is probably `puppet code deploy`.

Any additional information you are able to give us about how you got into this situation would be greatly appreciated.  Of particular value is the contents of file sync's data directory (/opt/puppetlabs/server/data/puppetserver/filesync ) and puppet server's log file (/var/log/puppetlabs/puppetserver/puppetserver.log).

Hope this helps,

Kevin