Neues Modul: BOTVAC (für Neato BotVac Connected)

Mort · 25 Februar 2020, 17:49:59

Sieht so aus, als wären die Freezes zwar etwas seltener geworden, aber doch noch da. Freezemon erkennt sie mit dnsServer nur nicht mehr richtig (mal an der falschen Stelle, mal gar nicht). Im Log gibt's aber nach wie vor die üblichen Stellen (s.u., gegen Ende, habe nur mal alles vermutlich dazugehörige mitgenommen). An der IP liegt's wohl doch nicht, den "DNS QUERY" gab's nur beim ersten https-Request. Was mir auffällt: Es gibt einen Request zwischendrin, der auch noch funktioniert hat.
Mein neuer RasPi ist übrigens im Gegensatz zum Vorgänger auch via WLAN verbunden. Hätte nicht gedacht, dass das einen Unterschied macht, aber vielleicht gibt es hier tatsächlich ein Problem auf niedrigerer Ebene (Treiber/Hardware)? Update: Raspi per Kabel ans Netz angeschlossen, sofort der nächste Freeze. Das war's also nicht.

Code Auswählen

2020.02.25 15:51:14 5: BOTVAC Neato: called function GetStatus()
2020.02.25 15:51:14 4: BOTVAC Neato: Read password from file
2020.02.25 15:51:14 5: BOTVAC Neato: called function SendCommand()
2020.02.25 15:51:14 4: BOTVAC Neato: REQ messages/getRobotState
2020.02.25 15:51:14 4: BOTVAC Neato: successors 0: messages,getSchedule 1: messages,getGeneralInfo 2: messages,getPreferences
2020.02.25 15:51:14 5: BOTVAC Neato: POST https://nucleo.neatocloud.com:4443/vendors/neato/robots/...-.../messages ({"reqId":"0","cmd":"getRobotState"})
2020.02.25 15:51:14 5: BOTVAC Neato: header Accept: application/vnd.neato.nucleo.v1^M
Content-Type: application/json^M
Date: Tue, 25 Feb 2020 14:51:14 GMT^M
Authorization: NEATOAPP ...
2020.02.25 15:51:14 5: HttpUtils url=https://nucleo.neatocloud.com:4443/vendors/neato/robots/...-.../messages
2020.02.25 15:51:14 5: DNS QUERY ...
2020.02.25 15:51:14 5: DNS ANSWER 340:...
2020.02.25 15:51:14 4: DNS result for nucleo.neatocloud.com: 54.90.247.80, ttl:3
2020.02.25 15:51:14 4: IP: nucleo.neatocloud.com -> 54.90.247.80
2020.02.25 15:51:15 5: HttpUtils request header:
POST /vendors/neato/robots/...-.../messages HTTP/1.0^M
Host: nucleo.neatocloud.com:4443^M
User-Agent: fhem^M
Accept-Encoding: gzip,deflate^M
Accept: application/vnd.neato.nucleo.v1^M
Content-Type: application/json^M
Date: Tue, 25 Feb 2020 14:51:14 GMT^M
Authorization: NEATOAPP ...^M
Content-Length: 35^M

