In letzter Zeit immer wieder hängende Backups von ceph -> nfs

[fips]

Hallo Leute,

ich habe vor ein paar Wochen von 5.1 auf 5.2 aktualisiert und seitdem bleibt mir nun alle 1-2 Tage ein Backup "hängen".
Das Procedere:
In der Früh schau ich mir die Logs an und sehe "backup failed: multiple problems" dann verbinde ich mich mit dem Cluster und sehe das ein Backup Task nach wie vor läuft.
Wenn ich mir der Task anschaue:

INFO: Starting Backup of VM 208 (lxc)
INFO: status = running
INFO: CT Name: www.example.com
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: create storage snapshot 'vzdump'
/dev/rbd7
INFO: creating archive '/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_05-23_19_27.tar.lzo'

Dann klicke ich auf stop und erhalte folgenden Output:

INFO: remove vzdump snapshot
rbd: sysfs write failed
can't unmap rbd volume vm-208-disk-1: rbd: sysfs write failed
ERROR: Backup of VM 208 failed - command 'set -o pipefail && tar cpf - --totals --one-file-system -p --sparse --numeric-owner --acls --xattrs '--xattrs-include=user.*' '--xattrs-include=security.capability' '--warning=no-file-ignored' '--warning=no-xattr-write' --one-file-system '--warning=no-file-ignored' '--directory=/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_05-23_19_27.tmp' ./etc/vzdump/pct.conf '--directory=/mnt/vzsnap0' --no-anchored '--exclude=lost+found' --anchored '--exclude=./tmp/?*' '--exclude=./var/tmp/?*' '--exclude=./var/run/?*.pid' ./ | lzop >/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_05-23_19_27.tar.dat' failed: interrupted by signal

Anschließend ist zum einen der CT immer locked (die wird von mir händisch unlocked) und zum anderen wenn ich wieder ein Backup machen will:

INFO: starting new backup job: vzdump 208 --remove 0 --mode snapshot --compress lzo --node ceph7 --storage Backup
INFO: Starting Backup of VM 208 (lxc)
INFO: status = running
INFO: CT Name: www.example.com
INFO: found old vzdump snapshot (force removal)
rbd: sysfs write failed
can't unmap rbd volume vm-208-disk-1: rbd: sysfs write failed
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: create storage snapshot 'vzdump'
snapshot create failed: starting cleanup
no lock found trying to remove 'backup'  lock
ERROR: Backup of VM 208 failed - rbd snapshot 'vm-208-disk-1' error: rbd: failed to create snapshot: (17) File exists
INFO: Backup job finished with errors
TASK ERROR: job errors

Also entferne ich den Snapshot mittels:

rbd snap rm ceph/vm-208-disk-1@vzdump

Und versuche das Backup nochmals durchzuführen aber leider:

INFO: starting new backup job: vzdump 208 --node ceph7 --mode snapshot --compress lzo --remove 0 --storage Backup
INFO: Starting Backup of VM 208 (lxc)
INFO: status = running
INFO: CT Name: www.example.com
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: create storage snapshot 'vzdump'
mount: /dev/rbd7 is already mounted or /mnt/vzsnap0 busy
umount: /mnt/vzsnap0/: not mounted
command 'umount -l -d /mnt/vzsnap0/' failed: exit code 32
ERROR: Backup of VM 208 failed - command 'mount -o ro,noload /dev/rbd7 /mnt/vzsnap0//' failed: exit code 32
INFO: Backup job finished with errors
TASK ERROR: job errors

Also prüfe ich noch wer das rbd gemapped hat mit:

rbd status ceph/vm-208-disk-1

und erhalte:

Watchers:
    watcher=172.30.3.27:0/2318717155 client.39789856 cookie=18446462598732840961
    watcher=172.30.3.27:0/2318717155 client.39789856 cookie=18446462598732840986

Das ist die Ceph IP des Nodes auf dem ich Backup machen wollte...

Mein Workaround ist dann: CT migrieren und Node neustarten, dann klappt es wieder für 1-2 Tage...
Ich hoffe das Problem ist euch irgendwie bekannt und ihr könnt mir helfen.

Danke

 

[Alwin]

/dev/rbd7

Beim Abbruch des Backups scheint das Device noch gemountet zu bleiben. Damit schlägt dann ein weiterer Versuch fehl.

