OWX_ASYNC besser aber noch Timingprobleme

fhem-challenge · 08 April 2014, 11:01:35

Hallo (hallo Norbert),

Seit Benutzung des OWX_ASYNC läuft OWX nun erheblich besser, aber immer noch tauchen Timingprobleme auf.

Siehe dazu :
http://forum.fhem.de/index.php/topic,21770.0.html
http://forum.fhem.de/index.php/topic,13580.msg155813.html#msg155813

Meine Umgebung:

1-wire --> Arduino (Mega) + Ethershield <--> FHEM Server (Cubitruck)

Ich habe hier im FHEM Server derzeit nur OWX/OWTHERM konfiguriert, um etwaige Implikationen anderer Module weitestgehend außschliessen zu können.

Wenn ich hingegen mein FHEM Server (Cubitruck) erheblich herunter takte (~200MHz) funktioniert es (dieser Effekt ist bei zwei ganz unterschiedlichen Systemen reproduzierbar). Beim Raspi als FHEM Server, funktioniert es hingegen auch tadellos, da dieser nun hinreichend "langsam" ist.

Wenn ich mir die Anzahl der 5 Minuten (1-wire) Temperaturwerte im Logfile anschaue, sind teilweise große Lücken erkennbar. I.d.R. sollten es 12 Werte pro Stunde sein, bei dem default OWX interval von 300(s).

Nachfolgende "Tabelle" zeigt die Anzahl der Werte pro Stunde (also 4 Werte im Zeitraum von 00:00 - 00:59 Uhr, oder 8 Werte im Zeitraum von 01:00 - 01:59 Uhr etc.), für einen 1w-Sensor. Teilweise sind es hier nur 2 Werte pro Stunde (14:00 - 14:59)

Code Auswählen

root@fhem-server:~# grep "2014-04-07" /opt/fhem/log/ow_EF1E58040000.2014.log | cut -d" " -f1 | grep -iEo "_[0-9]{1,2}" | sed s/"_"//g | uniq -c
      4 00
      8 01
      8 02
     12 03
      8 04
     12 05
     11 06
      8 07
      9 08
     11 09
     10 10
      8 11
      3 12
      3 13
      2 14
      4 15
     11 16
     12 17
     12 18
     11 19
      9 20
      5 21
     12 22
     12 23

Viele Grüße!

Andreas

ntruchsess · 08 April 2014, 17:49:29

füge in der 21_OWTHERM.pm, um die Zeile 380 herum doch mal bitte eine logzeile derart ein:

Code Auswählen


  #-- put into READINGS
  readingsBeginUpdate($hash);
  readingsBulkUpdate($hash,"temperature",$vval);
  Log3 $hash->{NAME},1,"OWTHERM: $hash->{NAME}: updating reading temperature $vval";
  #-- STATE
  readingsBulkUpdate($hash,"state",$svalue);
  readingsEndUpdate($hash,1);

damit wir sehen, ob readingsBulkUpdate aufgerufen wird, oder nicht.

Gruß,

Norbert

fhem-challenge · 09 April 2014, 09:16:05

Hallo Norbert,

