chr.istoph, der Blog

Wir haben das Problem, dass wir Server haben die einfach Abstürzen ohne einem Meldung im /var/log/kernel.log zu hinterlassen. Wir haben nun das Kernel Loggin Modul „netconsole“ verwendet, um die Logzeilen direkt vom Kernel via UDP verschicken zu können.

Dafür würde auf Empfänger und Sender Seite folgendes eingerichtet.

Empfänger:
Möchte man das ganze nicht Reboot fest machen und für mehrere Ports/Server einrichten kann man auch einfach den socat Befehl von Hand ausführen. Hier wird nun beschreiben wie wir einen dynamischer Systemd Service verwenden.

/etc/systemd/system/netconsole@.service

[Unit]
Description=netconsole
After=network.target remote-fs.target nss-lookup.target
PartOf=netconsole.service

[Service]
Type=simple
Environment="LANG=C"
ExecStart=/usr/bin/socat OPEN:/var/log/netconsole-%i,append udp4-listen:%i,reuseaddr,fork

Restart=always

[Install]
WantedBy=multi-user.target

/etc/systemd/system/netconsole.service

[Unit]
Description=netconsole
Wants=netconsole@10001.service netconsole@10002.service

[Service]
RemainAfterExit=yes
ExecStart=/bin/true

[Install]
WantedBy=multi-user.target

An dieser Stelle kann das der Punkt „Wants“ beliebig anpassen werden. Der Zahlen wert hinter dem @xxxx ist der übergebene Port.

Abschließend müssen das systemd noch aktiviert werden:

systemctl enable netconsole.service
systemctl start netconsole.service
systemctl status netconsole.service
● netconsole.service - netconsole
   Loaded: loaded (/etc/systemd/system/netconsole.service; enabled; vendor preset: enabled)
   Active: active (exited) since Mo 2017-05-08 10:54:23 CEST; 4s ago
  Process: 11124 ExecStart=/bin/true (code=exited, status=0/SUCCESS)
 Main PID: 11124 (code=exited, status=0/SUCCESS)

Mai 08 10:54:23 server systemd[1]: Started netconsole.

Sender:
/etc/modprobe.d/netconsole.conf

options netconsole netconsole=10000@192.168.0.1/br0,10001@192.168.0.9/00:00:00:00:00

Dann kann das Kernel Modul geladen werden:

modprobe netconsole

Möchte man das ganze reboot fest machen, muss das Modul in /etc/modules eingetragen werden:

echo "netconsole" >> /etc/modules

Zum Testen erzeugt folgender Befehl einen Eintrag im Kernel log, als auch auf dem Empfänger Server:

echo h > /proc/sysrq-trigger

Update 17.05.2017: für die Verwendung von CentOS7 wurde das Script von nc auf socat umgebaut.

Einige zeit lang hat es mich genervt das es Spam Server gibt, die von Domains verschicken die ausschließlich in Panama Register sind. Die sind mittlerweile so dreist das sie Spam score werte erreichen, die weit negativ sind, da bei ihnen alles stimmt. Aber eine Gemeinsamkeit haben Sie, neben dem whois Eintag das Sie aus Panama stammen, auch noch. Sie haben alle FreeDNS Einträge von Namecheap Inc. Ops die kann man getrost droppen:

In der /etc/postfix/main.cf habe ich den smtpd_recipient_restrictions folgende Eintrag angefügt:

smtpd_recipient_restrictions =
check_sender_ns_access hash:/etc/postfix/blacklist_ns.cf 

Dann habe ich die Datei /etc/postfix/blacklist_ns.cf angelegt:

dns1.registrar-servers.com REJECT Sender-Domain is registered at WhoisGuard Panama / Namecheap Inc
dns2.registrar-servers.com REJECT Sender-Domain is registered at WhoisGuard Panama / Namecheap Inc
dns3.registrar-servers.com REJECT Sender-Domain is registered at WhoisGuard Panama / Namecheap Inc
dns4.registrar-servers.com REJECT Sender-Domain is registered at WhoisGuard Panama / Namecheap Inc
dns5.registrar-servers.com REJECT Sender-Domain is registered at WhoisGuard Panama / Namecheap Inc

Anschließend habe ich die hash table erstellt:

postmap /etc/postfix/blacklist_ns.cf

Nach dem neu laden des Postfixes fand ich wenige Sekunden später folgendes im log:
postfix/smtpd[..]: connect from mx4.siegertarifpkv.com[...]
postfix/smtpd[..]: Anonymous TLS connection established from mx4.siegertarifpkv.com[...]: TLSv1.2 with cipher DHE-RSA-AES256-GCM-SHA384 (256/256 bits)
postfix/smtpd[..]: NOQUEUE: reject: RCPT from mx4.siegertarifpkv.com[...]: 554 5.7.1 : Sender address rejected: Sender-Domain is registered at WhoisGuard Panama / Namecheap Inc; from= to= proto=ESMTP helo=
postfix/smtpd[..]: disconnect from mx4.siegertarifpkv.com[...]

Für meine Server mit DRBD habe ich mir nun einen Zabbix Discover Script geschrieben, das automatisch alle DBRD Verbindungen sucht und überwacht.

