search

wimaha / TeslaBleHttpProxy

TeslaBleHttpProxy is a program written in Go that receives HTTP requests and forwards them via Bluetooth to a Tesla vehicle. The program can, for example, be easily used together with evcc.
Apache License 2.0
28 stars 5 forks source link

Should throw an error when no BLE command is sent after a request is received ? #6

Closed FraBoCH closed 1 month ago

FraBoCH commented 3 months ago

I’m using your proxy with evcc, within in a custom charger and it’s working quite good. Today I observed some strange behavior with current not being adjusted and charge not stopping. When looking at the log, I saw the requests received, but nothing happening and no error:

2024/06/16 14:56:53 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:5] 2024/06/16 14:58:23 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:4] 2024/06/16 14:58:53 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:3] 2024/06/16 14:59:23 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:2] 2024/06/16 15:01:24 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:3] 2024/06/16 15:01:24 received command "charge_start" (VIN: MYMODELY) with body: map[] 2024/06/16 15:01:53 received command "wake_up" (VIN: MYMODELY) with body: map[] 2024/06/16 15:02:23 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:5] 2024/06/16 15:03:53 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:3] 2024/06/16 15:04:23 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:1] 2024/06/16 15:06:53 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:2] 2024/06/16 15:07:23 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:3] 2024/06/16 15:07:53 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:4] 2024/06/16 15:08:23 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:2] 2024/06/16 15:08:53 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:1] 2024/06/16 15:11:03 received command "charge_stop" (VIN: MYMODELY) with body: map[] 2024/06/16 15:14:53 received command "charge_stop" (VIN: MYMODELY) with body: map[] 2024/06/16 15:18:23 received command "charge_stop" (VIN: MYMODELY) with body: map[]

After restarting the container, everything started to work as expected again:

2024/06/16 16:11:50 TeslaBleHttpProxy is loading ... 2024/06/16 16:11:50 TeslaBleHttpProxy is running! 2024/06/16 16:12:27 received command "charge_stop" (VIN: MYMODELY) with body: map[] 2024/06/16 16:12:27 handle command: charge_stop (VIN: MYMODELY) 2024/06/16 16:12:27 Connecting to vehicle... 2024/06/16 16:12:29 sending command "charge_stop"... 2024/06/16 16:12:30 The command "charge_stop" was successfully executed.

Going back in the log I observed there has been some errors before and then at some point it seems the just give up trying to send BLE command until the restart.

2024/06/16 11:34:37 retrying in 6 seconds 2024/06/16 11:34:43 Connecting to vehicle... 2024/06/16 11:34:53 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:7] 2024/06/16 11:34:53 stop retrying after 3 attempts 2024/06/16 11:34:53 The command "set_charging_amps" was canceled: 2024/06/16 11:34:53 [Error]failed to connect to vehicle (A): failed to find BLE beacon for MYMODELY (S67a76e989a933054C): can't scan: context deadline exceeded 2024/06/16 11:34:54 handle command: set_charging_amps (VIN: MYMODELY) 2024/06/16 11:34:54 Connecting to vehicle... 2024/06/16 11:35:23 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:8] 2024/06/16 11:35:53 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:7] 2024/06/16 11:42:53 received command "set_charging_amps" (VIN: MYMODELY) with body: map[charging_amps:6]

Do you understand this behavior ? Instead of stopping to send BLE command, shouldn’t error be thrown for every command (and reported to evcc) ? Would it be possible to detect this special state and automatically restart the container ?

Let me know if you know if you need more information or test, I’ll be happy to help!

wimaha commented 3 months ago

Thank you for the detailed description. This behavior should not be possible. I will try to add some more debug logs next week, so we can locate the problem.

gauner1986 commented 3 months ago

I'm having the same issue. After a while (usually an hour or two) commands are being received but not executed anymore. If the proxy is restarted everything works again.

Can I enable some logging that could help in this case?

body=map[] 2024/06/29 16:51:24 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 16:51:49 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4] 2024/06/29 16:55:05 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 16:55:21 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 16:55:49 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 16:56:05 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 16:56:30 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 16:56:44 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2] 2024/06/29 16:57:04 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 16:57:29 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 16:57:55 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 16:58:22 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2] 2024/06/29 16:58:34 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 16:59:19 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4] 2024/06/29 16:59:29 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 16:59:44 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4] 2024/06/29 17:03:54 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 17:06:14 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 17:06:34 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 17:32:59 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 17:33:19 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 17:34:59 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 17:35:29 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2] 2024/06/29 17:35:59 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 17:36:29 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 17:36:54 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2] 2024/06/29 17:37:09 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 17:41:49 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2] 2024/06/29 17:42:19 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3] 2024/06/29 17:43:39 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2] 2024/06/29 17:53:49 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2] 2024/06/29 17:56:14 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2] 2024/06/29 18:08:30 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 18:08:59 INFO received command command=charge_stop VIN= body=map[] 2024/06/29 18:09:22 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2] 2024/06/29 18:09:47 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2] 2024/06/29 18:23:42 INFO received command command=charge_stop VIN= body=map[]

wimaha commented 3 months ago

Can you please set the environment variable logLevel to debug and post the log of when this happens? I wasn’t able to reproduce this.

FraBoCH commented 3 months ago

@gauner1986, are you calling the ble proxy from a custom vehicle or a custom charger in evcc ? The reason I’m asking that is that I had this issue when using it at the charger level, and after charging a non-Tesla vehicle on my TWC3. Since I switched to using the ble proxy at the vehicle level for, I didn’t experience the issue. So it may be the accumulation of errors when trying to send commands to the no-connected vehicle that may lead to this weird state. In other words, can you provide more information on the context in which you are using the ble proxy ? This could help, in addition to more detail logs, to find the root cause of that.

gauner1986 commented 3 months ago

I have bumped the log level to debug and am hoping for a sunny day in the next time.

I'm actually not using EVCC at all. I have my own automations in home assistant which do my solar excess charging. My charger (Easee home) does not support going below 6A single phase that's why I don't use it for controlling charging speed during solar excess charging. I only set it to single phase when I enable solar excess charging which is typically long before charging is actually started.

Excerpt of my configuration.yaml

rest_command: tesla_set_charging_amps: url: http://pi:8080/api/1/vehicles/VIN/command/set_charging_amps method: POST payload: '{"charging_amps": "{{charging_amps}}"}' content_type: 'application/json' tesla_set_charge_limit: url: http://pi:8080/api/1/vehicles/VIN/command/set_charge_limit method: POST payload: '{"percent": "{{charge_limit}}"}' content_type: 'application/json' tesla_wakeup: url: http://pi:8080/api/1/vehicles/VIN/command/wake_up method: POST tesla_charge_start: url: http://pi:8080/api/1/vehicles/VIN/command/charge_start method: POST tesla_charge_stop: url: http://pi:8080/api/1/vehicles/VIN/command/charge_stop

haroldboom commented 3 months ago

Hi @wimaha does your http proxy try and wake the vehicle after a couple of errors? I have found that EVCC does not wake the vehicle reliably so after a couple of errors on charge start/stop or set charging amps I have my script send a wake command and then retry the previous command. Could that be the issue?

gauner1986 commented 3 months ago

Usually if that happens you receive a connection error though. In our error case here there's no feedback to the received commands at all.

I had a case where it just happened in a series of events without any delays:

2024/06/28 16:24:04 INFO The command was successfully executed. command=charge_stop 2024/06/28 16:24:24 INFO received command command=charge_start VIN=VIN body=map[] 2024/06/28 16:24:24 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:2] 2024/06/28 16:24:25 INFO handle command command=charge_start VIN=VIN 2024/06/28 16:24:28 INFO The command was successfully executed. command=charge_start 2024/06/28 16:24:29 INFO handle command command=set_charging_amps VIN=VIN 2024/06/28 16:24:32 INFO The command was successfully executed. command=set_charging_amps 2024/06/28 16:24:54 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:3] 2024/06/28 16:24:55 INFO handle command command=set_charging_amps VIN=VIN 2024/06/28 16:24:58 INFO The command was successfully executed. command=set_charging_amps 2024/06/28 16:25:15 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:25:15 INFO handle command command=charge_stop VIN=VIN 2024/06/28 16:25:24 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:26:05 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:26:24 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:3] 2024/06/28 16:26:35 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:26:44 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:27:04 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:27:19 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:30:40 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:32:04 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:3] 2024/06/28 16:32:24 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:3]

My automations were not yet perfect so the series of commands doesn't make sense in the end, but there should be feedback in the logs. Charging just continued in this case.

haroldboom commented 3 months ago

Are you using on board ble or a dongle? I had a dongle that would crash until I rebooted but that’s probably not your issue because that gave errors

On Tue, 2 Jul 2024 at 08:27, gauner1986 @.***> wrote:

Usually if that happens you receive a connection error though. In our error case here there's no feedback to the received commands at all.

I had a case where it just happened in a series of events without any delays:

2024/06/28 16:24:04 INFO The command was successfully executed. command=charge_stop 2024/06/28 16:24:24 INFO received command command=charge_start VIN=VIN body=map[] 2024/06/28 16:24:24 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:2] 2024/06/28 16:24:25 INFO handle command command=charge_start VIN=VIN 2024/06/28 16:24:28 INFO The command was successfully executed. command=charge_start 2024/06/28 16:24:29 INFO handle command command=set_charging_amps VIN=VIN 2024/06/28 16:24:32 INFO The command was successfully executed. command=set_charging_amps 2024/06/28 16:24:54 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:3] 2024/06/28 16:24:55 INFO handle command command=set_charging_amps VIN=VIN 2024/06/28 16:24:58 INFO The command was successfully executed. command=set_charging_amps 2024/06/28 16:25:15 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:25:15 INFO handle command command=charge_stop VIN=VIN 2024/06/28 16:25:24 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:26:05 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:26:24 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:3] 2024/06/28 16:26:35 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:26:44 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:27:04 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:27:19 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:30:40 INFO received command command=charge_stop VIN=VIN body=map[] 2024/06/28 16:32:04 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:3] 2024/06/28 16:32:24 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:3]

— Reply to this email directly, view it on GitHub https://github.com/wimaha/TeslaBleHttpProxy/issues/6#issuecomment-2201200666, or unsubscribe https://github.com/notifications/unsubscribe-auth/AKH2FP3GXU4BLG6PDHAJEQTZKHJUJAVCNFSM6AAAAABJMWDSZ6VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEMBRGIYDANRWGY . You are receiving this because you commented.Message ID: @.***>

gauner1986 commented 3 months ago

I'm using a raspberry pi 1 with a USB dongle.

haroldboom commented 3 months ago

Check dmesg for an issues in there. I found that my UB400 worked fine but my UB500 would crash on raspian. On Ubuntu on a pi zero 2 w the UB500 worked fine

On Tue, 2 Jul 2024 at 09:00, gauner1986 @.***> wrote:

I'm using a raspberry pi 1 with a USB dongle.

— Reply to this email directly, view it on GitHub https://github.com/wimaha/TeslaBleHttpProxy/issues/6#issuecomment-2201325408, or unsubscribe https://github.com/notifications/unsubscribe-auth/AKH2FPZCD4TPB2CT4RQ6ISTZKHNRBAVCNFSM6AAAAABJMWDSZ6VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEMBRGMZDKNBQHA . You are receiving this because you commented.Message ID: @.***>

gauner1986 commented 3 months ago

Will do. Though last time I had the problem it was enough to simply restart the proxy.

wimaha commented 3 months ago

There are no unhandled errors in the program. So maybe the problem is in the ble package itself. It seems the handle loop is blocked without return or error. Maybe we can find the error with debug log.

wimaha commented 3 months ago

Hi @wimaha does your http proxy try and wake the vehicle after a couple of errors? I have found that EVCC does not wake the vehicle reliably so after a couple of errors on charge start/stop or set charging amps I have my script send a wake command and then retry the previous command. Could that be the issue?

The proxy automatically wakes the vehicle when it is sleeping. So this is not the problem here.

svwhisper commented 2 months ago

I have the same issue on a Raspberry pi Zero W. When charging, I hit the proxy every 15 seconds with a "set_charging_amps" command. After several hours, I see repeated "received command", but the commands are not sent to the car, nor is there any other error or informational message.

wimaha commented 2 months ago

Any Debug Logs?

wimaha commented 2 months ago

I've created a new version with the following improvements that might solve this problem:

The version is under the dev tag on Docker: image: wimaha/tesla-ble-http-proxy:dev

Could you please test this version? Thank you!

Edit: Please also use debug mode:

environment:
      logLevel: debug
gauner1986 commented 2 months ago

Couldn't test a lot in the past few days because of very bad weather in Hamburg.

I'm building myself and running without docker due to system constraints. Did you commit in a special branch?

wimaha commented 2 months ago

Yes, you will find it in the branch refactor/performance-optimization: https://github.com/wimaha/TeslaBleHttpProxy/tree/refactor/performance-optimization

svwhisper commented 2 months ago

Any Debug Logs?

I am now running your "refactor" version, with debug set. I'll share my experience and the logs, should the issue reoccur.

svwhisper commented 2 months ago

Interesting behaviour... I notice that when the proxy throws this error, my car goes to zero amps (as shown on the app and in my energy monitor) and then quickly climbs back up to the target. When I kill the proxy, the odd behaviour goes away.

The odd behaviour doesn't happen every time I see this error, but whenever actual charge rate goes to zero, the error was thrown seconds prior.

Thoughts?

2024/07/07 12:31:46 INFO TeslaBleHttpProxy is loading ... 2024/07/07 12:31:46 DEBU LogLevel set to debug 2024/07/07 12:31:46 INFO TeslaBleHttpProxy is running! 2024/07/07 12:32:04 INFO received command command=set_charging_amps VIN=LRWYHCEL4PC726XYZ body=map[charging_amps:23] 2024/07/07 12:32:05 INFO handle command command=set_charging_amps VIN=LRWYHCEL4PC726XYZ 2024/07/07 12:32:06 WARN failed to connect to vehicle (A): ble: failed to enumerate device services: ATT request failed: input channel closed: io: read/write on closed pipe 2024/07/07 12:32:06 INFO retrying in 3 seconds 2024/07/07 12:32:10 WARN failed to connect to vehicle (A): ble: failed to enumerate device services: ATT request failed: input channel closed: io: read/write on closed pipe 2024/07/07 12:32:10 INFO retrying in 6 seconds 2024/07/07 12:32:19 INFO The command was successfully executed. command=set_charging_amps

gauner1986 commented 2 months ago

It happened again today. This time with debug logs enabled. I'm on 89dba612b2b71a91639b3cc8dee4397979626455. On restart everything went back to normal. This time it seemed to happen after the vehicle was temporarily not available..

