Uploaded image for project: 'Puppet Server'
  1. Puppet Server
  2. SERVER-2375

Puppetserver fails with Internal Server Error: java.lang.InterruptedException

    Details

    • Type: Task
    • Status: Closed
    • Priority: Normal
    • Resolution: Cannot Reproduce
    • Affects Version/s: SERVER 5.3.6
    • Fix Version/s: None
    • Component/s: Puppet Server
    • Labels:
      None
    • Template:
    • Team:
      Server
    • QA Risk Assessment:
      Needs Assessment

      Description

      Hi people, I see the following in my /var/log/puppetlabs/puppetserver/puppetserver.log:

      2018-10-27 00:00:18,854 ERROR [qtp349904914-573] [p.r.core] Internal Server Error: java.lang.InterruptedException
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
      	at com.puppetlabs.jruby_utils.pool.JRubyPool.borrowItemWithTimeout(JRubyPool.java:194)
      	at sun.reflect.GeneratedMethodAccessor25.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:93)
      	at clojure.lang.Reflector.invokeInstanceMethod(Reflector.java:28)
      	at puppetlabs.services.jruby_pool_manager.impl.jruby_internal$eval21970$borrow_with_timeout_fn__21975$fn__21976.invoke(jruby_internal.clj:133)
      	at puppetlabs.services.jruby_pool_manager.impl.jruby_internal$eval21970$borrow_with_timeout_fn__21975.invoke(jruby_internal.clj:130)
      	at clojure.core$partial$fn__4759.invoke(core.clj:2515)
      	at puppetlabs.services.jruby_pool_manager.impl.jruby_internal$eval22333$borrow_from_pool_BANG__STAR___22338$fn__22339.invoke(jruby_internal.clj:271)
      	at puppetlabs.services.jruby_pool_manager.impl.jruby_internal$eval22333$borrow_from_pool_BANG__STAR___22338.invoke(jruby_internal.clj:264)
      	at puppetlabs.services.jruby_pool_manager.impl.jruby_internal$eval22380$borrow_from_pool_with_timeout__22385$fn__22386.invoke(jruby_internal.clj:312)
      	at puppetlabs.services.jruby_pool_manager.impl.jruby_internal$eval22380$borrow_from_pool_with_timeout__22385.invoke(jruby_internal.clj:301)
      	at puppetlabs.services.jruby_pool_manager.jruby_core$eval23595$borrow_from_pool_with_timeout__23600$fn__23601.invoke(jruby_core.clj:212)
      	at puppetlabs.services.jruby_pool_manager.jruby_core$eval23595$borrow_from_pool_with_timeout__23600.invoke(jruby_core.clj:199)
      	at puppetlabs.puppetserver.jruby_request$wrap_with_jruby_instance$fn__24683.invoke(jruby_request.clj:46)
      	at puppetlabs.puppetserver.jruby_request$wrap_with_error_handling$fn__24679.invoke(jruby_request.clj:33)
      	at puppetlabs.services.request_handler.request_handler_service$reify__24780$service_fnk__5266__auto___positional$reify__24795.handle_request(request_handler_service.clj:47)
      	at puppetlabs.services.protocols.request_handler$eval15873$fn__15874$G__15865__15877.invoke(request_handler.clj:3)
      	at puppetlabs.services.protocols.request_handler$eval15873$fn__15874$G__15864__15881.invoke(request_handler.clj:3)
      	at clojure.core$partial$fn__4759.invoke(core.clj:2515)
      	at puppetlabs.trapperkeeper.authorization.ring_middleware$eval40055$wrap_authorization_check__40064$fn__40067$fn__40068.invoke(ring_middleware.clj:284)
      	at puppetlabs.ring_middleware.core$eval21163$wrap_bad_request__21172$fn__21175$fn__21181.invoke(core.clj:170)
      	at puppetlabs.ring_middleware.core$eval21261$wrap_uncaught_errors__21270$fn__21273$fn__21278.invoke(core.clj:216)
      	at puppetlabs.ring_middleware.core$eval20888$wrap_request_logging__20893$fn__20894$fn__20896.invoke(core.clj:47)
      	at puppetlabs.i18n.core$locale_negotiator$fn__124.invoke(core.clj:357)
      	at puppetlabs.ring_middleware.core$eval20917$wrap_response_logging__20922$fn__20923$fn__20924.invoke(core.clj:53)
      	at puppetlabs.puppetserver.ringutils$wrap_with_puppet_version_header$fn__33541.invoke(ringutils.clj:83)
      	at puppetlabs.services.master.master_core$eval34520$v3_ruby_routes__34525$fn__34526$fn__34533.invoke(master_core.clj:727)
      	at bidi.ring$eval26407$fn__26408.invoke(ring.cljc:25)
      	at bidi.ring$eval26386$fn__26387$G__26377__26396.invoke(ring.cljc:16)
      	at puppetlabs.comidi$make_handler$fn__28517.invoke(comidi.clj:245)
      	at puppetlabs.metrics.http$eval33698$wrap_with_request_metrics__33703$fn__33707$fn__33709$fn__33710$fn__33711.invoke(http.clj:152)
      	at puppetlabs.metrics.http.proxy$java.lang.Object$Callable$7da976d4.call(Unknown Source)
      	at com.codahale.metrics.Timer.time(Timer.java:101)
      	at puppetlabs.metrics.http$eval33698$wrap_with_request_metrics__33703$fn__33707$fn__33709$fn__33710.invoke(http.clj:152)
      	at puppetlabs.metrics.http.proxy$java.lang.Object$Callable$7da976d4.call(Unknown Source)
      	at com.codahale.metrics.Timer.time(Timer.java:101)
      	at puppetlabs.metrics.http$eval33698$wrap_with_request_metrics__33703$fn__33707$fn__33709.invoke(http.clj:148)
      	at puppetlabs.comidi$eval28578$wrap_with_route_metadata__28583$fn__28584$fn__28586.invoke(comidi.clj:332)
      	at puppetlabs.trapperkeeper.services.webserver.jetty9_core$ring_handler$fn__31484.invoke(jetty9_core.clj:433)
      	at puppetlabs.trapperkeeper.services.webserver.jetty9_core.proxy$org.eclipse.jetty.server.handler.AbstractHandler$ff19274a.handle(Unknown Source)
      	at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:93)
      	at clojure.lang.Reflector.invokeInstanceMethod(Reflector.java:28)
      	at puppetlabs.trapperkeeper.services.webserver.normalized_uri_helpers$eval31060$normalize_uri_handler__31065$fn__31066$fn__31067.invoke(normalized_uri_helpers.clj:74)
      	at puppetlabs.trapperkeeper.services.webserver.normalized_uri_helpers.proxy$org.eclipse.jetty.server.handler.HandlerWrapper$ff19274a.handle(Unknown Source)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
      	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1317)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:205)
      	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1219)
      	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
      	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:219)
      	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
      	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:724)
      	at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:56)
      	at com.puppetlabs.trapperkeeper.services.webserver.jetty9.utils.MDCRequestLogHandler.handle(MDCRequestLogHandler.java:36)
      	at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:169)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
      	at org.eclipse.jetty.server.Server.handle(Server.java:531)
      	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:352)
      	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
      	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281)
      	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
      	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680)
      	at java.lang.Thread.run(Thread.java:748)
       
      2018-10-27 00:00:19,078 ERROR [async-dispatch-3] [p.t.s.w.jetty9-core] Web server failed to shut down gracefully in configured timeout period (30,000); cancelling remaining requests.
      java.util.concurrent.TimeoutException: null
      	at org.eclipse.jetty.util.FutureCallback.get(FutureCallback.java:128)
      	at org.eclipse.jetty.util.FutureCallback.get(FutureCallback.java:30)
      	at org.eclipse.jetty.server.Server.doStop(Server.java:460)
      	at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:89)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:93)
      	at clojure.lang.Reflector.invokeNoArgInstanceMember(Reflector.java:313)
      	at puppetlabs.trapperkeeper.services.webserver.jetty9_core$eval31678$shutdown__31683$fn__31687$fn__31689.invoke(jetty9_core.clj:606)
      	at puppetlabs.trapperkeeper.services.webserver.jetty9_core$eval31678$shutdown__31683$fn__31687.invoke(jetty9_core.clj:605)
      	at puppetlabs.trapperkeeper.services.webserver.jetty9_core$eval31678$shutdown__31683.invoke(jetty9_core.clj:597)
      	at puppetlabs.trapperkeeper.services.webserver.jetty9_service$reify__32591$service_fnk__5266__auto___positional$reify__32598.stop(jetty9_service.clj:71)
      	at puppetlabs.trapperkeeper.services$eval5068$fn__5095$G__5060__5098.invoke(services.clj:9)
      	at puppetlabs.trapperkeeper.services$eval5068$fn__5095$G__5059__5102.invoke(services.clj:9)
      	at puppetlabs.trapperkeeper.internal$eval13835$run_lifecycle_fn_BANG___13842$fn__13843.invoke(internal.clj:198)
      	at puppetlabs.trapperkeeper.internal$eval13835$run_lifecycle_fn_BANG___13842.invoke(internal.clj:181)
      	at puppetlabs.trapperkeeper.internal$eval14258$shutdown_BANG___14263$fn__14264$shutdown_fn__14266$fn__14277.invoke(internal.clj:440)
      	at puppetlabs.trapperkeeper.internal$eval14258$shutdown_BANG___14263$fn__14264$shutdown_fn__14266.invoke(internal.clj:439)
      	at puppetlabs.trapperkeeper.internal$eval13905$initialize_lifecycle_worker__13916$fn__13917$fn__14013$state_machine__11875__auto____14014$fn__14016$fn__14029.invoke(internal.clj:276)
      	at puppetlabs.trapperkeeper.internal$eval13905$initialize_lifecycle_worker__13916$fn__13917$fn__14013$state_machine__11875__auto____14014$fn__14016.invoke(internal.clj:260)
      	at puppetlabs.trapperkeeper.internal$eval13905$initialize_lifecycle_worker__13916$fn__13917$fn__14013$state_machine__11875__auto____14014.invoke(internal.clj:251)
      	at clojure.core.async.impl.ioc_macros$run_state_machine.invokeStatic(ioc_macros.clj:1012)
      	at clojure.core.async.impl.ioc_macros$run_state_machine.invoke(ioc_macros.clj:1011)
      	at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invokeStatic(ioc_macros.clj:1016)
      	at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invoke(ioc_macros.clj:1014)
      	at clojure.core.async$ioc_alts_BANG_$fn__12043.invoke(async.clj:383)
      	at clojure.core.async$do_alts$fn__11989$fn__11992.invoke(async.clj:252)
      	at clojure.core.async.impl.channels.ManyToManyChannel$fn__6813.invoke(channels.clj:135)
      	at clojure.lang.AFn.run(AFn.java:22)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      	at java.lang.Thread.run(Thread.java:748)
      2018-10-27 00:00:19,079 INFO  [async-dispatch-3] [p.t.s.w.jetty9-core] Web server shutdown
      2018-10-27 00:00:19,297 INFO  [clojure-agent-send-off-pool-0] [p.t.s.w.filesystem-watch-core] Closing watcher puppetlabs.trapperkeeper.services.watcher.filesystem_watch_core.WatcherImpl@159ba7c7
      2018-10-27 00:00:19,618 INFO  [main] [p.t.internal] Finished shutdown sequence
      2018-10-27 00:00:29,909 WARN  [clojure-agent-send-pool-1] [puppetserver] Puppet Setting ca is deprecated. 
         (location: /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/settings.rb:1169:in `issue_deprecation_warning')
      2018-10-27 00:00:30,012 INFO  [clojure-agent-send-pool-1] [puppetserver] Puppet Puppet settings initialized; run mode: master
      

      My puppetserver is configured to listen for http requests on localhost (I've an nginx in front to terminate TLS):

      # /etc/puppetlabs/puppetserver/conf.d/webserver.conf
      webserver: {
          access-log-config: /etc/puppetlabs/puppetserver/request-logging.xml
          client-auth: none
          ssl-host: "127.0.0.1"
          ssl-port: 8141
          ssl-cert: "/etc/puppetlabs/puppet/ssl/certs/puppet.local.pem"
          ssl-key: "/etc/puppetlabs/puppet/ssl/private_keys/puppet.local.pem"
          ssl-ca-cert: "/etc/puppetlabs/puppet/ssl/certs/ca.pem"
          idle-timeout-milliseconds: 30000
          ssl-protocols: "TLSv1.2"
          cipher-suites: [
              "TLS_RSA_WITH_AES_256_CBC_SHA256",
              "TLS_RSA_WITH_AES_256_CBC_SHA",
              "TLS_RSA_WITH_AES_128_CBC_SHA256",
              "TLS_RSA_WITH_AES_128_CBC_SHA"
          ]
          host: "127.0.0.1"
          port: 8139
          acceptor-threads: 4
          selector-threads: 16
          ssl-acceptor-threads: 4
          ssl-selector-threads: 4
          max-threads: 300
      }
      

      After the exception the puppetserver isn't listening anymore on port 8139 nor 8141. My installed packages:

      rpm -qa | grep puppet
      puppet-agent-oauth-0.5.1-3.el7.noarch
      puppetdb-termini-5.2.6-1.el7.noarch
      puppet-release-1.0.0-3.el7.noarch
      puppet-agent-5.5.7-1.el7.x86_64
      puppetserver-5.3.6-1.el7.noarch
      

      grep -v '#\|^$' /etc/puppetlabs/puppetserver/conf.d/puppetserver.conf
      jruby-puppet: {
          ruby-load-path: [
              /opt/puppetlabs/puppet/lib/ruby/vendor_ruby,
              /opt/puppetlabs/puppet/cache/lib,
          ]
          gem-home: /opt/puppetlabs/server/data/puppetserver/jruby-gems
          gem-path: [${jruby-puppet.gem-home}, "/opt/puppetlabs/server/data/puppetserver/vendored-jruby-gems"]
          master-conf-dir: /etc/puppetlabs/puppet
          master-code-dir: /etc/puppetlabs/code
          master-var-dir: /opt/puppetlabs/server/data/puppetserver
          master-run-dir: /var/run/puppetlabs/puppetserver
          master-log-dir: /var/log/puppetlabs/puppetserver
          max-active-instances: 32
          max-requests-per-instance: 2048
          max-queued-requests: 0
          max-retry-delay: 1800
          use-legacy-auth-conf: false
          environment-class-cache-enabled: true
      }
      http-client: {
          ssl-protocols: [
              TLSv1.2,
          ]
          cipher-suites: [
              TLS_RSA_WITH_AES_256_CBC_SHA256,
              TLS_RSA_WITH_AES_256_CBC_SHA,
              TLS_RSA_WITH_AES_128_CBC_SHA256,
              TLS_RSA_WITH_AES_128_CBC_SHA,
          ]
          metrics-enabled: true
          idle-timeout-milliseconds: 1200000
          connect-timeout-milliseconds: 120000
      }
      profiler: {
          enabled: true
      }
      
      

      I can restart the service and it works for a few hours. I noticed this behavior 4 times today. I am not sure if it is triggered by a certain action or just be the amount of load hitting the server. It seems to be overloaded at the moment but I assume it still should not fail with such an exception. Let me know if you need further information.

        Attachments

          Activity

            jsd-sla-details-panel

              People

              • Assignee:
                Unassigned
                Reporter:
                bastelfreak Tim Meusel
              • Votes:
                0 Vote for this issue
                Watchers:
                5 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: