How do you read a bg log error

[Deactivated User]

The bg log has errors which are of this type

 

ERROR 2015-07-06 00:02:03,175

[Action Execution Pipeline 1 (tenant=clarity)]

bpm.engine (clarity:process_admin:1366276979__F4236F3E-7F7A-4A13-976E-739F62AD7440:none)

Error (will retry) caused by Step Instance: com.niku.bpm.engine.objects.StepInstance@1ac5479

[Id: 15685454 Process Instance Id: 10782341 Step Id: 5009799 State: BPM_SIS_EXEC_ACTION

Step Name: null

Start Date: 2015-07-02 19:20:02.0

Expected End Date: null

Percent Complete: 0.0

Warned: false

Retry Count: 916

No of Pre Conditions: -1

No of Post Conditions: -1

Last Condition Eval Time: 0

Pre Condition Wait Events: null

Post Condition Wait Events: null

Pass Conditions: null Error Id: -1

 

Process Thread: com.niku.bpm.engine.objects.ProcessThread@58ddd4ca [Id: 11232341 Parent Step Instance Id: -1 Join Step Instance Id: -1]

 

Split Threads: null

 

Join Threads:null]

 

How do you read that?

To me it looks like the process did not get to a process engine and did not get into any step yet, not even getting the pre conditions done.

It certainly did try almost a a thousand times though.

 

Does the error entry give an indication where to to look for the cause?

[David Morton]

Ugh ; no idea really!

 

I guess I would pick up the various ids from this line;

 

Id: 15685454 Process Instance Id: 10782341 Step Id: 5009799

 

and try to track these through the process run tables for the ids starting with 1 (since they look like instance ids) and maybe the process definition tables for the 500 id (the Step Id) since that looks like part of the process definition. That might help me find the process/step that is failing, but no clue as to why it is failing seems to be apparent.

[Deactivated User]

Thanks

I did trace the process instance ID's to a number of processes. No user reports on those.

Could then look at the data on their instances to see what were the statuses and if they were eventually run, but have not done so yet

[navzjoshi00]

Can you check what samos has suggested in the below thread ?

https://communities.ca.com/message/2300161#2300161

 

"My first simple suggestion, is to take this part of the error message:   Process Instance Id: 5519038   and use that id to replace in this URL (if you are using v12 or v8 clarity)  https:// >/niku/app?action=bpm.stepHistory&process_instance_id= 5519038 &object_type=admin&ui.page.space=bpm.processDefinitions&ui.page.template=union.adminPage&bpm.returnModuleAction=bpm.processInstancesReturn  and see what process it is.  This would be the first step in your investigation I'd say.  Otherwise, navigate to Clarity > Admin > Processes > Initiated > [filter by Error status]"

 

NJ

[Deactivated User]

Thanks, I've filtered the process instance ID*s and queried the database for the related processes and that to the process runs, not any good a match. Looked at the initiated process instances which gives a better match to the process runs. No match to the processes executed with a job. I am starting to conclude that those process were never started which also the step ID and number of retries suggest. That would result the processes not appearing in the initiated processes. That though gives no glue for the cause of the errors.

 

No, doing what samos suggest give less information than what I got through the above so I have not yet done that.

[Nick Darlington]

Everything between [Id: ... Join Threads:null] is just reporting the step instance data where an error occurred.

 

What appears after that ought to yield more about the specific cause (an exception was 'thrown' by some code when an anticipated or unanticipated problem occurred, and the logger should report the details of that exception once that block of text completes).

 

The inner contents of the block itself will likely not say much, except that in this case it looks like the step instance has been having issues on a recurring basis and that even after several (hundred) retries it still has not been successful.

 

But without the extra information about the exception that was thrown, it isn't possible to say why.

[Deactivated User]

ERROR 2015-07-06 00:02:03,175 [Action Execution Pipeline 0 (tenant=clarity)] bpm.engine (clarity:process_admin:1366276979__F4236F3E-7F7A-4A13-976E-739F62AD7440:none) Error (will retry) caused by Step Instance: com.niku.bpm.engine.objects.StepInstance@600d9dfb [Id: 15683164 Process Instance Id: 10782086 Step Id: 5012973 State: BPM_SIS_EXEC_ACTION Step Name: null Start Date: 2015-07-01 21:30:04.0 Expected End Date: null Percent Complete: 0.0 Warned: false Retry Count: 1182 No of Pre Conditions: 1 No of Post Conditions: -1 Last Condition Eval Time: 1435779004555 Pre Condition Wait Events: null Post Condition Wait Events: null Pass Conditions: null Error Id: -1

Process Thread: com.niku.bpm.engine.objects.ProcessThread@1dfefb01 [Id: 11232086 Parent Step Instance Id: -1 Join Step Instance Id: -1]

Split Threads: null

Join Threads:null]

com.niku.bpm.BpmException: java.lang.NullPointerException

    at com.niku.bpm.engine.rules.ActionExecutionPipeline.execute(ActionExecutionPipeline.java:107)

    at com.niku.bpm.engine.rules.Pipeline.run(Pipeline.java:280)

