instance system.adapter.luftdaten already running

[ratte-rizzo]

Describe the bug
I've 2 instances of luftdaten adapter running. Both polling values from local sensors. One of the sensors is quite far away from the WiFi access point and thus has sometimes timeouts. The issue is now, that the adapter gets a timeout error, seems to be ended according to the log but is not ended and still running which causes an "already running" error message with the next activation. See log below. Never the less, the affected sensor is reacheable (but sometimes with extended timeouts).

See also ioBroker forum thread for additional discussion: https://forum.iobroker.net/topic/41153/

To Reproduce
Difficult to reproduce. Need to cause a time-out at the sensor.

Expected behavior
Correct termination of the adapter, even after a timeout.

Screenshots & Logfiles
2021-01-18 21:30:00.017 - info: host.himbeere instance system.adapter.luftdaten.1 started with pid 3708 2021-01-18 21:30:04.032 - info: host.himbeere instance system.adapter.luftdaten.0 started with pid 3733 2021-01-18 21:30:15.715 - info: host.himbeere instance system.adapter.luftdaten.0 terminated with code 0 (NO_ERROR) 2021-01-18 21:32:11.045 - error: luftdaten.1 (3708) connect ETIMEDOUT 192.168.178.113:80 2021-01-18 21:32:21.556 - info: host.himbeere instance system.adapter.luftdaten.1 terminated with code 0 (NO_ERROR) 2021-01-18 21:35:00.017 - info: host.himbeere instance system.adapter.luftdaten.0 started with pid 8461 2021-01-18 21:35:04.034 - info: host.himbeere instance system.adapter.luftdaten.1 started with pid 8476 2021-01-18 21:35:11.849 - info: host.himbeere instance system.adapter.luftdaten.0 terminated with code 0 (NO_ERROR) 2021-01-18 21:40:00.002 - warn: host.himbeere instance system.adapter.luftdaten.1 already running with pid 8476

Versions:

• Adapter version: 1.0.1
• JS-Controller version: 3.1.6
• Node version: 10.20.1
• Operating system: Linux

Additional context
n/a

[klein0r]

I've extended some timeouts to ensure the instance will be stopped after some seconds.

[Smo-RBR]

Ist mir jetzt auch schon an zwei Tagen mit der 2.2.2 passiert.

host.debian | 2022-04-06 18:24:00.034 | info | instance system.adapter.luftdaten.0 started with pid 3260677
-- | -- | -- | --
host.debian | 2022-04-06 18:21:00.849 | error | instance system.adapter.luftdaten.0 terminated with code 7 (ADAPTER_ALREADY_RUNNING)
host.debian | 2022-04-06 18:21:00.514 | info | instance system.adapter.luftdaten.0 terminated with code 11 (ADAPTER_REQUESTED_TERMINATION)
luftdaten.0 | 2022-04-06 18:21:00.340 | error | luftdaten.0 already running
host.debian | 2022-04-06 18:21:00.031 | info | instance system.adapter.luftdaten.0 started with pid 3256293
host.debian | 2022-04-06 18:19:54.840 | error | instance system.adapter.luftdaten.0 terminated with code 7 (ADAPTER_ALREADY_RUNNING)
luftdaten.0 | 2022-04-06 18:19:54.323 | error | luftdaten.0 already running
host.debian | 2022-04-06 18:19:54.015 | info | instance system.adapter.luftdaten.0 started with pid 3254979
host.debian | 2022-04-06 18:19:53.988 | info | instance scheduled system.adapter.luftdaten.0 */3 * * * *
host.debian | 2022-04-06 18:19:50.979 | info | stopInstance system.adapter.luftdaten.0 (force=false, process=false)
host.debian | 2022-04-06 18:19:49.793 | info | stopInstance system.adapter.luftdaten.0 (force=false, process=false)
host.debian | 2022-04-06 18:19:49.793 | info | "system.adapter.luftdaten.0" enabled
host.debian | 2022-04-06 18:19:49.064 | info | stopInstance canceled schedule system.adapter.luftdaten.0
host.debian | 2022-04-06 18:19:49.064 | info | stopInstance system.adapter.luftdaten.0 (force=false, process=false)
host.debian | 2022-04-06 18:19:49.064 | info | "system.adapter.luftdaten.0" disabled
host.debian | 2022-04-06 18:18:57.649 | error | instance system.adapter.luftdaten.0 terminated with code 7 (ADAPTER_ALREADY_RUNNING)
luftdaten.0 | 2022-04-06 18:18:57.124 | error | luftdaten.0 already running

[klein0r]

@Kettenknecht Du hast als Zeitplan alle 3 Minuten festgelegt

host.debian | 2022-04-06 18:19:53.988 | info | instance scheduled system.adapter.luftdaten.0 /3 *

Das ist natürlich schon sehr oft. Wenn die Timeouts entsprechend hoch konfiguriert sind und der Dienst (mal wieder) sehr langsam antwortet, kann das schon knapp werden. Je nachdem wieviele Sensoren in der Instanz konfiguriert sind.

[ratte-rizzo]

Also die 2.1.3 läuft bei mir absolut stabil (5min Rhythmus). Hingegen ist die neue 2.2.2 wie beim @Kettenknecht immer wieder als Zombie unterwegs.

[klein0r]

Mh, dann muss ich das nochmal ausführlicher testen. In der 2.2.x stoppe ich erst, wenn alles erledigt ist. In den vorigen Versionen wird immer nach 60 Sekunden die Instanz gestoppt. Egal wie der Status ist.

[ratte-rizzo]

Danke fürs weiter testen. Es kann dann wirklich daran liegen, dass nicht automatisch gestoppt wird. Einer meiner Sensoren hat nur sehr schwaches WLAN, von daher ist da die Chance auf einen Timeout sehr hoch. Wäre super, wenn sich die Instanz dann dennoch (nach 60s oder so) beenden würde. Vermutlich ist das dann auch der Grund, warum ein Zombie unterwegs ist...

[klein0r]

Naja aber auch ein Timeout ist ja ein definiertes Ende. Der läuft ja nicht unendlich, sondern nur so lange wie in der Instanz konfiguriert. Was hast Du da eingestellt?

[ratte-rizzo]

So gesehen hast Du recht.

Ich habe 60s Timeout, 5min Zyklus eingestellt und habe 2 lokale Sensoren. Einer hat starken Empfang und der andere wie gesagt schwach.

[klein0r]

Dann sollte die Instanz ja spätestens nach 2*60 Sekunden beendet werden und somit mit dem 5-Minuten-Intervall nicht kollidieren.

[ratte-rizzo]

Ich könnte am Sonntag nochmal einen Debug-Testlauf mit der 2.2.x starten, wenn Dir das was hilft.

[klein0r]

Ja, ein komplettes Debug-Log wäre sicher hilfreich. Ich wüsste gerade nicht, warum der Adapter nicht stoppen sollte.

[Smo-RBR]

Okay, hab den Timout mal hochgesetzt, auch hier ist der Wlan Empfang manchmal schwierig. Setz das Loglevel auch mal auf Debug, aber das kann bisschen dauern, war innert eines Monats das zweite mal jetzt.

[klein0r]

@Kettenknecht Bitte stell auch mal den Zeitplan der Instanz um. Alle 3 Minuten die Daten abfragen ist wirklich zu oft 😄

[Smo-RBR]

Naja, das Ding misst ale drei Minuten. Daten muss man nehmen wenn man sie bekommen kann :)

[klein0r]

Bitte mit 2.2.3 testen

[ratte-rizzo]

So, hier mal das Log mit 2.2.3 und einem nicht beendeten Durchlauf:

2022-04-13 08:50:04.937  - info: host.himbeere instance system.adapter.luftdaten.0 terminated with code 0 (NO_ERROR)
2022-04-13 08:55:00.024  - info: host.himbeere instance system.adapter.luftdaten.0 started with pid 23583
2022-04-13 08:55:00.647  - debug: luftdaten.0 (23583) Redis Objects: Use Redis connection: 127.0.0.1:9001
2022-04-13 08:55:00.666  - debug: luftdaten.0 (23583) Objects client ready ... initialize now
2022-04-13 08:55:00.666  - debug: luftdaten.0 (23583) Objects create System PubSub Client
2022-04-13 08:55:00.667  - debug: luftdaten.0 (23583) Objects create User PubSub Client
2022-04-13 08:55:00.712  - debug: luftdaten.0 (23583) Objects client initialize lua scripts
2022-04-13 08:55:00.720  - debug: luftdaten.0 (23583) Objects connected to redis: 127.0.0.1:9001
2022-04-13 08:55:00.743  - debug: luftdaten.0 (23583) Redis States: Use Redis connection: 127.0.0.1:9000
2022-04-13 08:55:00.755  - debug: luftdaten.0 (23583) States create System PubSub Client
2022-04-13 08:55:00.755  - debug: luftdaten.0 (23583) States create User PubSub Client
2022-04-13 08:55:00.825  - debug: luftdaten.0 (23583) States connected to redis: 127.0.0.1:9000
2022-04-13 08:55:00.909  - debug: luftdaten.0 (23583) Plugin sentry Initialize Plugin (enabled=true)
2022-04-13 08:55:01.109  - info:  luftdaten.0 (23583) starting. Version 2.2.3 (non-npm:  klein0r/ioBroker.luftdaten) in  /opt/iobroker/node_modules/iobroker.luftdaten, node: v14.19.1,  js-controller: 4.0.21
2022-04-13 08:55:01.169  - debug: luftdaten.0 (23583) [onReady] sensor deviceId exists: "feinstaub-garten"
2022-04-13 08:55:01.170  - debug: luftdaten.0 (23583) [onReady] sensor deviceId exists: "feinstaub-strasse"
2022-04-13 08:55:01.171  - debug: luftdaten.0 (23583) [onReady] found 2 sensors in configuration, requesting data
2022-04-13 08:55:01.172  - debug: luftdaten.0 (23583) [onReady] sensor 1/2 with idenfitier "feinstaub-garten" will be saved as deviceId "feinstaub-garten"
2022-04-13 08:55:01.176  - debug:  luftdaten.0 (23583) [fillSensorData] sensor "Garten" with type:  "local", identifier: "feinstaub-garten", deviceId: "feinstaub-garten"
2022-04-13 08:55:01.235  - debug: luftdaten.0 (23583) [fillSensorData] local request started (timeout 60s): http://feinstaub-garten/data.json
2022-04-13 08:55:01.267  - debug:  luftdaten.0 (23583) [fillSensorData] local request done after 0.03s -  received data (200):  {"software_version":"NRZ-2020-133","age":"46","sensordatavalues":[{"value_type":"SDS_P1","value":"12.90"},{"value_type":"SDS_P2","value":"6.60"},{"value_type":"BME280_temperature","value":"11.13"},{"value_type":"BME280_pressure","value":"101376.16"},{"value_type":"BME280_humidity","value":"83.44"},{"value_type":"samples","value":"10190416"},{"value_type":"min_micro","value":"28"},{"value_type":"max_micro","value":"20096"},{"value_type":"interval","value":"295000"},{"value_type":"signal","value":"-64"}]}
2022-04-13 08:55:01.308  - debug: luftdaten.0 (23583) [onReady] sensor 1/2 - data of deviceId  "feinstaub-garten" filled in 0.03s
2022-04-13 08:55:01.309  - debug: luftdaten.0 (23583) [onReady] sensor 2/2 with idenfitier "feinstaub-strasse" will be saved as deviceId "feinstaub-strasse"
2022-04-13 08:55:01.309  - debug:  luftdaten.0 (23583) [fillSensorData] sensor "Strasse" with type:  "local", identifier: "feinstaub-strasse", deviceId: "feinstaub-strasse"
2022-04-13 08:55:01.389  - debug: luftdaten.0 (23583) [fillSensorData] local request started (timeout 60s): http://feinstaub-strasse/data.json
2022-04-13 09:00:00.003  - warn: host.himbeere instance system.adapter.luftdaten.0 already running with pid 23583

[klein0r]

Okay, Problem gefunden. Lang laufende Requests werden an 2.2.4 abgebrochen. Ich dachte eigentlich, das macht die Timeout-Option, aber das ist nicht der Fall...

https://stackoverflow.com/questions/36690451/timeout-feature-in-the-axios-library-is-not-working