Intermittent charges incorrectly recorded #3634

xxxarmitagexxx · 2024-01-28T05:03:40Z

Is there an existing issue for this?

I have searched the existing issues

What happened?

Our Tesla is charged at home with an EVSE with a Solar Only feature.
Consequently it can happen that the charge will stop temporarily if the sun comes down until the solar output reaches the desired 4.5kW level required by the charger.

Teslamate won't record correctly the charges in that case, only the first chunk before the charge is paused by the charger.

Here is today's use case, two charges but each with intermittent pause periods.
View from the charger app:

First Charge: 5.2kWh

Second charge: 11.5kWh upon to 80%

Tesla app view showing the cumulative daily charge of 16kWh:

Teslamate: only reporting 3.12kWh and 5.97kWh with the second charge ending at 77% rather than 80% among other inconsistencies

Expected Behavior

Expectation is for Teslamate to record the entire charges output, without as a single charge as long as the car is plugged or multiple charges if the charging is stopped while the car is plugged.

Steps To Reproduce

No response

Relevant log output

2024-01-28 03:53:56.865 car_id=1 [info] Phase correction: 2 -> 3
2024-01-28 03:53:56.869 car_id=1 [info] Derived efficiency factor: 158.0 Wh/km (14x confirmed)
2024-01-28 03:53:56.869 car_id=1 [info] Charging / Stopped / 5.97 kWh – 47 min
2024-01-28 03:53:56.870 car_id=1 [info] Start / :online
2024-01-28 03:53:56.874 car_id=1 [info] Connecting ...
2024-01-28 03:54:01.876 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:01.876 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:01.877 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:01.877 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:01.877 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:01.877 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:01.877 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:01.877 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:01.877 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:01.877 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:06.376 [error] GenServer TeslaMate.Mqtt.Publisher terminating
** (WithClauseError) no with clause matching: {:error, :timeout}
    (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
    (teslamate 1.28.2) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
    (stdlib 5.1.1) gen_server.erl:1113: :gen_server.try_handle_call/4
    (stdlib 5.1.1) gen_server.erl:1142: :gen_server.handle_msg/6
    (stdlib 5.1.1) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
Last message (from #PID<0.1249662.0>): {:publish, "teslamate/cars/1/est_battery_range_km", "403.58", [retain: true, qos: 1]}
2024-01-28 03:54:06.378 [error] Task #PID<0.1249647.0> started from #PID<0.1249610.0> terminating
** (stop) exited in: GenServer.call(TeslaMate.Mqtt.Publisher, {:publish, "teslamate/cars/1/scheduled_charging_start_time", "", [retain: true, qos: 1]}, 10000)
    ** (EXIT) an exception was raised:
        ** (WithClauseError) no with clause matching: {:error, :timeout}
            (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
            (teslamate 1.28.2) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
            (stdlib 5.1.1) gen_server.erl:1113: :gen_server.try_handle_call/4
            (stdlib 5.1.1) gen_server.erl:1142: :gen_server.handle_msg/6
            (stdlib 5.1.1) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
    (elixir 1.15.7) lib/gen_server.ex:1074: GenServer.call/3
    (elixir 1.15.7) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
    (elixir 1.15.7) lib/task/supervised.ex:36: Task.Supervised.reply/4
Function: &:erlang.apply/2
    Args: [#Function<4.102219062/1 in TeslaMate.Mqtt.PubSub.VehicleSubscriber.handle_info/2>, [scheduled_charging_start_time: nil]]
2024-01-28 03:54:32.575 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:32.575 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:32.576 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:32.576 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:32.576 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:32.576 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:32.577 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:32.577 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:32.577 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:32.577 [warning] MQTT publishing failed: :timeout
2024-01-28 03:54:37.076 [error] GenServer TeslaMate.Mqtt.Publisher terminating
** (WithClauseError) no with clause matching: {:error, :timeout}
    (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
    (teslamate 1.28.2) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
    (stdlib 5.1.1) gen_server.erl:1113: :gen_server.try_handle_call/4
    (stdlib 5.1.1) gen_server.erl:1142: :gen_server.handle_msg/6
    (stdlib 5.1.1) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
Last message (from #PID<0.1249702.0>): {:publish, "teslamate/cars/1/est_battery_range_km", "403.58", [retain: true, qos: 1]}
2024-01-28 03:54:37.078 [error] Task #PID<0.1249728.0> started from #PID<0.1249722.0> terminating
** (stop) exited in: GenServer.call(TeslaMate.Mqtt.Publisher, {:publish, "teslamate/cars/1/display_name", "Bluey", [retain: true, qos: 1]}, 10000)
    ** (EXIT) an exception was raised:
        ** (WithClauseError) no with clause matching: {:error, :timeout}
            (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
            (teslamate 1.28.2) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
            (stdlib 5.1.1) gen_server.erl:1113: :gen_server.try_handle_call/4
            (stdlib 5.1.1) gen_server.erl:1142: :gen_server.handle_msg/6
            (stdlib 5.1.1) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
    (elixir 1.15.7) lib/gen_server.ex:1074: GenServer.call/3
    (elixir 1.15.7) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
    (elixir 1.15.7) lib/task/supervised.ex:36: Task.Supervised.reply/4
Function: &:erlang.apply/2
    Args: [#Function<4.102219062/1 in TeslaMate.Mqtt.PubSub.VehicleSubscriber.handle_info/2>, [display_name: "Bluey"]]
2024-01-28 03:54:37.078 [error] Task #PID<0.1249712.0> started from #PID<0.1249722.0> terminating
** (stop) exited in: GenServer.call(TeslaMate.Mqtt.Publisher, {:publish, "teslamate/cars/1/heading", "189", [retain: true, qos: 1]}, 10000)
    ** (EXIT) an exception was raised:
        ** (WithClauseError) no with clause matching: {:error, :timeout}
            (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
            (teslamate 1.28.2) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
            (stdlib 5.1.1) gen_server.erl:1113: :gen_server.try_handle_call/4
            (stdlib 5.1.1) gen_server.erl:1142: :gen_server.handle_msg/6
            (stdlib 5.1.1) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
    (elixir 1.15.7) lib/gen_server.ex:1074: GenServer.call/3
    (elixir 1.15.7) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
    (elixir 1.15.7) lib/task/supervised.ex:36: Task.Supervised.reply/4
Function: &:erlang.apply/2
    Args: [#Function<4.102219062/1 in TeslaMate.Mqtt.PubSub.VehicleSubscriber.handle_info/2>, [heading: 189]]
2024-01-28 03:54:37.078 [error] Task #PID<0.1249726.0> started from #PID<0.1249722.0> terminating
** (stop) exited in: GenServer.call(TeslaMate.Mqtt.Publisher, {:publish, "teslamate/cars/1/healthy", "true", [retain: true, qos: 1]}, 10000)
    ** (EXIT) an exception was raised:
        ** (WithClauseError) no with clause matching: {:error, :timeout}
            (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
            (teslamate 1.28.2) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
            (stdlib 5.1.1) gen_server.erl:1113: :gen_server.try_handle_call/4
            (stdlib 5.1.1) gen_server.erl:1142: :gen_server.handle_msg/6
            (stdlib 5.1.1) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
    (elixir 1.15.7) lib/gen_server.ex:1074: GenServer.call/3
    (elixir 1.15.7) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
    (elixir 1.15.7) lib/task/supervised.ex:36: Task.Supervised.reply/4
Function: &:erlang.apply/2
    Args: [#Function<4.102219062/1 in TeslaMate.Mqtt.PubSub.VehicleSubscriber.handle_info/2>, [healthy: true]]
2024-01-28 03:54:37.079 [error] Task #PID<0.1249731.0> started from #PID<0.1249722.0> terminating
** (stop) exited in: GenServer.call(TeslaMate.Mqtt.Publisher, {:publish, "teslamate/cars/1/sentry_mode", "false", [retain: true, qos: 1]}, 10000)
    ** (EXIT) an exception was raised:
        ** (WithClauseError) no with clause matching: {:error, :timeout}
            (tortoise 0.10.0) lib/tortoise.ex:269: Tortoise.publish/4
            (teslamate 1.28.2) lib/teslamate/mqtt/publisher.ex:41: TeslaMate.Mqtt.Publisher.handle_call/3
            (stdlib 5.1.1) gen_server.erl:1113: :gen_server.try_handle_call/4
            (stdlib 5.1.1) gen_server.erl:1142: :gen_server.handle_msg/6
            (stdlib 5.1.1) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
    (elixir 1.15.7) lib/gen_server.ex:1074: GenServer.call/3
    (elixir 1.15.7) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
    (elixir 1.15.7) lib/task/supervised.ex:36: Task.Supervised.reply/4
Function: &:erlang.apply/2
    Args: [#Function<4.102219062/1 in TeslaMate.Mqtt.PubSub.VehicleSubscriber.handle_info/2>, [sentry_mode: false]]

Screenshots

No response

Additional data

No response

Type of installation

Docker

Version

v1.28.2

dyxyl · 2024-01-29T23:18:05Z

Can you post the rest of the log from 28th Jan? I think the part you posted doesn't show the time when charging should have started again (I assume your time is currently UTC+11 and the time in the log is UTC).

xxxarmitagexxx · 2024-01-29T23:46:32Z

Hi,

Yes the logs timestamps are in UTC while Teslamate is set as UTC+11.

Please find attached the logs starting on the 27th 1pm UTC up until 28th 1pm UTC which should encapsulate both charges

teslamate.log

xxxarmitagexxx · 2024-01-30T03:00:05Z

While yesterday charge lined up well between the charger data and Teslamate, today's charge is missing 20+ minutes at the start in Teslamate and is thus under reported:

teslamate_30.log

The Tesla app is correctly reporting 9kWh similar to the charger.

Any idea what's causing the erratic behavior as the charge reporting cannot be trusted as it stands ?
This time the charge once started was continuous unlike the prior examples.

wooter · 2024-01-30T08:26:09Z

Intermitted charging and driving logging is possibly related to a change in the API endpoint, see #3629. However, your charging durations are longer as "typical" for this issue, see #3635.

A fix for the API endpoint change in the works, #3630.

dyxyl · 2024-01-30T11:34:35Z

It looks like communication errors between the car and Tesla:

2024-01-30 00:39:50.107 [warning] GET https://owner-api.teslamotors.com/api/1/vehicles/.../vehicle_data -> 540 (2975.551 ms)
2024-01-30 00:39:50.107 [warning] TeslaApi.Error / vehicle error: it is online but not responsive
2024-01-30 00:39:50.107 car_id=1 [error] Error / :unknown
2024-01-30 00:40:10.617 car_id=1 [info] Suspending logging
2024-01-30 00:40:32.921 [warning] Too many disconnects from streaming API

I think the vehicle error: it is online but not responsive comes from the Tesla server.

Maybe a weak WiFi signal where the car is parked?

xxxarmitagexxx · 2024-01-30T11:37:31Z

The car is connected to a dedicated AP in the garage less than 5 meters from it so I don't the wi-fi strength would be the issue.

…

On Tue, 30 Jan 2024, 10:34 pm dyxyl, ***@***.***> wrote: It looks like communication errors between the car and Tesla: 2024-01-30 00:39:50.107 [warning] GET https://owner-api.teslamotors.com/api/1/vehicles/.../vehicle_data -> 540 (2975.551 ms) 2024-01-30 00:39:50.107 [warning] TeslaApi.Error / vehicle error: it is online but not responsive 2024-01-30 00:39:50.107 car_id=1 [error] Error / :unknown 2024-01-30 00:40:10.617 car_id=1 [info] Suspending logging 2024-01-30 00:40:32.921 [warning] Too many disconnects from streaming API I think the vehicle error: it is online but not responsive comes from the Tesla server. Maybe a weak WiFi signal where the car is parked? — Reply to this email directly, view it on GitHub <#3634 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AWS2JM4FGRTMOPPNUROHT33YRDLFNAVCNFSM6AAAAABCN4OD6SVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSMJWGY2TCMBQHE> . You are receiving this because you authored the thread.Message ID: ***@***.***>

dyxyl · 2024-01-30T11:46:29Z

While they aren't related to the car, are the large number of MQTT timeouts expected?

xxxarmitagexxx · 2024-01-30T19:24:42Z

I was wondering that as well. I am using the same mosquito broker as my home assistant instance and can't say I ever had any issue on that end.

…

On Tue, 30 Jan 2024, 10:46 pm dyxyl, ***@***.***> wrote: While they aren't related to the car, are the large number of MQTT timeouts expected? — Reply to this email directly, view it on GitHub <#3634 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AWS2JM22ZVDIAUV4EFOYMVLYRDMR7AVCNFSM6AAAAABCN4OD6SVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSMJWGY3DQOJQHA> . You are receiving this because you authored the thread.Message ID: ***@***.***>

JakobLichterfeld · 2024-02-03T13:02:46Z

TeslaMate wait for the car to fall asleep when the charge has stopped, and thus can be still in the state of waiting for sleep when you start charging again. This can only be prevented when forcing the car to be awake, or resume TeslaMate logging before start the charge again.

github-actions · 2024-03-05T01:08:38Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 7 days if no further activity occurs. Thank you for your contributions.

micves · 2024-03-05T15:12:08Z

TeslaMate wait for the car to fall asleep when the charge has stopped, and thus can be still in the state of waiting for sleep when you start charging again. This can only be prevented when forcing the car to be awake, or resume TeslaMate logging before start the charge again.

If streaming is enabled it should automatically start logging again on its own:

teslamate/lib/teslamate/vehicles/vehicle.ex

Lines 484 to 487 in 3ecd857

    
           %Stream.Data{shift_state: s, power: power} 
        
           when s in [nil, "P"] and is_number(power) and power < 0 -> 
        
             Logger.info("Charging detected: #{power} kW", car_id: data.car.id) 
        
             {:next_state, prev_state, data, schedule_fetch(0, data)}

xxxarmitagexxx · 2024-03-05T21:28:38Z

Streaming is enabled on my setup. Usually the start of a charge would be missing if the charge won't start soon after plugging the car in (as dependent on a solar export threshold).

…

On Wed, 6 Mar 2024, 2:12 am Michael Vestergaard, ***@***.***> wrote: TeslaMate wait for the car to fall asleep when the charge has stopped, and thus can be still in the state of waiting for sleep when you start charging again. This can only be prevented when forcing the car to be awake, or resume TeslaMate logging before start the charge again. If streaming is enabled it should automatically start logging again on its own: https://github.com/teslamate-org/teslamate/blob/3ecd85736adf9bc8dad933aa47dcff80a3e1fafe/lib/teslamate/vehicles/vehicle.ex#L484-L487 — Reply to this email directly, view it on GitHub <#3634 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AWS2JMZXOMYN636S5UO5ITTYWXOFNAVCNFSM6AAAAABCN4OD6SVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSNZYHE4TQOBSHE> . You are receiving this because you authored the thread.Message ID: ***@***.***>

micves · 2024-03-08T07:50:14Z

Maybe you have streaming connection problems when the charge start, which of course would make it not detect the charge.

Maybe the MQTT errors also causes issues. In the log it only seems to be [error] GenServer TeslaMate.Mqtt.Publisher terminating, but it could still mess up the rest of the system.

If you have an interface to the charger, it could help to wake up teslamate, similar to this:
#3701

xxxarmitagexxx · 2024-03-08T08:14:06Z

I have solved the MQTT error since sharing the logs, it was an issue with the docker network configuation. My guess is that if the start of the charge is too much delayed due to insufficient solar export, the car would be attempting to sleep or potentially being asleep. Same things when the charge drops in the middle. Last few days, with a consistent solar output and above minimum threshold soon after plugging it in, teslamate captured the whole charges. Thanks for the link, I will take a look. I have the charger integrated in Home Assistant.

…

On Fri, 8 Mar 2024, 6:50 pm Michael Vestergaard, ***@***.***> wrote: Maybe you have streaming connection problems when the charge start, which of course would make it not detect the charge. Maybe the MQTT errors also causes issues. In the log it only seems to be [error] GenServer TeslaMate.Mqtt.Publisher terminating, but it could still mess up the rest of the system. If you have an interface to the charger, it could help to wake up teslamate, similar to this: #3701 <#3701> — Reply to this email directly, view it on GitHub <#3634 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AWS2JM75HCD46O74UUHSGMTYXFUUXAVCNFSM6AAAAABCN4OD6SVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSOBVGIYDSMRTGQ> . You are receiving this because you authored the thread.Message ID: ***@***.***>

github-actions · 2024-04-08T01:08:50Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 7 days if no further activity occurs. Thank you for your contributions.

JakobLichterfeld added undetermined Not sure if this is considered a real bug note:more information needed The reporter has to provide more information labels Feb 1, 2024

github-actions bot added the Stale label Mar 5, 2024

github-actions bot removed the Stale label Mar 6, 2024

github-actions bot added the Stale label Apr 8, 2024

github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Apr 15, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Intermittent charges incorrectly recorded #3634

Intermittent charges incorrectly recorded #3634

xxxarmitagexxx commented Jan 28, 2024

dyxyl commented Jan 29, 2024

xxxarmitagexxx commented Jan 29, 2024

xxxarmitagexxx commented Jan 30, 2024

wooter commented Jan 30, 2024

dyxyl commented Jan 30, 2024

xxxarmitagexxx commented Jan 30, 2024 via email

dyxyl commented Jan 30, 2024

xxxarmitagexxx commented Jan 30, 2024 via email

JakobLichterfeld commented Feb 3, 2024

github-actions bot commented Mar 5, 2024

micves commented Mar 5, 2024

xxxarmitagexxx commented Mar 5, 2024 via email

micves commented Mar 8, 2024

xxxarmitagexxx commented Mar 8, 2024 via email

github-actions bot commented Apr 8, 2024

Intermittent charges incorrectly recorded #3634

Intermittent charges incorrectly recorded #3634

Comments

xxxarmitagexxx commented Jan 28, 2024

Is there an existing issue for this?

What happened?

Expected Behavior

Steps To Reproduce

Relevant log output

Screenshots

Additional data

Type of installation

Version

dyxyl commented Jan 29, 2024

xxxarmitagexxx commented Jan 29, 2024

xxxarmitagexxx commented Jan 30, 2024

wooter commented Jan 30, 2024

dyxyl commented Jan 30, 2024

xxxarmitagexxx commented Jan 30, 2024 via email

dyxyl commented Jan 30, 2024

xxxarmitagexxx commented Jan 30, 2024 via email

JakobLichterfeld commented Feb 3, 2024

github-actions bot commented Mar 5, 2024

micves commented Mar 5, 2024

xxxarmitagexxx commented Mar 5, 2024 via email

micves commented Mar 8, 2024

xxxarmitagexxx commented Mar 8, 2024 via email

github-actions bot commented Apr 8, 2024