5:56 a.m.
#289: Missing autotest debug logs
----------------------+-----------------------------------------------------
Reporter: kparal | Owner:
Type: defect | Status: new
Priority: major | Milestone: Hot issues
Component: autotest | Keywords:
----------------------+-----------------------------------------------------
I've found a test run where autotest debug logs are missing. What's wrong?
We need them.
http://autoqa.fedoraproject.org/results/72107-autotest/qa06.c.fedoraproje...
--
Ticket URL: <https://fedorahosted.org/autoqa/ticket/289>
AutoQA <http://autoqa.fedorahosted.org>
Automated QA project
8:57 a.m.
#289: Missing autotest debug logs
----------------------+-----------------------------------------------------
Reporter: kparal | Owner:
Type: defect | Status: new
Priority: major | Milestone: Hot issues
Component: autotest | Resolution:
Keywords: |
----------------------+-----------------------------------------------------
Comment (by jlaska):
We ran into disk space issues on our autoqa/autotest server yesterday.
I've resolved the issue by pruning old test results to free up space. I'm
also using this experience to help plan system requirements for our next
autoqa/autotest server.
I only see three results which exhibit this problem ...
*
http://autoqa.fedoraproject.org/results/70273-autotest/qa03.c.fedoraproje...
*
http://autoqa.fedoraproject.org/results/72107-autotest/qa06.c.fedoraproje...
*
http://autoqa.fedoraproject.org/results/72110-autotest/qa03.c.fedoraproje...
My suspicion is that this test couldn't upload all of it's logs due to
disk space issues. However, I can't really confirm that idea presently.
I can't think of anything to do with this ticket, other than to continue
monitoring for the issue. If we are not seeing these types of issues over
the next few days, I'm comfortable closing the ticket, and attributing it
to the disk space shortage.
--
Ticket URL: <https://fedorahosted.org/autoqa/ticket/289#comment:1>
AutoQA <http://autoqa.fedorahosted.org>
Automated QA project
6:29 a.m.
#289: Missing autotest debug logs
----------------------+-----------------------------------------------------
Reporter: kparal | Owner:
Type: defect | Status: new
Priority: major | Milestone: Hot issues
Component: autotest | Resolution:
Keywords: |
----------------------+-----------------------------------------------------
Comment (by kparal):
{{{
# cd /usr/share/autotest/results/
# df -h .
Filesystem Size Used Avail Use% Mounted on
/dev/mapper/GuestVolGroup00-root
18G 10G 6.4G 61% /
# for R in *-autotest; do if [ -z "`find $R -type d -name 'debug'`"
];
then echo $R; fi; done
70273-autotest
72107-autotest
72110-autotest
72289-autotest
72807-autotest
72808-autotest
72809-autotest
72985-autotest
77085-autotest
77086-autotest
77087-autotest
77088-autotest
77089-autotest
77090-autotest
}}}
Still happens.
--
Ticket URL: <https://fedorahosted.org/autoqa/ticket/289#comment:2>
AutoQA <http://autoqa.fedorahosted.org>
Automated QA project
6:54 a.m.
#289: Missing autotest debug logs
----------------------+-----------------------------------------------------
Reporter: kparal | Owner:
Type: defect | Status: new
Priority: major | Milestone: Hot issues
Component: autotest | Resolution:
Keywords: |
----------------------+-----------------------------------------------------
Comment (by kparal):
It's probably another issue for the last occurrences, only queue.log is
there.
http://autoqa.fedoraproject.org/results/77090-autotest/
And here's the tasks' status:
{{{
# atest job list -a | grep -E '770(8[5-9]|90)'
77085 autotest post-repo-update:conflicts.i386
Aborted=1(100.0%)
77086 autotest post-repo-update:repoclosure.i386
Aborted=1(100.0%)
77087 autotest post-repo-update:rats_sanity.i386
Aborted=1(100.0%)
77088 autotest post-repo-update:conflicts.x86_64
Aborted=1(100.0%)
77089 autotest post-repo-update:repoclosure.x86_64
Aborted=1(100.0%)
77090 autotest post-repo-update:rats_sanity.x86_64
Aborted=1(100.0%)
}}}
According to watcher logs, the jobs were created ok, but then went
aborted. Why?
All the logs in logs/ directory end by 2011-03-23 date. Should we create a
separate issues for this?
--
Ticket URL: <https://fedorahosted.org/autoqa/ticket/289#comment:3>
AutoQA <http://autoqa.fedorahosted.org>
Automated QA project
2:07 p.m.
#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
7:22 a.m.
New subject: [AutoQA] #289: Jobs are aborted prematurely
#289: Jobs are aborted prematurely
----------------------+-----------------------------------------------------
Reporter: kparal | Owner:
Type: defect | Status: new
Priority: major | Milestone: Hot issues
Component: autotest | Resolution:
Keywords: |
----------------------+-----------------------------------------------------
Changes (by kparal):
* summary: Missing autotest debug logs => Jobs are aborted prematurely
Comment:
This is still happening, I just reproduced it on our staging server with
autotest 0.13.1.
Job 8636 was created at 2011-12-12 04:20:32. And it was aborted in 16
minutes:
{{{
12/12 04:36:22 INFO |monitor_db:0053| Running periodic cleanup
12/12 04:36:22 INFO |monitor_db:0063| Aborting all jobs that have timed
out and are not complete
12/12 04:36:24 WARNI|monitor_db:0067| Aborting job 8636 due to job timeout
12/12 04:36:24 INFO |monitor_db:0075| Aborting all jobs that have passed
maximum runtime
12/12 04:36:24 INFO |monitor_db:0146| Clear out blocks for all completed
jobs.
12/12 04:36:24 INFO |monitor_db:0090| Cleaning db inconsistencies
12/12 04:36:24 INFO |monitor_db:0734| Aborting no host/8636 (8636) Queued
[aborted]
12/12 04:36:24 INFO |scheduler_:0561| no host/8636 (8636) Queued [aborted]
-> Aborted
}}}
Current settings are:
{{{
job_timeout_default: 1
job_max_runtime_hrs_default: 2
}}}
--
Ticket URL: <https://fedorahosted.org/autoqa/ticket/289#comment:5>
AutoQA <http://autoqa.fedorahosted.org>
Automated QA project
5:13 a.m.
New subject: [AutoQA] #289: Jobs are aborted prematurely
#289: Jobs are aborted prematurely
----------------------+-------------------------
Reporter: kparal | Owner:
Type: defect | Status: new
Priority: major | Milestone: Hot issues
Component: autotest | Resolution:
Keywords: |
----------------------+-------------------------
Comment (by kparal):
Reported as https://github.com/autotest/autotest/issues/117
--
Ticket URL: <https://fedorahosted.org/autoqa/ticket/289#comment:6>
AutoQA <http://autoqa.fedorahosted.org>
Automated QA project
5:05 a.m.
New subject: [AutoQA] #289: Jobs are aborted prematurely [waiting upstream] (was: Jobs are aborted prematurely)
#289: Jobs are aborted prematurely [waiting upstream]
----------------------+-------------------------
Reporter: kparal | Owner:
Type: defect | Status: new
Priority: major | Milestone: Hot issues
Component: autotest | Resolution:
Keywords: | Blocked By:
Blocking: |
----------------------+-------------------------
--
Ticket URL: <https://fedorahosted.org/autoqa/ticket/289#comment:7>
AutoQA <http://autoqa.fedorahosted.org>
Automated QA project
4502
days inactive
4796
days old
autoqa-devel@lists.fedorahosted.org
7 comments
1 participants
participants (1)
-
fedora-badges