drbd not activating on master after update/reboot

[candlerb]

Something strange here.

Short version: I migrated some VMs and rebooted the underlying hosts, and then DRBD was not getting configured at all on the master node.

Long version:

* Two nodes, wrn-vm1 (master) and wrn-vm2. Both are Debian wheezy. Both have identical sets of packages (output of "dpkg-query -l" is identical)

* I recently updated ganeti to 2.9.5 (from wheezy-backports; previously was on 2.8.4 from source)

* I also did a full "apt-get dist-upgrade" and found that a newer kernel was installed: 3.2.54-2, whereas 3.2.46-1 was running. So I decided to reboot the boxes in turn to activate the new kernel.

* There were only two important VMs, both running on wrn-vm1. I started another VM on wrn-vm2, migrated it back and forth to wrn-vm1 a few times to check all was OK, and left it on wrn-vm1.

So at this point there were three VMs running on wrn-vm1 (all using drbd disks), and nothing on wrn-vm2.

* I then rebooted wrn-vm2 to get the new kernel there. Fine.

* I then migrated all three VMs from wrn-vm1 to wrn-vm2. Fine.

* I then rebooted wrn-vm1. This is where the problems started.

When I tried to migrate a machine back from wrn-vm2 to wrn-vm1, it told me /proc/drbd was not present on wrn-vm1. Sure enough, lsmod showed that the drbd module hadn't been loaded.

So I did "modprobe drbd".

Now drbd is present, but completely unconfigured.

root@wrn-vm1:~# cat /proc/drbd

version: 8.3.11 (api:88/proto:86-96)

srcversion: F937DCB2E5D83C6CCE4A6C9

root@wrn-vm1:~#

Ganeti has not configured any of the drbd devices needed for the three VMs which are primary on wrn-vm2 and secondary on wrn-vm1.

So on wrn-vm1 I did "/etc/init.d/ganeti restart". No difference:

root@wrn-vm1:~# cat /proc/drbd

version: 8.3.11 (api:88/proto:86-96)

srcversion: F937DCB2E5D83C6CCE4A6C9

root@wrn-vm1:~#

root@wrn-vm1:~# gnt-cluster verify-disks

Submitted jobs 150105

Waiting for job 150105 ...

No disks need to be activated.

So, ganeti thinks everything is fine!

If I use "gnt-instance info" it clearly shows that the instance is using the drbd template, with nodeB being wrn-vm1

Looking at the wrn-vm2 side:

root@wrn-vm2:~# cat /proc/drbd

version: 8.3.11 (api:88/proto:86-96)

srcversion: F937DCB2E5D83C6CCE4A6C9

 1: cs:WFConnection ro:Primary/Unknown ds:UpToDate/DUnknown C r-----

    ns:120 nr:0 dw:5388 dr:135244 al:36 bm:6 lo:0 pe:0 ua:0 ap:0 ep:1 wo:f oos:248

 2: cs:WFConnection ro:Primary/Unknown ds:UpToDate/DUnknown C r-----

    ns:0 nr:0 dw:0 dr:1072 al:0 bm:0 lo:0 pe:0 ua:0 ap:0 ep:1 wo:f oos:0

 3: cs:WFConnection ro:Primary/Unknown ds:UpToDate/DUnknown C r-----

    ns:0 nr:0 dw:56 dr:1072 al:0 bm:0 lo:0 pe:0 ua:0 ap:0 ep:1 wo:f oos:0

root@wrn-vm2:~# drbd-overview

  1:??not-found??  WFConnection Primary/Unknown UpToDate/DUnknown C r-----

  2:??not-found??  WFConnection Primary/Unknown UpToDate/DUnknown C r-----

  3:??not-found??  WFConnection Primary/Unknown UpToDate/DUnknown C r-----

root@wrn-vm2:~#

I can't see any other problems with the cluster:

root@wrn-vm1:~# gnt-cluster getmaster

wrn-vm1.example.com

root@wrn-vm1:~# gnt-cluster verify

(all looks OK, no errors or warnings)

Both nodes have

options drbd minor_count=128 usermode_helper=/bin/true

in /etc/modprobe.d/drbd.conf

I rebooted wrn-vm1 again, all is exactly the same. Again I had to modprobe drbd by hand.

I added drbd to /etc/modules and rebooted wrn-vm1 again. This time drbd was present, but again no drbd devices have been created.

Presumably the drbd devices should be created at some point when the ganeti daemons start up, but I don't know at what point.

I found this in watcher.log:

2014-03-17 15:15:04,974: ganeti-watcher pid=4132 INFO Skipping disk activation for instance with not activated disks 'sftp'

2014-03-17 15:15:04,974: ganeti-watcher pid=4132 INFO Skipping disk activation for instance with not activated disks 'airfoo'

2014-03-17 15:15:04,974: ganeti-watcher pid=4132 INFO Skipping disk activation for instance with not activated disks 'netdot.example.com'

Those are the names of the three VMs. So the disks are not "activated"? Googling takes me to the manpage for gnt-instance activate-disks. And sure enough:

# gnt-instance activate-disks --wait-for-sync netdot.example.com