Caused by: java.lang.NullPointerException

    at com.niku.bpm.engine.objects.StepInstance.processSynchronousStepAction(StepInstance.java:839)

    at com.niku.bpm.engine.rules.ActionExecutionPipeline.execute(ActionExecutionPipeline.java:64)

    ... 1 more

ERROR 2015-07-06 00:02:03,175 [Action Execution Pipeline 1 (tenant=clarity)] bpm.engine (clarity:process_admin:1366276979__F4236F3E-7F7A-4A13-976E-739F62AD7440:none) Error (will retry) caused by Step Instance: com.niku.bpm.engine.objects.StepInstance@1ac5479 [Id: 15685454 Process Instance Id: 10782341 Step Id: 5009799 State: BPM_SIS_EXEC_ACTION Step Name: null Start Date: 2015-07-02 19:20:02.0 Expected End Date: null Percent Complete: 0.0 Warned: false Retry Count: 916 No of Pre Conditions: -1 No of Post Conditions: -1 Last Condition Eval Time: 0 Pre Condition Wait Events: null Post Condition Wait Events: null Pass Conditions: null Error Id: -1

Process Thread: com.niku.bpm.engine.objects.ProcessThread@58ddd4ca [Id: 11232341 Parent Step Instance Id: -1 Join Step Instance Id: -1]

Split Threads: null

Join Threads:null]

com.niku.bpm.BpmException: java.lang.NullPointerException

    at com.niku.bpm.engine.rules.ActionExecutionPipeline.execute(ActionExecutionPipeline.java:107)

    at com.niku.bpm.engine.rules.Pipeline.run(Pipeline.java:280)

Caused by: java.lang.NullPointerException

    at com.niku.bpm.engine.objects.StepInstance.processSynchronousStepAction(StepInstance.java:839)

    at com.niku.bpm.engine.rules.ActionExecutionPipeline.execute(ActionExecutionPipeline.java:64)

    ... 1 more

ERROR 2015-07-06 00:02:03,176 [Action Execution Pipeline 2 (tenant=clarity)] bpm.engine (clarity:process_admin:1366276979__F4236F3E-7F7A-4A13-976E-739F62AD7440:none) Error (will retry) caused by Step Instance: com.niku.bpm.engine.objects.StepInstance@5f8d7b1b [Id: 15683742 Process Instance Id: 10782385 Step Id: 5013958 State: BPM_SIS_EXEC_ACTION Step Name: null Start Date: 2015-07-02 23:17:01.0 Expected End Date: null Percent Complete: 0.0 Warned: false Retry Count: 873 No of Pre Conditions: 1 No of Post Conditions: -1 Last Condition Eval Time: 1435871821054 Pre Condition Wait Events: null Post Condition Wait Events: null Pass Conditions: null Error Id: -1

Process Thread: com.niku.bpm.engine.objects.ProcessThread@418d5a9f [Id: 11232385 Parent Step Instance Id: -1 Join Step Instance Id: -1]

Split Threads: null

Join Threads:null]

com.niku.bpm.BpmException: java.lang.NullPointerException

    at com.niku.bpm.engine.rules.ActionExecutionPipeline.execute(ActionExecutionPipeline.java:107)

    at com.niku.bpm.engine.rules.Pipeline.run(Pipeline.java:280)

Caused by: java.lang.NullPointerException

    at com.niku.bpm.engine.objects.StepInstance.processSynchronousStepAction(StepInstance.java:839)

    at com.niku.bpm.engine.rules.ActionExecutionPipeline.execute(ActionExecutionPipeline.java:64)

    ... 1 more

ERROR 2015-07-06 00:02:03,182 [Action Execution Pipeline 1 (tenant=clarity)] bpm.engine (clarity:process_admin:1366276979__F4236F3E-7F7A-4A13-976E-739F62AD7440:none) Error (will retry) caused by Step Instance: com.niku.bpm.engine.objects.StepInstance@605e24a8 [Id: 15683944 Process Instance Id: 10778806 Step Id: 5009799 State: BPM_SIS_EXEC_ACTION Step Name: null Start Date: 2015-07-03 10:35:02.0 Expected End Date: null Percent Complete: 0.0 Warned: false Retry Count: 738 No of Pre Conditions: 1 No of Post Conditions: -1 Last Condition Eval Time: 1435912502060 Pre Condition Wait Events: null Post Condition Wait Events: null Pass Conditions: null Error Id: -1

Process Thread: com.niku.bpm.engine.objects.ProcessThread@44b8c305 [Id: 11228806 Parent Step Instance Id: -1 Join Step Instance Id: -1]

Split Threads: null

Join Threads:null]

com.niku.bpm.BpmException: java.lang.NullPointerException

    at com.niku.bpm.engine.rules.ActionExecutionPipeline.execute(ActionExecutionPipeline.java:107)

    at com.niku.bpm.engine.rules.Pipeline.run(Pipeline.java:280)

Caused by: java.lang.NullPointerException

    at com.niku.bpm.engine.objects.StepInstance.processSynchronousStepAction(StepInstance.java:839)

    at com.niku.bpm.engine.rules.ActionExecutionPipeline.execute(ActionExecutionPipeline.java:64)

    ... 1 more

 

