Update duration 0 and charge logged not completely #2181

manuelkamp · 2021-11-22T14:27:05Z

Is there an existing issue for this?

I have searched the existing issues

What happened?

My Tesla updated and teslamate only logged "0 seconds" as duration (see screenshot 3)
In addition: the following charge, started after the update, was not logged completely. Only ~1 hour of the ~5 hour charge was logged and also the other values of this charge are wrong. Instead, "online" was logged for the remaining real charge time (see screenshot 2)
Also the number of charges in the actual version in the "Updates" view show 0, but should be 2 now. Two charges since update showing up in "Charges" - the wrong one from bullet point two and another one (this was logged correct). see screenshot 3

Expected Behavior

Log the correct update duration (it was about 35 minutes according to the notifications of the tesla app on my smartphone). 0 seconds is definitely wrong.
Log the correct charge time and all according values.
Show the correct amount of charges for the actual version.

Steps To Reproduce

Update Tesla to 2021.26.5.8
Charge the Tesla
View wrong/missing values in teslamate

I tried to correct it (unsuccessful) with the following command, where 141 is the id of the wrong logged charge:
docker-compose exec teslamate bin/teslamate rpc "TeslaMate.Repo.get!(TeslaMate.Log.ChargingProcess, 141) |> TeslaMate.Log.complete_charging_process()"

Relevant log output

