virtualzone/landroid-bridge

Multiple schedule updates and inconsistencies

Closed this issue · 3 comments

RolandRosenfeld commented

I fear, that the schedule mechanism is somewhat broken.
I did not yet read the code to find the root cause, but here are my observations:
I use landroid-bridge with scheduler enabled with the darksky weather api.
Today we have quite good weather conditions, the Schedule overview in the web GUI shows 0% rain risk the hole day and the schedule overview marks 12:00 to 20:00 in orange, meaning that the landroid will mow the for 8 hours today.
But after a first round it stayed in the charger.
The readings tab tells me that today (Sunday) the the following schedule:
Sunday = {"startHour":12,"startMinute":0,"durationMinutes":0,"cutEdge":false}

In the Openhab log file (which watches the MQTT output of landroid-bridge), I see the following changes this afternoon:

07:15:00 Landroid_Schedule_So changed to {"startHour":12,"startMinute":0,"durationMinutes":480,"cutEdge":true}
14:15:00 Landroid_Schedule_So changed to {"startHour":12,"startMinute":0,"durationMinutes":0,"cutEdge":false}
16:15:00 Landroid_Schedule_So changed to {"startHour":12,"startMinute":0,"durationMinutes":480,"cutEdge":true}
16:15:00 Landroid_Schedule_So changed to {"startHour":12,"startMinute":0,"durationMinutes":0,"cutEdge":false}

As you can see, durationMinutes switched to 0 at 14:15. This doesn't make match the weather conditions, but okay.
But then at 16:15 it first switches to 480 Minutes and in the same second back to 0.
This doesn't make sense to me.

Looking at the landroid-bridge log file, also looks confusing at 16:15:

May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.051] [INFO] ScheduledTasks - Running ScheduledTasks.applySchedule...
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.091] [INFO] LandroidS - Setting new schedule with update for weekday 0 to [["12:00",480,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.091] [INFO] LandroidS - Sending to landroid cloud: {"sc":{"d":[["12:00",480,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.091] [DEBUG] IoBrokerAdapter - Sending Message: {"sc":{"d":[["12:00",480,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.095] [INFO] LandroidS - Setting new schedule with update for weekday 1 to [["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.095] [INFO] LandroidS - Sending to landroid cloud: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.097] [DEBUG] IoBrokerAdapter - Sending Message: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.098] [INFO] LandroidS - Setting new schedule with update for weekday 2 to [["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.098] [INFO] LandroidS - Sending to landroid cloud: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.099] [DEBUG] IoBrokerAdapter - Sending Message: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.100] [INFO] LandroidS - Setting new schedule with update for weekday 3 to [["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.101] [INFO] LandroidS - Sending to landroid cloud: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.101] [DEBUG] IoBrokerAdapter - Sending Message: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.102] [INFO] LandroidS - Setting new schedule with update for weekday 4 to [["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.103] [INFO] LandroidS - Sending to landroid cloud: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.103] [DEBUG] IoBrokerAdapter - Sending Message: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.104] [INFO] LandroidS - Setting new schedule with update for weekday 5 to [["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.104] [INFO] LandroidS - Sending to landroid cloud: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.104] [DEBUG] IoBrokerAdapter - Sending Message: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.104] [INFO] LandroidS - Setting new schedule with update for weekday 6 to [["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.104] [INFO] LandroidS - Sending to landroid cloud: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.104] [DEBUG] IoBrokerAdapter - Sending Message: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.107] [INFO] LandroidS - Setting new schedule with update for weekday 0 to [["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.108] [INFO] LandroidS - Sending to landroid cloud: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.108] [DEBUG] IoBrokerAdapter - Sending Message: {"sc":{"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.175] [INFO] ScheduledTasks - Finished ScheduledTasks.applySchedule.
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.656] [DEBUG] IoBrokerAdapter - Landroid status: {"cfg":{"lg":"it","tm":"16:15:00","dt":"12/05/2019","sc":{"m":1,"p":0,"d":[["12:00",480,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]},"cmd":0,"mz":[0,0,0,0],"mzv":[0,0,0,0,0,0,0,0,0,0],"rd":120,"sn":"2018XXXXXXX"},"dat":{"mac":"XXXXXXXXXXX","fw":3.45,"bt":{"t":23.4,"v":19.41,"p":80,"nr":353,"c":0},"dmp":[-1.3,2.5,355.4],"st":{"b":3665,"d":68992,"wt":4152},"ls":1,"le":0,"lz":0,"rsi":-41,"lk":1}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.657] [INFO] Mqtt - Publishing MQTT message to topic landroid/status/dateTime: 2019-05-12 16:15:00
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.657] [INFO] Mqtt - Publishing MQTT message to topic landroid/status/wifiQuality: -41
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.657] [INFO] Mqtt - Publishing MQTT message to topic landroid/status/batteryVoltage: 19.41
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.657] [INFO] Mqtt - Publishing MQTT message to topic landroid/status/batteryTemperature: 23.4
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.657] [INFO] Mqtt - Publishing MQTT message to topic landroid/status/yaw: 355.4
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.657] [INFO] Mqtt - Publishing MQTT message to topic landroid/status/schedule/0: {"startHour":12,"startMinute":0,"durationMinutes":480,"cutEdge":true}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.922] [DEBUG] IoBrokerAdapter - Landroid status: {"cfg":{"lg":"it","tm":"16:15:00","dt":"12/05/2019","sc":{"m":1,"p":0,"d":[["12:00",0,0],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",360,1],["12:00",360,0],["12:00",0,0]]},"cmd":0,"mz":[0,0,0,0],"mzv":[0,0,0,0,0,0,0,0,0,0],"rd":120,"sn":"2018XXXXXXX"},"dat":{"mac":"XXXXXXXXXXXX","fw":3.45,"bt":{"t":23.4,"v":19.41,"p":80,"nr":353,"c":0},"dmp":[-1.3,2.5,356.1],"st":{"b":3665,"d":68992,"wt":4152},"ls":1,"le":0,"lz":0,"rsi":-41,"lk":1}}
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.923] [INFO] Mqtt - Publishing MQTT message to topic landroid/status/yaw: 356.1
May 12 16:15:00 luv landroid-bridge[10057]: [2019-05-12T16:15:00.923] [INFO] Mqtt - Publishing MQTT message to topic landroid/status/schedule/0: {"startHour":12,"startMinute":0,"durationMinutes":0,"cutEdge":false}

If I understand this log correctly, this sends updates to the week program at 16:15:00 eight times (instead of just a single update), which may be understood as API misuse.
Except from this, the first update changes the duration for today (Sunday) to 480 minutes, while all other updates are identical and update the Sunday duration to 0 minutes.

These eight updates of the schedule to the landroid clould result in two Landroid status updates from the landroid cloud, the first one with 480 minutes for Sunday, while the second update (in the same second) changes to 0 minutes for Sunday (okay, that matches what was requested to the cloud before).

Hopefully this analysis will help debugging this issue and fix the scheduler to stop abusing the API and result in the correct schedule (the mower should have worked this hole afternoon instead of switching to 0 minutes).

RolandRosenfeld commented

Today I observed some similar strange behavior again.
As far as I can see, the problem seems to be that the scheduler receives 8 days of weather forecast (from today (Friday) to next Friday) and evaluates every single one of them.
This means, that on evaluating next Fridays weather forecast, the Friday schedule is overwritten but not by using todays weather forcast but the one for next friday.

The following small patch seems to fix this issue for me, but I didn't fully test this out, maybe someone wants to verify this:

--- Scheduler.ts.org    2019-05-02 12:37:05.883576436 +0200
+++ Scheduler.ts        2019-06-07 13:43:08.836000568 +0200
@@ -34,8 +34,9 @@
                 Object.keys(schedule).sort().forEach((key, i) => {
                     let item = schedule[key];
                     let date = moment(key);
-                    settings.push([date, item.durationMinutes]);
-                    if (i <= 7) {
+                    if (i < 7) {
+                        settings.push([date, item.durationMinutes]);
+                    } else {
                         LandroidS.getInstance().setSchedule(date.weekday(), item.serialize());
                     }
                 });

Instead of sending 8 updates to the landroid cloud, it collects data for day 7 days (starting with current day) in the settings object and instead of overwriting the data for today it sends out the generated schedule to the landroid cloud on i=7 (only once).

RolandRosenfeld commented

Just for the notes: The above didn't fully fix the issue. There is still something wrong in the data that's sent to the landroid cloud.

While the scheduler (http://localhost/scheduler/next7day) tells me, that the mower has to mow today (for 360 minutes):

{
  "2019-06-07": {
    "startHour": 12,
    "startMinute": 0,
    "durationMinutes": 360,
    "cutEdge": true
  },
...
}

the last update to the landroid cloud was

{"sc":{"d":[
  ["12:00",360,1],
  ["12:00",0,0],
  ["12:00",0,0],
  ["12:00",0,0],
  ["12:00",480,1],
  ["12:00",0,0],
  ["12:00",360,0]
]}}

If I got this right, it's a list of the weekdays, starting with Sunday, so today (Friday) is ["12:00",0,0], which is different from the schedule output above...

RolandRosenfeld commented

Now I begin to understand the code. It seems to be necessary to update the change of every single day to the landroid cloud (IMHO this should be rewritten in a way to send only one accumulated update to them), but we have to skip the eights day, so my previous patch can be reduced to

--- Scheduler.ts.org    2019-05-02 12:37:05.883576436 +0200
+++ Scheduler.ts        2019-06-07 17:02:25.707438280 +0200
@@ -35,7 +35,7 @@
                     let item = schedule[key];
                     let date = moment(key);
                     settings.push([date, item.durationMinutes]);
-                    if (i <= 7) {
+                    if (i < 7) {
                         LandroidS.getInstance().setSchedule(date.weekday(), item.serialize());
                     }
                 });