process hangs on system startup after CRIU restore

[PavloMykhailyshyn]

Description

My service launches CRIU for each process (it could be the same binary with different arguments) simultaneously.
When all dumps are complete, the service ends. The system gets rebooted.
The system boots, the service starts again and goes through each dump folder. It runs CRIU on every image simultaneously.

Service did dump
/usr/sbin/criu-ns dump --images-dir /var/lib/dumps/images/zeb2ft-s5kpj2-64gu7z --shell-job --ext-unix-sk -v4 --log-file ../../logs/dump/2022-06-07T15:31:40Z_zeb2ft-s5kpj2-64gu7z.log --action-script /usr/local/sbin/criu_action_script.sh --tree 385732 --ghost-limit 1G --tcp-established

and restore
/usr/sbin/criu-ns restore --images-dir /var/lib/dumps/images/zeb2ft-s5kpj2-64gu7z --shell-job --ext-unix-sk -v4 --log-file ../../logs/restore/2022-06-07T15:36:06Z_zeb2ft-s5kpj2-64gu7z.log --action-script /usr/local/sbin/criu_action_script.sh --restore-detached --tcp-close

Dumps and Restores are always successful, but the process hangs. It is only reproducible after the system gets rebooted. While the system is on everything works perfectly.

the process stuck here (not CRIU process, CRIU finished successfully)

Thread 30 (Thread 0x7f01b27fc700 (LWP 2799)):
#0  __libc_read (nbytes=5, buf=0x11bd0f73, fd=6) at ../sysdeps/unix/sysv/linux/read.c:26
#1  __libc_read (fd=6, buf=0x11bd0f73, nbytes=5) at ../sysdeps/unix/sysv/linux/read.c:24
#2  0x00007f01cad0e3d9 in ?? () from target:/lib/x86_64-linux-gnu/libcrypto.so.1.1
#3  0x00007f01cad0967e in ?? () from target:/lib/x86_64-linux-gnu/libcrypto.so.1.1
#4  0x00007f01cad084d4 in ?? () from target:/lib/x86_64-linux-gnu/libcrypto.so.1.1
#5  0x00007f01cad08aa7 in BIO_read () from target:/lib/x86_64-linux-gnu/libcrypto.so.1.1
#6  0x00007f01cabf1b91 in ?? () from target:/lib/x86_64-linux-gnu/libssl.so.1.1
#7  0x00007f01cabf5e1e in ?? () from target:/lib/x86_64-linux-gnu/libssl.so.1.1
#8  0x00007f01cabf36d0 in ?? () from target:/lib/x86_64-linux-gnu/libssl.so.1.1
#9  0x00007f01cabfac45 in ?? () from target:/lib/x86_64-linux-gnu/libssl.so.1.1
#10 0x00007f01cac05a3f in ?? () from target:/lib/x86_64-linux-gnu/libssl.so.1.1
#11 0x00007f01cac05b47 in SSL_read () from target:/lib/x86_64-linux-gnu/libssl.so.1.1

How to solve this hanging problem? Maybe the connections were restored somehow wrong?
Is CRIU doing something bad or is my system causing such behavior (these reboots, etc)?

criu --version
Version: 3.16.1

[PavloMykhailyshyn]

@Snorch and @rst0git
Could you be so kind to suggest something about this?

[rst0git]

@PavloMykhailyshyn could you try adding --tcp-close to the dump command as well?
(We recently enabled this option for dump as well.)

[rst0git]

#11 0x00007f01cac05b47 in SSL_read () from target:/lib/x86_64-linux-gnu/libssl.so.1.1

It looks like the process is stuck on SSL_read() reading from closed TCP socket.
https://www.openssl.org/docs/man1.1.1/man3/SSL_read.html

[PavloMykhailyshyn]

still the same

[PavloMykhailyshyn]

I will try to run several tests and get back to you with criu logs and callstacks

[PavloMykhailyshyn]

/usr/sbin/criu-ns dump --images-dir /var/lib/myservice/agent-dumps/images/image-id --shell-job --ext-unix-sk -v4 --log-file ../../logs/dump/2022-06-16T09:37:55Z_image-id.log --action-script /usr/local/sbin/criu_action_script.sh --tree 3469854 --ghost-limit 1G --tcp-close
dump.txt