Deine Beschreibung ist von einem laufenden Backup, das manuell abgebrochen wird. Die Frage ist doch, warum schlagen ca. alle 1-2 Tage die Backups der Container fehl? Was ist den die Fehlermeldung die bei "backup failed: multiple problems" zu sehen ist?

 

[fips]

Genau, nun das Backup wird in der Nacht um 23:15 gestartet und sollte pro CT eigentlich in 1-2 Minuten fertig sein.
In dem von mir beschriebene Fall ist in der Früh der Backuptask immer noch nicht fertig, er hängt einfach. Ich sehe leider nicht genau woran es scheitert.
Das einzige das in der Mail bei "backup failed: multiple problems ist

can't aquire lock '/var/run/vzdump.lock' - got timeout

 

[Alwin]

Im Task Log sollte ein ganzer Auszug des Backups vorhanden sein. Der Timeout passiert, weil ein Backup schon einen Lock hält. Sind es immer die selben Container die fehlschlagen? Wie schaut die vmid.conf der Container aus?

 

[fips]

Leider nur das hier:

INFO: trying to get global lock - waiting...
ERROR: can't aquire lock '/var/run/vzdump.lock' - got timeout
TASK ERROR: got unexpected control message:

Ich habe das Gefühl das es häufiger beim CT 208 ist, aber ganz sicher auch schon bei anderen.
Den 208er hab ich auch schon komplett gelöscht und aus dem Backup wiederhergestellt.
208.conf:

arch: amd64
cores: 2
hostname: www.example.com
memory: 2048
nameserver: 10.0.10.3
net0: name=eth0,bridge=vmbr1,gw=10.0.10.3,hwaddr=DE:EC:D9:98:A9:AB,ip=10.0.10.97/24,tag=10,type=veth
ostype: debian
rootfs: ceph_ct:vm-208-disk-1,size=20G
searchdomain: example.it
swap: 4096

 

[Alwin]

Laufen auf dem System mehrere Backup Jobs gleichzeitig? Wie schaut der Inhalt von /etc/pve/vzdump.cron aus?

 

[fips]

Ja:

15 23 * * 1,2,3,4,5,7 root vzdump 101 105 111 113 115 201 202 204 205 207 208 209 210 215 216 401 211 611 212 213 219 218 217 104 103 206 221 220 102 116 --mailnotification always --quiet 1 --compress lzo --mailto admin@example.com --mode snapshot --storage Backup
15 23 * * 1,2,3,4,5,7 root vzdump 108 110 601 602 603 604 605 114 609 608 610 107 116 100 --mailnotification always --mailto admin@example.com --mode snapshot --storage OffsiteBackup --compress lzo --quiet 1

Ich kann auch schon deine Antwort Voraussagen: Teil die Backups auf mehrere Jobs auf ;-)

 

[Alwin]

Die Backup Jobs blockieren sich, der erste Job brauch länger als der zweite Job warten kann (timeout). Auf einer Node werden die Jobs immer seriell abgearbeitet. Ändere die Zeit des zweiten Jobs nach hinten, am besten wenn der erste Fertig ist.

 

[fips]

Schade, ich wollte schon fast den Thread als "Solved" markieren und sagen alles in Ordnung, aber leider ist es heute wieder passiert.
Diesmal mit einem anderen CT auf einem anderen Node als oben in den Logs aber mit exakt dem gleichen Fehlerbild.
Die beiden Backupjobs im vzdump.cron wurden um 2 Stunden auseinander gesetzt.
Der Zeitstempel im hängenden Backup zeigt eine Uhrzeit zu der kein anderes Backup oder etwas anderes großes (Wartung, große Filetransfer, sonstige Netzwerkauslastung) passiert ist.

 

[Alwin]

Es geht ja um die Dauer. Der erste Job holt sich das Lock und gibt es erst nach Abschluss wieder her. Ein zweiter Job wartet bis zu 3h auf die Freigabe, bekommt er die nicht dann bricht er ab. Dies gilt pro Node, sprich mehrere Jobs auf unterschiedlichen Nodes können gleichzeitig laufen.

 

[fips]

ok gut, aber wie kann ich prüfen warum der erste Job hängt??
Die einzelnen CT sollten ja in 1-2 Minuten gesichert sein, wenn er dann hängt läuft er in den Timeout.

 

[Alwin]

