Bug 1869023

Current information might not be enough to know what has happened.

Xiaohui, would you please keep the destionation host environment when it reproduces next time?  We need to know whether the tcp session has correctly closed on dest host first.

(In reply to Peter Xu from comment #1)
> Current information might not be enough to know what has happened.
> 
> Xiaohui, would you please keep the destionation host environment when it
> reproduces next time?  We need to know whether the tcp session has correctly
> closed on dest host first.

Hi, 
I could reproduce this bz for most times. 
I have sent you the environment information and test steps via email, please check.

The bug can be reproduced by me running the "nmcli conn down xxx" very quickly right after start postcopy on src, manually.

Not easy to dump the qemu backtrace on destination since it already does not respond to gdb signals, which seems to hang gdb attachings.  However strangely (but also luckily) it'll still respond to sigabrt, so finally I saw where the migration incoming thread hanged at:

Thread 7 (Thread 0x7f19f9fff700 (LWP 7334)):
#0  __libc_recvmsg (flags=1073741824, msg=0x7f19f9ffe2d0, fd=32) at ../sysdeps/unix/sysv/linux/recvmsg.c:28
#1  __libc_recvmsg (fd=32, msg=0x7f19f9ffe2d0, flags=1073741824) at ../sysdeps/unix/sysv/linux/recvmsg.c:25
#2  0x000055db480ddf0c in qio_channel_socket_readv ()
#3  0x000055db480db7f6 in qio_channel_read ()
#4  0x000055db47ff53c1 in channel_get_buffer ()
#5  0x000055db47ff3fd4 in qemu_fill_buffer ()
#6  0x000055db47ff49d5 in qemu_peek_byte ()
#7  0x000055db47ff4c92 in qemu_get_be32 ()
#8  0x000055db47ff4d22 in qemu_get_be64 ()
#9  0x000055db47e12879 in ram_load ()
#10 0x000055db47fef5bb in qemu_loadvm_state_main ()
#11 0x000055db47ff022c in postcopy_ram_listen_thread ()
#12 0x000055db48134b64 in qemu_thread_start ()
#13 0x00007f1b1497f14a in start_thread (arg=<optimized out>) at pthread_create.c:479
#14 0x00007f1b146b0f23 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

This is kind of strange, because after "nmcli conn down xxx" I thought the recvmsg() should return and fail gracefully and quickly (at least in 30 seconds).  It seems not...

I double confirmed this is the case by trigger again the bug and dump the kernel stack; it's indeed hanged in the tcp stack of recvmsg():

[<0>] wait_woken+0x43/0x80                                                                                                                        
[<0>] sk_wait_data+0x11f/0x130                                                                                                                    
[<0>] tcp_recvmsg+0x816/0xc60                                                                                                                     
[<0>] inet_recvmsg+0x5b/0xd0                                                                                                                      
[<0>] ____sys_recvmsg+0x91/0x150                                                                                                                  
[<0>] ___sys_recvmsg+0x7b/0xc0                                                                                                                    
[<0>] __sys_recvmsg+0x54/0xa0                                                                                                                     
[<0>] do_syscall_64+0x5b/0x1a0                                                                                                                    
[<0>] entry_SYSCALL_64_after_hwframe+0x65/0xca                                                                                                    

I'm not sure whether I get it right, but I do see that during schedule_timeout() of wait_woken() we'll even ignore signals (I guess that's why gdb attach won't work).  I did a quick trace on wait_woken() to dump the timeout, it seems to be a very huge number (0x7fffffffffffffff), not 100% sure I'm getting the right stuff dumped, though.

It gives me the feeling that this could be a network issue.  Adding Jason in the loop too in case there's any input.

I agree that I'd expect the TCP connection to time out; especially with those TCP settings - but I'll leave that to Jason.

However, can we recover the destination my issuing a 'migrate-pause' on an OOB qmp ?

(In reply to Peter Xu from comment #3)
> The bug can be reproduced by me running the "nmcli conn down xxx" very
> quickly right after start postcopy on src, manually.
> 
> Not easy to dump the qemu backtrace on destination since it already does not
> respond to gdb signals, which seems to hang gdb attachings.  However
> strangely (but also luckily) it'll still respond to sigabrt, so finally I
> saw where the migration incoming thread hanged at:
> 
> Thread 7 (Thread 0x7f19f9fff700 (LWP 7334)):
> #0  __libc_recvmsg (flags=1073741824, msg=0x7f19f9ffe2d0, fd=32) at
> ../sysdeps/unix/sysv/linux/recvmsg.c:28
> #1  __libc_recvmsg (fd=32, msg=0x7f19f9ffe2d0, flags=1073741824) at
> ../sysdeps/unix/sysv/linux/recvmsg.c:25
> #2  0x000055db480ddf0c in qio_channel_socket_readv ()
> #3  0x000055db480db7f6 in qio_channel_read ()
> #4  0x000055db47ff53c1 in channel_get_buffer ()
> #5  0x000055db47ff3fd4 in qemu_fill_buffer ()
> #6  0x000055db47ff49d5 in qemu_peek_byte ()
> #7  0x000055db47ff4c92 in qemu_get_be32 ()
> #8  0x000055db47ff4d22 in qemu_get_be64 ()
> #9  0x000055db47e12879 in ram_load ()
> #10 0x000055db47fef5bb in qemu_loadvm_state_main ()
> #11 0x000055db47ff022c in postcopy_ram_listen_thread ()
> #12 0x000055db48134b64 in qemu_thread_start ()
> #13 0x00007f1b1497f14a in start_thread (arg=<optimized out>) at
> pthread_create.c:479
> #14 0x00007f1b146b0f23 in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
> 
> This is kind of strange, because after "nmcli conn down xxx" I thought the
> recvmsg() should return and fail gracefully and quickly (at least in 30
> seconds).  It seems not...
> 
> I double confirmed this is the case by trigger again the bug and dump the
> kernel stack; it's indeed hanged in the tcp stack of recvmsg():
> 
> [<0>] wait_woken+0x43/0x80                                                  
> 
> [<0>] sk_wait_data+0x11f/0x130                                              
> 
> [<0>] tcp_recvmsg+0x816/0xc60                                               
> 
> [<0>] inet_recvmsg+0x5b/0xd0                                                
> 
> [<0>] ____sys_recvmsg+0x91/0x150                                            
> 
> [<0>] ___sys_recvmsg+0x7b/0xc0                                              
> 
> [<0>] __sys_recvmsg+0x54/0xa0                                               
> 
> [<0>] do_syscall_64+0x5b/0x1a0                                              
> 
> [<0>] entry_SYSCALL_64_after_hwframe+0x65/0xca                              
> 
> 
> I'm not sure whether I get it right, but I do see that during
> schedule_timeout() of wait_woken() we'll even ignore signals (I guess that's
> why gdb attach won't work).

It looks to me sk_wait_event() is using interruptible sleep?


  I did a quick trace on wait_woken() to dump the
> timeout, it seems to be a very huge number (0x7fffffffffffffff), not 100%
> sure I'm getting the right stuff dumped, though.

I suspect it was somehow related to the changing of tcp timeout due to the sysfs operations.

Thanks

> 
> It gives me the feeling that this could be a network issue.  Adding Jason in
> the loop too in case there's any input.

Hi:

Some questions:

1) Can you reproduce the issue without tunning tcp (sysfs)?
2) If not, can you try to see which parameter cause the long wait?

