provisiond: stuck on a 0-db namespace decommission

[zaibon]

2020-04-14T14:41:26Z info start decommissioning reservation duration=23h59m0s expired=true id=459135-2 tag= to-delete=true type=zdb
2020-04-14T14:41:26Z debug decommiion
2020-04-14T14:41:26Z debug exits
2020-04-14T14:41:26Z debug decomission func
2020-04-14T14:41:26Z debug decomission zdb storage find
2020-04-14T14:41:26Z debug decomission ensure container
2020-04-14T14:41:26Z debug decomission zdb connection
2020-04-14T14:41:26Z debug connect to unix:///var/run/zdb_zdb42231853-ecc2-481d-bc31-178c2667eab5/zdb.sock
2020-04-14T14:41:26Z debug decomission zdb conncet
2020-04-14T14:41:26Z debug zdb client connect
2020-04-14T14:41:26Z debug zdb new pool
2020-04-14T14:41:26Z debug zdb try ping
2020-04-14T14:41:26Z debug zdb dial
2020-04-14T14:41:26Z debug zdb dial end

[maxux]

This seems to happen because zdb is blocking on printf call. This is because stdout buffer is full.

It seems that containerd or shim restarted and stdout and stderr fifo wasn't reattached (supposedly) by new process.

/var/run/containerd/fifo # ls -alh */zdb*
prwx------    1 root     root           0 Apr 14 17:34 319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stderr
prwx------    1 root     root           0 Apr 13 15:05 319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stdout
prwx------    1 root     root           0 Apr 15 12:47 938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stderr
prwx------    1 root     root           0 Apr 15 12:47 938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stdout
prwx------    1 root     root           0 Apr 14 17:34 319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stderr
prwx------    1 root     root           0 Apr 13 15:05 319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stdout
prwx------    1 root     root           0 Apr 15 12:47 938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stderr
prwx------    1 root     root           0 Apr 15 12:47 938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stdout

/var/run/containerd/fifo # cat */zdb*
[...]

This unblocked processes and decommission succeed.

According to lsof, the /usr/bin/containerd-shim-runc-v2 were renamed to .old then deleted, probably after some update, which is the classic behavior when live-updating software (like nginx does).

1300	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stdout
1300	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stdout
1300	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stdout
1300	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stdout
1300	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stderr
1300	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stderr
1300	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stderr
1300	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/938905058/zdb54610d95-b67c-4e01-bfb3-2b36b0bcf30a-stderr
2886	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stdout
2886	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stdout
2886	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stdout
2886	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stdout
2886	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stderr
2886	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stderr
2886	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stderr
2886	/usr/bin/containerd-shim-runc-v2.old (deleted)	/var/run/containerd/fifo/319351265/zdbaed4b8d9-b4e0-4ce5-b8fa-cea2c949f9b4-stderr

[zaibon]

extra log has been added to track this error in the field: #726

[maxux]

Let's hope #726 will give more information but I'm not confident. I think this issue is more in the way how containerd/shim works on reattaching streams, not sure it's related to how we handle logs.

If we don't get more information, we maybe should try back how we logged before (without redis) and see if we this solve issue. Otherwise it's something else.

It would be great to be able to reproduce it at all, by restarting containerd, shim or I don't know what cause that. It's maybe an update of contd which broke it too. I don't know. But i'm quite sure it's something restarted/upgraded.

[zaibon]

It would be great to be able to reproduce it at all, by restarting containerd, shim

Let's do that. try to analyse how things works when you stop contd and/or containerd. Should be straight forward when running the development VM.

[maxux]

I can reproduce the issue. I have an flist which contains a process generate text on stdout continuously. When provisioning the container, I can tail -f the log file under /var/cache/modules/contd/logs which are default file we log stdout and stderr.

As soon as I do zinit stop contd the log file is not appending anymore. Using debugfs, if I attach the still running process, after a while, process stale in write().

If I go to /var/run/containerd/fifo/[id]/ and then cat 13-1-stdout which is the fifo, I have content (there is 100K in the fifo) and since fifo is emptied, process continue.

What happened with zbd is probably contd which restarted after an update and save issue happens.