Job errors with "ErrorMessage: None", possibly due to job timeout

I can't find anywhere in the message which particular target is in effect
when this happens. Any clue?

On 16 September 2013 08:20, Andrew McDermott <email address hidden>wrote:

> ** Description changed:
>
> The following job:
>
> - https://validation.linaro.org/scheduler/job/72876
> + https://validation.linaro.org/scheduler/job/72876
>
> reports back with:
>
> - Dispatcher error or test failure
> + Dispatcher error or test failure
>
> - ErrorMessage: None
> + ErrorMessage: None
>
> The job itself eventually runs the `jtreg' tests which can be seen in
> the output starting at:
>
> - 11:50:45 AM INFO: [ACTION-B] lava_test_shell is started with
> + 11:50:45 AM INFO: [ACTION-B] lava_test_shell is started with
> {u'timeout': 180000, u'testdef_repos': [{u'git-repo': u'git...
>
> and the timeout for that test is 50 hours which, as an aside, I'm
> suspecting is not long enough for this particular test/job. I would have
> expected LAVA to fail with a `timeout error' but I don't see that.
>
> And looking through the test runs I see that test 'lava_test_shell #13'
> fails with:
>
> + https://validation.linaro.org/dashboard/streams/public/team/linaro/pre-
> + built-vexpress64/bundles/0a75f2ca9c78f77fbadf327f8371ea7e5f7287c5
> + /344362fe-1dd9-11e3-8b3b-001e671608cd/result/13/
> +
> Lava failed at action lava_test_shell with error:None
> Traceback (most recent call last):
> - File
> "/srv/lava<email address hidden>/lava_dispatcher/job.py",
> line 254, in run
> - action.run(**params)
> - File
> "/srv/lava<email address hidden>/lava_dispatcher/actions/lava_test_shell.py",
> line 559, in run
> - while self._keep_running(runner, timeout, signal_director):
> - File
> "/srv/lava<email address hidden>/lava_dispatcher/actions/lava_test_shell.py",
> line 574, in _keep_running
> - idx = runner._connection.expect(patterns, timeout=timeout)
> - File
> "/srv/lava<email address hidden>/lava_dispatcher/utils.py",
> line 206, in expect
> - return super(logging_spawn, self).expect(*args, **kw)
> - File "/srv/lava/.cache/eggs/pexpect-2.4-py2.7.egg/pexpect.py", line
> 1316, in expect
> - return self.expect_list(compiled_pattern_list, timeout,
> searchwindowsize)
> - File "/srv/lava/.cache/eggs/pexpect-2.4-py2.7.egg/pexpect.py", line
> 1330, in expect_list
> - return self.expect_loop(searcher_re(pattern_list), timeout,
> searchwindowsize)
> - File "/srv/lava/.cache/eggs/pexpect-2.4-py2.7.egg/pexpect.py", line
> 1383, in expect_loop
> - c = self.read_nonblocking (self.maxread, timeout)
> - File "/srv/lava/.cache/eggs/pexpect-2.4-py2.7.egg/pexpect.py", line
> 820, in read_nonblocking
> - r,w,e = self.__select([self.child_fd], [], [], timeout)
> - File "/srv/lava/.cache/eggs/pexpect-2.4-py2.7.egg/pexpect.py", line
> 1554, in __select
> - return se...

It appears the job is timing out. We will investigate.

On 16 September 2013 07:47, Andrew Johnson <email address hidden> wrote:

> I can't find anywhere in the message which particular target is in effect
> when this happens. Any clue?
>
>
> On 16 September 2013 08:20, Andrew McDermott
> <email address hidden>wrote:
>
> > ** Description changed:
> >
> > The following job:
> >
> > - https://validation.linaro.org/scheduler/job/72876
> > + https://validation.linaro.org/scheduler/job/72876
> >
> > reports back with:
> >
> > - Dispatcher error or test failure
> > + Dispatcher error or test failure
> >
> > - ErrorMessage: None
> > + ErrorMessage: None
> >
> > The job itself eventually runs the `jtreg' tests which can be seen in
> > the output starting at:
> >
> > - 11:50:45 AM INFO: [ACTION-B] lava_test_shell is started with
> > + 11:50:45 AM INFO: [ACTION-B] lava_test_shell is started with
> > {u'timeout': 180000, u'testdef_repos': [{u'git-repo': u'git...
> >
> > and the timeout for that test is 50 hours which, as an aside, I'm
> > suspecting is not long enough for this particular test/job. I would
> have
> > expected LAVA to fail with a `timeout error' but I don't see that.
> >
> > And looking through the test runs I see that test 'lava_test_shell #13'
> > fails with:
> >
> > +
> https://validation.linaro.org/dashboard/streams/public/team/linaro/pre-
> > + built-vexpress64/bundles/0a75f2ca9c78f77fbadf327f8371ea7e5f7287c5
> > + /344362fe-1dd9-11e3-8b3b-001e671608cd/result/13/
> > +
> > Lava failed at action lava_test_shell with error:None
> > Traceback (most recent call last):
> > - File
> >
> "/srv/lava<email address hidden>
> /lava_dispatcher/job.py",
> > line 254, in run
> > - action.run(**params)
> > - File
> >
> "/srv/lava<email address hidden>
> /lava_dispatcher/actions/lava_test_shell.py",
> > line 559, in run
> > - while self._keep_running(runner, timeout, signal_director):
> > - File
> >
> "/srv/lava<email address hidden>
> /lava_dispatcher/actions/lava_test_shell.py",
> > line 574, in _keep_running
> > - idx = runner._connection.expect(patterns, timeout=timeout)
> > - File
> >
> "/srv/lava<email address hidden>
> /lava_dispatcher/utils.py",
> > line 206, in expect
> > - return super(logging_spawn, self).expect(*args, **kw)
> > - File "/srv/lava/.cache/eggs/pexpect-2.4-py2.7.egg/pexpect.py", line
> > 1316, in expect
> > - return self.expect_list(compiled_pattern_list, timeout,
> > searchwindowsize)
> > - File "/srv/lava/.cache/eggs/pexpect-2.4-py2.7.egg/pexpect.py", line
> > 1330, in expect_list
> > - return self.expect_loop(searcher_re(pattern_list), timeout,
> > searchwindowsize)
> > - File "/srv/lava/.cache/eggs/pexpect-2.4-py2.7.egg/pexpect.py", line
> > 1383, in expect_loop
> > - c = self.read_nonblocking (self.ma...

AndyJ:

When you say target, that to me is a device. :)

