Wiregate tot, Wasser kalt

[makki]

Nun, das kann&darf nicht sein!

Bitte mal sämtliches Backup im Webmin einfach komplett abschalten, da sind ein dutzend Bugs drin.
Hat damit vermutlich garnichts zu tun, aber hab trotzdem mal den Kernel aktualisiert -> restart bitte selbst.
Ändert nichts an der Sache: wenn der OOM-Killer kommt ist etwas total schiefgelaufen..

Makki

[johnnychicago]

Hallo Makki --

Ich kram den alten Thread noch mal raus. Mein WG ist jetzt einige Male hängengeblieben, jeweils ohne dass ich mehr machen konnte als Stecker raus und wieder rein.

Gestern blieb's gegen elf Uhr abends hängen. Das fiel auf, weil einige Linknx-Logiken Minuten brauchten, bis sie durch waren. Über's webif rein war nicht, pings kamen nur zu etwa 50% durch, und eine ssh-Verbindung brauchte gut 5 Minuten, bis ich auf der Shell war.

Weil Befehle auch ewig lang brauchten und quasi keine Reaktivität da war, habe ich mich auf folgendes beschränkt:

uptime (ich dachte hohen System load zu sehen):

23:31:31 up 13 days, 12:57, 1 user, load average: 0.01, 0.08, 0.08

dmesg, die letzten paar Zeilen:

[ 47.289858] fuse init (API version 7.13)
[ 47.457787] w83627hf: Found W83627HF chip at 0x290
[ 49.318827] eth0: link up, 100Mbps, full-duplex, lpa 0xCDE1
[ 51.945764] owserver[1970]: segfault at b806a3a1 ip 0804e3bf sp b74f5348 error 4
[ 55.413754] tun: Universal TUN/TAP device driver, 1.6
[ 55.420255] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
[ 62.012851] warning: `ntpd' uses 32-bit capabilities (legacy support in use)
[ 66.564221] owserver[2666]: segfault at b81a26b6 ip 0804e3bf sp b762c34c error 4
[466531.895352] usb 1-3: usbfs: process 28571 (owserver) did not claim interface 0 before use
[466531.895798] usb 1-3: usbfs: process 28571 (owserver) did not claim interface 0 before use

ps aux:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.2   1980   664 ?        Ss   Jan13   0:17 init [2]
root         2  0.0  0.0      0     0 ?        S    Jan13   0:00 [kthreadd]
root         3  0.0  0.0      0     0 ?        S    Jan13   0:00 [ksoftirqd/0]
root         4  0.0  0.0      0     0 ?        S    Jan13   0:00 [watchdog/0]
root         5  0.0  0.0      0     0 ?        S    Jan13   0:07 [events/0]
root         6  0.0  0.0      0     0 ?        S    Jan13   0:01 [khelper]
root         9  0.0  0.0      0     0 ?        S    Jan13   0:00 [async/mgr]
root        65  0.0  0.0      0     0 ?        S    Jan13   0:00 [sync_supers]
root        67  0.0  0.0      0     0 ?        S    Jan13   0:00 [bdi-default]
root        68  0.0  0.0      0     0 ?        S    Jan13   0:18 [kblockd/0]
root        70  0.0  0.0      0     0 ?        S    Jan13   0:00 [kacpid]
root        71  0.0  0.0      0     0 ?        S    Jan13   0:00 [kacpi_notify]
root        72  0.0  0.0      0     0 ?        S    Jan13   0:00 [kacpi_hotplug]
root       126  0.0  0.0      0     0 ?        S    Jan13   0:00 [kseriod]
root       170  0.0  0.0      0     0 ?        S    Jan13   0:00 [khungtaskd]
root       171  0.0  0.0      0     0 ?        S    Jan13   0:00 [kswapd0]
root       172  0.0  0.0      0     0 ?        S    Jan13   0:00 [aio/0]
root       173  0.0  0.0      0     0 ?        S    Jan13   0:00 [crypto/0]
root       635  0.0  0.0      0     0 ?        S    Jan13   0:00 [ksuspend_usbd]
root       665  0.0  0.0      0     0 ?        S    Jan13   0:00 [khubd]
root       670  0.0  0.0      0     0 ?        S    Jan13   0:00 [ata/0]
root       684  0.0  0.0      0     0 ?        Z    23:29   0:00 [watchdog] <defunct>
root       693  0.0  0.3   4592   948 pts/0    R+   23:29   0:00 ps aux
root       710  0.0  0.0      0     0 ?        S    Jan13   0:00 [ata_aux]
root       782  0.0  0.0      0     0 ?        S    Jan13   0:00 [kstriped]
root       786  0.0  0.0      0     0 ?        S    Jan13   0:00 [ksnapd]
root       903  0.0  0.3   2160   784 ?        S<s  Jan13   0:01 udevd --daemon
root      1236  0.0  0.0      0     0 ?        S    Jan13   0:00 [kpsmoused]
root      1689  0.0  0.0      0     0 ?        S    Jan13   0:06 [flush-3:0]
106       1791  0.0  0.3   1892   752 ?        S<   Jan13   0:18 avahi-autoipd: [eth0] bound 169.254.7.118
root      1792  0.0  0.1   1680   344 ?        S<s  Jan13   0:00 avahi-autoipd: [eth0] callout dispatcher
daemon    1799  0.0  0.1   1764   476 ?        Ss   Jan13   0:00 /sbin/portmap
statd     1810  0.0  0.2   1824   676 ?        Ss   Jan13   0:00 /sbin/rpc.statd
snmp      1975  0.0  1.7  10380  4320 ?        S    Jan13   6:08 /usr/sbin/snmpd -LSwd -Lf /dev/null -u snmp -I -smux -p /var/run/snmpd.pid
root      1996  0.0  2.1   7240  5292 ?        Ss   Jan13   0:35 /usr/bin/perl /usr/share/webmin/miniserv.pl /etc/webmin/miniserv.conf
root      2048  0.0  0.1   1672   448 ?        S    Jan13   4:22 /usr/sbin/ifplugd -i eth0 -b -q -f -u0 -d2 -w -I
root      2065  0.0  0.1   1832   348 ?        S    Jan13   0:00 /usr/sbin/xplhub
root      2068  0.0  0.2   1876   616 ?        S    Jan13   0:22 /usr/sbin/xplhub
root      2075  0.1  0.3   4240   988 ?        Ss   Jan13  36:50 /usr/bin/eibd -e 1.1.100 -c -S -D -i -T -R --tpuarts-ack-all-group -d -u --pid-file=/var/run/eibd.pid -c tpuarts:/dev/tul
root      2078  0.0  0.8   4072  2140 ?        Ss   Jan13   0:43 /usr/sbin/syslog-ng -p /var/run/syslog-ng.pid
root      2084  0.0  0.5   6944  1324 ?        Ss   Jan13   0:22 /usr/sbin/nmbd -D
root      2086  0.0  0.7  12400  1956 ?        Ss   Jan13   0:00 /usr/sbin/smbd -D
root      2092  0.0  0.3  12400   848 ?        S    Jan13   0:00 /usr/sbin/smbd -D
daemon    2136  0.0  0.1   1912   420 ?        Ss   Jan13   0:00 /usr/sbin/atd
root      2143  0.0  0.2   1648   516 ?        Ss   Jan13   0:00 /usr/sbin/acpid
root      2158  0.0  0.2  26328   592 ?        SLsl Jan13   1:21 /usr/sbin/rngd -r /dev/hwrng
root      2205  0.0  0.6   1692  1692 ?        SLs  Jan13   0:49 /usr/sbin/watchdog
root      2209  0.0  0.3   4372   980 ?        Ss   Jan13   0:04 /usr/sbin/cron
109       2219  0.0  0.3   2484   916 ?        Ss   Jan13   0:00 /usr/bin/dbus-daemon --system
root      2221  0.0  0.2   1820   604 ?        Ss   Jan13   0:00 /usr/sbin/inetd
root      2227  0.0  0.1   1644   304 ?        Ss   Jan13   0:00 /usr/sbin/collectdmon -P /var/run/collectdmon.pid -- -C /etc/collectd/collectd.conf
ntp       2228  0.0  0.4   4056  1120 ?        Ss   Jan13   0:00 /usr/sbin/ntpd -p /var/run/ntpd.pid -u 104:105 -g
root      2234  0.6  1.0  68368  2588 ?        Sl   Jan13 122:56 collectd -C /etc/collectd/collectd.conf -f
root      2483  0.0  0.4   5196  1036 ?        Ss   Jan13   0:16 /usr/sbin/sshd
100       2591  0.0  0.7   6136  1788 ?        Ss   Jan13   0:00 /usr/sbin/exim4 -bd -q30m
root      2665  0.0  0.6  27612  1568 ?        Ssl  Jan13   0:00 /usr/sbin/owhttpd -p 3001 -s localhost:4304 --pid_file /var/run/owhttpd.pid
avahi     2676  0.0  0.6   2864  1504 ?        S    Jan13   0:04 avahi-daemon: running [wiregate733.local]
avahi     2677  0.0  0.1   2748   408 ?        Ss   Jan13   0:00 avahi-daemon: chroot helper
root      2699  0.0  0.2   1648   500 tty2     Ss+  Jan13   0:00 /sbin/getty 38400 tty2
root      2700  0.0  0.2   1648   500 tty3     Ss+  Jan13   0:00 /sbin/getty 38400 tty3
root      2701  0.0  0.2   1648   504 tty4     Ss+  Jan13   0:00 /sbin/getty 38400 tty4
root      2702  0.0  0.2   1648   500 tty5     Ss+  Jan13   0:00 /sbin/getty 38400 tty5
root      2703  0.0  0.2   1648   500 tty6     Ss+  Jan13   0:00 /sbin/getty 38400 tty6
root      2704  0.0  0.1   1668   468 tty8     Ss+  Jan13   0:24 /usr/bin/tail -f /var/log/syslog
root      2705  0.0  0.1   1632   480 tty9     Ss+  Jan13   0:38 /usr/bin/vbusmonitor1time local:/tmp/eib
root      2706  0.0  0.1   1668   464 tty10    Ss+  Jan13   0:25 /usr/bin/tail -f /var/log/user.log
root      3632  1.2  8.5  29404 21036 ?        S    Jan20 107:46 /usr/bin/perl -w /usr/sbin/wiregated.pl -p /var/run/wiregated.pl.pid
root      3642  0.1  3.1  15548  7772 ?        S    Jan20  17:19 /usr/bin/perl -w /usr/sbin/wiregated-ow.pl -p /var/run/wiregated-ow.pl.pid
root     10151  0.0  1.7  15460  4332 ?        Ss   Jan23   3:57 /usr/bin/linknx -c/etc/linknx.xml -p /var/run/linknx.pid -d -w
root     21976  0.0  1.0   8072  2612 ?        Ss   23:05   0:00 sshd: root@pts/0
root     22131  0.8  0.7  68572  1964 ?        Ssl  Jan25  20:11 /usr/sbin/owserver -uall -uscan --autoserver --pid_file /var/run/owserver.pid
nobody   22321  0.0  0.3   4408   852 ?        Ss   Jan17   0:03 /usr/sbin/openvpn --writepid /var/run/openvpn.server.pid --daemon ovpn-server --cd /etc/openvpn --config /etc/openvpn/server.conf
root     22340  0.0  1.1  55164  2912 ?        Sl   Jan17   3:59 /usr/sbin/monit -d 60 -c /etc/monit/monitrc -s /var/lib/monit/monit.state
root     23489  0.1  1.5   7340  3940 pts/0    Ss   23:08   0:01 -bash
www-data 29743  0.0  0.9   6232  2320 ?        S    Jan20   2:37 /usr/sbin/lighttpd -f /etc/lighttpd/lighttpd.conf
root     31862  0.0  0.5   2716  1292 tty1     Ss+  23:26   0:00 /bin/bash /usr/sbin/wiregate-tty.sh

Mehr hab ich dann nicht mehr gemacht, sondern es rebootet. Tickt jetzt wieder als ob nichts gewesen wäre.

VPN ist offen - kannst Du noch mal kucken, bitte?

[makki]

Der eibd kachelt
a) AFAIK nie ab (zumindest nicht in dieser Konstellation)
b) wird gemonitored

Wenn aber der OOM (out-of-memory-killer) des Kernels dazukommt, wirds brutal unscharf: der erschiesst nach dem Beamten-Mikado-Prinzip (wer sich zuerst bewegt..) einfach wahllos jeden..
das ist so ähnlich wie wenn John Rambo den Frieden nach Afghanistan bringen soll (passend zum Namen und ohne was allzu aktuelles, damits ned politisch wird..)
Wir haben jetzt alle den MilMi-Heli vor Augen

zurück zum Thema: der OOM darf nie nicht kommen, weil dann ists schon viel zu spät..
Ich versuch das mal zu rekonstruieren bzw. kann ich das schon, nun muss ich mal gucken wie man das verhindert..

Makki

[johnnychicago]

@makki,

Good stuff - gehst Du davon aus, dass der eibd-Tod damit zu tun hat? Falls nicht, gibt's da eventuell eine Möglichkeit, mehr/besser zu loggen?

[makki]

Ok, hab das grad nochmal getestet: das backup.pl in der Crontab kommt natürlich vom Webif (Webmin) aber das läuft wild - da muss ich mal suchen gehen.
Ich habs bei dir jetzt vorerst mal auskommentiert, ich hab den dumpfen verdacht das es am nicht-exitierenden Verzeichnis 192.168.4.2/home/marc/wg_backup liegt aber das sollte deswegen natürlich nicht abkacheln..

Ich geh das mal hier auf nem Testsystem durch..

Makki

[johnnychicago]

@Makki,

Danke für den Blick drauf - da war aus gegebenen Gründen nicht viel mit Analyse am lebenden Objekt, der WAF hat so schon einen kleinen Dämpfer bekommen ;-)

Ich bin jetzt auch dazu gekommen, mal detailliert zu kucken. Das eib.log ist rabiat zu Ende, zu dem Zeitpunkt, an dem die Visu auch tot war (ich hab' einen Timestamp in der CV, der die letzte vom Wiregate an den Bus gegebene Zeit zeigt).

linknx.log läuft weiter, hat natürlich seit dem Zeitpunkt nichts mehr vom Bus, sondern nur interne Trigger.

wiregate-plugin.log hat zu dem Moment das Comfoair-plugin ausgeführt, da hat's aber keine für mich erkennbare Fehlermeldung. Die KWL-GA's waren auch die letzten, die im eib.log drin waren.

Sieht also aus, als ob eibd nicht mehr mochte. Gab's da nicht mal was mit einem watchdog? OBwohl der TP-UART ja eigentlich vorzüglichst stabil sein sollte (und auch definitiv nicht schlecht ist, das war jetzt der erste Uuups in Monaten).

Was die Kernel Msgs und die root-Bemerkung angeht: backup.pl ist nicht von mir, und es gibt keine crontab-Entries von mir. Ich kann natürlich nicht ausschliessen, dass Dinge, die ich als root auf der Kiste machen, solche memory hogs sind, dass das backup.pl nicht tut. Allerdings gebe ich zu Bedenken, dass die Wiregate-Backup-Funktion hier so ziemlich out of the box nicht funktioniert hat.

Ich hör mir aber gerne an, was Du davon hälst und nehme mir Tipps und Hinweise zu Herzen.

[makki]

nur ein kurzer Blick und eine subjektive Meinung:
ich bin root, ich darf das.
Aber root hat auch eine gewisse Verantwortung, sowas sollte ihm nicht passieren;

Dec  8 02:01:13 wiregate733 kernel: [20951.046252] Out of memory: kill process 4458 (cron) score 1658 or a child
Dec  8 02:01:13 wiregate733 kernel: [20951.052976] Killed process 4459 (backup.pl)

Ich ändere an bestehenden Systemen grundsätzlich nichts ohne explizite Freigabe, aber Fazit:
da geht der Speicher aus, fertig..

Makki

[johnnychicago]

Hallo --

mechanisch tot war's nicht, und ich konnte auch vor dem Reboot einloggen.

Verbindung über TP-UART. Ein Busmaster mit einer Handvoll Sensoren.

Ich bin nicht in meinem lokalen Netz und komme von daher nicht rein, aber es sieht aus, als ob der 1-wire-Teil weiterlief (ich habe RRD's, die während der Ausfallzeit bewegten). Der KNX-Teil war wohl weg.

Root ist frei, linknx läuft drauf, ausserdem ein selbstgeschriebener perl-daemon (iscp.pl, redet mit meinem Onkyo Receiver), und ein paar Bash-Scripte, die von linknx aufgerufen werden. Verändert wurde am Vortag die linknx-config - die lief aber nach der Veränderung definitiv stabil.

Ich konnte heute früh nicht viel Forensik betreiben, mich verwirrte bloss, dass die Visu auf Eingaben nicht reagierte, und noch nicht mal die Uhrzeit aktualisierte (die vom Wiregate auf den Bus geschickt wird). /var/log/syslog zeigte halt einen Haufen kernel Einträge an, und /var/log/linknx.log zeigte auf den ersten Blick keine vom Bus getriggerten Events an. Für mehr Details habe ich keine Zeit gehabt, weil ich durch den Warmwassermangel sowieso schon zu spät war

[StefanW]

Guten Morgen,

sehen wir uns an.

Damit ich das richtig verstehe, nach dem Reboot hat alles wieder funktioniert?

Das WG war / ist also nicht "tot" sondern ein oder mehrere Prozesse waren möglicherweise nicht funktionierend?

Bitte noch Informationen zur Infrastruktur:

- Wie erfolgt die Verbindung zum KNX?
- Was hast Du vor dem Ausfall verändert?
- 1-Wire Sensoren?
- Hast Du Dir den Root-Zugang freigeschaltet? Wenn ja, was verändert?


lg

Stefan

[johnnychicago]

Hallo Makki, StefanW --

Um 23:19 gestern abend ist mein Wiregate zumindest auf eibd-Seite gestorben. Witzigerweise war die Cometvisu auch tot.

Ich hab's heute um 7:22 durch reboot reaktiviert, weil's vergessen hatte, die Heizung einzuschalten. ICh konnte noch nicht viel kucken, weil das Leben weitergeht, habe aber in den Logs einen Haufen kernel messages gesehen.

Magt Ihr mal reinkucken? wiregate733 vpn ist offen.