Neue Versionen und Support zum Modbus-Modul

Begonnen von StefanStrobel, 20 August 2017, 12:11:08

Vorheriges Thema - Nächstes Thema
Drucken
Nach unten Seiten 1 ... 37 38 39 40 41 ... 87
Benutzer-Aktionen

StefanStrobel

#570
08 November 2020, 19:28:14
Hallo Roger,

Utils.pm gehört nach lib/FHEM/HTTPMOD.
Da sind Funktionen drin, die HTTPMOD, Modbus und künftig noch andere Module gemeinsam nutzen.

Gruß
    Stefan

Roger

#571
09 November 2020, 13:45:22 Letzte Bearbeitung: 09 November 2020, 18:40:06 von Roger
Hi Stefan,
auch es gibt ja auch zwei lib-Verzeichnisse:
- lib/FHEM/...
- FHEM/lib/...
Warum auch immer.

Die neue Utils.pm habe nun nach lib/FHEM/HTTPMOD kopiert.

//Roger
Zotac & RPIs mit 10*FHEM
2*HM-LAN, 2*JeeLink, 2*RS485, SignalESP
HomeMatic, PCA301 Komponenten, ModBus: Stromzähler, Fronius WR, Shelly, Victron

gadget

#572
10 November 2020, 10:12:16
Hallo,

ich wollte nur mal kurz loswerden, dass ich gestern ein völlig unbenutzbares fhem hatte und das kam so:

Ich habe einen Temperatur/Feuchte Sensor, der per Modbus abfragbar ist. Dieser hängt an einem Serial - USB Adapter. Dieser steckt wiederum an einem raspi auf dem ser2net läuft. Der fhem Server bzw. das Modbus-Modul greift über Netzwerk auf ser2net zu. Das Konstrukt läuft seit über einem Jahr problemlos. Jetzt hatte ich offenbar ein Problem bei der USB-Verbindung des Serial-USB-Adapters. Das hatte zur Folge, dass der Port auf dem raspi mit dem ser2net wohl nicht mehr zu öffnen war, der pi selbst war aber noch online. fhem-seitig ist dann aber das MODUS-Device Amok gelaufen und hat im Millisekunden-Abstand versucht, den Port wieder zu öffnen (und dabei natürlich auch das Log geflutet etc.). Letztendlich hat das dann die ganze fhem-Installation in die Knie gezwungen, inklusive Heizungssteuerung (fröstel). Ich hätte eigentlich erwartet, das so etwas nicht passiert, insbesondere wenn maxTimeoutsToReconnect und nextOpenDelay gesetzt sind.  Vielleicht kann da ja mal jemand an die entscheidenen Stellen im Code kritisch anschauen bzw. das auch mal nachstellen mit einem ser2net. Wahrscheinlich kann man das sogar reproduzieren, wenn man das ser2net per loopback direkt auf dem fhem-Server verwendet. Ich hänge ein List an. Soll natürlich keine Kritik an dem ansonsten tollen Modul und der vielen Arbeit sein, die da rein gesteckt wurde.

Mein Modbus-Device:

Code Auswählen

Internals:
   DEF        1 60 192.168.178.135:2002 RTU
   DeviceName 192.168.178.135:2002
   EXPECT     idle
   FD         204
   FUUID      5d8cc401-f33f-6385-e4cd-4cdd0c0360cf282b
   INTERVAL   60
   IODev      PKTH400A
   LASTOPEN   1604941486.48958
   MODBUSID   1
   MODE       master
   MODULEVERSION Modbus 4.1.5 - 17.9.2019
   NAME       PKTH400A
   NOTIFYDEV  global
   NR         759
   NTFY_ORDER 50-PKTH400A
   PARTIAL   
   PROTOCOL   RTU
   STATE      18.5 °C 86 %
   TCPConn    1
   TRIGGERTIME 1604998345.19715
   TRIGGERTIME_FMT 2020-11-10 09:52:25
   TRIGGERTIME_SAVED
   TYPE       ModbusAttr
   devioLoglevel 3
   lastUpdate 1604998285.19715
   nextOpenDelay 40
   QUEUE:
   READ:
     BUFFER     
   READINGS:
     2020-11-10 09:09:10   dewpoint        16.2
     2020-11-10 09:51:27   humidity        86.4
     2020-11-09 18:04:46   state           opened
     2020-11-10 09:51:25   temperature     18.5
   REMEMBER:
     lid        1
     lname      PKTH400A
     lrecv      1604998287.4279
     lsend      1604998286.64982
   defptr:
     PKTH400A   1
   gotReadings:
     humidity   86.4
   lastRead:
     h0         1604998285.97811
     h1         1604998287.42992
Attributes:
   alias      Estrich
   dev-h-defPoll 1
   disable    0
   event-aggregator temperature:6000:linear:mean,humidity:6000:linear:mean
   event-min-interval state:6000,temperature:6000,humidity:6000
   event-on-change-reading humidity,temperature
   group      Temperatur
   icon       scene_swimming
   maxTimeoutsToReconnect 100
   nextOpenDelay 40
   obj-h0-expr $val / 10
   obj-h0-reading temperature
   obj-h1-expr $val / 10
   obj-h1-reading humidity
   openTimeout 20
   room       Keller,Modbus
   sortby     Z99
   stateFormat {sprintf( "%.1f °C %.0f %%",ReadingsVal($name,"temperature",0),ReadingsVal($name,"humidity",0))}
   userattr   dev-h-defPoll obj-h0-expr obj-h0-reading obj-h1-expr obj-h1-reading obj-h2-reading


ser2net.conf:

Code Auswählen

BANNER:banner:\r\nser2net port \p device \d [\s] (Debian GNU/Linux)\r\n\r\n
# ModBus
2002:raw:0:/dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_0001-if00-port0:9600 1STOPBIT 8DATABITS HANGUP_WHEN_DONE


Grüße, gadget

StefanStrobel

#573
10 November 2020, 19:51:45
Hallo Gadget,

was kam denn im Log in dieser Zeit?
Könntest Du da mal einen Ausschnitt posten?

Gruss / Thanx
   Stefan

gadget

#574
14 November 2020, 17:25:25
Hallo,

das sind die Logeinträge von 2 Sekunden

Code Auswählen

2020.11.09 17:56:55 3: 192.168.178.135:2002 disconnected, waiting to reappear (PKTH400A)
2020.11.09 17:56:56 3: 192.168.178.135:2002 reappeared (PKTH400A)
2020.11.09 17:56:57 3: PKTH400A: read got new data while idle, drop buffer 506f727420616c726561647920696e207573650d0a
2020.11.09 17:56:57 3: 192.168.178.135:2002 disconnected, waiting to reappear (PKTH400A)
2020.11.09 17:56:57 3: 192.168.178.135:2002 reappeared (PKTH400A)
2020.11.09 17:56:57 3: PKTH400A: read got new data while idle, drop buffer 506f727420616c726561647920696e207573650d0a
2020.11.09 17:56:57 3: 192.168.178.135:2002 disconnected, waiting to reappear (PKTH400A)
2020.11.09 17:56:57 3: 192.168.178.135:2002 reappeared (PKTH400A)
2020.11.09 17:56:57 3: PKTH400A: read got new data while idle, drop buffer 506f727420616c726561647920696e207573650d0a
2020.11.09 17:56:57 3: 192.168.178.135:2002 disconnected, waiting to reappear (PKTH400A)
2020.11.09 17:56:57 3: 192.168.178.135:2002 reappeared (PKTH400A)
2020.11.09 17:56:57 3: PKTH400A: read got new data while idle, drop buffer 506f727420616c726561647920696e207573650d0a
2020.11.09 17:56:57 3: 192.168.178.135:2002 disconnected, waiting to reappear (PKTH400A)
2020.11.09 17:56:57 3: 192.168.178.135:2002 reappeared (PKTH400A)
2020.11.09 17:56:57 3: PKTH400A: read got new data while idle, drop buffer 506f727420616c726561647920696e207573650d0a
2020.11.09 17:56:57 3: 192.168.178.135:2002 disconnected, waiting to reappear (PKTH400A)
2020.11.09 17:56:57 3: 192.168.178.135:2002 reappeared (PKTH400A)
2020.11.09 17:56:57 3: PKTH400A: read got new data while idle, drop buffer 506f727420616c726561647920696e207573650d0a
2020.11.09 17:56:57 3: 192.168.178.135:2002 disconnected, waiting to reappear (PKTH400A)
2020.11.09 17:56:57 3: 192.168.178.135:2002 reappeared (PKTH400A)
2020.11.09 17:56:58 3: PKTH400A: read got new data while idle, drop buffer 506f727420616c726561647920696e207573650d0a
2020.11.09 17:56:58 3: 192.168.178.135:2002 disconnected, waiting to reappear (PKTH400A)
2020.11.09 17:56:58 3: 192.168.178.135:2002 reappeared (PKTH400A)
2020.11.09 17:56:58 3: PKTH400A: read got new data while idle, drop buffer 506f727420616c726561647920696e207573650d0a
2020.11.09 17:56:58 3: 192.168.178.135:2002 disconnected, waiting to reappear (PKTH400A)
2020.11.09 17:56:58 3: 192.168.178.135:2002 reappeared (PKTH400A)
2020.11.09 17:56:58 3: PKTH400A: read got new data while idle, drop buffer 506f727420616c726561647920696e207573650d0a
2020.11.09 17:56:58 3: 192.168.178.135:2002 disconnected, waiting to reappear (PKTH400A)
2020.11.09 17:56:58 3: 192.168.178.135:2002 reappeared (PKTH400A)


