Openj9: TestJlmRemoteMemoryNoAuth_0 powershell Stop-Process execute script failed

Created on 28 Oct 2020 · 15Comments · Source: eclipse/openj9

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_sanity.system_x86-64_windows_Nightly/523
TestJlmRemoteMemoryNoAuth_0
win2012-x86-2

STF 22:45:28.391 - +------ Step 4 - Stop LT1 process
STF 22:45:28.391 - | Kill running processes
STF 22:45:28.391 - |   Processes: [LT1]
STF 22:45:28.391 - |
STF 22:45:28.392 - Killing processes: LT1
STF 22:45:29.074 - Using powershell to kill LT1
STF 22:45:29.074 - Running command: cmd /c echo | powershell Stop-Process 192
STF 22:45:29.074 - Redirecting stderr to F:/Users/jenkins/workspace/Test_openjdk11_j9_sanity.system_x86-64_windows_Nightly/openjdk-tests/TKG/test_output_16038552302548/TestJlmRemoteMemoryNoAuth_0/20201027-223957-TestJlmRemoteMemoryNoAuth/results\kill_powershell.stderr
STF 22:45:29.074 - Redirecting stdout to F:/Users/jenkins/workspace/Test_openjdk11_j9_sanity.system_x86-64_windows_Nightly/openjdk-tests/TKG/test_output_16038552302548/TestJlmRemoteMemoryNoAuth_0/20201027-223957-TestJlmRemoteMemoryNoAuth/results\kill_powershell.stdout
STF 22:45:31.293 - **FAILED** execute script failed. Expected return value=0 Actual=1

kill_powershell.stderr and stdout are empty.

Maybe a machine problem.

test test failure

Source

pshipton

Most helpful comment

I've managed to reproduce this locally on a Windows 10 laptop. The Stop-Process command only gets the 'Access is denied' response occasionally. There are suggestions that it will occur if at the time of issuing the command the process happens to be performing certain operations - e.g. https://superuser.com/questions/585073/how-to-overcome-access-denied-when-killing-process-in-windows. I'll see if I can come up with some sort of a retry based workaround.

lumpfish on 26 Nov 2020

👍2

All 15 comments

Seems LT1 ran to completion.

22:44:44.824 - Completed 15.6%. Number of tests started=90311 (+6155)
22:45:04.714 - Completed 16.7%. Number of tests started=96430 (+6119)
22:45:24.714 - Completed 17.8%. Number of tests started=102518 (+6088)
22:45:44.824 - Completed 18.9%. Number of tests started=108746 (+6228)
22:46:04.824 - Completed 20.0%. Number of tests started=114975 (+6229)
...
23:08:24.715 - Completed 94.5%. Number of tests started=528398 (+6132)
23:08:44.746 - Completed 95.6%. Number of tests started=534494 (+6096)
23:09:04.903 - Completed 96.7%. Number of tests started=540731 (+6237)
23:09:24.840 - Completed 97.8%. Number of tests started=547024 (+6293)
23:09:44.731 - Completed 98.9%. Number of tests started=552957 (+5933)
23:10:04.465 - Thread completed. Suite=0 thread=29
23:10:04.465 - Thread completed. Suite=0 thread=18
23:10:04.465 - Thread completed. Suite=0 thread=6
23:10:04.465 - Thread completed. Suite=0 thread=9
23:10:04.481 - Thread completed. Suite=0 thread=12
23:10:04.496 - Thread completed. Suite=0 thread=13
23:10:04.496 - Thread completed. Suite=0 thread=5
23:10:04.512 - Thread completed. Suite=0 thread=10
23:10:04.512 - Thread completed. Suite=0 thread=28
23:10:04.512 - Thread completed. Suite=0 thread=1
23:10:04.528 - Thread completed. Suite=0 thread=0
23:10:04.543 - Thread completed. Suite=0 thread=24
23:10:04.559 - Thread completed. Suite=0 thread=22
23:10:04.575 - Thread completed. Suite=0 thread=27
23:10:04.606 - Thread completed. Suite=0 thread=7
23:10:04.606 - Thread completed. Suite=0 thread=25
23:10:04.606 - Thread completed. Suite=0 thread=14
23:10:04.621 - Thread completed. Suite=0 thread=21
23:10:04.637 - Thread completed. Suite=0 thread=26
23:10:04.637 - Thread completed. Suite=0 thread=20
23:10:04.668 - Thread completed. Suite=0 thread=23
23:10:04.668 - Thread completed. Suite=0 thread=17
23:10:04.684 - Thread completed. Suite=0 thread=3
23:10:04.700 - Thread completed. Suite=0 thread=16
23:10:04.700 - Thread completed. Suite=0 thread=2
23:10:04.715 - Thread completed. Suite=0 thread=19
23:10:04.731 - Thread completed. Suite=0 thread=11
23:10:04.746 - Completed 100.0%. Number of tests started=558876 (+5919)
23:10:04.762 - Thread completed. Suite=0 thread=15
23:10:04.762 - Thread completed. Suite=0 thread=8
23:10:04.778 - Thread completed. Suite=0 thread=4
23:10:04.856 - Test stopped due to reaching runtime limit
23:10:04.856 - Load test completed
23:10:04.856 -   Ran     : 558876
23:10:04.856 -   Passed  : 558876
23:10:04.856 -   Failed  : 0
23:10:04.856 -   Result  : PASSED

