Posts Tagged ‘работа’

2024-03-05 The failed live migration case

Tuesday, March 5th, 2024

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 to see it (and point out what is wrong with it).

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.

KVM VMs are a qemu process in the Linux userspace with multiple threads.

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).

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

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 and found the following:

2024-02-20T09:46:41.938285Z qemu-kvm-one: qemu_savevm_state_complete_precopy_non_iterable: bdrv_inactivate_all() failed (-1)

(seriously. Trying to trace anything via the logs in OpenNebula/libvirt/qemu feels like interrogating prisoners who don’t speak your language.)

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.

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.

Now, this was weird. The only mention of the above error was in https://bugzilla.redhat.com/show_bug.cgi?id=2058982 when the storage device on the originating side was broken. This was not the case here.

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.

What I was able to see in the thread that performed the migration was:

prctl(PR_SET_NAME, "live_migration")    = 0
…
sendmsg(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
sendmsg(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
write(2, "2024-02-15T07:00:23.057678Z ", 28) = 28
write(2, "qemu-kvm-one:", 13)           = 13
write(2, " ", 1)                        = 1
write(2, "qemu_savevm_state_complete_precopy_non_iterable: bdrv_inactivate_all() failed (-1)", 82) = 82
write(2, "\n", 1)                       = 1
futex(0x55586af89640, FUTEX_WAKE_PRIVATE, 1) = 1
sendmsg(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
futex(0x55586af89640, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
sendmsg(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

Some digging showed that 99 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.

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:

[root@somewhere str3]# gdb /usr/libexec/qemu-kvm
GNU gdb (GDB) Rocky Linux 8.2-20.el8.0.1
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/libexec/qemu-kvm...Reading symbols from .gnu_debugdata for /usr/libexec/qemu-kvm...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Missing separate debuginfos, use: yum debuginfo-install qemu-kvm-core-6.2.0-33.module+el8.8.0+1454+0b2cbfb8.x86_64
(gdb) quit

[root@somewhere str3]# yum debuginfo-install qemu-kvm-core-6.2.0-33.module+el8.8.0+1454+0b2cbfb8.x86_64
Repository storpool-contrib is listed more than once in the configuration
enabling epel-debuginfo repository
Extra Packages for Enterprise Linux 8 - x86_64 - Debug                                                                                                                                                                                            4.0 MB/s | 6.1 MB     00:01    
Last metadata expiration check: 0:00:02 ago on Thu Feb 15 16:26:34 2024.
Could 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
Could 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
Dependencies resolved.
Nothing to do.
Complete!

(I can already hear people saying, “You’re an idiot”; someone had to point that out to me)

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.

The mistake was that I did not collect all available information (or even most of it), still relying on assumptions.

I could deploy the latest qemu for AlmaLinux (almost the same as what the customer was using), download debug symbols, and start digging. Yay.

On strace, the issue looked the same – lots of sending to the socket and then just the error. So, I started digging with gdb 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 (some comments added to explain what these are):

set print pretty			# the usual gdb print is hard to read
set pagination off			# pagination is annoying in this regard, my terminal can scroll
handle SIGUSR1 nostop pass		# qemu uses SIGUSR1 a lot
break block/block-backend.c:253		# stop here
cont					# continue execution
bt full					# print me a full backtrace with local variables when stopped

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() was trying to remove write permissions from the devices and was failing for some reason.

6523     /* Inactivate this node */
6524     if (bs->drv->bdrv_inactivate) {
6525         ret = bs->drv->bdrv_inactivate(bs);
6526         if (ret < 0) {
6527             return ret;
6528         }
6529     }
6530 
6531     QLIST_FOREACH(parent, &bs->parents, next_parent) {
6532         if (parent->klass->inactivate) {
6533             ret = parent->klass->inactivate(parent);
6534             if (ret < 0) {
6535                 return ret;
6536             }
6537         }
6538     }
6539 
6540     bdrv_get_cumulative_perm(bs, &cumulative_perms,
6541                              &cumulative_shared_perms);
6542     if (cumulative_perms & (BLK_PERM_WRITE | BLK_PERM_WRITE_UNCHANGED)) {
6543         /* Our inactive parents still need write access. Inactivation failed. */
6544         return -EPERM;
6545     }

This is the code in question, and in bdrv_get_cumulative_perms(), there were some devices that still had r/w set even after the stuff between lines 6531 and 6533 had passed:

bdrv_inactivate_recurse (bs=0x556e00221530) at ../block.c:6534
6534                if (ret < 0) {
(gdb) 
6531        QLIST_FOREACH(parent, &bs->parents, next_parent) {
(gdb) 
6540        bdrv_get_cumulative_perm(bs, &cumulative_perms,
(gdb) 
6542        if (cumulative_perms & (BLK_PERM_WRITE | BLK_PERM_WRITE_UNCHANGED)) {
(gdb) 
bdrv_inactivate_all () at ../block.c:6591
6591            if (ret < 0) {
(gdb) 
6592                bdrv_next_cleanup(&it);
(gdb) 

The inactivate() function above was in block/block-backend.c and looks like this:

 250 static int blk_root_inactivate(BdrvChild *child)
 251 {
 252     BlockBackend *blk = child->opaque;
 253 
 254     if (blk->disable_perm) {
 255         return 0;
 256     }
 257 
 258     if (!blk_can_inactivate(blk)) {
 259         return -EPERM;
 260     }
 261 
 262     blk->disable_perm = true;
 263     if (blk->root) {
 264         bdrv_child_try_set_perm(blk->root, 0, BLK_PERM_ALL, &error_abort);
 265     }
 266 
 267     return 0;
 268 }

and what was happening was:

258         if (!blk_can_inactivate(blk)) {
(gdb) 
262         blk->disable_perm = true;
(gdb) 
263         if (blk->root) {
(gdb) 
264             bdrv_child_try_set_perm(blk->root, 0, BLK_PERM_ALL, &error_abort);
(gdb) 
bdrv_inactivate_recurse (bs=0x556e00221530) at ../block.c:6534

So qemu is calling it, and that was all OK.

Here, a few times, I had missed what this was trying to do. Here’s bdrv_child_try_set_perm():

2517 
2518 int bdrv_child_try_set_perm(BdrvChild *c, uint64_t perm, uint64_t shared,
2519                             Error **errp)
2520 {
2521     Error *local_err = NULL;
2522     Transaction *tran = tran_new();
2523     int ret;
2524 
2525     bdrv_child_set_perm(c, perm, shared, tran);
2526 
2527     ret = bdrv_refresh_perms(c->bs, &local_err);
2528 
2529     tran_finalize(tran, ret);
2530 
2531     if (ret < 0) {
2532         if ((perm & ~c->perm) || (c->shared_perm & ~shared)) {
2533             /* tighten permissions */
2534             error_propagate(errp, local_err);
2535         } else {
2536             /*
2537              * Our caller may intend to only loosen restrictions and
2538              * does not expect this function to fail.  Errors are not
2539              * fatal in such a case, so we can just hide them from our
2540              * caller.
2541              */
2542             error_free(local_err);
2543             ret = 0;
2544         }
2545     }
2546 
2547     return ret;
2548 }

So that 0 being passed is “remove all permissions”, but at some time late in the day, you can’t see it…

And now, I break into that one and try to see what happens:

(gdb) n
2197        *s = (BdrvChildSetPermState) {
(gdb) print *(local_err)
No symbol "local_err" in current context.
(gdb) 
No symbol "local_err" in current context.
(gdb) n
2203        c->perm = perm;
(gdb) print *(local_err)
No symbol "local_err" in current context.
(gdb) n
2204        c->shared_perm = shared;
(gdb) print *(local_err)
No symbol "local_err" in current context.
(gdb) n
2206        tran_add(tran, &bdrv_child_set_pem_drv, s);
(gdb) n
bdrv_child_try_set_perm (c=0x556e002e1730, perm=perm@entry=0, shared=shared@entry=31, errp=0x556dfeb99258 <error_abort>) at ../block.c:2527
2527        ret = bdrv_refresh_perms(c->bs, &local_err);
(gdb) print *(local_err)
Cannot access memory at address 0x0
(gdb) n
2529        tran_finalize(tran, ret);
(gdb) print *(local_err)
$1 = {
  msg = 0x7f25a4041b70 "Could not open '/var/lib/one//datastores/0/310/disk.0': No such file or directory", 
  err_class = ERROR_CLASS_GENERIC_ERROR, 
  src = 0x556dfe63ca2a "../util/osdep.c", 
  func = 0x556dfe63cbc0 <__func__.26488> "qemu_open_internal", 
  line = 359, 
  hint = 0x0
}
(gdb) q

Now, I see it going through the function, and I’m trying to look at that local_err if there’s something in it. Finally, I get the actual error; it has happened somewhere and is not propagated – but qemu has tried opening a file, and that doesn’t exist.

Two things here:
– 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);
– Why isn’t this error logged or propagated? I should probably send a patch for that…
– This was not in what strace showed, so what the hell.

So, I break at util/osdep.c in qemu_open_internal(), 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 on its own is a lot less likely than strace missing one syscall.

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 #):

(gdb) break util/osdep.c:312
Breakpoint 1 at 0x556dfe2c5c71: file ../util/osdep.c, line 312.
(gdb) handle SIGUSR1 nostop pass
Signal        Stop      Print   Pass to program Description
SIGUSR1       No        Yes     Yes             User defined signal 1
(gdb) set print pretty
(gdb) set pagination off
(gdb) cont
Continuing.
[New Thread 0x7f259c9ba700 (LWP 1798462)]
[New Thread 0x7f259c1b9700 (LWP 1798463)]

Thread 5 "CPU 0/KVM" received signal SIGUSR1, User defined signal 1.

Thread 5 "CPU 0/KVM" received signal SIGUSR1, User defined signal 1.

Thread 5 "CPU 0/KVM" received signal SIGUSR1, User defined signal 1.
[Switching to Thread 0x7f259c1b9700 (LWP 1798463)]

Thread 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
318         if (strstart(name, "/dev/fdset/", &fdset_id_str)) {
(gdb) bt full# nothing interesting in the backtrace
(gdb) disassemble 
Dump of assembler code for function qemu_open_internal:
   0x0000556dfe2c5c40 <+0>:     push   %r15
   0x0000556dfe2c5c42 <+2>:     push   %r14
   0x0000556dfe2c5c44 <+4>:     mov    %rcx,%r14
   0x0000556dfe2c5c47 <+7>:     push   %r13
   0x0000556dfe2c5c49 <+9>:     mov    %edx,%r13d
   0x0000556dfe2c5c4c <+12>:    push   %r12
   0x0000556dfe2c5c4e <+14>:    mov    %esi,%r12d
   0x0000556dfe2c5c51 <+17>:    lea    0x376dad(%rip),%rsi        # 0x556dfe63ca05
   0x0000556dfe2c5c58 <+24>:    push   %rbp
   0x0000556dfe2c5c59 <+25>:    mov    %rdi,%rbp
   0x0000556dfe2c5c5c <+28>:    push   %rbx
   0x0000556dfe2c5c5d <+29>:    sub    $0x28,%rsp
   0x0000556dfe2c5c61 <+33>:    mov    %fs:0x28,%rax
   0x0000556dfe2c5c6a <+42>:    mov    %rax,0x18(%rsp)
   0x0000556dfe2c5c6f <+47>:    xor    %eax,%eax
=> 0x0000556dfe2c5c71 <+49>:    lea    0x10(%rsp),%rdx
   0x0000556dfe2c5c76 <+54>:    callq  0x556dfe2c6a30 <strstart>
   0x0000556dfe2c5c7b <+59>:    test   %eax,%eax
   0x0000556dfe2c5c7d <+61>:    je     0x556dfe2c5cd8 <qemu_open_internal+152>
   0x0000556dfe2c5c7f <+63>:    mov    0x10(%rsp),%rdi
   0x0000556dfe2c5c84 <+68>:    callq  0x556dfe2c79b0 <qemu_parse_fd>
   0x0000556dfe2c5c89 <+73>:    movslq %eax,%rdi
   0x0000556dfe2c5c8c <+76>:    mov    %rdi,%rbx
   0x0000556dfe2c5c8f <+79>:    cmp    $0xffffffffffffffff,%rdi
   0x0000556dfe2c5c93 <+83>:    je     0x556dfe2c5d7c <qemu_open_internal+316>
   0x0000556dfe2c5c99 <+89>:    mov    %r12d,%esi
   0x0000556dfe2c5c9c <+92>:    callq  0x556dfe101b60 <monitor_fdset_dup_fd_add>
   0x0000556dfe2c5ca1 <+97>:    mov    %eax,%ebx
   0x0000556dfe2c5ca3 <+99>:    cmp    $0xffffffff,%eax
   0x0000556dfe2c5ca6 <+102>:   je     0x556dfe2c5db3 <qemu_open_internal+371>
   0x0000556dfe2c5cac <+108>:   mov    0x18(%rsp),%rcx
   0x0000556dfe2c5cb1 <+113>:   xor    %fs:0x28,%rcx
   0x0000556dfe2c5cba <+122>:   mov    %ebx,%eax
   0x0000556dfe2c5cbc <+124>:   jne    0x556dfe2c5dd3 <qemu_open_internal+403>
   0x0000556dfe2c5cc2 <+130>:   add    $0x28,%rsp
   0x0000556dfe2c5cc6 <+134>:   pop    %rbx
   0x0000556dfe2c5cc7 <+135>:   pop    %rbp
   0x0000556dfe2c5cc8 <+136>:   pop    %r12
   0x0000556dfe2c5cca <+138>:   pop    %r13
   0x0000556dfe2c5ccc <+140>:   pop    %r14
   0x0000556dfe2c5cce <+142>:   pop    %r15
   0x0000556dfe2c5cd0 <+144>:   retq   
   0x0000556dfe2c5cd1 <+145>:   nopl   0x0(%rax)
   0x0000556dfe2c5cd8 <+152>:   mov    %r12d,%esi
   0x0000556dfe2c5cdb <+155>:   mov    %r13d,%edx
   0x0000556dfe2c5cde <+158>:   mov    %rbp,%rdi
   0x0000556dfe2c5ce1 <+161>:   xor    %eax,%eax
   0x0000556dfe2c5ce3 <+163>:   or     $0x80000,%esi
   0x0000556dfe2c5ce9 <+169>:   callq  0x556dfdf0f190 <open64@plt>

…

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, which looks like the syscall open to me.

I spend some time stepping instruction by instruction and trying to understand (and failing) what /usr/include/bits/fcntl2.h is doing with the macros there, but instruction by instruction I get to this:

(gdb) si
__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
37      {
(gdb) si
0x00007f25d7a401d4      37      {
(gdb) si
0x00007f25d7a401d8      37      {
(gdb) disassemble 
Dump of assembler code for function __libc_open64:
   0x00007f25d7a401d0 <+0>:     endbr64 
   0x00007f25d7a401d4 <+4>:     sub    $0x68,%rsp
=> 0x00007f25d7a401d8 <+8>:     mov    %esi,%r10d
   0x00007f25d7a401db <+11>:    mov    %rdx,0x40(%rsp)
   0x00007f25d7a401e0 <+16>:    mov    %fs:0x28,%rax
   0x00007f25d7a401e9 <+25>:    mov    %rax,0x28(%rsp)
   0x00007f25d7a401ee <+30>:    xor    %eax,%eax
   0x00007f25d7a401f0 <+32>:    and    $0x40,%r10d
   0x00007f25d7a401f4 <+36>:    jne    0x7f25d7a40248 <__libc_open64+120>
   0x00007f25d7a401f6 <+38>:    mov    %esi,%eax
   0x00007f25d7a401f8 <+40>:    and    $0x410000,%eax
   0x00007f25d7a401fd <+45>:    cmp    $0x410000,%eax
   0x00007f25d7a40202 <+50>:    je     0x7f25d7a40248 <__libc_open64+120>
   0x00007f25d7a40204 <+52>:    mov    0x20d236(%rip),%eax        # 0x7f25d7c4d440 <__pthread_multiple_threads>
   0x00007f25d7a4020a <+58>:    test   %eax,%eax
   0x00007f25d7a4020c <+60>:    jne    0x7f25d7a40273 <__libc_open64+163>
   0x00007f25d7a4020e <+62>:    mov    %esi,%edx
   0x00007f25d7a40210 <+64>:    mov    $0x101,%eax
   0x00007f25d7a40215 <+69>:    mov    %rdi,%rsi
   0x00007f25d7a40218 <+72>:    mov    $0xffffff9c,%edi
   0x00007f25d7a4021d <+77>:    syscall 
   0x00007f25d7a4021f <+79>:    cmp    $0xfffffffffffff000,%rax
   0x00007f25d7a40225 <+85>:    ja     0x7f25d7a402c8 <__libc_open64+248>
   0x00007f25d7a4022b <+91>:    mov    0x28(%rsp),%rcx
   0x00007f25d7a40230 <+96>:    xor    %fs:0x28,%rcx
   0x00007f25d7a40239 <+105>:   jne    0x7f25d7a402f1 <__libc_open64+289>
   0x00007f25d7a4023f <+111>:   add    $0x68,%rsp

And that, at 0x00007f25d7a4021d <+77>: is obviously the entry point to the kernel (the syscall). So…

(gdb) si
0x00007f25d7a40289      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,
(gdb) si
0x00007f25d7a4028d      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,
(gdb) si
0x00007f25d7a40290      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,
(gdb) si
0x00007f25d7a40295      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,
(gdb) si
0x00007f25d7a4029a      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,
(gdb) si
0x00007f25d7a4029c      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,
(gdb) si
0x00007f25d7a4029f      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,
(gdb) si
0x00007f25d7a402a4      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,
(gdb) si
0x00007f25d7a402a6      48        return SYSCALL_CANCEL (openat, AT_FDCWD, file, oflag | EXTRA_OPEN_FLAGS,
(gdb) disassemble 
Dump of assembler code for function __libc_open64:
… 			# omitted
   0x00007f25d7a40285 <+181>:   mov    0xc(%rsp),%esi
   0x00007f25d7a40289 <+185>:   mov    (%rsp),%rdi
   0x00007f25d7a4028d <+189>:   mov    %eax,%r8d
   0x00007f25d7a40290 <+192>:   mov    0x8(%rsp),%r10d
   0x00007f25d7a40295 <+197>:   mov    $0x101,%eax
   0x00007f25d7a4029a <+202>:   mov    %esi,%edx
   0x00007f25d7a4029c <+204>:   mov    %rdi,%rsi
   0x00007f25d7a4029f <+207>:   mov    $0xffffff9c,%edi
   0x00007f25d7a402a4 <+212>:   syscall 
=> 0x00007f25d7a402a6 <+214>:   cmp    $0xfffffffffffff000,%rax
   0x00007f25d7a402ac <+220>:   ja     0x7f25d7a402de <__libc_open64+270>

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.

So for the hell of it I run strace -e trace=open,openat -p PIDFILE, and

[root@a8onekvm1 ~]# strace -f -p 1463232 -o dbg.open -s 255 -e trace=open,openat
strace: Process 1463232 attached with 6 threads
strace: Process 1832488 attached
strace: Process 1832489 attached
^Cstrace: Process 1463232 detached
strace: Process 1463236 detached
strace: Process 1463237 detached
strace: Process 1463240 detached
strace: Process 1463242 detached
strace: Process 1463245 detached

[root@a8onekvm1 ~]# grep open dbg.open 
1832489 openat(AT_FDCWD, "/var/lib/one//datastores/0/310/disk.0", O_RDONLY|O_DIRECT|O_CLOEXEC) = -1 ENOENT (No such file or directory)

So, now strace sees it, but otherwise doesn’t?

Cue 5 minutes of me, yelling about strace 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”.

And what do you know, it is:

[root@a8onekvm1 1463232]# nsenter -m -t 1463232 ls -l /var/lib/one//datastores/0/310/disk.0
lrwxrwxrwx 1 oneadmin oneadmin 28 Feb 16 11:02 /var/lib/one//datastores/0/310/disk.0 -> /dev/storpool-byid/fir.b.f2g
[root@a8onekvm1 1463232]# nsenter -m -t 1463232 ls -l /dev/storpool-byid
ls: cannot access '/dev/storpool-byid': No such file or directory

Sooo… 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.

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

virsh dumpxml one-316 |grep 'source dev.*datastores' | cut -d ' ' -f 2

with

xmlstarlet sel -t -m '//devices/disk/source' -v '@dev' -n "${DOMXML}" 2>/dev/null

Then, we apply this to the live environment to one VM, and happily tell the customer to try a live migration.

It fails with the same error.
(cut some time for swearing at the world and all broken software)

So I’m back to square one, as I try strace-ing the process in the live environment with -e trace=open,openat, and there is no such call. I also tried ltrace, but the only difference was that it was slower and didn’t show anything more.

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.

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 for myself.

Armed with debug symbols, I get the test VM again, attach to it, add a breakpoint at qemu_internal_open(), and nothing happens. It doesn’t get hit. It looks like strace wasn’t lying here.

I go back to the blk_root_inactivate() function and I notice:

Thread 8 "live_migration" hit Breakpoint 1, blk_root_inactivate (child=0x55586bf47c00) at ../block/block-backend.c:252
252         BlockBackend *blk = child->opaque;
(gdb) bt
#0  blk_root_inactivate (child=0x55586bf47c00) at ../block/block-backend.c:252
#1  0x000055586a5e8162 in bdrv_inactivate_recurse (bs=0x55586b297760) at ../block.c:6533
#2  0x000055586a5e963f in bdrv_inactivate_all () at ../block.c:6590
#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
#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
#5  0x000055586a374236 in migration_completion (s=0x55586b207000) at ../migration/migration.c:3260
#6  migration_iteration_run (s=0x55586b207000) at ../migration/migration.c:3672
#7  migration_thread (opaque=0x55586b207000) at ../migration/migration.c:3908
#8  0x000055586a6d9dc4 in qemu_thread_start (args=0x55586c0ee6c0) at ../util/qemu-thread-posix.c:585
#9  0x00007f4a951d11ca in start_thread () from target:/lib64/libpthread.so.0
#10 0x00007f4a94e3de73 in clone () from target:/lib64/libc.so.6
(gdb) n
254         if (blk->disable_perm) {
(gdb) n
bdrv_inactivate_recurse (bs=0x55586b297760) at ../block.c:6534

blk->disable_perm 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.

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:

Thread 7 "live_migration" hit Breakpoint 1, blk_root_inactivate (child=0x55586bf47c00) at ../block/block-backend.c:254
254         if (blk->disable_perm) {
(gdb) bt
#0  blk_root_inactivate (child=0x55586bf47c00) at ../block/block-backend.c:254
#1  0x000055586a5e8162 in bdrv_inactivate_recurse (bs=0x55586b297760) at ../block.c:6533
#2  0x000055586a5e963f in bdrv_inactivate_all () at ../block.c:6590
#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
#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
#5  0x000055586a374236 in migration_completion (s=0x55586b207000) at ../migration/migration.c:3260
#6  migration_iteration_run (s=0x55586b207000) at ../migration/migration.c:3672
#7  migration_thread (opaque=0x55586b207000) at ../migration/migration.c:3908
#8  0x000055586a6d9dc4 in qemu_thread_start (args=0x55586c2325e0) at ../util/qemu-thread-posix.c:585
#9  0x00007f4a951d11ca in start_thread () from target:/lib64/libpthread.so.0
#10 0x00007f4a94e3de73 in clone () from target:/lib64/libc.so.6
(gdb) print ( (BlockBackend *) (child->opaque))->disable_perm
$1 = true
(gdb) print ( (BlockBackend *) (child->opaque))->perm
$2 = 3
(gdb) set: variable ( (BlockBackend *) (child->opaque))->disable_perm = false
No symbol "false" in current context.	# arghhhh
(gdb) set variable ( (BlockBackend *) (child->opaque))->disable_perm = 0
(gdb) cont
Continuing.

Thread 7 "live_migration" hit Breakpoint 1, blk_root_inactivate (child=0x55586bf51850) at ../block/block-backend.c:254
254         if (blk->disable_perm) {
(gdb) print ( (BlockBackend *) (child->opaque))->disable_perm
$3 = false
(gdb) print ( (BlockBackend *) (child->opaque))->perm
$4 = 1
(gdb) cont
Continuing.
[Thread 0x7f4999ffb700 (LWP 144024) exited]
[Thread 0x7f499a7fc700 (LWP 144025) exited]

Thread 1 "qemu-kvm-one" received signal SIGTERM, Terminated.	# oops?
[Switching to Thread 0x7f4a985a6e40 (LWP 3460894)]
0x00007f4a94f28036 in ppoll () from target:/lib64/libc.so.6
(gdb) q

(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)

Then I see SIGTERM and think, “crap, I killed it”. Then I look at the logs, and it has actually migrated successfully.

So, finally, with some pointers (“the command in gdb is command” :) ) I write the following:

set print pretty
set pagination off
handle SIGUSR1 nostop pass
handle SIGTERM nostop pass
break block/block-backend.c:253
commands
print ( (BlockBackend *) (child->opaque))->disable_perm
print ( (BlockBackend *) (child->opaque))->perm
set variable ( (BlockBackend *) (child->opaque))->disable_perm = 0
cont
end
cont

and it works like a charm on the 10-or-something VMs with a corrupt state.

A list of errors and lessons learned:

– 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);
– 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;
– strace can hide syscalls and shouldn’t be fully trusted;
– If you’re searching for debuginfo (or anything like that), do your legwork, and don’t trust a single search engine;
– testing the wrong software version can reveal only a part of the problem (or a different one).

2023-09-21

Thursday, September 21st, 2023

Има дни, които започват с намирането, ремонтирането и report-ването на бъг в мобилното приложение на rocketchat, минават през срещи и гасене на 3 пожара паралелно, и завършват с


MariaDB [opennebula]> update vm_pool set short_body=replace(short_body,'80','33') where oid=39;
Query OK, 1 row affected (0.002 sec)
Rows matched: 1 Changed: 1 Warnings: 0

Един ден трябва да направя лекция за opennebula и за кандидатурата им за най-невъзможна за докарване в консистентно състояние база данни на тоя свят. Онова по-горе (редактиране на XML в базата със string операции, което теорията твърди, че е идиотщина, и аз съм съгласен) се налага, понеже има същите данни в 2 различни полета на същата таблица, с малка редакция, и понякога не са синхронизирани.

Имам чувството, че съм почнал да гледам на целия свят като някакъв проблем за дебъгване.

2023-06-02 Взимане на решения в екип

Friday, June 2nd, 2023

От няколко места виждам вариации на темата, та ми се стори уместно да напиша нещо.

Ще започна с нещо от Камил Галеев, който на моменти има много добри обяснения. Важният момент в това е, че хората, които са на власт/в позиция да взимат решения/вършат нещо, не могат да имат крайни позиции. Вършенето на работа в екип с някого изисква компромиси, и е далеч по-лесно да работиш с хора, които са съгласни с теб и с които може да си сглобиш обща цел, отколкото с такива, които трябва да бъдат насилвани.

От това има няколко посоки на изводите:

Първо, хората/организациите с крайни позиции са такива, които никога не са стигали до свършване на нещо реално. Неспособността да направиш някакъв компромис и да се промениш/пренасочиш, за да се справиш с някаква промяна в обстановката води до това да си по-зле от тези, които намират вариант и да “отпаднеш” по някакъв начин.
(тук има огромна скоба и малко примери, понеже може да се разбира по грешния начин…

Опциите за компромис и промяна на посоката винаги са повече от една. Първи пример, някой на база на горното може да каже “Това значи ли, че Украйна трябва да направи компромис с Русия?” и отговорът там е, че те са направили много компромиси със западния свят/ЕС, за да могат да продължат да се бият. Дали тези ще са им достатъчни, е отделен въпрос.

Друг пример, на скоро обяснявах нуждата от “черна каса” и бях гледан с огромно учудване, че това се налага в наши дни. Моето твърдение е, че на практика няма организация, в която да няма нещо подобно, просто защото има неща, които не могат да се случат без подобен фонд за плащания, които нямат насрещен документ. Имам някакво количество примери от моята практика, за които по очевидни причини няма да разкажа, и само ще отбележа, че всяка достатъчно голяма организация от едно ниво нагоре има нещо подобно, известно като “discretionary фондове”, с които определени хора разполагат по собствено усмотрение за благото на организацията. С тях се злоупотребява, но ползите от тях надминават загубите.
Чувал съм твърдение, че има организации без такива, но тогава тези неща се случват, като определени хора поемат тези разходи от собствения си джоб. В повечето НПО-та е така и за това в счетоводството на доста от тях може да се намери “и за <нещоси> на тоя член му платихме толкова пари”, като нещото е от типа на “да стои и да изглежда добре”
край на скобата)

Второ, съвсем нормално и здравословно в една организация е да има някакво количество спорове и да се достига до решение с дискусия. Мисля си, че сме супер повредени от много години на “един спасител, който знае всичко”, но очакването да има един-единствен диктатор/ръководител/авторитет и той да е прав за всичко е идиотщина и като цяло сбъркано. Смислените лидери (думата не ми харесва, но не ми хрумва по-добра) не взимат решенията ей-така, без да се консултират, и дори в повечето случаи работата им не е да вземат решението, а например да решат кога има някакъв приблизителен консенсус или достатъчно голямо мнозинство за някакво решение, и да прекратят дискусията.
Много полезна е идеята за rough consensus, дошла от IETF. Може да се каже дори, че организации работещи на еквивалента за тях на “rough consensus and running code” (щото не всички живеят на код) са по-здрави и работещи от тези, които не го правят.

За това и аз лично много се зарадвах на записа от заседанието на ПП, на което обсъждат правителството с ГЕРБ – понеже е пример за всичките неща по-горе и за смислен процес по взимане на решение (въпреки че чисто практически изтичането на записа има неприятни последици). Може би след някакво количество години подобни записи ще се използват за обучителни материали :)

(изобщо, може да не съм от ПП, но от време на време Кирил Петков свършва нещо, с което ми се издига в очите, което като цяло е огромна рядкост за български политик)

2023-01-21 процес на наемане на хора

Saturday, January 21st, 2023

Отдавна се каня да опиша нашия процес на наемане на хора, и защо е такъв – случва се от време на време хора да ме питат “а как си намирате хора”.

(това е бая важно като задача в една фирма, и почти навсякъде, където съм бил съм гледал да имам участие в процеса, за да не се наложи после да работя с хора, които не стават)

Прескачайки “откъде влизат cv-та” (jobs.bg и подобни сайтове), стъпките нататък са:

1) Базов преглед на CV-то. Ако в него няма нещо наистина притеснително, или не е тотално не подходящо, даваме нататък.
Някои хора гледат внимателно CV-та и на база на тях канят кандидатите на интервю. Всичкия ми опит с това е, че се губи много време, и на интервюиращите, и на кандидатите, понеже CV-то не показва много неща, хората лъжат и т.н.. В някои изключителни случаи (при много senior CV), може да направим първо интервю с човека предварително, но иначе, следваща стъпка:

2) Пращаме едни стандартни задачи на човека. Те са събрани от моята и фирмената практика, и като цяло не са от типа на “сферичен кон във вакуум”, и имат няколко цели:
– да видят на кандидата колко му се занимава
– да се види как мисли и за какви неща се усеща
– да дадат теми за разговор на интервюто :)
В предишни фирми това се заместваше от това да напишат един fizzbuzz на лист на интервюто, но понеже няма fizzbuzz еквивалент за админи, и понеже да каниш хората само за да ги изгониш като не решат задачата си е бая загуба на време. Задачите са повечко и е добре хората да могат да си ги решат на спокойствие, а и няма изискване да се решат всички, а е по избор на канидата.
Както и с fizzbuzz-а, случвало се е да се наемат някакви хора, които да не могат да ги минат тия неща, и това винаги е било голям провал.
Има и хора, дето казват “тия какво ще ме занимават, ще ида при някой друг” (това съм го чувал и от първа ръка) и в общи линии това е търсен ефект, понеже почти във всички случаи аз не искам хора, дето това хем им е голямо усилие, хем не им е достатъчно интересно, че да се хванат и да решат едно-две неща.
В много редки случаи сме филтрирали хора на тази стъпка, заради наистина ужасяващи решения.

3) Правим едно техническо интервю. От наша страна гледаме да сме до 3ма човека (повече от това почва да изглежда притеснително).
Първите 5-10 минути обясняваме ние с какво се занимаваме и какво представлява работата (една от първите реплики е “май ти го разказва това предния път, та сега съм аз”). Това е полезно за да си изгради кандидата контекст и да знае защо задаваме някакви въпроси.
(това май е рядко срещано, и аз не го правех преди)
После, имаме набор от теми, по които разпитваме човека. Започваме от задачите, минаваме през някакви мрежови, linux-ки неща, инструменти, но най-интересното е да разкаже нещо, което е правил сам. Особено хората с повече опит почти задължително имат нещо такова, и от там може да се види всъщност доколко способен е човека.
В тази част има нещо, което често се пропуска, че интервюто трябва да е полезно и за двете страни – ако кандидатът не знае нещо, му го обясняваме/разказваме.
Също така, целта на голяма част от въпросите е да изясни доколко работата ще е интересна за кандидата и доколко като цяло му харесва. Хора, които не са мотивирани, не са заинтересувани и това го работят между другото, като цяло не стават за при нас.
(това е доста видимо при почти всички кандидати, които се появяват от СофтУни)
Последните 10-15 минути гледаме да оставим за въпроси от кандидата към нас, всякакви неща свързани с работата.

Към края на интервюто обясняваме, че ще се свържем с кандидата до около седмица, без значение какво ни е решението – т.е. никого не оставяме без отговор и да се чуди какво става. Това важи и за предишната стъпка – който ни е пратил решение на задачите, е получавал отговор от нас.

4) Срещаме кандидата с целия екип. Това е разговор в сравнително свободен формат, двете страни да се запознаят и да решат дали им се работи заедно. Това винаги е доста забавно, и помага на кандидата да види в какво се забърква.

5) Прави се “човешко” интервю с кандидата, което е с CEO-то на фирмата, да се види дали не сме пропуснали, че човекът е психопат или нещо подобно (както се вижда, аз това тотално не го разбирам и вероятно не го описвам правилно :) ).

6) Правим оферта на човека, и ако приеме, почва при нас.

7) Месец след като е започнал, правим post-onboarding интервю. Тази идея дойде от Dan Luu, та хващаме и разпитваме човека какво не ни е наред, преди да е свикнал с нещата при нас.
(Дори файлът, в който водим бележките, се казва “Какво не е наред”)
(разбира се, onboarding-а продължава много повече, те само базовите неща са поне един месец, но е важно да се направи тоя разговор преди човекът да е привикнал с процесите)

Това са нещата по самия процес, в общи линии. Извън него има като цяло изграждането на имидж на фирмата (с появяване по конференции и т.н.), които не са ми по специалността. Само мога да кажа, че са важни (поне двама от екипа ми са дошли през конференции).

2018-11-27 StorPool-ската игра на OpenFest 2018

Tuesday, November 27th, 2018

(английската версия е в блога на StorPool)

В последните няколко години StorPool се появяват на OpenFest. За да направим щанда по-забавен, измисляме някоя игра. Миналата година задачата изглеждаше измамно проста, но доста затрудни хората, та тази година реших да опитам с нещо по-лесно.

“Fix the problems” задачата е базирана на много някакви стандартни случки от админския живот, т.е. на нещо, което би трябвало да ви се е случвало. Представете си обаждане от приятел (което може да е в 8 сутринта), в което ви казват “live сме с тая система, ама даже не тръгва, ПОМОЩ”. Та, логвате се и откривате ужасяваща кочина, сглобена от неща, правени от различни хора на различни езици, не-тествана и пълна с малки и големи проблеми, и трябва да проработи.

(или може би само на мен се случва, знам ли…)

Може да се пробвате, като свалите задачката с примерни данни от quiz.storpool.com/of2018.tgz и се пробвате. Отговорът започва с “8”.

За приключилите и нетърпеливите, ето описание:
Задачата се състои от следните файлове: a.c, a.php, a.pl, a.py, run.sh (който си мислех да кръстя “a.sh”) и един Makefile. “run.sh” свързва всички останали заедно, да сметне някакъв резултат от данните в “data/” директорията.

Цялото нещо си има история – имало 4 различни програмиста – C файлът бил написан от човек, който говори английски, PHP-то от финландец, Perl-а от унгарец, Python-а от арабин, и shell script-а от българин. Всички са имали лошо мнение за останалите и са оставили коментари в кода по адрес на останалите.

Счупванията са сравнително тривиални, понеже time limit-а за цялата задача беше 30 минути и имаше разни заблуждаващи моменти. Започвам от свързващия файл и после по pipe-а:

run.sh навързва всичките останали. Основната грешка е, че липсва -0 параметъра на xargs (което се забелязва доста лесно, понеже find използва -print0). Друга гадост е, че файлът е с DOS-овски нови редове и не може да бъде стартиран нормално, или трябва да се подменят, или да си копирате отвътре pipe и да го пуснете на ръка.

В коментарите може да се види как авторът нарича останалите “идиоти” (което съм сигурен, че всички са виждали в някакъв вид), и списъкът му за пазаруване. Последното може да се вижда странно и невероятно, но е нещо, което съм виждал в production код – случва се, като трябва веднага да се запише нещо и човекът го мързи да отвори нов прозорец в редактора или да намери малко хартия.
(някакъв спомен ми се мотае, че случая, който бях виждал беше поръчка за KFC…)

a.php добавя 1 към всички числа, и за да дразни останалите разработчици, добавя и допълнителни интервал. Очевидната грешка е че вместо STDIN е написано STDON, което бързо се оправя.

В коментарите се вижда как програмистът не е щастлив с останалите от екипа и водката му е почти свършила. Не съм виждал лично подобен коментар, но съм чувал от достоверни източници за подобни случаи. Колкото до смисъла от подобен код, има ужасно много такива дребни неща в много проекти, които никога не е трябвало да съществуват, но все пак са там.

a.pl просто премахва всички интервали, т.е. създава едно голямо число от всичките числа на реда. Грешката е, че се използва $__ вместо $_ – лесна за забелязване правописна грешка.

В последния коментар на файла има оплакване, че авторът не е разбрал нищо от това, което останалите са говорили и че финландецът е бил пиян. В някакъв момент бях се замислил дали не искам да разпиша някъде целият разговор на тия хора, щеше или да е много забавно, или много болезнено.

a.py взима всички числа и връща остатъкът им при деление на 2^63 (което е hard-code-нато като 9223372036854775808). Грешката тук е, че цикълът започва с while False:, което няма никакъв смисъл, и смяната му на while True: решава проблема. Самият код е малко по-гаден от останалите, понеже има променливи с имена на арабски, които се изписват от дясно на ляво и могат да объркат терминала, но в крайна сметка тези части не трябва да се пипат.

Оплакването на края е, че ако не си бил взел трета жена, нямало да му се налага да работи с тези хора…

И накрая, a.c прави странни изчисления и вади остатъка от деление на 2^10 на резултата в шестнайсетичен вид (за да е достатъчно кратко, че да върши работа за отговор). Грешката в кода е, че целочисленият тип в началото е грешен и трябва да се работи с long long (което се вижда в останалия код). Това е и причината в Makefile да има -Werror -Wall, за да се забележи лесно проблема.

А коментарите във файла са премахнати заради “PARA-22”, което не би трябвало да има нужда от дообясняване.

Цялото нещо може да изглежда много невероятно, особено колко е чувствително към числата и размера им. Мога да се оправдая с това, че е игра и че основно трябва да е забавно (и че ме мързи), но за съжаление подобни неща съм виждал достатъчно често или са ми разказвали за тях. Поне се надявам, че участниците са се забавлявали:)

2018-09-29 виртуални машини, кеш, cgroup-и и други гадости

Saturday, September 29th, 2018

(английската версия е в блога на StorPool)

Това е един случай, който отне известно време да се дебъгне, включващ StorPool, виртуални машини, cgroup-и, OOM killer-а и кеширането. Части от него би трябвало да са полезни и на други хора/админи.

Започна с оплакване от клиента:

> Пак се случва, на тоя hypervisor виртуалните машини ги убива
> OOM killer-а. Това не се случва на hyervisor-и, на които няма
> cgroup-и, не може ли да не ги конфигурирате?

(
Смисълът изобщо да имаме cgroup-и е, че няма друг начин да се резервират памет и процесори за даден набор процеси. Понеже storage системата е една от най-чувствителните части на системата към латентности и подобни проблеми (или, нека сме по-точни, всичко останало е много чувствително към проблеми на storage системата), доста е полезно да е предпазена от всичко останало. По същия начин е полезно и да се разделят виртуалните машини и системните процеси, за да не го отнесе грешното нещо при някой memory leak или побъркан allocation. Също така, има много забавен вариант за memory deadlock (който го има с всяка storage система, която не е в kernel-а и с някои които са вътре, който може да бъде описан по следния начин:

Процес към kernel-а: искам памет
Kernel към процеса: ей-сега
Kernel (говори си сам): то искаш, ама няма. Нямам какво да освободя друго, но мога да flush-на някакъв dirty cache
Kernel към storage системата: на ти тия данни, запиши ги
Storage системата към kernel-а: разбира се, за теб си режа даже ноктите без упойка
Storage системата (говори си сама): тия данни не са aling-нати както трябва за гнусния хардуер отдолу, трябва да ги копирам малко и наместя
Storage системата към kernel-а: искам памет
)

Разбира се, цялото нещо нямаше да е чак такъв проблем, ако Linux-кия OOM killer и cgroup-ите работеха правилно, но версиите по всичките kernel-и, които срещаме (което значи CentOS[67], т.е. kernel с име 3.10.xxx и с diff спрямо оригинала, който вероятно е колкото 30% от кода) се държат странно и от време на време застрелват sshd вместо който трябва. Новите идеи за отношенията м/у OOM killer-а и cgroup-ите се очертава да ни стъжнят живота още повече.

Та, за да си резервира човек някакъв набор памет за набор от процеси на KVM hypervisor, трябва да създаде memory cgroup-а за системните неща (system.slice), виртуалните машини (machine.slice), може би user-ските неща (user.slice), и в нашия случай storpool.slice. После за всички тия групи сборът на лимитите трябва да е с около 1-2GB по-малък от общата памет (понеже някаква част си е за kernel-а и той никъде не я account-ва), и да се подсигури, че всички процеси са по тези cgroup-и или техни деца, и няма никой в root cgroup-ата. Това се постига с разни опции на libvirt, systemd и малко тел+тиксо, но като цяло върши работа.

Има обаче известен проблем с memory cgroup-ите, буфер кеша и OOM killer-а. Ако не ползвате cgroup-и и не ви стига паметта, kernel-ът по принцип flush-ва dirty page-овете (т.е. незаписаните данни) и clean cache (прочетени файлове от файловата система), та да си върне памет и да може да я даде на който я иска. В случая с cgroup-ите обаче clean cache не се почиства, и предпочитания за kernel-а начин е просто да пусне OOM killer-а, който да застреля някой полезен процес.

(За който бори такива проблеми, има доста полезна информация колко памет е account-ната за какво в “memory.stat” за всяка cgroup-а в /sys, например /sys/fs/cgroup/memory/machine.slice/memory.stat)

Ако си говорим принципно, в случая с виртуалните машини това не трябва да е проблем, понеже те няма причина да ползват кеш – вътре във виртуалката ще има какъвто и трябва, и няма смисъл да се хаби двойно памет (съответно всичките дискове се настройват с cache=none). Да не говорим, че не-спирането на кеша (който разбира се е пуснат по default, ама post за идиотските default-и в qemu/libvirt ще е бая) не позволява да се правят live миграции (libvirt-а отказва, щото можело да доведе до загуба на данни).

(Което всъщност е оправено в https://github.com/qemu/qemu/commit/dd577a26ff03b6829721b1ffbbf9e7c411b72378, но още не изглежда да е merge-нато, благодаря на колегите, че ми го посочиха)

Повечето оркестрационни системи в наши дни ползват “cache=none” в техните конфигурации (и интеграциите на StorPool с тях гледат да го настроят, ако има как), но в този конкретен случай системата имаше някакви много стари виртуалки, правени от стари template-и (някои от които ползваха IDE вместо virtio), и със съответния default. Правилното решение за тези виртуалки би било да се оправи template-а и да се рестартират, но по някаква причина хората не са щастливи да рестартират виртуалките на клиентите, и предполагам, че и клиентите не са големи фенове на идеята. Също така имаше някаква странна причина (която мозъкът ми е изтрил) да не може да се сменят конкретно тези template-и.

Не сме първите, които удрят проблема с “твърде много clean cache в паметта, който не ни трябва”. Ето какво ни хрумна и какво направихме в крайна сметка:

Първата идея, която ни хрумна беше периодично да почистваме buffer cache, с “echo 3 > /proc/sys/vm/drop_caches”. Това ще сработи, но като решение е доста тъпа брадва, понеже и ще изхвърли от кеша полезни неща (и системата ще си препрочита libc-то постоянно).

Втората идея се появи с това, че има нещо много хубаво, наречено LD_PRELOAD, с което в общи линии може да се прихване всякаква функция, която се вика от дадено binary и да се добави още нещо. По този начин може да се прихване open() и ако се открие, че е block device, да му се сложи флаг O_DIRECT (който в общи линии значи “опитай се да не ползваш buffer cache”). Проблемът на O_DIRECT е, че има някои неприятни ограничения, като например изискването паметта и offset-ите при писане/четене да са подравнени по някакъв начин, като 512 байта подравняване би трябвало да са ОК, ако не се ползва файлова система (където може да се наложи подравняване на page size или повече). Понеже няма как да знаем какво прави виртуалната машина отгоре, имаше шанс да се наложи да прихващаме всички read() и write() и да правим копие на данните в наша, подравнена памет, което щеше да е прилично количество писане и щеше да е трудно да няма грешки.

Сетихме се също така, че в kernel-а има интерфейс, наречен posix_fadvise(), който може да се използва да маркира някаква част от кеша като “няма да ми трябва повече” (които kernel-а да разкара). Това можеше да се използва с LD_PRELOAD за read()-ове, като просто се маркираше прочетеното като POSIX_FADV_DONTNEED. Идеята я имаше донякъде реализирана в https://code.google.com/archive/p/pagecache-mangagement/ и тръгнах да я дописвам да прави нещо по-просто (просто posix_fadvise() веднага след read, вместо сложни сметки с колко кеш да се позволява на процес).

Някъде в тоя момент CTO-то ни попита “а то всъщност трябва ли да се вика posix_fadvise() от процеса, или може от всякъде”? Оказа се, че в същото repo има прост инструмент, който изхвърля от кеша данните за даден файл (или блоково устройство), наречен “fadv” (който открих след като написах същите 5 реда).

Крайният резултат беше малък скрипт, който пуска “fadv” за всички наши устройства и ги държи извън кеша, което се каза приемлив workaround. Оказа се и доста бърз – на първото си стартиране му отне около минута да изхвърли около 100GB от кеша, на следващите си пускания минаваше за под секунда.

2018-09-22 бавни ли са ни базите данни?

Saturday, September 22nd, 2018

(обмислям лекция за OpenFest по темата разни инструменти за debug-ване, които съм открил в последно време, звучи ли интересно на някого?)

Тия дни около една лекция на hack conf за scale-ването на приложения, разговори с разни хора за архитектура на системи и дебъгването на някакви готови неща почна да ми се мотае следния въпрос: наистина ли базите данни са толкова бавни и защо?

Въпросът идва от идеята, че единият начин да си спестиш натоварването в пиковите моменти на базата е да буферираш в някаква опашка (напр. Apache Kafka) заявките, така че да може да наваксаш в някакви по-тихи периоди. Това го чух и като идея изобщо за влизащите заявки в системата, без значение дали са batch заявки или такива директно от потребители.

За да не се губят данни, тази опашка трябва да persist-ва данните, т.е. реално да представлява един transaction log, който да се пише на диска преди да се отговори на клиента, че данните са получени. За да се приемат тези данни, вероятно е нужна и малко валидация, да се види дали са “приемливи”/отговарят на constraint-ите на системата.

… което е точно каквото прави всъщност базата данни. По това, което съм виждал (и чел в “Transaction processing”, което май все още е книгата “как се пише база данни”), базата прави точно това – проверява няколко неща и пише транзакцията в лога. Промяната на реалните данни се случва на batch-ове, като се затвори текущия сегмент от transaction log-а, така че писането в базата би трябвало да е бая бърза операция. Четенето се случва от кеш или от реалните данни, така че ако transaction log-а не е на същия хардуер, като цяло няма обективна причина опашката да помага, реално е вършене на същата работа още веднъж.

Та явно базите данни са по-бавни, отколкото би трябвало. Някой да има наблюдения по темата?

2018-08-24 интересен FreeBSD/ZFS проблем

Friday, August 24th, 2018

Днес борихме забавен проблем от типа “може да се дава за пример как се дебъгва нещо, което не разбираш”.

Оригиналното оплакване беше “защо ми е толкова висок пинга до тия машини”. Проследихме го до router-а им, едно FreeBSD (скоро update-вано), което върши разни вътрешни поддържащи дейности и е router за един набор тестова железария.
(аз, ако някой не знае, от FreeBSD не разбирам и конкретно на тая машина съм и се заканил да я преинсталирам с Debian, ама ме спират)

Проблемът беше доста на random и за различни хора. Основното нещо, което се забелязваше в top беше, че 25% от процесорното време отиват в "interrupt", което в общи линии значеше един от 4те core-а на процесора (машината няма hyper-threading). Понеже ми се искаше да имам някаква по-свястна видимост, реших така и така да тествам prometheus при нас, съответно update-нах port-овете на машината (оказва се, че node_exporter-а на prometheus вече го има там), сипах една виртуалка в офисния клъстер, сипах един prometheus и го вързах в grafana-та ни.
(все повече и повече обичам секундните статистики, не знам дали съм го казвал)

Проблемът с 25-те процента в interrupt си се виждаше много хубаво на графиките, и не корелираше с мрежов трафик или каквото и да е. След като си задавах въпроса “какъв е еквивалента на perf top във FreeBSD” открих един много полезен сайт с DTrace примери и по-специално hotkernel програмчето, което можеше да ми каже за даден период от време къде е висял kernel-а. Оказа се, че освен двете idle функции, основно се стои в vm_page_scan_contig(), т.е. някой усилено се опитваше да си заделя последователна памет. Нямаше някъде информация за някакъв известен такъв бъг (и се надявам google да индексира това за следващия, който търси).

Някъде в този момент се оказа, че backup-ите ни, които ходят до тази машина през един NFS вървят доста бавно – сетихме се от мрежовия проблем. В един момент колегата каза “абе, я да видим ако спрем писането им за малко дали нещо ще се промени” и изведнъж проблемът изчезна. Последва въпросът “това от NFS-а ли е, или от ZFS-а отдолу?”, което лесно се тества с едно копиране отвън, и се оказа, че този път (за разлика от доста други) NFS-ът е невинен.

Та, оказахме се с проблем, че като се опитваме да пишем по ZFS-а, той се опитва да си заделя памет, това го бави много и всичко върви зле, а докато kernel-а му търси памет, всичко, дето се опитва да се schedule-не на тоя процесор (като например прекъсванията на една от опашките на мрежовата карта) страда.

Ровихме разни неща по ZFS-а, и в един момент около размислите по паметта видяхме, че от 16GB памет 14GB се води "wired", т.е. заета от kernel-а за някакви неща, в случая изглеждаше да е за ARC кеша на ZFS. Решихме да я намалим, като и пипнахме vfs.zfs.arc_max на 10GB, което обаче нямаше ефект. С малко ровене открихме, че “то няма начин да се чисти кеша, но ако някое приложение си поиска памет, ще се flush-не”, съответно докато си извадя C програмката, дето яде памет, колегата драсна следното:


python -c 'a="b"*1024**4'

(което реално се опитва да изяде 1TB памет, та трябваше да го утрепем в един момент)

Съответно в момента, в който се появи някаква свободна памет, проблемът спря да се появява. Накратко казано, default-ната стойност за количество кеш на ZFS-а е толкова висока, че изяжда цялата памет, и прави всичките му нужни memory allocation-и много бавни, което потрошава цялата производителност. Вероятно това е някаква скорошна промяна, та се чудим дали/къде да го report-ваме.

Update: Разбира се, някой трябва да чете документация – sysctl-то трябва да отиде в loader.conf, преди да се пали root-а и т.н., понеже ZFS-а тия неща ги поглежда само докато си пуска pool-а и после не ни обръща внимание. С един reboot нещата се оправиха…

OpenFest 2017 network write-up

Monday, August 20th, 2018

Това иначе никога няма да го кача, та ето го като dump от оригналния документ, ако някой му се занимава да го преведе до смислен html да каже да му дам link към оригинала.

OpenFest 2017 network write-up

2018-06-30 две малки парчета код

Saturday, June 30th, 2018

Тия дни ми се случи да напиша две малки парчета код, които да ми решат някакъв проблем.

Първото е sproxy – малък демон, който чете на stdin, пълни един цикличен буфер и го дава на всеки, който се закачи за него. Използвам го, за да заместя multicast-а във FOSDEM-ските videobox-ове – видео потокът от encoder-а в кутията се налива в sproxy-то и си тече, и консуматорите (локалния recorder, voctomix-а, разни дебъгващи хора) могат да се свържат до него и да си дърпат видеото. Сумарно стана около 120 реда код на C – кратко, изчистено и доста просто.
Остана да му допиша още един порт, на който като се върже клиент, получава бързо всичко, което е в буфера (в момента който се свърже, получава всичко ново), за малкия tool по кутиите, който взима текущия кадър от видеото да го покаже на дисплея.
(писах го няколко часа и го дебъгвах още толкова)

А по време на първите лекции на БургасConf си сглобих нещо малко ffmpeg с ebur128 филтъра, малко питонски код, InfluxDB и Grafana, което в сравнително реално време да ми чертае нивото на звука от stream-а (примерен изглед). Цялата работа опря до един ffmpeg команден ред, един regex и една функция, която сипва данните в influx-а.
(в grafana-та има и един “километраж”, което е може би най-безсмисления тип визуализация, сложих го като демонстрация. Понеже не се оправя с отрицателни стойности, нещата, дето показва са +70db)
Нещото се оказа толкова лесно и удобно, че даже го показах в един lightning talk на БургасConf. С още малко доработка мисля да влезе в monitoring-а на FOSDEM и разните други конференции, които правим. Ще го кача след доработката, че сега никак не ме радва как работи и как няма буфериране, ако базата почне да се бави.

Такива неща са пример колко полезно и важно е човек да може да пише поне малко, понеже с малко код и съществуващия софтуер човек може да постигне интересни неща. Ето за това не мога да смятам системен администратор, който не може да пише за истински такъв. Чудя се мога ли да измисля някакъв курс за писане на дребни хакове :)

2018-06-23 Национална конференция на “Да България”

Saturday, June 23rd, 2018

Днес се проведе първата Национална конференция на “Да България”.

Обичам заниманията с неща, които други не са правили. Днес това беше реализираното електронно гласуване за всичките точки от дневния ред, което изглежда е първото такова нещо, правено в България, като малка демонстрация, че е нещо, което всъщност може да работи. В рамките на няколко часа бяха направени 45 гласувания, едно от които с интегрална бюлетина. От наблюденията ми на подобни неща (например на учредяването на партията), дори с перфектна организация и много преброители няма как едно гласуване да е под 10 минути, а тук се справяхме за 2-3. Цялата технология беше разработена от няколко човека (от приложението до backend-а) и издържа съвсем спокойно на цялото натоварване без на сървъра да му мигне окото.

В периода, в който вървеше live stream нямаше гласувания, но се надявам в някой момент да можем да публикуваме запис от протичането на едно примерно гласуване – режисьорската работа какво кога къде да показвам на моменти ми идваше много, особено при темповете, с които работехме към края, когато всички вече бяха свикнали със задачите си.

Не беше най-уморителното събитие, в което съм участвал (OpenFest и FOSDEM определено са по-страшни, а gaming турнира в рамките на Animes Expo беше в порядъци по-неприятен), но определено ще имам нужда да си почина малко.

2018-05-03 python, multiprocessing, thread-ове и забивания

Thursday, May 3rd, 2018

Всеки ден се убеждавам, че нищо не работи.

Открих забавен проблем с python и multiprocessing, който в момента още не мога да реша чий проблем е (в крайна сметка ще се окаже мой). Отне ми прилично количество време да го хвана и си струва да го разкажа.

Малко предистория: ползваме influxdb, в което тъпчем бая секундни данни, които после предъвкваме до минутни. InfluxDB има continuous queries, които вършат тази работа – на някакъв интервал от време хващат новите данни и ги сгъват. Тези заявки имаха няколко проблема:
– не се оправят с попълване на стари данни;
– изпълняват се рядко и минутните данни изостават;
– изпълняват се в общи линии в един thread, което кара минутните данни да изостават още повече (в нашия случай преди да ги сменим с около 12 часа).

Хванаха ме дяволите и си написах просто демонче на python, което да събира информация за различните бази какви данни могат да се сгънат, и паралелно да попълва данните. Работи в общи линии по следния начин:
– взима списък с базите данни
– пуска през multiprocessing-а да се събере за всяка база какви заявки трябва да се пуснат, на база на какви measurement-и има и докога са минутните и секундните данни в тях;
– пуска през multiprocessing-а събраните от предния pass заявки
– и така до края на света (или докато зависне).

След като навакса за няколко часа, успяваше да държи минутните данни в рамките на няколко минути от последните секундни данни, което си беше сериозно подобрение на ситуацията. Единственият проблем беше, че от време на време спираше да process-ва и увисваше.

Днес намерих време да го прегледам внимателно какво му се случва. Процесът изглежда като един parent и 5 fork()-нати child-а, като:
Parent-а спи във futex 0x22555a0;
Child 18455 във futex 0x7fdbfa366000;
Child 18546 read
Child 18457 във futex 0x7fdbfa366000
Child 18461 във futex 0x7fdbfa366000
Child 18462 във futex 0x7fdbfa366000
Child 18465 във futex 0x7fdbf908c2c0

Това не беше особено полезно, и се оказа, че стандартния python debugger (pdb) не може да се закача за съществуващи процеси, но за сметка на това gdb с подходящи debug символи може, и може да дава доста полезна информация. По този начин открих, че parent-а чака един child да приключи работата си:


#11 PyEval_EvalFrameEx (
f=f@entry=Frame 0x235fb80, for file /usr/lib64/python2.7/multiprocessing/pool.py, line 543, in wait (self== 1525137960000000000 AND time < 1525138107000000000 GROUP BY time(1m), * fill(linear)\' in a read only context, please use a POST request instead', u'level': u'warning'}], u'statement_id': 0}]}, None], _callback=None, _chunksize=1, _number_left=1, _ready=False, _success=True, _cond=<_Condition(_Verbose__verbose=False, _Condition__lock=, acquire=, _Condition__waiters=[], release=) at remote 0x7fdbe0015310>, _job=45499, _cache={45499: < ...>}) a...(truncated), throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3040

Като в pool.py около ред 543 има следното:


class ApplyResult(object):

...

def wait(self, timeout=None):
self._cond.acquire()
try:
if not self._ready:
self._cond.wait(timeout)
finally:
self._cond.release()

Първоначално си мислех, че 18546 очаква да прочете нещо от грешното място, но излезе, че това е child-а, който е спечелил състезанието за изпълняване на следващата задача и чака да му я дадат (което изглежда се раздава през futex 0x7fdbfa366000). Един от child-овете обаче чака в друг lock:


(gdb) bt
#0 __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1 0x00007fdbf9b68dcb in _L_lock_812 () from /lib64/libpthread.so.0
#2 0x00007fdbf9b68c98 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x7fdbf908c2c0 ) at ../nptl/pthread_mutex_lock.c:79
#3 0x00007fdbf8e846ea in _nss_files_gethostbyname4_r (name=name@entry=0x233fa44 "localhost", pat=pat@entry=0x7fdbecfcb8e0, buffer=buffer@entry=0x7fdbecfcb340 "hZ \372\333\177",
buflen=buflen@entry=1064, errnop=errnop@entry=0x7fdbecfcb8b0, herrnop=herrnop@entry=0x7fdbecfcb910, ttlp=ttlp@entry=0x0) at nss_files/files-hosts.c:381
#4 0x00007fdbf9170ed8 in gaih_inet (name=, name@entry=0x233fa44 "localhost", service=, req=req@entry=0x7fdbecfcbb90, pai=pai@entry=0x7fdbecfcb9f0,
naddrs=naddrs@entry=0x7fdbecfcb9e0) at ../sysdeps/posix/getaddrinfo.c:877
#5 0x00007fdbf91745cd in __GI_getaddrinfo (name=name@entry=0x233fa44 "localhost", service=service@entry=0x7fdbecfcbbc0 "8086", hints=hints@entry=0x7fdbecfcbb90, pai=pai@entry=0x7fdbecfcbb78)
at ../sysdeps/posix/getaddrinfo.c:2431
#6 0x00007fdbeed8760d in socket_getaddrinfo (self=
, args=) at /usr/src/debug/Python-2.7.5/Modules/socketmodule.c:4193
#7 0x00007fdbf9e5fbb0 in call_function (oparg=
, pp_stack=0x7fdbecfcbd10) at /usr/src/debug/Python-2.7.5/Python/ceval.c:4408
#8 PyEval_EvalFrameEx (
f=f@entry=Frame 0x7fdbe8013350, for file /usr/lib/python2.7/site-packages/urllib3/util/connection.py, line 64, in create_connection (address=('localhost', 8086), timeout=3000, source_address=None, socket_options=[(6, 1, 1)], host='localhost', port=8086, err=None), throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3040