ich logge nun mit, die Lücken sind auch hier sichtbar. Ich habe 5 x DS18B20 am Bus. Auch hier sieht man die sporadischen Lücken (bei 09:07:21, 08:57:21.

Code Auswählen

2014.04.09 08:52:07 3: FIRMATA: port 3030 opened
2014.04.09 08:52:07 3: NTFY return: OWX_ASYNC_Init failed: OW, FIRMATA is not connected
2014.04.09 08:52:07 0: Server started with 409 defined entities (version $Id: fhem.pl 5452 2014-04-06 06:24:47Z rudolfkoenig $, os linux, user root, pid 2663)
2014.04.09 08:52:08 4: Connection accepted from FRM:192.168.100.221:1154
2014.04.09 08:52:10 3: querying Firmata Firmware Version
2014.04.09 08:52:10 3: Firmata Firmware Version: fhem_firmata.ino V_2_05
2014.04.09 08:52:16 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.0625
2014.04.09 08:52:16 1: OWTHERM: temp_1ACC57040000: updating reading temperature 20.875
2014.04.09 08:52:16 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.75
2014.04.09 08:52:16 1: OWTHERM: temp_EF1E58040000: updating reading temperature 45.0625
2014.04.09 08:52:16 1: OWTHERM: temp_2A6757040000: updating reading temperature 20.9375
2014.04.09 08:57:21 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.75
2014.04.09 08:57:21 1: OWTHERM: temp_EF1E58040000: updating reading temperature 45
2014.04.09 08:57:21 1: OWTHERM: temp_2A6757040000: updating reading temperature 20.9375
2014.04.09 09:02:21 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.0625
2014.04.09 09:02:21 1: OWTHERM: temp_1ACC57040000: updating reading temperature 20.875
2014.04.09 09:02:21 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.6875
2014.04.09 09:02:21 1: OWTHERM: temp_EF1E58040000: updating reading temperature 44.75
2014.04.09 09:02:21 1: OWTHERM: temp_2A6757040000: updating reading temperature 20.875
2014.04.09 09:07:21 1: OWTHERM: temp_12E29D040000: updating reading temperature 21
2014.04.09 09:07:21 1: OWTHERM: temp_1ACC57040000: updating reading temperature 20.875
2014.04.09 09:07:21 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.6875
2014.04.09 09:12:21 1: OWTHERM: temp_12E29D040000: updating reading temperature 21
2014.04.09 09:12:21 1: OWTHERM: temp_1ACC57040000: updating reading temperature 20.875
2014.04.09 09:12:21 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.6875
2014.04.09 09:12:21 1: OWTHERM: temp_EF1E58040000: updating reading temperature 44.375
2014.04.09 09:12:21 1: OWTHERM: temp_2A6757040000: updating reading temperature 20.875

Weiterer Logauszug:

Code Auswählen

2014.04.09 11:52:02 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.4375
2014.04.09 11:52:02 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.25
2014.04.09 11:52:03 1: OWTHERM: temp_D6F59C040000: updating reading temperature 21.0625
2014.04.09 11:52:03 1: OWTHERM: temp_EF1E58040000: updating reading temperature 44.5
2014.04.09 11:52:03 1: OWTHERM: temp_2A6757040000: updating reading temperature 21.25

2014.04.09 11:57:07 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.375
2014.04.09 11:57:07 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.25
2014.04.09 11:57:07 1: OWTHERM: temp_D6F59C040000: updating reading temperature 21.0625
2014.04.09 11:57:07 1: OWTHERM: temp_EF1E58040000: updating reading temperature 44.4375
2014.04.09 11:57:07 1: OWTHERM: temp_2A6757040000: updating reading temperature 21.25

2014.04.09 12:02:12 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.25
2014.04.09 12:02:12 1: OWTHERM: temp_D6F59C040000: updating reading temperature 21.0625
2014.04.09 12:02:12 1: OWTHERM: temp_EF1E58040000: updating reading temperature 44.1875
2014.04.09 12:02:12 1: OWTHERM: temp_2A6757040000: updating reading temperature 21.25

2014.04.09 12:07:12 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.375
2014.04.09 12:07:12 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.1875
2014.04.09 12:07:12 1: OWTHERM: temp_D6F59C040000: updating reading temperature 21.0625
2014.04.09 12:07:12 1: OWTHERM: temp_EF1E58040000: updating reading temperature 44
2014.04.09 12:07:12 1: OWTHERM: temp_2A6757040000: updating reading temperature 21.1875

2014.04.09 12:12:12 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.3125
2014.04.09 12:12:12 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.1875
2014.04.09 12:12:12 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.9375

2014.04.09 12:17:12 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.3125
2014.04.09 12:17:12 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.1875
2014.04.09 12:17:12 1: OWTHERM: temp_D6F59C040000: updating reading temperature 21

2014.04.09 12:22:12 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.3125
2014.04.09 12:22:12 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.125
2014.04.09 12:22:12 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.9375
2014.04.09 12:22:13 1: OWTHERM: temp_EF1E58040000: updating reading temperature 43.375
2014.04.09 12:22:13 1: OWTHERM: temp_2A6757040000: updating reading temperature 21.125

2014.04.09 12:27:12 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.25
2014.04.09 12:27:12 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.0625
2014.04.09 12:27:12 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.875

2014.04.09 12:32:12 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.25
2014.04.09 12:32:12 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.0625
2014.04.09 12:32:12 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.9375

2014.04.09 12:37:15 1: OWTHERM: temp_2A6757040000: updating reading temperature 21.0625

2014.04.09 12:42:15 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.25
2014.04.09 12:42:15 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.0625
2014.04.09 12:42:15 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.875
2014.04.09 12:42:15 1: OWTHERM: temp_EF1E58040000: updating reading temperature 42.625
2014.04.09 12:42:15 1: OWTHERM: temp_2A6757040000: updating reading temperature 21.125

2014.04.09 12:47:15 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.1875
2014.04.09 12:47:15 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.0625
2014.04.09 12:47:15 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.8125

2014.04.09 12:52:15 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.1875
2014.04.09 12:52:15 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21
2014.04.09 12:52:15 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.875

2014.04.09 12:57:20 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.875
2014.04.09 12:57:20 1: OWTHERM: temp_EF1E58040000: updating reading temperature 42
2014.04.09 12:57:20 1: OWTHERM: temp_2A6757040000: updating reading temperature 21.0625

2014.04.09 13:02:20 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.1875
2014.04.09 13:02:20 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21.0625
2014.04.09 13:02:20 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.875
2014.04.09 13:02:20 1: OWTHERM: temp_EF1E58040000: updating reading temperature 41.8125
2014.04.09 13:02:20 1: OWTHERM: temp_2A6757040000: updating reading temperature 21.0625

2014.04.09 13:07:20 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.125
2014.04.09 13:07:20 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21
2014.04.09 13:07:20 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.8125
2014.04.09 13:07:20 1: OWTHERM: temp_EF1E58040000: updating reading temperature 41.625
2014.04.09 13:07:20 1: OWTHERM: temp_2A6757040000: updating reading temperature 20.9375

2014.04.09 13:12:20 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.0625
2014.04.09 13:12:20 1: OWTHERM: temp_1ACC57040000: updating reading temperature 20.875
2014.04.09 13:12:20 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.6875
2014.04.09 13:12:20 1: OWTHERM: temp_EF1E58040000: updating reading temperature 41.4375
2014.04.09 13:12:20 1: OWTHERM: temp_2A6757040000: updating reading temperature 20.875

2014.04.09 13:17:23 1: OWTHERM: temp_12E29D040000: updating reading temperature 21.125
2014.04.09 13:17:23 1: OWTHERM: temp_1ACC57040000: updating reading temperature 21
2014.04.09 13:17:23 1: OWTHERM: temp_D6F59C040000: updating reading temperature 20.8125
2014.04.09 13:17:23 1: OWTHERM: temp_EF1E58040000: updating reading temperature 41.25
2014.04.09 13:17:23 1: OWTHERM: temp_2A6757040000: updating reading temperature 21

Eine gleichmässige Verteilung , oder gar eine Logik ist nicht sichtbar. Es sind alle 1-w Sensoren von den 5 angebundenen Sensoren betroffen. Ein signifikantes Auftreten von "Lücken" für bestimmte Sensoren (oder auch eine Reihenfolge) ist nicht sichtbar.

Anbei die Verteilung der Messwerte auf die jeweiligen 1-w Sensoren für einen Zeitraum von ca. 1,5 Stunden.:

Code Auswählen

root@fhem-server:~# cat /opt/fhem/log/fhem-2014-04.log | grep -i "OWTHERM:" | grep -i "updating" | cut -d: -f5 | sort | uniq -c | sort -gr
     18  temp_D6F59C040000
     18  temp_1ACC57040000
     16  temp_12E29D040000
     14  temp_2A6757040000
     12  temp_EF1E58040000

Viele Grüße!

Andreas

Alexander Bauer · 09 April 2014, 11:53:23

Hallo,

ich habe heute versucht die aktuelle Versionen (OWX, OWSWITCH und OWCOUNT 5.15) über socat/kristech ebenfalls auf meinen Cubietruck zu nutzen.

Variante Sync

Code Auswählen

2014.04.09 11:19:53 3: Opening OWio1 device /dev/vmodem0
2014.04.09 11:19:53 3: Setting OWio1 baudrate to 9600
2014.04.09 11:19:53 3: OWio1 device opened
2014.04.09 11:19:53 1: OWX: Serial device /dev/vmodem0 defined
2014.04.09 11:19:55 3: OWAD:    Device OWX_20_F16410000000 defined.
2014.04.09 11:19:55 3: OWSWITCH: Device OWXSWITCH defined.
2014.04.09 11:19:55 3: OWSWITCH: Device WAC_SWITCH defined.
2014.04.09 11:19:55 3: OWID: Device OWX_01_1025C7160000 defined.
2014.04.09 11:19:55 3: OWCOUNT: Device H.U.ST.HK defined.
2014.04.09 11:19:55 3: OWCOUNT: Device H.U.ST.LV defined.
2014.04.09 11:19:55 3: OWCOUNT: Device H.U.ST.LL defined.
2014.04.09 11:19:55 1: OWX: 1-Wire bus OWio1: interface not found, answer was 0x07 0x05 0x0b 0x0f 0x01 
2014.04.09 11:19:56 1: OWX: 1-Wire bus OWio1: interface not found, answer was 0x07 0x05 0x0b 0x0f 0x01 
2014.04.09 11:19:57 1: OWX: 1-Wire bus OWio1: interface not found, answer was 0x07 0x05 0x0b 0x0f 0x01

Socat lief zu diesem Zeitpunkt.

Variante ASync

Code Auswählen

2014.04.09 11:27:09 3: OWAD:    Device OWX_20_F16410000000 defined.
2014.04.09 11:27:09 3: OWSWITCH: Device OWXSWITCH defined.
2014.04.09 11:27:09 3: OWSWITCH: Device WAC_SWITCH defined.
2014.04.09 11:27:09 3: OWID: Device OWX_01_1025C7160000 defined.
2014.04.09 11:27:09 3: OWCOUNT: Device H.U.ST.HK defined.
2014.04.09 11:27:09 3: OWCOUNT: Device H.U.ST.LV defined.
2014.04.09 11:27:09 3: OWCOUNT: Device H.U.ST.LL defined.
2014.04.09 11:27:09 3: H.U.ST.LL: unknown attribute loglevel. Type 'attr H.U.ST.LL ?' for a detailed list.
2014.04.09 11:27:09 1: CDVS WAC Found 15 Device(s): open: 0, closed: 0, titled: 0, excluded: 0, unknown: 15
2014.04.09 11:27:09 1: Including ./log/fhem.save
2014.04.09 11:27:09 1: configfile: H.U.ST.LL: unknown attribute loglevel. Type 'attr H.U.ST.LL ?' for a detailed list.

2014.04.09 11:27:09 3: Opening OWio1 device /dev/vmodem0
2014.04.09 11:27:09 3: Setting OWio1 baudrate to 9600
2014.04.09 11:27:09 3: OWio1 device opened
2014.04.09 11:27:09 1: OWX_SER: Serial device /dev/vmodem0@9600 defined

Dann hat sich 5 Minuten nichts mehr getan und ich habe den fhem und socat gekillt.

Da ich leider kein extra Testsystem habe, bin auf die bei mir bisher funktionierenden Versionen zurück:
# $Id: 21_OWAD.pm 5035 2014-02-24 03:47:01Z pahenning $
# $Id: 21_OWCOUNT.pm 5125 2014-03-04 12:38:50Z pahenning $
# $Id: 21_OWID.pm 5296 2014-03-22 17:08:16Z ntruchsess $
# $Id: 21_OWSWITCH.pm 5035 2014-02-24 03:47:01Z pahenning $
# $Id: 00_OWX.pm 5267 2014-03-20 20:44:43Z ntruchsess $

Code Auswählen

2014.04.09 11:32:34 3: Opening OWio1 device /dev/vmodem0
2014.04.09 11:32:34 3: Setting OWio1 baudrate to 9600
2014.04.09 11:32:34 3: OWio1 device opened
2014.04.09 11:32:34 1: OWX: Serial device /dev/vmodem0 defined
2014.04.09 11:32:35 3: telnetPort: port 7072 opened
2014.04.09 11:32:35 3: OWAD:    Device OWX_20_F16410000000 defined.
2014.04.09 11:32:35 3: OWSWITCH: Device OWXSWITCH defined.
2014.04.09 11:32:35 3: OWSWITCH: Device WAC_SWITCH defined.
2014.04.09 11:32:35 3: OWID: Device OWX_01_1025C7160000 defined.
2014.04.09 11:32:35 3: OWCOUNT: Device H.U.ST.HK defined.
2014.04.09 11:32:35 3: OWCOUNT: Device H.U.ST.LV defined.
2014.04.09 11:32:35 3: OWCOUNT: Device H.U.ST.LL defined.
2014.04.09 11:32:36 1: OWX: 1-Wire bus OWio1: interface master DS2480 detected for the first time
2014.04.09 11:32:57 1: OWX: 1-Wire devices found on bus OWio1 (OWX_20_F16410000000,OWXSWITCH,WAC_SWITCH,OWX_01_1025C7160000,H.U.ST.LL,H.U.ST.HK,H.U.ST.LV)

Auszug aus fhem.cfg

Code Auswählen

define OWio1 OWX /dev/vmodem0

define H.U.ST.LV OWCOUNT DS2423 B1CC0D000000
attr H.U.ST.LV AFactor 0.001
attr H.U.ST.LV AMode daily
attr H.U.ST.LV AName Stromverbrauch|energy
attr H.U.ST.LV APeriod hour
attr H.U.ST.LV AUnit kWk|kWk
attr H.U.ST.LV BFactor 0.001
attr H.U.ST.LV BMode daily
attr H.U.ST.LV BName Stromverbrauch2|energy2
attr H.U.ST.LV BPeriod hour
attr H.U.ST.LV BUnit kWk|kWk
attr H.U.ST.LV IODev OWio1
attr H.U.ST.LV LogM FileLog_H.U.ST.LV_M
attr H.U.ST.LV model DS2423
attr H.U.ST.LV room OWX
define OWXSWITCH OWSWITCH DS2413 B85403000000
attr OWXSWITCH AName Fussbodenheizung
attr OWXSWITCH BName Heizung
attr OWXSWITCH IODev OWio1
attr OWXSWITCH model DS2413
attr OWXSWITCH room OWX

ntruchsess · 09 April 2014, 14:32:01

@Andreas: das ist in der Tat merkwürdig. Stell mal im OWX_ASYNC verbose auf 5 und im OWTHERM loglevel auch auf 5, dann sollten die gelesenen 1-Wire-werte schön sauber geloggt werden (das sollte für weiteren Erkenntnisgewinn hoffendlich reichen. FRM-low-level ist eher unübersichtlich).

@Alexander: Scheint, als ob die über socat bereitgestellte virtuelle serielle Schnittstelle sich doch nicht identisch verhält oder das Timing bei der Initialisierung über Ethernet nicht passt. Die DS2480-Unterstützung in OWX_ASYNC ist bei der initialisierung vermutlich etwas kritisch. Deine Konfiguration kann ich mangels Hardware leider selber gar nicht testen und werde ich so (über socat) in OWX_ASYNC auch gar nicht unterstützen (wenn sich wer anders darum kümmern will, dann gerne - ich habe einfach nur begrenzt Zeit).
Ich möchte erst mal den DS2480 direkt (über USB/Seriell) angeschlossen richtig stabil kriegen, und würde anschließend für die remote-anbindung über Ethernet native Unterstützung direkt ins 11_OWX_SER.pm einbauen. Das Konstrukt mit socat sehe ich nur als Zwischenlösung.
Trotzdem vielen Dank für das Feedback, vieleicht magst du ja mal DS2480 ohne Ethernet testen.

Gruß,

Norbert

fhem-challenge · 09 April 2014, 15:16:02

Hallo Norbert,

anbei das Log mit Loglevel 5 & verbose 5. "readdata:" hat hier Lücken.

Code Auswählen

2014.04.09 14:52:23 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: 44, numread: 0, readdata: 
2014.04.09 14:52:24 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: 44, numread: 0, readdata: 
2014.04.09 14:52:24 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: 44, numread: 0, readdata: 
2014.04.09 14:52:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: be, numread: 9, readdata: 56014b467fff0a10d1
2014.04.09 14:52:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: be, numread: 9, readdata: 53014b467fff0d10e9
2014.04.09 14:52:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: be, numread: 9, readdata: 50014b467fff101049
2014.04.09 14:52:27 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: 44, numread: 0, readdata: 
2014.04.09 14:52:27 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: be, numread: 9, readdata: bf024b467fff0110af
2014.04.09 14:52:29 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: 44, numread: 0, readdata: 
2014.04.09 14:52:29 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: be, numread: 9, readdata: 53014b467fff0d10e9
2014.04.09 14:57:23 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: 44, numread: 0, readdata: 
2014.04.09 14:57:24 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: 44, numread: 0, readdata: 
2014.04.09 14:57:24 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: 44, numread: 0, readdata: 
2014.04.09 14:57:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: be, numread: 9, readdata: 56014b467fff0a10d1
2014.04.09 14:57:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: be, numread: 9, readdata: 53014b467fff0d10e9
2014.04.09 14:57:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: be, numread: 9, readdata: 50014b467fff101049
2014.04.09 14:57:27 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: 44, numread: 0, readdata: 
2014.04.09 14:57:27 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: be, numread: 9, readdata: bc024b467fff041095
2014.04.09 14:57:29 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: 44, numread: 0, readdata: 
2014.04.09 14:57:29 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: be, numread: 9, readdata: 53014b467fff0d10e9
2014.04.09 15:02:23 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: 44, numread: 0, readdata: 
2014.04.09 15:02:24 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: 44, numread: 0, readdata: 
2014.04.09 15:02:24 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: 44, numread: 0, readdata: 
2014.04.09 15:02:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: be, numread: 9, readdata: 56014b467fff0a10d1
2014.04.09 15:02:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: be, numread: 9, readdata: 53014b467fff0d10e9
2014.04.09 15:02:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: be, numread: 9, readdata: 51014b467fff0f10fe
2014.04.09 15:02:27 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: 44, numread: 0, readdata: 
2014.04.09 15:02:27 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: be, numread: 9, readdata: b8024b467fff0810cd
2014.04.09 15:02:32 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: 44, numread: 0, readdata: 
2014.04.09 15:02:32 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: be, numread: 9, readdata: 53014b467fff0d10e9
2014.04.09 15:07:23 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: 44, numread: 0, readdata: 
2014.04.09 15:07:24 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: 44, numread: 0, readdata: 
2014.04.09 15:07:24 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: 44, numread: 0, readdata: 
2014.04.09 15:07:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: be, numread: 9, readdata: 55014b467fff0b10d0
2014.04.09 15:07:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: be, numread: 9, readdata: 53014b467fff0d10e9
2014.04.09 15:07:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: be, numread: 9, readdata: 4f014b467fff0110cf
2014.04.09 15:07:27 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: 44, numread: 0, readdata: 
2014.04.09 15:07:27 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: be, numread: 9, readdata: b5024b467fff0b10e4
2014.04.09 15:07:33 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: 44, numread: 0, readdata: 
2014.04.09 15:07:33 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: be, numread: 9, readdata: 53014b467fff0d10e9
2014.04.09 15:12:23 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: 44, numread: 0, readdata: 
2014.04.09 15:12:24 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: 44, numread: 0, readdata: 
2014.04.09 15:12:24 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: 44, numread: 0, readdata: 
2014.04.09 15:12:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: be, numread: 9, readdata: 55014b467fff0b10d0
2014.04.09 15:12:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: be, numread: 9, readdata: 52014b467fff0e10ff
2014.04.09 15:12:24 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: be, numread: 9, readdata: 4f014b467fff0110cf
2014.04.09 15:12:27 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: 44, numread: 0, readdata: 
2014.04.09 15:12:27 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: be, numread: 9, readdata: b2024b467fff0e10cb
2014.04.09 15:12:33 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: 44, numread: 0, readdata: 
2014.04.09 15:12:33 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: be, numread: 9, readdata: 52014b467fff0e10ff

VIele Grüße!

Andreas

Alexander Bauer · 09 April 2014, 15:30:52

Hallo Norbert,

DS2480 ohne Ethernet geht seit letzten Freitag nimmer, da wegen anderer Dinge der Cubietruck umgezogen ist.

Falls es eine Version ohne socat gegeben sollte, bin ich gerne zum testen bereit.

Ciao

Alexander

ntruchsess · 09 April 2014, 15:31:56

Zitat von: fhem-challenge am 09 April 2014, 15:16:02
anbei das Log mit Loglevel 5 & verbose 5. "readdata:" hat hier Lücken.

'writedata: 44' triggert die Temperaturmessung, da wird nichts gelesen.
Gelesen werden jeweils 9 bytes bei 'writedata be'. Bei readdata stehen dann immer diese 9 bytes (uninterpretierte roh-werte).
Ohne diese Rohdaten jetzt zu analysieren sieht erst mal in Ordnung aus, jedenfalls werden alle 5 Minuten 5 Messungen angestoßen und jeweils ca. 1 sekunde später auch ausgelesen.

Dummerweise loggt das OWTHERM selbst nichts, sonst würde man sehen, wo bzw. ob diese roh-daten in Ordnung sind (oder z.B. CRC-fehler auftreten).

Gruß,

Norbert

ntruchsess · 09 April 2014, 15:42:02

stell mal im OWX_ASYNC verbose auf 4, dann loggt das die Fehler, die OWTHERM beim interpretieren der Rohwerte an OWX_ASYNC zurückgibt. Das kann OWTHERM im asynchronen Modus ja gar nicht loggen, weil es die Methode selber gar nicht aufruft.

verbose = 5 muss nicht sein, 4 reicht dafür.

EDIT: hab grad gesehen, dass ich da Mist geschrieben habe. Verbose in OWX_ASYNC stand ja wohl schon auf 5. Muss da noch ein bischen drüber sinieren - weil wenn die geloggten Meldungen im Log stehen, dann müsste eigentlich auch OWTHERM aufgerufen worden sein und entweder erfolgreich die Readings geupdatet haben oder eben eine Fehlermeldung zurückgeben, die dann im Log zu finden wäre.
Es sei denn, dass diese Bedingung nicht erfüllt gewesen wäre. Die tested aber lauter Werte, die sich nicht mehr ändern, solange das IODev verbunden bleibt.

Gruß,

Norbert

det. · 09 April 2014, 17:16:45

Hallo Norbert,
bin gerade mit einem Cubietruck fertig geworden und hab mal zum Test einen seriellen DS2480 Eigenbauadapter und paar Sensoren dran laufen lassen. Die cfg und log sind im Dateianhang. Vielleicht nutzt es Dir was.
Das Webinterface ist gefühlt sehr schnell trotz 5s Abfrageintervall.

ntruchsess · 09 April 2014, 20:14:04

Hallo det.

danke für die Rückmeldung, bis auf die beiden OWAD sieht das ja ganz gut aus. Ich schau gleich mal, welche Abfrage da eigentlich schiefgeht, wenn 'invalid data length, 0 instead of 10 bytes' geloggt wird.

Gruß,

Norbert

Prof. Dr. Peter Henning · 09 April 2014, 21:30:48

Selbstverständlich geben die entsprechenden Funktionen im OWTHERM Returnwerte mit Fehlermeldungen - z.B. CRC_Fehler. Fängst Du die in Deinem FRM-Backend möglicherweise ab, statt sie zu loggen ?

LG aus Tel Aviv

pah

ntruchsess · 09 April 2014, 21:52:31

Zitat von: Prof. Dr. Peter Henning am 09 April 2014, 21:30:48FRM-Backend möglicherweise ab, statt sie zu loggen ?

Nein, natürlich nicht. Zwischen dem FRM-backend und OWTHERM steht OWX_ASYNC_AfterExecute und das loggt alles, was OWTHERM über die AfterExecuteFn (aka OWTHERM_BinValues) zurückgibt mit loglevel 4. Ein paar Zeilen weiter oben ist die Logausgabe, die sich in Andreas log finden:

Zitat von: fhem-challenge am 09 April 2014, 15:16:02
Code Auswählen Erweitern
2014.04.09 14:52:27 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: 44, numread: 0, readdata: 2014.04.09 14:52:27 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: be, numread: 9, readdata: bf024b467fff0110af ...

Also entweder gabs da gar keinen Fehler, oder ich weiß auch nicht...

Gruß nach Tel Aviv

,

Norbert

fhem-challenge · 10 April 2014, 09:04:39

Hallo Norbert,

seit gestern Nachmittag bekomme ich im Log nun auch "OWX_ASYNC_AfterExecute [28.BAEC9C040000.40]: invalid data length, 8 instead of 9 bytes".

Logauszug:

Code Auswählen

2014.04.09 15:40:33 4: OWX_ASYNC_AfterExecute [28.12E29D040000.90]: invalid data length, 8 instead of 9 bytes
2014.04.09 15:40:33 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: 44, numread: 0, readdata: 
2014.04.09 15:40:33 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: be, numread: 9, readdata: 51014b467fff0f10fe
2014.04.09 15:40:33 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.D6F59C040000.71, writedata: be, numread: 9, readdata: 4e014b467fff0210d9
2014.04.09 15:40:33 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: 44, numread: 0, readdata: 
2014.04.09 15:40:34 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: 44, numread: 0, readdata: 
2014.04.09 15:40:34 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.BAEC9C040000.40, writedata: be, numread: 9, readdata: a1928cfefe1f203c
2014.04.09 15:40:34 4: OWX_ASYNC_AfterExecute [28.BAEC9C040000.40]: invalid data length, 8 instead of 9 bytes
2014.04.09 15:40:34 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.2A6757040000.E7, writedata: be, numread: 9, readdata: 51918cfefe1f20fc
2014.04.09 15:40:34 4: OWX_ASYNC_AfterExecute [28.2A6757040000.E7]: invalid data length, 8 instead of 9 bytes
2014.04.09 15:45:33 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: 44, numread: 0, readdata: 
2014.04.09 15:45:33 5: AfterExecute: context: ds182x.convert, success: 1, reset: 1, owx_dev: 28.1ACC57040000.49, writedata: 44, numread: 0, readdata: 
2014.04.09 15:45:33 5: AfterExecute: context: ds182x.reading, success: 1, reset: 1, owx_dev: 28.12E29D040000.90, writedata: be, numread: 9, readdata: 54918cfefe1920fa
2014.04.09 15:45:33 4: OWX_ASYNC_AfterExecute [28.12E29D040000.90]: invalid data length, 8 instead of 9 bytes

Frage:

Im Bereich der Zeile 863 (21_OWTHERM) ... ist hier schon $res vor dem "split" zu klein ?

Code Auswählen

#-- process results
  @data=split(//,$res);
  return "invalid data length, ".int(@data)." instead of 9 bytes"
    if (@data != 9); 
  return "invalid data"
    if (ord($data[7])<=0); 
  return "invalid CRC"
    if (OWX_CRC8(substr($res,0,8),$data[8])==0);  
  
  #-- this must be different for the different device types

Noch eigenartigere Frage: Ist es relevant, ob hier ein DS18B20 oder DS1820 am Bus hängt ? werden die richtig "erkannt" ?

Seit gestern Abend gab es teilweise Lücken von >= 1 Stunde. Ein "set FIRMATE reset" löst vorübergehend die Situation.

Viele Grüße!

Andreas

ntruchsess · 10 April 2014, 09:31:25

Zitat von: fhem-challenge am 10 April 2014, 09:04:39
seit gestern Nachmittag bekomme ich im Log nun auch "OWX_ASYNC_AfterExecute [28.BAEC9C040000.40]: invalid data length, 8 instead of 9 bytes".

Das erklärt, warum die Updates manchmal ausfallen.

Zitat von: fhem-challenge am 10 April 2014, 09:04:39
Im Bereich der Zeile 863 (21_OWTHERM) ... ist hier schon $res vor dem "split" zu klein ?

ja, das ist in dem Fall schon in der Firmata-message (und damit ziemlich sicher auch schon auf dem 1-Wire bus) zu kurz. Nur erkennt man das im Log wegen der 7-bit-codierung der Firmata-messages mit dem Auge nur sehr schwer.

Zitat von: fhem-challenge am 10 April 2014, 09:04:39
Noch eigenartigere Frage: Ist es relevant, ob hier ein DS18B20 oder DS1820 am Bus hängt ? werden die richtig "erkannt" ?

Die werden anhand der Family-id ('10' vs. '28') sicher unterschieden. Die Länge des Scratchpads ist aber bei beiden gleich. Das fehlende 9. Byte wäre der CRC-wert.

Eventuell sind ja die Delays zwischen dem Beginn der Temperaturmessung und dem Auslesen zu knapp bemessen. Das würde auch zu Deiner beobachteten Korrelation zwischen Taktfrequenz und Messerfolg passen. Mit niedriger Taktfrequenz ist es wahrscheinlicher, dass das Delay länger ausfällt (Fhem läuft ja nur in einem Thread). Bei kleinem Sampling-interval auch (wobei hier der Arduino für die mögliche Verlängerung verantwortlich wäre).

Du kannst ja zum Testen einfach mal alle Werte im %convtimes verdoppeln.

Gruß,

Norbert