action #25296

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 over 2 years ago. Updated over 1 year ago.

Status:RejectedStart date:15/09/2017
Priority:NormalDue date:
Assignee:dasantiago% Done:

0%

Category:Feature requests
Target version:QA - future
Difficulty:
Duration:

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


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

Duplicates openQA Project - action #27120: [tools][sprint 201711.2] Make worker upload part of its l... Resolved 30/10/2017

History

#1 Updated by szarate over 2 years ago

  • Related to action #27120: [tools][sprint 201711.2] Make worker upload part of its log to WebUI added

#2 Updated by szarate over 2 years ago

  • Related to deleted (action #27120: [tools][sprint 201711.2] Make worker upload part of its log to WebUI)

#3 Updated by szarate over 2 years ago

  • Duplicates action #27120: [tools][sprint 201711.2] Make worker upload part of its log to WebUI added

#4 Updated by szarate over 2 years ago

  • Status changed from New to Rejected
  • Assignee set to dasantiago

David's approach with the channels will do the trick, as he has some WIP already

#5 Updated by okurz over 1 year ago

  • Target version changed from future to future

Also available in: Atom PDF