So, this is running on the ARMv8 foundation model.

If your question is about which Java test is in effect then its the complete jtreg test that fails.

Tyler: when you say it appears the job is timing out, do you mean it is timing out, but on the 24 hour boundary?

Andy J:

Looking through the complete log output at:

  https://validation.linaro.org/scheduler/job/72876/log_file

the tests that were running or about to run were jdk_security:

FAILED: sample/mergesort/MergeSortTest.java
 TEST STATS: name=jdk_other run=75 pass=67 fail=8 excluded=2
 + rm -rf /tmp/jtreg/jdk_other.986
 + exit 0
 + test_dir=/lava/tests/0_jtreg/openjdk8-aarch64-test-archive/openjdk8-aarch64-port-snapshot/jdk/test
 + test_to_run=jdk_security1
 + t=/tmp/jtreg/jdk_security1.2541
 + rm -rf /tmp/jtreg/jdk_security1.2541
 + mkdir -p /tmp/jtreg/jdk_security1.2541
 + to=/tmp/jtreg/jdk_security1.2541/testoutput
 + '[' -n '' ']'
 + lava-test-case jdk_security1 --shell make -C /lava/tests/0_jtreg/openjdk8-aarch64-test-archive/openjdk8-aarch64-port-snapshot/jdk/test PRODUCT_HOME=/usr/lib/jvm/java-8-openjdk JTREG=/lava/tests/0_jtreg/jtreg-bin/jtreg/linux/bin/jtreg-lava JT_HOME=/lava/tests/0_jtreg/jtreg-bin/jtreg ALT_OUTPUTDIR=/tmp/jtreg/jdk_security1.2541 jdk_security1
 <LAVA_SIGNAL_STARTTC jdk_security1>
 echo LAVA_ACK
 make: Entering directory `/lava/tests/0_jtreg/openjdk8-aarch64-test-archive/openjdk8-aarch64-port-snapshot/jdk/test'
 echo "Running tests in agentvm mode: java/security"
 Running tests in agentvm mode: java/security
 make TEST_DEPENDENCIES="java/security" TESTDIRS="java/security" USE_JTREG_AGENTVM=true UNIQUE_DIR=jdk_security1 jtreg_tests
 make[1]: Entering directory `/lava/tests/0_jtreg/openjdk8-aarch64-test-archive/openjdk8-aarch64-port-snapshot/jdk/test'
 make[1]: Warning: File `/lava/tests/0_jtreg/jtreg-bin/jtreg/linux/bin/jtreg-lava' has modification time 278411 s in the future
 Excluding list contains 0 items
 ( ( JT_HOME=/lava/tests/0_jtreg/jtreg-bin/jtreg; export JT_HOME; /lava/tests/0_jtreg/jtreg-bin/jtreg/linux/bin/jtreg-lava -agentvm -a -ea -esa -v:fail,error,time -retain:fail,error -ignore:quiet -timeoutFactor:4 -J-Xmx512m -r:/tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/JTreport -w:/tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/JTwork -jdk:/usr/lib/jvm/java-8-openjdk -exclude:/tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/excludelist.txt java/security ) ; ( jtregExitCode=$? && _summary="/tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/JTreport/text/summary.txt"; rm -f -f /tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/Stats.txt /tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/runlist.txt /tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/passlist.txt /tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/faillist.txt /tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/exitcode.txt; echo "${jtregExitCode}" > /tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/exitcode.txt; if [ -r "${_summary}" ] ; then echo "Summary: jdk_security1" > /tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/Stats.txt; expand ${_summary} | egrep -v ' Not run.' > /tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/runlist.txt; egrep ' Passed.' /tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/runlist.txt | egrep -v ' Error.' | egrep -v ' Failed.' > /tmp/jtreg/jdk_security1.2541/testoutput/jdk_security1/passlist.txt; ( egrep ' Failed.' /tmp/jtreg/jdk_security1.2541/test...

We really just need a more useful error message when the timeout occurs

Dave, it's odd that the job runs for exactly 24 hours though, irrespective of the error message.

Any update on this issue. Looks like this particular issue is again affected by the same issue:
http://validation.linaro.org/scheduler/job/88719