/usr/sbin/criu-ns restore --images-dir /var/lib/myservice/agent-dumps/images/image-id --shell-job --ext-unix-sk -v4 --log-file ../../logs/restore/2022-06-16T09:45:38Z_image-id.log --action-script /usr/local/sbin/criu_action_script.sh --restore-detached --tcp-close
restore.txt

Thread 28 (Thread 0x7fed2ffe7700 (LWP 2550)):
#0  __libc_read (nbytes=5, buf=0x7fed3c058f43, fd=6) at ../sysdeps/unix/sysv/linux/read.c:26
#1  __libc_read (fd=6, buf=0x7fed3c058f43, nbytes=5) at ../sysdeps/unix/sysv/linux/read.c:24
#2  0x00007fed48ade3d9 in ?? () from target:/lib/x86_64-linux-gnu/libcrypto.so.1.1
#3  0x00007fed48ad967e in ?? () from target:/lib/x86_64-linux-gnu/libcrypto.so.1.1
#4  0x00007fed48ad84d4 in ?? () from target:/lib/x86_64-linux-gnu/libcrypto.so.1.1
#5  0x00007fed48ad8aa7 in BIO_read () from target:/lib/x86_64-linux-gnu/libcrypto.so.1.1
#6  0x00007fed489c1b91 in ?? () from target:/lib/x86_64-linux-gnu/libssl.so.1.1
#7  0x00007fed489c5e1e in ?? () from target:/lib/x86_64-linux-gnu/libssl.so.1.1
#8  0x00007fed489c36d0 in ?? () from target:/lib/x86_64-linux-gnu/libssl.so.1.1
#9  0x00007fed489cac45 in ?? () from target:/lib/x86_64-linux-gnu/libssl.so.1.1
#10 0x00007fed489d5a3f in ?? () from target:/lib/x86_64-linux-gnu/libssl.so.1.1
#11 0x00007fed489d5b47 in SSL_read () from target:/lib/x86_64-linux-gnu/libssl.so.1.1

Thread 10 (Thread 0x7fed42521700 (LWP 2532)):
#0  __libc_recv (flags=<optimised out>, len=1, buf=0x7fed4251eca0, fd=5) at ../sysdeps/unix/sysv/linux/recv.c:28
#1  __libc_recv (fd=5, buf=0x7fed4251eca0, len=1, flags=0) at ../sysdeps/unix/sysv/linux/recv.c:23

everything else waits on futex_wait_cancelable

[PavloMykhailyshyn]

@rst0git please take a look

[PavloMykhailyshyn]

but I noticed that after some period of time (perhaps 10-50 min, could be more, it depends) everything becomes normal and the process continues to work

[PavloMykhailyshyn]

I attempted to dump and restore the restored process. Now it is truly stuck.
I did it for two processes:

• first one

#0  __libc_recv (flags=<optimised out>, len=1, buf=0x7f8b3effaca0, fd=5) at ../sysdeps/unix/sysv/linux/recv.c:28
#1  __libc_recv (fd=5, buf=0x7f8b3effaca0, len=1, flags=0) at ../sysdeps/unix/sysv/linux/recv.c:23

• second

#0  __libc_recv (flags=<optimised out>, len=1, buf=0x7fa30d7f7ca0, fd=5) at ../sysdeps/unix/sysv/linux/recv.c:28
#1  __libc_recv (fd=5, buf=0x7fa30d7f7ca0, len=1, flags=0) at ../sysdeps/unix/sysv/linux/recv.c:23

[PavloMykhailyshyn]

processes call such fucntion
recv(m_sock, buf, block_read, 0);

[PavloMykhailyshyn]

@Snorch & @rst0git
Please suggest something here
Does the bug exist in criu or is it a problem on my end?

[PavloMykhailyshyn]

after attaching and detaching gdb from the process everything magically started to work

[PavloMykhailyshyn]

but the process takes much more time to finish its work than before dump and restore
(e.g. in a normal situation it lasts 40 min, after dump and restore almost 5 hours)

[PavloMykhailyshyn]

any thoughts?
@rst0git @Snorch @avagin @adrianreber
The problem is crucial, I need a suggestion here

[avagin]

What kernel do you use? Does it support time namespaces? Could you strace (strace -fo strace.log -s 1024 -p PID) the target process after restore? If it starts to work after gdb, it has to start work after strace too. I want to see first a few hundred lines in the log.