Die einzelnen CT sollten ja in 1-2 Minuten gesichert sein, wenn er dann hängt läuft er in den Timeout.

Ich denke, das Backup eines CT dauert schon länger als 1-2 Minuten. Das sollte auch im Log sichtbar sein. Ansonsten kann der Job auch auf der CLI von Hand ausgeführt werden (Zeile aus dem Cron). Dann heißt es, schauen was passiert, Server und Backup überwachen.

 

[fips]

Das Backup des (heute hängenden) 209er CT hat vorgestern exact 00:00:59 gedauert, konnte das der "Backup Status" Mail entnehmen.

 

[Alwin]

Ansonsten kann der Job auch auf der CLI von Hand ausgeführt werden (Zeile aus dem Cron). Dann heißt es, schauen was passiert, Server und Backup überwachen.

Dann bleibt nur noch.

 

[fips]

Hab es nun auf 2 CTs eingegrenzt.
Logs zeigen überhaupt nichts an, weder Ceph noch Host selbst.
2 CTs sind nun in einem eigenen Backup Task.
Beide CTs haben HA aktiviert (soll auch so bleiben), dann ist natürlich bei Backup kein Mode:stop möglich.

Kann ich das vielleicht irgendwie umgehen? Sprich CTs mit aktiviertem HA und Backup mode stop?

 

[Alwin]

Beide CTs haben HA aktiviert (soll auch so bleiben), dann ist natürlich bei Backup kein Mode:stop möglich.

Bei den anderen ist kein HA aktiviert? Tritt das selbe auf, wenn bei einem anderen Container HA aktiviert wird?

Kann ich das vielleicht irgendwie umgehen? Sprich CTs mit aktiviertem HA und Backup mode stop?

Nein. Der 'stop mode' fährt den Container runter und macht dann ein Backup. RBD kann Snapshots, da sollte der 'suspend mode' ausreichend sein, um Filesystem Konsistenz zu erreichen.

 

[fips]

HA ist auch bei anderen CTs und VMs aktiviert.

Ich habe den "suspend mode" schon probiert bekomme dann aber dieses Ergebnis und es bricht ab:

INFO: starting new backup job: vzdump 208 209 --quiet 1 --mailto admin@example.com --mailnotification always --mode suspend --storage Backup --compress lzo
INFO: Starting Backup of VM 208 (lxc)
INFO: status = running
INFO: backup mode: suspend
INFO: ionice priority: 7
INFO: CT Name: www.example.com
INFO: temporary directory is on NFS, disabling xattr and acl support, consider configuring a local tmpdir via /etc/vzdump.conf
INFO: starting first sync /proc/5851/root// to /mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/." failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/archiv" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/bzcmp" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/bzegrep" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/bzfgrep" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/bzless" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/dnsdomainname" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/domainname" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/lessfile" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/lsmod" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/mt" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/nc" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/netcat" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/nisdomainname" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/pidof" failed: Operation not permitted (1)
INFO: rsync: chown "/mnt/pve/Backup/dump/vzdump-lxc-208-2018_06_26-20_30_03.tmp/bin/rbash" failed: Operation not permitted (1)
usw...

 

[Alwin]

INFO: temporary directory is on NFS, disabling xattr and acl support, consider configuring a local tmpdir via /etc/vzdump.conf

Der "Mode" sollte da keinen Unterschied machen. Am besten das 'tmpdir' auf ein lokales Storage legen, dann sollte es passen.

 

[fips]

Ich kann es nicht auf ein lokales Storage legen, da die Node HD ziemlich klein ist.
Den Fehler konnte ich nun mit einem 3. CT reproduzieren und erhalte im syslog des Node folgende Meldungen:

Jul  1 12:29:01 ceph7 cron[2004]: (*system*vzdump) RELOAD (/etc/cron.d/vzdump)
Jul  1 12:29:01 ceph7 CRON[15146]: (root) CMD (vzdump 204 --mailnotification always --storage Backup --mode snapshot --compress lzo --quiet 1)
Jul  1 12:29:01 ceph7 vzdump[15147]: <root@pam> starting task UPID:ceph7:00003B2C:0000B874:5B38ACED:vzdump::root@pam:
Jul  1 12:29:01 ceph7 vzdump[15148]: INFO: starting new backup job: vzdump 204 --mode snapshot --compress lzo --mailnotification always --quiet 1 --storage Backup
Jul  1 12:29:01 ceph7 vzdump[15148]: INFO: Starting Backup of VM 204 (lxc)
Jul  1 12:30:00 ceph7 systemd[1]: Starting Proxmox VE replication runner...
Jul  1 12:30:01 ceph7 systemd[1]: Started Proxmox VE replication runner.
Jul  1 12:30:25 ceph7 kernel: [  555.666877] kernel BUG at drivers/block/rbd.c:4035!
Jul  1 12:30:25 ceph7 kernel: [  555.667381] CPU: 0 PID: 312 Comm: kworker/0:2 Tainted: P           O     4.15.17-1-pve #1
Jul  1 12:30:25 ceph7 kernel: [  555.667457] Workqueue: rbd rbd_queue_workfn [rbd]
Jul  1 12:30:25 ceph7 kernel: [  555.667511] RSP: 0018:ffffa93d07477e18 EFLAGS: 00010286
Jul  1 12:30:25 ceph7 kernel: [  555.667570] RDX: 0000000000000000 RSI: 0000000000000082 RDI: ffff8b8e1f616490
Jul  1 12:30:25 ceph7 kernel: [  555.667701] FS:  0000000000000000(0000) GS:ffff8b8e1f600000(0000) knlGS:0000000000000000
Jul  1 12:30:25 ceph7 kernel: [  555.667819]  ? __schedule+0x3eb/0x880
Jul  1 12:30:25 ceph7 kernel: [  555.670238]  ? process_one_work+0x400/0x400
Jul  1 12:30:25 ceph7 kernel: [  555.676155] RIP: rbd_queue_workfn+0x462/0x4f0 [rbd] RSP: ffffa93d07477e18

Jul  1 13:16:01 ceph7 cron[2023]: (*system*vzdump) RELOAD (/etc/cron.d/vzdump)
Jul  1 13:16:01 ceph7 CRON[15048]: (root) CMD (vzdump 204 --mailnotification always --compress lzo --quiet 1 --mode snapshot --storage Backup)
Jul  1 13:16:02 ceph7 systemd[1]: Started Proxmox VE replication runner.
Jul  1 13:16:02 ceph7 vzdump[15050]: <root@pam> starting task UPID:ceph7:00003B3F:0000C8AD:5B38B7F2:vzdump::root@pam:
Jul  1 13:16:02 ceph7 vzdump[15167]: INFO: starting new backup job: vzdump 204 --quiet 1 --storage Backup --mode snapshot --mailnotification always --compress lzo
Jul  1 13:16:02 ceph7 vzdump[15167]: INFO: Starting Backup of VM 204 (lxc)
Jul  1 13:17:00 ceph7 systemd[1]: Starting Proxmox VE replication runner...
Jul  1 13:17:01 ceph7 CRON[15884]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jul  1 13:17:02 ceph7 systemd[1]: Started Proxmox VE replication runner.
Jul  1 13:17:22 ceph7 kernel: [  593.344592] 
Jul  1 13:17:22 ceph7 kernel: [  593.344592] Assertion failure in rbd_queue_workfn() at line 4035:
Jul  1 13:17:22 ceph7 kernel: [  593.344592] 
Jul  1 13:17:22 ceph7 kernel: [  593.344592]     rbd_assert(op_type == OBJ_OP_READ || rbd_dev->spec->snap_id == CEPH_NOSNAP);
Jul  1 13:17:22 ceph7 kernel: [  593.344592] 
Jul  1 13:17:22 ceph7 kernel: [  593.344701] kernel BUG at drivers/block/rbd.c:4035!
Jul  1 13:17:22 ceph7 kernel: [  593.344760] Modules linked in: veth rbd libceph nfsv3 nfs_acl nfs lockd grace fscache ip_set ip6table_filter ip6_tables xfs iptable_filter softdog nfnetlink_log nfnetlink dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio libcrc32c intel_rapl sb_edac x86_pkg_temp_thermal intel_powerclamp coretemp ipmi_ssif kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc aesni_intel aes_x86_64 crypto_simd glue_helper mgag200 cryptd ttm drm_kms_helper snd_pcm snd_timer intel_cstate drm snd soundcore fb_sys_fops syscopyarea sysfillrect intel_rapl_perf serio_raw sysimgblt pcspkr hpilo zfs(PO) ioatdma lpc_ich shpchp zunicode(PO) zavl(PO) icp(PO) ipmi_si ipmi_devintf ipmi_msghandler mac_hid acpi_power_meter zcommon(PO) znvpair(PO) spl(O) vhost_net vhost tap ib_iser rdma_cm iw_cm ib_cm
Jul  1 13:17:22 ceph7 kernel: [  593.345250] Hardware name: HP ProLiant DL360e Gen8, BIOS P73 08/02/2014
Jul  1 13:17:22 ceph7 kernel: [  593.345343] RSP: 0018:ffffb530cdf33e18 EFLAGS: 00010286
Jul  1 13:17:22 ceph7 kernel: [  593.345467] R10: 00000000000001fb R11: 00000000ffffffff R12: ffff92a038794480
Jul  1 13:17:22 ceph7 kernel: [  593.345597] CR2: 000055caee76d000 CR3: 0000000b0420a001 CR4: 00000000000606e0
Jul  1 13:17:22 ceph7 kernel: [  593.345698]  worker_thread+0x4b/0x420
Jul  1 13:17:22 ceph7 kernel: [  593.346910]  ? kthread_create_worker_on_cpu+0x70/0x70
Jul  1 13:17:22 ceph7 kernel: [  593.350410]  ret_from_fork+0x35/0x40
Jul  1 13:17:22 ceph7 kernel: [  593.355187] ---[ end trace e95ebe6c2b65f0b2 ]---

