Re: vRO 7.3 getting "Unable to initialize a workfl...

qc4vmware · ‎08-09-2017

I've run into an error that I believe is new with vRO 7.3 as we've just upgraded vRA to 7.3 and its our first time seeing this. We have a workflow we call after a system is built that runs customization scripts. Generally we only ever need to run a single script but for a few situations we run a script, reboot, then run a second script. When we attempt to run the second time around I am getting an error "Unable to initialize a workflow handler" on the second script run. I can immediately re-run the failed workflow and it works. It seems like it only fails when called the second time inside of the parent workflow. Anyone seen this? Seems like a bug in 7.3. Maybe due to nesting or some other issue?

tschoergez · ‎08-09-2017

Are you using the "waiting timer" element in your logic in this context?
I just saw some error that might be related to this element in combination of nested workflows, also only occuring after an upgrade to 7.3.

qc4vmware · ‎08-09-2017

I'm using the canned actions for shutdown vm and wait for dns tools which I assume make use of timers... everyone uses these right?

qc4vmware · ‎08-09-2017

And yes there is lots of nesting going on.

qc4vmware · ‎08-09-2017

And the guest script manager "Improved Sleep" definitely uses it and I use that all the time.

qc4vmware · ‎08-09-2017

OK... I have cut out where I can in these workflow interactions usage of the timer and now things are not blowing up but it sure seems like things have slowed way down. I have the feeling this is a nasty bug... what's the team doing to fix this?

tschoergez · ‎08-09-2017

The library actions to wait for vmtools just use System.sleep(), no issues there.

But that "Improved Sleep" workflow uses indeed the waiting timer element, to improve scalability and reduce resource utilization of longer running workflows.

Is that a single-node vRO or clustered one? standalone appliance or vRA embedded?

And: Could you please open a SR with VMware support?

Thanks!

Joerg

qc4vmware · ‎08-10-2017

These are vRA embedded and clustered. Will do on opening a ticket with support. I am off on vacation starting Friday for two weeks but I'll open up the case anyway.

Paul

iiliev · ‎08-10-2017

"Unable to initialize a workflow handler" is a wrapper exception. Could you check vRO log files (eg. server.log); there should be a stacktrace showing the original exception.

qc4vmware · ‎08-10-2017

I'll reproduce this in our lab and get the error to you. Thanks for the attention on this.

qc4vmware · ‎09-01-2017

Sorry I didn't get to this before I went off on vacation. Before I spend the time reproducing this and getting the error to you, opening a support ticket, etc was there any further investigation or input from other customers? If I don't have to go through the exercise at this point I won't if you already have the root cause and its being worked on.

Thanks!!!

qc4vmware · ‎09-08-2017

I went ahead and reproduced the failure... I'm pretty sure this is the error. The workflow just immediately fails to run for whatever reason. I also did a log file dump immediately after these errors occurred.

2017-09-08 00:01:16.126-0700 [WorkflowExecutorPool-Thread-29668] WARN {qcvcloudadmin@na.qualcomm.com:QCbuildingMachineLinux:4cfaf00d-117b-40f6-8f9d-155192ff3df9:token=8ab5ba90

5dca1a41015e604ab82a296c:anctoken=8ab5ba905dca1a41015e604ab06d295f} [IGNORED_EXCEPTION] Ignored exception.

org.postgresql.util.PSQLException: This connection has been closed.

at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)

at org.postgresql.jdbc.PgConnection.setAutoCommit(PgConnection.java:712)

at ch.dunes.util.jdbc.DatasourceConnection.close(DatasourceConnection.java:49)

at ch.dunes.util.jdbc.DatasourceConnection.getConnection(DatasourceConnection.java:30)

at ch.dunes.scripting.server.locking.JdbcLocking.checkIfTableExists(JdbcLocking.java:213)

at ch.dunes.scripting.server.locking.JdbcLocking.retrieveAll(JdbcLocking.java:161)

at ch.dunes.scripting.server.locking.LockingSystem.internalRetrieveAll(LockingSystem.java:100)

at ch.dunes.scripting.server.locking.LockingSystem.retrieveAll(LockingSystem.java:77)

