Odd decoding of logs (negative distance)

[gregd]

Not sure where to aim this... I just grabbed the logs from my most recent drives (still fussing over 1146 errors), and ran them through the latest version of VMSParser.exe. I see the following:

12/06/2019 13:22:48 - 12/06/2019 13:28:23 (00:05:35) Charge 82% -> 82% 241V 24A of 40A 0.4 kWh 0.0 Ah 0.0 Ah
12/07/2019 11:08:16 - 12/07/2019 11:38:12 (00:29:56) Drive 82% -> 76% 17.9 mi 37.9 mph 59.8 mph 52884.3 mi 3.1 kWh 4.0 Ah 12.4 Ah 176 Wh/mi
12/07/2019 12:36:31 - 12/07/2019 13:05:01 (00:28:30) Drive 76% -> 69% -1841.2 mi -4002.6 mph 66.7 mph 51043.1 mi 5.5 kWh 3.5 Ah 18.2 Ah
12/07/2019 13:06:08 - 12/07/2019 15:11:22 (02:05:14) Charge 65% -> 83% 238V 24A of 40A 11.8 kWh 0.0 Ah 0.0 Ah
201912072345.tar Transient section: odometer: 51043.0 to 52897.0 (1854.0 mi), 56.8 hours of driving, 244.1 hours of charging, over 174.2 days
​

The odometer on the dash reads 52,902 miles, and OVMSv3 agrees with that (52,902.6). The Clock shows the right time (i.e. GPS is good).

So, puzzles...

1. How come the last drive turns up with negative distance (-1841.2 mi), at a speed of negative 4000mph? Presumably the result of math based on an incorrect odometer value, but where'd that come from?
2. How come the "transient section" report lists the odometer reading some 5 miles short of how far the car has gone? Shouldn't they be the same?

Has the car's log wrapped or gotten corrupted? Is the decoding of the log by VMSParser incorrect? Is my car sick?

 

[hcsharp]

Is my car sick?

Oh man, your car is really sick. Were you having a race with Starman? Backwards?

 

[gregd]

Oh man, your car is really sick. Were you having a race with Starman? Backwards?

What? You mean we aren't supposed to do that?

Reminds me of a cartoon strip "Robotman", where in the first panel he says he's going to take his new spaceship once around the galaxy and back. Second panel: "Click". Third panel: "Either this thing isn't working, or it's a heck of a lot faster than I thought."

 

[slcasner]

If you want to send your log file to me, I'll see what my parser says.

 

[gregd]

If you want to send your log file to me, I'll see what my parser says.

Message sent (standard email). Let us know what you find!

 

[tomsax]

Hi Greg,

Thanks for the bug report. There's nothing wrong with your car, just decode issue in my parser. There's a new version available on my web site that fixes the problem.

VMS Log Parser for Tesla Roadster

The details...

There is no such thing as a driving or charging session in the Roadster log file, just a stream of various types of records. The list you see when you run VMSParser without any special options shows a summary of drive and charge sessions as interpreted from the log file records.

The Roadster writes out a record every second while driving, but those records don't contain the odometer value. There's a different record that gets written about about once every ten minutes while driving that does have the odometer value.

In your case, the last odometer record was written at 12:56:29 (PST) but your drive session ran until 13:05:01, so there's no odometer data for those last 9 minutes of driving.

When the parser notices the end of a string of those 1-second drive records (by seeing a record that doesn't normally get written while the car is on), it then scans ahead to find the next record with an odometer value so it knows your final mileage. In this case, that was the last drive session recorded and there's wasn't another odometer written before the log file was downloaded.

The code that scans ahead for the next odometer record scanned past where the log wrapped back to the beginning and used the oldest record as the final odometer for that drive session, thus the large negative value.

I fixed the code to stop scanning when it hits the point where the transient section wraps back to the start. I already had code in there that approximates the mileage driven by integrating speed over time, so I now just use that approximation when there isn't an odometer record after the drive session. In this case, the approximation is 52902.5, just a bit off from the actual value you read from the touch screen.

Somewhat related, the summary at the end of the parser output that lists the starting and ending odometer values from the transient section only shows the values from the first and last actual odometer records, so those can differ from the actual first and list odometer readings for the same reason.

 

[tomsax]

BTW, there's an email link at the bottom of my web page that anyone can use to contact me with VMSParser issues.

 

[gregd]

Hi Greg,

Thanks for the bug report. There's nothing wrong with your car, just decode issue in my parser. There's a new version available on my web site that fixes the problem.

VMS Log Parser for Tesla Roadster

The details...

There is no such thing as a driving or charging session in the Roadster log file, just a stream of various types of records. The list you see when you run VMSParser without any special options shows a summary of drive and charge sessions as interpreted from the log file records.

The Roadster writes out a record every second while driving, but those records don't contain the odometer value. There's a different record that gets written about about once every ten minutes while driving that does have the odometer value.

In your case, the last odometer record was written at 12:56:29 (PST) but your drive session ran until 13:05:01, so there's no odometer data for those last 9 minutes of driving.

When the parser notices the end of a string of those 1-second drive records (by seeing a record that doesn't normally get written while the car is on), it then scans ahead to find the next record with an odometer value so it knows your final mileage. In this case, that was the last drive session recorded and there's wasn't another odometer written before the log file was downloaded.

The code that scans ahead for the next odometer record scanned past where the log wrapped back to the beginning and used the oldest record as the final odometer for that drive session, thus the large negative value.

I fixed the code to stop scanning when it hits the point where the transient section wraps back to the start. I already had code in there that approximates the mileage driven by integrating speed over time, so I now just use that approximation when there isn't an odometer record after the drive session. In this case, the approximation is 52902.5, just a bit off from the actual value you read from the touch screen.

Somewhat related, the summary at the end of the parser output that lists the starting and ending odometer values from the transient section only shows the values from the first and last actual odometer records, so those can differ from the actual first and list odometer readings for the same reason.

Yay! Thanks Tom. Works now as expected.