(gdb) frame 3
#3 0x00007fdbf8e846ea in _nss_files_gethostbyname4_r (name=name@entry=0x233fa44 "localhost", pat=pat@entry=0x7fdbecfcb8e0, buffer=buffer@entry=0x7fdbecfcb340 "hZ \372\333\177",
buflen=buflen@entry=1064, errnop=errnop@entry=0x7fdbecfcb8b0, herrnop=herrnop@entry=0x7fdbecfcb910, ttlp=ttlp@entry=0x0) at nss_files/files-hosts.c:381
381 __libc_lock_lock (lock);
(gdb) list
376 enum nss_status
377 _nss_files_gethostbyname4_r (const char *name, struct gaih_addrtuple **pat,
378 char *buffer, size_t buflen, int *errnop,
379 int *herrnop, int32_t *ttlp)
380 {
381 __libc_lock_lock (lock);
382
383 /* Reset file pointer to beginning or open file. */
384 enum nss_status status = internal_setent (keep_stream);
385

Или в превод – опитваме се да вземем стандартния lock, който libc-то използва за да си пази reentrant функциите, и някой го държи. Кой ли?


(gdb) p lock
$3 = {__data = {__lock = 2, __count = 0, __owner = 16609, __nusers = 1, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}},
__size = "\002\000\000\000\000\000\000\000\341@\000\000\001", '\000' , __align = 2}
(gdb) p &lock
$4 = (__libc_lock_t *) 0x7fdbf908c2c0

