Ceph OSDs beenden sich

[Ingo S]

Hallo miteinander

Seit gestern haben wir ein merkwürdiges Phänomen. Per Zufall habe ich gesehen, dass in unserem Cluster 3 OSDs auf verschiedenen Servern Down und Out waren. (Normalerweise bekommen wir da eine Alarmierung...) Ich habe diese dann mit systemctl start ceph-osd@<num> wieder gestartet. Das hat problemlos geklappt.
Heute das gleiche Spiel, es ist wieder eine OSD Down und Out.
Darum habe ich mir mal die Logs angesehen, für mich steht da allerdings nichts offensichtlich problematisches drin.
Auszug aus den Logs die OSD.10 betreffen (zur Zeit Down&Out)

2019-09-19 19:35:30 vm-1 systemd[1]: ceph-osd@10.service: Failed with result 'signal'.
2019-09-19 19:35:30 vm-1 systemd[1]: ceph-osd@10.service: Main process exited, code=killed, status=6/ABRT
2019-09-19 19:35:31 vm-1 systemd[1]: ceph-osd@10.service: Service RestartSec=100ms expired, scheduling restart.
2019-09-19 19:35:31 vm-1 systemd[1]: ceph-osd@10.service: Scheduled restart job, restart counter is at 1.
2019-09-19 19:35:31 vm-1 systemd[1]: Starting Ceph object storage daemon osd.10...
2019-09-19 19:35:31 vm-1 systemd[1]: Started Ceph object storage daemon osd.10.
2019-09-19 19:35:31 vm-1 systemd[1]: Stopped Ceph object storage daemon osd.10.
2019-09-19 19:35:38 vm-1 ceph-osd[844177]: 2019-09-19 19:35:38.435 7f9294b73f80 -1 osd.10 79735 log_to_monitors {default=true}
2019-09-19 19:35:38 vm-1 ceph-osd[844177]: 2019-09-19 19:35:38.447 7f928d898700 -1 osd.10 79735 set_numa_affinity unable to identify public interface 'bond2' numa node: (2) No such file or directory
2019-09-19 19:36:06 vm-1 systemd[1]: ceph-osd@10.service: Main process exited, code=killed, status=6/ABRT
2019-09-19 19:36:53 vm-1 ceph-osd[844605]: 2019-09-19 19:36:53.916 7fa84c089700 -1 osd.10 79743 get_health_metrics reporting 18 slow ops, oldest is osd_op(client.208422084.0:87526810 1.36b 1.132b5f6b (undecoded) ondisk+read+known_if_redirected e79743)
2019-09-19 19:36:54 vm-1 ceph-osd[844605]: 2019-09-19 19:36:54.880 7fa84c089700 -1 osd.10 79743 get_health_metrics reporting 18 slow ops, oldest is osd_op(client.208422084.0:87526810 1.36b 1.132b5f6b (undecoded) ondisk+read+known_if_redirected e79743)
2019-09-19 19:36:55 vm-1 ceph-osd[844605]: 2019-09-19 19:36:55.900 7fa84c089700 -1 osd.10 79743 get_health_metrics reporting 11 slow ops, oldest is osd_op(client.208422084.0:87526810 1.36b 1.132b5f6b (undecoded) ondisk+read+known_if_redirected e79743)
2019-09-19 19:36:55 vm-3 ceph-osd[28056]: 2019-09-19 19:36:55.977 7fb7a6fa8700 -1 osd.26 79743 heartbeat_check: no reply from 192.168.15.1:6824 osd.10 since back 2019-09-19 19:36:30.528227 front 2019-09-19 19:36:30.528332 (oldest deadline 2019-09-19 19:36:55.228216)

Außerdem hatte ich gerade beim starten der osd.10 folgende Meldung in der Ceph Übersicht in der PMX Gui:

osd.10 legacy statfs reporting detected, suggest to run store repair to get consistent statistic reports

Kann mir da jemand auf die Sprünge helfen was los ist?

Außerdem fehlt in der PMX Gui in der Ceph Übersicht der Hinweis das eine oder mehrere OSDs down&out sind. Es erscheint dort im Moment gar keine Meldung bei uns.
Irgendwas hat sich wohl mit Ceph geändert, so das auch unsere Alarmierung nicht mehr anschlägt, wenn Ceph einen Fehler meldet. Da muss ich dringend ran und den Fehler finden.

 

[dcsapak]

was sagt denn 'ceph status' in dem moment wenn die osd down&out sind?

 

