StackOverflowError on highstate

[rbjorklin]

Tried running this:

Sep 29, 2017 9:10:35 AM FINE com.waytta.saltstack
Discovered netapi: CherryPy/5.6.0

Sep 29, 2017 9:10:35 AM FINE com.waytta.saltstack
Sending JSON: {"client":"local_async","tgt":"example_group","expr_form":"nodegroup","fun":"state.highstate","kwarg":{"test":"True"}}

And the output is as follows:

Running jid: 20170929091035560269                                                                                                                                                                                
Waiting for 18 minions                                                                                                                                                                                           
0 minions are done                                                                                                                                                                                               
Will check status every 10 seconds...                                                                                                                                                                            
Some minions returned. Waiting 120 seconds                                                                                                                                                                       
FATAL: null                                                                                                                                                                                                      
java.lang.StackOverflowError                                                                                                                                                                                     
    at java.lang.Exception.<init>(Exception.java:102)                                                                                                                                                            
    at java.lang.ReflectiveOperationException.<init>(ReflectiveOperationException.java:89)                                                                                                                       
    at java.lang.reflect.InvocationTargetException.<init>(InvocationTargetException.java:72)                                                                                                                     
    at sun.reflect.GeneratedMethodAccessor1376.invoke(Unknown Source)                                                                                                                                            
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)                                                                                                                     
    at java.lang.reflect.Method.invoke(Method.java:498)                                                                                                                                                          
    at org.apache.commons.beanutils.PropertyUtilsBean.invokeMethod(PropertyUtilsBean.java:2170)                                                                                                                  
    at org.apache.commons.beanutils.PropertyUtilsBean.getSimpleProperty(PropertyUtilsBean.java:1332)                                                                                                             
    at org.apache.commons.beanutils.PropertyUtilsBean.getNestedProperty(PropertyUtilsBean.java:770)                                                                                                              
    at org.apache.commons.beanutils.PropertyUtilsBean.getProperty(PropertyUtilsBean.java:846)                                                                                                                    
    at org.apache.commons.beanutils.PropertyUtils.getProperty(PropertyUtils.java:426)                                                                                                                            
    at net.sf.json.JSONObject.defaultBeanProcessing(JSONObject.java:692)                                                                                                                                         
    at net.sf.json.JSONObject._fromBean(JSONObject.java:642)                                                                                                                                                     
    at net.sf.json.JSONObject.fromObject(JSONObject.java:169)                                                                                                                                                    
    at net.sf.json.JSONSerializer.toJSON(JSONSerializer.java:108)                                                                                                                                                
    at net.sf.json.AbstractJSON._processValue(AbstractJSON.java:239)                                                                                                                                             
    at net.sf.json.JSONArray._processValue(JSONArray.java:2492)                                                                                                                                                  
    at net.sf.json.JSONArray.processValue(JSONArray.java:2517)                                                                                                                                                   
    at net.sf.json.JSONArray.addValue(JSONArray.java:2504)                                                                                                                                                       
    at net.sf.json.JSONArray.element(JSONArray.java:1719)                                                                                                                                                        
    at net.sf.json.JSONArray.fromObject(JSONArray.java:159)                                                                                                                                                      
    at net.sf.json.JSONSerializer.toJSON(JSONSerializer.java:113)                                                                                                                                                
    at net.sf.json.AbstractJSON._processValue(AbstractJSON.java:239)
    ...
    ...

[mchugh19]

So far, I'm not able to directly replicate. In my setup where all minions return, things run as expected. In the situation where some minions are offline, a runtime exception is raised to fail the build.

Running jid: 20171004230055603642
Waiting for 2 minions
0 minions are done
Will check status every 5 seconds...
Some minions returned. Waiting 6 seconds
ERROR: Minions timed out:
["minion1"]