Тук се вижда как owner-а на lock-а всъщност е parent-а. Той обаче не смята, че го държи:


(gdb) p lock
$2 = 0
(gdb) p &lock
$3 = (__libc_lock_t *) 0x7fdbf9450df0
(gdb) x/20x 0x7fdbf9450df0
0x7fdbf9450df0
: 0x00000000 0x00000000 0x00000000 0x00000000
0x7fdbf9450e00 <__abort_msg>: 0x00000000 0x00000000 0x00000000 0x00000000
0x7fdbf9450e10 : 0x00000000 0x00000000 0x00000000 0x00000000
0x7fdbf9450e20 : 0x00000000 0x00000000 0x00000000 0x00000000
0x7fdbf9450e30 : 0x001762c9 0x00000000 0x00000000 0x00000000

… което е и съвсем очаквано, при условие, че са два процеса и тая памет не е обща.

Та, явно това, което се е случило е, че докато parent-а е правел fork(), тоя lock го е държал някой, и child-а реално не може да пипне каквото и да е, свързано с него (което значи никакви reentrant функции в glibc-то, каквито па всички ползват (и би трябвало да ползват)). Въпросът е, че по принцип това не би трябвало да е възможно, щото около fork() няма нищо, което да взима тоя lock, и би трябвало glibc да си освобождава lock-а като излиза от функциите си.