It goes on and on and on

[Nick Darlington]

Thanks - so in this case the originating cause of your log messages are from this:

 

Caused by: java.lang.NullPointerException

    at com.niku.bpm.engine.objects.StepInstance.processSynchronousStepAction(StepInstance.java:839)

 

And that can have (one of) two logical causes:

 

1) Clarity wasn't able to obtain a reference to a running Process Definition Controller.

2) The class to hold the results of the step action that ran wasn't populated with anything once it completed executing the action.

 

I would rule out #1 on the basis that if a PDC isn't running, a new one will be created anyway, so the reference is almost certainly to be valid.

 

The absence of other error messages between the instances reported suggests that for #2 the query named 'bpm.pe.getSynchronouslyRunningAction' that ran using the step instance id value as a parameter to get the action results didn't return any rows.

 

The query in question doesn't really have any joins or other complexities that would cause it to not show records that exist in the tables:

 

SELECT id, step_action_id, status_code FROM BPM_RUN_STEP_ACTION_RESULTS WHERE step_instance_id = ? AND status_code = 'BPM_AIS_RUNNING'

 

So I could only suspect that the record was not inserted or had other values (different status_code or similar, perhaps due to being cancelled/deleted or something else) which would prevent it from returning something.

 

The end result of that query not returning values would be the exception you see in the logs.

[Deactivated User]

Thanks for looking into this.

Now that we know how to read the error message, is there a way get to the root cause of the problem which seems come at random, but then runs wild until the bg is restarted?

With the current logging level is there a place to look for more information after the problem has occurred?

 

You rule #1 out on the basis that if a PDC isn't running, a new one will be created anyway. How soon would that happen. If you look at the time the errors are repeated after  0,01 seconds or less

What is PDC?

[Nick Darlington]

urmas wrote:

 

What is PDC?

 

 

Sorry, PDC = Process Definition Controller.  The time shouldn't matter, if it needed to created one of these, it would do so along the way and before it reached the next few lines of code where you are getting the error - so out of the possible causes on the line erroring, this one shouldn't be a factor.

 

Getting to the root cause would almost certainly need to be conducted through a support ticket, whilst an occurrence of the problem is live, and checking/confirming it is an issue of the contents written / being written to the BPM_RUN_STEP_ACTION_RESULTS table for that step instance resulting in the query not returning any rows (based on review alone, that is all the conclusion I can make).

[Deactivated User]

Thanks nick_darlington, will look to that table.

The problem occurs at random and when it does the bg has to be restarted, so it might be hard to have the problem live which a case with support is open.

[Deactivated User]

So took one of the logs, filtered for the error and got those 5500 lines which all had hundreds of retries.

They had 63 unique step instances. Queried those with

Select    

id   

,STEP_INSTANCE_ID   

,STEP_ACTION_ID   

,ACTION_RESULT   

,ENGINE_RUN_ID   

,JOB_ID   

,STATUS_CODE   

,CUSTOM_SCRIPT_SESSION_ID   

from BPM_RUN_STEP_ACTION_RESULTS   

WHERE rownum < 200   

AND STEP_INSTANCE_ID in   

(   

    14409862

,    15431053

and so on

 

Got 43 records

ID    STEP_INSTANCE_ID    STEP_ACTION_ID    ACTION_RESULT    ENGINE_RUN_ID    JOB_ID    STATUS_CODE    CUSTOM_SCRIPT_SESSION_ID

12177480    14409862    5190262        -1        BPM_AIS_ACTIVE   

13115535    15431053    5208566        -1        BPM_AIS_ACTIVE   

13245080    15683164    5172447        -1        BPM_AIS_DONE    9844080

13245134    15683285    5194513        -1        BPM_AIS_DONE    9844136

13245145    15683310    5194513        -1        BPM_AIS_DONE    9844148

13245289    15683637    5160126        -1        BPM_AIS_DONE    9844294

13245324    15683723    5172447        -1        BPM_AIS_DONE    9844330

13245332    15683742    5194513        -1        BPM_AIS_DONE    9844339

13245376    15683842    5165324        -1        BPM_AIS_DONE    9844386

 

Sorry to say can't figure what that is telling me.

[navzjoshi00]

Any update on this, urmas ?

 

NJ

[Deactivated User]

Sorry to say can't figure what that is telling me.

[Nick Darlington]

It shows that the query ran by Clarity is returning no results when it was hoping to receive 1 record at least in order to avoid the null pointer error, as the query Clarity runs includes the criteria "AND status_code = 'BPM_AIS_RUNNING'".

 

It's going to take more than a discussion here to dig further than that though; some problems just require detailed debugging with a combination of tools (that can't be shared) and a reproducible system.

[Deactivated User]

Thanks

nick_darlington

will pass that on and hopefully the pain will grow so that we'll get to the bottom of it.

[Ferhat Kuran]

Sorry for pinging an old issue but we are facing the same problem in 15.3. Did you resolve this issue? If yes, could you please share the resolution with us.

 

Best Regards

[Deactivated User]

We did not pursue that any further than what is above. Apparently the processes eventually completed.

The system has since then been taken down.