2020.02.25 15:51:15 4: https://nucleo.neatocloud.com:4443/vendors/neato/robots/...-.../messages: HTTP response code 200
2020.02.25 15:51:15 5: HttpUtils https://nucleo.neatocloud.com:4443/vendors/neato/robots/...-.../messages: Got data, length: 750
2020.02.25 15:51:15 5: HttpUtils response header:
HTTP/1.0 200 OK^M
server: Cowboy^M
date: Tue, 25 Feb 2020 14:51:14 GMT^M
content-length: 750^M
Access-Control-Allow-Origin: *^M
Access-Control-Allow-Methods: GET,POST,PUT,DELETE,OPTIONS^M
Access-Control-Allow-Headers: Accept,Date,X-Date,Authorization^M
Content-Type: application/json
2020.02.25 15:51:15 5: BOTVAC Neato: called function ReceiveCommand() rc: HASH(0x...) err:  data: {...}
2020.02.25 15:51:15 4: BOTVAC Neato: RCV messages/getRobotState
2020.02.25 15:51:15 4: BOTVAC Neato: successors 0: messages,getSchedule 1: messages,getGeneralInfo 2: messages,getPreferences
2020.02.25 15:51:15 4: BOTVAC Neato: RES messages/getRobotState - {...}
2020.02.25 15:51:15 4: BOTVAC Neato: Read password from file
2020.02.25 15:51:15 5: BOTVAC Neato: called function SendCommand()
2020.02.25 15:51:15 4: BOTVAC Neato: REQ messages/getSchedule
2020.02.25 15:51:15 4: BOTVAC Neato: successors 0: messages,getGeneralInfo 1: messages,getPreferences
2020.02.25 15:51:15 5: BOTVAC Neato: POST https://nucleo.neatocloud.com:4443/vendors/neato/robots/...-.../messages ({"reqId":"0","cmd":"getSchedule"})
2020.02.25 15:51:15 5: BOTVAC Neato: header Accept: application/vnd.neato.nucleo.v1^M
Content-Type: application/json^M
Date: Tue, 25 Feb 2020 14:51:15 GMT^M
Authorization: NEATOAPP ...
2020.02.25 15:51:15 5: HttpUtils url=https://nucleo.neatocloud.com:4443/vendors/neato/robots/...-.../messages
2020.02.25 15:51:15 4: IP: nucleo.neatocloud.com -> 54.90.247.80
--------------------------------- Freeze hier ---------------------------------
2020.02.25 15:54:15 4: HttpUtils: https://nucleo.neatocloud.com:4443/vendors/neato/robots/...-.../messages: Can't connect(2) to https://nucleo.neatocloud.com:4443:  SSL wants a read first
2020.02.25 15:54:15 5: BOTVAC Neato: called function ReceiveCommand() rc: HASH(0x4337ee0) err: https://nucleo.neatocloud.com:4443/vendors/neato/robots/...-.../messages: Can't connect(2) to https://nucleo.neatocloud.com:4443:  SSL wants a read first data:
2020.02.25 15:54:15 4: BOTVAC Neato:messages/getSchedule RCV https://nucleo.neatocloud.com:4443/vendors/neato/robots/...-.../messages: Can't connect(2) to https://nucleo.neatocloud.com:4443:  SSL wants a read first
2020.02.25 15:54:15 4: BOTVAC Neato: drop successors
2020.02.25 15:54:15 4: BOTVAC Neato: successors 0: messages,getGeneralInfo 1: messages,getPreferences[code]

Mort · 26 Februar 2020, 14:43:46

Zitat von: vuffiraa am 23 Februar 2020, 21:54:26
Ich würde mich über ein paar Tester freuen. Installation des Modul per
Code Auswählen Erweitern
update all https://raw.githubusercontent.com/fhem/BOTVAC/dev/controls_BOTVAC.txt

Die Installation hat jetzt geklappt, der Freeze taucht aber leider immer noch auf.

schnuddel · 26 Februar 2020, 15:21:26

Ich habe das neue Modul jetzt seit 24h im Test. Seitdem kein einziger Freeze von 180 s mehr bzw. kein einziger, der auf dieses Modul zurückzuführen wäre.
Ich werde weiter testen, aber von meiner Seite aus sieht es sehr gut aus.

Vielen Dank!

schnuddel · 27 Februar 2020, 15:41:21

... auch nach mehr als 48h kein einziger Freeze. Da ich vorher quasi jede Stunde welche hatte, sieht das Problem zumindest für mich gelöst aus.
Nochmal vielen Dank!
Gibst du Bescheid, wenn du das Modul eincheckst?

rabehd · 27 Februar 2020, 16:09:02

