On Wed, Mar 22, 2023 at 02:05:06PM +0000, Dr. David Alan Gilbert wrote:
> * Peter Xu (pet...@redhat.com) wrote:
> > On Tue, Mar 21, 2023 at 08:24:37PM +0000, Dr. David Alan Gilbert wrote:
> > > Hi Peter's,
> > > Peter M pointed me to a seg in a migration test in CI; I can reproduce
> > > it:
> > > * On an s390 host
> >
> > How easy to reproduce?
>
> Pretty much every time when run as:
> make check -j 4
>
> > > * only as part of a make check - running migration-test by itself
> > > doesn't trigger for me.
> > > * It looks like it's postcopy preempt
> > >
> > > (gdb) bt full
> > > #0 iov_size (iov=iov@entry=0x2aa00e60670, iov_cnt=<optimized out>) at
> > > ../util/iov.c:88
> > > len = 13517923312037845750
> > > i = 17305
> > > #1 0x000002aa004d068c in qemu_fflush (f=0x2aa00e58630) at
> > > ../migration/qemu-file.c:307
> > > local_error = 0x0
> > > #2 0x000002aa004d0e04 in qemu_fflush (f=<optimized out>) at
> > > ../migration/qemu-file.c:297
> > > #3 0x000002aa00613962 in postcopy_preempt_shutdown_file
> > > (s=s@entry=0x2aa00d1b4e0) at ../migration/ram.c:4657
> > > #4 0x000002aa004e12b4 in migration_completion (s=0x2aa00d1b4e0) at
> > > ../migration/migration.c:3469
> > > ret = <optimized out>
> > > current_active_state = 5
> > > must_precopy = 0
> > > can_postcopy = 0
> > > in_postcopy = true
> > > pending_size = 0
> > > __func__ = "migration_iteration_run"
> > > iter_state = <optimized out>
> > > s = 0x2aa00d1b4e0
> > > thread = <optimized out>
> > > setup_start = <optimized out>
> > > thr_error = <optimized out>
> > > urgent = <optimized out>
> > > #5 migration_iteration_run (s=0x2aa00d1b4e0) at
> > > ../migration/migration.c:3882
> > > must_precopy = 0
> > > can_postcopy = 0
> > > in_postcopy = true
> > > pending_size = 0
> > > __func__ = "migration_iteration_run"
> > > iter_state = <optimized out>
> > > s = 0x2aa00d1b4e0
> > > thread = <optimized out>
> > > setup_start = <optimized out>
> > > thr_error = <optimized out>
> > > urgent = <optimized out>
> > > #6 migration_thread (opaque=opaque@entry=0x2aa00d1b4e0) at
> > > ../migration/migration.c:4124
> > > iter_state = <optimized out>
> > > s = 0x2aa00d1b4e0
> > > --Type <RET> for more, q to quit, c to continue without paging--
> > > thread = <optimized out>
> > > setup_start = <optimized out>
> > > thr_error = <optimized out>
> > > urgent = <optimized out>
> > > #7 0x000002aa00819b8c in qemu_thread_start (args=<optimized out>) at
> > > ../util/qemu-thread-posix.c:541
> > > __cancel_buf =
> > > {__cancel_jmp_buf = {{__cancel_jmp_buf = {{__gregs =
> > > {4396782422080, 4393751543808, 4397299389454, 4396844235904,
> > > 2929182727824, 2929182933488, 4396843986792, 4397299389455,
> > > 33679382915066768, 33678512846981306}, __fpregs = {4396774031360,
> > > 8392704, 2929182933488, 0, 4396782422272, 2929172491858, 4396774031360,
> > > 1}}}, __mask_was_saved = 0}}, __pad = {0x3ffb4a77a60, 0x0, 0x0, 0x0}}
> > > __cancel_routine = 0x2aa00819bf0 <qemu_thread_atexit_notify>
> > > __not_first_call = <optimized out>
> > > start_routine = 0x2aa004e08f0 <migration_thread>
> > > arg = 0x2aa00d1b4e0
> > > r = <optimized out>
> > > #8 0x000003ffb7b1e2e6 in start_thread () at /lib64/libc.so.6
> > > #9 0x000003ffb7aafdbe in thread_start () at /lib64/libc.so.6
> > >
> > > It looks like it's in the preempt test:
> > >
> > > (gdb) where
> > > #0 0x000003ffb17a0126 in __pthread_kill_implementation () from
> > > /lib64/libc.so.6
> > > #1 0x000003ffb1750890 in raise () from /lib64/libc.so.6
> > > #2 0x000003ffb172a340 in abort () from /lib64/libc.so.6
> > > #3 0x000002aa0041c130 in qtest_check_status (s=<optimized out>) at
> > > ../tests/qtest/libqtest.c:194
> > > #4 0x000003ffb1a3b5de in g_hook_list_invoke () from
> > > /lib64/libglib-2.0.so.0
> > > #5 <signal handler called>
> > > #6 0x000003ffb17a0126 in __pthread_kill_implementation () from
> > > /lib64/libc.so.6
> > > #7 0x000003ffb1750890 in raise () from /lib64/libc.so.6
> > > #8 0x000003ffb172a340 in abort () from /lib64/libc.so.6
> > > #9 0x000002aa00420318 in qmp_fd_receive (fd=<optimized out>) at
> > > ../tests/qtest/libqmp.c:80
> > > #10 0x000002aa0041d5ee in qtest_qmp_receive_dict (s=0x2aa01eb2700) at
> > > ../tests/qtest/libqtest.c:713
> > > #11 qtest_qmp_receive (s=0x2aa01eb2700) at ../tests/qtest/libqtest.c:701
> > > #12 qtest_vqmp (s=s@entry=0x2aa01eb2700, fmt=fmt@entry=0x2aa00487100 "{
> > > 'execute': 'query-migrate' }", ap=ap@entry=0x3ffc247cc68)
> > > at ../tests/qtest/libqtest.c:765
> > > #13 0x000002aa00413f1e in wait_command (who=who@entry=0x2aa01eb2700,
> > > command=command@entry=0x2aa00487100 "{ 'execute': 'query-migrate' }")
> > > at ../tests/qtest/migration-helpers.c:73
> > > #14 0x000002aa00414078 in migrate_query (who=who@entry=0x2aa01eb2700) at
> > > ../tests/qtest/migration-helpers.c:139
> > > #15 migrate_query_status (who=who@entry=0x2aa01eb2700) at
> > > ../tests/qtest/migration-helpers.c:161
> > > #16 0x000002aa00414480 in check_migration_status (ungoals=0x0,
> > > goal=0x2aa00495c7e "completed", who=0x2aa01eb2700) at
> > > ../tests/qtest/migration-helpers.c:177
> > > #17 wait_for_migration_status (who=0x2aa01eb2700, goal=<optimized out>,
> > > ungoals=0x0) at ../tests/qtest/migration-helpers.c:202
> > > #18 0x000002aa0041300e in migrate_postcopy_complete
> > > (from=from@entry=0x2aa01eb2700, to=to@entry=0x2aa01eb3000,
> > > args=args@entry=0x3ffc247cf48)
> > > at ../tests/qtest/migration-test.c:1137
> > > #19 0x000002aa004131a4 in test_postcopy_common (args=0x3ffc247cf48) at
> > > ../tests/qtest/migration-test.c:1162
> > > #20 test_postcopy_preempt () at ../tests/qtest/migration-test.c:1178
> > >
> > > Looking at the iov and file it's garbage; so it makes me think this is
> > > something like a flush on a closed file.
> >
> > I didn't figure out how that could be closed, but I think there's indeed a
> > possible race that the qemufile can be accessed by both the return path
> > thread and the migration thread concurrently, while qemufile is not thread
> > safe on that.
> >
> > What postcopy_preempt_shutdown_file() does was: the src uses this EOS to
> > kick the dest QEMU preempt thread out of the migration and shut it off.
> > After some thought I think this is unnecessary complexity, since postcopy
> > should end at the point where dest received all the data, then it sends a
> > SHUT to src. So potentially it's not good to have dest relying on anything
> > from src to shutdown anything (the preempt thread here) because it's the
> > dest qemu that makes the final decision to finish. Ideally the preempt
> > thread on dest should be able to shutdown itself.
> >
> > The trick here is preempt thread will block at read() (aka, recvmsg()) at
> > the channel at that time and the only way to kick it out from that is a
> > shutdown() on dest. I attached a patch did it. I'm not 100% sure whether
> > it'll already resolve our problem but worth trying. This also made me
> > notice we forgot to enable SHUTDOWN feature on tls server when I was
> > running the patch 1 with qtest, so two patches needed.
>
> Well, it seems to fix it:
>
> Tested-by: Dr. David Alan Gilbert <dgilb...@redhat.com>
>
> Will this break interaction with an old qemu that's still waiting for
> the EOS?
Right.. when someone migrates from a 8.0+ QEMU (assuming this can land in
this release) to 7.2 QEMU with postcopy+preempt enabled.
I still see preempt full support only in 8.0; we did major rework in 8.0 to
shift to the return path. So maybe it's worth the risk? I can also add a
flag for this but it may add maintainance burden in general OTOH.
--
Peter Xu
