What do these WARN messages signify?

[amit joshi]

Hi,

I am seeing these WARN messages in the log files (CA-RA 6.6.9640 on RHEL)

on NAC in nolio_dm_all.log

"A soft-locked cache entry was expired by the underlying Ehcache. If this happens regularly you should consider increasing the cache timeouts and/or capacity limits"

"Trying to update job progress smaller than current progress. currentJobProgress [57.142857142857146]newJobProgress [56.70995670995671]"

"new event posted for job[id=7652134] but no event bus for that job exists. Event.toString()=JobStateChangedEvent[jobId=7652134, newJobState=[major=InQueue, minor=None], newJobServerStates[[jobServerId=10483927, newJobServerState=INIT],[jobServerId=10483926, newJobServerState=INIT],[jobServerId=10483925, newJobServerState=INIT]]]]"

What does it signify? Why do i see these WARN messages? What action is needed? What information are these messages giving out?

Best regards,
Amit Joshi

------------------------------
Senior DevOps Engineer
Tieto Finland Oy
------------------------------

[Saurabh Jain]

Hello Amit,
 Please find answer to your queries.

"A soft-locked cache entry was expired by the underlying Ehcache. If this happens regularly you should consider increasing the cache timeouts and/or capacity limits"

Why this message:

This is due to some bulk load activities RA do and need to evict some entries to accommodate.It is partially correct because this is just one of the possible scenarios to get this message. Another scenario is when hibernate can't find an item in the cache. This might happen because of running native queries - hibernate evicts some entities or even all entities from the 2-nd level cache after the native query is executed. We should do nothing for the first scenario and just ignore these messages. To understand if we have the first scenario we need to use JMX console and do the following actions:

1. Enable the cache statistics with calling the setStatisticsEnabled method from the noliocenter:name=dataModel manager

2. Check statistic with calling the getL2StatisticsAsHtml method from the noliocenter:name=dataModel manager.

Values, from the "mem" column, should be compared with the maxElementsInMemory value specified for the entity in the ehcache.xml file (this xml file can be found in the ra-business-logic-services-6.8.0.jar file) and in case these values are almost equal or even equal (which means we reached the cache limit) we might get this message in the nolio logs.

Changing timeout setting of cache, as per document https://ca-broadcomcsm.wolkenservicedesk.com/wolken/esd/knowledgebase_search?articleId=112368

Recommendation: As I mentioned above we might change cache settings in the ra-business-logic-services-6.8.0.jar\ehcache.xml but I don't think it is a good idea to change settings in the archived file. We need to understand the reason customer might want to do these changes.

In general these messages should be ignored in almost all cases.

"Trying to update job progress smaller than current progress. currentJobProgress [57.142857142857146]newJobProgress [56.70995670995671]"
This message just says that some notification came to RA which try to update execution job progress with the value less than the current progress value and because of that job's progress won't be updated. So nothing critical here and tis message might be ignored.
Nevertheless, I briefly checked the code and I believe there is something to improve. In the ExecutionStatusServiceImpl we are calculating the progress of the job (createJobServerStateDetails method) and It calculates this value depending on the state of the execution job:

1. If execution job is in the FILES_DISTRIBUTION state (distributing flow to the agent) the job progress is equal to the progress file transfer progress. This might update execution job progress with values from 0% to 100%.
2. All other steps - the execution job's progress is calculated depending on amount of actions/sub-flows executed on an agent. This might also update execution job progress with values from 0% to 100%.

Basically, this means that it will try to update execution job progress from 0% to 100% during the FILES_DISTRIBUTION state and after that it will try to update progress with values from 0% to 100% depending on the progress of the flow execution. The mentioned log entry will be created in case the previously updated value (with the FILES_DISTRIBUTION step) is higher than the current one. 

"new event posted for job[id=7652134] but no event bus for that job exists. Event.toString()=JobStateChangedEvent[jobId=7652134, newJobState=[major=InQueue, minor=None], newJobServerStates[[jobServerId=10483927, newJobServerState=INIT],[jobServerId=10483926, newJobServerState=INIT],[jobServerId=10483925, newJobServerState=INIT]]]]"
I checked this message and there is also something to improve but there is nothing critical about this message and customers should not worry about it.
In general this log entry is created because of the following order of the actions performed while ExecutionJob is created:
1. ExecutionJob instance is created in the New state
2. ExecutionJob is moved to the InQueue state and sends notification to the relevant event bus notifying system that job's state was changed (That is where this log entry is created)
3. JobExecutor starts running the job and creates the relevant event bus.

The problem is because of the message that is sent in the step 2 while the relevant event bus is not created. In this case, this message is just ignored.

------------------------------
Regards,
Saurabh
------------------------------