Mon Mar 17 15:17:48 2014  - INFO: Waiting for instance netdot.example.com to sync disks

Mon Mar 17 15:17:49 2014  - INFO: - device disk/0: 100.00% done, 0s remaining (estimated)

Mon Mar 17 15:17:49 2014  - INFO: Instance netdot.example.com's disks are in sync

wrn-vm2.example.com:disk/0:/dev/drbd1

And now I can migrate this machine back and forth happily.

But this to me begs a number of questions:

(1) What does "activating" a disk mean?

(2) Why, after rebooting wrn-vm1 (which was the master node but secondary for those instances), were the disks not activated?

(3) Why did "gnt-cluster verify-disks" say that no disks needed to be activated?

I may be able to leave the other VMs in an unactivated state for a short time, if it helps debug the issue, but I'd rather get them mirrored again sooner rather than later.

Regards,

Brian.

[candlerb]

Poking around python I see that disks_active is an attribute of class Instance in lib/watcher/__init__.py. And it is visible if you ask for it:

# gnt-instance list -o name,disks_active

Instance                  DisksActive

airfoo                    N

netdot.example.com        Y

sftp                      N

So ganeti knows they're not "active", and this seems to be suppressing gnt-watcher from fixing them. I don't grok haskell, but I see there's a description:

"Desired state of instance disks" [src/Ganeti/Query/Instance.hs]

If I look at "gnt-instance info" output, I see that the disk is 'degraded' but I can't see anything about it being activate or inactive.

  Disk template: drbd

  Disks:

    - disk/0: drbd, size 10.0G

      access mode: rw

      nodeA: wrn-vm2.example.com, minor=2

      nodeB: wrn-vm1.example.com, minor=2

      port: 11003

      auth key: XXXX

      on primary: /dev/drbd2 (147:2) in sync, status *DEGRADED*

      name: None

      UUID: f8e534f7-a593-48b8-80a1-49e52e818ca2

      child devices:

        - child 0: plain, size 10.0G

          logical_id: xenvg/a2151b02-43bc-4de9-85ff-29182ec6d0a3.disk0_data

          on primary: /dev/xenvg/a2151b02-43bc-4de9-85ff-29182ec6d0a3.disk0_data (253:9)

          on secondary: /dev/xenvg/a2151b02-43bc-4de9-85ff-29182ec6d0a3.disk0_data (253:7)

          name: None

          UUID: 7cdf3490-b59b-4b40-b0c2-99844f8b3b1c

        - child 1: plain, size 128M

          logical_id: xenvg/a2151b02-43bc-4de9-85ff-29182ec6d0a3.disk0_meta

          on primary: /dev/xenvg/a2151b02-43bc-4de9-85ff-29182ec6d0a3.disk0_meta (253:10)

          on secondary: /dev/xenvg/a2151b02-43bc-4de9-85ff-29182ec6d0a3.disk0_meta (253:8)

          name: None

          UUID: af5bfebd-57f6-491b-b842-29bc46c4cefa

But if I look in /var/lib/ganeti/config.data I see "disks_active":{true|false}

So it seems to me that disks being "active" is a persistent state, although somewhat hidden. In particular it's not shown in "gnt-instance info".

Therefore I may as well activate them now. The question is really how they became deactivated during the migrate/reboot process.

Although I have not lost any data, this is all pretty scary. It might be helpful if:

* "gnt-instance info" showed if the instance had deactivated disks

* "gnt-cluster verify-disks" warned about running instances with deactivated disks

Regards,

Brian.

[candlerb]

Now I know that "activate" is the key word, I grepped for "activ" in the logs and I found this in master-daemon.log, just after the first reboot of the master node which was at 14:44.

2014-03-17 14:45:05,418: ganeti-masterd pid=3756/ClientReq10 INFO New job with id 150090, summary: INSTANCE_ACTIVATE_DISKS(sftp)

2014-03-17 14:45:05,543: ganeti-masterd pid=3756/Jq4/Job150090 INFO Op 1/1: opcode INSTANCE_ACTIVATE_DISKS(sftp) waiting for locks

2014-03-17 14:45:05,873: ganeti-masterd pid=3756/Jq4/Job150090/I_ACTIVATE_DISKS WARNING Could not prepare block device disk/0 on node wrn-vm1.example.com (is_primary=False, pass=1): Error while assembling disk: The file /proc/drbd cannot be opened, check if the module is loaded ([Errno 2] No such file or directory: '/proc/drbd')

2014-03-17 14:45:07,397: ganeti-masterd pid=3756/Jq4/Job150090 ERROR Op 1/1: Caught exception in INSTANCE_ACTIVATE_DISKS(sftp)

    raise errors.OpExecError("Cannot activate block devices")

OpExecError: Cannot activate block devices

2014-03-17 14:45:07,902: ganeti-masterd pid=3756/ClientReq1 INFO New job with id 150091, summary: INSTANCE_ACTIVATE_DISKS(airfoo)

2014-03-17 14:45:08,027: ganeti-masterd pid=3756/Jq5/Job150091 INFO Op 1/1: opcode INSTANCE_ACTIVATE_DISKS(airfoo) waiting for locks