pshipton on 28 Oct 2020

This is likely to be a duplicate of https://github.com/AdoptOpenJDK/stf/issues/86

lumpfish on 5 Nov 2020

Not exactly the same - Could not terminate process PID=7080: Access is denied.
https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_sanity.system_x86-64_windows_Nightly/548

STF 22:46:52.606 - +------ Step 4 - Stop LT1 process
STF 22:46:52.606 - | Kill running processes
STF 22:46:52.606 - |   Processes: [LT1]
STF 22:46:52.606 - |
STF 22:46:52.606 - Killing processes: LT1
STF 22:46:53.165 - Using powershell to kill LT1
STF 22:46:53.165 - Running command: cmd /c echo | powershell Stop-Process 7080
STF 22:46:53.165 - Redirecting stderr to F:/Users/jenkins/workspace/Test_openjdk8_j9_sanity.system_x86-64_windows_Nightly/openjdk-tests/TKG/test_output_16057599861406/TestJlmRemoteMemoryNoAuth_0/20201118-224128-TestJlmRemoteMemoryNoAuth/results\kill_powershell.stderr
STF 22:46:53.165 - Redirecting stdout to F:/Users/jenkins/workspace/Test_openjdk8_j9_sanity.system_x86-64_windows_Nightly/openjdk-tests/TKG/test_output_16057599861406/TestJlmRemoteMemoryNoAuth_0/20201118-224128-TestJlmRemoteMemoryNoAuth/results\kill_powershell.stdout
Could not terminate process PID=7080: Access is denied.
**FAILED** at step 4 (Stop LT1 process). Expected return value=0 Actual=1 at F:/Users/jenkins/workspace/Test_openjdk8_j9_sanity.system_x86-64_windows_Nightly/openjdk-tests/\TKG\test_output_16057599861406\TestJlmRemoteMemoryNoAuth_0/20201118-224128-TestJlmRemoteMemoryNoAuth/execute.pl line 177.
STF 22:46:55.308 - **FAILED** execute script failed. Expected return value=0 Actual=1

pshipton on 19 Nov 2020

Before https://github.com/AdoptOpenJDK/stf/issues/86 was merged the pid being used as an argument to procdump,, Stop_Process etc. on machines with 64 bit perl was incorrect (pid 192 in this issue description).

The "Could not terminate process PID=7080: Access is denied." error is different - the pid is now looks correct but for some reason the user running the test appears not to be able to terminate a process started during the test.

Stop-Process is used a lot to terminate processes in the systemtests - particularly in the JLM tests. So elsewhere in the same test run we can see:

