Hi Paul,
thanks for letting me know!
I noticed that there were several runs that took 2:47 (our timeout
time), while successful runs more in the order of minutes. This
started to happen recently.
This is likely related to #1012629 [1] (also see #1012804 [2]), a hang
issue that was in fact caused by rocksdb and was eventually fixed in
rocksdb 7.2.2-5. Could the version that is tested in the autopkgtest and
its dependencies be still affected by that?
[...]
On top of that, when a test just hangs that's not good for our
infrastructure. I'll put balboa on our reject_list for amd64, i386, and
s390x.
I see. I wonder what the procedure to get off that list is?
With an updated autopkgtest chroot, the latest librocksdb and a rebuilt
version of balboa the autopkgtest consistently succeeds for me; see
attached log.
Cheers
Sascha
[1] https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1012629
[2] https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1012804
Reading package lists...
Building dependency tree...
Reading state information...
The following NEW packages will be installed:
apt-utils
0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded.
Need to get 446 kB of archives.
After this operation, 1,196 kB of additional disk space will be used.
Get:1 http://deb.debian.org/debian sid/main amd64 apt-utils amd64 2.5.0 [446 kB]
debconf: delaying package configuration, since apt-utils is not installed
Fetched 446 kB in 0s (1,135 kB/s)
Selecting previously unselected package apt-utils.
(Reading database ...
(Reading database ... 5%
(Reading database ... 10%
(Reading database ... 15%
(Reading database ... 20%
(Reading database ... 25%
(Reading database ... 30%
(Reading database ... 35%
(Reading database ... 40%
(Reading database ... 45%
(Reading database ... 50%
(Reading database ... 55%
(Reading database ... 60%
(Reading database ... 65%
(Reading database ... 70%
(Reading database ... 75%
(Reading database ... 80%
(Reading database ... 85%
(Reading database ... 90%
(Reading database ... 95%
(Reading database ... 100%
(Reading database ... 12914 files and directories currently installed.)
Preparing to unpack .../apt-utils_2.5.0_amd64.deb ...
Unpacking apt-utils (2.5.0) ...
Setting up apt-utils (2.5.0) ...
Get:1 file:/tmp/autopkgtest-lxc.51ch70jm/downtmp/binaries InRelease
Ign:1 file:/tmp/autopkgtest-lxc.51ch70jm/downtmp/binaries InRelease
Get:2 file:/tmp/autopkgtest-lxc.51ch70jm/downtmp/binaries Release [816 B]
Get:2 file:/tmp/autopkgtest-lxc.51ch70jm/downtmp/binaries Release [816 B]
Get:3 file:/tmp/autopkgtest-lxc.51ch70jm/downtmp/binaries Release.gpg
Ign:3 file:/tmp/autopkgtest-lxc.51ch70jm/downtmp/binaries Release.gpg
Get:4 file:/tmp/autopkgtest-lxc.51ch70jm/downtmp/binaries Packages [4,116 B]
Reading package lists...
Reading package lists...
Building dependency tree...
Reading state information...
Correcting dependencies...Starting pkgProblemResolver with broken count: 0
Starting 2 pkgProblemResolver with broken count: 0
Done
Done
Starting pkgProblemResolver with broken count: 0
Starting 2 pkgProblemResolver with broken count: 0
Done
The following additional packages will be installed:
balboa balboa-backend-common balboa-backend-rocksdb curl libbrotli1 libcurl4
libgflags2.2 libnghttp2-14 libpsl5 librocksdb7.2 librtmp1 libsnappy1v5
libssh2-1
Recommended packages:
ca-certificates publicsuffix
The following NEW packages will be installed:
balboa balboa-backend-common balboa-backend-rocksdb curl libbrotli1 libcurl4
libgflags2.2 libnghttp2-14 libpsl5 librocksdb7.2 librtmp1 libsnappy1v5
libssh2-1
0 upgraded, 13 newly installed, 0 to remove and 0 not upgraded.
1 not fully installed or removed.
Need to get 4,323 kB/7,945 kB of archives.
After this operation, 25.9 MB of additional disk space will be used.
Get:1 file:/tmp/autopkgtest-lxc.51ch70jm/downtmp/binaries balboa 2.0.0+ds-4 [3,236 kB]
Get:2 file:/tmp/autopkgtest-lxc.51ch70jm/downtmp/binaries balboa-backend-common 2.0.0+ds-4 [354 kB]
Get:3 file:/tmp/autopkgtest-lxc.51ch70jm/downtmp/binaries balboa-backend-rocksdb 2.0.0+ds-4 [31.6 kB]
Get:4 http://deb.debian.org/debian sid/main amd64 libgflags2.2 amd64 2.2.2-2 [83.5 kB]
Get:5 http://deb.debian.org/debian sid/main amd64 libsnappy1v5 amd64 1.1.9-2 [27.4 kB]
Get:6 http://deb.debian.org/debian sid/main amd64 librocksdb7.2 amd64 7.2.2-5 [2,921 kB]
Get:7 http://deb.debian.org/debian sid/main amd64 libbrotli1 amd64 1.0.9-2+b3 [276 kB]
Get:8 http://deb.debian.org/debian sid/main amd64 libnghttp2-14 amd64 1.47.0-1+b1 [76.3 kB]
Get:9 http://deb.debian.org/debian sid/main amd64 libpsl5 amd64 0.21.0-1.2 [57.3 kB]
Get:10 http://deb.debian.org/debian sid/main amd64 librtmp1 amd64 2.4+20151223.gitfa8646d.1-2+b2 [60.8 kB]
Get:11 http://deb.debian.org/debian sid/main amd64 libssh2-1 amd64 1.10.0-3+b1 [179 kB]
Get:12 http://deb.debian.org/debian sid/main amd64 libcurl4 amd64 7.83.1-2 [358 kB]
Get:13 http://deb.debian.org/debian sid/main amd64 curl amd64 7.83.1-2 [285 kB]
Fetched 4,323 kB in 2s (2,535 kB/s)
Selecting previously unselected package balboa.
(Reading database ...
(Reading database ... 5%
(Reading database ... 10%
(Reading database ... 15%
(Reading database ... 20%
(Reading database ... 25%
(Reading database ... 30%
(Reading database ... 35%
(Reading database ... 40%
(Reading database ... 45%
(Reading database ... 50%
(Reading database ... 55%
(Reading database ... 60%
(Reading database ... 65%
(Reading database ... 70%
(Reading database ... 75%
(Reading database ... 80%
(Reading database ... 85%
(Reading database ... 90%
(Reading database ... 95%
(Reading database ... 100%
(Reading database ... 12995 files and directories currently installed.)
Preparing to unpack .../00-balboa.deb ...
Unpacking balboa (2.0.0+ds-4) ...
Selecting previously unselected package balboa-backend-common.
Preparing to unpack .../01-balboa-backend-common.deb ...
Unpacking balboa-backend-common (2.0.0+ds-4) ...
Selecting previously unselected package libgflags2.2.
Preparing to unpack .../02-libgflags2.2_2.2.2-2_amd64.deb ...
Unpacking libgflags2.2 (2.2.2-2) ...
Selecting previously unselected package libsnappy1v5:amd64.
Preparing to unpack .../03-libsnappy1v5_1.1.9-2_amd64.deb ...
Unpacking libsnappy1v5:amd64 (1.1.9-2) ...
Selecting previously unselected package librocksdb7.2.
Preparing to unpack .../04-librocksdb7.2_7.2.2-5_amd64.deb ...
Unpacking librocksdb7.2 (7.2.2-5) ...
Selecting previously unselected package balboa-backend-rocksdb.
Preparing to unpack .../05-balboa-backend-rocksdb.deb ...
Unpacking balboa-backend-rocksdb (2.0.0+ds-4) ...
Selecting previously unselected package libbrotli1:amd64.
Preparing to unpack .../06-libbrotli1_1.0.9-2+b3_amd64.deb ...
Unpacking libbrotli1:amd64 (1.0.9-2+b3) ...
Selecting previously unselected package libnghttp2-14:amd64.
Preparing to unpack .../07-libnghttp2-14_1.47.0-1+b1_amd64.deb ...
Unpacking libnghttp2-14:amd64 (1.47.0-1+b1) ...
Selecting previously unselected package libpsl5:amd64.
Preparing to unpack .../08-libpsl5_0.21.0-1.2_amd64.deb ...
Unpacking libpsl5:amd64 (0.21.0-1.2) ...
Selecting previously unselected package librtmp1:amd64.
Preparing to unpack .../09-librtmp1_2.4+20151223.gitfa8646d.1-2+b2_amd64.deb ...
Unpacking librtmp1:amd64 (2.4+20151223.gitfa8646d.1-2+b2) ...
Selecting previously unselected package libssh2-1:amd64.
Preparing to unpack .../10-libssh2-1_1.10.0-3+b1_amd64.deb ...
Unpacking libssh2-1:amd64 (1.10.0-3+b1) ...
Selecting previously unselected package libcurl4:amd64.
Preparing to unpack .../11-libcurl4_7.83.1-2_amd64.deb ...
Unpacking libcurl4:amd64 (7.83.1-2) ...
Selecting previously unselected package curl.
Preparing to unpack .../12-curl_7.83.1-2_amd64.deb ...
Unpacking curl (7.83.1-2) ...
Setting up libpsl5:amd64 (0.21.0-1.2) ...
Setting up balboa-backend-common (2.0.0+ds-4) ...
Setting up balboa (2.0.0+ds-4) ...
Adding system user `balboa' (UID 105) ...
Adding new group `balboa' (GID 107) ...
Adding new user `balboa' (UID 105) with group `balboa' ...
Creating home directory `/var/lib/balboa' ...
Created symlink /etc/systemd/system/multi-user.target.wants/balboa.service → /lib/systemd/system/balboa.service.
Setting up libbrotli1:amd64 (1.0.9-2+b3) ...
Setting up libnghttp2-14:amd64 (1.47.0-1+b1) ...
Setting up libsnappy1v5:amd64 (1.1.9-2) ...
Setting up librtmp1:amd64 (2.4+20151223.gitfa8646d.1-2+b2) ...
Setting up libssh2-1:amd64 (1.10.0-3+b1) ...
Setting up libgflags2.2 (2.2.2-2) ...
Setting up librocksdb7.2 (7.2.2-5) ...
Setting up balboa-backend-rocksdb (2.0.0+ds-4) ...
Setting up libcurl4:amd64 (7.83.1-2) ...
Setting up curl (7.83.1-2) ...
Setting up autopkgtest-satdep (0) ...
Processing triggers for libc-bin (2.33-7) ...
(Reading database ... 13098 files and directories currently installed.)
Removing autopkgtest-satdep (0) ...
Jun 27 20:17:52 autopkgtest-lxc-ncvite systemd[1]: Started Basic Little Book of Answers, 'rocksdb' Backend.
● balboa-backend@rocksdb.service - Basic Little Book of Answers, 'rocksdb' Backend
Loaded: loaded (/lib/systemd/system/balboa-backend@.service; enabled; vendor preset: enabled)
Active: active (running) since Mon 2022-06-27 20:17:52 UTC; 1s ago
Docs: https://github.com/DCSO/balboa
Main PID: 585 (balboa-rocksdb)
Tasks: 14 (limit: 28472)
Memory: 1.7M
CPU: 12ms
CGroup: /system.slice/system-balboa\x2dbackend.slice/balboa-backend@rocksdb.service
└─585 /usr/bin/balboa-rocksdb
Jun 27 20:17:52 autopkgtest-lxc-ncvite systemd[1]: Started Basic Little Book of Answers, 'rocksdb' Backend.
Jun 27 20:17:52 autopkgtest-lxc-ncvite systemd[1]: Started Basic Little Book of Answers.
Jun 27 20:17:52 autopkgtest-lxc-ncvite balboa[549]: time="2022-06-27T20:17:52Z" level=info msg="switching to log file /var/log/balboa.log"
● balboa.service - Basic Little Book of Answers
Loaded: loaded (/lib/systemd/system/balboa.service; enabled; vendor preset: enabled)
Active: active (running) since Mon 2022-06-27 20:17:52 UTC; 2s ago
Docs: https://github.com/DCSO/balboa
Main PID: 549 (balboa)
Tasks: 11 (limit: 28472)
Memory: 3.4M
CPU: 16ms
CGroup: /system.slice/balboa.service
└─549 /usr/bin/balboa serve -f /etc/balboa/feeders.yaml -l /var/log/balboa.log
Jun 27 20:17:52 autopkgtest-lxc-ncvite systemd[1]: Started Basic Little Book of Answers.
Jun 27 20:17:52 autopkgtest-lxc-ncvite balboa[549]: time="2022-06-27T20:17:52Z" level=info msg="switching to log file /var/log/balboa.log"
{"level":"info","msg":"starting feeder HTTP Input","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"accepting submissions on port 8081","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"starting feeder Socket Input","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"starting feeder Suricata Socket Input","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"ConsumeFeed() starting","time":"2022-06-27T20:17:52Z"}
{"level":"warning","msg":"connecting to backend failed: dial tcp 127.0.0.1:4242: connect: connection refused","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"ConsumeFeed() finished","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"serving GraphQL on port 8080","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"starting feeder HTTP Input","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"accepting submissions on port 8081","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"starting feeder Socket Input","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"starting feeder Suricata Socket Input","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"ConsumeFeed() starting","time":"2022-06-27T20:17:52Z"}
{"level":"warning","msg":"connecting to backend failed: dial tcp 127.0.0.1:4242: connect: connection refused","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"ConsumeFeed() finished","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"serving GraphQL on port 8080","time":"2022-06-27T20:17:52Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:17:54Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:17:54Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:17:54Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:17:54Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:17:54Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:17:54Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:17:54Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:17:54Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:17:54Z"}
{"level":"info","msg":"ConsumeFeed() starting","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:02Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:03Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:03Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:03Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:03Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:03Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:03Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:03Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:03Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:03Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:03Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:04Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:04Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:04Z"}
{"level":"info","msg":"got 1562529 bytes via HTTP","time":"2022-06-27T20:18:04Z"}
{"level":"info","msg":"enqueued 11931 observations","time":"2022-06-27T20:18:04Z"}
{"data":{"entries":[{"rdata":"39.49.168.110","rrtype":"NS","count":12}]}}
test-run PASS