2024/07/07 14:45:43 INFO received command command=charge_start VIN= body=map[]
2024/07/07 14:45:43 INFO connectToVehicle ...
2024/07/07 14:45:43 DEBU trying connecting to vehicle attempt=1
2024/07/07 14:45:43 DEBU Connecting to vehicle (A)...
2024/07/07 14:45:44 DEBU Create vehicle object ...
2024/07/07 14:45:44 DEBU Connecting to vehicle (B)...
2024/07/07 14:45:44 DEBU start VCSEC session...
2024/07/07 14:45:45 DEBU car successfully wakeup
2024/07/07 14:45:45 DEBU start Infotainment session...
2024/07/07 14:45:58 DEBU Disconnect vehicle (B)
2024/07/07 14:45:58 DEBU Close connection (B)
2024/07/07 14:45:58 WARN failed to perform handshake with vehicle (B): context deadline exceeded
2024/07/07 14:45:58 INFO retrying in 3 seconds
2024/07/07 14:46:01 DEBU trying connecting to vehicle attempt=2
2024/07/07 14:46:01 DEBU Connecting to vehicle (A)...
2024/07/07 14:46:02 DEBU Create vehicle object ...
2024/07/07 14:46:02 DEBU Connecting to vehicle (B)...
2024/07/07 14:46:02 DEBU start VCSEC session...
2024/07/07 14:46:03 DEBU car successfully wakeup
2024/07/07 14:46:03 DEBU start Infotainment session...
2024/07/07 14:46:04 INFO Session started
2024/07/07 14:46:04 DEBU sending command ... command=charge_start
2024/07/07 14:46:05 INFO received command command=charge_start VIN= body=map[]
2024/07/07 14:46:05 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 14:46:05 INFO The command was successfully executed. command=charge_start
2024/07/07 14:46:05 DEBU sending command ... command=charge_start
2024/07/07 14:46:06 INFO the car is already charging
2024/07/07 14:46:06 INFO The command was successfully executed. command=charge_start
2024/07/07 14:46:06 DEBU sending command ... command=set_charging_amps
2024/07/07 14:46:07 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:46:30 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 14:46:30 DEBU sending command ... command=set_charging_amps
2024/07/07 14:46:31 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:46:34 DEBU Connection Timeout
2024/07/07 14:46:34 DEBU Disconnect vehicle (A)
2024/07/07 14:46:34 DEBU Close connection (A)
2024/07/07 14:46:45 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 14:46:45 INFO connectToVehicle ...
2024/07/07 14:46:45 DEBU trying connecting to vehicle attempt=1
2024/07/07 14:46:45 DEBU Connecting to vehicle (A)...
2024/07/07 14:46:45 DEBU Create vehicle object ...
2024/07/07 14:46:45 DEBU Connecting to vehicle (B)...
2024/07/07 14:46:45 DEBU start VCSEC session...
2024/07/07 14:46:47 DEBU car successfully wakeup
2024/07/07 14:46:47 DEBU start Infotainment session...
2024/07/07 14:46:48 INFO Session started
2024/07/07 14:46:48 DEBU sending command ... command=charge_stop
2024/07/07 14:46:49 INFO The command was successfully executed. command=charge_stop
2024/07/07 14:47:18 DEBU Connection Timeout
2024/07/07 14:47:18 DEBU Disconnect vehicle (A)
2024/07/07 14:47:18 DEBU Close connection (A)
2024/07/07 14:52:20 INFO received command command=charge_start VIN= body=map[]
2024/07/07 14:52:20 INFO connectToVehicle ...
2024/07/07 14:52:20 DEBU trying connecting to vehicle attempt=1
2024/07/07 14:52:20 DEBU Connecting to vehicle (A)...
2024/07/07 14:52:20 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 14:52:20 DEBU Create vehicle object ...
2024/07/07 14:52:20 DEBU Connecting to vehicle (B)...
2024/07/07 14:52:20 DEBU start VCSEC session...
2024/07/07 14:52:21 DEBU car successfully wakeup
2024/07/07 14:52:21 DEBU start Infotainment session...
2024/07/07 14:52:23 INFO Session started
2024/07/07 14:52:23 DEBU sending command ... command=charge_start
2024/07/07 14:52:24 INFO The command was successfully executed. command=charge_start
2024/07/07 14:52:24 DEBU sending command ... command=set_charging_amps
2024/07/07 14:52:25 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:52:51 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 14:52:51 DEBU sending command ... command=set_charging_amps
2024/07/07 14:52:51 DEBU Disconnect vehicle (A)
2024/07/07 14:52:51 DEBU Close connection (A)
2024/07/07 14:52:52 INFO connectToVehicle ...
2024/07/07 14:52:52 DEBU trying connecting to vehicle attempt=1
2024/07/07 14:52:52 DEBU Connecting to vehicle (A)...
2024/07/07 14:52:53 DEBU Create vehicle object ...
2024/07/07 14:52:53 DEBU Connecting to vehicle (B)...
2024/07/07 14:52:53 DEBU start VCSEC session...
2024/07/07 14:52:54 DEBU car successfully wakeup
2024/07/07 14:52:54 DEBU start Infotainment session...
2024/07/07 14:52:55 INFO Session started
2024/07/07 14:52:55 DEBU sending command ... command=set_charging_amps
2024/07/07 14:52:56 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:53:25 DEBU Connection Timeout
2024/07/07 14:53:25 DEBU Disconnect vehicle (A)
2024/07/07 14:53:25 DEBU Close connection (A)
2024/07/07 14:53:50 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 14:53:50 INFO connectToVehicle ...
2024/07/07 14:53:50 DEBU trying connecting to vehicle attempt=1
2024/07/07 14:53:50 DEBU Connecting to vehicle (A)...
2024/07/07 14:53:50 DEBU Create vehicle object ...
2024/07/07 14:53:50 DEBU Connecting to vehicle (B)...
2024/07/07 14:53:50 DEBU start VCSEC session...
2024/07/07 14:53:52 DEBU car successfully wakeup
2024/07/07 14:53:52 DEBU start Infotainment session...
2024/07/07 14:53:53 INFO Session started
2024/07/07 14:53:53 DEBU sending command ... command=charge_stop
2024/07/07 14:53:54 INFO The command was successfully executed. command=charge_stop
2024/07/07 14:54:19 INFO received command command=charge_start VIN= body=map[]
2024/07/07 14:54:19 DEBU sending command ... command=charge_start
2024/07/07 14:54:19 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2]
2024/07/07 14:54:29 WARN failed to start charge: context deadline exceeded
2024/07/07 14:54:29 INFO retrying in 3 seconds
2024/07/07 14:54:32 WARN failed to start charge: context deadline exceeded
2024/07/07 14:54:32 INFO retrying in 6 seconds
2024/07/07 14:54:38 DEBU Disconnect vehicle (A)
2024/07/07 14:54:38 DEBU Close connection (A)
2024/07/07 14:54:39 INFO connectToVehicle ...
2024/07/07 14:54:39 DEBU trying connecting to vehicle attempt=1
2024/07/07 14:54:39 DEBU Connecting to vehicle (A)...
2024/07/07 14:54:40 DEBU Create vehicle object ...
2024/07/07 14:54:40 DEBU Connecting to vehicle (B)...
2024/07/07 14:54:40 DEBU start VCSEC session...
2024/07/07 14:54:41 DEBU car successfully wakeup
2024/07/07 14:54:41 DEBU start Infotainment session...
2024/07/07 14:54:42 INFO Session started
2024/07/07 14:54:42 DEBU sending command ... command=charge_start
2024/07/07 14:54:43 INFO the car is already charging
2024/07/07 14:54:43 INFO The command was successfully executed. command=charge_start
2024/07/07 14:54:43 DEBU sending command ... command=set_charging_amps
2024/07/07 14:54:44 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:55:01 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 14:55:01 DEBU sending command ... command=charge_stop
2024/07/07 14:55:02 INFO The command was successfully executed. command=charge_stop
2024/07/07 14:55:12 DEBU Connection Timeout
2024/07/07 14:55:12 DEBU Disconnect vehicle (A)
2024/07/07 14:55:12 DEBU Close connection (A)
2024/07/07 14:55:40 INFO received command command=charge_start VIN= body=map[]
2024/07/07 14:55:40 INFO connectToVehicle ...
2024/07/07 14:55:40 DEBU trying connecting to vehicle attempt=1
2024/07/07 14:55:40 DEBU Connecting to vehicle (A)...
2024/07/07 14:55:40 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 14:55:40 DEBU Create vehicle object ...
2024/07/07 14:55:40 DEBU Connecting to vehicle (B)...
2024/07/07 14:55:40 DEBU start VCSEC session...
2024/07/07 14:55:41 DEBU car successfully wakeup
2024/07/07 14:55:41 DEBU start Infotainment session...
2024/07/07 14:55:42 INFO Session started
2024/07/07 14:55:42 DEBU sending command ... command=charge_start
2024/07/07 14:55:43 INFO The command was successfully executed. command=charge_start
2024/07/07 14:55:43 DEBU sending command ... command=set_charging_amps
2024/07/07 14:55:44 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:56:10 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 14:56:10 DEBU sending command ... command=set_charging_amps
2024/07/07 14:56:11 DEBU Disconnect vehicle (A)
2024/07/07 14:56:11 DEBU Close connection (A)
2024/07/07 14:56:12 INFO connectToVehicle ...
2024/07/07 14:56:12 DEBU trying connecting to vehicle attempt=1
2024/07/07 14:56:12 DEBU Connecting to vehicle (A)...
2024/07/07 14:56:12 DEBU Create vehicle object ...
2024/07/07 14:56:12 DEBU Connecting to vehicle (B)...
2024/07/07 14:56:12 DEBU start VCSEC session...
2024/07/07 14:56:14 DEBU car successfully wakeup
2024/07/07 14:56:14 DEBU start Infotainment session...
2024/07/07 14:56:15 INFO Session started
2024/07/07 14:56:15 DEBU sending command ... command=set_charging_amps
2024/07/07 14:56:16 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:56:30 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 14:56:30 DEBU sending command ... command=set_charging_amps
2024/07/07 14:56:31 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:56:45 DEBU Connection Timeout
2024/07/07 14:56:45 DEBU Disconnect vehicle (A)
2024/07/07 14:56:45 DEBU Close connection (A)
2024/07/07 14:58:00 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 14:58:00 INFO connectToVehicle ...
2024/07/07 14:58:00 DEBU trying connecting to vehicle attempt=1
2024/07/07 14:58:00 DEBU Connecting to vehicle (A)...
2024/07/07 14:58:01 DEBU Create vehicle object ...
2024/07/07 14:58:01 DEBU Connecting to vehicle (B)...
2024/07/07 14:58:01 DEBU start VCSEC session...
2024/07/07 14:58:02 DEBU car successfully wakeup
2024/07/07 14:58:02 DEBU start Infotainment session...
2024/07/07 14:58:03 INFO Session started
2024/07/07 14:58:03 DEBU sending command ... command=set_charging_amps
2024/07/07 14:58:05 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:58:14 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2]
2024/07/07 14:58:14 DEBU sending command ... command=set_charging_amps
2024/07/07 14:58:15 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:58:22 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 14:58:22 DEBU sending command ... command=set_charging_amps
2024/07/07 14:58:23 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:58:34 DEBU Connection Timeout
2024/07/07 14:58:34 DEBU Disconnect vehicle (A)
2024/07/07 14:58:34 DEBU Close connection (A)
2024/07/07 14:58:40 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 14:58:40 INFO connectToVehicle ...
2024/07/07 14:58:40 DEBU trying connecting to vehicle attempt=1
2024/07/07 14:58:40 DEBU Connecting to vehicle (A)...
2024/07/07 14:58:40 DEBU Create vehicle object ...
2024/07/07 14:58:40 DEBU Connecting to vehicle (B)...
2024/07/07 14:58:40 DEBU start VCSEC session...
2024/07/07 14:58:42 DEBU car successfully wakeup
2024/07/07 14:58:42 DEBU start Infotainment session...
2024/07/07 14:58:43 INFO Session started
2024/07/07 14:58:43 DEBU sending command ... command=set_charging_amps
2024/07/07 14:58:44 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:58:55 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 14:58:55 DEBU sending command ... command=set_charging_amps
2024/07/07 14:58:56 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 14:59:13 DEBU Connection Timeout
2024/07/07 14:59:13 DEBU Disconnect vehicle (A)
2024/07/07 14:59:13 DEBU Close connection (A)
2024/07/07 15:01:02 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 15:01:02 INFO connectToVehicle ...
2024/07/07 15:01:02 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:01:02 DEBU Connecting to vehicle (A)...
2024/07/07 15:01:02 DEBU Create vehicle object ...
2024/07/07 15:01:02 DEBU Connecting to vehicle (B)...
2024/07/07 15:01:02 DEBU start VCSEC session...
2024/07/07 15:01:03 DEBU car successfully wakeup
2024/07/07 15:01:03 DEBU start Infotainment session...
2024/07/07 15:01:04 INFO Session started
2024/07/07 15:01:04 DEBU sending command ... command=set_charging_amps
2024/07/07 15:01:06 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:01:19 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:01:19 DEBU sending command ... command=set_charging_amps
2024/07/07 15:01:20 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:01:30 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:01:30 DEBU sending command ... command=set_charging_amps
2024/07/07 15:01:31 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:01:35 DEBU Connection Timeout
2024/07/07 15:01:35 DEBU Disconnect vehicle (A)
2024/07/07 15:01:35 DEBU Close connection (A)
2024/07/07 15:01:40 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 15:01:40 INFO connectToVehicle ...
2024/07/07 15:01:40 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:01:40 DEBU Connecting to vehicle (A)...
2024/07/07 15:01:40 DEBU Create vehicle object ...
2024/07/07 15:01:40 DEBU Connecting to vehicle (B)...
2024/07/07 15:01:40 DEBU start VCSEC session...
2024/07/07 15:01:42 DEBU car successfully wakeup
2024/07/07 15:01:42 DEBU start Infotainment session...
2024/07/07 15:01:43 INFO Session started
2024/07/07 15:01:43 DEBU sending command ... command=set_charging_amps
2024/07/07 15:01:44 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:01:59 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:01:59 DEBU sending command ... command=set_charging_amps
2024/07/07 15:02:00 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:02:12 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:02:12 DEBU sending command ... command=set_charging_amps
2024/07/07 15:02:12 DEBU Disconnect vehicle (A)
2024/07/07 15:02:12 DEBU Close connection (A)
2024/07/07 15:02:13 INFO connectToVehicle ...
2024/07/07 15:02:13 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:02:13 DEBU Connecting to vehicle (A)...
2024/07/07 15:02:14 DEBU Create vehicle object ...
2024/07/07 15:02:14 DEBU Connecting to vehicle (B)...
2024/07/07 15:02:14 DEBU start VCSEC session...
2024/07/07 15:02:15 DEBU car successfully wakeup
2024/07/07 15:02:15 DEBU start Infotainment session...
2024/07/07 15:02:16 INFO Session started
2024/07/07 15:02:16 DEBU sending command ... command=set_charging_amps
2024/07/07 15:02:18 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:02:47 DEBU Connection Timeout
2024/07/07 15:02:47 DEBU Disconnect vehicle (A)
2024/07/07 15:02:47 DEBU Close connection (A)
2024/07/07 15:03:25 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:03:25 INFO connectToVehicle ...
2024/07/07 15:03:25 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:03:25 DEBU Connecting to vehicle (A)...
2024/07/07 15:03:26 DEBU Create vehicle object ...
2024/07/07 15:03:26 DEBU Connecting to vehicle (B)...
2024/07/07 15:03:26 DEBU start VCSEC session...
2024/07/07 15:03:27 DEBU car successfully wakeup
2024/07/07 15:03:27 DEBU start Infotainment session...
2024/07/07 15:03:28 INFO Session started
2024/07/07 15:03:28 DEBU sending command ... command=set_charging_amps
2024/07/07 15:03:29 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:03:58 DEBU Connection Timeout
2024/07/07 15:03:58 DEBU Disconnect vehicle (A)
2024/07/07 15:03:58 DEBU Close connection (A)
2024/07/07 15:04:51 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:04:51 INFO connectToVehicle ...
2024/07/07 15:04:51 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:04:51 DEBU Connecting to vehicle (A)...
2024/07/07 15:04:51 DEBU Create vehicle object ...
2024/07/07 15:04:51 DEBU Connecting to vehicle (B)...
2024/07/07 15:04:51 DEBU start VCSEC session...
2024/07/07 15:04:53 DEBU car successfully wakeup
2024/07/07 15:04:53 DEBU start Infotainment session...
2024/07/07 15:04:54 INFO Session started
2024/07/07 15:04:54 DEBU sending command ... command=set_charging_amps
2024/07/07 15:04:55 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:05:15 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 15:05:15 DEBU sending command ... command=set_charging_amps
2024/07/07 15:05:16 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:05:24 DEBU Connection Timeout
2024/07/07 15:05:24 DEBU Disconnect vehicle (A)
2024/07/07 15:05:24 DEBU Close connection (A)
2024/07/07 15:05:29 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 15:05:29 INFO connectToVehicle ...
2024/07/07 15:05:29 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:05:29 DEBU Connecting to vehicle (A)...
2024/07/07 15:05:30 DEBU Create vehicle object ...
2024/07/07 15:05:30 DEBU Connecting to vehicle (B)...
2024/07/07 15:05:30 DEBU start VCSEC session...
2024/07/07 15:05:31 DEBU car successfully wakeup
2024/07/07 15:05:31 DEBU start Infotainment session...
2024/07/07 15:05:32 INFO Session started
2024/07/07 15:05:32 DEBU sending command ... command=set_charging_amps
2024/07/07 15:05:33 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:06:02 DEBU Connection Timeout
2024/07/07 15:06:02 DEBU Disconnect vehicle (A)
2024/07/07 15:06:02 DEBU Close connection (A)
2024/07/07 15:07:39 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:07:39 INFO connectToVehicle ...
2024/07/07 15:07:39 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:07:39 DEBU Connecting to vehicle (A)...
2024/07/07 15:07:39 DEBU Create vehicle object ...
2024/07/07 15:07:39 DEBU Connecting to vehicle (B)...
2024/07/07 15:07:39 DEBU start VCSEC session...
2024/07/07 15:07:41 DEBU car successfully wakeup
2024/07/07 15:07:41 DEBU start Infotainment session...
2024/07/07 15:07:42 INFO Session started
2024/07/07 15:07:42 DEBU sending command ... command=charge_stop
2024/07/07 15:07:43 INFO The command was successfully executed. command=charge_stop
2024/07/07 15:08:12 DEBU Connection Timeout
2024/07/07 15:08:12 DEBU Disconnect vehicle (A)
2024/07/07 15:08:12 DEBU Close connection (A)
2024/07/07 15:08:15 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:08:15 INFO connectToVehicle ...
2024/07/07 15:08:15 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:08:15 DEBU Connecting to vehicle (A)...
2024/07/07 15:08:15 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2]
2024/07/07 15:08:15 DEBU Create vehicle object ...
2024/07/07 15:08:15 DEBU Connecting to vehicle (B)...
2024/07/07 15:08:15 DEBU start VCSEC session...
2024/07/07 15:08:17 DEBU car successfully wakeup
2024/07/07 15:08:17 DEBU start Infotainment session...
2024/07/07 15:08:18 INFO Session started
2024/07/07 15:08:18 DEBU sending command ... command=charge_start
2024/07/07 15:08:19 INFO The command was successfully executed. command=charge_start
2024/07/07 15:08:19 DEBU sending command ... command=set_charging_amps
2024/07/07 15:08:20 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:08:48 DEBU Connection Timeout
2024/07/07 15:08:48 DEBU Disconnect vehicle (A)
2024/07/07 15:08:48 DEBU Close connection (A)
2024/07/07 15:08:54 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:08:54 INFO connectToVehicle ...
2024/07/07 15:08:54 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:08:54 DEBU Connecting to vehicle (A)...
2024/07/07 15:08:54 DEBU Create vehicle object ...
2024/07/07 15:08:54 DEBU Connecting to vehicle (B)...
2024/07/07 15:08:54 DEBU start VCSEC session...
2024/07/07 15:08:56 DEBU car successfully wakeup
2024/07/07 15:08:56 DEBU start Infotainment session...
2024/07/07 15:08:57 INFO Session started
2024/07/07 15:08:57 DEBU sending command ... command=charge_stop
2024/07/07 15:08:58 INFO The command was successfully executed. command=charge_stop
2024/07/07 15:09:27 DEBU Connection Timeout
2024/07/07 15:09:27 DEBU Disconnect vehicle (A)
2024/07/07 15:09:27 DEBU Close connection (A)
2024/07/07 15:09:54 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:09:54 INFO connectToVehicle ...
2024/07/07 15:09:54 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:09:54 DEBU Connecting to vehicle (A)...
2024/07/07 15:09:54 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:09:55 DEBU Create vehicle object ...
2024/07/07 15:09:55 DEBU Connecting to vehicle (B)...
2024/07/07 15:09:55 DEBU start VCSEC session...
2024/07/07 15:09:56 DEBU car successfully wakeup
2024/07/07 15:09:56 DEBU start Infotainment session...
2024/07/07 15:09:57 INFO Session started
2024/07/07 15:09:57 DEBU sending command ... command=charge_start
2024/07/07 15:09:58 INFO The command was successfully executed. command=charge_start
2024/07/07 15:09:58 DEBU sending command ... command=set_charging_amps
2024/07/07 15:09:59 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:10:24 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:10:24 DEBU sending command ... command=set_charging_amps
2024/07/07 15:10:25 DEBU Disconnect vehicle (A)
2024/07/07 15:10:25 DEBU Close connection (A)
2024/07/07 15:10:26 INFO connectToVehicle ...
2024/07/07 15:10:26 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:10:26 DEBU Connecting to vehicle (A)...
2024/07/07 15:10:27 DEBU Create vehicle object ...
2024/07/07 15:10:27 DEBU Connecting to vehicle (B)...
2024/07/07 15:10:27 DEBU start VCSEC session...
2024/07/07 15:10:28 DEBU car successfully wakeup
2024/07/07 15:10:28 DEBU start Infotainment session...
2024/07/07 15:10:29 INFO Session started
2024/07/07 15:10:29 DEBU sending command ... command=set_charging_amps
2024/07/07 15:10:30 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:10:59 DEBU Connection Timeout
2024/07/07 15:10:59 DEBU Disconnect vehicle (A)
2024/07/07 15:10:59 DEBU Close connection (A)
2024/07/07 15:12:05 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 15:12:05 INFO connectToVehicle ...
2024/07/07 15:12:05 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:12:05 DEBU Connecting to vehicle (A)...
2024/07/07 15:12:05 DEBU Create vehicle object ...
2024/07/07 15:12:05 DEBU Connecting to vehicle (B)...
2024/07/07 15:12:05 DEBU start VCSEC session...
2024/07/07 15:12:07 DEBU car successfully wakeup
2024/07/07 15:12:07 DEBU start Infotainment session...
2024/07/07 15:12:08 INFO Session started
2024/07/07 15:12:08 DEBU sending command ... command=set_charging_amps
2024/07/07 15:12:09 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:12:19 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:12:19 DEBU sending command ... command=set_charging_amps
2024/07/07 15:12:20 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:12:34 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:12:34 DEBU sending command ... command=set_charging_amps
2024/07/07 15:12:44 WARN failed to set charging Amps to 4: context deadline exceeded
2024/07/07 15:12:44 INFO retrying in 3 seconds
2024/07/07 15:12:47 WARN failed to set charging Amps to 4: context deadline exceeded
2024/07/07 15:12:47 INFO retrying in 6 seconds
2024/07/07 15:12:53 ERRO The command was canceled. command=set_charging_amps err="failed to set charging Amps to 4: context deadline exceeded"
2024/07/07 15:12:53 DEBU Disconnect vehicle (A)
2024/07/07 15:12:53 DEBU Close connection (A)
2024/07/07 15:12:59 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:12:59 INFO connectToVehicle ...
2024/07/07 15:12:59 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:12:59 DEBU Connecting to vehicle (A)...
2024/07/07 15:13:00 DEBU Create vehicle object ...
2024/07/07 15:13:00 DEBU Connecting to vehicle (B)...
2024/07/07 15:13:00 DEBU start VCSEC session...
2024/07/07 15:13:01 DEBU car successfully wakeup
2024/07/07 15:13:01 DEBU start Infotainment session...
2024/07/07 15:13:02 INFO Session started
2024/07/07 15:13:02 DEBU sending command ... command=set_charging_amps
2024/07/07 15:13:03 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:13:30 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:13:30 DEBU sending command ... command=set_charging_amps
2024/07/07 15:13:31 DEBU Disconnect vehicle (A)
2024/07/07 15:13:31 DEBU Close connection (A)
2024/07/07 15:13:32 INFO connectToVehicle ...
2024/07/07 15:13:32 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:13:32 DEBU Connecting to vehicle (A)...
2024/07/07 15:13:32 DEBU Create vehicle object ...
2024/07/07 15:13:32 DEBU Connecting to vehicle (B)...
2024/07/07 15:13:32 DEBU start VCSEC session...
2024/07/07 15:13:34 DEBU car successfully wakeup
2024/07/07 15:13:34 DEBU start Infotainment session...
2024/07/07 15:13:35 INFO Session started
2024/07/07 15:13:35 DEBU sending command ... command=set_charging_amps
2024/07/07 15:13:36 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:13:50 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:13:50 DEBU sending command ... command=charge_stop
2024/07/07 15:13:51 INFO The command was successfully executed. command=charge_stop
2024/07/07 15:14:05 DEBU Connection Timeout
2024/07/07 15:14:05 DEBU Disconnect vehicle (A)
2024/07/07 15:14:05 DEBU Close connection (A)
2024/07/07 15:15:34 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:15:34 INFO connectToVehicle ...
2024/07/07 15:15:34 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:15:34 DEBU Connecting to vehicle (A)...
2024/07/07 15:15:34 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2]
2024/07/07 15:15:35 DEBU Create vehicle object ...
2024/07/07 15:15:35 DEBU Connecting to vehicle (B)...
2024/07/07 15:15:35 DEBU start VCSEC session...
2024/07/07 15:15:36 DEBU car successfully wakeup
2024/07/07 15:15:36 DEBU start Infotainment session...
2024/07/07 15:15:37 INFO Session started
2024/07/07 15:15:37 DEBU sending command ... command=charge_start
2024/07/07 15:15:38 INFO The command was successfully executed. command=charge_start
2024/07/07 15:15:38 DEBU sending command ... command=set_charging_amps
2024/07/07 15:15:39 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:16:05 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:16:05 DEBU sending command ... command=charge_stop
2024/07/07 15:16:05 DEBU Disconnect vehicle (A)
2024/07/07 15:16:05 DEBU Close connection (A)
2024/07/07 15:16:06 INFO connectToVehicle ...
2024/07/07 15:16:06 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:16:06 DEBU Connecting to vehicle (A)...
2024/07/07 15:16:07 DEBU Create vehicle object ...
2024/07/07 15:16:07 DEBU Connecting to vehicle (B)...
2024/07/07 15:16:07 DEBU start VCSEC session...
2024/07/07 15:16:08 DEBU car successfully wakeup
2024/07/07 15:16:08 DEBU start Infotainment session...
2024/07/07 15:16:09 INFO Session started
2024/07/07 15:16:09 DEBU sending command ... command=charge_stop
2024/07/07 15:16:10 INFO The command was successfully executed. command=charge_stop
2024/07/07 15:16:39 DEBU Connection Timeout
2024/07/07 15:16:39 DEBU Disconnect vehicle (A)
2024/07/07 15:16:39 DEBU Close connection (A)
2024/07/07 15:22:24 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:22:24 INFO connectToVehicle ...
2024/07/07 15:22:24 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:22:24 DEBU Connecting to vehicle (A)...
2024/07/07 15:22:24 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2]
2024/07/07 15:22:25 DEBU Create vehicle object ...
2024/07/07 15:22:25 DEBU Connecting to vehicle (B)...
2024/07/07 15:22:25 DEBU start VCSEC session...
2024/07/07 15:22:26 DEBU car successfully wakeup
2024/07/07 15:22:26 DEBU start Infotainment session...
2024/07/07 15:22:27 INFO Session started
2024/07/07 15:22:27 DEBU sending command ... command=charge_start
2024/07/07 15:22:28 INFO The command was successfully executed. command=charge_start
2024/07/07 15:22:28 DEBU sending command ... command=set_charging_amps
2024/07/07 15:22:29 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:22:34 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 15:22:34 DEBU sending command ... command=set_charging_amps
2024/07/07 15:22:35 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:22:54 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:22:54 DEBU sending command ... command=set_charging_amps
2024/07/07 15:22:55 DEBU Disconnect vehicle (A)
2024/07/07 15:22:55 DEBU Close connection (A)
2024/07/07 15:22:56 INFO connectToVehicle ...
2024/07/07 15:22:56 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:22:56 DEBU Connecting to vehicle (A)...
2024/07/07 15:22:57 DEBU Create vehicle object ...
2024/07/07 15:22:57 DEBU Connecting to vehicle (B)...
2024/07/07 15:22:57 DEBU start VCSEC session...
2024/07/07 15:22:58 DEBU car successfully wakeup
2024/07/07 15:22:58 DEBU start Infotainment session...
2024/07/07 15:23:00 INFO Session started
2024/07/07 15:23:00 DEBU sending command ... command=set_charging_amps
2024/07/07 15:23:01 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:23:15 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2]
2024/07/07 15:23:15 DEBU sending command ... command=set_charging_amps
2024/07/07 15:23:16 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:23:30 DEBU Connection Timeout
2024/07/07 15:23:30 DEBU Disconnect vehicle (A)
2024/07/07 15:23:30 DEBU Close connection (A)
2024/07/07 15:23:31 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2]
2024/07/07 15:23:31 INFO connectToVehicle ...
2024/07/07 15:23:31 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:23:31 DEBU Connecting to vehicle (A)...
2024/07/07 15:23:32 DEBU Create vehicle object ...
2024/07/07 15:23:32 DEBU Connecting to vehicle (B)...
2024/07/07 15:23:32 DEBU start VCSEC session...
2024/07/07 15:23:33 DEBU car successfully wakeup
2024/07/07 15:23:33 DEBU start Infotainment session...
2024/07/07 15:23:34 INFO Session started
2024/07/07 15:23:34 DEBU sending command ... command=set_charging_amps
2024/07/07 15:23:35 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:24:04 DEBU Connection Timeout
2024/07/07 15:24:04 DEBU Disconnect vehicle (A)
2024/07/07 15:24:04 DEBU Close connection (A)
2024/07/07 15:24:09 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:24:09 INFO connectToVehicle ...
2024/07/07 15:24:09 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:24:09 DEBU Connecting to vehicle (A)...
2024/07/07 15:24:10 DEBU Create vehicle object ...
2024/07/07 15:24:10 DEBU Connecting to vehicle (B)...
2024/07/07 15:24:10 DEBU start VCSEC session...
2024/07/07 15:24:11 DEBU car successfully wakeup
2024/07/07 15:24:11 DEBU start Infotainment session...
2024/07/07 15:24:12 INFO Session started
2024/07/07 15:24:12 DEBU sending command ... command=set_charging_amps
2024/07/07 15:24:13 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:24:25 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:24:25 DEBU sending command ... command=set_charging_amps
2024/07/07 15:24:27 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:24:42 DEBU Connection Timeout
2024/07/07 15:24:42 DEBU Disconnect vehicle (A)
2024/07/07 15:24:42 DEBU Close connection (A)
2024/07/07 15:25:09 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:25:10 INFO connectToVehicle ...
2024/07/07 15:25:10 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:25:10 DEBU Connecting to vehicle (A)...
2024/07/07 15:25:10 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:25:10 DEBU Create vehicle object ...
2024/07/07 15:25:10 DEBU Connecting to vehicle (B)...
2024/07/07 15:25:10 DEBU start VCSEC session...
2024/07/07 15:25:12 DEBU car successfully wakeup
2024/07/07 15:25:12 DEBU start Infotainment session...
2024/07/07 15:25:13 INFO Session started
2024/07/07 15:25:13 DEBU sending command ... command=charge_start
2024/07/07 15:25:14 WARN failed to start charge: car could not execute command: disconnected
2024/07/07 15:25:14 INFO retrying in 3 seconds
2024/07/07 15:25:18 WARN failed to start charge: car could not execute command: disconnected
2024/07/07 15:25:18 INFO retrying in 6 seconds
2024/07/07 15:25:24 ERRO The command was canceled. command=charge_start err="failed to start charge: context deadline exceeded"
2024/07/07 15:25:24 DEBU Disconnect vehicle (A)
2024/07/07 15:25:24 DEBU Close connection (A)
2024/07/07 15:25:26 INFO connectToVehicle ...
2024/07/07 15:25:26 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:25:26 DEBU Connecting to vehicle (A)...
2024/07/07 15:25:26 DEBU Create vehicle object ...
2024/07/07 15:25:26 DEBU Connecting to vehicle (B)...
2024/07/07 15:25:26 DEBU start VCSEC session...
2024/07/07 15:25:27 DEBU car successfully wakeup
2024/07/07 15:25:27 DEBU start Infotainment session...
2024/07/07 15:25:28 INFO Session started
2024/07/07 15:25:28 DEBU sending command ... command=set_charging_amps
2024/07/07 15:25:29 INFO The command was successfully executed. command=set_charging_amps
2024/07/07 15:25:54 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:25:54 DEBU sending command ... command=charge_start
2024/07/07 15:25:54 DEBU Disconnect vehicle (A)
2024/07/07 15:25:54 DEBU Close connection (A)
2024/07/07 15:25:54 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:25:55 INFO connectToVehicle ...
2024/07/07 15:25:55 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:25:55 DEBU Connecting to vehicle (A)...
2024/07/07 15:25:58 DEBU Create vehicle object ...
2024/07/07 15:25:58 DEBU Connecting to vehicle (B)...
2024/07/07 15:25:58 DEBU start VCSEC session...
2024/07/07 15:26:00 DEBU car successfully wakeup
2024/07/07 15:26:00 DEBU start Infotainment session...
2024/07/07 15:26:10 DEBU Disconnect vehicle (B)
2024/07/07 15:26:10 DEBU Close connection (B)
2024/07/07 15:26:10 WARN failed to perform handshake with vehicle (B): context deadline exceeded
2024/07/07 15:26:10 INFO retrying in 3 seconds
2024/07/07 15:26:13 DEBU trying connecting to vehicle attempt=2
2024/07/07 15:26:13 DEBU Connecting to vehicle (A)...
2024/07/07 15:26:19 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:26:19 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:26:28 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:26:28 INFO retrying in 6 seconds
2024/07/07 15:26:34 DEBU trying connecting to vehicle attempt=3
2024/07/07 15:26:34 DEBU Connecting to vehicle (A)...
2024/07/07 15:26:39 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:26:39 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:26:49 ERRO stop retrying after 3 attempts error="failed to connect to vehicle (A): context deadline exceeded"
2024/07/07 15:26:50 INFO connectToVehicle ...
2024/07/07 15:26:50 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:26:50 DEBU Connecting to vehicle (A)...
2024/07/07 15:27:05 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:27:05 INFO retrying in 3 seconds
2024/07/07 15:27:08 DEBU trying connecting to vehicle attempt=2
2024/07/07 15:27:08 DEBU Connecting to vehicle (A)...
2024/07/07 15:27:23 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:27:23 INFO retrying in 6 seconds
2024/07/07 15:27:29 DEBU trying connecting to vehicle attempt=3
2024/07/07 15:27:29 DEBU Connecting to vehicle (A)...
2024/07/07 15:27:44 ERRO stop retrying after 3 attempts error="failed to connect to vehicle (A): context deadline exceeded"
2024/07/07 15:27:45 INFO connectToVehicle ...
2024/07/07 15:27:45 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:27:45 DEBU Connecting to vehicle (A)...
2024/07/07 15:27:59 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:27:59 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 15:28:00 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:28:00 INFO retrying in 3 seconds
2024/07/07 15:28:03 DEBU trying connecting to vehicle attempt=2
2024/07/07 15:28:03 DEBU Connecting to vehicle (A)...
2024/07/07 15:28:18 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:28:18 INFO retrying in 6 seconds
2024/07/07 15:28:19 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:28:19 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:28:24 DEBU trying connecting to vehicle attempt=3
2024/07/07 15:28:24 DEBU Connecting to vehicle (A)...
2024/07/07 15:28:34 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:28:34 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:28:39 ERRO stop retrying after 3 attempts error="failed to connect to vehicle (A): context deadline exceeded"
2024/07/07 15:28:40 INFO connectToVehicle ...
2024/07/07 15:28:40 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:28:40 DEBU Connecting to vehicle (A)...
2024/07/07 15:28:54 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:28:54 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:28:55 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:28:55 INFO retrying in 3 seconds
2024/07/07 15:28:58 DEBU trying connecting to vehicle attempt=2
2024/07/07 15:28:58 DEBU Connecting to vehicle (A)...
2024/07/07 15:29:04 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:29:04 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:29:13 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:29:13 INFO retrying in 6 seconds
2024/07/07 15:29:19 DEBU trying connecting to vehicle attempt=3
2024/07/07 15:29:19 DEBU Connecting to vehicle (A)...
2024/07/07 15:29:34 ERRO stop retrying after 3 attempts error="failed to connect to vehicle (A): context deadline exceeded"
2024/07/07 15:29:35 INFO connectToVehicle ...
2024/07/07 15:29:35 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:29:35 DEBU Connecting to vehicle (A)...
2024/07/07 15:29:50 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:29:50 INFO retrying in 3 seconds
2024/07/07 15:29:53 DEBU trying connecting to vehicle attempt=2
2024/07/07 15:29:53 DEBU Connecting to vehicle (A)...
2024/07/07 15:30:04 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:30:04 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:30:08 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:30:08 INFO retrying in 6 seconds
2024/07/07 15:30:14 DEBU trying connecting to vehicle attempt=3
2024/07/07 15:30:14 DEBU Connecting to vehicle (A)...
2024/07/07 15:30:19 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:30:19 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:30:29 ERRO stop retrying after 3 attempts error="failed to connect to vehicle (A): context deadline exceeded"
2024/07/07 15:30:31 INFO connectToVehicle ...
2024/07/07 15:30:31 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:30:31 DEBU Connecting to vehicle (A)...
2024/07/07 15:30:46 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:30:46 INFO retrying in 3 seconds
2024/07/07 15:30:49 DEBU trying connecting to vehicle attempt=2
2024/07/07 15:30:49 DEBU Connecting to vehicle (A)...
2024/07/07 15:30:49 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:30:49 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:31:04 WARN failed to connect to vehicle (A): context deadline exceeded
2024/07/07 15:31:04 INFO retrying in 6 seconds
2024/07/07 15:31:04 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:31:04 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:31:10 DEBU trying connecting to vehicle attempt=3
2024/07/07 15:31:10 DEBU Connecting to vehicle (A)...
2024/07/07 15:31:19 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:31:19 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:31:25 ERRO stop retrying after 3 attempts error="failed to connect to vehicle (A): context deadline exceeded"
2024/07/07 15:31:26 INFO connectToVehicle ...
2024/07/07 15:31:26 DEBU trying connecting to vehicle attempt=1
2024/07/07 15:31:26 DEBU Connecting to vehicle (A)...
2024/07/07 15:31:49 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:31:49 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:33:39 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:33:39 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 15:34:09 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:34:09 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:35:59 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:35:59 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:39:09 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:39:09 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:39:39 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:39:39 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 15:39:49 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:39:49 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:40:14 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:40:14 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:40:24 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:40:24 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:41:34 INFO received command command=charge_start VIN= body=map[]
2024/07/07 15:41:34 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:42:53 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:43:54 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:44:08 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:44:58 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:45:28 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:45:40 INFO received command command=set_charging_amps VIN= body=map[charging_amps:2]
2024/07/07 15:45:59 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:47:13 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:47:38 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:47:59 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:48:09 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:48:23 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:49:09 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:49:33 INFO received command command=set_charging_amps VIN= body=map[charging_amps:3]
2024/07/07 15:50:28 INFO received command command=set_charging_amps VIN= body=map[charging_amps:5]
2024/07/07 15:51:03 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:51:28 INFO received command command=set_charging_amps VIN= body=map[charging_amps:4]
2024/07/07 15:52:18 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:53:28 INFO received command command=charge_stop VIN= body=map[]
2024/07/07 15:53:56 INFO received command command=charge_stop VIN= body=map[]
wimaha commented 2 months ago