Thanks

(In reply to jason wang from comment #7)
> Hi:
> 
> Some questions:
> 
> 1) Can you reproduce the issue without tunning tcp (sysfs)?
> 2) If not, can you try to see which parameter cause the long wait?
> 
> Thanks

I haven't available machines for this test now and this may need some days.
I will try to loan two machines and test it asap.

(In reply to jason wang from comment #7)
> Hi:
> 

Hi, sorry for so late.

> Some questions:
> 
> 1) Can you reproduce the issue without tunning tcp (sysfs)?

Could still reproduce this bz without tunning tcp (sysfs).
But not always reproduce, the reproduce rate is lower (maybe 1/10)

> 2) If not, can you try to see which parameter cause the long wait?

Viewing the answer of question 1, this bz isn't related with tunning tcp.

> 
> Thanks

(In reply to Li Xiaohui from comment #10)
> (In reply to jason wang from comment #7)
> > Hi:
> > 
> 
> Hi, sorry for so late.
> 
> > Some questions:
> > 
> > 1) Can you reproduce the issue without tunning tcp (sysfs)?
> 
> Could still reproduce this bz without tunning tcp (sysfs).
> But not always reproduce, the reproduce rate is lower (maybe 1/10)

Update the accurate reproduce rate: 3/10

> 
> > 2) If not, can you try to see which parameter cause the long wait?
> 
> Viewing the answer of question 1, this bz isn't related with tunning tcp.
> 
> > 
> > Thanks