Zitat von: Mort am 26 Februar 2020, 14:43:46
Die Installation hat jetzt geklappt, der Freeze taucht aber leider immer noch auf.

Bei mir genauso

vuffiraa · 28 Februar 2020, 08:50:09

Hallo Leute,

die letzten Tage bin hier nicht zum Schreiben gekommen, aber ich habe mitgelesen

Die Testversion scheint ja wenigstens für einen einen Vorteil zu bringen. Ich werde weiter schauen!

Zu den Diskussionen hier hätte ich ein paar Anmerkungen. Ich habe ein paar Zweifel, ob eine DNS-Cache wirklich hilft. Soweit mir bekannt, wird der Servername zu mindestens 3 IP-Adressen aufgelöst. Außerdem kann die TCP-Verbindung nicht länger offen gehalten werden, sie wird doch recht schnell wieder abgebaut.

Das Log von Mort ist wahrscheinlich noch nicht mit der Testversion entstanden? Wenn die Testversion richtig funktioniert, wäre für den besagten Call "messages/getSchedule" keine SSL Aushandlung mehr nötig. Eigentlich sollte dann maximal "messages/getStatus" blockieren.

Vielleicht noch eine Erklärung zu den 180 Sekunden. Die werden durch das Modul selber gesetzt, da hat Neato keine Schuld und blockiert auch selber sehr wahrscheinlich nix. Diese 180 Sekunden sind die Einstellung, wie lange auf eine Antwort vom Server gewartet wird. Bei der normalen Requestverarbeitung fällt das nicht weiter auf, da sie nicht blockierend ist. Die Zahl ist so hoch, da ich schon öfter Antwortzeiten von 20 - 40 Sekunden beobachtet habe. Wenn man die reduziert, dass sie keinen Freeze mehr erzeugt, würden wahrscheinlich Antworten verloren gehen. Durch die hohe Zahl fällt aber auch erst mal auf, dass es ein Problem gibt. Bringt es einen Vorteil, wenn das Freeze auf, sagen wir, 30 Sekunden reduziert wird?

Viele Grüße,
VuffiRaa

schnuddel · 03 März 2020, 13:24:12

Ich habe gerade nochmal die freezemon-logs durchgesehen.
In den letzten 7 Tagen hatte ich 2 freezes, jeweils wieder 180s. Aus meiner Sicht auf jeden Fall eine signifikante Verbesserung.

the ratman · 15 März 2020, 09:29:24

moin, moin

nur ne info:
seit gestern krieg ich nach dem serverrestart folgende warnings:

Code Auswählen

2020.03.15 09:23:43 1:  PERL WARNING: Use of uninitialized value $expa in numeric gt (>) at ./FHEM/70_BOTVAC.pm line 1230.
2020.03.15 09:23:43 1:  stacktrace:
2020.03.15 09:23:43 1:      main::__ANON__                      called by ./FHEM/70_BOTVAC.pm (1230)
2020.03.15 09:23:43 1:      BOTVAC::ReceiveCommand              called by FHEM/HttpUtils.pm (634)
2020.03.15 09:23:43 1:      main::__ANON__                      called by fhem.pl (753)
2020.03.15 09:23:43 1:  PERL WARNING: Use of uninitialized value $expt in numeric gt (>) at ./FHEM/70_BOTVAC.pm line 1232.
2020.03.15 09:23:43 1:  stacktrace:
2020.03.15 09:23:43 1:      main::__ANON__                      called by ./FHEM/70_BOTVAC.pm (1232)
2020.03.15 09:23:43 1:      BOTVAC::ReceiveCommand              called by FHEM/HttpUtils.pm (634)
2020.03.15 09:23:43 1:      main::__ANON__                      called by fhem.pl (753)
2020.03.15 09:23:43 1:  PERL WARNING: Use of uninitialized value $expt in numeric gt (>) at ./FHEM/70_BOTVAC.pm line 1233.
2020.03.15 09:23:43 1:  stacktrace:
2020.03.15 09:23:43 1:      main::__ANON__                      called by ./FHEM/70_BOTVAC.pm (1233)
2020.03.15 09:23:43 1:      BOTVAC::ReceiveCommand              called by FHEM/HttpUtils.pm (634)
2020.03.15 09:23:43 1:      main::__ANON__                      called by fhem.pl (753)

