JCP and JWP write trace at start | java.lang.InterruptedException: "null"

Products

• CA Automic Workload Automation - Automation Engine
• CA Automic One Automation

Issue/Introduction

At startup JCP and JWP generate a forced traces. No technical problem visible, Advanced Search, Monitoring, Authentication, Rest API are working fine.

Log from JCP

20200122/170209.219 - 35   U00003472 Connection to Server 'AUTOMIC#WP011' has been closed.
20200122/170209.219 - 35   U00003407 Client connection '7' from '<ip address>:46602' has logged off from the Server.
20200122/170209.227 - 231       Jetty: Stopped ServerConnector@e85dce0{HTTP/1.1,[http/1.1]}{0.0.0.0:8088}
20200122/170209.227 - 231       Jetty: node0 Stopped scavenging
20200122/170209.229 - 231       Jetty: Stopped o.e.j.s.ServletContextHandler@6f45a9b9{/,null,UNAVAILABLE}
20200122/170209.249 - 35   U00003472 Connection to Server 'AUTOMIC#WP001' has been closed.
20200122/170209.250 - 35   U00003407 Client connection '6' from '<ip address>:46572' has logged off from the Server.
20200122/170209.255 - 37   U00045161 RunId '0' received from 'AUTOMIC#WP017'. Old RunId was '214882932'.
20200122/170209.255 - 37   U00003475 Server 'AUTOMIC#WP017' is the primary server of the system 'AUTOMIC'.
20200122/170209.291 - 231  U00045129 Search index update: deactivated.
20200122/170209.299 - 231  U00003432 Termination of Server 'AUTOMIC#CP001' initiated.
20200122/170209.300 - 231  U00045014 Exception 'java.lang.InterruptedException: "null"' at 'java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos():2067'.
20200122/170209.300 - 231  U00003620 Routine 'com.automic.kernel.impl.NetworkMessageDispatcher' forces trace because of error.
20200122/170209.315 - 231  U00003450 The TRACE file was opened with the switches '0000000000000000'.
20200122/170209.580 - 231  U00003449 Output to the TRACE file is finished.

Trace extract of the same JCP;

20200122/170209.400 - 231       Current memory usage of the heap:init = 394264576(385024K) used = 578421056(564864K) committed = 1811415040(1768960K) max = 3817865216(3728384K)
20200122/170209.400 - 231       Current memory usage of non-heap memory:init = 2555904(2496K) used = 99599112(97264K) committed = 104464384(102016K) max = -1(-1K)
20200122/170209.401 - 231       
20200122/170209.401 - 231       ----------------------- Stack Trace -----------------------
20200122/170209.401 - 231       java.lang.InterruptedException
20200122/170209.401 - 231           at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2067)
20200122/170209.401 - 231           at java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1475)
20200122/170209.401 - 231           at java.util.concurrent.Executors$DelegatedExecutorService.awaitTermination(Executors.java:675)
20200122/170209.401 - 231           at com.automic.kernel.impl.NetworkMessageDispatcher.shutdown(NetworkMessageDispatcher.java:152)
20200122/170209.401 - 231           at com.automic.kernel.impl.ServerProcess$2.runSave(ServerProcess.java:532)

Same errors found in JWP trace files.

When a PWP change happens, the JCP receives a message with a runid 0, which should not happen during the change.

Environment

 AUTOMATION ENGINE : 12.3.1 

 

Cause

A problem existed where JCP/REST API would shut down after receiving an invalid runId from the PWP. Instead they will re-request a new runId by disconnecting.

Resolution

This is fixed in version  AE 12.3.3, upgrade AE to this service or to a higher one.