Landis+Gyr E650 sends data, but ends with "No or too long answer from Serial Device after last request."

[MichaelUray]

I did connect the meter via IR interface and it also sends a response to the start sequence "/?!" which the iobroker adapter sends out, but when the meter completed the frame, then the adapter ist still waiting and about 1 minute later it ends in a timout. It looks to me as if the adapter does not recognice the end of the frame

My serial monitor (jpnevulator) shows me the following communication between the adapter and the meter at the start:

2022-04-02 13:36:54.681215:
2F 3F 21 0D 0A                                  /?!..
2022-04-02 13:36:55.049011:
2F 4C 47 5A 35 5C 32 5A 4D 44 34 31 30 34 34 30 /LGZ5\2ZMD410440
37 2E 42 33 31 0D 0A                            7.B31..
2022-04-02 13:36:57.495505:
02 46 2E 46 28 30 30 30 30 30 30 30 30 29 0D 0A .F.F(00000000)..
30 2E 30 2E 30 28 35 30 33 30 32 35 38 35 29 0D 0.0.0(50302585).
0A 30 2E 31 2E 30 28 31 31 29 0D 0A 30 2E 31 2E .0.1.0(11)..0.1.
30 2A 31 31 28 32 32 2D 30 34 2D 30 31 20 30 30 0*11(22-04-01 00
3A 30 30 29 0D 0A 30 2E 31 2E 30 2A 31 30 28 32 :00)..0.1.0*10(2
32 2D 30 33 2D 30 31 20 30 30 3A 30 30 29 0D 0A 2-03-01 00:00)..
30 2E 31 2E 30 2A 30 39 28 32 32 2D 30 32 2D 30 0.1.0*09(22-02-0
31 20 30 30 3A 30 30 29 0D 0A 30 2E 31 2E 30 2A 1 00:00)..0.1.0*
30 38 28 32 32 2D 30 31 2D 30 31 20 30 30 3A 30 08(22-01-01 00:0
30 29 0D 0A 30 2E 31 2E 30 2A 30 37 28 32 31 2D 0)..0.1.0*07(21-
31 32 2D 30 31 20 30 30 3A 30 30 29 0D 0A 30 2E 12-01 00:00)..0.
31 2E 30 2A 30 36 28 32 31 2D 31 31 2D 30 31 20 1.0*06(21-11-01
30 30 3A 30 30 29 0D 0A 30 2E 31 2E 30 2A 30 35 00:00)..0.1.0*05
28 32 31 2D 31 30 2D 30 31 20 30 30 3A 30 30 29 (21-10-01 00:00)
0D 0A 30 2E 31 2E 30 2A 30 34 28 32 31 2D 30 39 ..0.1.0*04(21-09
2D 30 31 20 30 30 3A 30 30 29 0D 0A 30 2E 31 2E -01 00:00)..0.1.
30 2A 30 33 28 32 31 2D 30 38 2D 30 31 20 30 30 0*03(21-08-01 00
3A 30 30 29 0D 0A 30 2E 31 2E 30 2A 30 32 28 32 :00)..0.1.0*02(2
...

And it receives the following data at the end:

...
31 2E 37 28 30 33 2E 34 34 2A 41 29 0D 0A 35 31 1.7(03.44*A)..51
2E 37 28 30 33 2E 33 37 2A 41 29 0D 0A 37 31 2E .7(03.37*A)..71.
37 28 30 33 2E 33 35 2A 41 29 0D 0A 39 31 2E 37 7(03.35*A)..91.7
28 30 30 2E 30 34 2A 41 29 0D 0A 31 34 2E 37 28 (00.04*A)..14.7(
34 39 2E 39 39 2A 48 7A 29 0D 0A 38 31 2E 37 2E 49.99*Hz)..81.7.
30 28 20 20 20 30 2A 44 65 67 29 0D 0A 38 31 2E 0(   0*Deg)..81.
37 2E 31 28 20 31 32 30 2A 44 65 67 29 0D 0A 38 7.1( 120*Deg)..8
31 2E 37 2E 32 28 20 32 34 30 2A 44 65 67 29 0D 1.7.2( 240*Deg).
0A 38 31 2E 37 2E 34 28 20 31 39 39 2A 44 65 67 .81.7.4( 199*Deg
29 0D 0A 38 31 2E 37 2E 35 28 20 33 32 31 2A 44 )..81.7.5( 321*D
65 67 29 0D 0A 38 31 2E 37 2E 36 28 20 20 38 30 eg)..81.7.6(  80
2A 44 65 67 29 0D 0A 21 0D 0A 03 19             *Deg)..!....

After that data transmittion from the meter stopped, the adapter is still waiting and it ends then in a timeout.

smartmeter.0 | 2022-04-02 13:41:35.000 | debug | SCHEDULE NEXT RUN IN 300000s
-- | -- | -- | --
smartmeter.0 | 2022-04-02 13:41:34.999 | debug | DELETE rest of data (0) because new Message start with a new Request Message
smartmeter.0 | 2022-04-02 13:41:34.999 | debug | CURRENT SIGNON MESSAGE COUNTER 1 OF 1
smartmeter.0 | 2022-04-02 13:41:34.997 | debug | SERIALPORT REMOVE LISTENERS
smartmeter.0 | 2022-04-02 13:41:34.997 | debug | SERIALPORT CLOSE
smartmeter.0 | 2022-04-02 13:41:34.993 | debug | CLEAR MESSAGE TIMEOUT TIMER
smartmeter.0 | 2022-04-02 13:41:34.992 | debug | STOP
smartmeter.0 | 2022-04-02 13:41:34.992 | debug | Transport Reset!! Restart = true
smartmeter.0 | 2022-04-02 13:41:34.991 | debug | Error: No or too long answer from Serial Device after last request.
smartmeter.0 | 2022-04-02 13:41:34.990 | warn | No or too long answer from Serial Device after last request.
smartmeter.0 | 2022-04-02 13:41:34.989 | debug | Error: No or too long answer from Serial Device after last request.
smartmeter.0 | 2022-04-02 13:41:34.987 | debug | MESSAGE TIMEOUT TRIGGERED
smartmeter.0 | 2022-04-02 13:36:54.986 | debug | SET MESSAGE TIMEOUT TIMER2: 280000
smartmeter.0 | 2022-04-02 13:36:54.985 | debug | DONE SEND 0
smartmeter.0 | 2022-04-02 13:36:54.733 | debug | DONE SEND 1
smartmeter.0 | 2022-04-02 13:36:54.632 | debug | connected set to false
smartmeter.0 | 2022-04-02 13:36:54.625 | debug | TO SEND 1: /?!
smartmeter.0 | 2022-04-02 13:36:54.625 | debug | CURRENT PROCESS STEP 1 IN GETNEXTMESSAGE
smartmeter.0 | 2022-04-02 13:36:54.625 | debug | TO SEND 2:
smartmeter.0 | 2022-04-02 13:36:54.624 | debug | CURRENT PROCESS STEP 0 IN GETNEXTMESSAGE
smartmeter.0 | 2022-04-02 13:36:54.624 | debug | INITIAL MESSAGES TO SEND: 2
smartmeter.0 | 2022-04-02 13:36:54.620 | debug | SERIALPORT RESET BAUDRATE TO 300
smartmeter.0 | 2022-04-02 13:36:54.611 | debug | SERIALPORT OPEN
smartmeter.0 | 2022-04-02 13:36:54.607 | debug | CREATE SERIALPORT: 300 7 1 even
smartmeter.0 | 2022-04-02 13:36:54.605 | debug | SmartmeterObis  options:  {"debug":2,"protocol":"D0Protocol","transport":"SerialRequestResponseTransport","requestInterval":"300","anotherQueryDelay":"2000","transportSerialPort":"/dev/serial/by-id/usb-FTDI_USB_Serial_Converter_FTBYZZT3-if00-port0","transportSerialBaudrate":300,"transportSerialDataBits":7,"transportSerialStopBits":1,"transportSerialParity":"even","transportSerialMessageTimeout":280000,"protocolD0WakeupCharacters":null,"obisFallbackMedium":1}
smartmeter.0 | 2022-04-02 13:36:54.586 | info | starting. Version 3.3.4 in /opt/iobroker/node_modules/iobroker.smartmeter, node: v14.19.1, js-controller: 4.0.21
smartmeter.0 | 2022-04-02 13:36:54.447 | debug | Plugin sentry Initialize Plugin (enabled=true)
smartmeter.0 | 2022-04-02 13:36:54.433 | debug | States connected to redis: 127.0.0.1:9000
smartmeter.0 | 2022-04-02 13:36:54.429 | debug | States create User PubSub Client
smartmeter.0 | 2022-04-02 13:36:54.428 | debug | States create System PubSub Client
smartmeter.0 | 2022-04-02 13:36:54.425 | debug | Redis States: Use Redis connection: 127.0.0.1:9000
smartmeter.0 | 2022-04-02 13:36:54.414 | debug | Objects connected to redis: 127.0.0.1:9001
smartmeter.0 | 2022-04-02 13:36:54.411 | debug | Objects client initialize lua scripts
smartmeter.0 | 2022-04-02 13:36:54.403 | debug | Objects create User PubSub Client
smartmeter.0 | 2022-04-02 13:36:54.402 | debug | Objects create System PubSub Client
smartmeter.0 | 2022-04-02 13:36:54.401 | debug | Objects client ready ... initialize now
smartmeter.0 | 2022-04-02 13:36:54.381 | debug | Redis Objects: Use Redis connection: 127.0.0.1:9001
host.stocking | 2022-04-02 13:36:53.614 | info | instance system.adapter.smartmeter.0 started with pid 6566
host.stocking | 2022-04-02 13:36:53.592 | info | "system.adapter.smartmeter.0" enabled

These are my adapter settings:

Versions:

• Adapter version: 3.3.4
• JS-Controller version: 4.0.21
• Node version: 14.19.1
• Operating system: Debian 11

There is the full data response to find which the meter sent me via a terminal after sending "/?!" https://forum.iobroker.net/topic/47328/smartmeter-adapter-probleme/25?_=1648889794421

[Apollon77]

Interesting ... you discbered a bug noone else had in the last years ... the reason is that a ) is the last character before the "end" sequence. WIll provide a fix soon

[Apollon77]

PS: Are you really sure it is this problem? Because I can not reproduce it ... and when looking at the posted Debug log I do not see anything incomig at all ... So ... no data are received (make sure to NOT have a read command on the serial port running in a shell in parallel!! Then adapter will not get any data

[MichaelUray]

Oh boy, you are absolutly right, it did not receive anything since my "sniffer" was blocking the received data. Fixing that I get at least some data into the log, but now I run into the issue, that it reports MESSAGE TIMEOUT TRIGGERED No or too long answer from Serial Device after last request. What could cause that?

Please find there the full log file. iobroker.2022-04-02.log.zip

[Apollon77]

I close here ... we iterate in Forum ... two places makes no sense :-)