Issue occured on 19.11.2021, log starts at 20.11.2021 (over 100MB repeated this lines, where the value in the brackets in the end of the first line is different):
�[36mteslamate_1  |�[0m     Args: [#Function<4.48828428/1 in TeslaMate.Mqtt.PubSub.VehicleSubscriber.handle_info/2>, [usable_battery_level: 74]]
�[36mteslamate_1  |�[0m 2021-11-22 15:04:17.120 [error] Task #PID<0.25096.6> started from #PID<0.25066.6> terminating
�[36mteslamate_1  |�[0m ** (stop) exited in: GenServer.call(TeslaMate.Mqtt.Publisher, {:publish, "teslamate/cars/1/charger_voltage", "2", [retain: true, qos: 1]}, 10000)
�[36mteslamate_1  |�[0m     ** (EXIT) an exception was raised:
�[36mteslamate_1  |�[0m         ** (WithClauseError) no with clause matching: {:error, :timeout}
�[36mteslamate_1  |�[0m             (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
�[36mteslamate_1  |�[0m             (teslamate 1.25.0) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) gen_server.erl:721: :gen_server.try_handle_call/4
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) gen_server.erl:750: :gen_server.handle_msg/6
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/gen_server.ex:1024: GenServer.call/3
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/task/supervised.ex:35: Task.Supervised.reply/5
�[36mteslamate_1  |�[0m     (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
�[36mteslamate_1  |�[0m Function: &:erlang.apply/2
�[36mteslamate_1  |�[0m     Args: [#Function<4.48828428/1 in TeslaMate.Mqtt.PubSub.VehicleSubscriber.handle_info/2>, [charger_voltage: 2]]
�[36mteslamate_1  |�[0m 2021-11-22 15:04:17.117 [error] Task #PID<0.25089.6> started from #PID<0.25066.6> terminating
�[36mteslamate_1  |�[0m ** (stop) exited in: GenServer.call(TeslaMate.Mqtt.Publisher, {:publish, "teslamate/cars/1/doors_open", "false", [retain: true, qos: 1]}, 10000)
�[36mteslamate_1  |�[0m     ** (EXIT) an exception was raised:
�[36mteslamate_1  |�[0m         ** (WithClauseError) no with clause matching: {:error, :timeout}
�[36mteslamate_1  |�[0m             (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
�[36mteslamate_1  |�[0m             (teslamate 1.25.0) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) gen_server.erl:721: :gen_server.try_handle_call/4
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) gen_server.erl:750: :gen_server.handle_msg/6
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/gen_server.ex:1024: GenServer.call/3
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/task/supervised.ex:35: Task.Supervised.reply/5
�[36mteslamate_1  |�[0m     (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
�[36mteslamate_1  |�[0m Function: &:erlang.apply/2
�[36mteslamate_1  |�[0m     Args: [#Function<4.48828428/1 in TeslaMate.Mqtt.PubSub.VehicleSubscriber.handle_info/2>, [doors_open: false]]
�[36mteslamate_1  |�[0m 2021-11-22 15:04:17.119 [error] Task #PID<0.25093.6> started from #PID<0.25066.6> terminating
�[36mteslamate_1  |�[0m ** (stop) exited in: GenServer.call(TeslaMate.Mqtt.Publisher, {:publish, "teslamate/cars/1/battery_level", "75", [retain: true, qos: 1]}, 10000)
�[36mteslamate_1  |�[0m     ** (EXIT) an exception was raised:
�[36mteslamate_1  |�[0m         ** (WithClauseError) no with clause matching: {:error, :timeout}
�[36mteslamate_1  |�[0m             (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
�[36mteslamate_1  |�[0m             (teslamate 1.25.0) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) gen_server.erl:721: :gen_server.try_handle_call/4
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) gen_server.erl:750: :gen_server.handle_msg/6
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/gen_server.ex:1024: GenServer.call/3
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/task/supervised.ex:35: Task.Supervised.reply/5
�[36mteslamate_1  |�[0m     (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
�[36mteslamate_1  |�[0m Function: &:erlang.apply/2
�[36mteslamate_1  |�[0m     Args: [#Function<4.48828428/1 in TeslaMate.Mqtt.PubSub.VehicleSubscriber.handle_info/2>, [battery_level: 75]]
�[36mteslamate_1  |�[0m 2021-11-22 15:04:17.122 [error] Task #PID<0.25098.6> started from #PID<0.25066.6> terminating
�[36mteslamate_1  |�[0m ** (stop) exited in: GenServer.call(TeslaMate.Mqtt.Publisher, {:publish, "teslamate/cars/1/time_to_full_charge", "0.0", [retain: true, qos: 1]}, 10000)
�[36mteslamate_1  |�[0m     ** (EXIT) an exception was raised:
�[36mteslamate_1  |�[0m         ** (WithClauseError) no with clause matching: {:error, :timeout}
�[36mteslamate_1  |�[0m             (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
�[36mteslamate_1  |�[0m             (teslamate 1.25.0) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) gen_server.erl:721: :gen_server.try_handle_call/4
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) gen_server.erl:750: :gen_server.handle_msg/6
�[36mteslamate_1  |�[0m             (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/gen_server.ex:1024: GenServer.call/3
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
�[36mteslamate_1  |�[0m     (elixir 1.12.3) lib/task/supervised.ex:35: Task.Supervised.reply/5
�[36mteslamate_1  |�[0m     (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
�[36mteslamate_1  |�[0m Function: &:erlang.apply/2
�[36mteslamate_1  |�[0m     Args: [#Function<4.48828428/1 in TeslaMate.Mqtt.PubSub.VehicleSubscriber.handle_info/2>, [time_to_full_charge: 0.0]]

Screenshots

Additional data

charges.csv
charging_processes.csv

Type of installation

Docker

Version

1.25.0

manuelkamp · 2021-11-22T14:33:44Z

Is this maybe corresponding to the tesla server problems? https://winfuture.de/news,126546.html
If yes: How can I manually edit the missing data of the update and the charge? And if yes, why the last two charges are not counted in the "Updates" tab?

DrMichael · 2021-11-22T15:28:26Z

My Tesla updated and teslamate only logged "0 seconds" as duration (see screenshot 3)

That is already fixed: #2125 It was a display issue.

manuelkamp · 2021-11-25T15:02:24Z

My Tesla updated and teslamate only logged "0 seconds" as duration (see screenshot 3)

That is already fixed: #2125 It was a display issue.

well, it seems not for me. I have several charges since the last software update and the counter still says "0" for the duration and "0" charges on this software revision in the "Updates" tab. Also the average rated range value is missing. I just checked again, I am using the latest teslamate version.

Do I have to adjust something manually?

But this is just an "nice to have" information - much more I am interested in how to fix the missing charging data?

DrMichael · 2021-11-25T15:30:05Z

Oh, I only meant the duration of updates in timeline

manuelkamp · 2021-11-26T09:16:18Z

Ok, so I have fixed the duration now with this: update updates set end_date='2021-11-19 16:21:34' where id='17';
I took the correct time from the "States" view, there it was logged correct.

where does this "Updates" view take the "# of charges" and the "avg rated range" values, so that I can fix that too?

manuelkamp · 2021-11-26T09:22:28Z

And I added the missing charging data manually now, by updating the charge in the table "charging_processes". I updated the following columns (i calculated the values by the following data in the timeline and based on other charge values):

end_ideal_range_km='373.00'
end_battery_level='81'
duration_min='277'
end_rated_range_km='373.0'
charge_energy_used='13.63'
charge_energy_added='12.77'
cost='2.52'

is this enough, or did i forgot something there? (I do not mind the missing charging details for the graphs with soc, voltage...)

manuelkamp · 2021-11-28T08:03:30Z

noone can answer this?

where does this "Updates" view take the "# of charges" and the "avg rated range" values, so that I can fix that too?

DrMichael · 2021-11-28T12:47:57Z

Concerning # of charges in Updates: What do you get with
select * from charging_processes where start_date BETWEEN '2021-11-19' AND '2021-11-23';
?

manuelkamp · 2021-11-28T13:35:45Z

2 charges, which is correct

142 | 2021-11-22 07:09:56.043 | 2021-11-22 07:23:54.518 | 2.30 | 333.02 | 349.53 | 73 | 76 | 14 | 4.2 | 1 | 1269513 | 108 | 333.02 | 349.53 | | 2.53 | 141 | 2021-11-19 18:45:30.246 | 2021-11-20 00:42:47.123 | 12.77 | 269.05 | 373.00 | 59 | 81 | 277 | 11.2 | 1 | 1262115 | 1 | 269.05 | 373.00 | 1 | 13.63 | 2.52 (2 rows)

DrMichael · 2021-11-28T15:15:03Z

Sorry, out of ideas...

manuelkamp · 2021-11-29T12:03:25Z

Today I had a Ranger visit (to install the Homelink module) and he did an "Update" to enable the functionality. I now have the values for the Version where it was missing before, but now have again no values for the recent version. The Version numbers are the same unfortunately... It seems that a counter or anything like that went wrong in my installation due to the initial problems. If I do the query select count(*) from charging_processes where start_date BETWEEN '2011-11-19' AND '2021-11-28'; I get 143 as a result. But when I look at the "Charging Stats" page, it shows only 140 total number of charges...?

I tried to read through the SQL in the grafana settings for "Updates" - but it is too complicated for me to understand (I am more the code guy, just basic dba stuff - enough to do simple cud operations, but thats it pretty much). Maybe someone with a better understanding can explain or figure it out with that possible hint? Also I am offering a tip for solving it, for sure - it seems it is getting very deep into it now.

18 | 2021-11-29 10:24:55.821 | 2021-11-29 10:33:40.1 | 2021.36.5.8 43e7bf261905 | 1
17 | 2021-11-19 14:25:40.895 | 2021-11-19 16:21:34.123 | 2021.36.5.8 43e7bf261905 | 1

EDIT: the difference in the total number of charges is a result of the filter "charge_energy_added > 0.01" in the grafana page.

manuelkamp · 2021-11-29T13:25:09Z

new update on this: I have now inspected the code for the Updates table in grafana. I figured out, that there is definitely a problem: The following query (it is a subquery of the original query) delivers a wrong line:

select *, coalesce(lag(start_date) over(order by start_date desc), now()) as next_start_date
from updates
where car_id = '1' and start_date BETWEEN '2011-11-29T13:15:16.272Z' AND '2021-11-29T13:15:16.272Z';

result:
id | start_date | end_date | version | car_id | next_start_date
----+-------------------------+-------------------------+---------------------------+--------+----------------------------
18 | 2021-11-29 10:24:55.821 | 2021-11-29 10:33:40.1 | 2021.36.5.8 43e7bf261905 | 1 | 1934-08-23 00:57:36+00
17 | 2021-11-19 14:25:40.895 | 2021-11-19 16:21:34.123 | 2021.36.5.8 43e7bf261905 | 1 | 2021-11-29 10:24:55.821+00
16 | 2021-10-29 07:16:37.303 | 2021-10-29 07:39:03.881 | 2021.36.5.5 c6d521764ab9 | 1 | 2021-11-19 14:25:40.895+00

you can see in id 18, the next_start_date is in the year 1934... I do not know where this comes from, since I do not have any start date like this in the table "updates"? following the logic of the query, in the result line id 18 the value should be the result of now()?

DrMichael · 2021-11-29T13:32:19Z

Oh, what gives select now();?

manuelkamp · 2021-11-29T13:34:30Z

yes, that was the path I was looking for. Indeed it gives 1934-08-23 00:57:36+00
also select timeofday(); gives: Thu Jan 01 00:12:48.33144068 1970 UTC

interesting: the result of now() stays the same, always...

but date on the servers console shows: Mon 29 Nov 14:32:42 CET 2021

how do i set the correct time for this (I guess the docker container?)

DrMichael · 2021-11-29T13:38:40Z

Either the database or the grafana container:

docker-compose exec grafana date
docker-compose exec database date

manuelkamp · 2021-11-29T13:42:48Z

it seems both are wrong:

pi@rp-tesla:~ $ docker-compose exec grafana date
Sun Jan 0 00:100:3649750 1900
pi@rp-tesla:~ $ docker-compose exec database date
Thu 01 Jan 1970 12:00:00 AM UTC

also it seems, the problem occured due the update to version 1.25 - I have this problem since the update of teslamate and it has nothing to do with charges, updates etc. of tesla itself...

pi@rp-tesla:~ $ docker container ls
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
0352e1a1f2f0 teslamate/teslamate:latest "tini -- /bin/sh /en…" 9 days ago Up 2 days 127.0.0.1:4000->4000/tcp pi_teslamate_1
3e1609ba9038 teslamate/grafana:latest "/run.sh" 9 days ago Up 2 days 127.0.0.1:3000->3000/tcp pi_grafana_1
6f9ffafd5b3e eclipse-mosquitto:1.6 "/docker-entrypoint.…" 9 days ago Up 2 days 127.0.0.1:1883->1883/tcp pi_mosquitto_1
398198983b35 postgres:12 "docker-entrypoint.s…" 9 days ago Up 2 days 5432/tcp pi_database_1

edit: I tried restarting docker (down / up) and also restarting the machine completely - none worked

DrMichael · 2021-11-29T14:09:05Z

We are talking of the standard container images, right?

Why don't you make a backup, remove all images and containers, make a fresh pull and up and restore the backup?

(Or do you happen to have another machine to read in the backup?)

manuelkamp · 2021-11-30T15:51:03Z

correct, the standard container images.

I now made a specific backup of the db, removed everything (deleted the volumes), also updated postgres to v13 (since this is a good opportunity), pulled the containers, stopped teslamate to not insert data while restoring, and finally restored the db and started teslamate again. the process itself worked fine, all data still here - but still the date issue exists.

My backup strategy is usually per machine. So if anything fails, I have complete disk images to restore. I also tried this, with the same (expected) result: date issue still exists.

Is there any possibility that me running a 64bit Kernel on my pi caused this issue - the OS itself is 32bit? I mean I have switched to 64bit kernel several months ago, but this wrong-date-problem exists only since the last teslamate update to version 1.25. None of the previous updates caused problems - I also tried to disable the 64bit kernel and rebooted the machine with the 32bit Kernel, but still no change with the date issue.

PostgreSQL Database directory appears to contain a database; Skipping initialization
1970-01-01 00:00:00.000 UTC [1] LOG: starting PostgreSQL 13.5 (Debian 13.5-1.pgdg110+1) on arm-unknown-linux-gnueabihf, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 32-bit
1970-01-01 00:00:00.000 UTC [1] LOG: listening on IPv4 address "0.0.0.0", port 5432
1970-01-01 00:00:00.000 UTC [1] LOG: listening on IPv6 address "::", port 5432
1970-01-01 00:00:00.000 UTC [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
1970-01-01 00:00:00.000 UTC [26] LOG: database system was shut down at 1970-06-25 17:32:24 UTC
1970-01-01 00:00:00.000 UTC [1] LOG: database system is ready to accept connections
1970-01-01 00:00:00.000 UTC [31] LOG: stats_timestamp 2000-01-01 00:00:00+00 is later than collector's time 1969-12-31 23:59:53.982312+00 for database 0
1970-01-01 00:00:00.000 UTC [30] LOG: stats collector's time 1970-05-26 06:18:36.55068+00 is later than backend local time 1970-01-03 16:39:36+00
1970-01-01 00:00:00.000 UTC [31] LOG: stats_timestamp 1970-05-26 06:18:36.55068+00 is later than collector's time 1969-12-31 23:59:53.982312+00 for database 0

EDIT: well, it seems there was an issue with docker itself. I recieved a docker upgrade via apt and after a restart, I get time!:
pi@rp-tesla:~ $ docker-compose exec grafana date Tue Nov 30 16:21:22 UTC 2021

AND
pi@rp-tesla:~ $ docker-compose exec database date
Tue 30 Nov 2021 04:22:55 PM UTC

I do not know what resolved the issue exactly, but in the "Updates" I now see the number 0 in the # of charges (which is correct, I recieved an update from tesla today). But 0 is better than no value.

I am wondering, if I was the only one who had this issue - or the only one who cared?

Now only the "avg rated range" is an empty value - is that normal, since there was no drive since the tesla update?

manuelkamp · 2021-11-30T16:34:07Z

For me the root cause is still unknown. Facts show, that there was an error existing since a tesla update and a teslamate update on the same day. The issue was mainly resolved by manually editing data in the db and applying a docker update via apt. Thanks to @DrMichael for your time and help

manuelkamp closed this as completed Nov 30, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Update duration 0 and charge logged not completely #2181

Update duration 0 and charge logged not completely #2181

manuelkamp commented Nov 22, 2021 •

edited

Loading

manuelkamp commented Nov 22, 2021

DrMichael commented Nov 22, 2021

manuelkamp commented Nov 25, 2021 •

edited

Loading

DrMichael commented Nov 25, 2021

manuelkamp commented Nov 26, 2021 •

edited

Loading

manuelkamp commented Nov 26, 2021 •

edited

Loading

manuelkamp commented Nov 28, 2021

DrMichael commented Nov 28, 2021 •

edited

Loading

manuelkamp commented Nov 28, 2021 •

edited

Loading

DrMichael commented Nov 28, 2021

manuelkamp commented Nov 29, 2021 •

edited

Loading

manuelkamp commented Nov 29, 2021 •

edited

Loading

DrMichael commented Nov 29, 2021

manuelkamp commented Nov 29, 2021 •

edited

Loading

DrMichael commented Nov 29, 2021

manuelkamp commented Nov 29, 2021 •

edited

Loading

DrMichael commented Nov 29, 2021

manuelkamp commented Nov 30, 2021 •

edited

Loading

manuelkamp commented Nov 30, 2021

Update duration 0 and charge logged not completely #2181

Update duration 0 and charge logged not completely #2181

Comments

manuelkamp commented Nov 22, 2021 • edited Loading

Is there an existing issue for this?

What happened?

Expected Behavior

Steps To Reproduce

Relevant log output

Screenshots

Additional data

Type of installation

Version

manuelkamp commented Nov 22, 2021

DrMichael commented Nov 22, 2021

manuelkamp commented Nov 25, 2021 • edited Loading

DrMichael commented Nov 25, 2021

manuelkamp commented Nov 26, 2021 • edited Loading

manuelkamp commented Nov 26, 2021 • edited Loading

manuelkamp commented Nov 28, 2021

DrMichael commented Nov 28, 2021 • edited Loading

manuelkamp commented Nov 28, 2021 • edited Loading

DrMichael commented Nov 28, 2021

manuelkamp commented Nov 29, 2021 • edited Loading

manuelkamp commented Nov 29, 2021 • edited Loading

DrMichael commented Nov 29, 2021

manuelkamp commented Nov 29, 2021 • edited Loading

DrMichael commented Nov 29, 2021

manuelkamp commented Nov 29, 2021 • edited Loading

DrMichael commented Nov 29, 2021

manuelkamp commented Nov 30, 2021 • edited Loading

manuelkamp commented Nov 30, 2021

manuelkamp commented Nov 22, 2021 •

edited

Loading

manuelkamp commented Nov 25, 2021 •

edited

Loading

manuelkamp commented Nov 26, 2021 •

edited

Loading

manuelkamp commented Nov 26, 2021 •

edited

Loading

DrMichael commented Nov 28, 2021 •

edited

Loading

manuelkamp commented Nov 28, 2021 •

edited

Loading

manuelkamp commented Nov 29, 2021 •

edited

Loading

manuelkamp commented Nov 29, 2021 •

edited

Loading

manuelkamp commented Nov 29, 2021 •

edited

Loading

manuelkamp commented Nov 29, 2021 •

edited

Loading

manuelkamp commented Nov 30, 2021 •

edited

Loading