[Ovmsdev] Server Log 'S' Records Missing

[Tom Saxton]

Well, color me embarrassed, but it appears that the missing S records are a
problem on my side. It appears that my script that downloads and archives
the server records has a bug.

So, nevermind.

    Tom

On 12/9/14, 3:48 PM, "Tom Saxton" <tom at idleloop.com> wrote:

First off, I really appreciate that there's a way to get a log of OVMS data
from the server. It's been incredibly helpful to have this data as a
compliment to what's available in the Roadster's log file. I'm sure it's
even more useful for vehicles that don't have an accessible, built-in
logging system. Thanks, Mark!

In examining the OVMS server logs, I've noticed some missing status 'S'
records (generated by the net_msgp_stat function). Specifically, I'm not
seeing S records during a charge, when the SOC changes while the car is
idle, or when the smartphone app connects to get SOC info.

The details...

I'm using the HTTP API to download the OVMS records from the default server,
tmc.openvehicles.com. I have firmware version 2.6.7/TR/V2 (with Mark's
commit on Dec 7th), with a slight modification that has it read the
calculated amp-hour capacity (CAC) 11 minutes after each charge or drive
segment.

I have a script that decodes and summarizes the records to make them more
human-readable, and convert the timestamps to local time.

I drove yesterday, December 8th, and plugged it in when I got home. I see
the expected environment 'D' records once an hour thereafter, up through
this one at 4:56 am:

12/09/2014-04:56:02 D odo 42963.6, trip 27.8, Amb 15C, Batt 19C, PEM 26C,
Motor 37C, parked 14:04:47

According to the logs, the charge started at 5:53:39 am this morning,
December 9th. At 5:55, it sent four S records within 30 seconds as the
charge was ramping up.

12/09/2014-05:55:20 S standard 81%, 150 IM, CAC 149.84 Ah, 0:00, 0 kWh,
-1V/0A, CTP 1:22
12/09/2014-05:55:25 S standard 81%, 150 IM, CAC 149.84 Ah, 0:00, 0 kWh,
1V/0A, CTP 1:22
12/09/2014-05:55:40 S standard 81%, 150 IM, CAC 149.84 Ah, 0:00, 0 kWh,
1V/0A, CTP 1:22
12/09/2014-05:55:44 S standard 81%, 150 IM, CAC 149.84 Ah, 0:00, 0 kWh,
240V/17A, CTP 1:22

While it was charging, it sent in D records every 10 minutes.

12/09/2014-05:56:08 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 20C,
Motor 18C, parked 15:04:57
12/09/2014-06:06:06 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 34C,
Motor 25C, parked 15:14:48
12/09/2014-06:16:05 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 34C,
Motor 31C, parked 15:24:50
12/09/2014-06:26:03 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 34C,
Motor 36C, parked 15:34:52
12/09/2014-06:36:01 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 34C,
Motor 41C, parked 15:44:43
12/09/2014-06:45:59 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 34C,
Motor 45C, parked 15:54:45
12/09/2014-06:55:57 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 34C,
Motor 49C, parked 16:04:46
12/09/2014-07:05:56 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 34C,
Motor 52C, parked 16:14:37

Presumably this is from the code in net_state_ticker600() that checks all of
the potential messages to the server every 10 minutes when the car is "busy"
and sends those that have changed, but why are there D records but not S
records when we know the SOC value is changing?

Problem #1: Why are there no S records reported during a charge?

At the end of the charge, there are two records. This first one shows the
car is no longer charging at 7:10:30 am with the SOC at 98% and 182 ideal
miles. This is the car's preliminary SOC estimate (which is generally too
high).

12/09/2014-07:10:30 S standard 98%, 182 IM, CAC 149.84 Ah, 1:15, 8 kWh,
1V/0A, CTP 1:22

Next is the charge log record which says the charge ended at 07:08:31, and
shows the end charge with the preliminary SOC estimate.

12/09/2014-07:11:00 h Charge Log 0, 12/09/2014-05:53:39 1:14:52, Standard,
81% -> 98%, 150 -> 182 IM, CAC 149.84 Ah

Next we get another drive record with updated temperatures.

12/09/2014-07:15:59 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 32C,
Motor 51C, parked 16:24:49

Ten minutes after a charge (or drive) segment ends, the car updates the SOC
estimate with a more reliable number. At the same time, it updates the CAC.
(My change to the OVMS firmware reads the CAC a minute after this happens.)
Conveniently, I see an S record which has the updated information. I don't
see what generates this record, but I have seen this pattern on the last two
charges and I like it.

12/09/2014-07:21:23 S standard 96%, 179 IM, CAC 149.90 Ah, -1, 8 kWh,
-1V/127A, CTP 1:22

Now the car settles into the idle state where, once an hour, it looks at all
of the car data and sends messages to the server with any records which have
updated fields. The D record always updates because the park time is
constantly changing even if none of the temperatures do. So, we get a string
of D records, once every hour.

12/09/2014-08:15:52 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 32C,
Motor 51C, parked 17:24:38
12/09/2014-09:15:42 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 32C,
Motor 51C, parked 18:24:27

At 9:09, I checked the car's touchscreen and saw that the SOC on the
touchscreen was reading 177 ideal miles. I'm not sure when this happened,
but it was clearly before 9:15 when the last D record was sent.

Problem #2: Why didn't the the net_state_ticker3600() function send an S
record when the SOC changed?

At 9:59 am, I connected with the OVMS iPhone app, and saw that the SOC was
showing correctly in the app. When the screen first drew, it said the car's
data was 45 minutes old but it had the correct SOC, 177 ideal miles. It then
updated to "live", still showing the correct SOC. From the server log, I see
that a D record got recored when I connected with the iPhone, but there's no
S record.

12/09/2014-10:00:51 D odo 42963.6, trip 27.8, Amb 16C, Batt 19C, PEM 32C,
Motor 51C, parked 19:09:34

Problem #3: How did the app get the updated SOC if the server hasn't
received any S records? Clearly, it got the SOC from somewhere, but it's not
showing up in the server logs.

The firmware code looks great to me. It should send along the S records when
the SOC and CAC fields change, but there seem to be a bunch missing from the
reported server logs. Either they aren't getting sent (which doesn't explain
how the smartphone app gets the correct values) or they aren't being
recorded on the server, or they aren't being reported by the HTTP API.

Any idea what's going on?

   Tom


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.teslaclub.hk/pipermail/ovmsdev/attachments/20141210/705add22/attachment.html>