{"id":3474,"date":"2024-03-05T18:15:10","date_gmt":"2024-03-05T16:15:10","guid":{"rendered":"https:\/\/vasil.ludost.net\/blog\/?p=3474"},"modified":"2024-03-08T12:25:02","modified_gmt":"2024-03-08T10:25:02","slug":"2024-03-05-the-failed-live-migration-case","status":"publish","type":"post","link":"https:\/\/vasil.ludost.net\/blog\/?p=3474","title":{"rendered":"2024-03-05 The failed live migration case"},"content":{"rendered":"

There’s a purpose in everyone’s life. Some days, it seems like mine is to show people what not to do.<\/p>\n

I’ve written this explanation to show my mistakes and that, hopefully, other people don’t (there’s no hope for me). What follows is most of my debugging process, and it could be helpful to other people to see it (and point out what is wrong with it).<\/p>\n

This happens in a StorPool deployment for a customer who runs a public cloud service. We provide the shared storage via some drivers of our own, and the customer uses OpenNebula to control Linux\/KVM hypervisors. It’s all integrated very nicely and is used for our internal clouds.<\/p>\n

KVM VMs are a qemu<\/code> process in the Linux userspace with multiple threads.<\/p>\n

The case started with a customer complaining that after an update we did to the storage software, the live migrations of his VMs started failing (the VMs would fail to move but would continue working on the original host). The problem was narrowed down to VMs started before a specific date (when we did the update mentioned above), and initially, it seemed to be contained to VMs that had QEMU CPU set (i.e., the least performant one).<\/p>\n

At this point, I asked – can’t they restart all such VMs? This CPU type is mainly contributing to global warming anyway.
\nThe reply was, “Are you insane? These are 900 VMs. We’ll reboot them, but we really don’t want to do that now”.
\nFair point.<\/p>\n

Then, some further tests showed that any VMs, not just the ones with the QEMU CPU, were failing the migration. Finally, someone looked into the (not easy to find) logs of qemu<\/code> and found the following:<\/p>\n

\n2024-02-20T09:46:41.938285Z qemu-kvm-one: qemu_savevm_state_complete_precopy_non_iterable: bdrv_inactivate_all() failed (-1)\n<\/pre>\n
(seriously. Trying to trace anything via the logs in OpenNebula\/libvirt\/qemu feels like interrogating prisoners who don’t speak your language.)<\/p>\n
Two mistakes above that would’ve saved a day or two – I should’ve looked into the issue immediately myself instead of relying on hearsay and building the wrong picture (based on assumptions) in my head. I did not expect that the (routine) update we did could have any such effect.<\/p>\n
I specifically checked if the same problem existed in our labs and test environments, where we had done the same routine update, and it didn’t exist.<\/p>\n
Now, this was weird. The only mention of the above error was in https:\/\/bugzilla.redhat.com\/show_bug.cgi?id=2058982<\/a> when the storage device on the originating side was broken. This was not the case here.<\/p>\n
My first step was to get permission to use one VM at the customer for tests, and after I had that, I ran strace on it while migrating.<\/p>\n
What I was able to see in the thread that performed the migration was:<\/p>\n
\nprctl(PR_SET_NAME, \"live_migration\")    = 0\n\u2026\nsendmsg(99, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base=\"...\"..., iov_len=32768}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 32768\nsendmsg(99, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base=\"...\"..., iov_len=32768}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 32768\nwrite(2, \"2024-02-15T07:00:23.057678Z \", 28) = 28\nwrite(2, \"qemu-kvm-one:\", 13)           = 13\nwrite(2, \" \", 1)                        = 1\nwrite(2, \"qemu_savevm_state_complete_precopy_non_iterable: bdrv_inactivate_all() failed (-1)\", 82) = 82\nwrite(2, \"\\n\", 1)                       = 1\nfutex(0x55586af89640, FUTEX_WAKE_PRIVATE, 1) = 1\nsendmsg(20, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base=\"{\\\"timestamp\\\": {\\\"seconds\\\": 1707980423, \\\"microseconds\\\": 57880}, \\\"event\\\": \\\"MIGRATION\\\", \\\"data\\\": {\\\"status\\\": \\\"failed\\\"}}\\r\\n\", iov_len=115}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 115\nfutex(0x55586af89640, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)\nsendmsg(20, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base=\"{\\\"timestamp\\\": {\\\"seconds\\\": 1707980423, \\\"microseconds\\\": 58133}, \\\"event\\\": \\\"RESUME\\\"}\\r\\n\", iov_len=82}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 82\n<\/pre>\n
Some digging showed that 99<\/code> was the file descriptor with the connection to the remote qemu. This was the memory transfer, followed almost immediately by writing out the error and nothing in between.<\/p>\n
So, being somewhat lost, I looked up debug symbols for qemu to see if I could trace this further. The usual tooling told me there weren’t:<\/p>\n
\n[root@somewhere str3]# gdb \/usr\/libexec\/qemu-kvm<\/b>\nGNU gdb (GDB) Rocky Linux 8.2-20.el8.0.1\nCopyright (C) 2018 Free Software Foundation, Inc.\nLicense GPLv3+: GNU GPL version 3 or later <http:\/\/gnu.org\/licenses\/gpl.html>\nThis is free software: you are free to change and redistribute it.\nThere is NO WARRANTY, to the extent permitted by law.\nType \"show copying\" and \"show warranty\" for details.\nThis GDB was configured as \"x86_64-redhat-linux-gnu\".\nType \"show configuration\" for configuration details.\nFor bug reporting instructions, please see:\n<http:\/\/www.gnu.org\/software\/gdb\/bugs\/>.\nFind the GDB manual and other documentation resources online at:\n    <http:\/\/www.gnu.org\/software\/gdb\/documentation\/>.\n\nFor help, type \"help\".\nType \"apropos word\" to search for commands related to \"word\"...\nReading symbols from \/usr\/libexec\/qemu-kvm...Reading symbols from .gnu_debugdata for \/usr\/libexec\/qemu-kvm...(no debugging symbols found)...done.\n(no debugging symbols found)...done.\nMissing separate debuginfos, use: yum debuginfo-install qemu-kvm-core-6.2.0-33.module+el8.8.0+1454+0b2cbfb8.x86_64\n(gdb) quit<\/b>\n\n[root@somewhere str3]# yum debuginfo-install qemu-kvm-core-6.2.0-33.module+el8.8.0+1454+0b2cbfb8.x86_64<\/b>\nRepository storpool-contrib is listed more than once in the configuration\nenabling epel-debuginfo repository\nExtra Packages for Enterprise Linux 8 - x86_64 - Debug                                                                                                                                                                                            4.0 MB\/s | 6.1 MB     00:01    \nLast metadata expiration check: 0:00:02 ago on Thu Feb 15 16:26:34 2024.\nCould not find debuginfo package for the following installed packages: qemu-kvm-core-15:6.2.0-33.module+el8.8.0+1454+0b2cbfb8.x86_64\nCould not find debugsource package for the following installed packages: qemu-kvm-core-15:6.2.0-33.module+el8.8.0+1454+0b2cbfb8.x86_64\nDependencies resolved.\nNothing to do.\nComplete!\n<\/pre>\n
(I can already hear people saying, “You’re an idiot”; someone had to point that out to me)<\/p>\n
Then, the colleague in communication with the customer said, “BTW, do you remember that at that time we did the other update, to migrate from one-type-of-volume-name to the-other-type-of-volume-name”? Of course, I didn’t. We ran the same migration in our lab, and the issue was reproduced immediately.<\/p>\n
The mistake was that I did not collect all available information (or even most of it), still relying on assumptions.<\/p>\n
I could deploy the latest qemu for AlmaLinux (almost the same as what the customer was using), download debug symbols, and start digging. Yay.<\/p>\n
On strace<\/code>, the issue looked the same – lots of sending to the socket and then just the error. So, I started digging with gdb<\/code> by attaching, adding a breakpoint, continuing the process, and then running a live migration to see how the situation looked like at different points of the program. I had something like this primed and pasted when I ran gdb -p xxxx<\/code> (some comments added to explain what these are): <\/p>\n
\nset print pretty\t\t\t# the usual gdb print is hard to read<\/i>\nset pagination off\t\t\t# pagination is annoying in this regard, my terminal can scroll<\/i>\nhandle SIGUSR1 nostop pass\t\t# qemu uses SIGUSR1 a lot<\/i>\nbreak block\/block-backend.c:253\t\t# stop here<\/i>\ncont\t\t\t\t\t# continue execution<\/i>\nbt full\t\t\t\t\t# print me a full backtrace with local variables when stopped<\/i>\n<\/pre>\n
It took some time to read through the relevant code and ensure there wasn’t something obvious (which took many wrong turns). The issue looked like that bdrv_inactivate_recurse()<\/code> was trying to remove write permissions from the devices and was failing for some reason.<\/p>\n
\n6523     \/* Inactivate this node *\/\n6524     if (bs->drv->bdrv_inactivate) {\n6525         ret = bs->drv->bdrv_inactivate(bs);\n6526         if (ret < 0) {\n6527             return ret;\n6528         }\n6529     }\n6530 \n6531     QLIST_FOREACH(parent, &bs->parents, next_parent) {\n6532         if (parent->klass->inactivate) {\n6533             ret = parent->klass->inactivate(parent);\n6534             if (ret < 0) {\n6535                 return ret;\n6536             }\n6537         }\n6538     }\n6539 \n6540     bdrv_get_cumulative_perm(bs, &cumulative_perms,\n6541                              &cumulative_shared_perms);\n6542     if (cumulative_perms & (BLK_PERM_WRITE | BLK_PERM_WRITE_UNCHANGED)) {\n6543         \/* Our inactive parents still need write access. Inactivation failed. *\/\n6544         return -EPERM;\n6545     }\n\n<\/pre>\n
This is the code in question, and in bdrv_get_cumulative_perms()<\/code>, there were some devices that still had r\/w set even after the stuff between lines 6531 and 6533 had passed:<\/p>\n
\nbdrv_inactivate_recurse (bs=0x556e00221530) at ..\/block.c:6534\n6534                if (ret < 0) {\n(gdb) \n6531        QLIST_FOREACH(parent, &bs->parents, next_parent) {\n(gdb) \n6540        bdrv_get_cumulative_perm(bs, &cumulative_perms,\n(gdb) \n6542        if (cumulative_perms & (BLK_PERM_WRITE | BLK_PERM_WRITE_UNCHANGED)) {\n(gdb) \nbdrv_inactivate_all () at ..\/block.c:6591\n6591            if (ret < 0) {\n(gdb) \n6592                bdrv_next_cleanup(&it);\n(gdb) \n\n<\/pre>\n
The inactivate()<\/code> function above was in block\/block-backend.c<\/code> and looks like this:<\/p>\n
\n 250 static int blk_root_inactivate(BdrvChild *child)\n 251 {\n 252     BlockBackend *blk = child->opaque;\n 253 \n 254     if (blk->disable_perm) {\n 255         return 0;\n 256     }\n 257 \n 258     if (!blk_can_inactivate(blk)) {\n 259         return -EPERM;\n 260     }\n 261 \n 262     blk->disable_perm = true;\n 263     if (blk->root) {\n 264         bdrv_child_try_set_perm(blk->root, 0, BLK_PERM_ALL, &error_abort);\n 265     }\n 266 \n 267     return 0;\n 268 }\n<\/pre>\n
and what was happening was:<\/p>\n
\n258         if (!blk_can_inactivate(blk)) {\n(gdb) \n262         blk->disable_perm = true;\n(gdb) \n263         if (blk->root) {\n(gdb) \n264             bdrv_child_try_set_perm(blk->root, 0, BLK_PERM_ALL, &error_abort);\n(gdb) \nbdrv_inactivate_recurse (bs=0x556e00221530) at ..\/block.c:6534\n<\/pre>\n
So qemu<\/code> is calling it, and that was all OK. <\/p>\n
Here, a few times, I had missed what this was trying to do. Here’s bdrv_child_try_set_perm()<\/code>:<\/p>\n
\n2517 \n2518 int bdrv_child_try_set_perm(BdrvChild *c, uint64_t perm, uint64_t shared,\n2519                             Error **errp)\n2520 {\n2521     Error *local_err = NULL;\n2522     Transaction *tran = tran_new();\n2523     int ret;\n2524 \n2525     bdrv_child_set_perm(c, perm, shared, tran);\n2526 \n2527     ret = bdrv_refresh_perms(c->bs, &local_err);\n2528 \n2529     tran_finalize(tran, ret);\n2530 \n2531     if (ret < 0) {\n2532         if ((perm & ~c->perm) || (c->shared_perm & ~shared)) {\n2533             \/* tighten permissions *\/\n2534             error_propagate(errp, local_err);\n2535         } else {\n2536             \/*\n2537              * Our caller may intend to only loosen restrictions and\n2538              * does not expect this function to fail.  Errors are not\n2539              * fatal in such a case, so we can just hide them from our\n2540              * caller.\n2541              *\/\n2542             error_free(local_err);\n2543             ret = 0;\n2544         }\n2545     }\n2546 \n2547     return ret;\n2548 }\n<\/pre>\n
So that 0<\/code> being passed is “remove all permissions”, but at some time late in the day, you can’t see it\u2026<\/p>\n
And now, I break into that one and try to see what happens:<\/p>\n
\n(gdb) n<\/b>\n2197        *s = (BdrvChildSetPermState) {\n(gdb) print *(local_err)<\/b>\nNo symbol \"local_err\" in current context.\n(gdb) \nNo symbol \"local_err\" in current context.\n(gdb) n<\/b>\n2203        c->perm = perm;\n(gdb) print *(local_err)<\/b>\nNo symbol \"local_err\" in current context.\n(gdb) n<\/b>\n2204        c->shared_perm = shared;\n(gdb) print *(local_err)<\/b>\nNo symbol \"local_err\" in current context.\n(gdb) n<\/b>\n2206        tran_add(tran, &bdrv_child_set_pem_drv, s);\n(gdb) n<\/b>\nbdrv_child_try_set_perm (c=0x556e002e1730, perm=perm@entry=0, shared=shared@entry=31, errp=0x556dfeb99258 <error_abort>) at ..\/block.c:2527\n2527        ret = bdrv_refresh_perms(c->bs, &local_err);\n(gdb) print *(local_err)\nCannot access memory at address 0x0\n(gdb) n<\/b>\n2529        tran_finalize(tran, ret);\n(gdb) print *(local_err)<\/b>\n$1 = {\n  msg = 0x7f25a4041b70 \"Could not open '\/var\/lib\/one\/\/datastores\/0\/310\/disk.0': No such file or directory\", \n  err_class = ERROR_CLASS_GENERIC_ERROR, \n  src = 0x556dfe63ca2a \"..\/util\/osdep.c\", \n  func = 0x556dfe63cbc0 <__func__.26488> \"qemu_open_internal\", \n  line = 359, \n  hint = 0x0\n}\n(gdb) q<\/b>\n<\/pre>\n
Now, I see it going through the function, and I’m trying to look at that local_err<\/code> if there’s something in it. Finally, I get the actual error; it has happened somewhere and is not propagated – but qemu<\/code> has tried opening a file, and that doesn’t exist.<\/p>\n
Two things here:
\n– This file does exist (it’s a symlink to a symlink to a block device, and I can access it with the permissions of the process);
\n– Why isn’t this error logged or propagated? I should probably send a patch for that\u2026
\n– This was not in what strace<\/code> showed, so what the hell.<\/p>\n
So, I break at util\/osdep.c<\/code> in qemu_open_internal()<\/code>, to see what happens. I pass through that a few times, trying to see where that error comes from, because I still think there is no syscall there, and glibc is screwing with me. This goes to show that you shouldn’t debug when tired because glibc returning ENOENT<\/code> on its own is a lot less likely than strace<\/code> missing one syscall.<\/p>\n
I’m going to leave out a lot of unsuccessful attempts and show you how I got to the next clue in one large gdb session (commends with #):<\/p>\n
\n(gdb) break util\/osdep.c:312<\/b>\nBreakpoint 1 at 0x556dfe2c5c71: file ..\/util\/osdep.c, line 312.\n(gdb) handle SIGUSR1 nostop pass\nSignal        Stop      Print   Pass to program Description\nSIGUSR1       No        Yes     Yes             User defined signal 1\n(gdb) set print pretty<\/b>\n(gdb) set pagination off<\/b>\n(gdb) cont<\/b>\nContinuing.\n[New Thread 0x7f259c9ba700 (LWP 1798462)]\n[New Thread 0x7f259c1b9700 (LWP 1798463)]\n\nThread 5 \"CPU 0\/KVM\" received signal SIGUSR1, User defined signal 1.\n\nThread 5 \"CPU 0\/KVM\" received signal SIGUSR1, User defined signal 1.\n\nThread 5 \"CPU 0\/KVM\" received signal SIGUSR1, User defined signal 1.\n[Switching to Thread 0x7f259c1b9700 (LWP 1798463)]\n\nThread 8 \"live_migration\" hit Breakpoint 1, qemu_open_internal (name=name@entry=0x556e0021b241 \"\/var\/lib\/one\/\/datastores\/0\/310\/disk.0\", flags=16384, mode=mode@entry=0, errp=errp@entry=0x7f259c1b85e0) at ..\/util\/osdep.c:318\n318         if (strstart(name, \"\/dev\/fdset\/\", &fdset_id_str)) {\n(gdb) bt full<\/b>\n\u2026 \t\t\t\t# nothing interesting in the backtrace<\/i>\n(gdb) disassemble <\/b>\nDump of assembler code for function qemu_open_internal:\n   0x0000556dfe2c5c40 <+0>:     push   %r15\n   0x0000556dfe2c5c42 <+2>:     push   %r14\n   0x0000556dfe2c5c44 <+4>:     mov    %rcx,%r14\n   0x0000556dfe2c5c47 <+7>:     push   %r13\n   0x0000556dfe2c5c49 <+9>:     mov    %edx,%r13d\n   0x0000556dfe2c5c4c <+12>:    push   %r12\n   0x0000556dfe2c5c4e <+14>:    mov    %esi,%r12d\n   0x0000556dfe2c5c51 <+17>:    lea    0x376dad(%rip),%rsi        # 0x556dfe63ca05\n   0x0000556dfe2c5c58 <+24>:    push   %rbp\n   0x0000556dfe2c5c59 <+25>:    mov    %rdi,%rbp\n   0x0000556dfe2c5c5c <+28>:    push   %rbx\n   0x0000556dfe2c5c5d <+29>:    sub    $0x28,%rsp\n   0x0000556dfe2c5c61 <+33>:    mov    %fs:0x28,%rax\n   0x0000556dfe2c5c6a <+42>:    mov    %rax,0x18(%rsp)\n   0x0000556dfe2c5c6f <+47>:    xor    %eax,%eax\n=> 0x0000556dfe2c5c71 <+49>:    lea    0x10(%rsp),%rdx\n   0x0000556dfe2c5c76 <+54>:    callq  0x556dfe2c6a30 <strstart>\n   0x0000556dfe2c5c7b <+59>:    test   %eax,%eax\n   0x0000556dfe2c5c7d <+61>:    je     0x556dfe2c5cd8 <qemu_open_internal+152>\n   0x0000556dfe2c5c7f <+63>:    mov    0x10(%rsp),%rdi\n   0x0000556dfe2c5c84 <+68>:    callq  0x556dfe2c79b0 <qemu_parse_fd>\n   0x0000556dfe2c5c89 <+73>:    movslq %eax,%rdi\n   0x0000556dfe2c5c8c <+76>:    mov    %rdi,%rbx\n   0x0000556dfe2c5c8f <+79>:    cmp    $0xffffffffffffffff,%rdi\n   0x0000556dfe2c5c93 <+83>:    je     0x556dfe2c5d7c <qemu_open_internal+316>\n   0x0000556dfe2c5c99 <+89>:    mov    %r12d,%esi\n   0x0000556dfe2c5c9c <+92>:    callq  0x556dfe101b60 <monitor_fdset_dup_fd_add>\n   0x0000556dfe2c5ca1 <+97>:    mov    %eax,%ebx\n   0x0000556dfe2c5ca3 <+99>:    cmp    $0xffffffff,%eax\n   0x0000556dfe2c5ca6 <+102>:   je     0x556dfe2c5db3 <qemu_open_internal+371>\n   0x0000556dfe2c5cac <+108>:   mov    0x18(%rsp),%rcx\n   0x0000556dfe2c5cb1 <+113>:   xor    %fs:0x28,%rcx\n   0x0000556dfe2c5cba <+122>:   mov    %ebx,%eax\n   0x0000556dfe2c5cbc <+124>:   jne    0x556dfe2c5dd3 <qemu_open_internal+403>\n   0x0000556dfe2c5cc2 <+130>:   add    $0x28,%rsp\n   0x0000556dfe2c5cc6 <+134>:   pop    %rbx\n   0x0000556dfe2c5cc7 <+135>:   pop    %rbp\n   0x0000556dfe2c5cc8 <+136>:   pop    %r12\n   0x0000556dfe2c5cca <+138>:   pop    %r13\n   0x0000556dfe2c5ccc <+140>:   pop    %r14\n   0x0000556dfe2c5cce <+142>:   pop    %r15\n   0x0000556dfe2c5cd0 <+144>:   retq   \n   0x0000556dfe2c5cd1 <+145>:   nopl   0x0(%rax)\n   0x0000556dfe2c5cd8 <+152>:   mov    %r12d,%esi\n   0x0000556dfe2c5cdb <+155>:   mov    %r13d,%edx\n   0x0000556dfe2c5cde <+158>:   mov    %rbp,%rdi\n   0x0000556dfe2c5ce1 <+161>:   xor    %eax,%eax\n   0x0000556dfe2c5ce3 <+163>:   or     $0x80000,%esi\n   0x0000556dfe2c5ce9 <+169>:   callq  0x556dfdf0f190 <open64@plt>\n\n\u2026\n\n<\/pre>\n
I am not good at reading assembly, so if I’m doing this, I’m desperate (the colleague talking to the client was sitting next to me and asking why I was digging in the assembly). I see that it should call open64@plt<\/code>, which looks like the syscall open<\/code> to me.<\/p>\n
I spend some time stepping instruction by instruction and trying to understand (and failing) what \/usr\/include\/bits\/fcntl2.h<\/code> is doing with the macros there, but instruction by instruction I get to this:<\/p>\n
\n(gdb) si<\/b>\n__libc_open64 (file=file@entry=0x556e0021b241 \"\/var\/lib\/one\/\/datastores\/0\/310\/disk.0\", oflag=oflag@entry=540672) at ..\/sysdeps\/unix\/sysv\/linux\/open64.c:37\n37      {\n(gdb) si<\/b>\n0x00007f25d7a401d4      37      {\n(gdb) si<\/b>\n0x00007f25d7a401d8      37      {\n(gdb) disassemble <\/b>\nDump of assembler code for function __libc_open64:\n   0x00007f25d7a401d0 <+0>:     endbr64 \n   0x00007f25d7a401d4 <+4>:     sub    $0x68,%rsp\n=> 0x00007f25d7a401d8 <+8>:     mov    %esi,%r10d\n   0x00007f25d7a401db <+11>:    mov    %rdx,0x40(%rsp)\n   0x00007f25d7a401e0 <+16>:    mov    %fs:0x28,%rax\n   0x00007f25d7a401e9 <+25>:    mov    %rax,0x28(%rsp)\n   0x00007f25d7a401ee <+30>:    xor    %eax,%eax\n   0x00007f25d7a401f0 <+32>:    and    $0x40,%r10d\n   0x00007f25d7a401f4 <+36>:    jne    0x7f25d7a40248 <__libc_open64+120>\n   0x00007f25d7a401f6 <+38>:    mov    %esi,%eax\n   0x00007f25d7a401f8 <+40>:    and    $0x410000,%eax\n   0x00007f25d7a401fd <+45>:    cmp    $0x410000,%eax\n   0x00007f25d7a40202 <+50>:    je     0x7f25d7a40248 <__libc_open64+120>\n   0x00007f25d7a40204 <+52>:    mov    0x20d236(%rip),%eax        # 0x7f25d7c4d440 <__pthread_multiple_threads>\n   0x00007f25d7a4020a <+58>:    test   %eax,%eax\n   0x00007f25d7a4020c <+60>:    jne    0x7f25d7a40273 <__libc_open64+163>\n   0x00007f25d7a4020e <+62>:    mov    %esi,%edx\n   0x00007f25d7a40210 <+64>:    mov    $0x101,%eax\n   0x00007f25d7a40215 <+69>:    mov    %rdi,%rsi\n   0x00007f25d7a40218 <+72>:    mov    $0xffffff9c,%edi\n   0x00007f25d7a4021d <+77>:    syscall \n   0x00007f25d7a4021f <+79>:    cmp    $0xfffffffffffff000,%rax\n   0x00007f25d7a40225 <+85>:    ja     0x7f25d7a402c8 <__libc_open64+248>\n   0x00007f25d7a4022b <+91>:    mov    0x28(%rsp),%rcx\n   0x00007f25d7a40230 <+96>:    xor    %fs:0x28,%rcx\n   0x00007f25d7a40239 <+105>:   jne    0x7f25d7a402f1 <__libc_open64+289>\n   0x00007f25d7a4023f <+111>:   add    $0x68,%rsp\n<\/pre>\n
And that, at 0x00007f25d7a4021d <+77>:<\/code> is obviously the entry point to the kernel (the syscall). So\u2026<\/p>\n
\n(gdb) si<\/b>\n0x00007f25d7a40289      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,\n(gdb) si<\/b>\n0x00007f25d7a4028d      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,\n(gdb) si<\/b>\n0x00007f25d7a40290      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,\n(gdb) si<\/b>\n0x00007f25d7a40295      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,\n(gdb) si<\/b>\n0x00007f25d7a4029a      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,\n(gdb) si<\/b>\n0x00007f25d7a4029c      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,\n(gdb) si<\/b>\n0x00007f25d7a4029f      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,\n(gdb) si<\/b>\n0x00007f25d7a402a4      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,\n(gdb) si<\/b>\n0x00007f25d7a402a6      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,\n(gdb) disassemble <\/b>\nDump of assembler code for function __libc_open64:\n\u2026 \t\t\t# omitted<\/i>\n   0x00007f25d7a40285 <+181>:   mov    0xc(%rsp),%esi\n   0x00007f25d7a40289 <+185>:   mov    (%rsp),%rdi\n   0x00007f25d7a4028d <+189>:   mov    %eax,%r8d\n   0x00007f25d7a40290 <+192>:   mov    0x8(%rsp),%r10d\n   0x00007f25d7a40295 <+197>:   mov    $0x101,%eax\n   0x00007f25d7a4029a <+202>:   mov    %esi,%edx\n   0x00007f25d7a4029c <+204>:   mov    %rdi,%rsi\n   0x00007f25d7a4029f <+207>:   mov    $0xffffff9c,%edi\n   0x00007f25d7a402a4 <+212>:   syscall \n=> 0x00007f25d7a402a6 <+214>:   cmp    $0xfffffffffffff000,%rax\n   0x00007f25d7a402ac <+220>:   ja     0x7f25d7a402de <__libc_open64+270>\n\n<\/pre>\n
Maybe not the one I expected, but by stepping instruction by instruction, I obviously called a syscall here. So qemu asks the kernel about the file, and the kernel says it’s not there.<\/p>\n
So for the hell of it I run strace -e trace=open,openat -p PIDFILE<\/code>, and<\/p>\n
\n[root@a8onekvm1 ~]# strace -f -p 1463232 -o dbg.open -s 255 -e trace=open,openat<\/b>\nstrace: Process 1463232 attached with 6 threads\nstrace: Process 1832488 attached\nstrace: Process 1832489 attached\n^Cstrace: Process 1463232 detached\nstrace: Process 1463236 detached\nstrace: Process 1463237 detached\nstrace: Process 1463240 detached\nstrace: Process 1463242 detached\nstrace: Process 1463245 detached\n\n[root@a8onekvm1 ~]# grep open dbg.open <\/b>\n1832489 openat(AT_FDCWD, \"\/var\/lib\/one\/\/datastores\/0\/310\/disk.0\", O_RDONLY|O_DIRECT|O_CLOEXEC) = -1 ENOENT (No such file or directory)\n<\/pre>\n
So, now strace<\/code> sees it, but otherwise doesn’t?<\/p>\n
Cue 5 minutes of me, yelling about strace<\/code> betraying me, then checking that the file exists, writing a small C program to execute the exact same syscall with the permissions of the process, and (being late Friday afternoon and being tired) complaining to other people. And someone says, “this is most probably mount namespaces issue”.<\/p>\n
And what do you know, it is:<\/p>\n
\n[root@a8onekvm1 1463232]# nsenter -m -t 1463232 ls -l \/var\/lib\/one\/\/datastores\/0\/310\/disk.0<\/b>\nlrwxrwxrwx 1 oneadmin oneadmin 28 Feb 16 11:02 \/var\/lib\/one\/\/datastores\/0\/310\/disk.0 -> \/dev\/storpool-byid\/fir.b.f2g\n[root@a8onekvm1 1463232]# nsenter -m -t 1463232 ls -l \/dev\/storpool-byid<\/b>\nls: cannot access '\/dev\/storpool-byid': No such file or directory\n<\/pre>\n
Sooo\u2026 what we have done is replace the symlink from pointing to \/dev\/storpool\/XXX to \/dev\/storpool-byid\/YYY. The namespace for qemu doesn’t have the second directory, it was not in use when the process was started, and we have just screwed it by moving the symlink.<\/p>\n
So, happy with that, on Monday I wrote a lousy script to recreate the links, which one of my colleagues made into a good script that people won’t be ashamed to show, for example, replacing<\/p>\n
\nvirsh dumpxml one-316 |grep 'source dev.*datastores' | cut -d ' ' -f 2\n<\/pre>\n
with<\/p>\n
\nxmlstarlet sel -t -m '\/\/devices\/disk\/source' -v '@dev' -n \"${DOMXML}\" 2>\/dev\/null\n<\/pre>\n
Then, we apply this to the live environment to one VM, and happily tell the customer to try a live migration.<\/p>\n
It fails with the same error.
\n(cut some time for swearing at the world and all broken software)<\/p>\n
So I’m back to square one, as I try strace<\/code>-ing the process in the live environment with -e trace=open,openat<\/code>, and there is no such call. I also tried ltrace<\/code>, but the only difference was that it was slower and didn’t show anything more.<\/p>\n
Then, a colleague says, “You know, these debuginfo packages should exist, they’re not that old”, goes looking in the mirrors, and FINDS THEM. For some reason, google doesn’t index that part, and I could not find them the lazy way.<\/p>\n
Here’s the obvious error that you should look for yourself. It would’ve been even easier if I logged in to the local mirror we have for Rocky Linux and ran a find<\/code> for myself.<\/p>\n
Armed with debug symbols, I get the test VM again, attach to it, add a breakpoint at qemu_internal_open()<\/code>, and nothing happens. It doesn’t get hit. It looks like strace wasn’t lying here.<\/p>\n
I go back to the blk_root_inactivate()<\/code> function and I notice:<\/p>\n
\nThread 8 \"live_migration\" hit Breakpoint 1, blk_root_inactivate (child=0x55586bf47c00) at ..\/block\/block-backend.c:252\n252         BlockBackend *blk = child->opaque;\n(gdb) bt<\/b>\n#0  blk_root_inactivate (child=0x55586bf47c00) at ..\/block\/block-backend.c:252\n#1  0x000055586a5e8162 in bdrv_inactivate_recurse (bs=0x55586b297760) at ..\/block.c:6533\n#2  0x000055586a5e963f in bdrv_inactivate_all () at ..\/block.c:6590\n#3  0x000055586a37b535 in qemu_savevm_state_complete_precopy_non_iterable (f=0x55586c05d500, in_postcopy=<optimized out>, inactivate_disks=<\/optimized><optimized out>) at ..\/migration\/savevm.c:1441\n#4  0x000055586a37b622 in qemu_savevm_state_complete_precopy (f=0x55586c05d500, iterable_only=iterable_only@entry=false, inactivate_disks=inactivate_disks@entry=true) at ..\/migration\/savevm.c:1493\n#5  0x000055586a374236 in migration_completion (s=0x55586b207000) at ..\/migration\/migration.c:3260\n#6  migration_iteration_run (s=0x55586b207000) at ..\/migration\/migration.c:3672\n#7  migration_thread (opaque=0x55586b207000) at ..\/migration\/migration.c:3908\n#8  0x000055586a6d9dc4 in qemu_thread_start (args=0x55586c0ee6c0) at ..\/util\/qemu-thread-posix.c:585\n#9  0x00007f4a951d11ca in start_thread () from target:\/lib64\/libpthread.so.0\n#10 0x00007f4a94e3de73 in clone () from target:\/lib64\/libc.so.6\n(gdb) n<\/b>\n254         if (blk->disable_perm) {\n(gdb) n<\/b>\nbdrv_inactivate_recurse (bs=0x55586b297760) at ..\/block.c:6534\n<\/pre>\n
blk->disable_perm<\/code> is already set, so it looks like in this version of qemu (a bit older than what I initially used), when the live migration fails, this flag doesn’t get reset. I made a diff between the two versions, and that part has enough changes to warrant this idea. So, VMs that didn’t fail the migration would be fine.<\/p>\n
Now, what about this one and a few more? They seem to be in a corrupt state. I read a bit more code, then bite the bullet and change the variable live:<\/p>\n
\nThread 7 \"live_migration\" hit Breakpoint 1, blk_root_inactivate (child=0x55586bf47c00) at ..\/block\/block-backend.c:254\n254         if (blk->disable_perm) {\n(gdb) bt<\/b>\n#0  blk_root_inactivate (child=0x55586bf47c00) at ..\/block\/block-backend.c:254\n#1  0x000055586a5e8162 in bdrv_inactivate_recurse (bs=0x55586b297760) at ..\/block.c:6533\n#2  0x000055586a5e963f in bdrv_inactivate_all () at ..\/block.c:6590\n#3  0x000055586a37b535 in qemu_savevm_state_complete_precopy_non_iterable (f=0x55586c05d500, in_postcopy=<\/optimized><optimized out>, inactivate_disks=<\/optimized><optimized out>) at ..\/migration\/savevm.c:1441\n#4  0x000055586a37b622 in qemu_savevm_state_complete_precopy (f=0x55586c05d500, iterable_only=iterable_only@entry=false, inactivate_disks=inactivate_disks@entry=true) at ..\/migration\/savevm.c:1493\n#5  0x000055586a374236 in migration_completion (s=0x55586b207000) at ..\/migration\/migration.c:3260\n#6  migration_iteration_run (s=0x55586b207000) at ..\/migration\/migration.c:3672\n#7  migration_thread (opaque=0x55586b207000) at ..\/migration\/migration.c:3908\n#8  0x000055586a6d9dc4 in qemu_thread_start (args=0x55586c2325e0) at ..\/util\/qemu-thread-posix.c:585\n#9  0x00007f4a951d11ca in start_thread () from target:\/lib64\/libpthread.so.0\n#10 0x00007f4a94e3de73 in clone () from target:\/lib64\/libc.so.6\n(gdb) print ( (BlockBackend *) (child->opaque))->disable_perm<\/b>\n$1 = true\n(gdb) print ( (BlockBackend *) (child->opaque))->perm<\/b>\n$2 = 3\n(gdb) set: variable ( (BlockBackend *) (child->opaque))->disable_perm = false<\/b>\nNo symbol \"false\" in current context.\t# arghhhh<\/i>\n(gdb) set variable ( (BlockBackend *) (child->opaque))->disable_perm = 0<\/b>\n(gdb) cont<\/b>\nContinuing.\n\nThread 7 \"live_migration\" hit Breakpoint 1, blk_root_inactivate (child=0x55586bf51850) at ..\/block\/block-backend.c:254\n254         if (blk->disable_perm) {\n(gdb) print ( (BlockBackend *) (child->opaque))->disable_perm<\/b>\n$3 = false\n(gdb) print ( (BlockBackend *) (child->opaque))->perm<\/b>\n$4 = 1\n(gdb) cont<\/b>\nContinuing.\n[Thread 0x7f4999ffb700 (LWP 144024) exited]\n[Thread 0x7f499a7fc700 (LWP 144025) exited]\n\nThread 1 \"qemu-kvm-one\" received signal SIGTERM, Terminated.\t# oops?<\/i>\n[Switching to Thread 0x7f4a985a6e40 (LWP 3460894)]\n0x00007f4a94f28036 in ppoll () from target:\/lib64\/libc.so.6\n(gdb) q<\/b>\n\n<\/pre>\n
(imagine this being done live and as quickly as possible, as the VM is hanging. You also see two devices, OpenNebula adds a context image to all VMs, and it’s a CD-ROM device that the migration didn’t get to corrupt)<\/p>\n
Then I see SIGTERM and think, “crap, I killed it”. Then I look at the logs, and it has actually migrated successfully.<\/p>\n
So, finally, with some pointers (“the command in gdb is command” :) ) I write the following:<\/p>\n
\nset print pretty\nset pagination off\nhandle SIGUSR1 nostop pass\nhandle SIGTERM nostop pass\nbreak block\/block-backend.c:253\ncommands\nprint ( (BlockBackend *) (child->opaque))->disable_perm\nprint ( (BlockBackend *) (child->opaque))->perm\nset variable ( (BlockBackend *) (child->opaque))->disable_perm = 0\ncont\nend\ncont\n<\/pre>\n
and it works like a charm on the 10-or-something VMs with a corrupt state.<\/p>\n
A list of errors and lessons learned:<\/p>\n
– Don’t assume that because there’s something not right, it’s the cause of the problem you’re looking at (QEMU processor for the VMs);
\n– Collect all relevant information (and maybe even irrelevant) – I keep telling people that it’s easier to work with too much information than with not enough. I should listen to myself one of these days;
\n– strace can hide syscalls and shouldn’t be fully trusted;
\n– If you’re searching for debuginfo (or anything like that), do your legwork, and don’t trust a single search engine;
\n– testing the wrong software version can reveal only a part of the problem (or a different one).<\/p>\n","protected":false},"excerpt":{"rendered":"
There’s a purpose in everyone’s life. Some days, it seems like mine is to show people what not to do. I’ve written this explanation to show my mistakes and that, hopefully, other people don’t (there’s no hope for me). What follows is most of my debugging process, and it could be helpful to other people […]<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"0","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[1],"tags":[16],"class_list":["post-3474","post","type-post","status-publish","format-standard","hentry","category-general","tag-16"],"_links":{"self":[{"href":"https:\/\/vasil.ludost.net\/blog\/index.php?rest_route=\/wp\/v2\/posts\/3474","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/vasil.ludost.net\/blog\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/vasil.ludost.net\/blog\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/vasil.ludost.net\/blog\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/vasil.ludost.net\/blog\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=3474"}],"version-history":[{"count":0,"href":"https:\/\/vasil.ludost.net\/blog\/index.php?rest_route=\/wp\/v2\/posts\/3474\/revisions"}],"wp:attachment":[{"href":"https:\/\/vasil.ludost.net\/blog\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=3474"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/vasil.ludost.net\/blog\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=3474"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/vasil.ludost.net\/blog\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=3474"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}