einmal hatte ich das schon vorher und zwar um mitternacht. warum grade um die zeit dürfts mich allerdings nicht fragen *g* es passiert auch sonst nix böses und alle dinge gehen ihren lauf.

vuffiraa · 15 März 2020, 12:12:38

Zitat von: the ratman am 15 März 2020, 09:29:24
moin, moin

nur ne info:
seit gestern krieg ich nach dem serverrestart folgende warnings:
Code Auswählen Erweitern
2020.03.15 09:23:43 1: PERL WARNING: Use of uninitialized value $expa in numeric gt (>) at ./FHEM/70_BOTVAC.pm line 1230. 2020.03.15 09:23:43 1: stacktrace: 2020.03.15 09:23:43 1: main::__ANON__ called by ./FHEM/70_BOTVAC.pm (1230) 2020.03.15 09:23:43 1: BOTVAC::ReceiveCommand called by FHEM/HttpUtils.pm (634) 2020.03.15 09:23:43 1: main::__ANON__ called by fhem.pl (753) 2020.03.15 09:23:43 1: PERL WARNING: Use of uninitialized value $expt in numeric gt (>) at ./FHEM/70_BOTVAC.pm line 1232. 2020.03.15 09:23:43 1: stacktrace: 2020.03.15 09:23:43 1: main::__ANON__ called by ./FHEM/70_BOTVAC.pm (1232) 2020.03.15 09:23:43 1: BOTVAC::ReceiveCommand called by FHEM/HttpUtils.pm (634) 2020.03.15 09:23:43 1: main::__ANON__ called by fhem.pl (753) 2020.03.15 09:23:43 1: PERL WARNING: Use of uninitialized value $expt in numeric gt (>) at ./FHEM/70_BOTVAC.pm line 1233. 2020.03.15 09:23:43 1: stacktrace: 2020.03.15 09:23:43 1: main::__ANON__ called by ./FHEM/70_BOTVAC.pm (1233) 2020.03.15 09:23:43 1: BOTVAC::ReceiveCommand called by FHEM/HttpUtils.pm (634) 2020.03.15 09:23:43 1: main::__ANON__ called by fhem.pl (753)einmal hatte ich das schon vorher und zwar um mitternacht. warum grade um die zeit dürfts mich allerdings nicht fragen *g* es passiert auch sonst nix böses und alle dinge gehen ihren lauf.

Kannst du mal probieren, ob du den Fehler auch bei "reloadMaps" bekommst. Das sollte die gleiche Funktion sein. Dann würde mich eine Log mit verbose=5 interessieren. Zur Info, so ein Kartenupdate wird beim Start des Servers und auch immer um Mitternacht gemacht

the ratman · 15 März 2020, 15:20:17

haste recht ...
reload maps =

Code Auswählen