at sun.reflect.GeneratedMethodAccessor629.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.mozilla.javascript.MemberBox.invoke(MemberBox.java:126)

at org.mozilla.javascript.NativeJavaMethod.call(NativeJavaMethod.java:225)

at org.mozilla.javascript.Interpreter.interpretLoop(Interpreter.java:1473)

at org.mozilla.javascript.Interpreter.interpret(Interpreter.java:815)

at org.mozilla.javascript.InterpretedFunction.call(InterpretedFunction.java:109)

at ch.dunes.scripting.server.script.DynamicFunction.call(DynamicFunction.java:99)

at org.mozilla.javascript.Interpreter.interpretLoop(Interpreter.java:1473)

at org.mozilla.javascript.Interpreter.interpret(Interpreter.java:815)

at org.mozilla.javascript.InterpretedFunction.call(InterpretedFunction.java:109)

at ch.dunes.scripting.server.script.DynamicFunction.call(DynamicFunction.java:99)

at org.mozilla.javascript.Interpreter.interpretLoop(Interpreter.java:1473)

at org.mozilla.javascript.Interpreter.interpret(Interpreter.java:815)

at org.mozilla.javascript.InterpretedFunction.call(InterpretedFunction.java:109)

at org.mozilla.javascript.ContextFactory.doTopCall(ContextFactory.java:394)

at org.mozilla.javascript.ScriptRuntime.doTopCall(ScriptRuntime.java:3091)

at org.mozilla.javascript.InterpretedFunction.exec(InterpretedFunction.java:120)

at ch.dunes.scripting.server.script.MainScriptingObject.executeScript(MainScriptingObject.java:259)

at ch.dunes.scripting.server.script.MainScriptingObject.executeScript(MainScriptingObject.java:245)

at ch.dunes.workflow.engine.mbean.WorkflowScriptRunner.execute(WorkflowScriptRunner.java:187)

at ch.dunes.workflow.engine.mbean.runner.WorkflowItemTaskRunner.execute(WorkflowItemTaskRunner.java:44)

at ch.dunes.workflow.engine.mbean.runner.WorkflowItemTaskRunner.execute(WorkflowItemTaskRunner.java:25)

at ch.dunes.workflow.engine.mbean.helper.WorkflowHandler.executeItem(WorkflowHandler.java:1179)

at ch.dunes.workflow.engine.mbean.helper.WorkflowHandler.requestElementExecution(WorkflowHandler.java:1139)

at ch.dunes.workflow.engine.mbean.helper.WorkflowHandler.handleWorkflowTokenNextStep(WorkflowHandler.java:804)

at ch.dunes.workflow.engine.mbean.helper.WorkflowHandler.executeToken(WorkflowHandler.java:693)

at ch.dunes.workflow.engine.mbean.helper.WorkflowHandler.handleTokenExecution(WorkflowHandler.java:615)

at ch.dunes.workflow.engine.mbean.helper.WorkflowHandler.access$100(WorkflowHandler.java:114)

at ch.dunes.workflow.engine.mbean.helper.WorkflowHandler$1.execute(WorkflowHandler.java:404)

at ch.dunes.model.ar.AccessRightsTemplate.executeWithAccessRights(AccessRightsTemplate.java:16)

at ch.dunes.workflow.engine.mbean.helper.WorkflowHandler.doExecute(WorkflowHandler.java:400)

at ch.dunes.workflow.engine.mbean.helper.WorkflowHandler.run(WorkflowHandler.java:271)

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

at java.util.concurrent.FutureTask.run(FutureTask.java:266)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

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

at java.lang.Thread.run(Thread.java:748)

iiliev · ‎09-08-2017

I don't think this particular error is problematic. The exception is thrown at a point when the code tries to close an already closed connection, but it should not be a big problem as the error is caught and not propagated up the call stack.

Are there other suspicious errors/exceptions in the log files?

qc4vmware · ‎09-11-2017

I looked through the log files but I was having a hard time finding anything. I did reproduce the issue today, created a log bundle, and a support ticket 17569124809.

All

vRO 7.3 getting "Unable to initialize a workflow handler" error when I try to run a script via vm tools in a guest os twice. Always fails second time.