Stacktrace Meldung: missed to call readingsBeginUpdate first

[klausw]

Hallo zusammen,

Ich bekomme eine Reihe von stacktrace Meldungen. Hier ein Beispiel:

Code Auswählen Erweitern

2020.01.09 18:31:12 1: stacktrace:
2020.01.09 18:31:12 1:     main::readingsBulkUpdate            called by ./FHEM/98_livetracking.pm (1103)
2020.01.09 18:31:12 1:     main::livetracking_ParseOwnTracks   called by ./FHEM/98_livetracking.pm (1207)
2020.01.09 18:31:12 1:     main::livetracking_Notify           called by fhem.pl (3761)
2020.01.09 18:31:12 1:     main::CallFn                        called by fhem.pl (3681)
2020.01.09 18:31:12 1:     main::DoTrigger                     called by fhem.pl (4745)
2020.01.09 18:31:12 1:     main::readingsEndUpdate             called by fhem.pl (4927)
2020.01.09 18:31:12 1:     main::readingsSingleUpdate          called by ./FHEM/10_MQTT_DEVICE.pm (249)
2020.01.09 18:31:12 1:     MQTT::DEVICE::onmessage             called by ./FHEM/00_MQTT.pm (535)
2020.01.09 18:31:12 1:     MQTT::__ANON__                      called by FHEM/GPUtils.pm (75)
2020.01.09 18:31:12 1:     GPUtils::GP_ForallClients           called by ./FHEM/00_MQTT.pm (545)
2020.01.09 18:31:12 1:     MQTT::Read                          called by fhem.pl (3761)
2020.01.09 18:31:12 1:     main::CallFn                        called by fhem.pl (756)
2020.01.09 18:31:12 1: readingsUpdate(ot.klaus,distance,299.8) missed to call readingsBeginUpdate first.

Die Meldungen kommen für alle Readings dieses Moduls.
Allerdings nur in Verbindung mit dem Modul