Wie immer habe ich daraus ein Paket für Debian und Ubuntu gebaut das ich in meinem repostiory befindet. Der Quellcode steht auch schon auf Github bereit.

Im ersten Schritt habe ich die folgenden Werte aus /proc/drbd die überwacht werden übernommen:

• cs (connection state)
• ro (roles)
• ds (disk states)
• ns (network send)
• nr (network receive)
• dw (disk write)
• dr (disk read)
• al (activity log)
• bm (bit map)
• lo (local count)
• pe (pending)
• ua (unacknowledged)
• ap (application pending)
• ep (epochs)
• wo (write order)
• oos (out of sync)

(mehr …)

Nach dem neu starten unserer VServer Plattform mit dem Kernel 3.10.0-514, traten nach sofort nach dem Booten folgende schwerwiegenden Fehler im Log auf:

kernel: Buffer I/O error on dev dm-15, logical block 8892681, lost async page write
kernel: sd 4:0:0:0: [sdc] FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
kernel: sd 4:0:0:0: [sdc] Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdc] Add. Sense: Logical unit communication failure
kernel: sd 4:0:0:0: [sdc] CDB: Write(16) 8a 00 00 00 00 00 37 7d 48 00 00 00 40 00 00 00
kernel: blk_update_request: I/O error, dev sdc, sector 930957312
kernel: sd 4:0:0:0: [sdc] FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE


Aber auch folgende syslog events traten auf, nachdem mittels:

lvmcreate -L 10G -n lv_snapshot -S vg/lv

ein snapshot erzeugt wurde.

kernel: EXT4-fs (dm-28): INFO: recovery required on readonly filesystem
kernel: EXT4-fs (dm-28): write access will be enabled during recovery
kernel: EXT4-fs warning (device dm-28): ext4_clear_journal_err:4718: Filesystem error recorded from previous mount: IO fail
ure
kernel: EXT4-fs warning (device dm-28): ext4_clear_journal_err:4719: Marking fs in need of filesystem check.
kernel: EXT4-fs (dm-28): recovery complete
kernel: EXT4-fs (dm-28): mounted filesystem with ordered data mode. Opts: (null)
kernel: EXT4-fs (dm-28): INFO: recovery required on readonly filesystem
kernel: EXT4-fs (dm-28): write access will be enabled during recovery
kernel: EXT4-fs (dm-28): orphan cleanup on readonly fs
kernel: EXT4-fs (dm-28): 6 orphan inodes deleted
kernel: EXT4-fs (dm-28): recovery complete

Schlimmer noch, die VMs wechselten nach kurzer Zeit in den read only Modus. Und konnten ohne erweitertes Filesystem Check nicht wieder gestart werden.

Zugglück sind wir schnell auf den Kernel Parameter gekommen, der das Problem verursacht hat.

cat /sys/block/sda/queue/max_sectors_kb
32767

Dieser Wert war bei älteren Servern noch auf 512 eingestellt. Bei den von dem Bug betroffenen Server durfte er nicht über 4096 eingestellt sein, stand aber immer wieder auf 8192.

Der CentOS Bug Report 12725, in dem das selbe verhalten mittels:

parted -s /dev/sda unit s print

beschrieben wurdet, half uns den Fehler weiter auf den Kernel einzuschränken. Immer wenn eine Partitionsabfrage, oder eine Änderung am LVM Stattgefunden hat, änderte sich der Wert plötzlich wieder auf 8192.

Folgende udev Regel, die wir unter /etc/udev/rules.d/99-san.rules eingefügt haben, verhinderte das umstellen des wertes:

ACTION=="add|change", ENV{ID_FS_USAGE}!="filesystem", ENV{ID_PATH}=="*-iscsi-*", RUN+="/bin/sh -c 'echo 4096 > /sys$DEVPATH/queue/max_sectors_kb'"

Fazit:
Ein so schwerwiegenden Kernel Bug ist mit schon lange nicht mehr untergekommen. Er hatte für uns zufolge das wir bei einzelnen VMs nur noch teile retten konnten und komplett aus dem Backup wiederhergestellt werden mussten. Auch das Rechercheiren des Bugs ist bei CentOS kaum möglich. Da es zu RedHat binär kompatibel kann man nicht einfach durch ein git repository zu scrolen und sich die Änderungen und Kommentare anschauen. Wo bei mir die Überlegung offen ist, zukünftig auf einen Vanilla-Kernel zu wechseln und/oder CentOS zu vermeiden.

Unser Kernel: 3.10.0-514.6.1.el7.x86_64
Quelle Burgreport: https://bugs.centos.org/view.php?id=12725

Nach dem der Cisco Switch beim Letzten Stromausfall nicht überlebt hat. Ist jetzt auch einer meiner ältesten Server nicht mehr da.
Bei einer Uptime von 2847 Tagen habe ich das Letzte Screenshot gemacht:

Neben der Uptime habe ich auch mittels dumpe2fs /dev/sda1 den Zeitpunkt anzeigen lassen wann das Filesystem das letzte mal ein gehangen wurde. Das war am 08.02.2009.

Da heutzutage Server Quasi täglich mit Sicherheitsupdates versorgt werden müssen und es mittlerweile stabile Livemigration von VMs gibt. Wird es bei mir nicht mehr vorkommen, dass ein Server eine derart hohe Uptime erreichen wird.