ERROR: Build step failed with exception
com.waytta.SaltException: {"master":{"return":{"...
Caused: java.lang.RuntimeException
	at com.waytta.SaltAPIBuilder.perform(SaltAPIBuilder.java:264)
	at hudson.tasks.BuildStepCompatibilityLayer.perform(BuildStepCompatibilityLayer.java:81)
	at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:20)
	at hudson.model.AbstractBuild$AbstractBuildExecution.perform(AbstractBuild.java:735)
	at hudson.model.Build$BuildExecution.build(Build.java:206)
	at hudson.model.Build$BuildExecution.doRun(Build.java:163)
	at hudson.model.AbstractBuild$AbstractBuildExecution.run(AbstractBuild.java:490)
	at hudson.model.Run.execute(Run.java:1735)
	at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:43)
	at hudson.model.ResourceController.execute(ResourceController.java:97)
	at hudson.model.Executor.run(Executor.java:405)
Build step 'Send a message to Salt API' marked build as failure
Finished: FAILURE

In your case, did the FATAL: null error occur about 120 seconds after some minions returned?
If so, can you try using a timeout value of -120? As documented in the help icon next to that option, a negative value there will still timeout, but not fail the build due to unresponsive minions.

Running jid: 20171004230341725630
Waiting for 2 minions
0 minions are done
Will check status every 5 seconds...
Some minions returned. Waiting 6 seconds
ERROR: Minions timed out:
["minion1"]


Response on state.highstate test=True for group1:
[{"master": {
  "return":   {
   ...
Finished: SUCCESS

[mchugh19]

Hey @rbjorklin

Are you still able to replicate this problem? As discussed in #107, it may be related to the Jenkins version. What version were you on when you encountered the exception?

[rbjorklin]

We have had this running as a nightly job which magically started working last night. We are on 2.83 right now and have been for about 2 days. The job has now failed once and worked once with 2.83 so not sure it's related to the Jenkins version.

[mchugh19]

Is the saltapi response very large?

Based on comments in #101, I think we may have found a cause for this issue. The http call to get the response from the salt-api only waits 5 seconds, and if it is a large response, this might not be enough. I've just upped it to 30 in this release. Could test and see if this helps?

[mchugh19]

Just published the release with the increased timeout. It should hit the mirrors within the next 24 hours. Since everything is currently working, I'll close this out for now, but please let me know if you have any further problems.

[rbjorklin]

Sorry about the delay, I'll upgrade the plugin today and get back to you if the problem reoccurs but I think it's safe to leave this issue as closed.

[rbjorklin]

Actually, the issue reoccurred over the weekend but the stacktrace is slightly different so it might be a new issue?

Waiting for 18 minions                                                      
0 minions are done                                                             
Will check status every 10 seconds...                                          
Some minions returned. Waiting 120 seconds                                     
FATAL: null                                                                    
                                                                               
java.lang.StackOverflowError                                                   
    at java.util.WeakHashMap.getTable(WeakHashMap.java:350)                    
    at java.util.WeakHashMap.get(WeakHashMap.java:397)                         
    at org.apache.commons.beanutils.WeakFastHashMap.get(WeakFastHashMap.java:160) 
    at org.apache.commons.beanutils.PropertyUtilsBean.getPropertyDescriptors(PropertyUtilsBean.java:971) 
    at org.apache.commons.beanutils.PropertyUtilsBean.getPropertyDescriptors(PropertyUtilsBean.java:1084) 
    at org.apache.commons.beanutils.PropertyUtilsBean.getPropertyDescriptor(PropertyUtilsBean.java:912) 
    at org.apache.commons.beanutils.PropertyUtilsBean.getSimpleProperty(PropertyUtilsBean.java:1319) 
    at org.apache.commons.beanutils.PropertyUtilsBean.getNestedProperty(PropertyUtilsBean.java:770) 
    at org.apache.commons.beanutils.PropertyUtilsBean.getProperty(PropertyUtilsBean.java:846) 
    at org.apache.commons.beanutils.PropertyUtils.getProperty(PropertyUtils.java:426) 
    at net.sf.json.JSONObject.defaultBeanProcessing(JSONObject.java:692)       
    at net.sf.json.JSONObject._fromBean(JSONObject.java:642)                   
    at net.sf.json.JSONObject.fromObject(JSONObject.java:169)                  
    at net.sf.json.JSONSerializer.toJSON(JSONSerializer.java:108)              
    at net.sf.json.AbstractJSON._processValue(AbstractJSON.java:239)           
    at net.sf.json.JSONArray._processValue(JSONArray.java:2492)                
    at net.sf.json.JSONArray.processValue(JSONArray.java:2517)                 
    at net.sf.json.JSONArray.addValue(JSONArray.java:2504)                     
    at net.sf.json.JSONArray.element(JSONArray.java:1719)                      
    at net.sf.json.JSONArray.fromObject(JSONArray.java:159)                    
    at net.sf.json.JSONSerializer.toJSON(JSONSerializer.java:113)

[mchugh19]

Hmmm. These errors sure look like the jsonSearializer isn't able to parse json, meaning the response back from the salt-api isn't proper json. I'm currently unable to replicate, but perhaps we can get he bad return. If you were able to increase logging and able to view the response, that would be really helpful. Alternatively, perhaps manually querying the salt-api will show a bad response. Here's some curl to submit and query the salt-api. If you run the last curl on your JID, do you get a consistant reply, and is it valid json?

#!/bin/sh

JSON='{"client":"local_async","tgt":"*","expr_form":"glob","fun":"state.sls","arg":"tests.dup","kwarg":{}}'

# Login
RESPONSE=`curl -ik http://localhost:8000/login -H 'Content-Type: application/json' -d '{"eauth":"pam","password":"jenkins","username":"jenkins"}' 2>/dev/null`
TOKEN=$(echo $RESPONSE |
    sed -e 's/[{}]/''/g' |
    awk -v k="text" '{n=split($0,a,","); for (i=1; i<=n; i++) print a[i]}' |
    grep token | cut -d: -f 2 | cut -d'"' -f 2 )
echo $TOKEN

# Submit request
RESPONSE=`curl -k http://localhost:8000/minions -H 'Accept: application/json' -H "X-Auth-Token: $TOKEN" -H 'Content-Type: application/json' -d "$JSON" 2>/dev/null`
echo $RESPONSE
JID=$(echo $RESPONSE |
    sed -e 's/[{}]/''/g' | sed -e 's/"return":/''/g' |
    awk -v k="text" '{n=split($0,a,","); for (i=1; i<=n; i++) print a[i]}' |
    grep jid | cut -d: -f2 | cut -d'"' -f2)
echo $JID

sleep 5

# Query response
RESPONSE=`curl -k http://localhost:8000/jobs/$JID -H 'Accept: application/json' -H "X-Auth-Token: $TOKEN" -H 'Content-Type: application/json' 2>/dev/null`
echo $RESPONSE

[richardsimko]

I had a look at the response, the JSON is in deed valid but it's 3 Mb in size so that may have something to do with it ;) My suspicion is that the JSON structure is too deep so I'll try increasing Java's stack memory and check if that helps.

For context, what we're doing is running the highstate on all machines as part of a nightly build to make sure that they're all in sync.

[mchugh19]

Can you send me the json return? I'd like to see if I can replicate with your results.

[richardsimko]

Ping @rbjorklin, he should be able to fetch it

[mchugh19]

Can you try this release? https://github.com/jenkinsci/saltstack-plugin/releases/tag/3.1.4-beta1
I was able to finally replicate and this fixes the issue for me.

[rbjorklin]

I've tried 3.1.4-beta1 without success :/ I emailed you the json response.

Sorry about the delay @mchugh19.