Timestamps added to logs in autopkgtest and autopkgtest-cloud

[Tim Andersson]

Hey there,

Recently in Canonical Ubuntu QA we made some changes to autopkgtest which
went into both upstream and ubuntu-devel which preprends timestamps to the
logs.

The timestamps are in seconds and are measured since the beginning of all
the tests when you run autopkgtest against a package. We hope that this can
make it easier to extract valuable information from log files when reading
logs from the autopkgtest-cloud environment. It can help with determining
where tests are hanging, for instance.

A log snippet can be seen below:
```
  0s autopkgtest [18:59:38]: starting date and time: 2023-06-12
18:59:38+0100
  0s autopkgtest [18:59:38]: git checkout: a2cc92d Merge branch
'add_timestamp_to_logs' into 'master'
  0s autopkgtest [18:59:38]: host duckstation7; command line:
runner/autopkgtest -o /home/andersson123/tests/ mawk -- qemu
--ram-size=1536 --cpus 2
/home/andersson123/canonical/images/autopkgtest-lunar-amd64.img
 13s autopkgtest [18:59:51]: testbed dpkg architecture: amd64
 17s autopkgtest [18:59:55]: testbed running kernel: Linux 6.2.0-20-generic
#20-Ubuntu SMP PREEMPT_DYNAMIC Thu Apr  6 07:48:48 UTC 2023
 17s autopkgtest [18:59:55]: @@@@@@@@@@@@@@@@@@@@ apt-source mawk
 19s Get:1 http://archive.ubuntu.com/ubuntu lunar/main mawk
1.3.4.20200120-3.1 (dsc) [1,776 B]
 19s Get:2 http://archive.ubuntu.com/ubuntu lunar/main mawk
1.3.4.20200120-3.1 (tar) [469 kB]
 19s Get:3 http://archive.ubuntu.com/ubuntu lunar/main mawk
1.3.4.20200120-3.1 (diff) [14.1 kB]
 19s gpgv: Signature made Fri 17 Jun 2022 04:38:22 PM BST
 19s gpgv:                using RSA key
406220C8B8552802378CCE411F5C7A8B45564314
 19s gpgv:                issuer "bage at debian.org"
 19s gpgv: Can't check signature: No public key
 19s dpkg-source: warning: cannot verify inline signature for
./mawk_1.3.4.20200120-3.1.dsc: no acceptable signature found
 19s autopkgtest [18:59:57]: testing package mawk version 1.3.4.20200120-3.1
 19s autopkgtest [18:59:57]: build not needed
 20s autopkgtest [18:59:58]: test mawktest: preparing testbed
 22s Reading package lists...
 22s Building dependency tree...
 22s Reading state information...
 22s Starting pkgProblemResolver with broken count: 0
 22s Starting 2 pkgProblemResolver with broken count: 0
```

It does not prepend the timestamp to stdout, just to the log file itself.

You will soon start seeing this in all logs in autopkgtest-cloud soon. Let
us know if you run into any issues. If you use autopkgtest from source
(both ubuntu-devel and from debian) and update your master branch, you will
also start to see this in your log files.

*Ubuntu QA* (Brian Murray, Paride Legovini & Tim Andersson)

*The upstream MP can be seen here:*
https://salsa.debian.org/ci-team/autopkgtest/-/merge_requests/229

*The change fixes this debian bug from a little while ago:*
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=977037
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.ubuntu.com/archives/ubuntu-devel/attachments/20230613/749bd25b/attachment.html>