Battery status flapping

Troubleshooting
#1

When machine is turned off the battery state is flapping and causing critical_level events.

Your environment

  • Dongle Version: Not shown in interface, only stating “up to date”
    probably e582497af01162ce4d6023f1b836811b13fc388a (see log below)
  • Vehicle: BMW 1 E87
    • The car is shutting down all power consumers inside the vehicle when removing the key
    • The only still active components are the radio and the OBD port (= AutoPi Dongle)
    • During the recording below the Dongle turned itself on and did not go to sleep meanwhile
    • The vehicle is parked in a car parking with steady conditions (no direct sunlight, mostly constant temperature, …) so the battery should not be affected by environmental conditions
    • At the time shown below the car was already parked for ~1.5h

Steps to reproduce

  • (Have a new battery)
  • Add Dongle to car
  • Let the dongle read the battery status after car has been parked for some time

Expected behaviour

  • Battery readings are (mostly) consistent

Actual behaviour

Time Event Payload
10:17:11 AM release.updated { "event.release.id": "e582497af01162ce4d6023f1b836811b13fc388a" }
11:06:57 AM power.on { "event.power.trigger": "stn" }
11:08:10 AM battery.critical_level { "event.battery.voltage": 12.2 }
{ "event.battery.level": 60 }
11:08:11 AM battery.discharging { "event.battery.voltage": 12.6 }
{ "event.battery.level": 100 }
11:23:17 AM battery.critical_level { "event.battery.voltage": 12.3 }
{ "event.battery.level": 70 }
11:23:19 AM battery.discharging { "event.battery.voltage": 12.6 }
{ "event.battery.level": 100 }
11:32:04 AM battery.critical_level { "event.battery.voltage": 12.3 }
{ "event.battery.level": 70 }
11:32:06 AM battery.discharging { "event.battery.voltage": 12.6 }
{ "event.battery.level": 100 }
11:36:35 AM battery.critical_level { "event.battery.voltage": 12.3 }
{ "event.battery.level": 70 }
11:36:36 AM battery.discharging { "event.battery.voltage": 12.6 }
{ "event.battery.level": 100 }
11:37:13 AM power.sleep { "event.power.delay": 10 }
{ "event.power.interval": 3600 }
{ "event.power.reason": "engine_stopped" }
#2

Hi Luzifer

From the events you posted, it looks like the voltage goes down, and then immediately up after a second or two.
Is the above situation happening all the time, or is it only sometimes?

The dongle is using the voltage to decide when the car is started or not.
The default trigger for turning on the device is a voltage increase of 0.2v or more, for 2 seconds, and from looking at the events you attached, it may cause the device to start at unexpected times. How often do you see the below event?

power.on	{ "event.power.trigger": "stn" }

If you see this event at other times than when you manually turn on the ignition, you may want to tweak the above mentioned trigger setting.
You can see the current configuration by running the below command

power.status

Regarding the many battery events, we have on our roadmap to change the battery event generator to sample over a few seconds, as the current logic can emit quite a lot of events when the voltage is just on the “edge”.
This will make the log more clean.

#3

Lets see:

$ curl "https://api.autopi.io/logbook/events/...&start_utc=2018-06-26T17:30:00Z&end_utc=2018-06-27T17:30:34.709Z" > events.json

$ jq -r '.[0].events |.[] | select(.area == "power") | select(.event == "on") | .ts + " => " + (.data|tojson)' events.json | grep stn
2018-06-27T15:47:59.262500Z => [{"event.power.trigger":"stn"}]
2018-06-27T14:09:52.923322Z => [{"event.power.trigger":"stn"}]
2018-06-27T09:39:28.801246Z => [{"event.power.trigger":"stn"}]
2018-06-27T09:06:57.184463Z => [{"event.power.trigger":"stn"}]
2018-06-27T07:09:31.895019Z => [{"event.power.trigger":"stn"}]

$ jq -r '.[0].events |.[] | select(.area == "engine") | select(.event == "running") | "" + .ts + " => " + .event' events.json
2018-06-27T15:47:16.108955Z => running
2018-06-27T07:09:37.182562Z => running

So from this I’ve started the engine twice in the time selected from the API which is true. So there were three “false-positive” stn events.

During the same time frame there were several battery recordings with a variance of 0.6V and 40% battery level:

$ jq -r '.[0].events |.[] | select(.area == "battery") | select(.event == ("critical_level", "discharging")) | .ts + " (" + .event + ") => " + (.data|tojson)' events.json
2018-06-27T14:09:08.806776Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T13:56:49.040306Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T13:36:05.093208Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T13:36:03.974697Z (critical_level) => [{"event.battery.voltage":12.3},{"event.battery.level":70}]
2018-06-27T12:37:09.868581Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T11:28:42.235812Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T11:25:58.028765Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T11:25:58.028765Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T11:14:04.157309Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T09:38:45.525809Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T09:36:36.467656Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T09:36:35.317638Z (critical_level) => [{"event.battery.voltage":12.3},{"event.battery.level":70}]
2018-06-27T09:32:06.393326Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T09:32:04.943790Z (critical_level) => [{"event.battery.voltage":12.3},{"event.battery.level":70}]
2018-06-27T09:23:19.069079Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T09:23:17.948669Z (critical_level) => [{"event.battery.voltage":12.3},{"event.battery.level":70}]
2018-06-27T09:08:11.955528Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T09:08:10.803540Z (critical_level) => [{"event.battery.voltage":12.2},{"event.battery.level":60}]
2018-06-27T08:19:05.711777Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-27T07:45:35.417757Z (discharging)    => [{"event.battery.voltage":12.8},{"event.battery.level":100}]
2018-06-27T07:44:16.076425Z (discharging)    => [{"event.battery.voltage":12.8},{"event.battery.level":100}]
2018-06-27T07:44:06.127150Z (discharging)    => [{"event.battery.voltage":12.8},{"event.battery.level":100}]
2018-06-27T07:43:51.356968Z (discharging)    => [{"event.battery.voltage":12.8},{"event.battery.level":100}]
2018-06-27T07:43:44.016640Z (discharging)    => [{"event.battery.voltage":12.8},{"event.battery.level":100}]
2018-06-27T07:43:39.127800Z (discharging)    => [{"event.battery.voltage":12.8},{"event.battery.level":100}]
2018-06-27T07:43:25.606769Z (discharging)    => [{"event.battery.voltage":12.8},{"event.battery.level":100}]
2018-06-26T18:46:38.164273Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-26T18:34:16.507209Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-26T18:21:54.521421Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]
2018-06-26T18:09:33.255139Z (discharging)    => [{"event.battery.voltage":12.6},{"event.battery.level":100}]

In the end this happened that often I disabled critical_level email alerts as they got too spammy…

When the engine is running the voltages reported do differ from what I’m seeing above but there is no significant difference:

$ jq -r '.[0].events |.[] | select(.area == "battery") | select(.event == ("charging", "charging_slow")) | .ts + " (" + .event + ") => " + (.data|tojson)' events.json
2018-06-27T16:46:39.661034Z (charging)      => [{"event.battery.voltage":14.0},{"event.battery.level":100}]
2018-06-27T16:46:38.400260Z (charging_slow) => [{"event.battery.voltage":13.6},{"event.battery.level":100}]
2018-06-27T15:47:15.534953Z (charging)      => [{"event.battery.voltage":14.1},{"event.battery.level":100}]
2018-06-27T11:28:41.100363Z (charging_slow) => [{"event.battery.voltage":13.0},{"event.battery.level":100}]
2018-06-27T07:45:34.163388Z (charging_slow) => [{"event.battery.voltage":12.9},{"event.battery.level":100}]
2018-06-27T07:44:14.762218Z (charging_slow) => [{"event.battery.voltage":12.9},{"event.battery.level":100}]
2018-06-27T07:44:04.864743Z (charging_slow) => [{"event.battery.voltage":12.9},{"event.battery.level":100}]
2018-06-27T07:43:46.456491Z (charging_slow) => [{"event.battery.voltage":12.9},{"event.battery.level":100}]
2018-06-27T07:43:41.576746Z (charging_slow) => [{"event.battery.voltage":12.9},{"event.battery.level":100}]
2018-06-27T07:43:29.226251Z (charging_slow) => [{"event.battery.voltage":12.9},{"event.battery.level":100}]
2018-06-27T07:43:15.670348Z (charging_slow) => [{"event.battery.voltage":12.9},{"event.battery.level":100}]
2018-06-27T07:13:30.076717Z (charging)      => [{"event.battery.voltage":14.0},{"event.battery.level":100}]
2018-06-27T07:13:28.816095Z (charging_slow) => [{"event.battery.voltage":13.6},{"event.battery.level":100}]
2018-06-27T07:09:36.445902Z (charging)      => [{"event.battery.voltage":14.0},{"event.battery.level":100}]
#4

Hi Luzifer

First of all, thank you for your thorough examples!
So, it seems that the voltage changes enough for the device to think the car is started. Why the voltage changes, I don’t know, but I think the easiest solution is to tweak the configuration.
I will get back to you tomorrow with the commands, and our suggestion as to what the configuration should be changed to.
But I think it’s positive that it only happens a few times, so it should not really impact the power usage - Does the device go to sleep between the power.on events?

As i said above, we have on our roadmap to make the battery events a little less noisy, I’m also thinking that we could change the triggers to take a configurable delay, so that each trigger can be configured to only trigger once the delay has expired.
Currently it’s hardcoded to once per minute, but we may hit this situation again for other types of events later.

Thanks again :slight_smile:

Best regards
/ Malte

#5

Hi Luzifer

You can do the following to change the voltage wake configuration:

  1. See the current config

    stn.volt_change_wake

  2. Change the configuration from 1000ms to 2000ms

    stn.volt_change_wake enable=True ms=2000

  3. Verify the new configuration has been set

    stn.volt_change_wake

That should make it ignore those random voltage spikes.
Unfortunately, the above configuration will be overwritten the next time the device auto updates, but we are currently implementing changes so that those values can be configured by the user, so the first part of the solution is to see if the above configuration change fixes the issues :slight_smile:

(btw, you can see the mentioned module source code here: stn module)

Best regards
/ Malte

#6

Hey Malte,

thanks for the sniplet. Will apply this the next time my car isn’t in a mobile-network-black-hole (sadly my home parking spot is such a place) and report back after testing with the new settings…

Cheers,
Knut

1 Like
#7

Hi

Just a quick note to tell you that we have changed the battery event emitter to be a bit more sparse with the events that are sent from the device.

If you device has not updated automatically yet, you can trigger the update manually from the software state page on my.autopi.io

Best regards
/ Malte

#8