Първоначалното ми идиотско предположение беше, че в signal handler-а на SIGCHLD multiprocessing модула създава новите child-ове, и така докато нещо друго държи lock-а идва сигнал, прави се нов процес и той го “наследява” заключен. Това беше твърде глупаво, за да е истина, и се оказа, че не е…

Около въпросите с lock-а бях стигнал с търсене до две неща – issue 127 в gperftools и Debian bug 657835. Първото каза, че проблемът ми може да е от друг lock, който някой друг държи преди fork-а (което ме накара да се загледам по-внимателно какви lock-ове се държат), а второто, че като цяло ако fork-ваш thread-нато приложение, може после единствено да правиш execve(), защото всичко друго не е ясно колко ще работи.

И накрая се оказа, че ако се ползва multiprocessing модула, той пуска в главния процес няколко thread-а, които да се занимават със следенето и пускането на child-ове за обработка. Та ето какво реално се случва:

– някой child си изработва нужния брой операции и излиза
– parent-а получава SIGCHLD и си отбелязва, че трябва да види какво става
– главния thread на parent-а тръгва да събира списъка бази, и вика в някакъв момент _nss_files_gethostbyname4_r, който взима lock-а;
– по това време другия thread казва “а, нямам достатъчно child-ове, fork()”
– profit.

