#289: Missing autotest debug logs
----------------------+-----------------------------------------------------
Reporter: kparal | Owner:
Type: defect | Status: new
Priority: major | Milestone: Hot issues
Component: autotest | Resolution:
Keywords: |
----------------------+-----------------------------------------------------
Comment (by jlaska):
Replying to [comment:3 kparal]:
According to watcher logs, the jobs were created ok, but then went
aborted. Why?
The autotest schedule aborted them ''due to job timeout''. Which seems
odd given the timestamps around the messages. Perhaps this message is
emitted on autotestd shutdown or something? Not sure, will need to look
into autotest.
{{{
# for JOB in $(seq 77085 77090); do echo "== Job#$JOB Log ==" ; grep $JOB
/usr/share/autotest/logs/scheduler.log.2011-0* ; echo ; echo ; done
== Job#77085 Log ==
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:09
INFO |monitor_db:2770| creating block 77085/8
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:09
INFO |monitor_db:2906| post-repo-update:conflicts.i386/4/None (job 77085,
entry 77085) scheduled on 172.16.0.17, status=Queued
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:09
INFO |monitor_db:2815| 172.16.0.17/77085 (77085) Queued [active] ->
Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:15
INFO |monitor_db:2815| 172.16.0.17/77085 (77085) Verifying [active] ->
Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:21
INFO |monitor_db:2815| 172.16.0.17/77085 (77085) Verifying [active] ->
Pending
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:21
INFO |monitor_db:2815| 172.16.0.17/77085 (77085) Pending [active] ->
Starting
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:26
WARNI|monitor_db:0065| Aborting job 77085 due to job timeout
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:1054| Aborting 172.16.0.17/77085 (77085) Starting
[active,aborted]
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:2815| 172.16.0.17/77085 (77085) Starting [active,aborted]
-> Aborted
== Job#77086 Log ==
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:09
INFO |monitor_db:2770| creating block 77086/6
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:09
INFO |monitor_db:2906| post-repo-update:repoclosure.i386/4/None (job
77086, entry 77086) scheduled on
qa05.c.fedoraproject.org, status=Queued
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:09
INFO |monitor_db:2815|
qa05.c.fedoraproject.org/77086 (77086) Queued
[active] -> Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:15
INFO |monitor_db:2815|
qa05.c.fedoraproject.org/77086 (77086) Verifying
[active] -> Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:21
INFO |monitor_db:2815|
qa05.c.fedoraproject.org/77086 (77086) Verifying
[active] -> Pending
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:21
INFO |monitor_db:2815|
qa05.c.fedoraproject.org/77086 (77086) Pending
[active] -> Starting
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:26
WARNI|monitor_db:0065| Aborting job 77086 due to job timeout
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:1054| Aborting
qa05.c.fedoraproject.org/77086 (77086)
Starting [active,aborted]
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:2815|
qa05.c.fedoraproject.org/77086 (77086) Starting
[active,aborted] -> Aborted
== Job#77087 Log ==
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:09
INFO |monitor_db:2770| creating block 77087/7
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:09
INFO |monitor_db:2906| post-repo-update:rats_sanity.i386/4/None (job
77087, entry 77087) scheduled on
qa06.c.fedoraproject.org, status=Queued
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:09
INFO |monitor_db:2815|
qa06.c.fedoraproject.org/77087 (77087) Queued
[active] -> Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:15
INFO |monitor_db:2815|
qa06.c.fedoraproject.org/77087 (77087) Verifying
[active] -> Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:21
INFO |monitor_db:2815|
qa06.c.fedoraproject.org/77087 (77087) Verifying
[active] -> Pending
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:21
INFO |monitor_db:2815|
qa06.c.fedoraproject.org/77087 (77087) Pending
[active] -> Starting
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:26
WARNI|monitor_db:0065| Aborting job 77087 due to job timeout
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:1054| Aborting
qa06.c.fedoraproject.org/77087 (77087)
Starting [active,aborted]
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:2815|
qa06.c.fedoraproject.org/77087 (77087) Starting
[active,aborted] -> Aborted
== Job#77088 Log ==
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:08
INFO |monitor_db:2770| creating block 77088/9
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:08
INFO |monitor_db:2906| post-repo-update:conflicts.x86_64/1/None (job
77088, entry 77088) scheduled on 172.16.0.18, status=Queued
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:08
INFO |monitor_db:2815| 172.16.0.18/77088 (77088) Queued [active] ->
Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:15
INFO |monitor_db:2815| 172.16.0.18/77088 (77088) Verifying [active] ->
Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:21
INFO |monitor_db:2815| 172.16.0.18/77088 (77088) Verifying [active] ->
Pending
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:21
INFO |monitor_db:2815| 172.16.0.18/77088 (77088) Pending [active] ->
Starting
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:26
WARNI|monitor_db:0065| Aborting job 77088 due to job timeout
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:1054| Aborting 172.16.0.18/77088 (77088) Starting
[active,aborted]
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:2815| 172.16.0.18/77088 (77088) Starting [active,aborted]
-> Aborted
== Job#77089 Log ==
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:15
INFO |monitor_db:2770| creating block 77089/2
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:15
INFO |monitor_db:2906| post-repo-update:repoclosure.x86_64/1/None (job
77089, entry 77089) scheduled on
qa01.c.fedoraproject.org, status=Queued
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:15
INFO |monitor_db:2815|
qa01.c.fedoraproject.org/77089 (77089) Queued
[active] -> Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:21
INFO |monitor_db:2815|
qa01.c.fedoraproject.org/77089 (77089) Verifying
[active] -> Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:26
WARNI|monitor_db:0065| Aborting job 77089 due to job timeout
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
WARNI|monitor_db:2435| initialized <class '__main__.HostQueueEntry'>
77089
instance requery is updating: {'aborted': (0, 1)}
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:1054| Aborting
qa01.c.fedoraproject.org/77089 (77089)
Verifying [active,aborted]
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:2815|
qa01.c.fedoraproject.org/77089 (77089) Verifying
[active,aborted] -> Aborted
== Job#77090 Log ==
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:15
INFO |monitor_db:2770| creating block 77090/3
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:15
INFO |monitor_db:2906| post-repo-update:rats_sanity.x86_64/1/None (job
77090, entry 77090) scheduled on
qa02.c.fedoraproject.org, status=Queued
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:15
INFO |monitor_db:2815|
qa02.c.fedoraproject.org/77090 (77090) Queued
[active] -> Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:21
INFO |monitor_db:2815|
qa02.c.fedoraproject.org/77090 (77090) Verifying
[active] -> Verifying
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:26
WARNI|monitor_db:0065| Aborting job 77090 due to job timeout
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
WARNI|monitor_db:2435| initialized <class '__main__.HostQueueEntry'>
77090
instance requery is updating: {'aborted': (0, 1)}
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:1054| Aborting
qa02.c.fedoraproject.org/77090 (77090)
Verifying [active,aborted]
/usr/share/autotest/logs/scheduler.log.2011-03-23-09.14.33:04/02 21:32:27
INFO |monitor_db:2815|
qa02.c.fedoraproject.org/77090 (77090) Verifying
[active,aborted] -> Aborted
}}}
--
Ticket URL: <
https://fedorahosted.org/autoqa/ticket/289#comment:4>
AutoQA <
http://autoqa.fedorahosted.org>
Automated QA project