Grüße, gadget

StefanStrobel

#575
15 November 2020, 15:24:53
Hallo Gadget,

danke für das Log.
Ich werde mal auf die Suche gehen.
Falls Du eine Test-Config posten kannst, mit der man das Problem nachvollziehen kann, wäre das natürlich sehr hilfreich.

Gruss / Thanx
   Stefan

gadget

#576
16 November 2020, 11:52:05
Wäre super wenn Du da was finden würdest.
Nachstellen wäre denke ich am einfachsten, wenn man einen USB-Adapter, der direkt am fhem-Server hängt, statt direkt vom Modul über ser2net per loopback (127.0.0.1) zugreift, also statt

Code Auswählen

define modbus Modbus /dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_0001-if00-port0@9600,8,N,1
attr modbus ModbusAttr 1 60



den Stick an ser2net betreiben

Code Auswählen


apt-get install ser2net

nano /etc/ser2net.conf :

2002:raw:0:/dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_0001-if00-port0:9600 1STOPBIT 8DATABITS HANGUP_WHEN_DONE
systemctl enable ser2net
systemctl start ser2net
systemctl status ser2net


und den define ändern in

Code Auswählen

define modbus Modbus 1 60 127.0.0.1:2002 RTU



Damit sollte erst mal alles normal weiterlaufen. Wenn man nun den Stick abzieht (und ggf. auch den pi durchstartet) müsste das ungewünschte Verhalten auftreten.

Grüße, gadget

StefanStrobel

#577
17 November 2020, 19:19:22
Hallo Gadget,

ich konnte das Phänomen nachstellen.
Das Problem ist dass ser2net in dieser Situation die TCP-Verbindung von Fhem akzeptiert und dann sofort wieder schließt.
Der Parameter nextOpenDelay greift hier nicht, weil die Verbindung ja erfolgreich aufgebaut wurde.
Es gibt viele Konfigurationen, in denen das Modbus-Modul bei Verlust der TCP-Verbindung diese sofort wieder aufbauen soll. daher ist die Lösung nicht so ganz offensichtlich. Bin noch am überlegen, wie man das ohne andere Seiteneffeke verhindern könnte...

Gruss
   Stefan

killah78

#578
18 November 2020, 09:50:05
Hi kurze Frage:
Ich habe mehrere Modbus Devices eingebunden mit ModbusAttr.
Wenn ich apptime starte, bekomme ich keine Modbus Antworten mehr.
Erst nach einem FHEM Neustart kommen wieder Modbus Nachrichten.
Kann das jemand bestätigen? Oder habe ich ein lokales Problem?

Gruss

StefanStrobel

#579
19 November 2020, 17:37:14
Hallo,

mir ist das Problem nicht bekannt.
Poste doch mal die genaue Konfiguration und wie man das Problem nachstellen kann.
Am besten auch einen Log-Auszug mit verbose 5 für die Modbus-Geräte.

Gruss
    Stefan

killah78

#580
20 November 2020, 11:12:27 Letzte Bearbeitung: 23 November 2020, 11:21:48 von killah78
Hallo Stefan

hier ein Verbose5 von dem Gerät "KSEM" vor dem Aufruf von apptime. In den letzten 2 Zeilen sieht man eine Warning vom Starten von Apptime.

