Ausfall der Datenannahme am 1. September 2018 um 06:52 Uhr

Guten Morgen,

seit heute morgen ungefähr 6:51 Uhr kommen keine Daten im Dashboard mehr an.

Offensichtlich trifft es nicht nur mein Dashboard, sondern auch andere, deshalb vermute ich eine zentralere Ursache.

https://swarm.hiveeyes.org/grafana/d/000000178/munchen-trudering-trudies?orgId=2

https://swarm.hiveeyes.org/grafana/d/763KRx7mk/freiland-potsdam-thias-lora-multi-hive?refresh=5m&orgId=2&from=1535744456780&to=1535787656780&var-HIVE=thias_hive1_up_sensors&var-STATION=Potsdam

@Andreas - da Du beim letzten Mal siehe https://community.hiveeyes.org/t/ausfall-bei-der-datenannahme/903 die Lösung gefunden hast, hoffe ich das Du auch diesmal fündig wirst.

Schon mal vielen Dank vorab!
Stefan


Update

Inzwischen (10:10 Uhr) werden die Daten wieder im Dashboard angezeigt - insofern erst mal kein Handlungsbedarf.

Guten Tag,

@Stefan: Vielen Dank für Deine Meldung.

Wir haben heute morgen festgestellt, dass der Mosquitto Dienst spontan kaputtgegangen ist, genauso wie beim Ausfall der Datenannahme am 1. Juli 2018 um 06:45 Uhr. @einsiedlerkrebs hat ihn dann neugestartet (vielen Dank dafür!) und seither sollte wieder alles einwandfrei laufen. Wir werden uns in Folge darum kümmern, ihn genauer zu überwachen und ggf. automatisch neuzustarten. Dafür eignet sich der Klassiker “Monit” hervorragend.

Entschuldigt bitte die Unannehmlichkeiten!

Viele Grüße vom Hiveeyes Team.


P.S.: Hier die Meldungen zu dem Vorfall aus unserem Monitoringsystem:

Störung

image

Entstörung

image

1 Like

Analyse

Hier nochmal rückblickend die Analyse des mosquitto.log zum besagten Zeitpunkt am Saturday, September 1, 2018, die Uhrzeiten sind jeweils AM GMT+02:00 DST, alle identifizierenden Merkmale wurden anonymisiert:

Zeitpunkt des Crashs?

# 06:51:02 AM
1535777462: New connection from 80.135.176.42 on port 1883.

# 06:52:05 AM
1535777525: mosquitto version 1.5 starting
1535777525: Config loaded from /etc/mosquitto/mosquitto.conf.
1535777525: Opening ipv4 listen socket on port 1883.
1535777525: Error: Address already in use

# 06:51:02 AM
1535777462: Client b7873cc2-9814-4ccc-ba41-91855c208e1e already connected, closing old connection.
1535777462: Socket error on client b7873cc2-9814-4ccc-ba41-91855c208e1e, disconnecting.
1535777462: New client connected from 80.135.176.42 as b7873cc2-9814-4ccc-ba41-91855c208e1e (c1, k300, u'user2').

# 06:52:05 AM
1535777525: mosquitto version 1.5 terminating

Manueller Neustart

# 10:08:06 AM
1535789286: mosquitto version 1.5 starting
1535789286: Config loaded from /etc/mosquitto/mosquitto.conf.
1535789286: Opening ipv4 listen socket on port 1883.
1535789286: Opening ipv6 listen socket on port 1883.

Bewertung

Ich werde aus den Einträgen im Logfile nicht ganz schlau. Der Mosquitto Dienst will um 06:52:05 AM starten, was jedoch per Error: Address already in use fehlschlägt. Eigentlich müsste er zu diesem Zeitpunkt noch laufen, woher kommt also das Signal zum nochmaligen Starten? Auch die Fehlermeldung weist ja darauf hin, dass der Dienst weiterhin läuft und den Port (1883) gebunden hat. Auf jeden Fall terminiert der Dienst dann in Folge des aufgetretenen Fehlers und bleibt scheinbar aus. Hm.

P.S.: Die Einträge im Logfile sind in der exakten Reihenfolge wiedergegeben wie dargestellt. Dass sie nicht in dieser Reihenfolge aufgetreten sein können, sieht man an den Zeitstempeln. Die krumme Reihenfolge liegt vermutlich an internen Mechanismen wie Logfile Buffering, so we are probably Suffering from Buffering? here. No matter what, the Mosquitto service finally seems to get terminated by Murphy, so we will just take care of this.