Текущото ми глупаво решение е да не правя нищо в главния thread, което може да взима тоя lock и да се надявам, че няма още някой такъв. Бъдещото ми решение е или да го пиша на python3 с някой друг модул по темата, или на go (което ще трябва да науча).

2018-01-28 чукове

Sunday, January 28th, 2018

“Не го насилвай, вземи по-голям чук”

Каня се от много време да направя debugging workshop, и около мисленето как точно да стане днес стигнах до интересен извод за инструментите, дето ползвам и си правя за дебъгващи цели и като цяло за разни мои начини на работа.

Чукът е хубаво нещо. Какъвто и проблем да имаш, след удара с чука резултатът има същия вид (сплескан) и донякъде ми се вижда като хубава метафора за начина, по който оправям някакви проблеми. Той може да се опише като “най-краткия и прост начин за достигане на нужното крайно състояние, без да има особено значение какво е началното.

Като за пример, тия дни ми се налагаше да подменя едно парче софтуер в 50-тина клъстера, като всеки от тях имаше м/у 3 и 50 машини. Понеже инструментите, които имам са pssh и pscp, се оказа най-лесно на един пас да копирам нужните файлове по всички сървъри, и на втори пас да се логне pssh и ако трябва, да копира където трябва, иначе просто да изтрие това, което бях копирал. Някакъв по-подреден начин би било да извадя списък на всички машини, на които има нужда да се направи действието и да го направя само там, но щях да го напиша и направя по-бавно, отколкото по грубия и бърз начин.