Code Auswählen
2020.11.20 10:53:00.519 5: KSEM: GetUpdate called from HandleTimeout
2020.11.20 10:53:00.519 5: KSEM: SetartUpdateTimer called from GetUpdate updated timer, will call GetUpdate in 30.0 sec at 2020-11-20 10:53:30, interval 30
2020.11.20 10:53:00.520 5: KSEM: GetUpdate objects from attributes: h42 h40 h0 h122 h752 h592 h512 h596 h756 h672 h516 h120 h82 h80 h2 h676
2020.11.20 10:53:00.520 5: KSEM: GetUpdate full object list: h0 h120 h122 h2 h40 h42 h512 h516 h592 h596 h672 h676 h752 h756 h80 h82
2020.11.20 10:53:00.520 5: KSEM: GetUpdate check h0 => Active_Power_total_+_W, poll = 1, last = 0
2020.11.20 10:53:00.520 4: KSEM: GetUpdate will request Active_Power_total_+_W
2020.11.20 10:53:00.520 5: KSEM: GetUpdate check h120 => Active_Power_L3_+_W, poll = 1, last = 1605865965.65916
2020.11.20 10:53:00.520 4: KSEM: GetUpdate will request Active_Power_L3_+_W
2020.11.20 10:53:00.520 5: KSEM: GetUpdate check h122 => Active_Power_L3_-_W, poll = 1, last = 0
2020.11.20 10:53:00.521 4: KSEM: GetUpdate will request Active_Power_L3_-_W
2020.11.20 10:53:00.521 5: KSEM: GetUpdate check h2 => Active_Power_total_-_W, poll = 1, last = 1605865969.87493
2020.11.20 10:53:00.521 4: KSEM: GetUpdate will request Active_Power_total_-_W
2020.11.20 10:53:00.521 5: KSEM: GetUpdate check h40 => Active_Power_L1_+_W, poll = 1, last = 1605865954.69412
2020.11.20 10:53:00.521 4: KSEM: GetUpdate will request Active_Power_L1_+_W
2020.11.20 10:53:00.521 5: KSEM: GetUpdate check h42 => Active_Power_L1_-_W, poll = 1, last = 1605865968.64777
2020.11.20 10:53:00.521 4: KSEM: GetUpdate will request Active_Power_L1_-_W
2020.11.20 10:53:00.521 5: KSEM: GetUpdate check h512 => Active_Energy_total_+_Wh, poll = 1, last = 1605865958.145
2020.11.20 10:53:00.521 4: KSEM: GetUpdate will request Active_Energy_total_+_Wh
2020.11.20 10:53:00.522 5: KSEM: GetUpdate check h516 => Active_Energy_total_-_Wh, poll = 1, last = 1605865970.30209
2020.11.20 10:53:00.522 4: KSEM: GetUpdate will request Active_Energy_total_-_Wh
2020.11.20 10:53:00.522 5: KSEM: GetUpdate check h592 => Active_Energy_L1_+_Wh, poll = 1, last = 1605865969.15706
2020.11.20 10:53:00.522 4: KSEM: GetUpdate will request Active_Energy_L1_+_Wh
2020.11.20 10:53:00.522 5: KSEM: GetUpdate check h596 => Active_Energy_L1_-_Wh, poll = 1, last = 1605865970.48032
2020.11.20 10:53:00.522 4: KSEM: GetUpdate will request Active_Energy_L1_-_Wh
2020.11.20 10:53:00.522 5: KSEM: GetUpdate check h672 => Active_Energy_L2_+_Wh, poll = 1, last = 1605865969.3816
2020.11.20 10:53:00.522 4: KSEM: GetUpdate will request Active_Energy_L2_+_Wh
2020.11.20 10:53:00.522 5: KSEM: GetUpdate check h676 => Active_Energy_L2_-_Wh, poll = 1, last = 1605865968.84743
2020.11.20 10:53:00.522 4: KSEM: GetUpdate will request Active_Energy_L2_-_Wh
2020.11.20 10:53:00.523 5: KSEM: GetUpdate check h752 => Active_Energy_L3_+_Wh, poll = 1, last = 1605865969.71687
2020.11.20 10:53:00.523 4: KSEM: GetUpdate will request Active_Energy_L3_+_Wh
2020.11.20 10:53:00.523 5: KSEM: GetUpdate check h756 => Active_Energy_L3_-_Wh, poll = 1, last = 1605865954.27527
2020.11.20 10:53:00.523 4: KSEM: GetUpdate will request Active_Energy_L3_-_Wh
2020.11.20 10:53:00.523 5: KSEM: GetUpdate check h80 => Active_Power_L2_P_W, poll = 1, last = 1605865966.42502
2020.11.20 10:53:00.523 4: KSEM: GetUpdate will request Active_Power_L2_P_W
2020.11.20 10:53:00.523 5: KSEM: GetUpdate check h82 => Active_Power_L2_-_W, poll = 1, last = 1605865970.0956
2020.11.20 10:53:00.523 4: KSEM: GetUpdate will request Active_Power_L2_-_W
2020.11.20 10:53:00.523 5: KSEM: GetUpdate tries to combine read commands
2020.11.20 10:53:00.524 5: KSEM: GetUpdate cant combine request for Active_Power_total_+_W / h0 with Active_Power_total_-_W / h2, span 4 > max 1
2020.11.20 10:53:00.524 5: KSEM: GetUpdate cant combine request for Active_Power_total_-_W / h2 with Active_Power_L1_+_W / h40, span 40 > max 1
2020.11.20 10:53:00.524 5: KSEM: GetUpdate cant combine request for Active_Power_L1_+_W / h40 with Active_Power_L1_-_W / h42, span 4 > max 1
2020.11.20 10:53:00.524 5: KSEM: GetUpdate cant combine request for Active_Power_L1_-_W / h42 with Active_Power_L2_P_W / h80, span 40 > max 1
2020.11.20 10:53:00.524 5: KSEM: GetUpdate cant combine request for Active_Power_L2_P_W / h80 with Active_Power_L2_-_W / h82, span 4 > max 1
2020.11.20 10:53:00.524 5: KSEM: GetUpdate cant combine request for Active_Power_L2_-_W / h82 with Active_Power_L3_+_W / h120, span 40 > max 1
2020.11.20 10:53:00.525 5: KSEM: GetUpdate cant combine request for Active_Power_L3_+_W / h120 with Active_Power_L3_-_W / h122, span 4 > max 1
2020.11.20 10:53:00.525 5: KSEM: GetUpdate cant combine request for Active_Power_L3_-_W / h122 with Active_Energy_total_+_Wh / h512, span 394 > max 1
2020.11.20 10:53:00.525 5: KSEM: GetUpdate cant combine request for Active_Energy_total_+_Wh / h512 with Active_Energy_total_-_Wh / h516, span 8 > max 1
2020.11.20 10:53:00.525 5: KSEM: GetUpdate cant combine request for Active_Energy_total_-_Wh / h516 with Active_Energy_L1_+_Wh / h592, span 80 > max 1
2020.11.20 10:53:00.525 5: KSEM: GetUpdate cant combine request for Active_Energy_L1_+_Wh / h592 with Active_Energy_L1_-_Wh / h596, span 8 > max 1
2020.11.20 10:53:00.525 5: KSEM: GetUpdate cant combine request for Active_Energy_L1_-_Wh / h596 with Active_Energy_L2_+_Wh / h672, span 80 > max 1
2020.11.20 10:53:00.525 5: KSEM: GetUpdate cant combine request for Active_Energy_L2_+_Wh / h672 with Active_Energy_L2_-_Wh / h676, span 8 > max 1
2020.11.20 10:53:00.525 5: KSEM: GetUpdate cant combine request for Active_Energy_L2_-_Wh / h676 with Active_Energy_L3_+_Wh / h752, span 80 > max 1
2020.11.20 10:53:00.525 5: KSEM: GetUpdate cant combine request for Active_Energy_L3_+_Wh / h752 with Active_Energy_L3_-_Wh / h756, span 8 > max 1
2020.11.20 10:53:00.526 5: KSEM: GetUpdate doesn't sort objList before sending requests
2020.11.20 10:53:00.526 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 52, type h, adr 592, len 4 for device KSEM reading Active_Energy_L1_+_Wh (getUpdate), read buffer empty
2020.11.20 10:53:00.526 5: KSEM: QueueRequest called from DoRequest (KSEM) with h592, qlen 0
2020.11.20 10:53:00.526 4: KSEM: ProcessRequestQueue called from QueueRequest, qlen 1, next entry to id 1 (KSEM), last send to this device was 10.120 secs ago, last read 10.048 secs ago, last read on bus 10.048 secs ago from id 1 (KSEM)
2020.11.20 10:53:00.527 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:52:50.478) for KSEM, delay 9.949secs over
2020.11.20 10:53:00.527 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:52:50.407) for KSEM, delay 10.020secs over
2020.11.20 10:53:00.527 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 1, sending 003400000006010302500004 request: id 1, fCode 3, tid 52, type h, adr 592, len 4 for device KSEM reading Active_Energy_L1_+_Wh (getUpdate), queued 0.00 secs ago, read buffer empty
2020.11.20 10:53:00.527 5: SW: 003400000006010302500004
2020.11.20 10:53:00.529 5: KSEM: StartQueueTimer called from ProcessRequestQueue removes internal timer because it is not needed now
2020.11.20 10:53:00.530 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 41, type h, adr 676, len 4 for device KSEM reading Active_Energy_L2_-_Wh (getUpdate), read buffer empty
2020.11.20 10:53:00.530 5: KSEM: QueueRequest called from DoRequest (KSEM) with h676, qlen 0
2020.11.20 10:53:00.530 5: KSEM: StartQueueTimer called form QueueRequest sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:00.530 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 108, type h, adr 120, len 2 for device KSEM reading Active_Power_L3_+_W (getUpdate), read buffer empty
2020.11.20 10:53:00.531 5: KSEM: QueueRequest called from DoRequest (KSEM) with h120, qlen 1
2020.11.20 10:53:00.531 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 175, type h, adr 0, len 2 for device KSEM reading Active_Power_total_+_W (getUpdate), read buffer empty
2020.11.20 10:53:00.531 5: KSEM: QueueRequest called from DoRequest (KSEM) with h0, qlen 2
2020.11.20 10:53:00.532 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 119, type h, adr 2, len 2 for device KSEM reading Active_Power_total_-_W (getUpdate), read buffer empty
2020.11.20 10:53:00.532 5: KSEM: QueueRequest called from DoRequest (KSEM) with h2, qlen 3
2020.11.20 10:53:00.532 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 47, type h, adr 512, len 4 for device KSEM reading Active_Energy_total_+_Wh (getUpdate), read buffer empty
2020.11.20 10:53:00.532 5: KSEM: QueueRequest called from DoRequest (KSEM) with h512, qlen 4
2020.11.20 10:53:00.532 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 230, type h, adr 122, len 2 for device KSEM reading Active_Power_L3_-_W (getUpdate), read buffer empty
2020.11.20 10:53:00.533 5: KSEM: QueueRequest called from DoRequest (KSEM) with h122, qlen 5
2020.11.20 10:53:00.533 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 173, type h, adr 82, len 2 for device KSEM reading Active_Power_L2_-_W (getUpdate), read buffer empty
2020.11.20 10:53:00.533 5: KSEM: QueueRequest called from DoRequest (KSEM) with h82, qlen 6
2020.11.20 10:53:00.533 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 188, type h, adr 42, len 2 for device KSEM reading Active_Power_L1_-_W (getUpdate), read buffer empty
2020.11.20 10:53:00.533 5: KSEM: QueueRequest called from DoRequest (KSEM) with h42, qlen 7
2020.11.20 10:53:00.534 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 207, type h, adr 672, len 4 for device KSEM reading Active_Energy_L2_+_Wh (getUpdate), read buffer empty
2020.11.20 10:53:00.534 5: KSEM: QueueRequest called from DoRequest (KSEM) with h672, qlen 8
2020.11.20 10:53:00.534 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 171, type h, adr 756, len 4 for device KSEM reading Active_Energy_L3_-_Wh (getUpdate), read buffer empty
2020.11.20 10:53:00.534 5: KSEM: QueueRequest called from DoRequest (KSEM) with h756, qlen 9
2020.11.20 10:53:00.534 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 148, type h, adr 752, len 4 for device KSEM reading Active_Energy_L3_+_Wh (getUpdate), read buffer empty
2020.11.20 10:53:00.535 5: KSEM: QueueRequest called from DoRequest (KSEM) with h752, qlen 10
2020.11.20 10:53:00.535 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 138, type h, adr 596, len 4 for device KSEM reading Active_Energy_L1_-_Wh (getUpdate), read buffer empty
2020.11.20 10:53:00.535 5: KSEM: QueueRequest called from DoRequest (KSEM) with h596, qlen 11
2020.11.20 10:53:00.535 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 59, type h, adr 516, len 4 for device KSEM reading Active_Energy_total_-_Wh (getUpdate), read buffer empty
2020.11.20 10:53:00.535 5: KSEM: QueueRequest called from DoRequest (KSEM) with h516, qlen 12
2020.11.20 10:53:00.536 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 182, type h, adr 40, len 2 for device KSEM reading Active_Power_L1_+_W (getUpdate), read buffer empty
2020.11.20 10:53:00.536 5: KSEM: QueueRequest called from DoRequest (KSEM) with h40, qlen 13
2020.11.20 10:53:00.536 4: KSEM: DoRequest called from GetUpdate created request: id 1, fCode 3, tid 252, type h, adr 80, len 2 for device KSEM reading Active_Power_L2_P_W (getUpdate), read buffer empty
2020.11.20 10:53:00.536 5: KSEM: QueueRequest called from DoRequest (KSEM) with h80, qlen 14
2020.11.20 10:53:00.537 5: KSEM: read buffer: 00340000000b0103080000000000abca2d
2020.11.20 10:53:00.537 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 52, dlen 11 and data 080000000000abca2d
2020.11.20 10:53:00.537 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:00.538 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:00.538 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:00.538 5: KSEM: ParseObj called with data 0000000000abca2d, type h, adr 592, valuesLen 4, op read
2020.11.20 10:53:00.538 5: KSEM: ParseObj ObjInfo for h592: reading=Active_Energy_L1_+_Wh, unpack=Q>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:00.539 5: KSEM: ParseObj unpacked 0000000000abca2d with Q> to 11258413 hex 3131323538343133
2020.11.20 10:53:00.539 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Energy_L1_+_Wh, val=11258413, expr=$val / 10
2020.11.20 10:53:00.539 5: KSEM: CheckEval for ParseObj result is 1125841.3
2020.11.20 10:53:00.539 5: KSEM: ParseObj for Active_Energy_L1_+_Wh does sprintf with format %.2f, value is 1125841.3
2020.11.20 10:53:00.539 5: KSEM: ParseObj for Active_Energy_L1_+_Wh sprintf result is 1125841.30
2020.11.20 10:53:00.539 4: KSEM: ParseObj assigns value 1125841.30 to Active_Energy_L1_+_Wh
2020.11.20 10:53:00.572 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:00.574 4: KSEM: ResponseDone request: id 1, fCode 3, tid 52, type h, adr 592, len 4 for device KSEM reading Active_Energy_L1_+_Wh (getUpdate), queued 0.05 secs ago, sent 0.05 secs ago, Current read buffer: 00340000000b0103080000000000abca2d, Id 1, fCode 3, tid 52, response: id 1, fCode 3, type h, adr 592, len 4, value 0000000000abca2d
2020.11.20 10:53:00.574 5: KSEM: DropFrame - drop 00340000000b0103080000000000abca2d
2020.11.20 10:53:00.575 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:00.577 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 15, next entry to id 1 (KSEM), last send to this device was 0.048 secs ago, last read 0.039 secs ago, last read on bus 0.039 secs ago from id 1 (KSEM)
2020.11.20 10:53:00.577 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:00.538) for KSEM, rest 0.061, set timer to try again later
2020.11.20 10:53:00.577 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.061 seconds
2020.11.20 10:53:00.640 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 15, next entry to id 1 (KSEM), last send to this device was 0.111 secs ago, last read 0.102 secs ago, last read on bus 0.102 secs ago from id 1 (KSEM)
2020.11.20 10:53:00.640 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:00.538) for KSEM, delay 0.003secs over
2020.11.20 10:53:00.640 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:00.529) for KSEM, delay 0.012secs over
2020.11.20 10:53:00.641 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 15, sending 002900000006010302a40004 request: id 1, fCode 3, tid 41, type h, adr 676, len 4 for device KSEM reading Active_Energy_L2_-_Wh (getUpdate), queued 0.11 secs ago, read buffer empty
2020.11.20 10:53:00.641 5: SW: 002900000006010302a40004
2020.11.20 10:53:00.643 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:00.643 5: KSEM: read buffer: 00290000000b01030800000000007f10c5
2020.11.20 10:53:00.644 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 41, dlen 11 and data 0800000000007f10c5
2020.11.20 10:53:00.644 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:00.644 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:00.644 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:00.644 5: KSEM: ParseObj called with data 00000000007f10c5, type h, adr 676, valuesLen 4, op read
2020.11.20 10:53:00.645 5: KSEM: ParseObj ObjInfo for h676: reading=Active_Energy_L2_-_Wh, unpack=Q>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:00.645 5: KSEM: ParseObj unpacked 00000000007f10c5 with Q> to 8327365 hex 38333237333635
2020.11.20 10:53:00.645 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Energy_L2_-_Wh, val=8327365, expr=$val / 10
2020.11.20 10:53:00.645 5: KSEM: CheckEval for ParseObj result is 832736.5
2020.11.20 10:53:00.645 5: KSEM: ParseObj for Active_Energy_L2_-_Wh does sprintf with format %.2f, value is 832736.5
2020.11.20 10:53:00.645 5: KSEM: ParseObj for Active_Energy_L2_-_Wh sprintf result is 832736.50
2020.11.20 10:53:00.645 4: KSEM: ParseObj assigns value 832736.50 to Active_Energy_L2_-_Wh
2020.11.20 10:53:00.675 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:00.675 4: KSEM: ResponseDone request: id 1, fCode 3, tid 41, type h, adr 676, len 4 for device KSEM reading Active_Energy_L2_-_Wh (getUpdate), queued 0.15 secs ago, sent 0.04 secs ago, Current read buffer: 00290000000b01030800000000007f10c5, Id 1, fCode 3, tid 41, response: id 1, fCode 3, type h, adr 676, len 4, value 00000000007f10c5
2020.11.20 10:53:00.675 5: KSEM: DropFrame - drop 00290000000b01030800000000007f10c5
2020.11.20 10:53:00.676 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:00.678 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 14, next entry to id 1 (KSEM), last send to this device was 0.035 secs ago, last read 0.034 secs ago, last read on bus 0.034 secs ago from id 1 (KSEM)
2020.11.20 10:53:00.678 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:00.644) for KSEM, rest 0.066, set timer to try again later
2020.11.20 10:53:00.678 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.066 seconds
2020.11.20 10:53:00.746 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 14, next entry to id 1 (KSEM), last send to this device was 0.104 secs ago, last read 0.102 secs ago, last read on bus 0.102 secs ago from id 1 (KSEM)
2020.11.20 10:53:00.746 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:00.644) for KSEM, delay 0.003secs over
2020.11.20 10:53:00.747 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:00.642) for KSEM, delay 0.005secs over
2020.11.20 10:53:00.747 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 14, sending 006c00000006010300780002 request: id 1, fCode 3, tid 108, type h, adr 120, len 2 for device KSEM reading Active_Power_L3_+_W (getUpdate), queued 0.22 secs ago, read buffer empty
2020.11.20 10:53:00.747 5: SW: 006c00000006010300780002
2020.11.20 10:53:00.749 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:00.749 5: KSEM: read buffer: 006c0000000701030400000000
2020.11.20 10:53:00.750 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 108, dlen 7 and data 0400000000
2020.11.20 10:53:00.750 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:00.750 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:00.750 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:00.750 5: KSEM: ParseObj called with data 00000000, type h, adr 120, valuesLen 2, op read
2020.11.20 10:53:00.751 5: KSEM: ParseObj ObjInfo for h120: reading=Active_Power_L3_+_W, unpack=I>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:00.751 5: KSEM: ParseObj unpacked 00000000 with I> to 0 hex 30
2020.11.20 10:53:00.751 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Power_L3_+_W, val=0, expr=$val / 10
2020.11.20 10:53:00.751 5: KSEM: CheckEval for ParseObj result is 0
2020.11.20 10:53:00.751 5: KSEM: ParseObj for Active_Power_L3_+_W does sprintf with format %.2f, value is 0
2020.11.20 10:53:00.751 5: KSEM: ParseObj for Active_Power_L3_+_W sprintf result is 0.00
2020.11.20 10:53:00.751 4: KSEM: ParseObj assigns value 0.00 to Active_Power_L3_+_W
2020.11.20 10:53:00.752 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:00.752 4: KSEM: ResponseDone request: id 1, fCode 3, tid 108, type h, adr 120, len 2 for device KSEM reading Active_Power_L3_+_W (getUpdate), queued 0.22 secs ago, sent 0.01 secs ago, Current read buffer: 006c0000000701030400000000, Id 1, fCode 3, tid 108, response: id 1, fCode 3, type h, adr 120, len 2, value 00000000
2020.11.20 10:53:00.752 5: KSEM: DropFrame - drop 006c0000000701030400000000
2020.11.20 10:53:00.753 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:00.754 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 13, next entry to id 1 (KSEM), last send to this device was 0.006 secs ago, last read 0.004 secs ago, last read on bus 0.004 secs ago from id 1 (KSEM)
2020.11.20 10:53:00.755 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:00.750) for KSEM, rest 0.095, set timer to try again later
2020.11.20 10:53:00.755 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.095 seconds
2020.11.20 10:53:00.853 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 13, next entry to id 1 (KSEM), last send to this device was 0.104 secs ago, last read 0.103 secs ago, last read on bus 0.103 secs ago from id 1 (KSEM)
2020.11.20 10:53:00.853 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:00.750) for KSEM, delay 0.003secs over
2020.11.20 10:53:00.853 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:00.748) for KSEM, delay 0.005secs over
2020.11.20 10:53:00.853 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 13, sending 00af00000006010300000002 request: id 1, fCode 3, tid 175, type h, adr 0, len 2 for device KSEM reading Active_Power_total_+_W (getUpdate), queued 0.32 secs ago, read buffer empty
2020.11.20 10:53:00.853 5: SW: 00af00000006010300000002
2020.11.20 10:53:00.855 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:00.856 5: KSEM: read buffer: 00af0000000701030400000000
2020.11.20 10:53:00.856 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 175, dlen 7 and data 0400000000
2020.11.20 10:53:00.856 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:00.856 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:00.857 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:00.857 5: KSEM: ParseObj called with data 00000000, type h, adr 0, valuesLen 2, op read
2020.11.20 10:53:00.857 5: KSEM: ParseObj ObjInfo for h0: reading=Active_Power_total_+_W, unpack=I>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:00.857 5: KSEM: ParseObj unpacked 00000000 with I> to 0 hex 30
2020.11.20 10:53:00.857 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Power_total_+_W, val=0, expr=$val / 10
2020.11.20 10:53:00.858 5: KSEM: CheckEval for ParseObj result is 0
2020.11.20 10:53:00.858 5: KSEM: ParseObj for Active_Power_total_+_W does sprintf with format %.2f, value is 0
2020.11.20 10:53:00.858 5: KSEM: ParseObj for Active_Power_total_+_W sprintf result is 0.00
2020.11.20 10:53:00.858 4: KSEM: ParseObj assigns value 0.00 to Active_Power_total_+_W
2020.11.20 10:53:00.888 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:00.888 4: KSEM: ResponseDone request: id 1, fCode 3, tid 175, type h, adr 0, len 2 for device KSEM reading Active_Power_total_+_W (getUpdate), queued 0.36 secs ago, sent 0.04 secs ago, Current read buffer: 00af0000000701030400000000, Id 1, fCode 3, tid 175, response: id 1, fCode 3, type h, adr 0, len 2, value 00000000
2020.11.20 10:53:00.888 5: KSEM: DropFrame - drop 00af0000000701030400000000
2020.11.20 10:53:00.889 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:00.890 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 12, next entry to id 1 (KSEM), last send to this device was 0.035 secs ago, last read 0.034 secs ago, last read on bus 0.034 secs ago from id 1 (KSEM)
2020.11.20 10:53:00.891 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:00.856) for KSEM, rest 0.066, set timer to try again later
2020.11.20 10:53:00.891 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.066 seconds
2020.11.20 10:53:00.959 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 12, next entry to id 1 (KSEM), last send to this device was 0.104 secs ago, last read 0.102 secs ago, last read on bus 0.102 secs ago from id 1 (KSEM)
2020.11.20 10:53:00.959 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:00.856) for KSEM, delay 0.002secs over
2020.11.20 10:53:00.959 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:00.855) for KSEM, delay 0.004secs over
2020.11.20 10:53:00.959 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 12, sending 007700000006010300020002 request: id 1, fCode 3, tid 119, type h, adr 2, len 2 for device KSEM reading Active_Power_total_-_W (getUpdate), queued 0.43 secs ago, read buffer empty
2020.11.20 10:53:00.959 5: SW: 007700000006010300020002
2020.11.20 10:53:00.961 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:00.964 5: KSEM: read buffer: 0077000000070103040000002d
2020.11.20 10:53:00.964 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 119, dlen 7 and data 040000002d
2020.11.20 10:53:00.964 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:00.964 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:00.965 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:00.965 5: KSEM: ParseObj called with data 0000002d, type h, adr 2, valuesLen 2, op read
2020.11.20 10:53:00.965 5: KSEM: ParseObj ObjInfo for h2: reading=Active_Power_total_-_W, unpack=I>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:00.965 5: KSEM: ParseObj unpacked 0000002d with I> to 45 hex 3435
2020.11.20 10:53:00.965 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Power_total_-_W, val=45, expr=$val / 10
2020.11.20 10:53:00.966 5: KSEM: CheckEval for ParseObj result is 4.5
2020.11.20 10:53:00.966 5: KSEM: ParseObj for Active_Power_total_-_W does sprintf with format %.2f, value is 4.5
2020.11.20 10:53:00.966 5: KSEM: ParseObj for Active_Power_total_-_W sprintf result is 4.50
2020.11.20 10:53:00.966 4: KSEM: ParseObj assigns value 4.50 to Active_Power_total_-_W
2020.11.20 10:53:00.996 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:00.996 4: KSEM: ResponseDone request: id 1, fCode 3, tid 119, type h, adr 2, len 2 for device KSEM reading Active_Power_total_-_W (getUpdate), queued 0.46 secs ago, sent 0.04 secs ago, Current read buffer: 0077000000070103040000002d, Id 1, fCode 3, tid 119, response: id 1, fCode 3, type h, adr 2, len 2, value 0000002d
2020.11.20 10:53:00.996 5: KSEM: DropFrame - drop 0077000000070103040000002d
2020.11.20 10:53:00.997 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:00.998 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 11, next entry to id 1 (KSEM), last send to this device was 0.037 secs ago, last read 0.034 secs ago, last read on bus 0.034 secs ago from id 1 (KSEM)
2020.11.20 10:53:00.999 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:00.964) for KSEM, rest 0.066, set timer to try again later
2020.11.20 10:53:00.999 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.066 seconds
2020.11.20 10:53:01.067 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 11, next entry to id 1 (KSEM), last send to this device was 0.106 secs ago, last read 0.102 secs ago, last read on bus 0.102 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.067 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:00.964) for KSEM, delay 0.003secs over
2020.11.20 10:53:01.067 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:00.961) for KSEM, delay 0.006secs over
2020.11.20 10:53:01.067 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 11, sending 002f00000006010302000004 request: id 1, fCode 3, tid 47, type h, adr 512, len 4 for device KSEM reading Active_Energy_total_+_Wh (getUpdate), queued 0.54 secs ago, read buffer empty
2020.11.20 10:53:01.068 5: SW: 002f00000006010302000004
2020.11.20 10:53:01.069 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:01.070 5: KSEM: read buffer: 002f0000000b0103080000000000ef22b5
2020.11.20 10:53:01.070 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 47, dlen 11 and data 080000000000ef22b5
2020.11.20 10:53:01.070 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:01.071 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:01.071 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:01.071 5: KSEM: ParseObj called with data 0000000000ef22b5, type h, adr 512, valuesLen 4, op read
2020.11.20 10:53:01.071 5: KSEM: ParseObj ObjInfo for h512: reading=Active_Energy_total_+_Wh, unpack=Q>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:01.071 5: KSEM: ParseObj unpacked 0000000000ef22b5 with Q> to 15671989 hex 3135363731393839
2020.11.20 10:53:01.072 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Energy_total_+_Wh, val=15671989, expr=$val / 10
2020.11.20 10:53:01.072 5: KSEM: CheckEval for ParseObj result is 1567198.9
2020.11.20 10:53:01.072 5: KSEM: ParseObj for Active_Energy_total_+_Wh does sprintf with format %.2f, value is 1567198.9
2020.11.20 10:53:01.072 5: KSEM: ParseObj for Active_Energy_total_+_Wh sprintf result is 1567198.90
2020.11.20 10:53:01.072 4: KSEM: ParseObj assigns value 1567198.90 to Active_Energy_total_+_Wh
2020.11.20 10:53:01.073 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:01.073 4: KSEM: ResponseDone request: id 1, fCode 3, tid 47, type h, adr 512, len 4 for device KSEM reading Active_Energy_total_+_Wh (getUpdate), queued 0.54 secs ago, sent 0.01 secs ago, Current read buffer: 002f0000000b0103080000000000ef22b5, Id 1, fCode 3, tid 47, response: id 1, fCode 3, type h, adr 512, len 4, value 0000000000ef22b5
2020.11.20 10:53:01.073 5: KSEM: DropFrame - drop 002f0000000b0103080000000000ef22b5
2020.11.20 10:53:01.073 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:01.075 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 10, next entry to id 1 (KSEM), last send to this device was 0.006 secs ago, last read 0.004 secs ago, last read on bus 0.004 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.075 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.070) for KSEM, rest 0.095, set timer to try again later
2020.11.20 10:53:01.076 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.095 seconds
2020.11.20 10:53:01.175 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 10, next entry to id 1 (KSEM), last send to this device was 0.106 secs ago, last read 0.104 secs ago, last read on bus 0.104 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.175 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.070) for KSEM, delay 0.005secs over
2020.11.20 10:53:01.176 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:01.069) for KSEM, delay 0.007secs over
2020.11.20 10:53:01.176 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 10, sending 00e6000000060103007a0002 request: id 1, fCode 3, tid 230, type h, adr 122, len 2 for device KSEM reading Active_Power_L3_-_W (getUpdate), queued 0.64 secs ago, read buffer empty
2020.11.20 10:53:01.177 5: SW: 00e6000000060103007a0002
2020.11.20 10:53:01.180 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:01.181 5: KSEM: read buffer: 00e600000007010304000003b6
2020.11.20 10:53:01.181 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 230, dlen 7 and data 04000003b6
2020.11.20 10:53:01.181 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:01.181 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:01.181 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:01.182 5: KSEM: ParseObj called with data 000003b6, type h, adr 122, valuesLen 2, op read
2020.11.20 10:53:01.182 5: KSEM: ParseObj ObjInfo for h122: reading=Active_Power_L3_-_W, unpack=I>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:01.182 5: KSEM: ParseObj unpacked 000003b6 with I> to 950 hex 393530
2020.11.20 10:53:01.182 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Power_L3_-_W, val=950, expr=$val / 10
2020.11.20 10:53:01.182 5: KSEM: CheckEval for ParseObj result is 95
2020.11.20 10:53:01.183 5: KSEM: ParseObj for Active_Power_L3_-_W does sprintf with format %.2f, value is 95
2020.11.20 10:53:01.183 5: KSEM: ParseObj for Active_Power_L3_-_W sprintf result is 95.00
2020.11.20 10:53:01.183 4: KSEM: ParseObj assigns value 95.00 to Active_Power_L3_-_W
2020.11.20 10:53:01.212 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:01.213 4: KSEM: ResponseDone request: id 1, fCode 3, tid 230, type h, adr 122, len 2 for device KSEM reading Active_Power_L3_-_W (getUpdate), queued 0.68 secs ago, sent 0.04 secs ago, Current read buffer: 00e600000007010304000003b6, Id 1, fCode 3, tid 230, response: id 1, fCode 3, type h, adr 122, len 2, value 000003b6
2020.11.20 10:53:01.213 5: KSEM: DropFrame - drop 00e600000007010304000003b6
2020.11.20 10:53:01.213 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:01.215 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 9, next entry to id 1 (KSEM), last send to this device was 0.036 secs ago, last read 0.034 secs ago, last read on bus 0.034 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.215 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.181) for KSEM, rest 0.066, set timer to try again later
2020.11.20 10:53:01.216 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.066 seconds
2020.11.20 10:53:01.284 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 9, next entry to id 1 (KSEM), last send to this device was 0.105 secs ago, last read 0.102 secs ago, last read on bus 0.102 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.284 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.181) for KSEM, delay 0.003secs over
2020.11.20 10:53:01.284 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:01.178) for KSEM, delay 0.006secs over
2020.11.20 10:53:01.284 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 9, sending 00ad00000006010300520002 request: id 1, fCode 3, tid 173, type h, adr 82, len 2 for device KSEM reading Active_Power_L2_-_W (getUpdate), queued 0.75 secs ago, read buffer empty
2020.11.20 10:53:01.285 5: SW: 00ad00000006010300520002
2020.11.20 10:53:01.286 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:01.287 5: KSEM: read buffer: 00ad00000007010304000003be
2020.11.20 10:53:01.287 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 173, dlen 7 and data 04000003be
2020.11.20 10:53:01.288 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:01.288 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:01.288 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:01.288 5: KSEM: ParseObj called with data 000003be, type h, adr 82, valuesLen 2, op read
2020.11.20 10:53:01.289 5: KSEM: ParseObj ObjInfo for h82: reading=Active_Power_L2_-_W, unpack=I>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:01.289 5: KSEM: ParseObj unpacked 000003be with I> to 958 hex 393538
2020.11.20 10:53:01.289 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Power_L2_-_W, val=958, expr=$val / 10
2020.11.20 10:53:01.289 5: KSEM: CheckEval for ParseObj result is 95.8
2020.11.20 10:53:01.289 5: KSEM: ParseObj for Active_Power_L2_-_W does sprintf with format %.2f, value is 95.8
2020.11.20 10:53:01.289 5: KSEM: ParseObj for Active_Power_L2_-_W sprintf result is 95.80
2020.11.20 10:53:01.289 4: KSEM: ParseObj assigns value 95.80 to Active_Power_L2_-_W
2020.11.20 10:53:01.319 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:01.319 4: KSEM: ResponseDone request: id 1, fCode 3, tid 173, type h, adr 82, len 2 for device KSEM reading Active_Power_L2_-_W (getUpdate), queued 0.79 secs ago, sent 0.04 secs ago, Current read buffer: 00ad00000007010304000003be, Id 1, fCode 3, tid 173, response: id 1, fCode 3, type h, adr 82, len 2, value 000003be
2020.11.20 10:53:01.320 5: KSEM: DropFrame - drop 00ad00000007010304000003be
2020.11.20 10:53:01.320 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:01.322 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 8, next entry to id 1 (KSEM), last send to this device was 0.036 secs ago, last read 0.034 secs ago, last read on bus 0.034 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.322 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.288) for KSEM, rest 0.066, set timer to try again later
2020.11.20 10:53:01.322 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.066 seconds
2020.11.20 10:53:01.390 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 8, next entry to id 1 (KSEM), last send to this device was 0.104 secs ago, last read 0.102 secs ago, last read on bus 0.102 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.390 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.288) for KSEM, delay 0.003secs over
2020.11.20 10:53:01.390 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:01.286) for KSEM, delay 0.005secs over
2020.11.20 10:53:01.391 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 8, sending 00bc000000060103002a0002 request: id 1, fCode 3, tid 188, type h, adr 42, len 2 for device KSEM reading Active_Power_L1_-_W (getUpdate), queued 0.86 secs ago, read buffer empty
2020.11.20 10:53:01.391 5: SW: 00bc000000060103002a0002
2020.11.20 10:53:01.393 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:01.395 5: KSEM: read buffer: 00bc0000000701030400000000
2020.11.20 10:53:01.395 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 188, dlen 7 and data 0400000000
2020.11.20 10:53:01.395 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:01.395 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:01.395 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:01.395 5: KSEM: ParseObj called with data 00000000, type h, adr 42, valuesLen 2, op read
2020.11.20 10:53:01.396 5: KSEM: ParseObj ObjInfo for h42: reading=Active_Power_L1_-_W, unpack=I>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:01.396 5: KSEM: ParseObj unpacked 00000000 with I> to 0 hex 30
2020.11.20 10:53:01.396 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Power_L1_-_W, val=0, expr=$val / 10
2020.11.20 10:53:01.396 5: KSEM: CheckEval for ParseObj result is 0
2020.11.20 10:53:01.396 5: KSEM: ParseObj for Active_Power_L1_-_W does sprintf with format %.2f, value is 0
2020.11.20 10:53:01.397 5: KSEM: ParseObj for Active_Power_L1_-_W sprintf result is 0.00
2020.11.20 10:53:01.397 4: KSEM: ParseObj assigns value 0.00 to Active_Power_L1_-_W
2020.11.20 10:53:01.397 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:01.397 4: KSEM: ResponseDone request: id 1, fCode 3, tid 188, type h, adr 42, len 2 for device KSEM reading Active_Power_L1_-_W (getUpdate), queued 0.86 secs ago, sent 0.01 secs ago, Current read buffer: 00bc0000000701030400000000, Id 1, fCode 3, tid 188, response: id 1, fCode 3, type h, adr 42, len 2, value 00000000
2020.11.20 10:53:01.397 5: KSEM: DropFrame - drop 00bc0000000701030400000000
2020.11.20 10:53:01.398 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:01.400 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 7, next entry to id 1 (KSEM), last send to this device was 0.008 secs ago, last read 0.005 secs ago, last read on bus 0.005 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.400 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.395) for KSEM, rest 0.095, set timer to try again later
2020.11.20 10:53:01.401 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.095 seconds
2020.11.20 10:53:01.499 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 7, next entry to id 1 (KSEM), last send to this device was 0.107 secs ago, last read 0.104 secs ago, last read on bus 0.104 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.500 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.395) for KSEM, delay 0.005secs over
2020.11.20 10:53:01.500 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:01.392) for KSEM, delay 0.008secs over
2020.11.20 10:53:01.501 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 7, sending 00cf00000006010302a00004 request: id 1, fCode 3, tid 207, type h, adr 672, len 4 for device KSEM reading Active_Energy_L2_+_Wh (getUpdate), queued 0.97 secs ago, read buffer empty
2020.11.20 10:53:01.501 5: SW: 00cf00000006010302a00004
2020.11.20 10:53:01.504 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:01.505 5: KSEM: read buffer: 00cf0000000b010308000000000033c3ae
2020.11.20 10:53:01.505 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 207, dlen 11 and data 08000000000033c3ae
2020.11.20 10:53:01.505 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:01.505 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:01.505 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:01.505 5: KSEM: ParseObj called with data 000000000033c3ae, type h, adr 672, valuesLen 4, op read
2020.11.20 10:53:01.506 5: KSEM: ParseObj ObjInfo for h672: reading=Active_Energy_L2_+_Wh, unpack=Q>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:01.506 5: KSEM: ParseObj unpacked 000000000033c3ae with Q> to 3392430 hex 33333932343330
2020.11.20 10:53:01.506 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Energy_L2_+_Wh, val=3392430, expr=$val / 10
2020.11.20 10:53:01.506 5: KSEM: CheckEval for ParseObj result is 339243
2020.11.20 10:53:01.506 5: KSEM: ParseObj for Active_Energy_L2_+_Wh does sprintf with format %.2f, value is 339243
2020.11.20 10:53:01.506 5: KSEM: ParseObj for Active_Energy_L2_+_Wh sprintf result is 339243.00
2020.11.20 10:53:01.507 4: KSEM: ParseObj assigns value 339243.00 to Active_Energy_L2_+_Wh
2020.11.20 10:53:01.507 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:01.507 4: KSEM: ResponseDone request: id 1, fCode 3, tid 207, type h, adr 672, len 4 for device KSEM reading Active_Energy_L2_+_Wh (getUpdate), queued 0.97 secs ago, sent 0.01 secs ago, Current read buffer: 00cf0000000b010308000000000033c3ae, Id 1, fCode 3, tid 207, response: id 1, fCode 3, type h, adr 672, len 4, value 000000000033c3ae
2020.11.20 10:53:01.507 5: KSEM: DropFrame - drop 00cf0000000b010308000000000033c3ae
2020.11.20 10:53:01.508 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:01.509 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 6, next entry to id 1 (KSEM), last send to this device was 0.007 secs ago, last read 0.004 secs ago, last read on bus 0.004 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.510 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.505) for KSEM, rest 0.095, set timer to try again later
2020.11.20 10:53:01.510 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.095 seconds
2020.11.20 10:53:01.607 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 6, next entry to id 1 (KSEM), last send to this device was 0.105 secs ago, last read 0.102 secs ago, last read on bus 0.102 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.608 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.505) for KSEM, delay 0.003secs over
2020.11.20 10:53:01.608 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:01.503) for KSEM, delay 0.005secs over
2020.11.20 10:53:01.608 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 6, sending 00ab00000006010302f40004 request: id 1, fCode 3, tid 171, type h, adr 756, len 4 for device KSEM reading Active_Energy_L3_-_Wh (getUpdate), queued 1.07 secs ago, read buffer empty
2020.11.20 10:53:01.608 5: SW: 00ab00000006010302f40004
2020.11.20 10:53:01.610 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:01.611 5: KSEM: read buffer: 00ab0000000b010308000000000073be42
2020.11.20 10:53:01.611 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 171, dlen 11 and data 08000000000073be42
2020.11.20 10:53:01.611 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:01.612 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:01.612 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:01.612 5: KSEM: ParseObj called with data 000000000073be42, type h, adr 756, valuesLen 4, op read
2020.11.20 10:53:01.612 5: KSEM: ParseObj ObjInfo for h756: reading=Active_Energy_L3_-_Wh, unpack=Q>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:01.613 5: KSEM: ParseObj unpacked 000000000073be42 with Q> to 7585346 hex 37353835333436
2020.11.20 10:53:01.613 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Energy_L3_-_Wh, val=7585346, expr=$val / 10
2020.11.20 10:53:01.613 5: KSEM: CheckEval for ParseObj result is 758534.6
2020.11.20 10:53:01.613 5: KSEM: ParseObj for Active_Energy_L3_-_Wh does sprintf with format %.2f, value is 758534.6
2020.11.20 10:53:01.613 5: KSEM: ParseObj for Active_Energy_L3_-_Wh sprintf result is 758534.60
2020.11.20 10:53:01.613 4: KSEM: ParseObj assigns value 758534.60 to Active_Energy_L3_-_Wh
2020.11.20 10:53:01.643 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:01.643 4: KSEM: ResponseDone request: id 1, fCode 3, tid 171, type h, adr 756, len 4 for device KSEM reading Active_Energy_L3_-_Wh (getUpdate), queued 1.11 secs ago, sent 0.04 secs ago, Current read buffer: 00ab0000000b010308000000000073be42, Id 1, fCode 3, tid 171, response: id 1, fCode 3, type h, adr 756, len 4, value 000000000073be42
2020.11.20 10:53:01.643 5: KSEM: DropFrame - drop 00ab0000000b010308000000000073be42
2020.11.20 10:53:01.644 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:01.645 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 5, next entry to id 1 (KSEM), last send to this device was 0.036 secs ago, last read 0.034 secs ago, last read on bus 0.034 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.646 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.612) for KSEM, rest 0.066, set timer to try again later
2020.11.20 10:53:01.646 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.066 seconds
2020.11.20 10:53:01.714 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 5, next entry to id 1 (KSEM), last send to this device was 0.104 secs ago, last read 0.102 secs ago, last read on bus 0.102 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.714 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.612) for KSEM, delay 0.003secs over
2020.11.20 10:53:01.714 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:01.609) for KSEM, delay 0.005secs over
2020.11.20 10:53:01.715 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 5, sending 009400000006010302f00004 request: id 1, fCode 3, tid 148, type h, adr 752, len 4 for device KSEM reading Active_Energy_L3_+_Wh (getUpdate), queued 1.18 secs ago, read buffer empty
2020.11.20 10:53:01.715 5: SW: 009400000006010302f00004
2020.11.20 10:53:01.717 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:01.717 5: KSEM: read buffer: 00940000000b0103080000000000404928
2020.11.20 10:53:01.718 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 148, dlen 11 and data 080000000000404928
2020.11.20 10:53:01.718 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:01.718 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:01.718 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:01.718 5: KSEM: ParseObj called with data 0000000000404928, type h, adr 752, valuesLen 4, op read
2020.11.20 10:53:01.719 5: KSEM: ParseObj ObjInfo for h752: reading=Active_Energy_L3_+_Wh, unpack=Q>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:01.719 5: KSEM: ParseObj unpacked 0000000000404928 with Q> to 4213032 hex 34323133303332
2020.11.20 10:53:01.719 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Energy_L3_+_Wh, val=4213032, expr=$val / 10
2020.11.20 10:53:01.719 5: KSEM: CheckEval for ParseObj result is 421303.2
2020.11.20 10:53:01.719 5: KSEM: ParseObj for Active_Energy_L3_+_Wh does sprintf with format %.2f, value is 421303.2
2020.11.20 10:53:01.719 5: KSEM: ParseObj for Active_Energy_L3_+_Wh sprintf result is 421303.20
2020.11.20 10:53:01.719 4: KSEM: ParseObj assigns value 421303.20 to Active_Energy_L3_+_Wh
2020.11.20 10:53:01.720 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:01.720 4: KSEM: ResponseDone request: id 1, fCode 3, tid 148, type h, adr 752, len 4 for device KSEM reading Active_Energy_L3_+_Wh (getUpdate), queued 1.19 secs ago, sent 0.01 secs ago, Current read buffer: 00940000000b0103080000000000404928, Id 1, fCode 3, tid 148, response: id 1, fCode 3, type h, adr 752, len 4, value 0000000000404928
2020.11.20 10:53:01.720 5: KSEM: DropFrame - drop 00940000000b0103080000000000404928
2020.11.20 10:53:01.721 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:01.722 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 4, next entry to id 1 (KSEM), last send to this device was 0.006 secs ago, last read 0.004 secs ago, last read on bus 0.004 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.723 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.718) for KSEM, rest 0.095, set timer to try again later
2020.11.20 10:53:01.723 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.095 seconds
2020.11.20 10:53:01.823 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 4, next entry to id 1 (KSEM), last send to this device was 0.106 secs ago, last read 0.105 secs ago, last read on bus 0.105 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.824 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.718) for KSEM, delay 0.006secs over
2020.11.20 10:53:01.824 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:01.716) for KSEM, delay 0.008secs over
2020.11.20 10:53:01.825 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 4, sending 008a00000006010302540004 request: id 1, fCode 3, tid 138, type h, adr 596, len 4 for device KSEM reading Active_Energy_L1_-_Wh (getUpdate), queued 1.29 secs ago, read buffer empty
2020.11.20 10:53:01.825 5: SW: 008a00000006010302540004
2020.11.20 10:53:01.827 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:01.829 5: KSEM: read buffer: 008a0000000b0103080000000000583e77
2020.11.20 10:53:01.829 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 138, dlen 11 and data 080000000000583e77
2020.11.20 10:53:01.830 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:01.830 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:01.830 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:01.831 5: KSEM: ParseObj called with data 0000000000583e77, type h, adr 596, valuesLen 4, op read
2020.11.20 10:53:01.832 5: KSEM: ParseObj ObjInfo for h596: reading=Active_Energy_L1_-_Wh, unpack=Q>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:01.833 5: KSEM: ParseObj unpacked 0000000000583e77 with Q> to 5783159 hex 35373833313539
2020.11.20 10:53:01.833 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Energy_L1_-_Wh, val=5783159, expr=$val / 10
2020.11.20 10:53:01.834 5: KSEM: CheckEval for ParseObj result is 578315.9
2020.11.20 10:53:01.834 5: KSEM: ParseObj for Active_Energy_L1_-_Wh does sprintf with format %.2f, value is 578315.9
2020.11.20 10:53:01.834 5: KSEM: ParseObj for Active_Energy_L1_-_Wh sprintf result is 578315.90
2020.11.20 10:53:01.834 4: KSEM: ParseObj assigns value 578315.90 to Active_Energy_L1_-_Wh
2020.11.20 10:53:01.835 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:01.835 4: KSEM: ResponseDone request: id 1, fCode 3, tid 138, type h, adr 596, len 4 for device KSEM reading Active_Energy_L1_-_Wh (getUpdate), queued 1.30 secs ago, sent 0.01 secs ago, Current read buffer: 008a0000000b0103080000000000583e77, Id 1, fCode 3, tid 138, response: id 1, fCode 3, type h, adr 596, len 4, value 0000000000583e77
2020.11.20 10:53:01.835 5: KSEM: DropFrame - drop 008a0000000b0103080000000000583e77
2020.11.20 10:53:01.836 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:01.837 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 3, next entry to id 1 (KSEM), last send to this device was 0.011 secs ago, last read 0.007 secs ago, last read on bus 0.007 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.837 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.830) for KSEM, rest 0.093, set timer to try again later
2020.11.20 10:53:01.838 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.093 seconds
2020.11.20 10:53:01.932 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 3, next entry to id 1 (KSEM), last send to this device was 0.106 secs ago, last read 0.102 secs ago, last read on bus 0.102 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.933 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.830) for KSEM, delay 0.003secs over
2020.11.20 10:53:01.934 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:01.826) for KSEM, delay 0.007secs over
2020.11.20 10:53:01.934 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 3, sending 003b00000006010302040004 request: id 1, fCode 3, tid 59, type h, adr 516, len 4 for device KSEM reading Active_Energy_total_-_Wh (getUpdate), queued 1.40 secs ago, read buffer empty
2020.11.20 10:53:01.934 5: SW: 003b00000006010302040004
2020.11.20 10:53:01.937 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:01.943 5: KSEM: read buffer: 003b0000000b01030800000000011a592f
2020.11.20 10:53:01.944 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 59, dlen 11 and data 0800000000011a592f
2020.11.20 10:53:01.944 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:01.944 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:01.945 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:01.945 5: KSEM: ParseObj called with data 00000000011a592f, type h, adr 516, valuesLen 4, op read
2020.11.20 10:53:01.946 5: KSEM: ParseObj ObjInfo for h516: reading=Active_Energy_total_-_Wh, unpack=Q>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:01.947 5: KSEM: ParseObj unpacked 00000000011a592f with Q> to 18503983 hex 3138353033393833
2020.11.20 10:53:01.947 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Energy_total_-_Wh, val=18503983, expr=$val / 10
2020.11.20 10:53:01.947 5: KSEM: CheckEval for ParseObj result is 1850398.3
2020.11.20 10:53:01.947 5: KSEM: ParseObj for Active_Energy_total_-_Wh does sprintf with format %.2f, value is 1850398.3
2020.11.20 10:53:01.948 5: KSEM: ParseObj for Active_Energy_total_-_Wh sprintf result is 1850398.30
2020.11.20 10:53:01.948 4: KSEM: ParseObj assigns value 1850398.30 to Active_Energy_total_-_Wh
2020.11.20 10:53:01.948 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:01.949 4: KSEM: ResponseDone request: id 1, fCode 3, tid 59, type h, adr 516, len 4 for device KSEM reading Active_Energy_total_-_Wh (getUpdate), queued 1.41 secs ago, sent 0.02 secs ago, Current read buffer: 003b0000000b01030800000000011a592f, Id 1, fCode 3, tid 59, response: id 1, fCode 3, type h, adr 516, len 4, value 00000000011a592f
2020.11.20 10:53:01.949 5: KSEM: DropFrame - drop 003b0000000b01030800000000011a592f
2020.11.20 10:53:01.949 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:01.951 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 2, next entry to id 1 (KSEM), last send to this device was 0.015 secs ago, last read 0.007 secs ago, last read on bus 0.007 secs ago from id 1 (KSEM)
2020.11.20 10:53:01.952 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.944) for KSEM, rest 0.093, set timer to try again later
2020.11.20 10:53:01.952 5: KSEM: StartQueueTimer called form CheckDelay sets internal timer to call Modbus_ProcessRequestQueue in 0.093 seconds
2020.11.20 10:53:02.045 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 2, next entry to id 1 (KSEM), last send to this device was 0.109 secs ago, last read 0.101 secs ago, last read on bus 0.101 secs ago from id 1 (KSEM)
2020.11.20 10:53:02.046 5: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:01.944) for KSEM, delay 0.001secs over
2020.11.20 10:53:02.046 5: KSEM: CheckDelay called from ProcessRequestQueue sendDelay (0.1s since 10:53:01.936) for KSEM, delay 0.010secs over
2020.11.20 10:53:02.046 4: KSEM: ProcessRequestQueue (V4.1.5 - 17.9.2019) qlen 2, sending 00b600000006010300280002 request: id 1, fCode 3, tid 182, type h, adr 40, len 2 for device KSEM reading Active_Power_L1_+_W (getUpdate), queued 1.51 secs ago, read buffer empty
2020.11.20 10:53:02.046 5: SW: 00b600000006010300280002
2020.11.20 10:53:02.048 5: KSEM: StartQueueTimer called form ProcessRequestQueue sets internal timer to call Modbus_ProcessRequestQueue in 1.000 seconds
2020.11.20 10:53:02.049 5: KSEM: read buffer: 00b60000000701030400000743
2020.11.20 10:53:02.049 4: KSEM: ParseFrameStart (TCP) extracted id 1, fCode 3, tid 182, dlen 7 and data 0400000743
2020.11.20 10:53:02.049 5: KSEM: HandleResponse called from Read
2020.11.20 10:53:02.049 5: KSEM: ParseResponse called from HandleResponse
2020.11.20 10:53:02.049 5: KSEM: HandleResponse now passing to logical device KSEM for parsing data
2020.11.20 10:53:02.049 5: KSEM: ParseObj called with data 00000743, type h, adr 40, valuesLen 2, op read
2020.11.20 10:53:02.050 5: KSEM: ParseObj ObjInfo for h40: reading=Active_Power_L1_+_W, unpack=I>, expr=$val / 10, format=%.2f, map=
2020.11.20 10:53:02.050 5: KSEM: ParseObj unpacked 00000743 with I> to 1859 hex 31383539
2020.11.20 10:53:02.050 5: KSEM: CheckEval for ParseObj evaluates expr for Active_Power_L1_+_W, val=1859, expr=$val / 10
2020.11.20 10:53:02.050 5: KSEM: CheckEval for ParseObj result is 185.9
2020.11.20 10:53:02.051 5: KSEM: ParseObj for Active_Power_L1_+_W does sprintf with format %.2f, value is 185.9
2020.11.20 10:53:02.051 5: KSEM: ParseObj for Active_Power_L1_+_W sprintf result is 185.90
2020.11.20 10:53:02.051 4: KSEM: ParseObj assigns value 185.90 to Active_Power_L1_+_W
2020.11.20 10:53:02.081 5: KSEM: HandleResponse got 1 readings from ParseObj for KSEM
2020.11.20 10:53:02.082 4: KSEM: ResponseDone request: id 1, fCode 3, tid 182, type h, adr 40, len 2 for device KSEM reading Active_Power_L1_+_W (getUpdate), queued 1.55 secs ago, sent 0.04 secs ago, Current read buffer: 00b60000000701030400000743, Id 1, fCode 3, tid 182, response: id 1, fCode 3, type h, adr 40, len 2, value 00000743
2020.11.20 10:53:02.082 5: KSEM: DropFrame - drop 00b60000000701030400000743
2020.11.20 10:53:02.082 5: KSEM: StartQueueTimer called form Read sets internal timer to call Modbus_ProcessRequestQueue in 0.000 seconds
2020.11.20 10:53:02.084 4: KSEM: ProcessRequestQueue called from HandleTimeout, qlen 1, next entry to id 1 (KSEM), last send to this device was 0.037 secs ago, last read 0.035 secs ago, last read on bus 0.035 secs ago from id 1 (KSEM)
2020.11.20 10:53:02.084 4: KSEM: CheckDelay called from ProcessRequestQueue commDelay (0.1s since 10:53:02.049) for KSEM, rest 0.065, set timer to try again later
... abgeschnitten... :-(

StefanStrobel

#581
21 November 2020, 17:50:18
Hallo,

das Log scheint abgeschnitten - am Ende steht nichts von apptime oder timeouts.
So lange Logs sollte man in Code-Tags einpacken.

Anbei nochmal eine neue Version, in der es ein neues Attribut nextOpenDelay2 gibt. Das verzögert aufeinanderfolgende Open-Calls, auch wenn der vorherige erfolgreich war.
@Gadget, damit müsstest Du Deinen Fall in den Griff bekommen.

Gruss
   Stefan

ch.eick

#582
21 November 2020, 18:10:27 Letzte Bearbeitung: 21 November 2020, 18:13:47 von ch.eick
Zitat von: StefanStrobel am 21 November 2020, 17:50:18
So lange Logs sollte man in Code-Tags einpacken.
Ein Forum Post hat auch eine Limitierung, da wird dann auch das code Tag am Ende abgeschnitten.
Also doch besser als .txt anhängen.
My five cent
   Christian
RPI4; Docker; CUNX; Eltako FSB61NP; SamsungTV H-Serie; Sonos; Vallox; Luxtronik; 3x FB7490; Stromzähler mit DvLIR; wunderground; Plenticore 10 mit BYD; EM410; SMAEM; Modbus TCP
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/ch.eick

gadget

#583
23 November 2020, 10:08:57
Zitat von: StefanStrobel am 21 November 2020, 17:50:18
Anbei nochmal eine neue Version, in der es ein neues Attribut nextOpenDelay2 gibt. Das verzögert aufeinanderfolgende Open-Calls, auch wenn der vorherige erfolgreich war.
@Gadget, damit müsstest Du Deinen Fall in den Griff bekommen.

Erfolgreich getestet. Mit

Code Auswählen
nextOpenDelay 40
nextOpenDelay2 30

bekomme ich jetzt im Fehlerfall (device in ser2net konfiguiert, aber physikalisch abgesteckt) exakt 1 Minute zwischen den Retries. Warum 1 Minute und nicht 30 Sekunden ist mir nicht klar, aber das ist mir auch nicht wichtig. Hauptsache nicht mehrfach pro Sekunde.

Danke und Grüße,

gadget.

killah78

#584
23 November 2020, 11:26:38
Zitat von: StefanStrobel am 21 November 2020, 17:50:18
das Log scheint abgeschnitten - am Ende steht nichts von apptime oder timeouts.
So lange Logs sollte man in Code-Tags einpacken.

Ja, ist abgeschnitten. Ich hatte es in Code-Tags verpackt, und die Vorschau sah auch gut aus. Naja.
Hier nochmal per File.
1.txt ist der Abruf vor apptime. Apptime verursacht Warnungen beim Aufruf (letzte 3 Zeilen).
2. txt und 3. txt sind dann manuelle Abrufe per set reread.
Eigenständig wird ab dem Aufruf von Apptime nichts mehr gelesen. Für kein Modbus-Gerät. Erst wieder nach dem Neustart von Fhem. Andere Geräte sind nicht betroffen.

Viele Grüße
Drucken
Nach oben Seiten 1 ... 37 38 39 40 41 ... 87
Benutzer-Aktionen