Message boards : ATLAS application : Sometimes no Hits-file produced according to stderr log for vbox tasks
Message board moderation

To post messages, you must log in.

AuthorMessage
Harri Liljeroos
Avatar

Send message
Joined: 28 Sep 04
Posts: 367
Credit: 19,381,711
RAC: 32,434
Message 39978 - Posted: 20 Sep 2019, 7:20:24 UTC

Lately I have seen some odd lines in the stderr which might relate to not properly ending of an Atlas task. First a snippet of what looks like a normal stderr from task:https://lhcathome.cern.ch/lhcathome/result.php?resultid=246079279
2019-09-19 15:16:46 (9800): Status Report: Elapsed Time: '6004.295595'
2019-09-19 15:16:46 (9800): Status Report: CPU Time: '19444.359375'
2019-09-19 16:56:50 (9800): Status Report: Elapsed Time: '12008.635559'
2019-09-19 16:56:50 (9800): Status Report: CPU Time: '39400.656250'
2019-09-19 18:36:55 (9800): Status Report: Elapsed Time: '18013.250986'
2019-09-19 18:36:55 (9800): Status Report: CPU Time: '61188.125000'
2019-09-19 20:16:59 (9800): Status Report: Elapsed Time: '24017.511396'
2019-09-19 20:16:59 (9800): Status Report: CPU Time: '82512.296875'
2019-09-19 21:57:03 (9800): Status Report: Elapsed Time: '30021.766174'
2019-09-19 21:57:03 (9800): Status Report: CPU Time: '105783.328125'
2019-09-19 23:37:08 (9800): Status Report: Elapsed Time: '36026.391401'
2019-09-19 23:37:08 (9800): Status Report: CPU Time: '126439.234375'
2019-09-20 00:54:31 (9800): Guest Log: The last 10 lines of the pilot log.
2019-09-20 00:54:31 (9800): Guest Log: -rw-------  1 atlas01 atlas01   760 Aug 22 12:01 setup.py
2019-09-20 00:54:31 (9800): Guest Log: -rw-------  1 atlas01 atlas01   221 Jul 25 17:38 TODO.md
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01 11 Sep 19 13:37 /home/atlas01/RunAtlas/pilot2/pandaIDs.out
2019-09-20 00:54:31 (9800): Guest Log: 4483542698
2019-09-20 00:54:31 (9800): Guest Log: 2019-09-19 21:53:30 UTC [wrapper] Test setup, not cleaning
2019-09-20 00:54:31 (9800): Guest Log: 2019-09-19 21:53:30 UTC [wrapper] ==== wrapper stdout END ====
2019-09-20 00:54:31 (9800): Guest Log: 2019-09-19 21:53:30 UTC [wrapper] ==== wrapper stderr END ====
2019-09-20 00:54:31 (9800): Guest Log: 2019-09-19 21:53:30 UTC [wrapper] wrapper wrapperexiting ec=0, duration=40626
2019-09-20 00:54:31 (9800): Guest Log: 2019-09-19 21:53:30 UTC [wrapper] apfmon messages muted
2019-09-20 00:54:31 (9800): Guest Log: Listing of results directory
2019-09-20 00:54:31 (9800): Guest Log: total 538796
2019-09-20 00:54:31 (9800): Guest Log: -rw-r--r-- 1 atlas01 atlas01    259319 Sep 18 16:25 pilot2.tar.gz
2019-09-20 00:54:31 (9800): Guest Log: -rw-r--r-- 1 atlas01 atlas01      4480 Sep 18 17:05 queuedata.json
2019-09-20 00:54:31 (9800): Guest Log: -rwx------ 1 atlas01 atlas01     12641 Sep 18 17:05 runpilot2-wrapper.sh
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01      2839 Sep 18 17:05 pandaJobData.out
2019-09-20 00:54:31 (9800): Guest Log: -rwxr-xr-x 1 atlas01 atlas01 272885263 Sep 19 13:36 EVNT.18605762._000055.pool.root.1
2019-09-20 00:54:31 (9800): Guest Log: -rwxr-xr-x 1 atlas01 atlas01      8593 Sep 19 13:36 init_data.xml
2019-09-20 00:54:31 (9800): Guest Log: -rwxr-xr-x 1 atlas01 atlas01    267471 Sep 19 13:36 input.tar.gz
2019-09-20 00:54:31 (9800): Guest Log: -rwxr-xr-x 1 atlas01 atlas01       812 Sep 19 13:36 RTE.tar.gz
2019-09-20 00:54:31 (9800): Guest Log: -rwxr-xr-x 1 atlas01 atlas01     14022 Sep 19 13:36 start_atlas.sh
2019-09-20 00:54:31 (9800): Guest Log: drwxr-xr-x 3 atlas01 atlas01      4096 Sep 19 13:36 APPS
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01   4050984 Sep 19 13:36 agis_schedconf.cvmfs.json
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01   7561623 Sep 19 13:37 agis_ddmendpoints.json
2019-09-20 00:54:31 (9800): Guest Log: drwx------ 3 atlas01 atlas01      4096 Sep 19 13:37 pilot2
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01 258970875 Sep 20 00:49 HITS.19056259._002750.pool.root.1
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01    869188 Sep 20 00:52 log.19056259._002750.job.log.tgz.1
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01     72926 Sep 20 00:52 heartbeat.json
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01     13637 Sep 20 00:53 pilotlog.txt
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01   1893846 Sep 20 00:53 log.19056259._002750.job.log.1
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01       463 Sep 20 00:53 output.list
2019-09-20 00:54:31 (9800): Guest Log: -rw-r--r-- 1 atlas01 atlas01       692 Sep 20 00:53 runtime_log
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01   4741120 Sep 20 00:53 result.tar.gz
2019-09-20 00:54:31 (9800): Guest Log: -rw-r--r-- 1 atlas01 atlas01      6851 Sep 20 00:53 runtime_log.err
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01       531 Sep 20 00:53 qgfMDmNlpUvn9Rq4apoT9bVoABFKDmABFKDmDn7aDmABFKDmC0c7em.diag
2019-09-20 00:54:31 (9800): Guest Log: HITS file was successfully produced
2019-09-20 00:54:31 (9800): Guest Log: -rw------- 1 atlas01 atlas01 258970875 Sep 20 00:49 /home/atlas01/RunAtlas/HITS.19056259._002750.pool.root.1
2019-09-20 00:54:31 (9800): Guest Log: Successfully finished the ATLAS job!
2019-09-20 00:54:31 (9800): Guest Log: Copying the results back to the shared directory!
2019-09-20 00:54:31 (9800): Guest Log: Copied the result file back to the shared directory and created atlas_done file!
2019-09-20 00:54:31 (9800): Guest Log: Success! Shutting down the machine.