По подобен начин за друг инструмент си бях написал скрипт, който го налива в цял клъстер и отделен, който го update-ва. В един момент осъзнах, че това е тъпо и направих инсталатора така, че да не му пука, ако има вече нещо инсталирано и просто спокойно да може да слага отгоре (както и ако го прекъсна и го пусна пак, да свърши пак нужната работа). Крайният резултат беше, че общото количество код намаля.

Принципът изглежда да може да се приложи към любимите ми начини за дебъгване – това, което ползвай най-често е strace, което спокойно може да се опише като един от най-тежките чукове за дебъгване. Почти без значение какво дебъгвам – компилиран C код, php, python, perl, java – успявам да видя симптомите и да се ориентирам какво става, въпреки че като цяло за всеки от тия езици има специализиран и вероятно доста по-нежен вариант да се гледа какво става.
(искам да отбележа, че има и други тежки случаи – имам колега, който за да смята някакви математически изрази от време на време вместо да си пусне някакъв калкулатор като bc, пуска gdb и прави в него нещо като “p 1024*1024*231/1.1”)

Замислил се бях дали това всъщност не е погрешно и че трябва да се избягва, и стигнах до извода, че не виждам друг работещ начин. Много често ни се налага да дебъгваме чужд код (който сме link-нали/който е под нас някъде/от който зависим, или просто това са ни изсипали) и вариантът да го прочетем и разберем не е опция, понеже в наши дни почти няма проекти, които да могат да бъдат изчетени и опознати за под седмица-две (рекордно малкият код, който в една от фирмите, в които съм работил и търкаляше основните услуги беше около 20000 реда, което е горе-долу в човешките възможности, и пак ще отнеме доста време да се разгледа, а фирмата в това отношение беше сериозно изключение). Това води до нуждата за всякакви помощни средства, за да можем да се справим, понеже човешката глава има сериозни ограничения по темата, и тук на помощ ни идват чуковете, с които всеки проблем може да бъде сведен до пирон (или хлебарка, която трябва да се прасне достатъчно силно).