2020.03.15 09:26:31 1:  logfile wurde gelöscht
2020.03.15 15:19:46 1:  PERL WARNING: Use of uninitialized value $expa in numeric gt (>) at ./FHEM/70_BOTVAC.pm line 1230.
2020.03.15 15:19:46 1:  stacktrace:
2020.03.15 15:19:46 1:      main::__ANON__                      called by ./FHEM/70_BOTVAC.pm (1230)
2020.03.15 15:19:46 1:      BOTVAC::ReceiveCommand              called by FHEM/HttpUtils.pm (634)
2020.03.15 15:19:46 1:      main::__ANON__                      called by fhem.pl (753)
2020.03.15 15:19:46 1:  PERL WARNING: Use of uninitialized value $expt in numeric gt (>) at ./FHEM/70_BOTVAC.pm line 1232.
2020.03.15 15:19:46 1:  stacktrace:
2020.03.15 15:19:46 1:      main::__ANON__                      called by ./FHEM/70_BOTVAC.pm (1232)
2020.03.15 15:19:46 1:      BOTVAC::ReceiveCommand              called by FHEM/HttpUtils.pm (634)
2020.03.15 15:19:46 1:      main::__ANON__                      called by fhem.pl (753)
2020.03.15 15:19:46 1:  PERL WARNING: Use of uninitialized value $expt in numeric gt (>) at ./FHEM/70_BOTVAC.pm line 1233.
2020.03.15 15:19:46 1:  stacktrace:
2020.03.15 15:19:46 1:      main::__ANON__                      called by ./FHEM/70_BOTVAC.pm (1233)
2020.03.15 15:19:46 1:      BOTVAC::ReceiveCommand              called by FHEM/HttpUtils.pm (634)
2020.03.15 15:19:46 1:      main::__ANON__                      called by fhem.pl (753)

nachtrag der vollständigkeit halber:
die karte passt aber - zumindest die katzenklo-reinigung von gestern 17 uhr.

vuffiraa · 15 März 2020, 17:39:03

Nicht gut, aber dann ist die Ursache klar. Dein Katzenklo ist zu klein und aufgrund der Reinigung kann dann wohl nicht berechnet werden, welche Reinigungsfläche mit deinem Akku geschafft wird.

Mich würde aber mal die Antwort im Log interessieren, vielleicht gibt es da andere Daten, die interessant sind.

the ratman · 15 März 2020, 19:28:32

was würdest den gerne im log haben und wie soll ich das am besten erzwingen?
weil mehr war da nicht im log - und ich putz ja nicht das katzenklo, sondern alles großzügig drum rum - seit ca. 9 monaten jeden tag. er meint da immer rund 2m² geputzt zu haben lt. statistik und lt. reading: "map_cleaned_area 2.2432" schauts auch gut aus. auch sonst schaut alles wie immer aus.

das interessante daran: heute, punkt 17 uhr hab ich meine katze wieder ärgern lassen ... auch im log stehen wieder die selben 3 warnings. allerdings für 17:00:36. also nicht, wenn das ding fertig ist, was so um 17:04 bis 17:06 sein sollte, sondern beim start der reinigung. da fragt der doch keine karte ab, oder?

vuffiraa · 16 März 2020, 17:12:32

Du musst im Gerät selber das Attribute "verbose" auf den Wert 4 setzen. Danach schreibt das Modul mehr Einträge ins Logfile.

Beim Ausführen von "reloadMaps" sollte dann etwa folgendes im Log auftauchen:

Code Auswählen