Move RHEL-AV bugs to RHEL9. If necessary to resolve in RHEL8, then clone to the current RHEL8 release.

After evaluating this issue, there are no plans to address it further or fix it in an upcoming release.  Therefore, it is being closed.  If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened.

Reopen as this bug was closed due to out of stale date.  Will close as currentrelease if not reproduce on RHEL 9.1.

Still reproduce this bug on RHEL 9.1.0 hosts(kernel-5.14.0-105.el9.x86_64 && qemu-kvm-7.0.0-5.el9.x86_64)

(In reply to Dr. David Alan Gilbert from comment #4)
> I agree that I'd expect the TCP connection to time out; especially with
> those TCP settings - but I'll leave that to Jason.
> 
> However, can we recover the destination my issuing a 'migrate-pause' on an
> OOB qmp ?

Sorry to ignore this comment.

When I use {"exec-oob":"migrate-pause"} to pause migration on destination host, it works well.
And after network recovery, postcopy migration succeeds after recovering migration, and vm works on destination host.

This aging bug was planned to be resolved within the 9.2.0 release timeframe; however, since it has not been addressed by ITM 24, we are closing as deferred. 

If this bug is reopened, there must be a downstream commit ready to be posted for merge or the bug must be part of some rebase. When reopening, add the release ITR and appropriate DTM.

Hi John,

Yesterday I tried to test this bug on the latest RHEL 9.2 (kernel-5.14.0-252.el9.x86_64 & qemu-kvm-7.2.0-8.el9.x86_64), they all passed, didn't hit any issues.


So maybe we can close this bug as currentrelease if you agree.

(In reply to Li Xiaohui from comment #22)
> Hi John,
> 
> Yesterday I tried to test this bug on the latest RHEL 9.2
> (kernel-5.14.0-252.el9.x86_64 & qemu-kvm-7.2.0-8.el9.x86_64), they all
> passed, didn't hit any issues.

repeat 100 times, all passed.

> 
> 
> So maybe we can close this bug as currentrelease if you agree.

(In reply to Li Xiaohui from comment #22)
> Hi John,
> 
> Yesterday I tried to test this bug on the latest RHEL 9.2
> (kernel-5.14.0-252.el9.x86_64 & qemu-kvm-7.2.0-8.el9.x86_64), they all
> passed, didn't hit any issues.
> 
> 
> So maybe we can close this bug as currentrelease if you agree.

Sure I can change to currentrelease given the outcome, although I have no way to attribute the resolution to any specific commit as that knowledge so I'll just update TargetRelease to 9.2, but not change ITR (and set any other fields or keyword to TestOnly - feel free to do so if you wish though).

(In reply to John Ferlan from comment #24)
> (In reply to Li Xiaohui from comment #22)
> > Hi John,
> > 
> > Yesterday I tried to test this bug on the latest RHEL 9.2
> > (kernel-5.14.0-252.el9.x86_64 & qemu-kvm-7.2.0-8.el9.x86_64), they all
> > passed, didn't hit any issues.
> > 
> > 
> > So maybe we can close this bug as currentrelease if you agree.
> 
> Sure I can change to currentrelease given the outcome, although I have no
> way to attribute the resolution to any specific commit as that knowledge so
> I'll just update TargetRelease to 9.2, but not change ITR (and set any other
> fields or keyword to TestOnly - feel free to do so if you wish though).

Thank you. I think the current status is ok.