Failed to export to MinderGas: Unexpected status code received

[dennissiemensma]

Ik krijg sinds de laatste release elke dag de fout Failed to export to MinderGas: Unexpected status code received.

Ik heb de code herschreven, maar ik zie niet zo 1-2-3 waar het fout gaat. Hiervoor moet ik even lokaal debuggen tegen de live API.

[dennissiemensma]

De API van mindergas.nl is redelijk beperkt in communicatie en ik kan alleen zien dat er een fout optreed. Wellicht is het simpelweg wat te snel voor een v4 meter. Er is sowieso geen reden om direct na middernacht de gasstand te uploaden, dus ik zal er nog wat meer slack in doen. Hopelijk lost dat het issue op.

[dennissiemensma]

Kijken of dit het oplost en het een timing bug is. Anders is het iets anders.

[dennissiemensma]

Oke dat lost het wel op. Het is een timing ding en alleen een issue voor DSMR v4 vermoed ik. Gaat mee in patch.

[dajappie]

Hi Dennis, heb geupgrade naar v2.11.2 maar het probleem speelt nog altijd voor mij. RPi 3b met DSMR v4 en Python 3.5. Ook upgrade naar Python 3.6 geen effect voor het geval dat. Overigens lijken de meterstanden wel netjes bij MinderGas aan te komen, in de webinterface van MinderGas staan de afgelopen dagn gewoon vermeld.

The current logging level only logs warnings and errors, to reduce I/O. More information can be found here: https://dsmr-reader.readthedocs.io/en/v2/troubleshooting.html#logging
[2019-11-13 00:43:03,305] ERROR    MinderGas: Upload failed (HTTP 422): 
[2019-11-13 00:43:03,360] ERROR    Unexpected status code received
Traceback (most recent call last):
  File "/home/dsmr/dsmr-reader/dsmr_mindergas/services.py", line 32, in run
    export()
  File "/home/dsmr/dsmr-reader/dsmr_mindergas/services.py", line 79, in export
    raise AssertionError(_('Unexpected status code received'))
AssertionError: Unexpected status code received
[2019-11-14 00:58:03,583] ERROR    MinderGas: Upload failed (HTTP 422): 
[2019-11-14 00:58:03,587] ERROR    Unexpected status code received
Traceback (most recent call last):
  File "/home/dsmr/dsmr-reader/dsmr_mindergas/services.py", line 32, in run
    export()
  File "/home/dsmr/dsmr-reader/dsmr_mindergas/services.py", line 79, in export
    raise AssertionError(_('Unexpected status code received'))
AssertionError: Unexpected status code received
The current logging level only logs warnings and errors, to reduce I/O. More information can be found here: https://dsmr-reader.readthedocs.io/en/v2/troubleshooting.html#logging
[2019-11-15 00:25:01,737] ERROR    MinderGas: Upload failed (HTTP 422): 
[2019-11-15 00:25:01,771] ERROR    Unexpected status code received
Traceback (most recent call last):
  File "/home/dsmr/dsmr-reader/dsmr_mindergas/services.py", line 32, in run
    export()
  File "/home/dsmr/dsmr-reader/dsmr_mindergas/services.py", line 90, in export
    raise AssertionError(_('Unexpected status code received'))
AssertionError: Unexpected status code received

[dennissiemensma]

Bedankt voor je melding. Het lijkt erop dat er iets misgaat bij het doorgeven van de gasstand. Volgens je log geeft MinderGas code 422 terug en hun website geeft aan:

 422 Unprocessable Entity
Er is een validatiefout opgetreden. Dit kan komen door:

    Er is al een meterstand voor de opgegeven datum.
    De meterstand is geen getal.
    De meterstand is kleiner dan de vorige meterstand.
    De meterstand is groter dan de volgende meterstand.
    De datum ligt in de toekomst.
    De datum ligt voor 31 december 2005.

Tip: Je kan achterhalen wat er mis is door de meterstand handmatig in te voeren op de website. De foutmelding wordt op de website getoond. 

De meest voorkomende fout is Er is al een meterstand voor de opgegeven datum., maar dat kan ik niet voor je controleren.

Wat je nog kunt proberen is om in DSMR-reader naar /admin/dsmr_backend/scheduledprocess/ te gaan en daar het proces voor de meterstand-upload te plannen op de volgende dag tussen 03:00 en 06:00.

En je draait niet toevallig een dubbele instantie van DSMR-reader he? Die dan beiden de gasstand proberen te uploaden. :]

[dajappie]

Dat is het, er draait een dubbele instance. De supervisor config geeft netjes 4 processen, maar blijkbaar is er iets dat dsmrreader nogmaals aftrapt tijdens een reboot, het PID is ook een paar hoger dan de 4 opvolgende procesnummers die waarschijnlijk uit de 4 gedefinieerde processen van dsmr-reader.conf komen. In /var/log/supervisor/supervisord.log zie ik alleen die 4 processen, terwijl het extra proces wel netjes als user dsmr draait. Een kill helpt ook niet, het proces komt gewoon terug.

[dennissiemensma]

Heb je een screenshot of dump van de processen? Dat ze opnieuw gestart worden is ook het doel van Supervisor, het hangt er alleen vanaf over welke je het hebt. Alleen dsmr_backend stuurt meterstanden door en dat proces zou in principe niet dubbel moeten voorkomen.

[dajappie]

Hieronder een dumpje na een reboot van de hele RPi. Processen 833-836 zijn sequentieel genummerd en lijken volgens de /var/log/supervisord.log te komen uit de /etc/supervisor/conf.d/dsmr-reader.conf. Grote vraag is waarom wordt de laatste nogmaals gestart, er staat niks extra in de supervisord.log.

ps aux:

dsmr       833  2.1  1.8  23764 17948 ?        SN   10:10   0:01 /home/dsmr/.virtualenvs/dsmrreader/bin/python3.6 -u /home/dsmr/dsmr-reader/manage.py dsmr_mqtt
dsmr       834  2.6  1.7  21056 16292 ?        SN   10:10   0:01 /home/dsmr/.virtualenvs/dsmrreader/bin/python3.6 /home/dsmr/.virtualenvs/dsmrreader/bin/gunicorn --timeout 60 --max-requests 500 --bind unix:/var/tmp/gunicorn--dsmr_webinterface.socket --pid /var/tmp/gunicorn--dsmr_webinterface.pid dsmrreader.wsgi
dsmr       835  2.1  1.9  23764 18088 ?        SN   10:10   0:01 /home/dsmr/.virtualenvs/dsmrreader/bin/python3.6 -u /home/dsmr/dsmr-reader/manage.py dsmr_datalogger
dsmr       836  2.1  1.9  23764 18180 ?        SN   10:10   0:01 /home/dsmr/.virtualenvs/dsmrreader/bin/python3.6 -u /home/dsmr/dsmr-reader/manage.py dsmr_backend
dsmr       948  0.0  1.3  21056 12660 ?        SN   10:11   0:00 /home/dsmr/.virtualenvs/dsmrreader/bin/python3.6 /home/dsmr/.virtualenvs/dsmrreader/bin/gunicorn --timeout 60 --max-requests 500 --bind unix:/var/tmp/gunicorn--dsmr_webinterface.socket --pid /var/tmp/gunicorn--dsmr_webinterface.pid dsmrreader.wsgi

tail /var/log/supervisord.log:
2019-11-19 10:10:26,825 INFO supervisord started with pid 566
2019-11-19 10:10:27,834 INFO spawned: 'dsmr_mqtt' with pid 833
2019-11-19 10:10:27,846 INFO spawned: 'dsmr_webinterface' with pid 834
2019-11-19 10:10:27,856 INFO spawned: 'dsmr_datalogger' with pid 835
2019-11-19 10:10:27,866 INFO spawned: 'dsmr_backend' with pid 836
2019-11-19 10:10:28,870 INFO success: dsmr_mqtt entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-11-19 10:10:28,870 INFO success: dsmr_datalogger entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-11-19 10:10:28,871 INFO success: dsmr_backend entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2019-11-19 10:10:31,223 INFO success: dsmr_webinterface entered RUNNING state, process has stayed up for > than 3 seconds (startsecs)

[Ernst79]

I have this also with DSMR v2.2, so not limited to DSMR 4 meters (with v2.11.1).

[dennissiemensma]

@dajappie Gunicorn is de applicatieserver voor de webinterface en die kan meerdere instanties hebben. Dat is overigens niet erg en zoals bedoeld. De webserver voert zelf geen uploads uit, dat gebeurt alleen in dsmr_backend, waar altijd maar 1 instantie van is.

[dennissiemensma]

@dajappie je kunt anders debug-logging wel aanzetten en in de gaten houden op welke moment er een meterstand-upload gedaan wordt: MinderGas: Uploading gas meter position..

[dennissiemensma]

@Ernst79 try enabling debug logging and monitor the occurences of gas meter position uploads: MinderGas: Uploading gas meter position..

[Ernst79]

@dennissiemensma Heb de laatste foutmelding op 13-11 gehad. Ik houd het even in de gaten, maar zag jouw opmerking dat het alleen op DSMR v4 zou spelen. Vandaar mijn melding dat het ook op DSMR v2.2 speelt. Maar ik zal het in de gaten houden.

[dajappie]

Gisteren en vandaag geen foutmeldingen meer gezien, fingers crossed.