2020.03.16 07:41:47 4: BOTVAC neato: REQ robots/maps
2020.03.16 07:41:48 4: BOTVAC neato: RCV robots/maps
2020.03.16 07:41:48 4: BOTVAC neato: RES robots/maps - {"stats":{},"maps":[{"id":"2020-02-10T07:36:39Z","url":"https://neatorobotics.s3.amazonaws.com/user-maps/OPS44615-EC1127F36D10/2020-02-10T07:36:39Z/66ac51b12f07a4d324ae54f62012002a/user-map.png?X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=AKIAIJA2XL2XP5OB72XQ%2F20200316%2Fus-east-1%2Fs3%2Faws4_request\u0026X-Amz-Date=20200316T064148Z\u0026X-Amz-Expires=300\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=fcbc74eef5a9dde6525a222fe340fd8c87f1b00c8af9f916bf8adc745d36fdd2","url_valid_for_seconds":300,"version":1,"generated_at":"2020-02-10T08:07:48Z","status":"complete","launched_from":"robot","error":null,"modifier":1,"start_at":"2020-02-10T07:36:39Z","end_at":"2020-02-10T08:07:48Z","end_orientation_relative_degrees":310,"run_charge_at_start":55,"run_charge_at_end":34,"persistent_map_id":null,"cleaned_with_persistent_map_id":null,"suspended_cleaning_charging_count":0,"time_in_suspended_cleaning":0,"time_in_error":0,"time_in_pause":0,"cleaned_area":20.6848,"base_count":0,"is_docked":false,"delocalized":false,"valid_as_persistent_map":false,"category":2,"mode":2,"navigation_mode":null},{"id":"2020-01-30T09:00:00Z","url":"https://neatorobotics.s3.amazonaws.com/user-maps/OPS44615-EC1127F36D10/2020-01-30T09:00:00Z/a3ec3f01e924e355ff055443c7056673/user-map.png?X-Amz-Algorithm=AWS4-HMAC-SHA256\u0026X-Amz-Credential=AKIAIJA2XL2XP5OB72XQ%2F20200316%2Fus-east-1%2Fs3%2Faws4_request\u0026X-Amz-Date=20200316T064148Z\u0026X-Amz-Expires=300\u0026X-Amz-SignedHeaders=host\u0026X-Amz-Signature=4a273cd3326ce76337ed93043f44adbe9d8ba4cbd7c7dfa01479556c97af1f2e","url_valid_for_seconds":300,"version":1,"generated_at":"2020-01-30T09:54:08Z","status":"complete","launched_from":"schedule","error":null,"modifier":1,"start_at":"2020-01-30T09:00:00Z","end_at":"2020-01-30T09:54:08Z","end_orientation_relative_degrees":3,"run_charge_at_start":93,"run_charge_at_end":52,"persistent_map_id":null,"cleaned_with_persistent_map_id":null,"suspended_cleaning_charging_count":0,"time_in_suspended_cleaning":0,"time_in_error":0,"time_in_pause":0,"cleaned_area":39.4496,"base_count":1,"is_docked":true,"delocalized":false,"valid_as_persistent_map":false,"category":2,"mode":2,"navigation_mode":null},
...

Dabei scheinen bei dir die Daten nicht zu dem zu passen, was das Modul erwartet. Wenn du mir so ein Log zukommen lassen kannst, finde ich vielleicht raus, was da anders ist.

the ratman · 16 März 2020, 17:23:21

verbose 4 - relaod maps:

Code Auswählen

2020.03.16 17:21:41 2:  BOTVAC set tatortreiniger reloadMaps
2020.03.16 17:21:41 4:  BOTVAC tatortreiniger: Read password from file
2020.03.16 17:21:41 4:  BOTVAC tatortreiniger: REQ robots/maps
2020.03.16 17:21:52 1:  RMDIR: ./restoreDir/save/2020-03-10

lustig - keine warnings heute? mitternacht gabs auf jeden fall noch welche. ein direkter relaod meines weblinks um 17:28 uhr, produzeirt auch keine warnings.
langsam denk ich, es ist/war nicht dein modul ...

sollten wir wohl als "erledigt" einstufen. sollt ich wieder warnings kriegen, geb ich bescheid.
derweil wohl: thx für deine aufmerksamkeit!

vuffiraa · 16 März 2020, 17:37:12

Nein, in deinem Ausschnitt fehlt noch die eigentlich Antwort auf die Anfrage.

Es muss 3 Zeilen geben:
- BOTVAC tatortreiniger: REQ robots/maps --> REQ = request / Anfrage
- BOTVAC tatortreiniger: RCV robots/maps --> RCV = received / Antwort erhalten
- BOTVAC tatortreiniger: RES robots/maps --> RES = response / eigentliche Antwort

Spätestens nach 3 Minuten sollten diese Zeilen im Log sein. 3 Minuten sind die maximale Zeit, wo auf eine Antwort gewartet wird. Normalerweise sollte die Antwort nach ein paar Sekunden da sein.