The Application Server Java stopped - No appropriate logs can be found for investigation
Symptom:
AS Java terminates and no relevant log enries can be found in std_server log file.
AS Java terminates with exit code:
In dev_server files it can be seen that the system is terminated with for example exit code 1:
F [Thr 3342] Thu Jan 26 08:08:04 2017
F [Thr 3342] *** LOG => SfCJavaVm: exit hook is called. (rc = 1)
F ********************************************************************************
F *** ERROR => Java node 'server1<x> terminated with exit code 1.
F ***
F *** Please see section 'Java program exit codes'
F *** in SAP Note 1316652 for additional information and trouble shooting advice.
F ********************************************************************************
F [Thr 3342] *** LOG => exiting (exitcode 1, retcode 1).
M [Thr 3342] CCMS: CCMS Monitoring Cleanup finished successfully.
Or for example with exit code 11112:
F [Thr 140265776588544] Tue Jan 10 09:55:42 2017
F [Thr 140265776588544] *** LOG => SfCJavaVm: exit hook is called. (rc = -11112)
F ********************************************************************************
F *** ERROR => Java node 'server<x>' terminated with exit code -11112.
F ***
F *** Please see section 'Java program exit codes'
F *** in SAP Note 1316652 for additional information and trouble shooting advice.
F ********************************************************************************
F [Thr 140265776588544] *** LOG => exiting (exitcode -11112, retcode 2).
M [Thr 140265776588544] CCMS: CCMS Monitoring Cleanup finished successfully.
Shutdown occures due to expired time seen in dev_server log file:
F [Thr 139643987195744] *** LOG => Timer expired (120000 ms).
Or:
ERROR => Shutdown timer expired.
No further related entries can be found either in the instance work directory logs or in the default trace. After this AS Java can be started without any issue.
Resolution:
1. Open Configtool.
2. Choose the affected instance -> VM Parameters -> Additional -> click in New -> next to "Name" put "-XX:+DumpStackTraceOnSystemExit" -> press "OK".
3. Then you will see "-XX:+DumpStackTraceOnSystemExit" as a parameter under "VM Parameters". This parameter will be generating a thread dump from the shut down halt.
4. Restart the whole instance in order to validate changes.
5. Similar thread dumps can be seen in the latest dev_server log files after the next shutdown halt:
J Thu Jan 5 05:34:07 2017
J JVM_Halt called with exit code 1
J "Managed_Application_Thread_26" #160 prio=5 os_prio=0 cpu=320.00 [reset 40.00] ms elapsed=65.97 [reset 1.01] s allocated=35801568 B (34.14 MB) [reset 3417824 B (3.26 MB)] defined_classes=46
J io= file i/o: 72293/14580 B, net i/o: 1747986/573008 B, files opened:3, socks opened:0 [reset file i/o: 72293/14580 B, net i/o: 82198/44320 B, files opened:3, socks opened:0 ]
J user="XXXXX" application="ariba.com/ariba_JobBean" isapplicationthread="true" tid=0x0000000001e88800 nid=0x1f04e / 127054 pthread-id=139842005186304 runnable [_thread_in_vm (_running), stack(0x00007f2f80eb3000,0x00007f2f810b4000)] [0x00007f2f810af000]
J java.lang.Thread.State: RUNNABLE
J at java.lang.Shutdown.halt0(I)V(Native Method)
J at java.lang.Shutdown.halt(I)V(Shutdown.java:95)
J - locked <0x0000000747e92e78> (a java.lang.Shutdown$Lock)
J at java.lang.Shutdown.exit(I)V(Shutdown.java:169)
J - locked <0x0000000747e04a98> (a java.lang.Class for java.lang.Shutdown)
J at java.lang.Runtime.exit(I)V(Runtime.java:90)
J at java.lang.System.exit(I)V(System.java:910)
J at ariba.filetransferclient.Util.zip(Ljava/io/File;Ljava/io/File;Ljava/io/FilenameFilter;)V(Util.java:390)
J at ariba.filetransferclient.Util.generateZip(Ljava/io/File;Ljava/io/File;Ljava/io/FilenameFilter;Lorg/apache/commons/logging/Log;)V(Util.java:489)
The above example shows that ariba.com/ariba_JobBean application somehow gave a sign for shutdown process. In this case an ARIBA expert should analyse the background of the issue further.
J Fri Jan 13 06:58:33 2017
J JVM_Halt called with exit code -11112
J "Thread-86" #2642 prio=5 os_prio=0 cpu=70.00 [reset 70.00] ms elapsed=20.09 [reset 20.09] s allocated=8080384 B (7.71 MB) [reset 8080384 B (7.71 MB)] defined_classes=6
J io= file i/o: 8472/3475 B, net i/o: 357/85161 B, files opened:5, socks opened:-9 [reset file i/o: 8472/3475 B, net i/o: 357/85161 B, files opened:5, socks opened:-9 ]
J user="Administrator" isapplicationthread="true" tid=0x00007ff874da9800 nid=0x6b5b / 27483 pthread-id=140705505916672 runnable [_thread_in_vm (_running), stack(0x00007ff88d92b000,0x00007ff88db2c000)] [0x00007ff88db2a000]
J java.lang.Thread.State: RUNNABLE
J at java.lang.Shutdown.halt0(I)V(Native Method)
J at java.lang.Shutdown.halt(I)V(Shutdown.java:139)
J - locked <0x00000007563f8e40> (a java.lang.Shutdown$Lock)
J at java.lang.Shutdown.exit(I)V(Shutdown.java:213)
J - locked <0x00000007563f4098> (a java.lang.Class for java.lang.Shutdown)
J at java.lang.Runtime.exit(I)V(Runtime.java:109)
J at java.lang.System.exit(I)V(System.java:977)
J at com.sap.engine.core.Framework.shutDown0(ILjava/util/Properties;)V(Framework.java:550)
J - locked <0x00000007583fab88> (a com.sap.engine.core.Framework)
According to the previous entries someone with Administrator user shut down the AS Java Systems with sapcontrol, jsmon/jcmon etc. As this user is Administrator, it is not possible to find out who and why had restarted the Systems. In this case it is recommended to change the password of the Administrator user.
These two thread dumps are only examples. Other scenario might happen in different cases. This method is a good way to identify the reason of the shutdown of AS java systems.
Reference Snote: 2457769
