Archiv 30. Juni 2019

Sonntag, 30. Juni 2019

Irgendwas ist am UniFi Firmware 4.0.42.10433 nicht ganz koscher

Link zu diesem Artikel

Bis vor wenigen Wochen hatte ich nie irgendwelche Probleme mit Firmware-Upgrades für UniFi-Produkte. Das hat sich mit Version 4.0.42.10433 geändert: Ich verzeichne mindestens zwei Probleme mit diesem Upgrade.

DHCP funktioniert mit gewissen Geräten nicht mehr

Bei mir macht dieses Update auf einem UniFi AP-AC-Mesh wie auch auf einem UniFi AP-AC-LR im Zusammenspiel mit DHCP-Anfragen Probleme. Das Resultat: Die Geräte sind zwar im Controller sichtbar, können aber keine IP beziehen.

In der Controller-App für iOS sieht man bei solchen Geräten die Warnung:

„DHCP Timeout. Please check that your DHCP server is accessible and properly configured“

Die meisten Geräte wie Laptops, Smartphones und Tablets können mit DHCP IPs beziehen; Probleme haben derzeit nur zwei Geräte(typen) gemacht: Ein Canon Selphy sowie ein Industrieboard für einen Wechselrichter. Meine derzeitige Vermutung: Auf diesen Dingern läuft eine ältere Linux-Version und ein älterer DHCP-Client, der irgendwie nicht (mehr) mit Antworten des DHCP-Servers über UniFi-Komponenten klarkommt, oder UniFi blockiert Antworten auf DHCP-Requests dieser Clients aus irgendeinem Grund.

Das zeigt sich daran, dass in den DHCP-Server-Logs unzählige folgende Meldungen auftauchen:

...
Jun 30 18:16:31 DHCPSERVER dhcpd[19637]: DHCPOFFER on 10.1.2.225 to 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:17:36 DHCPSERVER dhcpd[19637]: DHCPDISCOVER from 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:17:37 DHCPSERVER dhcpd[19637]: DHCPOFFER on 10.1.2.225 to 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:18:42 DHCPSERVER dhcpd[19637]: DHCPDISCOVER from 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:18:43 DHCPSERVER dhcpd[19637]: DHCPOFFER on 10.1.2.225 to 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:19:48 DHCPSERVER dhcpd[19637]: DHCPDISCOVER from 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:19:49 DHCPSERVER dhcpd[19637]: DHCPOFFER on 10.1.2.225 to 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:20:54 DHCPSERVER dhcpd[19637]: DHCPDISCOVER from 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:20:55 DHCPSERVER dhcpd[19637]: DHCPOFFER on 10.1.2.225 to 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:22:00 DHCPSERVER dhcpd[19637]: DHCPDISCOVER from 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:22:01 DHCPSERVER dhcpd[19637]: DHCPOFFER on 10.1.2.225 to 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:23:06 DHCPSERVER dhcpd[19637]: DHCPDISCOVER from 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:23:07 DHCPSERVER dhcpd[19637]: DHCPOFFER on 10.1.2.225 to 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:24:12 DHCPSERVER dhcpd[19637]: DHCPDISCOVER from 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:24:13 DHCPSERVER dhcpd[19637]: DHCPOFFER on 10.1.2.225 to 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:25:18 DHCPSERVER dhcpd[19637]: DHCPDISCOVER from 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:25:19 DHCPSERVER dhcpd[19637]: DHCPOFFER on 10.1.2.225 to 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
Jun 30 18:26:24 DHCPSERVER dhcpd[19637]: DHCPDISCOVER from 00:00:00:00:00:00 (SELPHY_DHCP_INSTANCE_0) via eth0
...

Syslog geflutet

Der UniFi AP-AC-Mesh an einem Standort brachte meinen ELK-Cluster für das Sammeln von Syslog-Meldungen aus allen Sites fast zum Glühen, nachdem die neue Firmware installiert war und der Access Point neu gebootet hatte.

Das Gerät sendete folgende Meldung 29 Mal pro Sekunde an den Syslog-Server:

<4> Jun 10 16:00:00 unifi.site.domain.local U7MSH,788a20263e00,v4.0.42.10433 kernel: [103146.842183] [wifi1] FWLOG: [105639111] VDEV_MGR_DEBID_DEFINITION_START ( 0x3, 0x40, 0x1, 0x6 )

Sobald ich wieder die alte Firmware (4.0.21.9965) installiert hatte, hörte die Log-Flut auf.

In Kibana ist die Flutwelle gut ersichtlich …

… welche sich auch in der CPU-Auslastung wiederspiegelt:

Auch Smokeping zeigt, dass das Gerät mit dem neuen Firmware eine deutlich höhere Latenz bei ICMP Ping Requests aufweist:

Ein anderer Benutzer hatte dieses Phänomen bereits im März 2019 beobachtet und dies in einem Beitrag im offiziellen Support-Forum kundgetan: WAL_DBGID_SECURITY_ALLOW_DATA and VDEV_MGR_DEBID_DEFINITION_START — leider ohne Lösung.

Um das Problem ohne Downgrade des Firmwares zu beheben, habe ich meine rsyslog-Konfiguration, welche die Meldungen lokal in Empfang nimmt und an ELK weiterleitet, folgendermassen angepasst:

/etc/rsyslog.conf

...
# EMERGENCY 2019-06-10
if $msg contains 'VDEV_MGR_DEBID_DEFINITION_START' then {
    /dev/null
    stop
}

# Send all logs to ELK server
*.* @10.1.2.3:514
...

Tags: , , , , , ,
Labels: IT

1 Kommentar | neuen Kommentar verfassen