Unsauberer Start nach Stromausfall - Telegram Plugin

[Sisamiwe]

Hallo,

bei uns kommt es gelegentlich vor, dass das 230V Netz nicht stabil ist und die Spannung kurz weg ist. Dies ist meist bei Gewitter der Fall.
Da ich (noch) keine USV habe, geht auch der RPI mit shNG scheinbar kurz aus und startet neu. Nun habe ich beobachtet, dass dieser Start nicht sauber abläuft.
Insbesondere das Telegram Plugin geht danach nicht, und die Backend ist auch nicht erreichbar.

Heute Nacht 0:17 war es wieder soweit. Das Log zeigt einen Neustart der relativ normal verläuft, bis das Telegram Plugin initialisiert werden soll.

Das Log sagt:

2019-08-07  00:17:36 DEBUG    Main         init plugins.telegram
2019-08-07  00:17:46 WARNING  Main         Retrying (Retry(total=2, connect=None, read=None, redirect=None)) after connection broken by 'NewConnectionError('<telegram.vendor.ptb_urllib3.urllib3.connection.VerifiedHTTPSConnection object at 0x69d12c10>: Failed to establish a new connection: [Errno -3] Temporärer Fehler bei der Namensauflösung',)': /bot404137557:AAE7sC5AXNwSyU3F1PkX5bKO058IwyVbZpo/getMe
2019-08-07  00:17:57 WARNING  Main         Retrying (Retry(total=1, connect=None, read=None, redirect=None)) after connection broken by 'NewConnectionError('<telegram.vendor.ptb_urllib3.urllib3.connection.VerifiedHTTPSConnection object at 0x69d12c90>: Failed to establish a new connection: [Errno -3] Temporärer Fehler bei der Namensauflösung',)': /bot404137557:AAE7sC5AXNwSyU3F1PkX5bKO058IwyVbZpo/getMe
2019-08-07  00:18:07 WARNING  Main         Retrying (Retry(total=0, connect=None, read=None, redirect=None)) after connection broken by 'NewConnectionError('<telegram.vendor.ptb_urllib3.urllib3.connection.VerifiedHTTPSConnection object at 0x69d12cd0>: Failed to establish a new connection: [Errno -3] Temporärer Fehler bei der Namensauflösung',)': /bot404137557:AAE7sC5AXNwSyU3F1PkX5bKO058IwyVbZpo/getMe
2019-08-07  00:18:17 ERROR    Main         Plugin 'telegram' from section 'telegram' exception: urllib3 HTTPError HTTPSConnectionPool(host='api.telegram.org', port=443): Max retries exceeded with url: /bot404137557:AAE7sC5AXNwSyU3F1PkX5bKO058IwyVbZpo/getMe (Caused by NewConnectionError('<telegram.vendor.ptb_urllib3.urllib3.connection.VerifiedHTTPSConnection object at 0x69d12dd0>: Failed to establish a new connection: [Errno -3] Temporärer Fehler bei der Namensauflösung',))
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connection.py", line 141, in _new_conn
    (self.host, self.port), self.timeout, **extra_kw)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/util/connection.py", line 60, in create_connection
    for res in socket.getaddrinfo(host, port, family, socket.SOCK_STREAM):
  File "/usr/lib/python3.5/socket.py", line 733, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -3] Temporärer Fehler bei der Namensauflösung

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 617, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 360, in _make_request
    self._validate_conn(conn)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 857, in _validate_conn
    super(HTTPSConnectionPool, self)._validate_conn(conn)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 289, in _validate_conn
    conn.connect()
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connection.py", line 284, in connect
    conn = self._new_conn()
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connection.py", line 150, in _new_conn
    self, "Failed to establish a new connection: %s" % e)
telegram.vendor.ptb_urllib3.urllib3.exceptions.NewConnectionError: <telegram.vendor.ptb_urllib3.urllib3.connection.VerifiedHTTPSConnection object at 0x69d12dd0>: Failed to establish a new connection: [Errno -3] Temporärer Fehler bei der Namensauflösung

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/telegram/utils/request.py", line 203, in _request_wrapper
    resp = self._con_pool.request(*args, **kwargs)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/request.py", line 66, in request
    **urlopen_kw)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/request.py", line 87, in request_encode_url
    return self.urlopen(method, url, **extra_kw)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/poolmanager.py", line 244, in urlopen
    response = conn.urlopen(method, u.request_uri, **kw)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 695, in urlopen
    **response_kw)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 695, in urlopen
    **response_kw)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 695, in urlopen
    **response_kw)
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/connectionpool.py", line 666, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/local/lib/python3.5/dist-packages/telegram/vendor/ptb_urllib3/urllib3/util/retry.py", line 376, in increment
    raise MaxRetryError(_pool, url, error or ResponseError(cause))
telegram.vendor.ptb_urllib3.urllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='api.telegram.org', port=443): Max retries exceeded with url: /botxxxxxxxxx:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/getMe (Caused by NewConnectionError('<telegram.vendor.ptb_urllib3.urllib3.connection.VerifiedHTTPSConnection object at 0x69d12dd0>: Failed to establish a new connection: [Errno -3] Temporärer Fehler bei der Namensauflösung',))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/smarthome/lib/plugin.py", line 145, in __init__
    plugin_thread = PluginWrapper(smarthome, plugin, classname, classpath, args, instance, self.meta, self._gtrans)
  File "/usr/local/smarthome/lib/plugin.py", line 627, in __init__
    exec("self.plugin.__init__(smarthome{0}{1})".format("," if len(arglist) else "", argstring))
  File "<string>", line 1, in <module>
  File "/usr/local/smarthome/plugins/telegram/__init__.py", line 108, in __init__
    self.logger.info("Telegram bot is listening: {0}".format(self._bot.getMe()))
  File "/usr/local/lib/python3.5/dist-packages/telegram/bot.py", line 65, in decorator
    result = func(self, *args, **kwargs)
  File "/usr/local/lib/python3.5/dist-packages/telegram/bot.py", line 204, in get_me
    result = self._request.get(url, timeout=timeout)
  File "/usr/local/lib/python3.5/dist-packages/telegram/utils/request.py", line 253, in get
    result = self._request_wrapper('GET', url, **urlopen_kwargs)
  File "/usr/local/lib/python3.5/dist-packages/telegram/utils/request.py", line 209, in _request_wrapper
    raise NetworkError('urllib3 HTTPError {0}'.format(error))