Jul  1 13:38:01 ceph7 CRON[15742]: (root) CMD (vzdump 204 --storage Backup --mode snapshot --compress lzo --quiet 1 --mailnotification always)
Jul  1 13:38:02 ceph7 systemd[1]: Started Proxmox VE replication runner.
Jul  1 13:38:02 ceph7 vzdump[15743]: <root@pam> starting task UPID:ceph7:00003DBC:0000C898:5B38BD1A:vzdump::root@pam:
Jul  1 13:38:02 ceph7 vzdump[15804]: INFO: starting new backup job: vzdump 204 --mailnotification always --mode snapshot --quiet 1 --storage Backup --compress lzo
Jul  1 13:38:02 ceph7 vzdump[15804]: INFO: Starting Backup of VM 204 (lxc)
Jul  1 13:38:04 ceph7 kernel: [  515.055266] rbd: rbd3: capacity 10737418240 features 0x1
Jul  1 13:39:00 ceph7 systemd[1]: Starting Proxmox VE replication runner...
Jul  1 13:39:01 ceph7 systemd[1]: Started Proxmox VE replication runner.
Jul  1 13:39:23 ceph7 kernel: [  594.668746]  ib_core sunrpc iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ip_tables x_tables autofs4 btrfs xor zstd_compress raid6_pq psmouse ahci libahci igb hpsa i2c_algo_bit scsi_transport_sas ixgbe dca ptp pps_core mdio
Jul  1 13:39:23 ceph7 kernel: [  594.668888] Hardware name: HP ProLiant DL360e Gen8, BIOS P73 08/02/2014
Jul  1 13:39:23 ceph7 kernel: [  594.668954] RIP: 0010:rbd_queue_workfn+0x462/0x4f0 [rbd]
Jul  1 13:39:23 ceph7 kernel: [  594.669006] RAX: 0000000000000086 RBX: ffff8bda86bf7000 RCX: 0000000000000006
Jul  1 13:39:23 ceph7 kernel: [  594.669071] RBP: ffffb27506273e60 R08: 0000000000000000 R09: 0000000000000548
Jul  1 13:39:23 ceph7 kernel: [  594.669170] FS:  0000000000000000(0000) GS:ffff8bdadf600000(0000) knlGS:0000000000000000
Jul  1 13:39:23 ceph7 kernel: [  594.669267] Call Trace:
Jul  1 13:39:23 ceph7 kernel: [  594.669330]  worker_thread+0x4b/0x420
Jul  1 13:39:23 ceph7 kernel: [  594.672867]  ? kthread_create_worker_on_cpu+0x70/0x70
Jul  1 13:39:23 ceph7 kernel: [  594.677628] RIP: rbd_queue_workfn+0x462/0x4f0 [rbd] RSP: ffffb27506273e18

 

[Alwin]

Wie ist das Cluster aufgebaut, Hardware und Konfiguration?