(да не говорим, че хората искат да пишат умно, и колкото по-умно пишат, толкова по-трудно се дебъгва това, което са сътворили)

2017-12-18 ARP в Linux

Monday, December 18th, 2017

Почнал съм да събирам списък “неща, на които разчитам и не работят”. Ето едно от тях, в което се ударих преди малко – arp-а на linux kernel-а.

(след като тоя протокол и поддръжката му ги има от години и всички го ползват, някакси очаквам да не ме ритат в кокалчетата)

Преди няколко дни имах оплакване, че от определени места не се стига до marla. След малко тестове нещото сработи от самосебе си и не успяхме да го хванем. Тая вечер проблемът се появи пак, като интересното беше, че до други машини в същата мрежа имаше свързаност, само до marla – не.

Последваха стандартните неща – едно mtr до marla, едно до един от адресите, който не е от нашата мрежа, и нищо. Слушайки на интерфейсите, виждах да влиза трафик, но не виждах нищо да излиза.

Един ip r get каза следното:

77.246.xxx.xxx via 193.169.198.179 dev eth3.1030 src 193.169.198.230

193.169.198.179 е inetbg.bix.bg, които са доставчика на човека. Пинг до това ip нямаше, нямаше и arp entry за него и моята първа мисъл беше “тия па какво са объркали”. След което пуснах един tcpdump и видях следното:

22:06:48.470979 ARP, Request who-has 193.169.198.179 tell 185.117.82.66, length 28

