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@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.
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@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:
The change fixes this debian bug from a little while ago:
