search

Apollon77 / ioBroker.smartmeter

ioBroker-Adapter to read out Smart-Meter using protocols like SML, D0 and such
MIT License
36 stars 17 forks source link

Redirect via socat not working #374

Closed stephanritscher closed 1 year ago

stephanritscher commented 1 year ago

I'm running iobroker on computer A and a second B with the usb serial connector. On A, I run

socat PTY,raw,echo=0,link=/dev/ttySMARTMETER tcp:B:4444

and set device to /dev/ttySMARTMETER in ioBroker.smartmeter.

On B, I run

socat /dev/ttyUSB0,raw,echo=0 tcp-listen:4444,reuseaddr

Then ioBroker logs show Error: No or too long answer from Serial Device after last request. for the smartmeter instance.

Expected behavior
ioBroker.smartmeter should be able to read meter values as if the serial device was connected to A directly.

Versions:

Additional context
When connecting the usb serial connector to A, ioBroker.smartmeter can read out the meter values flawlessly. I'm searching for any working (lightweight) solution for redirecting the serial communication via (local) network, not necessarily socat.

Apollon77 commented 1 year ago

That depends a lot. How is your configuration in smartmeter?

Normally with socal you need to hard configure the baudrate - I do not see this in your parameters. This also means that it only works with SML because with D0 wthere is a baudrate changeover potentially which is not popssible with socat.

stephanritscher commented 1 year ago

Thanks for the quick response! My setup is with a SML (1.03/1.04) meter. I tried with empty settings for data transfer and explicitely setting the defaults to confirm I use the right values with socat below. I tried with using the symbolic link /dev/ttySMARTMETER or the explicit character device (e.g. /dev/pts/3) both entered via user defined device name. I updated my commands based on your hint: On A:

socat -d -d -v -b1 PTY,rawer,link=/dev/ttySMARTMETER,b9600,cs8,cstopb=0,parenb=0 tcp:B:4444

On B:

socat -d -d -v -b1 /dev/ttyUSB0,rawer,b9600,cs8,cstopb=0,parenb=0 tcp-listen:4444,reuseaddr

My thoughts:

After 19456 bytes, the output of transferred data on A stops while it continues on B. If I add wait-slave option to the socat PTY device parameters on A, no transferred data is displayed, neither on A nor B. If I execute cat < /dev/ttySMARTMETER on A, however, transferred data is displayed.

My current conclusion would be that somehow the PTY device /dev/ttySMARTMETER on A isn't successfully opened by ioBroker.smartmeter, however even on silly debug level nothing closely related is displayed. The last messages before the timeout are

SmartmeterObis options: {"debug":0,"protocol":"SmlProtocol","transport":"SerialResponseTransport","requestInterval":"300","anotherQueryDelay":"1000","transportSerialPort":"/dev/ttySMARTMETER","transportSerialBaudrate":9600,"transportSerialDataBits":8,"transportSerialStopBits":1,"transportSerialParity":"none","transportSerialMessageTimeout":null,"protocolSmlIgnoreInvalidCRC":false}
connected set to false
Apollon77 commented 1 year ago

Pleas epost a full debug log

stephanritscher commented 1 year ago 
2023-05-26 21:37:26.947  - info: host.A "system.adapter.smartmeter.0" enabled
2023-05-26 21:37:26.974  - info: host.A instance system.adapter.smartmeter.0 started with pid 897721
2023-05-26 21:37:27.834  - debug: smartmeter.0 (897721) Redis Objects: Use Redis connection: 127.0.0.1:6379
2023-05-26 21:37:27.864  - debug: smartmeter.0 (897721) Objects client ready ... initialize now
2023-05-26 21:37:27.865  - debug: smartmeter.0 (897721) Objects create System PubSub Client
2023-05-26 21:37:27.866  - debug: smartmeter.0 (897721) Objects create User PubSub Client
2023-05-26 21:37:27.895  - debug: smartmeter.0 (897721) Objects client initialize lua scripts
2023-05-26 21:37:27.899  - debug: smartmeter.0 (897721) Objects connected to redis: 127.0.0.1:6379
2023-05-26 21:37:27.912  - debug: smartmeter.0 (897721) Redis States: Use Redis connection: 127.0.0.1:6379
2023-05-26 21:37:27.916  - debug: smartmeter.0 (897721) States create System PubSub Client
2023-05-26 21:37:27.917  - debug: smartmeter.0 (897721) States create User PubSub Client
2023-05-26 21:37:27.922  - debug: smartmeter.0 (897721) States connected to redis: 127.0.0.1:6379
2023-05-26 21:37:27.936  - debug: smartmeter.0 (897721) Plugin sentry Do not initialize Plugin (enabled=false)
2023-05-26 21:37:27.940  - debug: smartmeter.0 (897721) Plugin sentry destroyed because not initialized correctly
2023-05-26 21:37:27.971  - info: smartmeter.0 (897721) starting. Version 3.3.4 in /opt/iobroker/node_modules/iobroker.smartmeter, node: v18.16.0, js-controller: 4.0.24
2023-05-26 21:37:27.993  - debug: smartmeter.0 (897721) SmartmeterObis options: {"debug":2,"protocol":"SmlProtocol","transport":"SerialResponseTransport","requestInterval":"300","anotherQueryDelay":"1000","transportSerialPort":"/dev/ttySMARTMETER","transportSerialBaudrate":null,"transportSerialMessageTimeout":null,"protocolSmlIgnoreInvalidCRC":false}
2023-05-26 21:37:27.995  - debug: smartmeter.0 (897721) CREATE SERIALPORT: 9600 8 1 none
2023-05-26 21:37:28.000  - debug: smartmeter.0 (897721) SET MESSAGE TIMEOUT TIMER: 120000
2023-05-26 21:37:28.011  - debug: smartmeter.0 (897721) connected set to false
2023-05-26 21:39:28.001  - debug: smartmeter.0 (897721) MESSAGE TIMEOUT TRIGGERED
2023-05-26 21:39:28.003  - debug: smartmeter.0 (897721) Error: No or too long answer from Serial Device after last request.
2023-05-26 21:39:28.005  - warn: smartmeter.0 (897721) No or too long answer from Serial Device after last request.
2023-05-26 21:39:28.005  - debug: smartmeter.0 (897721) Error: No or too long answer from Serial Device after last request.
2023-05-26 21:39:28.006  - debug: smartmeter.0 (897721) Transport Reset!! Restart = true
2023-05-26 21:39:28.007  - debug: smartmeter.0 (897721) SCHEDULE NEXT RUN IN 300s
2023-05-26 21:44:28.010  - debug: smartmeter.0 (897721) CREATE SERIALPORT: 9600 8 1 none
2023-05-26 21:44:28.013  - debug: smartmeter.0 (897721) SET MESSAGE TIMEOUT TIMER: 120000
2023-05-26 21:46:28.014  - debug: smartmeter.0 (897721) MESSAGE TIMEOUT TRIGGERED
2023-05-26 21:46:28.015  - debug: smartmeter.0 (897721) Error: No or too long answer from Serial Device after last request.
2023-05-26 21:46:28.015  - warn: smartmeter.0 (897721) No or too long answer from Serial Device after last request.
2023-05-26 21:46:28.016  - debug: smartmeter.0 (897721) Error: No or too long answer from Serial Device after last request.
2023-05-26 21:46:28.016  - debug: smartmeter.0 (897721) Transport Reset!! Restart = true
2023-05-26 21:46:28.017  - debug: smartmeter.0 (897721) SCHEDULE NEXT RUN IN 300s

Now with log level debug as described in your readme I have more messages than yesterday with log level silly - kind of unexpected. Probably the logic for setting the debug parameter for SmartmeterOrbis doesn't respect the silly level.

Apollon77 commented 1 year ago

Also wie man sieht öffnet der Adapter den seriellen port und bekommt aber keinerlei Daten.

Was sagt denn socat wenn du es im Debug Modus startest?

stephanritscher commented 1 year ago 
socat -d -d -d -d -v -b1 PTY,rawer,link=/dev/ttySMARTMETER,b9600,cs8,cstopb=0,parenb=0,wait-slave tcp:raspberry:4444 2>&1 | tee a.log

a.log

socat -d -d -d -d -v /dev/ttyUSB1,rawer,b9600,cs8,cstopb=0,parenb=0 tcp-listen:4444,reuseaddr 2>&1 | tee b.log

b.log

grep smartmeter /opt/iobroker/logs/iobroker.current.log

2023-05-28 00:44:26.852  - info: host.A stopInstance system.adapter.smartmeter.0 (force=false, process=true)
2023-05-28 00:44:26.854  - info: smartmeter.0 (14302) Got terminate signal TERMINATE_YOURSELF
2023-05-28 00:44:26.853  - info: host.A stopInstance system.adapter.smartmeter.0 send kill signal
2023-05-28 00:44:26.855  - info: smartmeter.0 (14302) terminating
2023-05-28 00:44:26.856  - info: smartmeter.0 (14302) Terminated (ADAPTER_REQUESTED_TERMINATION): Without reason
2023-05-28 00:44:27.381  - info: host.A instance system.adapter.smartmeter.0 terminated with code 11 (ADAPTER_REQUESTED_TERMINATION)
2023-05-28 00:44:29.901  - info: host.A instance system.adapter.smartmeter.0 started with pid 16547
2023-05-28 00:44:30.780  - debug: smartmeter.0 (16547) Redis Objects: Use Redis connection: 127.0.0.1:6379
2023-05-28 00:44:30.808  - debug: smartmeter.0 (16547) Objects client ready ... initialize now
2023-05-28 00:44:30.809  - debug: smartmeter.0 (16547) Objects create System PubSub Client
2023-05-28 00:44:30.810  - debug: smartmeter.0 (16547) Objects create User PubSub Client
2023-05-28 00:44:30.840  - debug: smartmeter.0 (16547) Objects client initialize lua scripts
2023-05-28 00:44:30.844  - debug: smartmeter.0 (16547) Objects connected to redis: 127.0.0.1:6379
2023-05-28 00:44:30.856  - debug: smartmeter.0 (16547) Redis States: Use Redis connection: 127.0.0.1:6379
2023-05-28 00:44:30.860  - debug: smartmeter.0 (16547) States create System PubSub Client
2023-05-28 00:44:30.861  - debug: smartmeter.0 (16547) States create User PubSub Client
2023-05-28 00:44:30.867  - debug: smartmeter.0 (16547) States connected to redis: 127.0.0.1:6379
2023-05-28 00:44:30.882  - debug: smartmeter.0 (16547) Plugin sentry Do not initialize Plugin (enabled=false)
2023-05-28 00:44:30.886  - debug: smartmeter.0 (16547) Plugin sentry destroyed because not initialized correctly
2023-05-28 00:44:30.925  - info: smartmeter.0 (16547) starting. Version 3.3.4 in /opt/iobroker/node_modules/iobroker.smartmeter, node: v18.16.0, js-controller: 4.0.24
2023-05-28 00:44:30.944  - debug: smartmeter.0 (16547) SmartmeterObis options: {"debug":2,"protocol":"SmlProtocol","transport":"SerialResponseTransport","requestInterval":"300","anotherQueryDelay":"1000","transportSerialPort":"/dev/ttySMARTMETER","transportSerialBaudrate":null,"transportSerialMessageTimeout":null,"protocolSmlIgnoreInvalidCRC":false}
2023-05-28 00:44:30.946  - debug: smartmeter.0 (16547) CREATE SERIALPORT: 9600 8 1 none
2023-05-28 00:44:30.951  - debug: smartmeter.0 (16547) SET MESSAGE TIMEOUT TIMER: 120000
2023-05-28 00:44:30.964  - debug: smartmeter.0 (16547) connected set to false
2023-05-28 00:46:30.952  - debug: smartmeter.0 (16547) MESSAGE TIMEOUT TRIGGERED
2023-05-28 00:46:30.954  - debug: smartmeter.0 (16547) Error: No or too long answer from Serial Device after last request.
2023-05-28 00:46:30.956  - warn: smartmeter.0 (16547) No or too long answer from Serial Device after last request.
Apollon77 commented 1 year ago

Honestly ... no idea ... I would have expected to see in socat log when the adapter tries to open the port but there is nothing about that in the logs. also no error sin iobroker ... and when you use cat or such on commandline you get that data?

stale[bot] commented 1 year ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs within the next 7 days. Please check if the issue is still relevant in the most current version of the adapter and tell us. Also check that all relevant details, logs and reproduction steps are included and update them if needed. Thank you for your contributions. Dieses Problem wurde automatisch als veraltet markiert, da es in letzter Zeit keine Aktivitäten gab. Es wird geschlossen, wenn nicht innerhalb der nächsten 7 Tage weitere Aktivitäten stattfinden. Bitte überprüft, ob das Problem auch in der aktuellsten Version des Adapters noch relevant ist, und teilt uns dies mit. Überprüft auch, ob alle relevanten Details, Logs und Reproduktionsschritte enthalten sind bzw. aktualisiert diese. Vielen Dank für Eure Unterstützung.

stale[bot] commented 1 year ago

This issue has been automatically closed because of inactivity. Please open a new issue if still relevant and make sure to include all relevant details, logs and reproduction steps. Thank you for your contributions. Dieses Problem wurde aufgrund von Inaktivität automatisch geschlossen. Bitte öffnet ein neues Issue, falls dies noch relevant ist und stellt sicher das alle relevanten Details, Logs und Reproduktionsschritte enthalten sind. Vielen Dank für Eure Unterstützung.

stephanritscher commented 1 year ago

Maybe it was a permission issue like #378 - the symptoms were the same and I don't explicitly remember checking the device permissions. Not sure if I will try this solution again. I think running an iobroker slave (see #378) should be more stable with regards to stability than redirecting the device via socat (e.g. if one of the hosts restarts). I was already wondering back then what it would need to detect hung up connections and automatically restart the link and the data collection.