Thank you for the logs. I can see the part which is blocking. Unfortunately the blocking part is ether in the tesla command repository or in the go ble package.

But I think the teal problem here ist, that the connection can't be established after 18 attempts. Perhaps we should add something, that after 5 failed attempts no new commands are accepted and the proxy waits for a view minutes for the connection issue to be resolved.

gauner1986 commented 2 months ago

Hm. Not sure if this is the only trigger. There were other cases where the connection was fine beforehand.

gauner1986 commented 2 months ago

Got a new occurence. I didn't pay a lot of attention the last few days. There was one temporary connection issue again and then it got stalled for days without recovery:

2024/07/11 11:09:21 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:2]
2024/07/11 11:09:21 DEBU sending command ... command=set_charging_amps
2024/07/11 11:09:22 INFO The command was successfully executed. command=set_charging_amps
2024/07/11 11:09:31 INFO received command command=charge_stop VIN=VIN body=map[]
2024/07/11 11:09:31 DEBU sending command ... command=charge_stop
2024/07/11 11:09:32 INFO The command was successfully executed. command=charge_stop
2024/07/11 11:09:45 DEBU Connection Timeout
2024/07/11 11:09:45 DEBU Disconnect vehicle (A)
2024/07/11 11:09:45 DEBU Close connection (A)
2024/07/11 11:10:50 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/11 11:10:51 INFO connectToVehicle ...
2024/07/11 11:10:51 DEBU trying connecting to vehicle attempt=1
2024/07/11 11:10:51 DEBU Connecting to vehicle (A)...
2024/07/11 11:10:51 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:3]
2024/07/11 11:11:10 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/11 11:11:11 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:2]
2024/07/11 11:14:45 INFO received command command=charge_start VIN=VIN body=map[]
....
2024/07/11 11:42:30 INFO received command command=set_charging_amps VIN=VIN body=map[charging_amps:4]
2024/07/11 11:42:45 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/11 11:43:00 INFO received command command=charge_start VIN=VIN body=map[]
....
2024/07/11 18:07:34 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/12 20:48:45 INFO received command command=charge_stop VIN=VIN body=map[]
2024/07/14 09:28:42 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/14 09:49:01 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/14 10:26:11 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/14 13:14:05 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/14 14:10:05 INFO received command command=charge_stop VIN=VIN body=map[]
2024/07/15 09:31:56 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/15 10:17:05 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/15 10:32:17 INFO received command command=charge_start VIN=VIN body=map[]
2024/07/15 10:33:35 INFO received command command=charge_start VIN=VIN body=map[]