And here is an output that looks a bit odd from task:https://lhcathome.cern.ch/lhcathome/result.php?resultid=246093757
2019-09-19 15:56:17 (14864): Status Report: Elapsed Time: '6004.350254'
2019-09-19 15:56:17 (14864): Status Report: CPU Time: '18572.750000'
2019-09-19 17:36:21 (14864): Status Report: Elapsed Time: '12008.812870'
2019-09-19 17:36:21 (14864): Status Report: CPU Time: '40275.218750'
2019-09-19 19:16:26 (14864): Status Report: Elapsed Time: '18013.299120'
2019-09-19 19:16:26 (14864): Status Report: CPU Time: '60527.515625'
2019-09-19 20:56:30 (14864): Status Report: Elapsed Time: '24017.753424'
2019-09-19 20:56:30 (14864): Status Report: CPU Time: '83031.171875'
2019-09-19 22:36:35 (14864): Status Report: Elapsed Time: '30022.301228'
2019-09-19 22:36:35 (14864): Status Report: CPU Time: '105165.078125'
2019-09-19 23:36:48 (14864): Guest Log: BIOS: AX=0305 BX=0000 CX=0000 DX=0000 
2019-09-20 00:16:40 (14864): Status Report: Elapsed Time: '36027.152363'
2019-09-20 00:16:40 (14864): Status Report: CPU Time: '126463.218750'
2019-09-20 01:56:44 (14864): Status Report: Elapsed Time: '42031.612814'
2019-09-20 01:56:44 (14864): Status Report: CPU Time: '148069.406250'
2019-09-20 03:36:49 (14864): Status Report: Elapsed Time: '48036.180416'
2019-09-20 03:36:49 (14864): Status Report: CPU Time: '168851.828125'
2019-09-20 04:03:10 (14864): VM Completion File Detected.
2019-09-20 04:03:10 (14864): Powering off VM.
2019-09-20 04:03:11 (14864): Successfully stopped VM.

Both tasks validate normally.
So far I have found that if the 'Status Report' section has 'Guest Log: BIOS' line in the middle, the log is missing the section of file listing and the mention about HITS file. So what can cause the odd 'Guest Log: BIOS ...' line here? The information on this line varies, sometimes it is like shown above but sometimes it has other information. Anyway if there is that kind of line the HITS file is not mentioned and the output is not complete.

This is a Win 10 machine with Boinc 7.6.33 and virtualbox 5.1.30 and this started to happen for task during last week. I don't remember seeing this before that.
ID: 39978 · Report as offensive     Reply Quote

Message boards : ATLAS application : Sometimes no Hits-file produced according to stderr log for vbox tasks


©2019 CERN