telegram.error.NetworkError: urllib3 HTTPError HTTPSConnectionPool(host='api.telegram.org', port=443): Max retries exceeded with url: /XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX (Caused by NewConnectionError('<telegram.vendor.ptb_urllib3.urllib3.connection.VerifiedHTTPSConnection object at 0x69d12dd0>: Failed to establish a new connection: [Errno -3] Temporärer Fehler bei der Namensauflösung',))
2019-08-07  00:18:17 INFO     Main         Loading '/usr/local/smarthome/plugins/onewire/plugin.yaml' to 'OrderedDict'

Für das nicht erreichbare Backend konnte ich keinen Eintrag im Log finden.

Startet man den den RPI neu oder auch shNG neu, klappt alles wunderbar.

Woran kann das liegen bzw. wie kann man das abstellen?
Gäbe es auch eine Art "primitiv" USV, also nur eine Pufferbatterie für wenige Minuten?

Danke Euch.

[Bonze]

Ich könnte mir nur vorstellen, das dies eigentlich ein Netzwerkfehler ist. Ob und wie man das abfangen kann, kann ich dir aber nicht sagen.

[Sisamiwe]

Bonze
Du meinst, dass der RPI mit shNG schneller startet, als die Fritzbox die Internetverbindung wieder aufbaut?
Das ist gut möglich.

[jzehnter]

Bonze
Du meinst, dass der RPI mit shNG schneller startet, als die Fritzbox die Internetverbindung wieder aufbaut?
Das ist gut möglich.

Laut Log ist es ja ein Problem der Namensauflösung, was natürlich passiert, wenn der Internetzugriff noch nicht gewährleistet ist.

Ein Pi ist wohl ca. nach 45 Sek einsatzbereit
Die Fritzbox braucht zum Booten ca genauso lanhe. Der DSL-Sync in der Regel auch nochmal 3 Minuten.

Das passt schon zusammen.

Du kannst ja mal einen Stromausfall beim Pi simulieren und schauen ob der dann wieder normal mit Telegram hochfährt.

[Onkelandy]

Raspi usv guckst du hier
https://olmatic.de/

[bmx]

Also das abzufangen ist recht viel Arbeit weil es bereits tief in der verwendeten Telegram Library liegt. Außerdem würde ich jetzt nicht beigehen wollen mir einen Raspi zu konfigurieren nur um dann Stecker zu ziehen und zu debuggen.
Da ist sicher die USV der richtige Weg, verbunden mit einem geordneten runterfahren von SHNG...

[gama]

Ich habe das Problem auch, dass PRI schneller ist als die FB. Daher habe ich eine (manuelle) Einschalt Sequenz mittels LS im Schaltschrank festgelegt. Besser wäre natürlich ein automatischer "Boot-Sequezer" der nach und nach schaltet. Hatte mir schon überlegt, dies mittels einen Schaltaktors sehr hardwarenah zu basteln - ist aber wieder liegen geblieben...

[bmx]

Wenn ich dieses Problem mit dem Booten hätte, würde ich überlegen, ob ich evtl. eine Abhängigkeit zum Erreichen einer oder mehrerer IP-Adressen im Netz im systemd verankern kann. Also sprich: SHNG wird erst dann gestartet, wenn apple.de aufgelöst werden kann und ein Ping beantwortet wird.
Anderer Ansatz wäre es SHNG zu starten aber das Telegramm Plugin erst dann zu launchen, wenn o.a. Bedingung erfüllt wird. Das dürfte derzeit noch nicht so out-of-the box klappen aber vielleicht kann Msinn was dazu sagen, ob man ein Plugin Programm/Logikgesteuert erst zur Laufzeit laden, initialisieren und starten kann.
Möglicherweise könnte man auch vieles was im Init des Telegram steht auch in Start verschieben.

[Msinn]

ob man ein Plugin Programm/Logikgesteuert erst zur Laufzeit laden, initialisieren und starten kann.

Nein, das geht bisher nicht.

[gama]

Der bedingte Start von Plugins wäre allgemein eine super Idee (gerade da ja start/stop) implementiert werden soll...
Ich habe das gleiche Problem mit dem Mähroboter, der mit der Cloud kommuniziert - da bietet sich evtl. eine übergreifende Lösung an, bevor pro Plugin gebastelt wird.

Die ICMP Erreichbarkeit von Hosts mit einem Retry-Timeout wäre ein erster Ansatz für eine Bedingung, die vor dem Plugin-Start erfüllt sein muss.
Weiter gedacht könnte man ein Monitoring einführen, die das Plugin stoppen solange ein Dienst nicht erreichbar ist.

[bmx]

Um solche Sachen einzubauen braucht es aber mehr Manpower (oder Womanpower) mit den paar Leuten die sich um Erweiterungen, Plugins, Doku & Co. kümmern reicht das nicht ...

[gama]

Klar - verstehe ich - ich kämpfe ja selbst hin und wieder mit "meinem" Plugin, welches ich endlich mal pushen möchte ... ich glaube nicht, das mein Wissen nicht ausreicht um im core rumzupatchen...