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

🙊⛔㏒😷 transient IllegalStateException / WP violation in jruby-service-test



    • Bug
    • Status: Closed
    • Normal
    • Resolution: Fixed
    • None
    • SERVER 1.1.0, SERVER 2.1.0
    • None
    • None
    • 1
    • Server Jade 2015-04-15


      As of ce030bb in the stable branch of Puppet Server, if you run the jruby-puppet-service-test in a loop:

      for i in {1..100}; do lein test puppetlabs.services.jruby.jruby-puppet-service-test; done

      You will occasionally see an error logged to the console:

      lein test puppetlabs.services.jruby.jruby-puppet-service-test
      2015-04-01 16:16:59,076 ERROR [p.t.internal] shutdown-on-error triggered because of exception!
      java.lang.IllegalStateException: There was a problem adding a JRubyPuppet instance to the pool.
      	at puppetlabs.services.jruby.jruby_puppet_agents$eval12054$prime_pool_BANG___12055$fn__12059.invoke(jruby_puppet_agents.clj:60) ~[na:na]
      	at puppetlabs.services.jruby.jruby_puppet_agents$eval12054$prime_pool_BANG___12055.invoke(jruby_puppet_agents.clj:38) ~[na:na]
      	at puppetlabs.services.jruby.jruby_puppet_agents$eval12160$send_prime_pool_BANG___12161$fn__12162$fn__12164.invoke(jruby_puppet_agents.clj:132) ~[na:na]
      	at puppetlabs.trapperkeeper.internal$shutdown_on_error_STAR_.invoke(internal.clj:256) [na:na]
      	at puppetlabs.trapperkeeper.internal$shutdown_on_error_STAR_.invoke(internal.clj:240) [na:na]
      	at puppetlabs.trapperkeeper.internal$shutdown_service$reify__6095$service_fnk__5288__auto___positional$reify__6100.shutdown_on_error(internal.clj:295) [na:na]
      	at puppetlabs.trapperkeeper.internal$eval6031$fn__6043$G__6017__6051.invoke(internal.clj:264) [na:na]
      	at puppetlabs.trapperkeeper.internal$eval6031$fn__6043$G__6016__6060.invoke(internal.clj:264) [na:na]
      	at clojure.lang.AFn.applyToHelper(AFn.java:160) [clojure-1.6.0.jar:na]
      	at clojure.lang.AFn.applyTo(AFn.java:144) [clojure-1.6.0.jar:na]
      	at clojure.core$apply.invoke(core.clj:626) [clojure-1.6.0.jar:na]
      	at clojure.core$partial$fn__4228.doInvoke(core.clj:2468) [clojure-1.6.0.jar:na]
      	at clojure.lang.RestFn.applyTo(RestFn.java:137) [clojure-1.6.0.jar:na]
      	at clojure.core$apply.invoke(core.clj:626) [clojure-1.6.0.jar:na]
      	at clojure.core$partial$fn__4228.doInvoke(core.clj:2468) [clojure-1.6.0.jar:na]
      	at clojure.lang.RestFn.invoke(RestFn.java:408) [clojure-1.6.0.jar:na]
      	at puppetlabs.services.jruby.jruby_puppet_agents$eval12032$send_agent__12033$fn__12034$agent_fn__12035.invoke(jruby_puppet_agents.clj:32) [na:na]
      	at clojure.core$binding_conveyor_fn$fn__4145.invoke(core.clj:1913) [clojure-1.6.0.jar:na]
      	at clojure.lang.AFn.applyToHelper(AFn.java:154) [clojure-1.6.0.jar:na]
      	at clojure.lang.RestFn.applyTo(RestFn.java:132) [clojure-1.6.0.jar:na]
      	at clojure.lang.Agent$Action.doRun(Agent.java:114) [clojure-1.6.0.jar:na]
      	at clojure.lang.Agent$Action.run(Agent.java:163) [clojure-1.6.0.jar:na]
      	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]
      	at java.lang.Thread.run(Thread.java:744) [na:1.7.0_55]
      Caused by: java.lang.Exception: JRuby service missing config value 'ruby-load-path'
      	at puppetlabs.services.jruby.jruby_puppet_internal$eval11795$create_pool_instance_BANG___11796$fn__11797.invoke(jruby_puppet_internal.clj:93) ~[na:na]
      	at puppetlabs.services.jruby.jruby_puppet_internal$eval11795$create_pool_instance_BANG___11796.invoke(jruby_puppet_internal.clj:83) ~[na:na]
      	at puppetlabs.services.jruby.jruby_puppet_agents$eval12054$prime_pool_BANG___12055$fn__12059.invoke(jruby_puppet_agents.clj:54) ~[na:na]
      	... 24 common frames omitted

      I would guess it occurs somewhere on the order of once every 30 runs on my box. This does not cause any test failures. I've had a hard time tracking down exactly what's causing it; my best guess is that it is a test race and not an actual bug in the code, but I don't have any way to validate that yet.

      Talked through the issue with jeremy.barlow and our theory is that it might have something to do with some random combination of:

      1. If the TK app is shut down before the JRuby pool finishes initializing, the background thread that is doing the initializing keeps on going,
      2. If we finished one test and moved on to the next one while issue #1 was occurring, it's possible that the logging could be re-initialized for the next test and that there would be a brief window where a log message would slip through to the console, and
      3. There is at least one test in that namespace that is intentionally trying to cause/catch an exception.

      I've tried commenting out some of the tests in the namespace to see if I can narrow it down, but so far I haven't been able to repro it with any of the tests commented out.

      I also tried adding print statements to the beginning and end of each test. Every time I've witnessed the error message since then, it's happened during the execution of `test-with-jruby-puppet` (I see a print from the beginning of that test, then the error, and then a print from the end of that test each time.)

      However, I've tried commenting out all of the other tests besides that one and running in a loop, and haven't seen it repro so far. Will probably try adding back in the test just before and just after that one and see if that gives any more clues, and then punt on this for now.


        Issue Links



              chris Chris Price
              chris Chris Price
              Kurt Wall Kurt Wall
              0 Vote for this issue
              4 Start watching this issue



                Zendesk Support