Code (https://forum.fhem.de/index.php/topic,93565.msg862147.html#msg862147) Auswählen Erweitern

98_livetrackingconn.pm
Ohne eine Definition von 98_livetrackingconn.pm kommt keine Stacktrace Meldung.

Das Modul 98_livetrackingconn.pm hat als "NOTIFYDEV" "TYPE=livetracking" definiert. Bei einem notify werden Funktionen des Moduls RESIDENTStk aufgerufen um in den Resident Devices die Positionsreadings zu aktualisieren.

Hat jemand einen Tip für mich wieso die Meldungen kommen?
Wenn ich das richtig verstehe wird beim BulkUpdate doch erst mit readingsEndUpdate ein notify ausgelöst.
Die Stacktrace Meldungen suggerieren aber was anderes.

Grüße
Klaus

[rudolfkoenig]

Das gezeigte Beispiel ist irrefuehrend: da die Zeile mit "missed to call" vor dem stacktrace ausgegeben wird, kann man die readingsBulkUpdate Parameter nicht mit den stacktrace-Zeilen korrelieren.

Die Meldung kommt, wenn $hash->{".updateTimestamp"} nicht definiert ist, und das wird nur in readingsBeginUpdate angelegt, und in readingsEndUpdate entfernt, d.h. readingsEndUpdate wird (direkt oder indirekt) nach readingsBeginUpdate und vor dem problematischen readingsBulkUpdate aufgerufen.

Ich koennte nur anhand eines "attr global verbose 5" logs mehr sagen, oder wenn man mir etwas zum Nachstellen gibt.

[klausw]

Hier nochmal mit verbose 5:

Code Auswählen Erweitern

2020.01.11 00:06:14 4: WEB_127.0.0.1_42310 POST /fhem?cmd.x=set%20mqtt.klaus%20cmd%20%7B%22_type%22%3A%22transition%22%2C%22acc%22%3A20%2C%22desc%22%3A%22Adl%22%2C%22event%22%3A%22enter%22%2C%22lat%22%3A50.111%2C%22lon%22%3A8.555%2C%22t%22%3A%22l%22%2C%22tid%22%3A%22KW%22%2C%22tst%22%3A1578693749%2C%22wtst%22%3A1518169127785%7D&XHR=1&fwcsrf=csrf_301719868384684&fw_id=573; BUFLEN:0
2020.01.11 00:06:14 5: Cmd: >set mqtt.klaus cmd {"_type":"transition","acc":20,"desc":"Adl","event":"enter","lat":50.111,"lon":8.555,"t":"l","tid":"KW","tst":1578693749,"wtst":1518169127785}<
2020.01.11 00:06:14 5: MQTT mqtt message sent: Publish/at-least-once owntracks/klaus/Klaus/event/9
  7b 22 5f 74 79 70 65 22 3a 22 74 72 61 6e 73 69  {"_type":"transi
  74 69 6f 6e 22 2c 22 61 63 63 22 3a 32 30 2c 22  tion","acc":20,"
  64 65 73 63 22 3a 22 41 64 6c 22 2c 22 65 76 65  desc":"Adl","eve
  6e 74 22 3a 22 65 6e 74 65 72 22 2c 22 6c 61 74  nt":"enter","lat
  22 3a 35 30 2e 31 31 31 2c 22 6c 6f 6e 22 3a 38  ":50.111,"lon":8
  2e 35 35 35 2c 22 74 22 3a 22 6c 22 2c 22 74 69  .555,"t":"l","ti
  64 22 3a 22 4b 57 22 2c 22 74 73 74 22 3a 31 35  d":"KW","tst":15
  37 38 36 39 33 37 34 39 2c 22 77 74 73 74 22 3a  78693749,"wtst":
  31 35 31 38 31 36 39 31 32 37 37 38 35 7d        1518169127785}
2020.01.11 00:06:14 5: SW: 32ad01001b6f776e747261636b732f6b6c6175732f4b6c6175732f6576656e7400097b225f74797065223a227472616e736974696f6e222c22616363223a32302c2264657363223a2241646c222c226576656e74223a22656e746572222c226c6174223a35302e3131312c226c6f6e223a382e3535352c2274223a226c222c22746964223a224b57222c22747374223a313537383639333734392c2277747374223a313531383136393132373738357d
2020.01.11 00:06:14 5: Starting notify loop for mqtt.klaus, 1 event(s), first is cmd: {"_type":"transition","acc":20,"desc":"Adl","event":"enter","lat":50.111,"lon":8.555,"t":"l","tid":"KW","tst":1578693749,"wtst":1518169127785}
2020.01.11 00:06:14 4: ot.klaus Detected OwnTracks data from MQTT device notify
2020.01.11 00:06:14 4: ot.klaus OwnTracks: 2020-01-10 23:02:29  {"_type":"transition","acc":20,"desc":"Adl","event":"enter","lat":50.111,"lon":8.555,"t":"l","tid":"KW","tst":1578693749,"wtst":1518169127785}
2020.01.11 00:06:14 5: Starting notify loop for ot.klaus, 6 event(s), first is latitude: 50.111
2020.01.11 00:06:14 5: ltconn: Notify from ot.klaus
2020.01.11 00:06:14 5: ltconn: Notify from ot.klaus: latitude: 50.111
2020.01.11 00:06:14 5: ltconn: Notify from ot.klaus: longitude: 8.555
2020.01.11 00:06:14 5: ltconn: Notify from ot.klaus: location: 50.111,8.555
2020.01.11 00:06:14 5: ltconn: Notify from ot.klaus: id: KW
2020.01.11 00:06:14 5: ltconn: Notify from ot.klaus: accuracy: 20
2020.01.11 00:06:14 5: ltconn: Notify from ot.klaus: enter: Adl
2020.01.11 00:06:14 4: ltconn: Notify from ot.klaus: enter: Adl -> using it
2020.01.11 00:06:14 5: ltconn : Checking r*_geofenceUUIDs for rr_KlausFFM
2020.01.11 00:06:14 3: ltconn: Found matching UUID at ROOMMATE device rr_KlausFFM
2020.01.11 00:06:14 4: ltconn: location = Adl, Trigger = 1
2020.01.11 00:06:14 5: HttpUtils url=https://nominatim.openstreetmap.org/reverse?format=jsonv2&lat=50.111&lon=8.555&addressdetails=1&accept-language=de
2020.01.11 00:06:15 5: HttpUtils request header:
GET /reverse?format=jsonv2&lat=50.111&lon=8.555&addressdetails=1&accept-language=de HTTP/1.0
Host: nominatim.openstreetmap.org
User-Agent: fhem
Accept-Encoding: gzip,deflate

2020.01.11 00:06:16 4: https://nominatim.openstreetmap.org/reverse?format=jsonv2&lat=50.111&lon=8.555&addressdetails=1&accept-language=de: HTTP response code 200
2020.01.11 00:06:16 5: HttpUtils https://nominatim.openstreetmap.org/reverse?format=jsonv2&lat=50.111&lon=8.555&addressdetails=1&accept-language=de: Got data, length: 686
2020.01.11 00:06:16 5: HttpUtils response header:
HTTP/1.1 200 OK
Date: Fri, 10 Jan 2020 23:06:15 GMT
Server: Apache/2.4.29 (Ubuntu)
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: OPTIONS,GET
Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
Expect-CT: max-age=0, report-uri="https://openstreetmap.report-uri.com/r/d/ct/reportOnly"
Upgrade: h2
Connection: Upgrade, close
Content-Type: application/json; charset=UTF-8
2020.01.11 00:06:16 4: ot.klaus: address received
$VAR1 = {
          'addresstype' => 'building',
          'lon' => '8.554502307732733',
          'display_name' => '8, Am Leisrain, Sossenheim, Frankfurt am Main, Hessen, 65936, Deutschland',
          'boundingbox' => [
                             '50.1113499',
                             '50.1114625',
                             '8.5544141',
                             '8.5545905'
                           ],
          'type' => 'yes',
          'lat' => '50.1114062',
          'place_rank' => 30,
          'licence' => "Data \x{c2}\x{a9} OpenStreetMap contributors, ODbL 1.0. https://osm.org/copyright",
          'importance' => 0,
          'place_id' => 133089635,
          'osm_type' => 'way',
          'category' => 'building',
          'address' => {
                         'county' => 'Frankfurt am Main',
                         'postcode' => '65936',
                         'road' => 'Am Leisrain',
                         'suburb' => 'Sossenheim',
                         'city_district' => 'Sossenheim',
                         'city' => 'Frankfurt am Main',
                         'house_number' => '8',
                         'country_code' => 'de',
                         'country' => 'Deutschland',
                         'state' => 'Hessen'
                       },
          'osm_id' => 197371039,
          'name' => undef
        };

2020.01.11 00:06:16 5: ROOMMATE rr_KlausFFM: received location information: id=KW name=Adl trig=1 date=2020-01-10 23:02:29 lat=50.111 long=8.555 posLat=50.111 posLong=8.555 address=Am Leisrain 8
65936 Frankfurt am Main
Deutschland device=ot.klaus
2020.01.11 00:06:16 5: ROOMMATE rr_KlausFFM: received signal from home location
2020.01.11 00:06:16 5: Starting notify loop for rr_KlausFFM, 18 event(s), first is locationPresence: present
2020.01.11 00:06:16 5: End notify loop for rr_KlausFFM
2020.01.11 00:06:16 5: ltconn: Notify from ot.klaus: address: Am Leisrain 8
65936 Frankfurt am Main
Deutschland
2020.01.11 00:06:16 5: End notify loop for ot.klaus
2020.01.11 00:06:16 4: ot.klaus OwnTracks Zone Event: enter Adl
2020.01.11 00:06:16 1: readingsUpdate(ot.klaus,place,Adl) missed to call readingsBeginUpdate first.
2020.01.11 00:06:16 1: stacktrace:
2020.01.11 00:06:16 1:     main::readingsBulkUpdate            called by ./FHEM/98_livetracking.pm (1074)
2020.01.11 00:06:16 1:     main::livetracking_ParseOwnTracks   called by ./FHEM/98_livetracking.pm (1207)
2020.01.11 00:06:16 1:     main::livetracking_Notify           called by fhem.pl (3761)
2020.01.11 00:06:16 1:     main::CallFn                        called by fhem.pl (3681)
2020.01.11 00:06:16 1:     main::DoTrigger                     called by fhem.pl (4745)
2020.01.11 00:06:16 1:     main::readingsEndUpdate             called by fhem.pl (4927)
2020.01.11 00:06:16 1:     main::readingsSingleUpdate          called by ./FHEM/10_MQTT_DEVICE.pm (118)
2020.01.11 00:06:16 1:     MQTT::DEVICE::Set                   called by fhem.pl (3756)
2020.01.11 00:06:16 1:     main::CallFn                        called by fhem.pl (1899)
2020.01.11 00:06:16 1:     main::DoSet                         called by fhem.pl (1931)
2020.01.11 00:06:16 1:     main::CommandSet                    called by fhem.pl (1245)
2020.01.11 00:06:16 1:     main::AnalyzeCommand                called by ./FHEM/01_FHEMWEB.pm (2686)
2020.01.11 00:06:16 1:     main::FW_fC                         called by ./FHEM/01_FHEMWEB.pm (914)
2020.01.11 00:06:16 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (583)
2020.01.11 00:06:16 1:     main::FW_Read                       called by fhem.pl (3761)
2020.01.11 00:06:16 1:     main::CallFn                        called by fhem.pl (756)
2020.01.11 00:06:16 1: readingsUpdate(ot.klaus,zone_1,active) missed to call readingsBeginUpdate first.
2020.01.11 00:06:16 1: stacktrace:
2020.01.11 00:06:16 1:     main::readingsBulkUpdate            called by ./FHEM/98_livetracking.pm (1078)
2020.01.11 00:06:16 1:     main::livetracking_ParseOwnTracks   called by ./FHEM/98_livetracking.pm (1207)
2020.01.11 00:06:16 1:     main::livetracking_Notify           called by fhem.pl (3761)
2020.01.11 00:06:16 1:     main::CallFn                        called by fhem.pl (3681)
2020.01.11 00:06:16 1:     main::DoTrigger                     called by fhem.pl (4745)
2020.01.11 00:06:16 1:     main::readingsEndUpdate             called by fhem.pl (4927)
2020.01.11 00:06:16 1:     main::readingsSingleUpdate          called by ./FHEM/10_MQTT_DEVICE.pm (118)
2020.01.11 00:06:16 1:     MQTT::DEVICE::Set                   called by fhem.pl (3756)
2020.01.11 00:06:16 1:     main::CallFn                        called by fhem.pl (1899)
2020.01.11 00:06:16 1:     main::DoSet                         called by fhem.pl (1931)
2020.01.11 00:06:16 1:     main::CommandSet                    called by fhem.pl (1245)
2020.01.11 00:06:16 1:     main::AnalyzeCommand                called by ./FHEM/01_FHEMWEB.pm (2686)
2020.01.11 00:06:16 1:     main::FW_fC                         called by ./FHEM/01_FHEMWEB.pm (914)
2020.01.11 00:06:16 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (583)
2020.01.11 00:06:16 1:     main::FW_Read                       called by fhem.pl (3761)
2020.01.11 00:06:16 1:     main::CallFn                        called by fhem.pl (756)
2020.01.11 00:06:16 1: readingsUpdate(ot.klaus,trigger,unknown) missed to call readingsBeginUpdate first.
2020.01.11 00:06:16 1: stacktrace:
2020.01.11 00:06:16 1:     main::readingsBulkUpdate            called by ./FHEM/98_livetracking.pm (1103)
2020.01.11 00:06:16 1:     main::livetracking_ParseOwnTracks   called by ./FHEM/98_livetracking.pm (1207)
2020.01.11 00:06:16 1:     main::livetracking_Notify           called by fhem.pl (3761)
2020.01.11 00:06:16 1:     main::CallFn                        called by fhem.pl (3681)
2020.01.11 00:06:16 1:     main::DoTrigger                     called by fhem.pl (4745)
2020.01.11 00:06:16 1:     main::readingsEndUpdate             called by fhem.pl (4927)
2020.01.11 00:06:16 1:     main::readingsSingleUpdate          called by ./FHEM/10_MQTT_DEVICE.pm (118)
2020.01.11 00:06:16 1:     MQTT::DEVICE::Set                   called by fhem.pl (3756)
2020.01.11 00:06:16 1:     main::CallFn                        called by fhem.pl (1899)
2020.01.11 00:06:16 1:     main::DoSet                         called by fhem.pl (1931)
2020.01.11 00:06:16 1:     main::CommandSet                    called by fhem.pl (1245)
2020.01.11 00:06:16 1:     main::AnalyzeCommand                called by ./FHEM/01_FHEMWEB.pm (2686)
2020.01.11 00:06:16 1:     main::FW_fC                         called by ./FHEM/01_FHEMWEB.pm (914)
2020.01.11 00:06:16 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (583)
2020.01.11 00:06:16 1:     main::FW_Read                       called by fhem.pl (3761)
2020.01.11 00:06:16 1:     main::CallFn                        called by fhem.pl (756)
2020.01.11 00:06:16 5: End notify loop for mqtt.klaus
2020.01.11 00:06:16 5: Starting notify loop for mqtt.klaus, 1 event(s), first is transmission-state: outgoing publish sent
2020.01.11 00:06:16 4: WRONG MQTT TYPE $VAR1 = 'transmission-state: outgoing publish sent';

2020.01.11 00:06:16 5: End notify loop for mqtt.klaus
2020.01.11 00:06:16 4: WEB: /fhem?cmd.x=set%20mqtt.klaus%20cmd%20%7B%22_type%22%3A%22transition%22%2C%22acc%22%3A20%2C%22desc%22%3A%22Adl%22%2C%22event%22%3A%22enter%22%2C%22lat%22%3A50.111%2C%22lon%22%3A8.555%2C%22t%22%3A%22l%22%2C%22tid%22%3A%22KW%22%2C%22tst%22%3A1578693749%2C%22wtst%22%3A1518169127785%7D&XHR=1&fwcsrf=csrf_301719868384684&fw_id=573 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate

2020.01.11 00:06:16 5: MQTT mqtt message received: PubAck/at-most-once 9
2020.01.11 00:06:16 5: Starting notify loop for mqtt.klaus, 1 event(s), first is transmission-state: outgoing publish acknowledged
2020.01.11 00:06:16 4: WRONG MQTT TYPE $VAR1 = 'transmission-state: outgoing publish acknowledged';

2020.01.11 00:06:16 5: End notify loop for mqtt.klaus
2020.01.11 00:06:16 5: MQTT mqtt message received: Publish/at-most-once owntracks/klaus/Klaus/event
  7b 22 5f 74 79 70 65 22 3a 22 74 72 61 6e 73 69  {"_type":"transi
  74 69 6f 6e 22 2c 22 61 63 63 22 3a 32 30 2c 22  tion","acc":20,"
  64 65 73 63 22 3a 22 41 64 6c 22 2c 22 65 76 65  desc":"Adl","eve
  6e 74 22 3a 22 65 6e 74 65 72 22 2c 22 6c 61 74  nt":"enter","lat
  22 3a 35 30 2e 31 31 31 2c 22 6c 6f 6e 22 3a 38  ":50.111,"lon":8
  2e 35 35 35 2c 22 74 22 3a 22 6c 22 2c 22 74 69  .555,"t":"l","ti
  64 22 3a 22 4b 57 22 2c 22 74 73 74 22 3a 31 35  d":"KW","tst":15
  37 38 36 39 33 37 34 39 2c 22 77 74 73 74 22 3a  78693749,"wtst":
  31 35 31 38 31 36 39 31 32 37 37 38 35 7d        1518169127785}
2020.01.11 00:06:16 5: publish received for owntracks/klaus/Klaus/event, {"_type":"transition","acc":20,"desc":"Adl","event":"enter","lat":50.111,"lon":8.555,"t":"l","tid":"KW","tst":1578693749,"wtst":1518169127785}
2020.01.11 00:06:16 5: Starting notify loop for mqtt.klaus, 1 event(s), first is transmission-state: incoming publish received
2020.01.11 00:06:16 4: WRONG MQTT TYPE $VAR1 = 'transmission-state: incoming publish received';

2020.01.11 00:06:16 5: End notify loop for mqtt.klaus
2020.01.11 00:06:16 5: calling readingsSingleUpdate(mqtt.klaus,event,{"_type":"transition","acc":20,"desc":"Adl","event":"enter","lat":50.111,"lon":8.555,"t":"l","tid":"KW","tst":1578693749,"wtst":1518169127785},1)
2020.01.11 00:06:16 5: Starting notify loop for mqtt.klaus, 1 event(s), first is event: {"_type":"transition","acc":20,"desc":"Adl","event":"enter","lat":50.111,"lon":8.555,"t":"l","tid":"KW","tst":1578693749,"wtst":1518169127785}
2020.01.11 00:06:16 4: ot.klaus Detected OwnTracks data from MQTT device notify
2020.01.11 00:06:16 4: ot.klaus OwnTracks: 2020-01-10 23:02:29  {"_type":"transition","acc":20,"desc":"Adl","event":"enter","lat":50.111,"lon":8.555,"t":"l","tid":"KW","tst":1578693749,"wtst":1518169127785}
2020.01.11 00:06:16 5: Starting notify loop for ot.klaus, 6 event(s), first is latitude: 50.111
2020.01.11 00:06:16 5: ltconn: Notify from ot.klaus
2020.01.11 00:06:16 5: ltconn: Notify from ot.klaus: latitude: 50.111
2020.01.11 00:06:16 5: ltconn: Notify from ot.klaus: longitude: 8.555
2020.01.11 00:06:16 5: ltconn: Notify from ot.klaus: location: 50.111,8.555
2020.01.11 00:06:16 5: ltconn: Notify from ot.klaus: id: KW
2020.01.11 00:06:16 5: ltconn: Notify from ot.klaus: accuracy: 20
2020.01.11 00:06:16 5: ltconn: Notify from ot.klaus: enter: Adl
2020.01.11 00:06:16 4: ltconn: Notify from ot.klaus: enter: Adl -> using it
2020.01.11 00:06:16 5: ltconn : Checking r*_geofenceUUIDs for rr_KlausFFM
2020.01.11 00:06:16 3: ltconn: Found matching UUID at ROOMMATE device rr_KlausFFM
2020.01.11 00:06:16 4: ltconn: location = Adl, Trigger = 1
2020.01.11 00:06:16 5: HttpUtils url=https://nominatim.openstreetmap.org/reverse?format=jsonv2&lat=50.111&lon=8.555&addressdetails=1&accept-language=de
2020.01.11 00:06:20 5: HttpUtils request header:
GET /reverse?format=jsonv2&lat=50.111&lon=8.555&addressdetails=1&accept-language=de HTTP/1.0
Host: nominatim.openstreetmap.org
User-Agent: fhem
Accept-Encoding: gzip,deflate

2020.01.11 00:06:21 4: https://nominatim.openstreetmap.org/reverse?format=jsonv2&lat=50.111&lon=8.555&addressdetails=1&accept-language=de: HTTP response code 200
2020.01.11 00:06:21 5: HttpUtils https://nominatim.openstreetmap.org/reverse?format=jsonv2&lat=50.111&lon=8.555&addressdetails=1&accept-language=de: Got data, length: 686
2020.01.11 00:06:21 5: HttpUtils response header:
HTTP/1.1 200 OK
Date: Fri, 10 Jan 2020 23:06:20 GMT
Server: Apache/2.4.29 (Ubuntu)
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: OPTIONS,GET
Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
Expect-CT: max-age=0, report-uri="https://openstreetmap.report-uri.com/r/d/ct/reportOnly"
Upgrade: h2
Connection: Upgrade, close
Content-Type: application/json; charset=UTF-8
2020.01.11 00:06:21 4: ot.klaus: address received
$VAR1 = {
          'name' => undef,
          'osm_id' => 197371039,
          'address' => {
                         'city' => 'Frankfurt am Main',
                         'house_number' => '8',
                         'country_code' => 'de',
                         'country' => 'Deutschland',
                         'state' => 'Hessen',
                         'road' => 'Am Leisrain',
                         'postcode' => '65936',
                         'county' => 'Frankfurt am Main',
                         'suburb' => 'Sossenheim',
                         'city_district' => 'Sossenheim'
                       },
          'category' => 'building',
          'osm_type' => 'way',
          'place_id' => 133089635,
          'place_rank' => 30,
          'lat' => '50.1114062',
          'type' => 'yes',
          'boundingbox' => [
                             '50.1113499',
                             '50.1114625',
                             '8.5544141',
                             '8.5545905'
                           ],
          'importance' => 0,
          'licence' => "Data \x{c2}\x{a9} OpenStreetMap contributors, ODbL 1.0. https://osm.org/copyright",
          'display_name' => '8, Am Leisrain, Sossenheim, Frankfurt am Main, Hessen, 65936, Deutschland',
          'addresstype' => 'building',
          'lon' => '8.554502307732733'
        };

2020.01.11 00:06:21 5: ROOMMATE rr_KlausFFM: received location information: id=KW name=Adl trig=1 date=2020-01-10 23:02:29 lat=50.111 long=8.555 posLat=50.111 posLong=8.555 address=Am Leisrain 8
65936 Frankfurt am Main
Deutschland device=ot.klaus
2020.01.11 00:06:21 5: ROOMMATE rr_KlausFFM: received signal from home location
2020.01.11 00:06:21 5: Starting notify loop for rr_KlausFFM, 18 event(s), first is locationPresence: present
2020.01.11 00:06:21 5: End notify loop for rr_KlausFFM
2020.01.11 00:06:21 5: ltconn: Notify from ot.klaus: address: Am Leisrain 8
65936 Frankfurt am Main
Deutschland
2020.01.11 00:06:21 5: End notify loop for ot.klaus
2020.01.11 00:06:21 4: ot.klaus OwnTracks Zone Event: enter Adl
2020.01.11 00:06:21 1: readingsUpdate(ot.klaus,place,Adl) missed to call readingsBeginUpdate first.
2020.01.11 00:06:21 1: stacktrace:
2020.01.11 00:06:21 1:     main::readingsBulkUpdate            called by ./FHEM/98_livetracking.pm (1074)
2020.01.11 00:06:21 1:     main::livetracking_ParseOwnTracks   called by ./FHEM/98_livetracking.pm (1207)
2020.01.11 00:06:21 1:     main::livetracking_Notify           called by fhem.pl (3761)
2020.01.11 00:06:21 1:     main::CallFn                        called by fhem.pl (3681)
2020.01.11 00:06:21 1:     main::DoTrigger                     called by fhem.pl (4745)
2020.01.11 00:06:21 1:     main::readingsEndUpdate             called by fhem.pl (4927)
2020.01.11 00:06:21 1:     main::readingsSingleUpdate          called by ./FHEM/10_MQTT_DEVICE.pm (249)
2020.01.11 00:06:21 1:     MQTT::DEVICE::onmessage             called by ./FHEM/00_MQTT.pm (535)
2020.01.11 00:06:21 1:     MQTT::__ANON__                      called by FHEM/GPUtils.pm (75)
2020.01.11 00:06:21 1:     GPUtils::GP_ForallClients           called by ./FHEM/00_MQTT.pm (545)
2020.01.11 00:06:21 1:     MQTT::Read                          called by fhem.pl (3761)
2020.01.11 00:06:21 1:     main::CallFn                        called by fhem.pl (756)
2020.01.11 00:06:21 1: readingsUpdate(ot.klaus,zone_1,active) missed to call readingsBeginUpdate first.
2020.01.11 00:06:21 1: stacktrace:
2020.01.11 00:06:21 1:     main::readingsBulkUpdate            called by ./FHEM/98_livetracking.pm (1078)
2020.01.11 00:06:21 1:     main::livetracking_ParseOwnTracks   called by ./FHEM/98_livetracking.pm (1207)
2020.01.11 00:06:21 1:     main::livetracking_Notify           called by fhem.pl (3761)
2020.01.11 00:06:21 1:     main::CallFn                        called by fhem.pl (3681)
2020.01.11 00:06:21 1:     main::DoTrigger                     called by fhem.pl (4745)
2020.01.11 00:06:21 1:     main::readingsEndUpdate             called by fhem.pl (4927)
2020.01.11 00:06:21 1:     main::readingsSingleUpdate          called by ./FHEM/10_MQTT_DEVICE.pm (249)
2020.01.11 00:06:21 1:     MQTT::DEVICE::onmessage             called by ./FHEM/00_MQTT.pm (535)
2020.01.11 00:06:21 1:     MQTT::__ANON__                      called by FHEM/GPUtils.pm (75)
2020.01.11 00:06:21 1:     GPUtils::GP_ForallClients           called by ./FHEM/00_MQTT.pm (545)
2020.01.11 00:06:21 1:     MQTT::Read                          called by fhem.pl (3761)
2020.01.11 00:06:21 1:     main::CallFn                        called by fhem.pl (756)
2020.01.11 00:06:21 1: readingsUpdate(ot.klaus,trigger,unknown) missed to call readingsBeginUpdate first.
2020.01.11 00:06:21 1: stacktrace:
2020.01.11 00:06:21 1:     main::readingsBulkUpdate            called by ./FHEM/98_livetracking.pm (1103)
2020.01.11 00:06:21 1:     main::livetracking_ParseOwnTracks   called by ./FHEM/98_livetracking.pm (1207)
2020.01.11 00:06:21 1:     main::livetracking_Notify           called by fhem.pl (3761)
2020.01.11 00:06:21 1:     main::CallFn                        called by fhem.pl (3681)
2020.01.11 00:06:21 1:     main::DoTrigger                     called by fhem.pl (4745)
2020.01.11 00:06:21 1:     main::readingsEndUpdate             called by fhem.pl (4927)
2020.01.11 00:06:21 1:     main::readingsSingleUpdate          called by ./FHEM/10_MQTT_DEVICE.pm (249)
2020.01.11 00:06:21 1:     MQTT::DEVICE::onmessage             called by ./FHEM/00_MQTT.pm (535)
2020.01.11 00:06:21 1:     MQTT::__ANON__                      called by FHEM/GPUtils.pm (75)
2020.01.11 00:06:21 1:     GPUtils::GP_ForallClients           called by ./FHEM/00_MQTT.pm (545)
2020.01.11 00:06:21 1:     MQTT::Read                          called by fhem.pl (3761)
2020.01.11 00:06:21 1:     main::CallFn                        called by fhem.pl (756)
2020.01.11 00:06:21 5: End notify loop for mqtt.klaus
2020.01.11 00:06:21 4: WEB_127.0.0.1_42310 POST /fhem?cmd.x=attr%20global%20verbose%201&XHR=1&fwcsrf=csrf_301719868384684&fw_id=573; BUFLEN:0
2020.01.11 00:06:21 5: Cmd: >attr global verbose 1<

Die Minimalconfig dazu (es wird noch ein MQTT Device benötigt)

Code Auswählen Erweitern


defmod mqtt.klaus MQTT_DEVICE
attr mqtt.klaus IODev mqtt
attr mqtt.klaus publishSet_cmd owntracks/klaus/Klaus/event
attr mqtt.klaus qos at-least-once
attr mqtt.klaus room stTest
attr mqtt.klaus subscribeReading_event owntracks/klaus/Klaus/event
attr mqtt.klaus subscribeReading_position owntracks/klaus/Klaus

defmod ot.klaus livetracking
attr ot.klaus addressLanguage de
attr ot.klaus addressReading 1
attr ot.klaus owntracksDevice mqtt.klaus
attr ot.klaus room stTest
attr ot.klaus zonename_1 Adl

defmod ltconn livetrackingconn
attr ltconn room stTest

defmod rr_KlausFFM ROOMMATE BewohnerFFM
attr rr_KlausFFM alias Status
attr rr_KlausFFM devStateIcon .*zuhause:user_available:absent .*anwesend:user_available:absent .*abwesend:user_away:home .*verreist:user_ext_away:home .*bettfertig:scene_toilet:asleep .*schlaeft:scene_sleeping:awoken .*schläft:scene_sleeping:awoken .*aufgestanden:scene_sleeping_alternat:home .*:user_unknown:home
attr rr_KlausFFM eventMap home:zuhause absent:abwesend gone:verreist gotosleep:bettfertig asleep:schläft awoken:aufgestanden
attr rr_KlausFFM group KlausFFM
attr rr_KlausFFM icon people_sensor
attr rr_KlausFFM room stTest
attr rr_KlausFFM rr_geofenceUUIDs ot.klaus
attr rr_KlausFFM rr_locationHome Adl
attr rr_KlausFFM rr_realname group
attr rr_KlausFFM sortby 1
attr rr_KlausFFM webCmd state
attr rr_KlausFFM widgetOverride state:zuhause,bettfertig,schläft,aufgestanden,abwesend,verreist


mit

Code Auswählen Erweitern

set mqtt.klaus cmd {"_type":"transition","acc":20,"desc":"Adl","event":"enter","lat":50.111,"lon":8.555,"t":"l","tid":"KW","tst":1578693749,"wtst":1518169127785}

kann der Fehler nachgestellt werden. (da das device mqtt.klaus den Befehl hier sendet und auch empfängt ist alles doppelt)

Wenn attr ot.klaus addressReading auf 0 gesetzt wird kommt der Fehler nicht mehr.
Wenn das Define von livetrackingconn entfernt wird oder rr_KlausFFM dann kommt der Fehler auch nicht mehr.

Mechanismus:
ot.klaus empfängt eine neue Position
über "NOTIFYDEV -> TYPE=livetracking" bekommt ltconn die aktualisierten Readings
ltconn sucht einen ROOMMATE der ot.klaus als rr_geofenceUUIDs und aktuaisiert dort die Werte

[rudolfkoenig]

Ich gehe davon aus (noch nicht getestet), dass DoTrigger in der Zeile 1060 die Ursache ist.
Generell ist eine Mischung von DoTrigger und readings*Event nicht empfohlen.
Genauso wie das Mischen von readingsBeginEvent/readingsBulkEvent/readingsEndEvent mit readingsSingleEvent.

[Wzut]

wie das Mischen von readingsBeginEvent/readingsBulkEvent/readingsEndEvent mit readingsSingleEvent.

gutes Stichwort , ich bin da in 10_MAX auch über eine Sonderlösung gestolpert um vermutlich genau das Problem zu umgehen.
Dort wird immer zuerst $hash->{".updateTimestamp"}  geprüft (readingsSingleUpdate ist doch in Wahrheit ein mini BulkUpdate) .
Vllt auch eine Lösung für klausw ?   

[klausw]

Ich gehe davon aus (noch nicht getestet), dass DoTrigger in der Zeile 1060 die Ursache ist.

Ja das isses. Danke! Hatte ich übersehen.

gutes Stichwort , ich bin da in 10_MAX auch über eine Sonderlösung gestolpert um vermutlich genau das Problem zu umgehen.
Dort wird immer zuerst $hash->{".updateTimestamp"}  geprüft (readingsSingleUpdate ist doch in Wahrheit ein mini BulkUpdate) .
Vllt auch eine Lösung für klausw ?

Das Modul stammt nicht von mir. Ich hatte nur ein connector Modul (bisher nicht eingeckecked) zu den Resident Devices geschrieben. In dieser Verbindung trat der Fehler erst auf. Vermutlich bekommt man ihn auch über at oder DOIF.

Ich frage mal beim Autor des Moduls an.

[Markus M.]

Das Problem sollte mit dem Update morgen gelöst sein.