Ако нещо ви се вижда да не е наред – прави сте. Не би трябвало да питам в тоя сегмент с адрес, дето съм извадил от съвсем друго място, и е доста очаквано, че някой няма да иска да ми отговори. Кратко търсене и спомняне ме доведе до /proc/sys/net/ipv4/conf/*/arp_announce, за което може да прочетете в ip-sysctl.txt в документацията на kernel-а.

За който не му се чете, параметърът по default е 0, което значи “сложи там за source ip някакъв адрес, който ти хареса”, 1 значи “гледай поне да е от същата мрежа” и 2 значи “избери внимателно”. Защо не е 2 default-а, не мога да си обясня (но преди малко беше изконфигуриран на двата router-а при нас да е така).

Допълнително на който му се забавлява, може да види какво пише за останалите arp опции и как се държи по default kernel-а, например че може да отговори на arp за един интерфейс от друг, без изобщо да му пука (и което по някакви твърдения отговаря на RFC-тата, което обаче не успях да открия). За всички, които искат смислено поведение на arp-а на linux kernel-а, препоръчвам следните sysctl-та:

net.ipv4.conf.all.arp_filter=1
net.ipv4.conf.all.arp_announce=2
net.ipv4.conf.all.arp_ignore=2

(тези са особено нужни ако имате сегмент, в който имате две мрежи и по два и повече физически интерфейса и искате някакъв контрол откъде и как ви върви трафика)

2017-12-13 разни

Wednesday, December 13th, 2017

И много неща на едно място, че все няма време за блогване.

Лабът организира голямо коледно LAN party, на 21.12, с всякакъв хардуер и игри.

Също така подредихме пак в лаба студио за записване на podcast-и, и дори записахме един тестов подкаст (записът е с много малко обработка, май трябва да се усили още малко). Като цяло може да се подобри малко софтуерната част (т.е. да отделя един час и да я поавтоматизирам), и да вземем още една стойка за единия микрофон (вместо да стои в едно диджириду, което е подпряно на стойка за китара), но изглежда да върши работа.

И финално лабово, насъбрали сме толкова странна техника, че обмислям workshop/състезание кой ще успее да подкара най-много неща. В момента ситуацията е такава, че мога да вържа VAX-а по оптика (което много ми се иска да направя тия дни, като имам малко време).

А на мен ми се спи. Тия дни успявам да събера някакъв сън, но като цяло трудно събирам наистина почивни weekend-и, в които основно да спя и да си почивам, та трябва да измисля нещо по въпроса, самия openfest ужасно ме умори (там имах няколко седмици без никаква почивка). Наскоро имах и един ден, в който събрах два пъти по 8 часа работа (второто беше да подредя видео и подобната техника от феста в лаба, че имаше нужда и заемаше място на неправилните места).

В работата е забавно, всеки ден откривам нови неща, които не работят и странни бъгове и дизайн решения в компоненти, които уж хората са тествали, ползват и са ок. От по-пресните примери е как continuous queries на influxdb при достатъчно бази и данни просто никога не могат да наваксат, защото са в един thread, който се вика дявол знае кога. Успях да ги заместя с 200 реда код на python (и разпитвайки google, не само аз съм така).

На книжния фронт една от основните новини е, че авторът на Worm е приключил последния си проект (Twig) и се е хванал пак да пише в света на Worm (казва се Ward), което е страхотно за всички, обичащи книгите по 5000 страници.

Тоя weekend има хакатон във ФМИ, за който услужихме от лаба с малко странна техника. Има ли някой, който може да пробута идеята на отборите да декодират радиопредаванията, с които наливат данни на таблата по спирките? Има нужния хардуер, вероятно със съществуващите неща като gnuradio няма да е сложно да се демодулира, и дори няма нужда да се доправя частта, с която може да се подават произволни надписи за показване по тия табла…

Върви подготовката за FOSDEM. След последните тестове (които правихме на един хакатон там на място) моя код, дето ползва openpgm не retransmit-ва, и за един ден дебъгване (и вкарване на print-ове на разни места и опити да разбера какво точно искат да кажат тия хора, които в разни функции с имена “провери-нещо-си” променят по генералния state и които доста намразих) не успях да намеря що не сработва. Обмислям да се скрия някъде по празниците и да го дебъгвам, или да измисля решение с TCP най-накрая.
(как може никой да не е написал multicast TCP. Трябва да го дадем за задача на някой, дето не знае, че не е възможно и да видим какво ще излезе…)

Спирам, преди това да е станало съвсем несвързано.

2017-11-06 задача

Monday, November 6th, 2017

(по-подробно за феста – като се наспя)

За OpenFest 2017 за щанда на StorPool бях написал една задача, та който я реши, да получи тениска. Задачата звучи измамно просто и аз също не съм се усетил, че не е лесно решима за 10 минути.

Задачата е следната – имате директория с някакво количество файлове, да видите кои от тях са MD5 и кои – SHA1 колизии, и да дадете първите букви от имената им (4 файла за md5 и 4 за sha1). Моето решение беше във временна директория да се направят файлове с имена MD5 (и после – SHA1) сумите, в които да се напишат имената и SHA256 сумите на файловете с тая MD5 сума, и после с един sort на всеки файл лесно се вижда в кой има различни файлове (трябва да са еднакви по принцип). Ако е просто да се види коя е md5 сумата, може да се броят уникалните sha256 суми във всички файлове, да се види къде са колизиите.

Интересно ще ми е наистина ли е толкова трудна задачата (доколкото знам, за два дни само един човек я е решил за 10 минути).

Също така ми е интересно дали някой не е решил да пита google какви са checksum-ите на демонстрационните sha1/md5 колизии и да види дали аз не съм си събрал файловете по тоя начин…

Кодът, който генерира задачата е качен на https://vasil.ludost.net/progs/storpool-of-task.tgz. Вътре има gen.sh, който трябва да се пипне малко къде да прави файловете и който при пускане създава малко файлове и ви дава отговора. Не съм сложил другите неща (това, което се прави на login shell и нещото, което праща отговорите по slack на проверяващия), но те не са толкова интересни.

2017-10-26 policy routing с Linux

Thursday, October 26th, 2017

В последно време на няколко места по различни случаи ми се налага да подкарвам policy routing под Linux, та тук мисля да систематизирам защо и как.

1) Какво е policy routing

Съвсем просто, routing, който не се базира САМО на destination IP адрес. В linux това се реализира чрез правила (rules), които на база на нещо решават да се гледа друга routing таблица, не стандартната.

2) Защо ни трябва

Основният use case е когато имаме два или повече default route-а, и искаме да можем за трафик, който е дошъл от единия да излизаме навън пак през него. Примерът, който ще дам по-долу е с два internet доставчика, но при мен се налага като конфигурирам bgp с някой, да слагам policy routing за адресите, които са на самия link да си излизат от верния интерфейс, за да мога да вляза от там, ако нещо се е ошашкало по bgp-то.

3) Как се настройва за крайна машина

Примерът, който ще дам е какво правим, ако имаме два доставчика, които ще кръстя pesho и gosho (ако искате, PeshoNet и GoshoCom).

pesho ви е дал link, на който имате адрес 10.1.1.30/24 с default gw 10.1.1.1 и сте го вързали на eth0, gosho ви е дал 10.2.2.40/24 с default gw 10.2.2.254 и сте го вързали на eth1.

Давам настройките директно с команди, как да интегрирате това в настройките на дистрибуцията си варира твърде много (мога да кажа, че в debian с pre-up и down директиви в interfaces файла може да се направи цялото нещо).

Ако просто ги настроите директно, routing таблицата ще изглежда по следния начин:

~ # ip r
default via 10.1.1.1 dev eth0
default via 10.2.2.254 dev eth1
10.1.1.0/24 dev eth0  proto kernel  scope link  src 10.1.1.30
10.2.2.0/24 dev eth1  proto kernel  scope link  src 10.2.2.40

Това никаква работа не върши, понеже ако отвън дойде пакет за 10.1.1.30, може да излезе от другия link и обратно, а това доставчиците никак не го обичат и филтрират. За това просто в тая таблица оставяте само единия от двата default-а и продължаваме нататък.

Първо, харесваме си числата 1 и 2, даваме 1 на pesho, 2 на gosho, и ги описваме в /etc/iproute2/rt_tables (там има и други неща, това са редовете за добавяне):


...
1 pesho
2 gosho
...

Смисълът от това е, че можем да пишем неща като ip r show table pesho вместо ip r show table 1.

Имайки тези таблици, ги попълваме с каквито пътища имаме:

ip route add 10.1.1.0/24 dev eth0 table pesho
ip route add default via 10.1.1.1 table pesho
ip route add 10.2.2.0/24 dev eth1 table gosho
ip route add default via 10.2.2.254 table gosho

И след това пишем самите правила:

ip rule add from 10.1.1.30 iif lo table pesho
ip rule add from 10.2.2.40 iif lo table gosho

Тук има нужда от малко обяснение – “iif lo” означава “идващи от локалната машина”, останалото е в общи линии просто – ако source адресът е този, гледай конкретната таблица.

До тук е setup-а, ако имате просто една машина и нищо повече…

4) Как се настройва при NAT

Какво правим, ако имаме отзад една мрежичка, да кажем стандартната 192.168.0.0/24, на eth7?

Като за начало, трябва да добавим тази мрежа и в другите две таблици:

for t in pesho gosho; do ip route add 192.168.0.0/24 dev eth7 table $t; done

(някой би написал командите, но ми се е налагало да правя това за 10 таблици и почва да става досадно)

Съответно, да речем, че си имате едни прости правила за nat, които казват, че маскирате трафика навън:

iptables -t nat -A POSTROUTING -o eth0 -j MASQUERADE
iptables -t nat -A POSTROUTING -o eth1 -j MASQUERADE

и някакво правило, че имате някакво web сървърче навътре на 192.168.0.100 порт 8080:

iptables -t nat -A PREROUTING -d 10.1.1.30/32 -i eth0 -p tcp -m tcp --dport 8080 -j DNAT --to-destination 192.168.0.100:80
iptables -t nat -A PREROUTING -d 10.2.2.40/32 -i eth1 -p tcp -m tcp --dport 8080 -j DNAT --to-destination 192.168.0.100:80

Тук за изходящите връзки, ако решите да смените през кой доставчик, съществуващите ще тръгнат да излизат през новия път (и няма да работят), а ако имате входящи от този, през който не ви е текущия default route, пак ще се опитват да излязат от грешното място, понеже маскирането се случва някъде след routing-а. Решението е т.нар. “CONNMARK”, с който може 1) да маркирате определени връзки, 2) маркировката да се пренася в/у пакетите, и после 3) по маркировката да решавате коя таблица да ползвате.

Това се случва в mangle:

iptables -t mangle -A PREROUTING -i eth0 -m conntrack --ctstate NEW -j CONNMARK --set-xmark 0x1/0xffffffff
iptables -t mangle -A PREROUTING -i eth1 -m conntrack --ctstate NEW -j CONNMARK --set-xmark 0x2/0xffffffff
iptables -t mangle -A PREROUTING -j CONNMARK --restore-mark --nfmask 0xffffffff --ctmask 0xffffffff
iptables -t mangle -A POSTROUTING -j CONNMARK --save-mark --nfmask 0xffffffff --ctmask 0xffffffff

Тези неща се превеждат като “по единия интерфейс маркирай с 1, по другия с 2, на вход сипвай маркировката от connection-а в пакета (restore-mark), на изход сипвай от пакета на connection-а” (взех ги от един готов save-нат iptables, за това са с тия пълни маски, мисля, че по принцип не бяха нужни). Другото, което трябва е да добавим routing правила, които да взимат решение коя таблица се гледа:

ip rule add fwmark 0x1 table pesho
ip rule add fwmark 0x2 table gosho

5) Load balancing, failover, такива неща

Това е голяма гадост. Писал съм преди по темата за fail-over. Като изключим gwping-а и може би една добавка ако той сменя връзката, понеже е умряла да трепе всичкия state в conntrack-а, нямам какво да добавя.

За load balancing бих препоръчал нещо сравнително статично, определени неща през единия доставчик и други през другия, с нещо, което ги трие, когато изпадне единия доставчик. Бях провеждал експеримент в initLab да правя 2 connection-а през единия доставчик и един през другия или някакви такива неща, резултатът беше доста неприятен.

2017-05-09 bias-и и дебъгване

Tuesday, May 9th, 2017

Нещо странично.

Тия дни в офиса около някакви занимания обсъждахме следната задача:

“Имаме банда пирати (N на брой, капитан и N-1 останали членове), които искат да си разделят съкровище от 100 пари. Пиратите имат строга линейна йерархия (знае се кой след кой е). Разделянето става по следния начин – текущият капитан предлага разпределение, гласува се и ако събере половината или повече от гласовете се приема, ако не – убиват го и следващия по веригата предлага разпределение. Въпросът е какво трябва да предложи капитанът, така че всички да се съгласят, ако приемем, че всички в екипажа са перфектни логици. Също така пиратите са кръвожадни и ако при гласуване против има шанс да спечели и същите пари, пак ще предпочете да убие капитана. Също така всички са алчни и целта е капитанът да запази най-много за себе си.”
(задачата не идва от икономиката, въпреки че и там всички са перфектни логици и за това толкова много им се дънят теориите)

Решението на задачата е интересно (за него – по-долу), но е доста по-интересно колко трудно се оказа да я реша. Първоначалната ми идея беше просто на горната половина от пиратите да се разделят намалящи суми, понеже това е стандартния начин, по който се случват нещата. Това се оказа неефективно. После ми напомниха (което сам трябваше да се сетя), че такива задачи се решават отзад-напред и по индукция, и като за начало започнахме с въпроса, какво става ако са само двама?

Първият ми отговор беше – ами другия член на екипажа ще иска винаги да убие капитана, щото така ще вземе всичко. Обаче се оказа, че и капитана има глас, т.е. ако останат само двама, капитанът взима всичко и разпределението е 100 за него и нищо за другия.

Какво следва, ако са трима? Казах – добре, тогава даваш на единия 1, на другия 2, и останалото за капитана, понеже ако останат само двама, последния няма да вземе нищо, капитанът гласува за себе си и втория и да е за и против, няма значение. Само че няма нужда да даваме нищо на средния, щото не ни пука за мнението му, така всъщност правилното разпределение идва 1, 0, 99. Тук пак си пролича bias-а, пак очаквах да има някаква пропорция.

Long story short, следващата итерация е 0, 1, 0, 99, понеже така ако не се съгласят, на следващия ход предпоследния ако не се съгласи няма да вземе нищо, и на другите двама мнението няма значение. Pattern-а мисля, че си личи :)

Лошото е колко много влияеше bias-а, който съм натрупал от четене за разпределения в реалния живот – какво са пиратите, как няма перфектни логици (и реално никой няма да смята по тоя начин, а ще се стремят към нещо, което им се вижда честно), как това тотално изключва политическата възможност N/2+1 от долната част да гласуват винаги против, докато не дойде всичкото до тях и после да си го разделят по равно и всякакви подобни варианти от реалния живот. Ако примерът беше с каквото и да е друго (например не включваше хора), вероятно щеше да е доста по-лесно да гледам абстрактно.

Което е още един довод в подкрепа на идеята ми, че много по-лесно се дебъгва нещо чуждо (често и което никога не си виждал), отколкото нещо, с което почти постоянно се занимаваш. Над 90% от проблемите (това не се базира на никаква статистика, а на усещане) са достатъчно прости, че да могат да се решат със стандартни методи и да не изискват много задълбочено познаване на системата (половината ми живот е минал в дебъгване на неща, които не разбирам, доста по-често успешно, отколкото не) и вероятно като/ако правя debug workshop-а (за който много хора ми натякват), ще е с проблеми, с които и аз не съм запознат, да е наистина забавно …

2017-04-10 splitpatch

Monday, April 10th, 2017

Нов ценен tool – splitpatch (има го в debian, нищо, че е на ruby).

Трябваше да вкараме едно парче код (на perl) в главното ни repo, и след code review имаше забележки като за 11 промени. Вкарахме ги, тествах го и открих, че не работи – output-а беше много много различен от този в началото (който си се знаеше, че е верен).

Един вариант беше някой да гледа промените ред по ред и да се разбере какво е объркано. Вместо да се стига до такива крайни мерки, намерих tool, който може да сцепи patch-а на hunk-ове, и след това направих следното:

for i in ptch/* ; do patch -o test TOOL $i ; ./test debug > $i.output ; done

и след това с един прост for и diff видях кои съвпадат и кои се различават, и проблемния commit лъсна…

Имаше и варианта вместо да patch-вам оригинала, да махам по един patch от финалния, докато не изчезне проблема. При зависещи един от друг hunk-ове пък може да се направи нещо още по-забавно – да се направят всичките комбинации от patch-ове (като са 11 не са толкова много), да се изтества и пак да се хване разликата сравнително лесно (ако например два са виновни).

Изводът е, че човек може да дебъгва код на нещо в много случаи и без да знае езика…

2017-04-05 интервюта за админи

Wednesday, April 5th, 2017

Смених работата, но се оказва, че от интервютата бягане няма. Тоя път са за системни администратори.

За всеки нов вид интервюта си трябва доста време, за да се свикне и измисли хубав метод. Например, нямам fizzbuzz, доста по-трудно е да кажеш “покажи какво си писал”, а срещането на NDA, заради което не може да се говори какво е вършено не е чак толкова рядък случай. Да разбереш дали някой разбира в дълбочина някоя технология не винаги може да стане с 2-3 въпроса. Да не говорим, че докато не видиш как работи човека, няма как да го прецениш дали става…
(най-добрия вариант го правят в automattic, просто един месец ти плащат да работиш с екипа и ти дават задачи и гледат как се справяш. За съжаление не е лесно да се направи на друго място.)

Като за начало съм си сглобил малък админски тест, който да пращам на хората. Има даже дребен състезателен елемент и се чудя дали не мога да го разпъна до нещо escape-room-о-подобно :)

(in other news, бях седнал да си си разписвам escape room за админи, ако се намери достатъчно интерес може да я сглобя в лаба, има всякакви странни неща вътре)

(p.s. ако някой тия задачи са му лесни и си търси работа, лесно се разбира де да си прати CV-то…)