cmdLineTester_criu_jitPostRestore failing in OMR acceptance on alinux

[pshipton]

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.functional_aarch64_linux_OMR_testList_0/43/
https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.functional_aarch64_linux_OMR_testList_1/43/
https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.functional_aarch64_linux_OMR_testList_0/355
https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.functional_aarch64_linux_OMR_testList_1/355
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.functional_aarch64_linux_OMR_testList_0/371
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.functional_aarch64_linux_OMR_testList_1/371
cmdLineTester_criu_jitPostRestore - all variants 0,1,2

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.functional_aarch64_linux_OMR_testList_0/371
cmdLineTester_criu_jitPostRestore_1

06:13:22  Testing: Check Verbose Log
06:13:22  Test start time: 2023/06/28 10:13:22 Coordinated Universal Time
06:13:22  Running command: bash /home/jenkins/workspace/Test_openjdk11_j9_sanity.functional_aarch64_linux_OMR_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuCatVlog.sh vlog true true
06:13:22  Time spent starting: 7 milliseconds
06:13:22  Time spent executing: 20 milliseconds
06:13:22  Test result: FAILED
06:13:22  Output from test:
06:13:22   [OUT] start running script
06:13:22   [OUT] Outputting vlog vlog
06:13:22   [OUT] �����/Ready for restore
06:13:22   [OUT] �����/Start and elapsed time: startTime=25037557, elapsedTime= 13179
06:13:22   [OUT] �����/Reset start and elapsed time: startTime=25053074, elapsedTime=     0
06:13:22   [OUT] #INFO:  Stopping compilation thread, vmThread pointer 0000000000015C00, thread ID 1
06:13:22   [OUT] #INFO:  Stopping compilation thread, vmThread pointer 000000000001CB00, thread ID 4
06:13:22   [OUT] #INFO:  Stopping compilation thread, vmThread pointer 0000000000021500, thread ID 6
06:13:22   [OUT] #INFO:  Stopping compilation thread, vmThread pointer 0000000000018100, thread ID 2
06:13:22   [OUT] #INFO:  Stopping compilation thread, vmThread pointer 0000000000013700, thread ID 0
06:13:22   [OUT] #INFO:  Stopping compilation thread, vmThread pointer 000000000001F000, thread ID 5
06:13:22   [OUT] #INFO:  Stopping compilation thread, vmThread pointer 000000000001A600, thread ID 3
06:13:22   [OUT] #INFO:  Stopping compilation thread, vmThread pointer 0000000000036100, thread ID 15
06:13:22   [OUT] 
06:13:22   [OUT] Outputting previous test output
06:13:22   [OUT] Pre-checkpoint
06:13:22   [OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Wed Jun 28 10:13:14 UTC 2023, System.currentTimeMillis(): 1687947194457, System.nanoTime(): 422616491989023
06:13:22   [OUT] Post-checkpoint
06:13:22   [OUT] 
06:13:22   [OUT] Removed test output files
06:13:22   [OUT] finished script
06:13:22  >> Success condition was not found: [Output match: CHECKPOINT RESTORE: Ready for restore]
06:13:22  >> Success condition was not found: [Output match: CAT VLOG FORCE PASS]

Change from nightly build (where this did not occur) is one OMR change.
eclipse-openj9/openj9-omr@0c448df...d384988
eclipse-omr/omr#5508

[pshipton]

@tajila @jdmpapin @0xdaryl @mpirvu fyi

Until we figure out what's going on, this is blocking OMR acceptance.

[pshipton]

Also this is new #17185 (comment)

[pshipton]

More failures, not all platforms are completed.
https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.functional_s390x_linux_OMR/352
https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.functional_s390x_linux_OMR/44
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.functional_x86-64_linux_OMR/455
cmdLineTester_criu_jitPostRestore_0
cmdLineTester_criu_jitPostRestore_1
cmdLineTester_criu_jitPostRestore_2
cmdLineTester_criu_jitserverAcrossCheckpoint_0

[dsouzai]

The test is failing because it's looking for

06:13:22  >> Success condition was not found: [Output match: CHECKPOINT RESTORE: Ready for restore]

but the actual output is

�����/Ready for restore

Is there something that's an issue with the verbose log output on alinux?

On s390x failing job the output is

`Ready for restore

[dsouzai]

Oh, looks like in that OMR change, TR_Vlog_BI was added to the TR_VlogTag enum, but the corresponding string wasn't added to TR_VerboseLog::_vlogTable.

Fyi @jdmpapin @xiacijie @mingweiarthurli

[mingweiarthurli]

Hi, sorry for the bug. I will fix this soon.

[mingweiarthurli]

Hi @pshipton @dsouzai, I have fixed this issue by adding the corresponding string to TR_VerboseLog::_vlogTable. The change has been pushed to our repo.
Could you please try running Jeknkins again? Sorry for the inconvenience.

[jdmpapin]

@mingweiarthurli Please open a pull request

[mingweiarthurli]

Hi @jdmpapin, I opened a pull request now to close this issue.