Abgehängte Knoten (2)

m.bitterlich · 28. Juni 2016 um 21:27

Moin,

gestern hat sich mal wieder ein Knoten abgehängt und ist heute ohne Eingriff wieder im Netz zurück. So ist das Logfile nicht durch ein Reboot verloren gegangen. Der “uplink” war die ganze Zeit online und konnte den angehängten Knoten auch sehen:
http://map.4830.org/mueritz/#!v:m;n:30b5c22264ce

root@17192-Salon-Gisela:~# batctl o | grep -i mesh0

32:b8:c3:c2:b7:ec    3.980s   (216) 32:b8:c3:c2:b7:ec [     mesh0]: 32:b8:c3:c2:b7:ec (216)

http://map.4830.org/mueritz/#!v:m;n:30b5c2c2b7ec

root@17192-Magic-Meile:~# logread
[...]
Mon Jun 27 14:56:57 2016 kern.err kernel: [401420.620000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Mon Jun 27 14:57:00 2016 kern.err kernel: [401423.800000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Mon Jun 27 14:57:00 2016 kern.err kernel: [401424.310000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Mon Jun 27 14:57:01 2016 kern.err kernel: [401424.620000] ath: phy0: Failed to stop TX DMA, queues=0x102!
Mon Jun 27 14:57:04 2016 kern.err kernel: [401427.400000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Mon Jun 27 14:57:19 2016 kern.err kernel: [401442.750000] ath: phy0: Failed to stop TX DMA, queues=0x00a!
Mon Jun 27 14:57:21 2016 kern.err kernel: [401444.700000] ath: phy0: Failed to stop TX DMA, queues=0x00a!
Mon Jun 27 14:57:29 2016 kern.err kernel: [401453.190000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Mon Jun 27 14:57:31 2016 kern.err kernel: [401454.620000] ath: phy0: Failed to stop TX DMA, queues=0x002!Mon Jun 27 14:58:07 2016 kern.err kernel: [401490.870000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Mon Jun 27 14:58:09 2016 kern.err kernel: [401492.720000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Mon Jun 27 14:58:11 2016 kern.err kernel: [401495.280000] ath: phy0: Failed to stop TX DMA, queues=0x102!
Mon Jun 27 14:58:26 2016 kern.err kernel: [401509.420000] ath: phy0: Failed to stop TX DMA, queues=0x102!
Mon Jun 27 14:58:27 2016 kern.err kernel: [401510.640000] ath: phy0: Failed to stop TX DMA, queues=0x102!
Mon Jun 27 14:59:27 2016 kern.err kernel: [401570.860000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Mon Jun 27 14:59:29 2016 kern.err kernel: [401572.900000] ath: phy0: Failed to stop TX DMA, queues=0x102!
Mon Jun 27 14:59:44 2016 kern.err kernel: [401587.650000] ath: phy0: Failed to stop TX DMA, queues=0x102!
Mon Jun 27 15:06:43 2016 kern.err kernel: [402007.190000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Mon Jun 27 15:11:46 2016 kern.err kernel: [402309.580000] ath: phy0: Failed to stop TX DMA, queues=0x102!
Mon Jun 27 15:11:46 2016 kern.err kernel: [402310.000000] ath: phy0: Failed to stop TX DMA, queues=0x10e!
Mon Jun 27 15:11:47 2016 kern.err kernel: [402311.320000] ath: phy0: Failed to stop TX DMA, queues=0x006!
Mon Jun 27 15:11:56 2016 kern.err kernel: [402320.030000] ath: phy0: Failed to stop TX DMA, queues=0x106!
Mon Jun 27 15:12:04 2016 kern.err kernel: [402327.490000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Mon Jun 27 15:16:00 2016 user.notice gluon-offline-ssid: TQ is 0, SSID is mueritz.freifunk.net, change to FF_OFFLINE_30b5c2c2b7ec
Mon Jun 27 15:22:33 2016 daemon.info dnsmasq[1839]: reading /tmp/resolv.conf.auto
Mon Jun 27 15:22:33 2016 daemon.info dnsmasq[1839]: using local addresses only for domain lan
Mon Jun 27 15:22:33 2016 daemon.info dnsmasq[1839]: using nameserver fd39:e4e3:eee1::5#53
Mon Jun 27 15:28:49 2016 daemon.warn dnsmasq[1839]: no servers found in /tmp/resolv.conf.auto, will retry
Tue Jun 28 21:35:02 2016 user.notice firewall: Reloading firewall due to ifupdate of client (br-client)
Tue Jun 28 21:35:04 2016 daemon.info dnsmasq[1839]: reading /tmp/resolv.conf.auto
Tue Jun 28 21:35:04 2016 daemon.info dnsmasq[1839]: using local addresses only for domain lan
Tue Jun 28 21:35:04 2016 daemon.info dnsmasq[1839]: using nameserver fd39:e4e3:eee1::6#53
Tue Jun 28 21:35:04 2016 daemon.info dnsmasq[1839]: using nameserver fd39:e4e3:eee1::5#53
Tue Jun 28 21:36:00 2016 user.notice gluon-offline-ssid: TQ is 61, SSID is FF_OFFLINE_30b5c2c2b7ec, change to mueritz.freifunk.net

Wo ist hier der Wurm drin?

Gruß Matthias

m.bitterlich · 28. Juni 2016 um 21:41

… einen hab ich noch … mit den selben Symptomen.

root@17194-Tressow-9824:~# logread
[...]
Tue Jun 28 15:57:48 2016 kern.err kernel: [490773.410000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Tue Jun 28 15:57:56 2016 kern.err kernel: [490781.190000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Tue Jun 28 15:57:57 2016 kern.err kernel: [490782.320000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Tue Jun 28 15:57:58 2016 kern.err kernel: [490783.240000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Tue Jun 28 15:58:02 2016 kern.err kernel: [490787.240000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Tue Jun 28 15:58:24 2016 daemon.info hostapd: client0: STA cc:3a:61:97:91:33 IEEE 802.11: disassociated due to inactivity
Tue Jun 28 15:58:25 2016 daemon.info hostapd: client0: STA cc:3a:61:97:91:33 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Tue Jun 28 16:02:01 2016 user.notice gluon-offline-ssid: TQ is 0, SSID is mueritz.freifunk.net, change to FF_OFFLINE_60e327c79824
Tue Jun 28 16:05:44 2016 daemon.info dnsmasq[1292]: reading /tmp/resolv.conf.auto
Tue Jun 28 16:05:44 2016 daemon.info dnsmasq[1292]: using local addresses only for domain lan
Tue Jun 28 16:05:44 2016 daemon.info dnsmasq[1292]: using nameserver fd39:e4e3:eee1::5#53
Tue Jun 28 16:13:13 2016 daemon.warn dnsmasq[1292]: no servers found in /tmp/resolv.conf.auto, will retry
Tue Jun 28 22:11:57 2016 daemon.info dnsmasq[1292]: reading /tmp/resolv.conf.auto
Tue Jun 28 22:11:57 2016 daemon.info dnsmasq[1292]: using local addresses only for domain lan
Tue Jun 28 22:11:57 2016 daemon.info dnsmasq[1292]: using nameserver fd39:e4e3:eee1::6#53
Tue Jun 28 22:12:03 2016 daemon.info dnsmasq[1292]: reading /tmp/resolv.conf.auto
Tue Jun 28 22:12:03 2016 daemon.info dnsmasq[1292]: using local addresses only for domain lan
Tue Jun 28 22:12:03 2016 daemon.info dnsmasq[1292]: using nameserver fd39:e4e3:eee1::6#53
Tue Jun 28 22:12:03 2016 daemon.info dnsmasq[1292]: using nameserver fd39:e4e3:eee1::5#53
Tue Jun 28 22:13:00 2016 user.notice gluon-offline-ssid: TQ is 68, SSID is FF_OFFLINE_60e327c79824, change to mueritz.freifunk.net

wusel · 28. Juni 2016 um 21:43

Örks. Das ist ein Bug, der eigentlich längst gefixt sein sollte. Es gibt von einer anderen Community ein Modul, was bei Auftreten dieser Situation den Knoten rebootet. Ich guck’ mal, damit eine neue experimental fertig zu machen, evtl. erklärt das verschiedene (Teil-) Ausfälle auch bei uns im Kreis GT.

Danke für den Hinweis!

m.bitterlich · 28. Juni 2016 um 21:48

Bei einigen Knoten denke ich, dass die dann in einer Reboot-Schleife festhängen werden.

wusel · 28. Juni 2016 um 21:56

Das ist die eine Gefahr. Übrigens ist ein Paket, gluon-wificheck, schon in der eingesetzten FW:

this script looks for wifi mesh neighbours. If at least 2 meshneibours are found once (after boot), the script is set into trigger mode.

then the absence of neighbours in the wifimesh will alert the node. and if the absence is still present the next minute, the node is rebootet.

Tja, in Eurem Fall ist es nur 1 Mesh-Partner, also feuert das Skript nicht

m.bitterlich · 4. Juli 2016 um 21:35

Moin.

Ich habe die letzten Tage einen Tip zum Thema gefunden, der zurzeit im Test bei “zickigen” Knoten als cronjob läuft:

*/15 * * * *   /usr/sbin/iw dev mesh0 scan | grep SSID > /tmp/scan_SSID.txt

Zwei abgehängte Fälle konnte ich “beheben” … einer hält sich hartnäckig offline.
Vielleicht war ersteres auch nur Zufall.

Cul8er
Matthias

wusel · 5. Juli 2016 um 13:11

Ja, das habe ich auch gelesen, daß das helfen soll; mangels Replizierbarkeit des Problems ist das mit den Workarounds immer so ein Ratespiel

frosty-geek · 5. Juli 2016 um 23:09

Dann läuft dir über kurz oder lang der RAM (/tmp) voll und die Kiste crash’d & rebooted (im optimalen Fall) oder bleibt stehen.

Wenn das wirklich der Workaround ist dann leite nach /dev/null um

wusel · 6. Juli 2016 um 00:15

Wieso sollte grep SSID > /tmp/scan_SSID.txt das RAM vollmachen? Außer in meinem Umfeld ist die Anzahl der SSIDs in der Umgebung eher konstant …

frosty-geek · 6. Juli 2016 um 05:26

NVM, dachte an ‘>>’ vs. ‘>’ und das das File diese protokollieren soll…

Ralf

m.bitterlich · 6. Juli 2016 um 17:41

Moin.

… hier funktionierte es auf dem Knoten, der die Verbindung „verloren“ hatte. Die Gegenstelle hat den selben Aufruf zur gleichen Zeit (+/- Zeitdifferenz der Geräte) - das Protokoll dazu ist schon übergelaufen …
Vielleicht passt der „Workaround“ in /lib/gluon/ssid-changer/ssid-changer.sh
Wenn Verbindung wech … dann „schaun wir mal“ uns um. Ob das protokolliert werden soll oder im Nirvana landet, ist später für stable interessant.

Leider ist das der einzige Standort, an dem ich das bis jetzt nachvollziehen konnte.

Wed Jul  6 17:47:38 2016 kern.err kernel: [45268.360000] ath: phy0: Failed to stop TX DMA, queues=0x002!
Wed Jul  6 17:48:03 2016 kern.err kernel: [45293.750000] ath: phy0: Failed to stop TX DMA, queues=0x00a!
Wed Jul  6 17:53:00 2016 user.notice gluon-offline-ssid: TQ is 0, SSID is mueritz.freifunk.net, change to FF_OFFLINE_e894f660e6ae
Wed Jul  6 17:53:55 2016 daemon.info dnsmasq[1379]: reading /tmp/resolv.conf.auto
Wed Jul  6 17:53:55 2016 daemon.info dnsmasq[1379]: using local addresses only for domain lan
Wed Jul  6 17:53:55 2016 daemon.info dnsmasq[1379]: using nameserver fd39:e4e3:eee1::5#53
Wed Jul  6 17:57:36 2016 daemon.warn dnsmasq[1379]: no servers found in /tmp/resolv.conf.auto, will retry
Wed Jul  6 18:00:01 2016 cron.info crond[963]: crond: USER root pid 21813 cmd /usr/sbin/iw dev mesh0 scan | grep -i SSID > /tmp/SSID_scan.txt
Wed Jul  6 18:00:07 2016 daemon.info dnsmasq[1379]: reading /tmp/resolv.conf.auto
Wed Jul  6 18:00:07 2016 daemon.info dnsmasq[1379]: using local addresses only for domain lan
Wed Jul  6 18:00:07 2016 daemon.info dnsmasq[1379]: using nameserver fd39:e4e3:eee1::6#53
Wed Jul  6 18:00:07 2016 daemon.info dnsmasq[1379]: using nameserver fd39:e4e3:eee1::5#53
Wed Jul  6 18:00:39 2016 daemon.info dnsmasq[1379]: reading /tmp/resolv.conf.auto
Wed Jul  6 18:00:39 2016 daemon.info dnsmasq[1379]: using local addresses only for domain lan
Wed Jul  6 18:00:39 2016 daemon.info dnsmasq[1379]: using nameserver fd39:e4e3:eee1::6#53
Wed Jul  6 18:00:39 2016 daemon.info dnsmasq[1379]: using nameserver fd39:e4e3:eee1::5#53
Wed Jul  6 18:03:00 2016 user.notice gluon-offline-ssid: TQ is 89, SSID is FF_OFFLINE_e894f660e6ae, change to mueritz.freifunk.net

m.bitterlich · 7. Juli 2016 um 15:14

Moin,

heute hatten bei drei hartnäckigen Fällen auch die Uplinks (2x 1043ND / 1x 841N) die Schuld … dort war mesh0 weg.

Thu Jul  7 15:45:01 2016 cron.info crond[994]: crond: USER root pid 29742 cmd /usr/sbin/iw dev mesh0 scan | grep SSID > /tmp/scan_SSID.txt
Thu Jul  7 15:45:02 2016 kern.info kernel: [14556.560000] IPv6: ADDRCONF(NETDEV_UP): mesh0: link is not ready

Nun habe ich dort noch in /etc/crontabs/root folgende Zeile eingebaut:

*/6  * * * *   if [ $(ifconfig | grep ^mesh0 | wc -l) -eq 0 ]; then sleep 30; if [ $(ifconfig | grep ^mesh0 | wc -l) -eq 0 ]; then reboot; fi; fi

Gruß
Matthias

PS: Vielleicht hat das ja auch nix zu sagen … aber aufgefallen ist mir, dass die Meldung “Failed to stop TX DMA”’, wenn sie überhaupt auftaucht, bei 841-v9-Geräten häufiger auftritt als bei 841-v10- und 1043-v2-Geräten.

m.bitterlich · 7. Juli 2016 um 15:25

Hier eine ganz frische Meldung von einem 4. Gerät:

    Thu Jul  7 17:15:01 2016 cron.info crond[979]: crond: USER root pid 9550 cmd /usr/sbin/iw dev mesh0 scan | grep SSID > /tmp/scan_SSID.txt
    Thu Jul  7 17:16:24 2016 kern.info kernel: [38079.520000] batman_adv: bat0: Interface deactivated: mesh0
    Thu Jul  7 17:16:24 2016 daemon.notice netifd: Network device 'mesh0' link is down
    Thu Jul  7 17:16:24 2016 daemon.notice netifd: Interface 'mesh_radio0' has link connectivity loss
    Thu Jul  7 17:16:24 2016 kern.info kernel: [38079.630000] batman_adv: bat0: Removing interface: mesh0
    Thu Jul  7 17:20:02 2016 kern.info kernel: [38297.270000] IPv6: ADDRCONF(NETDEV_UP): mesh0: link is not ready