On 11.02.23 18:18, Paul Gevers wrote:
* [suspect 1] network issues between the s390x and the main ci.d.n

server (the results (log files) of the autopkgtests are transferred to
the main server). Our ppc64el hosts are also located at Marist, so I
would expect commonality here, but also ppc64el isn't performing great,
so maybe part of the problem is common.

Do you have any kind of statistics on the network connections? I.e. how
often it reconnects and how long it takes to reconnect? The Marist
network has a very weird firewall inbound (e.g. if I do too many SSH
requests in a row, I'm backholed) - so I would not be surprised if there
is some weirdness there.

Kind regards
Philipp Kern

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

To: [email protected] (debian-s390)
To: [email protected]
To: [email protected] (Paul Flint)
Copy: [email protected] (Debian CI team)

This is an OpenPGP/MIME signed message (RFC 4880 and 3156) --------------f0Z034o7GjbLEIB1SExHBfEe
Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: base64

SGkgUGhpbCBhbmQgYWxsIG90aGVycyBvZmZlcmluZyBoZWxwLA0KDQpPbiAxMi0wMi0yMDIz IDIwOjMyLCBQaGlsaXBwIEtlcm4gd3JvdGU6DQo+IE9uIDExLjAyLjIzIDE4OjE4LCBQYXVs IEdldmVycyB3cm90ZToNCj4gIMKgKiBbc3VzcGVjdCAxXSBuZXR3b3JrIGlzc3VlcyBiZXR3 ZWVuIHRoZSBzMzkweCBhbmQgdGhlIG1haW4gY2kuZC5uDQo+PiBzZXJ2ZXIgKHRoZSByZXN1 bHRzIChsb2cgZmlsZXMpIG9mIHRoZSBhdXRvcGtndGVzdHMgYXJlIHRyYW5zZmVycmVkIHRv IA0KPj4gdGhlIG1haW4gc2VydmVyKS4gT3VyIHBwYzY0ZWwgaG9zdHMgYXJlIGFsc28gbG9j YXRlZCBhdCBNYXJpc3QsIHNvIEkgDQo+PiB3b3VsZCBleHBlY3QgY29tbW9uYWxpdHkgaGVy ZSwgYnV0IGFsc28gcHBjNjRlbCBpc24ndCBwZXJmb3JtaW5nIA0KPj4gZ3JlYXQsIHNvIG1h eWJlIHBhcnQgb2YgdGhlIHByb2JsZW0gaXMgY29tbW9uLg0KPiANCj4gRG8geW91IGhhdmUg YW55IGtpbmQgb2Ygc3RhdGlzdGljcyBvbiB0aGUgbmV0d29yayBjb25uZWN0aW9ucz8gSS5l LiBob3cgDQo+IG9mdGVuIGl0IHJlY29ubmVjdHMgYW5kIGhvdyBsb25nIGl0IHRha2VzIHRv IHJlY29ubmVjdD8gVGhlIE1hcmlzdCANCj4gbmV0d29yayBoYXMgYSB2ZXJ5IHdlaXJkIGZp cmV3YWxsIGluYm91bmQgKGUuZy4gaWYgSSBkbyB0b28gbWFueSBTU0ggDQo+IHJlcXVlc3Rz IGluIGEgcm93LCBJJ20gYmFja2hvbGVkKSAtIHNvIEkgd291bGQgbm90IGJlIHN1cnByaXNl ZCBpZiB0aGVyZSANCj4gaXMgc29tZSB3ZWlyZG5lc3MgdGhlcmUuDQoNCkkgaGF2ZSBtdW5p biBbMV0sIGJ1dCBhcyBzYWlkLCBJJ20gbm90IGEgdHJhaW5lZCBzeXNhZG1pbi4gSSBkb24n dCBrbm93IA0Kd2hhdCBJJ20gbG9va2luZyBmb3IgaWYgeW91IGFzayAic3RhdGlzdGljcyBv biB0aGUgbmV0d29yayIuDQoNCkFsc28sIEkgaGF2ZSBubyBleHBlcmllbmNlIHdpdGggczM5 MHggZXhjZXB0IGZvciBkZXBsb3lpbmcgdGhlIERlYmlhbiANCnNvZnR3YXJlIG9uIHRoZSBz ZXJ2ZXIgc2V0dXAgYnkgUGhpbC4gQWxsIHRoZSBxdWlya3Mgb2YgczM5MHggYXJlIGJleW9u ZCBtZS4NCg0KSSBjYW4gcHJvdmlkZSBsb2dnaW5nIGZyb20gdGhlIGhvc3QsIGJ1dCBJJ2xs IG5lZWQgZGV0YWlsZWQgaW5zdHJ1Y3Rpb25zIA0Kb2Ygd2hhdCBwZW9wbGUgZmluZCB1c2Vm dWwgdG8gbG9vayBhdC4gUmVjZW50bHkgQW50b25pbyB0YXVnaHQgbWUgYSANCnRyaWNrIHRv IHByb3ZpZGUgdGVtcG9yYXJ5IGFjY2VzcyB0byBhIGx4YyBjb250YWluZXIgb24gYW55IG9m IG91ciANCmhvc3RzLCBzbyBpZiBpdCBoZWxwcyB0byBiZSBvbiB0aGUgaG9zdCAoYnV0IGlu c2lkZSBseGMpIHdlIGNhbiBwcm92aWRlIA0KZm9yIHRoYXQuDQoNClBhdWwNCg0KWzFdIA0K aHR0cHM6Ly9jaS5kZWJpYW4ubmV0L211bmluL2NpLXdvcmtlci1zMzkweC0wMS9jaS13b3Jr ZXItczM5MHgtMDEvaW5kZXguaHRtbA0K

--------------f0Z034o7GjbLEIB1SExHBfEe--

-----BEGIN PGP SIGNATURE-----

wsB5BAABCAAjFiEEWLZtSHNr6TsFLeZynFyZ6wW9dQoFAmPpXGYFAwAAAAAACgkQnFyZ6wW9dQoZ Ggf/R+rtr25VY2sp7RCns8JubLi0gp1PkE4ZoSlsGuNAtXwjUYclD3vmADypW3Igcd6V4vfLzfAP au5mKLgB5fNGsgnrZ0eoVMyd6oIJ5iMWGT5idYfb0vvoz7u+Dxnqh4hiiIMFYWVji2YFABSa8d4O vUQvxNhCHaFc2EHQiIec+f121EyjGwJCN0uS2yoY2SDup9cFAHmre9BHu39Gx1hWWk0Jn8IttEZ5 UswKWB6QwtZ/vXcuC+R6BqB0ktiym7GwdZZnsYG7lhOMFTVUFHhO5a2laXahtJZyWYkmOEb9GX2Q +ZlbEsRfrc4ZdjNCKPbOdrBHXGUl+O2nKa1C3EjqBQ==
=PCIZ
-----END PGP SIGNATURE-----

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

Hi,

On 12.02.23 22:38, Paul Gevers wrote:

I have munin [1], but as said, I'm not a trained sysadmin. I don't know
what I'm looking for if you ask "statistics on the network".

This is more of a software development / devops question than a sysadmin question, but alas. What I am interested in is *application-level*
logging on reconnects. Presumably the connection to RabbitMQ is
outbound? Is it tunneled? Does your application log somewhere when a
reconnect happens? Does it say when it successfully connected?

I'd expect good software to log something like this:

[10:00:00] Connecting to broker "rabbitmq.debci.debian.net:12345"...
[10:00:05] Connected to broker "rabbitmq.debci.debian.net:12345".

And also:

[10:00:00] Connecting to broker "rabbitmq.debci.debian.net:12345"...
[10:00:01] Connection to broker "rabbitmq.debci.debian.net:12345"
failed: Connection refused

Kind regards
Philipp Kern

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

To: [email protected] (Philipp Kern)
To: [email protected] (debian-s390)
To: [email protected] ([email protected])
To: [email protected] (Paul Flint)
To: [email protected] (William Desportes)
Copy: [email protected] (Debian CI team)

This is an OpenPGP/MIME signed message (RFC 4880 and 3156) --------------E8zAMTJo4PdF4cVuXgbTHezZ
Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: base64

SGksDQoNCk9uIDEzLTAyLTIwMjMgMTU6NTksIERpcGFrIFpvcGUxIHdyb3RlOg0KPiBUaGVy ZSBpcyBzb21lIGlzc3VlIHdpdGggNS4xMC4wLTIxIGtlcm5lbCBhbmQgd2UgYXJlIHdvcmtp bmcgb24gaXQuIFRoaXMgDQo+IGNhbiBjYXVzZSBwZXJmb3JtYW5jZSBpbXBhY3Qgb24gQ0kg c2VydmVycy4NCg0KSSBoYXZlIHJlYm9vdGVkIHRvIHRoZSBvbGQga2VybmVsIHllc3RlcmRh eS4gVGhhdCBoZWxwcyBhIGJpdCBpbmRlZWQsIA0KYWx0aG91Z2ggbW9zdCBvZiB0aGUgaXNz dWVzIEkgcmVwb3J0ZWQgcHJlZGF0ZSB0aGF0IGtlcm5lbCB1cGdyYWRlLg0KDQo+IEFzIFBh dWwgbWVudGlvbmVkIHdlIGhhdmUgdXBncmFkZWQgQ0kgc2VydmVycyB0byBiZXR0ZXIgY2Fw YWNpdHkgaW4gTWF5IA0KPiBsYXN0IHllYXIuIElzIHRvZGF54oCZcyBwZXJmb3JtYW5jZSB3 b3JzZSB0aGFuIHdoYXQgd2Ugb2JzZXJ2ZWQgcmlnaHQgDQo+IGFmdGVyIHVwZ3JhZGU/DQoN CkFzIHlvdSBjYW4gc2VlIGUuZy4gaGVyZSBbMSwyXSBpdCBjb21lcyBhbmQgZ29lcyAoYWxi ZWl0IHNvbWV0aW1lcyB0aGUgDQpxdWV1ZSB3YXMgZW1wdHkpLiBJIGRvbid0IHRoaW5rIGl0 cyB2ZXJ5IGRpZmZlcmVudCwgSSBqdXN0IG5ldmVyIGdvdCBvdXQgDQpvZiB0aGUgczM5MHgg aG9zdCB3aGF0IEkgd2FzIGV4cGVjdGluZy4gTG9uZyB0aW1lIEkgYmxhbWVkIGl0IG9uIHRo ZSANCiJzdGVhbGluZyIgdGhhdCBoYXBwZW5zIG9uIGEgc2hhcmVkIGhvc3QsIGJ1dCBJIHRo aW5rIHRoZXJlJ3MgbW9yZS4NCg0KWzFdIA0KaHR0cHM6Ly9jaS5kZWJpYW4ubmV0L211bmlu L2NpLXdvcmtlci1zMzkweC0wMS9jaS13b3JrZXItczM5MHgtMDEvZGViY2lfcGFja2FnZXNf cHJvY2Vzc2VkLmh0bWwNCg0KWzJdIA0KaHR0cHM6Ly9jaS5kZWJpYW4ubmV0L211bmluL2Np LXdvcmtlci1zMzkweC0wMS9jaS13b3JrZXItczM5MHgtMDEvY3B1Lmh0bWwNCg0KPiBJcyB0 aGUgcGVyZm9ybWFuY2UgZGV0ZXJpb3JhdGVkIGNvbnNpc3RlbnRseSBvdmVyIHBlcmlvZCAN Cj4gb2YgdGltZSBvciBzdWRkZW5seSBvYnNlcnZlZD8gSXMgdGhlcmUgYW55IGluY2lkZW5j ZSDigJMgbGlrZSANCj4gY2hhbmdlL3VwZ3JhZGUgaW4gc29mdHdhcmUgb3IgaGFyZHdhcmUg Y29tcG9uZW50IHdoaWNoIGlzIGNvaW5jaWRpbmcgDQo+IHdpdGggaXQgaWYgaXQgaXMgc3Vk ZGVuIGNoYW5nZT8NCg0KSmFtZXMgQWRkaXNvbiBzdWdnZXN0ZWQgaW4gWzNdIHRvIGluY3Jl YXNlIGEgcHJlZmV0Y2ggY291bnRlciBpbiBhbXFwIA0KKGFsdGhvdWdoIGl0cyB0aGUgc2Ft ZSBvbiBhbGwgaG9zdHMpOyBJIGhhdmUgZG9uZSBzbyBvbiB0aGUgczM5MHggaG9zdCANCmFu ZCBhdCBsZWFzdCBpbml0aWFsbHkgaXQgc2VlbXMgdG8gaGVscCBrZWVwaW5nIHRoZSBob3N0 IGJ1c2llci4NCg0KWzNdIGh0dHBzOi8vc2Fsc2EuZGViaWFuLm9yZy9jaS10ZWFtL2RlYmNp Ly0vaXNzdWVzLzkyI25vdGVfMzgxMzA2DQoNClBhdWwNCg==

--------------E8zAMTJo4PdF4cVuXgbTHezZ--

-----BEGIN PGP SIGNATURE-----

wsB5BAABCAAjFiEEWLZtSHNr6TsFLeZynFyZ6wW9dQoFAmPuXrQFAwAAAAAACgkQnFyZ6wW9dQqX RQf+JJBF9tP/4jTzFL2e+w4ah0Z7ys/ObV/ZOwmypYZ8vSdXV5Z+jG2mSCwjHxRgwlUoe/1azGAX Mm3ZFWYiQ4rpEyNmN8Gbb8XKdExs5Lfu0IuRpZ+RPYDdoPHFsCohrMW6+jer3U53P0lfDzgp7Ksu uEqjKOA2s8OafSudNLlgMn/yCk6jGaBzSFTIUuK/3d99lYjzC4jK01oCQNky5PnRa/Qyyd+ZV8Vi cjGE3PaTPBP8ldkShbkLJBIWVjQXC7esx4XTE/FBUE3yVAaIIhxnvyAxd1GOUhPF5AgXAW36Qm/3 17prG7QwdV9z86wkf6dZRw3uRQuM/8dUn0tVb9vWxg==
=R5df
-----END PGP SIGNATURE-----

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

On Tue, Feb 14, 2023 at 09:42:09PM +0100, Paul Gevers wrote:

Hi Phil,

On 13-02-2023 08:57, Philipp Kern wrote:

On 12.02.23 22:38, Paul Gevers wrote:

I have munin [1], but as said, I'm not a trained sysadmin. I don't
know what I'm looking for if you ask "statistics on the network".

This is more of a software development / devops question than a sysadmin question, but alas.

I acknowledge that my reach out was broad and didn't only cover s390x.

What I am interested in is *application-level* logging on reconnects. Presumably the connection to RabbitMQ is outbound?

Our configuration can be seen here: https://salsa.debian.org/ci-team/debian-ci-config/-/blob/master/cookbooks/rabbitmq/templates/rabbitmq.conf.erb

Is it tunneled? Does your application log somewhere when a reconnect happens? Does it say when it successfully connected?

I'd expect good software to log something like this:

[10:00:00] Connecting to broker "rabbitmq.debci.debian.net:12345"... [10:00:05] Connected to broker "rabbitmq.debci.debian.net:12345".

And also:

[10:00:00] Connecting to broker "rabbitmq.debci.debian.net:12345"... [10:00:01] Connection to broker "rabbitmq.debci.debian.net:12345"
failed: Connection refused

@terceiro; I haven't seen these kind of logs on the worker hosts. Do you
know if they exist or if we can generate them?

The worker does log it's initial connection, see below.

I think I'm seeing something on the main host. admin@ci-master:/var/log/rabbitmq$ sudo grep 148.100.88.163 [email protected] | grep -v '\[info\]' | grep -v '\[warning\]'
2023-02-14 00:00:37.522 [error] <0.30951.85> closing AMQP connection <0.30951.85> (148.100.88.163:49540 -> 10.1.14.198:5671):
2023-02-14 02:27:56.050 [error] <0.15184.87> closing AMQP connection <0.15184.87> (148.100.88.163:49988 -> 10.1.14.198:5671):
2023-02-14 02:36:05.496 [error] <0.17479.87> closing AMQP connection <0.17479.87> (148.100.88.163:57098 -> 10.1.14.198:5671):
2023-02-14 04:06:13.869 [error] <0.16105.88> closing AMQP connection <0.16105.88> (148.100.88.163:42984 -> 10.1.14.198:5671):
2023-02-14 04:15:27.696 [error] <0.19038.88> closing AMQP connection <0.19038.88> (148.100.88.163:56650 -> 10.1.14.198:5671):
2023-02-14 20:05:38.702 [error] <0.23586.97> closing AMQP connection <0.23586.97> (148.100.88.163:34278 -> 10.1.14.198:5671):

and a lot more warnings (220 times in 20 hours) as well; like:
2023-02-14 20:05:09.011 [warning] <0.20860.97> closing AMQP connection <0.20860.97> (148.100.88.163:45624 -> 10.1.14.198:5671, vhost: '/', user: 'guest'):

And a lot (around 544) (obviously I don't know if that's only or even includes the s390x host):
client unexpectedly closed TCP connection

root@ci-worker-s390x-01:~# journalctl -u [email protected]e --since='2 days ago' -t debci -b 0 | grep amqp
Feb 15 15:10:21 ci-worker-s390x-01 debci[663]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 15 17:58:53 ci-worker-s390x-01 debci[2740543]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 15 19:23:40 ci-worker-s390x-01 debci[1855652]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 15 19:28:12 ci-worker-s390x-01 debci[1939916]: retry: amqp-publish returned 1, backing off for 10 seconds and trying again...
Feb 15 20:50:51 ci-worker-s390x-01 debci[783145]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 15 21:36:25 ci-worker-s390x-01 debci[1966510]: retry: amqp-publish returned 1, backing off for 10 seconds and trying again...
Feb 15 22:21:43 ci-worker-s390x-01 debci[3243793]: retry: amqp-publish returned 1, backing off for 10 seconds and trying again...
Feb 16 00:29:41 ci-worker-s390x-01 debci[4119188]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 01:21:26 ci-worker-s390x-01 debci[2097411]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 03:02:20 ci-worker-s390x-01 debci[1133799]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 06:40:46 ci-worker-s390x-01 debci[953820]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 08:00:24 ci-worker-s390x-01 debci[2875496]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 09:59:09 ci-worker-s390x-01 debci[3864527]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 11:47:09 ci-worker-s390x-01 debci[2310984]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 14:08:01 ci-worker-s390x-01 debci[1968077]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 16:58:24 ci-worker-s390x-01 debci[2496027]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 18:40:23 ci-worker-s390x-01 debci[1074224]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 20:35:15 ci-worker-s390x-01 debci[824124]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 16 22:23:07 ci-worker-s390x-01 debci[3567266]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 17 01:16:26 ci-worker-s390x-01 debci[40757]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 17 04:22:34 ci-worker-s390x-01 debci[1275755]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 17 06:24:45 ci-worker-s390x-01 debci[448310]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net
Feb 17 08:26:47 ci-worker-s390x-01 debci[830390]: I: Connecting to AMQP queue debci-tests-s390x-lxc on amqps://ci-master.debian.net

So, for example, we sometimes see errors when publishing results (the
retry: lines), so maybe we are also having problems getting jobs.

Also, it seems the client connects again several times a day, what is definitively not normal (the amqp connection is supposed to be
persistent). I checked for example one of the arm64 on the Huawei cloud
-- since it's also not inside AWS, but on a different network path --
and it didn't need to reconnect even once in the last full days, having processed > 500 jobs in that time.

So there is for sure something wrong with the client-server connection
there. Reworking the client for robustness is on my TODO list for a
while.

-----BEGIN PGP SIGNATURE-----

iQIzBAABCAAdFiEEst7mYDbECCn80PEM/A2xu81GC94FAmPvpXcACgkQ/A2xu81G C97zWQ/+NopnKocwuJNU1p5nYUbk7xGpxjo2qR7rxKu97124OOmJh4o0LrjtqyPk xhxJ2gNdZHeYptW4E+sAA0MfgCJNBDugn7QnmKs+oIn0lkAD2XztPm7ybLvNxJnN iPOghTC6q/ZwTr+pEskxqZW6CN4yRsxTx6PjD2UdVNeXF8X07Why0FQw+xx3rhMb VCM4bXp2Fnt4D4fBdu5ifLu7tQ1jB4bfH2mW/QPhht6PlIbhWGqyWAsaSWRDXn3M KfR6h0JPcoIuk8UZnbKGL2IFmy+4QxEXUjXT+HEvlEV8pS0j6ioIJ3Ji0wh6nhi5 JIhy1nNzmQisEgjTgknOP/cJF2X5UA4E09H2GXw48ugIu1mGu0WGtw1CADOIF1Qg nfbYkGhj13UmqhJ37OscqOTrpIgvPl6Z3Tk2tNUEzfqH0vhyZF2tH+8jjtxxpFqP XRcSx1HC7GRie746xYBgjektumuWMMsLUr0dhH0WunChTot9ULtptnewobPWmwAk BUCdEwhmiCWVfZ0QJnW6GsyKSbJJ2QfzeHZam1FyfVI7Fb7T5XyCQX3tvoxcRzLx eWxDhy66DaumgexVB1tHNF40N81Ue/CVS7DCVnLVBB1mMxeOKFjXGZy2yqwqDwnS hxKAydCAU4qet/LzAjf0xPWOQ3hojnNU+8d9bjdfD9sJKI94KP0=
=myM7
-----END PGP SIGNATURE-----

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

James Addison suggested in [3] to increase a prefetch counter in amqp (although its the same on all hosts); I have done so on the s390x host and at least initially it seems to help keeping the host busier.

Thanks for applying that - I was hoping that the change might also
result in reductions in the debci queue size for s390x, but that
doesn't appear to have happened, going by https://ci.debian.net/munin/debian.net/ci-master.debian.net/debci_queue_size.html

[3] https://salsa.debian.org/ci-team/debci/-/issues/92#note_381306

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

Hi,

On 17.02.23 17:04, Antonio Terceiro wrote:

So there is for sure something wrong with the client-server connection
there. Reworking the client for robustness is on my TODO list for a
while.

There's a lot of these:

Feb 14 08:56:25 ci-worker-s390x-01 debci[1155941]: waiting for header frame: a SSL error occurred

But alas, the worker will fail and immediately restart. But what's more concerning is the context:

Feb 14 08:39:50 ci-worker-s390x-01 debci[1355790]: bacula testing/s390x tmpfail
Feb 14 08:56:25 ci-worker-s390x-01 debci[1155941]: waiting for header frame: a SSL error occurred

This looks pretty common:

Feb 14 00:45:12 ci-worker-s390x-01 debci[2652291]: libgd2 testing/s390x fail Feb 14 01:01:48 ci-worker-s390x-01 debci[546227]: waiting for header frame: a SSL error occurred

Feb 14 02:45:30 ci-worker-s390x-01 debci[1209706]: mmdebstrap testing/s390x pass
Feb 14 03:02:05 ci-worker-s390x-01 debci[3642098]: waiting for header frame: a SSL error occurred

Feb 14 04:40:10 ci-worker-s390x-01 debci[12655]: cacti testing/s390x tmpfail Feb 14 04:56:51 ci-worker-s390x-01 debci[3015158]: waiting for header frame: a SSL error occurred

So we seem to lose at least 15 minutes of worker time when that happens.
The failures are sometimes but not necessarily correlated:

Feb 17 01:07:17 ci-worker-s390x-01 debci[1149352]: waiting for header frame: a SSL error occurred
Feb 17 01:13:46 ci-worker-s390x-01 debci[552417]: waiting for header frame: a SSL error occurred
Feb 17 01:16:19 ci-worker-s390x-01 debci[1261598]: waiting for header frame: a SSL error occurred
Feb 17 01:21:02 ci-worker-s390x-01 debci[1487252]: waiting for header frame: a SSL error occurred
Feb 17 01:53:30 ci-worker-s390x-01 debci[3589185]: waiting for header frame: a SSL error occurred
Feb 17 02:03:24 ci-worker-s390x-01 debci[4184831]: waiting for header frame: a SSL error occurred
Feb 17 02:18:31 ci-worker-s390x-01 debci[3986861]: waiting for header frame: a SSL error occurred
Feb 17 02:41:11 ci-worker-s390x-01 debci[4167140]: waiting for header frame: a SSL error occurred
Feb 17 05:44:55 ci-worker-s390x-01 debci[1543385]: waiting for header frame: a SSL error occurred
Feb 17 05:47:10 ci-worker-s390x-01 debci[2598734]: waiting for header frame: a SSL error occurred
Feb 17 06:24:39 ci-worker-s390x-01 debci[1275755]: waiting for header frame: a SSL error occurred
Feb 17 06:50:05 ci-worker-s390x-01 debci[3680449]: waiting for header frame: a SSL error occurred
Feb 17 07:33:09 ci-worker-s390x-01 debci[107515]: waiting for header frame: a SSL error occurred
Feb 17 07:48:04 ci-worker-s390x-01 debci[2816244]: waiting for header frame: a SSL error occurred
Feb 17 07:54:07 ci-worker-s390x-01 debci[2284573]: waiting for header frame: a SSL error occurred
Feb 17 12:40:38 ci-worker-s390x-01 debci[4069122]: waiting for header frame: a SSL error occurred
Feb 17 15:39:40 ci-worker-s390x-01 debci[3343838]: waiting for header frame: a SSL error occurred
Feb 17 20:23:33 ci-worker-s390x-01 debci[3531969]: waiting for header frame: a SSL error occurred
Feb 17 21:21:28 ci-worker-s390x-01 debci[1815008]: waiting for header frame: a SSL error occurred
Feb 17 23:28:02 ci-worker-s390x-01 debci[2830093]: waiting for header frame: a SSL error occurred
Feb 18 01:38:13 ci-worker-s390x-01 debci[3999976]: waiting for header frame: a SSL error occurred
Feb 18 04:21:49 ci-worker-s390x-01 debci[1774710]: waiting for header frame: a SSL error occurred
Feb 18 04:21:53 ci-worker-s390x-01 debci[1530267]: waiting for header frame: a SSL error occurred
Feb 18 04:43:09 ci-worker-s390x-01 debci[2484158]: waiting for header frame: a SSL error occurred
Feb 18 04:54:21 ci-worker-s390x-01 debci[3870455]: waiting for header frame: a SSL error occurred
Feb 18 06:46:27 ci-worker-s390x-01 debci[632005]: waiting for header frame: a SSL error occurred
Feb 18 06:52:56 ci-worker-s390x-01 debci[516286]: waiting for header frame: a SSL error occurred
Feb 18 09:41:23 ci-worker-s390x-01 debci[57375]: waiting for header frame: a SSL error occurred

It doesn't look like amqp-consume has a lot of options in this space. I
do wonder if a Wireguard tunnel would help, if only to move this from a firewall-mediated TCP stream to a couple of UDP packets that are less
likely to be filtered. But I don't know how amenable the firewall is to
these either.

I'm personally not a friend of munin because it makes math on the graphs
hard. Do you have an idea how many packages the s390x manages to process
per day and how that compares to the other workers? PubSub queues are
not the easiest to introspect and I'd like to know how far we are off in
intake into the queue per day vs. what we can process.

Kind regards and thanks
Philipp Kern

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

On 16.02.23 17:49, Paul Gevers wrote:

As you can see e.g. here [1,2] it comes and goes (albeit sometimes the
queue was empty). I don't think its very different, I just never got out
of the s390x host what I was expecting. Long time I blamed it on the "stealing" that happens on a shared host, but I think there's more.

https://ci.debian.net/munin/ci-worker-s390x-01/ci-worker-s390x-01/debci_packages_processed.html

So a pet peeve of mine are unitless graphs. Can we please annotate what
the unit is? If we're looking at "Packages processed by architecture"[1]
(which again, isn't a workable unit), then we see that s390x does not
have a bad average, nor an overly bad max - given that it's with one
worker instead of like 14 for amd64 and 10 for arm64?

The average/max for the week is double for amd64 vs. s390x, so what does
the queue size mean? Is there still obsolete work in the queue as well
or does every item have the same value? (There's no way right now it can
catch up with that many items in the queue. Although that again depends
on the unit...)

Kind regards
Philipp Kern

[1] https://ci.debian.net/munin/debian.net/ci-master.debian.net/debci_total_packages_processed.html

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

To: [email protected] (Philipp Kern)
To: [email protected] (debian-s390)
To: [email protected] ([email protected])
To: [email protected] (Paul Flint)
To: [email protected] (William Desportes)
Copy: [email protected] (Debian CI team)

This is an OpenPGP/MIME signed message (RFC 4880 and 3156) --------------rKvqOcGKICAQwI50WMTPmHpW
Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: base64

SGksDQoNCk9uIDIxLTAyLTIwMjMgMTc6NDYsIERpcGFrIFpvcGUxIHdyb3RlOg0KPiBJIGFt IHdvbmRlcmluZyB3aGV0aGVyIHdlIGhhdmUgZG93bmdyYWRlZCB0aGUgbWFjaGluZXMgdG8g NS4xMC4wLTIwIA0KPiBrZXJuZWwgdG8gZ2V0IHJpZCBvZiB0aGUga2VybmVsIGJ1Zy4NCg0K SSB0aGluayBJIG1lbnRpb25lZCBpdCBiZWZvcmUsIHdlIGRvd25ncmFkZWQgaW5kZWVkOg0K cm9vdEBjaS13b3JrZXItczM5MHgtMDE6fiMgdW5hbWUgLWENCkxpbnV4IGNpLXdvcmtlci1z MzkweC0wMSA1LjEwLjAtMjAtczM5MHggIzEgU01QIERlYmlhbiA1LjEwLjE1OC0yIA0KKDIw MjItMTItMTMpIHMzOTB4IEdOVS9MaW51eA0KDQo+IENhbiB3ZSBjaGVjayBpZiB0aGUgcGF0 Y2ggc29sdmVzIGFueSBvZiB0aGUgQ0kgaXNzdWVzPw0KDQpJZiB0aGVyZSdzIGEgcGFja2Fn ZSBhdmFpbGFibGUgc29tZXdoZXJlLCBJIGNhbiBpbnN0YWxsIGl0LCBidXQgSSANCmN1cnJl bnRseSBkb24ndCBoYXZlIHRoZSB0aW1lIChub3IgdGhlIHdpbGwsIHNvcnJ5KSB0byBsZWFy biBob3cgdG8gDQpidWlsZCBEZWJpYW4gczM5MHgga2VybmVsIHBhY2thZ2VzLg0KDQpQYXVs
DQo=

--------------rKvqOcGKICAQwI50WMTPmHpW--

-----BEGIN PGP SIGNATURE-----

wsB5BAABCAAjFiEEWLZtSHNr6TsFLeZynFyZ6wW9dQoFAmP1HyYFAwAAAAAACgkQnFyZ6wW9dQr+ yAf/VgWpy++2EDYSa/KqcOgtbtiSxcHpGFoJuw/c72A9jMtcsAucgyz75X20jXWQhmKjavR2RSLt y2MqRtjhnzqnQuXn8Q1wqsE3E0q1fFgT4VoK+Jxshf5FXTCSUFcr9ZR3+AJmRvpLf14KfPyhpWYm G6zPWepiJJdDvCpTOk6u1+1fVHlkoov+UhYgLcjZvsPbJSUQiSfNMsKkTJSmcAbaUyvKAp7xO1QL cpamgugR6OWBUN0R3ZJHpoAOqmCW8Gk3wSuWfiq3nGc9ouZEERjoc0e1ONE1vUsN7uEpI6GA44dz CIYQ2gfh8gDVFYl1B9LBQRvZdh+MDm642gptFLv8hw==
=03R9
-----END PGP SIGNATURE-----

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

Attempting to sum together what look, to me, like a pair of 2s:

* The s390x Debian CI queue size[1] is growing again.

* A recent bug report[2] by Dipak describes userspace processes
getting stuck on an s390 Linux kernel version that Debian's CI infra
has been using

The bug does seem to have caused CI package build timeouts, as Paul
and others have discussed[3]. I was skeptical about the
kernel-as-cause theory, but now agree with it.

Perhaps the timeouts explain the queue backlog?


Also note: Sumanth has offered a fix as an s390 kernel patch[4], and
it is pending -- that is, the fix has been uploaded and is awaiting
general availability after a delay for people to review the relevant
changes -- for distribution in Debian stable.


I'm puzzled by some conflicting data, though: the ppc64 queue _isn't_
growing currently. Why did it follow the s390x trend so closely
during the previous queue buildup, and yet doesn't appear to be doing
so this time?


[1] - https://ci.debian.net/munin/debian.net/ci-master.debian.net/debci_queue_size.html

[2] - https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1031753

[3] - https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1030545

[4] - https://lists.debian.org/debian-kernel/2023/02/msg00124.html

On Sat, 18 Feb 2023 at 14:23, James Addison <[email protected]> wrote:

James Addison suggested in [3] to increase a prefetch counter in amqp (although its the same on all hosts); I have done so on the s390x host and at least initially it seems to help keeping the host busier.

Thanks for applying that - I was hoping that the change might also
result in reductions in the debci queue size for s390x, but that
doesn't appear to have happened, going by https://ci.debian.net/munin/debian.net/ci-master.debian.net/debci_queue_size.html

[3] https://salsa.debian.org/ci-team/debci/-/issues/92#note_381306

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

Copy: [email protected] (Debian CI team)
Copy: [email protected] (Dipak Zope1)
Copy: [email protected] (Philipp Kern)
Copy: [email protected] (debian-s390)
Copy: [email protected] ([email protected])
Copy: [email protected] (Paul Flint)
Copy: [email protected] (William Desportes)
Copy: [email protected]

This is an OpenPGP/MIME signed message (RFC 4880 and 3156) --------------i9zHv0SCgulgPSLmiqSaVjah
Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: base64

SGksDQoNCk9uIDI4LTAyLTIwMjMgMDE6MzksIEphbWVzIEFkZGlzb24gd3JvdGU6DQo+IEF0 dGVtcHRpbmcgdG8gc3VtIHRvZ2V0aGVyIHdoYXQgbG9vaywgdG8gbWUsIGxpa2UgYSBwYWly IG9mIDJzOg0KPiANCj4gICAgKiBUaGUgczM5MHggRGViaWFuIENJIHF1ZXVlIHNpemVbMV0g aXMgZ3Jvd2luZyBhZ2Fpbi4NCg0KWWVzLCBidXQgdGhpcyB0aW1lIGl0J3MgYmVjYXVzZSBz b21lIHRlc3Qgc2VlbXMgdG8gYmUgbWlzYmVoYXZpbmcgKG9ubHkgDQpvbiBzMzkweCBvciBi aWcgZW5kaWFuIG9yLi4uICkgYW5kIGZpbGxzIHRoZSBkaXNrIChhbmQgZ2V0cyBraWxsZWQg YnkgYSANCmNyb24gam9iIGFuZCByZXN0YXJ0cykuIEknbSBzdXNwZWN0aW5nIGRvbGZpbiAo YW5kIHB5dGhvbi1vc2xvLmRiKSBhdCANCnRoZSBtb21lbnQuDQoNCj4gICAgKiBBIHJlY2Vu dCBidWcgcmVwb3J0WzJdIGJ5IERpcGFrIGRlc2NyaWJlcyB1c2Vyc3BhY2UgcHJvY2Vzc2Vz DQo+IGdldHRpbmcgc3R1Y2sgb24gYW4gczM5MCBMaW51eCBrZXJuZWwgdmVyc2lvbiB0aGF0 IERlYmlhbidzIENJIGluZnJhDQo+IGhhcyBiZWVuIHVzaW5nDQoNCldlIHJldmVydGVkIHRv IHRoZSBwcmV2aW91cyBrZXJuZWw6DQpyb290QGNpLXdvcmtlci1zMzkweC0wMTp+IyB1bmFt ZSAtYQ0KTGludXggY2ktd29ya2VyLXMzOTB4LTAxIDUuMTAuMC0yMC1zMzkweCAjMSBTTVAg RGViaWFuIDUuMTAuMTU4LTIgDQooMjAyMi0xMi0xMykgczM5MHggR05VL0xpbnV4DQoNClBh dWwNCg==

--------------i9zHv0SCgulgPSLmiqSaVjah--

-----BEGIN PGP SIGNATURE-----

wsB5BAABCAAjFiEEWLZtSHNr6TsFLeZynFyZ6wW9dQoFAmP+Xl0FAwAAAAAACgkQnFyZ6wW9dQq7 wwgArQSR46P/HNXflaoMZDxSPh3yTEQEeOGxLFeJ/g3thxdIisFbMrEYwnZV8/CUKaIpREkXm6QL suc/pMq07SaJjQbo3jQij8euxp3IutuUAR8YSz39D16e/zVM7WJrry9SeY8xxIyaZel8b0+JXfC5 hMOdbK7onyp7ofJQrjo/CB7JddAEliP7GXo6M3QSYlXya7Il40PYDEvsYpCF2q1qpdOXqvOi2Zzq XK/6aJLdTkunB3//KvzIPcqn61CAPdSHh0vr8+xzOlaQ5lgskbbSpTj21hw2zF9uvOANqxUIJjKA rD7upVVVcMIR2x0iZJeCnpiyZvTJ25a0syzy9omfGA==
=mndO
-----END PGP SIGNATURE-----

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

On Sun, Feb 12, 2023 at 1:39 PM Paul Gevers <[email protected]> wrote:

I can provide logging from the host, but I'll need detailed instructions
of what people find useful to look at. Recently Antonio taught me a
trick to provide temporary access to a lxc container on any of our
hosts, so if it helps to be on the host (but inside lxc) we can provide
for that.

I had a call with Dipak this morning to discuss some of how we can
help, between my Linux admin and networking experience, and what we
can otherwise pull together on the Z side at IBM, we're eager to see
what we can do to make these systems a bit quicker. I think access to
the host in an LXC container would be valuable, especially if we're
still having any issues with SSH timeouts and could see about
replicating.

I noticed that the Munin graphs are showing that the queue problems
from earlier this year seem to have been reduced now, is that correct,
or has the VM just not been restarted lately? It would be helpful to
have a starting point.

Many thanks.

--
Elizabeth K. Joseph || Lyz || pleia2

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)

Copy: [email protected] (Philipp Kern)
Copy: [email protected] (debian-s390)
Copy: [email protected]
Copy: [email protected] (Paul Flint)
Copy: [email protected] (Debian CI team)

This is an OpenPGP/MIME signed message (RFC 4880 and 3156) --------------iu21NjQXKhiPNP2eRIprsNUG
Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: base64

SGkgRWxpemFiZXRoLA0KDQpPbiAxOC0wNC0yMDIzIDIyOjQ2LCBFbGl6YWJldGggSy4gSm9z ZXBoIHdyb3RlOg0KPiBJIG5vdGljZWQgdGhhdCB0aGUgTXVuaW4gZ3JhcGhzIGFyZSBzaG93 aW5nIHRoYXQgdGhlIHF1ZXVlIHByb2JsZW1zDQo+IGZyb20gZWFybGllciB0aGlzIHllYXIg c2VlbSB0byBoYXZlIGJlZW4gcmVkdWNlZCBub3csIGlzIHRoYXQgY29ycmVjdCwNCj4gb3Ig aGFzIHRoZSBWTSBqdXN0IG5vdCBiZWVuIHJlc3RhcnRlZCBsYXRlbHk/IEl0IHdvdWxkIGJl IGhlbHBmdWwgdG8NCj4gaGF2ZSBhIHN0YXJ0aW5nIHBvaW50Lg0KDQpJIHdhcyBzdXNwZWN0 aW5nIHRoYXQgYWZ0ZXIgdGhlIGxhc3QgY29tbXVuaWNhdGlvbnMgdGhlcmUgd2VyZSBzb21l IA0KY2hhbmdlcyBvbiB5b3VyIHNpZGUsIGJlY2F1c2UgSSByZWJvb3RlZCB0aGUgVk0gbWF5 YmUgdHdvIG9yIHRocmVlIHRpbWVzIA0KWzFdIGFuZCBub3RpY2VkIG5vdCBzZWVpbmcgdGhl IHNsb3cgZG93biBhcyBJIHdhcyB1c2VkIHRvLiBJIGFsc28gaGFkIA0KdGhlIGltcHJlc3Np b24gdGhhdCBzb21lIG9mIG15IG90aGVyIHBhaW4gcG9pbnQgaW1wcm92ZWQgYSBiaXQuDQoN CkF0IHRoaXMgbW9tZW50IERlYmlhbiBpcyBpbiBmcmVlemUgWzJdIGluIHByZXBhcmF0aW9u IGZvciB0aGUgcmVsZWFzZSBvZiANCkRlYmlhbiBib29rd29ybSwgaGVuY2UgaXQncyByYXRo ZXIgZHVsbCBvbiB0aGUgQ0kgc2lkZS4gVGhhdCBtYWtlcyANCmludGVycHJldGluZyB0aGUg TXVuaW4gZ3JhcGhzIGEgYml0IGRpZmZpY3VsdC4gSW4gdGhlIG1lYW4gdGltZSBJIGhhdmUg DQphbHNvIHVwZ3JhZGVkIHRoZSBWTSB0byBydW4gRGViaWFuIGJvb2t3b3JtIChhcm91bmQg MjAyMy0wMy0xNCksIG1heWJlIA0KdGhhdCBhbHNvIG1ha2UgYSBkaWZmZXJlbmNlLg0KDQpJ IHByb3Bvc2Ugd2Ugd2FpdCB3aXRoIGZ1cnRoZXIgaW52ZXN0aWdhdGlvbnMgdW50aWwgYWZ0 ZXIgdGhlIGJvb2t3b3JtIA0KcmVsZWFzZS4gT25jZSBvdXIgQ0kgaG9zdHMgYXJlIGxvYWRl ZCBub3JtYWxseSBhZ2FpbiBJIHRoaW5rIHdlJ3JlIGluIGEgDQpiZXR0ZXIgcG9zaXRpb24g dG8ganVkZ2UgcmVhbCBwZXJmb3JtYW5jZS4gSGF2aW5nIHNhaWQgdGhhdCwgSSdtIGhhcHB5 IA0KdG8gc2NoZWR1bGUgYW5kL29yIGFycmFuZ2UgYWNjZXNzIHRvIGFuIExYQyBjb250YWlu ZXIgb24gb3VyIGhvc3QgZm9yIA0KaW52ZXN0aWdhdGlvbnMgYWxyZWFkeSBiZWZvcmUgdGhh dCB0aW1lIGlmIHlvdSB3YW50IHRvIHBva2UgYXJvdW5kLg0KDQpQYXVsDQoNClsxXSANCmh0 dHBzOi8vY2kuZGViaWFuLm5ldC9tdW5pbi9jaS13b3JrZXItczM5MHgtMDEvY2ktd29ya2Vy LXMzOTB4LTAxL3VwdGltZS5odG1sDQpbMl0gaHR0cHM6Ly9yZWxlYXNlLmRlYmlhbi5vcmcv dGVzdGluZy9mcmVlemVfcG9saWN5Lmh0bWwjc3VtbWFyeQ0K

--------------iu21NjQXKhiPNP2eRIprsNUG--

-----BEGIN PGP SIGNATURE-----

wsB5BAABCAAjFiEEWLZtSHNr6TsFLeZynFyZ6wW9dQoFAmRA2fQFAwAAAAAACgkQnFyZ6wW9dQqq 0gf/W02q++rnwDf+f1AYNsJo6DlIdUu6eV8bZDhhhanp4FQhsVM6/suL5Ypcz/Oh0wmOR+WfsgLL dU6jHqRbiwvZj/JiQWlKTKjTjnRwXa2+Pnes2x814irzqn63Bp2P/ZrQqhdPyzNxNXqKjSrRV/51 /0LSTlaEMm4P/HlY1CmE3X4dZxoOIlRUG89ZbGMOThv61Xwu4E5w6xcqcaFXKN0LWxfq5p+oB/K7 6VOynDgQ/u7fKjV1J03rC+azVwWfXfhrSm+hXgox4wGxgoFtn/u4ZmM7j/qbmDXtGsFx5zO6JLme oF2FL3D6GlZ149MgPBh9nkSCukFjB6Slt6rn9jpjiw==
=BJLy
-----END PGP SIGNATURE-----

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)