Angelehnt an mosquitto/mosquitto.monit at master · eclipse/mosquitto · GitHub haben wir nun folgende Überwachungskonfiguration per Monit zugeschaltet:

check process mosquitto with pidfile /var/run/mosquitto.pid
        start = "/bin/systemctl start mosquitto"
        stop = "/bin/systemctl stop mosquitto"
        if failed port 1883 then restart

Es wird nun alle zwei Minuten geprüft, ob a) der Mosquitto Dienst noch läuft und b) auf Port 1883 antwortet. Falls nicht, wird er neugestartet.

Enjoy!

In mosquitto 1.4.x gab es im letzten Jahr den bug CVE-2017-7652, der bei einigen Ubuntu-basierenden distros mit z.B. 1.4.8 erst jüngst ausgebügelt wurde - daran erinnerte mich das zuerst.

Nun sehe ich aber, daß das inzwischen 1.5 ist, Du schriebst zuletzt, daß eine 1.4.10 installiert wurde, da debian stable, - und nun eine 1.5 ?! Wolltest Du 1.4.15 nicht mehr installieren und hast gleich eine 1.5.x gebaut (1.5 oder 1.5.1)?

Jedenfalls scheint es bei 1.5(.0) eine regression zu geben (bug tracker: #825, #882), dessen Vermeidung liest sich hart:

As a work around, comment out the listener 1883 section.

Inwiefern da zur Zeit ein erwähnter systemd-Bug noch mit eine Rolle spielt, kann ich nicht einschätzen. - Wenn 1.5 sein muß, dann gleich die 1.5.1 draus machen.

Vielleicht aus (D)einem mosquitto.service -file mit den Einträgen:

Restart=on-failure
RestartSec=1

?

Hi @weef,

danke für Deine Nachforschungen!

Paketversion

Wir haben das Paket vom Upstream abonniert:

root@elbanco:~# cat /etc/apt/sources.list.d/mosquitto-jessie.list
deb http://repo.mosquitto.org/debian jessie main

Da sollte also eigentlich die aktuellste Version anliegen. Die Dateien mosquitto, mosquitto_pub, und mosquitto_sub auf der Maschine sind vom 8. August - das klingt recht in Ordnung?

systemd woes

Das System ist ein »Debian GNU/Linux 8 (jessie)«, da wird Mosquitto scheinbar noch per SysVinit (/etc/init.d/mosquitto) gestartet. Hier ist weit und breit kein entsprechendes natives systemd unit file zu sehen. Einzig der folgende automatisch generierte Wrapper ist wohl im Einsatz:

root@elbanco:~# cat /run/systemd/generator.late/mosquitto.service
# Automatically generated by systemd-sysv-generator

[Unit]
SourcePath=/etc/init.d/mosquitto
Description=LSB: mosquitto MQTT v3.1 message broker
Before=runlevel2.target runlevel3.target runlevel4.target runlevel5.target shutdown.target
After=remote-fs.target systemd-journald-dev-log.socket
Conflicts=shutdown.target

[Service]
Type=forking
Restart=no
TimeoutSec=5min
IgnoreSIGPIPE=no
KillMode=process
GuessMainPID=no
RemainAfterExit=yes
SysVStartPriority=2
ExecStart=/etc/init.d/mosquitto start
ExecStop=/etc/init.d/mosquitto stop
ExecReload=/etc/init.d/mosquitto reload

Korrektur: Die 1.5.1er kam erst am 16. August raus, ergo läuft hier vermutlich noch die Mosquitto Version 1.5.0. JP wartet ebenfalls schon auf ein neues Debian Paket:

https://github.com/eclipse/mosquitto/issues/939

Hier fand ich gerade auch noch zwei Beiträge, die zum Thema passen könnten:
https://github.com/eclipse/mosquitto/issues/176
https://github.com/eclipse/mosquitto/issues/849

Die 1.5.2. ist diese Woche herausgekommen, aber leider immer noch keine updates bei den debian-paketen auf auch nur 1.5.1 … 8(

Roger Light was pretty busy fixing stuff on Mosquitto these days but we believe he made it. Jan-Piet Mens just mentioned:

we’re now seeing [Mosquitto] packages for 1.5.3. Much appreciated!

We are now running Mosquitto 1.5.3 on "elbanco". We continued reasoning about the possible root cause at Ausfall der Datenannahme am 1. Oktober 2018 um 06:53 Uhr.