Is there a possibility to monitor a command and kill it if no success event is received in a certain time frame?

dglaude commented 2 months ago

I cam back from a week-end and no command are working, even after restarting evcc and TeslaBleHttpProxy and even waking up / starting the car from the phone app.

My setup is interesting because I am migrating and I have two instances of TeslaBleHttpProxy v1.2 running, one on a Raspberry Pi4 (docker image) and one on an Intel NUC (self go compile).

To switch, I change the evcc config and restart. But I have the same problem on both machines... Actually I have another Pi4 and same problem. Also generating new key and trying to register it did work.

So I wonder is the problem is on TeslaBleHttpProxy, or could it be on the car side that sometimes just don't want to communicate at all? I tried to remove all the "Unknow key" to kind of clean, but now I have difficulty to recreate a key.

It is so sad to have seen it working for hours or days and now it fail. I'll sleep on that and try again whenever possible with https://github.com/teslamotors/vehicle-command/ to check the basics.

dglaude commented 2 months ago

I tested with vehicule-command after successfully adding a key and then copying that key to ~/TeslaBleHttpProxy/key but I had no success with evcc controling the charge (here trying to stop the charge).


dglaude@dglaude-NUC5PPYB:~/evcc$ sudo journalctl -fau TeslaBleHttpProxy
jui 21 23:51:57 dglaude-NUC5PPYB systemd[1]: Started TeslaBleHttpProxy.
jui 21 23:51:57 dglaude-NUC5PPYB TeslaBleHttpProxy[434183]: 2024/07/21 23:51:57 INFO TeslaBleHttpProxy 1.2 is loading ...
jui 21 23:51:57 dglaude-NUC5PPYB TeslaBleHttpProxy[434183]: 2024/07/21 23:51:57 INFO BleControl initialized
jui 21 23:51:57 dglaude-NUC5PPYB TeslaBleHttpProxy[434183]: 2024/07/21 23:51:57 INFO TeslaBleHttpProxy is running!
jui 21 23:58:47 dglaude-NUC5PPYB TeslaBleHttpProxy[434183]: 2024/07/21 23:58:47 INFO received command=charge_stop body=map[]
jui 21 23:58:47 dglaude-NUC5PPYB TeslaBleHttpProxy[434183]: 2024/07/21 23:58:47 INFO connecting to Vehicle ...
jui 21 23:59:02 dglaude-NUC5PPYB TeslaBleHttpProxy[434183]: 2024/07/21 23:59:02 WARN failed to connect to vehicle (A): context deadline exceeded
jui 21 23:59:02 dglaude-NUC5PPYB TeslaBleHttpProxy[434183]: 2024/07/21 23:59:02 INFO retrying in 3 seconds
jui 21 23:59:07 dglaude-NUC5PPYB TeslaBleHttpProxy[434183]: 2024/07/21 23:59:07 can't accept: listner timed out
jui 21 23:59:20 dglaude-NUC5PPYB TeslaBleHttpProxy[434183]: 2024/07/21 23:59:20 WARN failed to connect to vehicle (A): context deadline exceeded
jui 21 23:59:20 dglaude-NUC5PPYB TeslaBleHttpProxy[434183]: 2024/07/21 23:59:20 INFO retrying in 6 seconds```

The interesting part is that if I try with `vehicule-command` while `TeslaBleHttpProxy` still run, I get error. I had to stop `TeslaBleHttpProxy` then at second attempt I was able to change the charge speed.

```dglaude@dglaude-NUC5PPYB:~/GIT/vehicle-command$ sudo /home/dglaude/go/bin/tesla-control -vin XP7YYYYY1YY999999 -key-file private.pem -ble charging-set-amps 6
Error: failed to find a BLE device: can't init hci: no devices available: (hci0: can't down device: device or resource busy)
dglaude@dglaude-NUC5PPYB:~/GIT/vehicle-command$ sudo systemctl stop TeslaBleHttpProxy.service
dglaude@dglaude-NUC5PPYB:~/GIT/vehicle-command$ sudo /home/dglaude/go/bin/tesla-control -vin XP7YYYYY1YY999999 -key-file private.pem -ble charging-set-amps 6
Error: ble: failed to enumerate device services: ATT request failed: input channel closed: io: read/write on closed pipe
dglaude@dglaude-NUC5PPYB:~/GIT/vehicle-command$ sudo /home/dglaude/go/bin/tesla-control -vin XP7YYYYY1YY999999 -key-file private.pem -ble charging-set-amps 6
dglaude@dglaude-NUC5PPYB:~/GIT/vehicle-command$```

Right now it mean that `vehicule-command` is working and `TeslaBleHttpProxy` is not working anymore. But the key is right and the hardware is capable...

Notice that the key created with `vehicule-command` is visible as unknown in the car UI (in French "Verrouillage" section) and can be renamed.
dglaude commented 2 months ago

Some positive progress in my setup. The whole daylight, we had to manually adjust the power level... I was about to give a try to an MQTT alternative to this software with the hope that it would solve my problem. But before that, I moved two Pi4 and my NUC closer to the car, I was already near, but now I am as close as possible without being outside. As a result, my two instances of TeslaBleHttpProxy one on each Pi4 are working as expected (the NUC does not work yet).

Maybe it is not related to the distance, maybe it is just that both machine have been off during the move and the new installation...

Still, it works for me (at least tonight). Either both stop working in a few hours or day... or maybe those few meter made the difference. If you have trouble, please give that a try.

I also suspect that Tesla may have included power saving change in recent software upgrade, and that could include BLE power/sensitivity or make the car harder to wake up for us.

gauner1986 commented 2 months ago

Another occurence. After a timeout again:

Jul 28 16:20:00 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:20:00 INFO The command was successfully executed. command=charge_start Jul 28 16:20:00 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:20:00 DEBU sending command ... command=set_charging_amps Jul 28 16:20:01 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:20:01 INFO The command was successfully executed. command=set_charging_amps Jul 28 16:20:17 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:20:17 DEBU Connection Timeout Jul 28 16:20:17 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:20:17 DEBU Disconnect vehicle (A) Jul 28 16:20:17 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:20:17 DEBU Close connection (A) Jul 28 16:20:25 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:20:25 INFO received command command=set_charging_amps VIN=5YJSA7E54PF503416 body=map[charging_amps:2] Jul 28 16:20:25 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:20:25 INFO connectToVehicle ... Jul 28 16:20:25 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:20:25 DEBU trying connecting to vehicle attempt=1 Jul 28 16:20:25 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:20:25 DEBU Connecting to vehicle (A)... Jul 28 16:21:24 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:21:24 INFO received command command=charge_stop VIN=5YJSA7E54PF503416 body=map[] Jul 28 16:21:32 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:21:32 INFO received command command=set_charging_amps VIN=5YJSA7E54PF503416 body=map[charging_amps:2] Jul 28 16:22:24 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:22:24 INFO received command command=set_charging_amps VIN=5YJSA7E54PF503416 body=map[charging_amps:3] Jul 28 16:22:34 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:22:34 INFO received command command=set_charging_amps VIN=5YJSA7E54PF503416 body=map[charging_amps:4] Jul 28 16:22:59 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:22:59 INFO received command command=set_charging_amps VIN=5YJSA7E54PF503416 body=map[charging_amps:3] Jul 28 16:23:44 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:23:44 INFO received command command=set_charging_amps VIN=5YJSA7E54PF503416 body=map[charging_amps:3] Jul 28 16:24:09 DietPi TeslaBleHttpProxy[536]: 2024/07/28 16:24:09 INFO received command command=set_charging_amps VIN=5YJSA7E54PF503416 body=map[charging_amps:3] .... Jul 28 18:25:46 DietPi TeslaBleHttpProxy[536]: 2024/07/28 18:25:46 INFO received command command=set_charging_amps VIN=5YJSA7E54PF503416 body=map[charging_amps:2] Jul 28 18:26:31 DietPi TeslaBleHttpProxy[536]: 2024/07/28 18:26:31 INFO received command command=charge_stop VIN=5YJSA7E54PF503416 body=map[] Jul 28 18:27:24 DietPi TeslaBleHttpProxy[536]: 2024/07/28 18:27:24 INFO received command command=charge_stop VIN=5YJSA7E54PF503416 body=map[] Jul 28 18:29:14 DietPi TeslaBleHttpProxy[536]: 2024/07/28 18:29:14 INFO received command command=set_charging_amps VIN=5YJSA7E54PF503416 body=map[charging_amps:2] Jul 28 18:34:35 DietPi TeslaBleHttpProxy[536]: 2024/07/28 18:34:35 INFO received command command=charge_stop VIN=5YJSA7E54PF503416 body=map[] Jul 28 18:36:35 DietPi TeslaBleHttpProxy[536]: 2024/07/28 18:36:35 INFO received command command=charge_stop VIN=5YJSA7E54PF503416 body=map[] Jul 28 18:41:28 DietPi TeslaBleHttpProxy[536]: 2024/07/28 18:41:28 INFO received command command=charge_stop VIN=5YJSA7E54PF503416 body=map[]

wimaha commented 1 month ago

There are now even more logs with version 1.2.2. Please use this version and report any error logs with this problem. Thank You!!

wimaha commented 1 month ago

The Bug ist finally resolved with Version 1.2.4 :-)

gauner1986 commented 1 week ago

Unfortunately it still seems to happen sometimes. :(

This is from 1.2.4:

Sep 15 12:38:36 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:38:36 INFO sending command=set_charging_amps body=map[charging_amps:4]
Sep 15 12:38:36 DietPi TeslaBleHttpProxy[11114]: 2024-09-15T12:38:36+02:00 [debug] TX: 320208033a1212108f0e67054671d7009f643bff2618dfd79a0310073b08aec6d15756a66ee41ec4c537035207dfc8391437b7dd6a81010a430a4104ed711e034775d6dc32594edc8adb96eed0fba6e09807eec593bc449a9693d9ba476415de3edb6eb53a7cd735e98c961c3e6bdfc99afcbb54ee75bb5b9edd76782a3a0a10781854b66ccb43e863e90a29222647a4120ce2edc231fb788c4aa8bff5c618c903251cdb07002a109b5a4604be2dd78851cb9db2ba9936cf
Sep 15 12:38:37 DietPi TeslaBleHttpProxy[11114]: 2024-09-15T12:38:37+02:00 [debug] RX: 321212108f0e67054671d7009f643bff2618dfd73a02080352020a00920310073b08aec6d15756a66ee41ec4c537039a0310815aef109e4cf92a0483e53d2daf6788
Sep 15 12:38:37 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:38:37 INFO successfully executed command=set_charging_amps body=map[charging_amps:4]
Sep 15 12:38:50 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:38:50 INFO received command=set_charging_amps body=map[charging_amps:4]
Sep 15 12:38:50 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:38:50 INFO sending command=set_charging_amps body=map[charging_amps:4]
Sep 15 12:38:50 DietPi TeslaBleHttpProxy[11114]: 2024-09-15T12:38:50+02:00 [debug] TX: 320208033a1212108f0e67054671d7009f643bff2618dfd79a0310528f18485052005179132ae9dbc4c0745207f9bd44adadc0a16a81010a430a4104ed711e034775d6dc32594edc8adb96eed0fba6e09807eec593bc449a9693d9ba476415de3edb6eb53a7cd735e98c961c3e6bdfc99afcbb54ee75bb5b9edd76782a3a0a10781854b66ccb43e863e90a29222647a4120c7380b9159570e7c8c422667718ca03252adb07002a10c90e8e367d30e768b4915bb7fb0fe497
Sep 15 12:38:51 DietPi TeslaBleHttpProxy[11114]: 2024-09-15T12:38:51+02:00 [warn ] [528f18485052005179132ae9dbc4c074] Terminal transmission error: ATT request failed: input channel closed: io: read/write on closed pipe
Sep 15 12:38:51 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:38:51 DEBU disconnect vehicle (A)
Sep 15 12:38:51 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:38:51 DEBU close connection (A)
Sep 15 12:38:52 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:38:52 INFO connecting to Vehicle ...
Sep 15 12:38:52 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:38:52 DEBU trying connecting to vehicle attempt=1
Sep 15 12:38:52 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:38:52 DEBU connecting to vehicle (A)...
Sep 15 12:38:52 DietPi TeslaBleHttpProxy[11114]: 2024-09-15T12:38:52+02:00 [debug] Reusing existing BLE device
Sep 15 12:38:52 DietPi TeslaBleHttpProxy[11114]: 2024-09-15T12:38:52+02:00 [debug] Searching for BLE beacon S131821dd4fdd0f1aC...
Sep 15 12:38:52 DietPi TeslaBleHttpProxy[11114]: 2024-09-15T12:38:52+02:00 [debug] Connecting to BLE beacon b0:d2:78:0b:27:9a...
Sep 15 12:38:52 DietPi TeslaBleHttpProxy[11114]: 2024-09-15T12:38:52+02:00 [warn ] BLE connection attempt failed: ble: failed to enumerate device services: ATT request failed: input channel closed: io: read/write on closed pipe
Sep 15 12:38:52 DietPi TeslaBleHttpProxy[11114]: 2024-09-15T12:38:52+02:00 [debug] Reusing existing BLE device
Sep 15 12:38:52 DietPi TeslaBleHttpProxy[11114]: 2024-09-15T12:38:52+02:00 [debug] Searching for BLE beacon S131821dd4fdd0f1aC...
Sep 15 12:39:00 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:39:00 INFO received command=set_charging_amps body=map[charging_amps:5]
Sep 15 12:39:30 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:39:30 INFO received command=set_charging_amps body=map[charging_amps:5]
Sep 15 12:39:55 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:39:55 INFO received command=set_charging_amps body=map[charging_amps:5]
Sep 15 12:47:50 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:47:50 INFO received command=set_charging_amps body=map[charging_amps:5]
Sep 15 12:48:20 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:48:20 INFO received command=charge_stop body=map[]
Sep 15 12:51:00 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:51:00 INFO received command=charge_stop body=map[]
Sep 15 12:51:20 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:51:20 INFO received command=set_charging_amps body=map[charging_amps:3]
Sep 15 12:51:32 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:51:32 INFO received command=set_charging_amps body=map[charging_amps:4]
Sep 15 12:52:00 DietPi TeslaBleHttpProxy[11114]: 2024/09/15 12:52:00 INFO received command=set_charging_amps body=map[charging_amps:5]