action #25296: [tools] Bookmarking of worker log: Have the worker log show what job was it working in the logs. - openQA Project (public) - openSUSE Project Management Tool

Actions

Copy link

action #25296

closed

action #6660: [tools][tools][sprint 201709.1][easy hack] use mojo::log in the worker

[tools] Bookmarking of worker log: Have the worker log show what job was it working in the logs.

Added by szarate about 7 years ago. Updated over 6 years ago.

Status:

Rejected

Priority:

Normal

Assignee:

dasantiago

Category:

Feature requests

Target version:

QA (public, currently private due to #173521) - future

Start date:

2017-09-15

Due date:

% Done:

Estimated time:

Description

Currently we have the situation where the worker log looks like this:

Sep 15 07:21:13 openqaworker6 worker[10949]: [DEBUG] Job 1170621 scheduled for next cycle
Sep 15 07:21:13 openqaworker6 worker[10949]: [INFO] got job 1170621: 01170621-sle-15-Leanos-DVD-x86_64-Build257.3-process_stress@64bit
Sep 15 07:21:13 openqaworker6 worker[10949]: [DEBUG] CACHE: Health: Real size: 53461895680, Configured limit: 53687091200
Sep 15 07:21:13 openqaworker6 worker[10949]: [INFO] OpenQA::Worker::Cache: Initialized with openqa.suse.de at /var/lib/openqa/cache, current size is 53461895680
Sep 15 07:21:13 openqaworker6 worker[10949]: [DEBUG] Found HDD_1, caching SLES-15-x86_64-257.3-minimal_with_sdk257.3_installed.qcow2
Sep 15 07:21:13 openqaworker6 worker[10949]: [DEBUG] CACHE: Aquiring lock for /var/lib/openqa/cache/SLES-15-x86_64-257.3-minimal_with_sdk257.3_installed.qcow2 in the database
Sep 15 07:21:13 openqaworker6 worker[10949]: [INFO] CACHE: Being downloaded by another worker, sleeping.
...
Sep 15 07:21:38 openqaworker6 worker[10949]: [DEBUG] Calling flock /var/lib/openqa/cache/needleslock rsync -avHP rsync://openqa.suse.de/tests/ --delete /var/lib/openqa/cache/tests/
Sep 15 07:21:39 openqaworker6 worker[10949]: [INFO] Waiting for subprocess
Sep 15 07:21:39 openqaworker6 worker[10949]: [INFO] Waiting for subprocess
Sep 15 07:21:40 openqaworker6 worker[10949]: [INFO] Waiting for subprocess
Sep 15 07:21:40 openqaworker6 worker[10949]: [INFO] Waiting for subprocess
Sep 15 07:21:40 openqaworker6 worker[10949]: receiving incremental file list
Sep 15 07:21:41 openqaworker6 worker[10949]: [INFO] Waiting for subprocess
Sep 15 07:21:41 openqaworker6 worker[10949]: sent 3,400 bytes  received 3,074,018 bytes  2,051,612.00 bytes/sec
Sep 15 07:21:41 openqaworker6 worker[10949]: total size is 5,491,730,108  speedup is 1,784.53
Sep 15 07:21:41 openqaworker6 worker[10949]: [DEBUG] RSYNC: Synchronization of tests directory took 3.00 seconds
Sep 15 07:21:41 openqaworker6 worker[10949]: [INFO] 38249: WORKING 1170621
Sep 15 07:21:41 openqaworker6 worker[10949]: [DEBUG] Sending IMMEDIATELY worker status to openqa.suse.de
Sep 15 07:21:41 openqaworker6 worker[10949]: [DEBUG] Sending worker status to openqa.suse.de
Sep 15 07:21:43 openqaworker6 qemu-system-x86_64[38286]: looking for plugins in '/usr/lib64/sasl2', failed to open directory, error: No such file or directory
Sep 15 07:21:56 openqaworker6 worker[10949]: [DEBUG] Sending worker status to openqa.suse.de
Sep 15 07:22:11 openqaworker6 worker[10949]: [DEBUG] Sending worker status to openqa.suse.de
Sep 15 07:22:26 openqaworker6 worker[10949]: [DEBUG] Sending worker status to openqa.suse.de
Sep 15 07:22:41 openqaworker6 worker[10949]: [DEBUG] Sending worker status to openqa.suse.de
Sep 15 07:22:51 openqaworker6 worker[10949]: [INFO] cleaning up 01170621-sle-15-Leanos-DVD-x86_64-Build257.3-process_stress@64bit
Sep 15 07:22:51 openqaworker6 worker[10949]: [DEBUG] Build finished, setting us free to pick up new jobs
Sep 15 07:22:51 openqaworker6 worker[10949]: [DEBUG] Sending IMMEDIATELY worker status to openqa.suse.de
Sep 15 07:22:56 openqaworker6 worker[10949]: [DEBUG] Sending worker status to openqa.suse.de
Sep 15 07:23:11 openqaworker6 worker[10949]: [DEBUG] Sending worker status to openqa.suse.de
Sep 15 07:23:26 openqaworker6 worker[10949]: [DEBUG] Sending worker status to openqa.suse.de
Sep 15 07:23:41 openqaworker6 worker[10949]: [DEBUG] Sending worker status to openqa.suse.de

Where one can easily miss some valuable output, and this output could be also be attached as part of the test results for easier analysis specially when a job has failed with an incomplete.

Having an output that looks like this, will do the trick.

Sep 15 07:21:13 openqaworker6 worker[10949]: [DEBUG] Job 1170621 scheduled for next cycle
Sep 15 07:21:13 openqaworker6 worker[10949]: [INFO][1170621] got job 1170621: 01170621-sle-15-Leanos-DVD-x86_64-Build257.3-process_stress@64bit
...
Sep 15 07:21:13 openqaworker6 worker[10949]: [DEBUG][1170621] CACHE: Health: Real size: 53461895680, Configured limit: 53687091200
Sep 15 07:21:13 openqaworker6 worker[10949]: [INFO][1170621] OpenQA::Worker::Cache: Initialized with openqa.suse.de at /var/lib/openqa/cache, current size is 53461895680
Sep 15 07:21:39 openqaworker6 worker[10949]: [INFO][1170621] Waiting for subprocess

This task must be split in two smaller tasks, described in the checklist

Hide closed

Checklist

Have the worker add the job id to the log string after the log level as soon as it picks a job, and remove it once it's done.
Have the worker attach the worker log section for the current job to the test results (worker log should be the last thing to be uploaded)

Related issues 1 (0 open — 1 closed)