2014-03-17 14:45:08,433: ganeti-masterd pid=3756/Jq5/Job150091/I_ACTIVATE_DISKS WARNING Could not prepare block device disk/0 on node wrn-vm1.example.com (is_primary=False, pass=1): Error while assembling disk: The file /proc/drbd cannot be opened, check if the module is loaded ([Errno 2] No such file or directory: '/proc/drbd')

2014-03-17 14:45:09,125: ganeti-masterd pid=3756/Jq5/Job150091 ERROR Op 1/1: Caught exception in INSTANCE_ACTIVATE_DISKS(airfoo)

    raise errors.OpExecError("Cannot activate block devices")

OpExecError: Cannot activate block devices

2014-03-17 14:45:09,579: ganeti-masterd pid=3756/ClientReq8 INFO New job with id 150092, summary: INSTANCE_ACTIVATE_DISKS(netdot.example.com)

2014-03-17 14:45:09,697: ganeti-masterd pid=3756/Jq6/Job150092 INFO Op 1/1: opcode INSTANCE_ACTIVATE_DISKS(netdot.example.com) waiting for locks

2014-03-17 14:45:10,004: ganeti-masterd pid=3756/Jq6/Job150092/I_ACTIVATE_DISKS WARNING Could not prepare block device disk/0 on node wrn-vm1.example.com (is_primary=False, pass=1): Error while assembling disk: The file /proc/drbd cannot be opened, check if the module is loaded ([Errno 2] No such file or directory: '/proc/drbd')

2014-03-17 14:45:10,673: ganeti-masterd pid=3756/Jq6/Job150092 ERROR Op 1/1: Caught exception in INSTANCE_ACTIVATE_DISKS(netdot.example.com)

    raise errors.OpExecError("Cannot activate block devices")

OpExecError: Cannot activate block devices

So my theory of what happened is:

* drbd module was not present at boot time

* ganeti failed to activate the disks

* ganeti set the flag disks_active to false (persistently)

* this prevented ganeti from ever trying to activate the disks again, e.g. when I restarted ganeti or rebooted the box

If that assessment is correct, the fact I now have drbd in /etc/modules should prevent this in future.

It's strange that this problem didn't occur when rebooting the non-master node (wrn-vm2) though. Something must have triggered the loading of the drbd module. That machine was rebooted at 14:32, and master-daemon.log on wrn-vm1 shows INSTANCE_ACTIVATE_DISK events at 14:35, with no errors.

Regards,

Brian.

[Thomas Thrainer]

Hi Brian,

First to what disks active means: Usually if an instance is down, its disk are not active. This means that Ganeti cleans up the block devices for the disks, in the case of DRBD that's /dev/drbd<x>, but this could be different for other disk templates. For DRBD, this means as well that the mirroring between primary and secondary is stopped when the instance is down.

Disks are either activated when the instance starts or when you explicitly activate them with 'gnt-instance activate-disks'. The latter command is useful if you want to mount the block device and perform some maintenance on the disks.

So in a nutshell, an activated disk is a disk for which the block device is created up to the point that a hypervisor can use it for a VM.

This sounds very likely. I think to fix this there are some steps which should get performed:

 * I guess ganeti-watcher runs as part of a cron job for you. You should set up a warning/error for when it fails (which it should have done for your case)

 * 'gnt-cluster verify' or 'gnt-cluster verify-disks' should report an error if an instance is running but appears to have no active disks. I've filed an issue [0] for that.

Overall, I think it's OK for Ganeti to try once (automatically) to active the disks again and then stop trying. But it would have been useful for you to get the feedback from the watcher that it failed, which you could have gotten with proper alerting. In every case, gnt-cluster verify should have complained about the problem.

Thanks for the detailed analysis,

Thomas

 

If that assessment is correct, the fact I now have drbd in /etc/modules should prevent this in future.

It's strange that this problem didn't occur when rebooting the non-master node (wrn-vm2) though. Something must have triggered the loading of the drbd module. That machine was rebooted at 14:32, and master-daemon.log on wrn-vm1 shows INSTANCE_ACTIVATE_DISK events at 14:35, with no errors.

Regards,

Brian.

[0]: https://code.google.com/p/ganeti/issues/detail?id=761

--

Thomas Thrainer | Software Engineer | thom...@google.com | 

Google Germany GmbH

Dienerstr. 12

80331 München

Registergericht und -nummer: Hamburg, HRB 86891
Sitz der Gesellschaft: Hamburg
Geschäftsführer: Graham Law, Christine Elizabeth Flores

[candlerb]

Thank you - I see you have created https://code.google.com/p/ganeti/issues/detail?id=761

The reason I got into this state was my fault. Instead of adding to /etc/modules like the installation tutorial says, I created /etc/modprobe.d/drbd.conf. This was so that "modprobe drbd" would automatically use the right options, and also in case /etc/modules was overwritten by an upgrade.

However, that didn't make it load automatically at boot. You need to put the module in /etc/modules, or in one of the modules-load.d directories listed in /etc/init.d/kmod, for that to happen.

Regards,

Brian.