04:36:02  STF 22:36:01.075 - +------ Step 4 - Stop LT1 process
04:36:02  STF 22:36:01.075 - | Kill running processes
04:36:02  STF 22:36:01.075 - |   Processes: [LT1]
04:36:02  STF 22:36:01.075 - |
04:36:02  STF 22:36:01.075 - Killing processes: LT1
04:36:03  STF 22:36:03.039 - Using powershell to kill LT1
04:36:03  STF 22:36:03.040 - Running command: cmd /c echo | powershell Stop-Process 6516
04:36:03  STF 22:36:03.040 - Redirecting stderr to F:/Users/jenkins/workspace/Test_openjdk8_j9_sanity.system_x86-64_windows_Nightly/openjdk-tests/TKG/test_output_16057599861406/TestJlmRemoteClassNoAuth_0/20201118-223048-TestJlmRemoteClassNoAuth/results\kill_powershell.stderr
04:36:03  STF 22:36:03.040 - Redirecting stdout to F:/Users/jenkins/workspace/Test_openjdk8_j9_sanity.system_x86-64_windows_Nightly/openjdk-tests/TKG/test_output_16057599861406/TestJlmRemoteClassNoAuth_0/20201118-223048-TestJlmRemoteClassNoAuth/results\kill_powershell.stdout
04:36:05  STF 22:36:05.039 -   o Process LT1 killed

lumpfish on 19 Nov 2020

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_sanity.system_x86-32_windows_Nightly/552 - win2012-x86-2
TestJlmRemoteClassNoAuth_0

STF 21:30:34.999 - Redirecting stdout to F:/Users/jenkins/workspace/Test_openjdk8_j9_sanity.system_x86-32_windows_Nightly/openjdk-tests/TKG/test_output_16061017257266/TestJlmRemoteClassNoAuth_0/20201122-212507-TestJlmRemoteClassNoAuth/results\kill_powershell.stdout
Could not terminate process PID=4380: Access is denied.
**FAILED** at step 4 (Stop LT1 process). Expected return value=0 Actual=1 at F:/Users/jenkins/workspace/Test_openjdk8_j9_sanity.system_x86-32_windows_Nightly/openjdk-tests/\TKG\test_output_16061017257266\TestJlmRemoteClassNoAuth_0/20201122-212507-TestJlmRemoteClassNoAuth/execute.pl line 177.

pshipton on 23 Nov 2020

https://ci.eclipse.org/openj9/job/Test_openjdk15_j9_sanity.system_x86-64_windows_Nightly/113 - win2012-x86-5
TestJlmRemoteMemoryNoAuth_0
Could not terminate process PID=15012: Access is denied.

pshipton on 23 Nov 2020

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_sanity.system_x86-64_windows_Nightly/547 - win2012-x86-6
TestJlmRemoteClassNoAuth_0
Could not terminate process PID=6584: Access is denied.

pshipton on 24 Nov 2020

https://ci.eclipse.org/openj9/job/Test_openjdk15_j9_sanity.system_x86-64_windows_Nightly/115 - win2012-x86-4
TestJlmRemoteMemoryNoAuth_0
Could not terminate process PID=3052: Access is denied.

pshipton on 25 Nov 2020

The instance in previous comment was running on win2012-x86-4. Do these win2012-x86-n machines have anything in common (e.g. same hardware). Are there other Windows variants (i.e. not 2012) on which this is not being seen?

lumpfish on 25 Nov 2020

All the OpenJ9 Windows machines are the same. They are all virtual, and I think they are all clones of each other. @jdekonin can provide more details if necessary.

pshipton on 25 Nov 2020

All virtual, all clones, created on IBM Cloud. They are not very current with Adopt playbooks changes, but I can see this failure mode on my internal Windows 2016 machines/builds as well and they are current (up to about 2 weeks ago).

With the internal machines/builds, I also see sanity.system passing on the same machine that had failed the previous nights build which would seem to indicate is it not a machine setup/configuration issue.