[Ingo S]

Da steht dann x osds down, x osds out, das ist korrekt.
Leider habe ich vorhin die osds gestartet, so das ich gerade nicht mehr im Detail gucken kann.

Also es erscheinen Fehlermeldungen in der Übersicht von Ceph, nur dachte ich, das eben dort vor dem Update auch direkt ne Warnung angezeigt wurde wenn ne OSD down&out ist:


Heute Morgen waren übrigens die gleichen OSDs wieder down&out. Es sieht so aus als wären es immer die gleichen OSDs die sich verabschieden.
S.M.A.R.T scheint unaufällig zu sein. Bei S.M.A.R.T Fehlern bekommen wir ja eine Mail, und da war nichts.

 

[dcsapak]

2019-09-19 19:35:38 vm-1 ceph-osd[844177]: 2019-09-19 19:35:38.447 7f928d898700 -1 osd.10 79735 set_numa_affinity unable to identify public interface 'bond2' numa node: (2) No such file or directory

kann das vielleicht ein problem sein? existiert bond2 ? ist das das interface für ceph?

die warnung 'mon vm-6 is low on available space' würde ich auch mal beheben
wegen

osd.10 legacy statfs reporting detected, suggest to run store repair to get consistent statistic reports

siehe https://forum.proxmox.com/threads/osd-legacy-statfs-reporting-detected.57175/

auch was wird angezeigt wenn du auf das 'i' klickst, bei 'on 8 OSD(s)' ?

 

[Ingo S]

Ja, also nach dem Speicherplatz auf VM-6 habe ich bereits gesehen, das ist noch nicht kritisch. Liegt daran, das da gerade ein paar Kernel und ein paar updates gecached rumliegen. Es sind noch 2GB frei, sollte reichen, bis ich aufgeräumt habe.

Wegen der legacy statfs Meldung: Jipp schon angegangen das Problem. Ich habe auf allen OSDs den repair ausgeführt, war alles erfolgreich. Die Meldung für VM-6 bleibt jedoch bestehen *kopfkratz*

bond2 ist das interface für ceph. Das hast du korrekt erfasst.
bond2 existiert und funktioniert auch. Das Interface wird überwacht, bzw. der Port auf dem Switch. Würde der offline gehen, gäbe es eine Warnmeldung von unserem Monitoring. Extern (Verkabelung, VLAN und Switch) scheint alles sauber zu sein.

OSD.3 liegt auf VM-2 und OSD.10 liegt auf VM-1

 

[dcsapak]

etwas längere auszüge aus den relevanten logs und aus dem dmesg wären noch interessant (die erste zeile vom log im ersten post scheint schon zu spät zu sein)
auch die ceph logs können helfen (/var/log/ceph)

 

[Ingo S]

Ich hab dir jetzt einfach mal den kompletten Log Auszug ab 19:23:00 angefügt, dann hast du 2min mehr.

Habs als Datei eingefügt, ist sonst zu lang für einen Post.

Ich muss dazu sagen: Wir schicken das Journal an einen Log Server (Graylog) Leider war das neue rsyslog vom Timestamp anders konfiguriert, so das nach den Sekunden die Millisekunden verloren gegangen sind. Deshalb sind Vorgänge die innerhalb einer Sekunde abgelaufen sind, unter umständen nicht in der richtigen Reihenfolge. Das habe ich aber mittlerweile behoben. Neuere Logs sind wieder auf Millisekunden genau, so das sie richtig sortiert sein sollten.

PS: Der Inhalt von /var/log/ceph scheint nicht im Journal und in rsyslog aufzutauchen. Kann man das irgendwie so "manipulieren" das wir den Inhalt auch in den Log Server werfen? Am besten via rsyslog...

 

[dcsapak]

ich seh da einige disk errors:

"2019-09-19T17:35:28.000Z","vm-1","vm-1 kernel: [3322809.017346] print_req_error: critical medium error, dev sde, sector 2363722768 flags 0"

"2019-09-19T17:35:28.000Z","vm-1","vm-1 kernel: [3322809.017340] sd 0:0:3:0: [sde] tag#4884 Add. Sense: Unrecovered read error"
...

 

[Ingo S]

Japp die Disk wird demnächst ausgetauscht. Die Disk wo OSD.3 drauf läuft ist aber in Ordnung, und auch andere OSDs hatten sich letztens spontan beendet, ohne das uns I/O Error aufgefallen wären.
Interessanterweise finde ich keine Log Einträge der anderen OSDs.