Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ble.NewConnection sometimes never returns #272

Open
wimaha opened this issue Jul 7, 2024 · 6 comments
Open

ble.NewConnection sometimes never returns #272

wimaha opened this issue Jul 7, 2024 · 6 comments

Comments

@wimaha
Copy link

wimaha commented Jul 7, 2024

Hello,

when there are connection issues the function ble.NewConnection(ctx, vin) returns with context deadline exceeded. That's the expected behavior.
But after a while (> 15 attempts) the function just never returns.

Any clue what could cause this issue?

The problem also occurs with this #269

@sethterashima
Copy link
Collaborator

Could you please include the output of running the command with -debug and provide your OS and hardware information?

@Jan21493
Copy link

I had the same or at least a very similar problem. As long as the vehicle is nearby the command tesla-control works well, even if repeated thousands of times over a longer time period. With the new code from a few weeks ago the BLE connection is very stable on my system.

But when the vehicle is driven away, I got the same error Error: context deadline exceeded as expected, but after a few times I got Error: failed to find a BLE device: can't init hci: no devices available: (hci0: can't down device: device or resource busy). I also got Error: failed to find a BLE device: can't init hci: can't create socket: too many open files. See attached output for details.

A temporary workaround was to restart the bluetooth service (systemctl restart bluetooth), however this does not last long. Reason for the problem might be a missing 'close' for the underlying socket (socket is created by code from "github.com/go-ble/ble", in ble/linux/hci/socket/socket.go starting lin line 63). I'm neither an expert with Go nor the go-ble package, so I haven't prepared a pull request, but was able to add a few lines of code (see attachment) that look to fix the problem for me.

Please add that fix (or a better one) .

error--too-many-open-files.txt

Jan21493 added a commit to Jan21493/LoxBerry-Plugin-TeslaCmd that referenced this issue Aug 14, 2024
Modified code that includes patch to prevent some errors with BLE interface. See teslamotors/vehicle-command#272 (comment)
@wimaha
Copy link
Author

wimaha commented Aug 20, 2024

I think my issue is different. @sethterashima here are the logs:

I'am using a custom Go-App (https://github.com/wimaha/TeslaBleHttpProxy) with this library. So here is a mix of logs from my program and this library. The relevant part starts at 15:34:58. I'm posting some additional log lines to provide context. In the relevant part I added to corresponding function calls to the logs from my program.

2024/08/20 15:30:34 INFO received command=set_charging_amps body=map[charging_amps:2]
2024/08/20 15:30:34 INFO connecting to Vehicle ...
2024/08/20 15:30:34 DEBU trying connecting to vehicle attempt=1
2024/08/20 15:30:34 DEBU connecting to vehicle (A)...
2024-08-20T15:30:34+02:00 [debug] Reusing existing BLE device
2024-08-20T15:30:34+02:00 [debug] Searching for BLE beacon S20613d5100e9150eC...
2024-08-20T15:30:49+02:00 [warn ] BLE connection attempt failed: failed to find BLE beacon for XP7YGCEK7RB272570 (S20613d5100e9150eC): can't scan: context d
eadline exceeded
2024/08/20 15:30:49 WARN failed to connect to vehicle (A): context deadline exceeded
2024/08/20 15:30:49 INFO retrying in 3 seconds
2024/08/20 15:30:52 DEBU trying connecting to vehicle attempt=2
2024/08/20 15:30:52 DEBU connecting to vehicle (A)...
2024-08-20T15:30:52+02:00 [debug] Reusing existing BLE device
2024-08-20T15:30:52+02:00 [debug] Searching for BLE beacon S20613d5100e9150eC...
2024-08-20T15:30:52+02:00 [debug] Connecting to BLE beacon 74:b8:39:60:94:0e...
2024-08-20T15:30:53+02:00 [info ] Connected to vehicle BLE
2024/08/20 15:30:53 DEBU create vehicle object ...
2024/08/20 15:30:53 DEBU connecting to vehicle (B)...
2024-08-20T15:30:53+02:00 [info ] Starting dispatcher service...
2024/08/20 15:30:53 DEBU start VCSEC session...
2024-08-20T15:30:53+02:00 [info ] Requesting session info from DOMAIN_VEHICLE_SECURITY
2024-08-20T15:30:53+02:00 [debug] TX: 320208023a1212105243ddc04cf2f2a430cf0c41e7bd3e6f9a031098f8f1c1bccda01ba53a8db1dd3057b072430a4104a3a786148880a88ff15d3b
6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d
2024-08-20T15:30:53+02:00 [debug] RX: 321212105243ddc04cf2f2a430cf0c41e7bd3e6f3a0208027a5e081e124104052a16de96939b8d1f24deb5ed6ec07595bcee328d90c189781f3e2d
8e78a7f670f7d53c15aa0f8ae04115b426a1cda86c368e8842d00ce4abec541040023cc51a1011c62736e2e98c56c72973b4cf7ff0d1252670000030076a2432220a20dc01f694ce578ebfb91494
c66c6bb537ce766e3d916d14620ca6e4ffc4f2a11992031098f8f1c1bccda01ba53a8db1dd3057b0
2024-08-20T15:30:53+02:00 [info ] [98f8f1c1bccda01ba53a8db1dd3057b0] Updated session info for DOMAIN_VEHICLE_SECURITY
2024-08-20T15:30:53+02:00 [debug] TX: 320208023a12121050b6a6302c870c3271ccf074a9d069df9a03107bdc6ded817476a24a7fddb5761ecf3852028d9b6a80010a430a4104a3a78614
8880a88ff15d3b6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d2a390a1011c62736e2e98c56c72973b4cf7f
f0d1120c8478f9e39e57879430f51bcb181f25337000002a10d0e153057c948f1b340a9bb520dbe397
2024-08-20T15:30:54+02:00 [debug] RX: 320208003a020802521f1a1d12160a14b86f84eac74183c3c3e4d5d35281d3ebb2e3f11b1802220101
2024-08-20T15:30:54+02:00 [debug] [00] Dropping message to DOMAIN_BROADCAST
2024-08-20T15:30:54+02:00 [debug] RX: 3212121050b6a6302c870c3271ccf074a9d069df3a0208029203107bdc6ded817476a24a7fddb5761ecf38
2024/08/20 15:30:54 DEBU car successfully wakeup
2024/08/20 15:30:54 DEBU start Infotainment session...
2024-08-20T15:30:54+02:00 [info ] Requesting session info from DOMAIN_INFOTAINMENT
2024-08-20T15:30:54+02:00 [info ] Session for DOMAIN_VEHICLE_SECURITY loaded from cache
2024-08-20T15:30:54+02:00 [debug] TX: 320208033a121210afa23c63ea150b86598444e9f6edee639a03102fde235261ebfe41f1e00c89bbb2d9a472430a4104a3a786148880a88ff15d3b
6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d
2024-08-20T15:30:55+02:00 [debug] RX: 32121210afa23c63ea150b86598444e9f6edee633a0208037a5f08e701124104944831bdf9849ad5fd19089e77def799ef9779664d7c3eb4d8d5b5
2e16e7f693a21f4a365f19214831f52fe1a8a8098e2b73ba60cc4f1ca714b373b37850cab21a101a019054164c37c886883a40d6539e65255981050030076a2432220a20cb99ef6eee59718778c1
83c73f4027dd3045ef685e5a1e422615b9b679071e799203102fde235261ebfe41f1e00c89bbb2d9a4
2024-08-20T15:30:55+02:00 [info ] [2fde235261ebfe41f1e00c89bbb2d9a4] Updated session info for DOMAIN_INFOTAINMENT
2024/08/20 15:30:55 INFO connection established
2024/08/20 15:30:55 INFO sending command=set_charging_amps body=map[charging_amps:2]
2024-08-20T15:30:55+02:00 [debug] TX: 320208033a121210afa23c63ea150b86598444e9f6edee639a031064b955ee4bb7475bc08418c3a87ea32c52073eb1b8e20ddf0d6a81010a430a41
04a3a786148880a88ff15d3b6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d2a3a0a101a019054164c37c886
883a40d6539e65120c3edf2011cc5114fa6396c12718e80125638105002a10f268709e9c743eefee6198e2856c6721
2024-08-20T15:30:56+02:00 [debug] RX: 32121210afa23c63ea150b86598444e9f6edee633a02080352020a0092031064b955ee4bb7475bc08418c3a87ea32c9a03102617868d2c2900dfee
60db3b571d036d
2024/08/20 15:30:56 INFO successfully executed command=set_charging_amps body=map[charging_amps:2]
2024/08/20 15:31:03 INFO received command=set_charging_amps body=map[charging_amps:3]
2024/08/20 15:31:03 INFO sending command=set_charging_amps body=map[charging_amps:3]
2024-08-20T15:31:03+02:00 [debug] TX: 320208033a121210afa23c63ea150b86598444e9f6edee639a0310ac2ae864b116bb7ed3dce72b9b727caf52075fdc9a09b861576a81010a430a41
04a3a786148880a88ff15d3b6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d2a3a0a101a019054164c37c886
883a40d6539e65120c98e384c2fc3adaeda515917b18e901256a8105002a10fc3d8cc318c322c8ac92ed48d5bb5854
2024-08-20T15:31:04+02:00 [debug] RX: 32121210afa23c63ea150b86598444e9f6edee633a02080352020a00920310ac2ae864b116bb7ed3dce72b9b727caf9a0310772a3c013ef0fa9e6b
17ad61c1a61739
2024/08/20 15:31:04 INFO successfully executed command=set_charging_amps body=map[charging_amps:3]
2024/08/20 15:31:25 DEBU connection Timeout
2024/08/20 15:31:25 DEBU disconnect vehicle (A)
2024/08/20 15:31:25 DEBU close connection (A)
2024/08/20 15:32:36 INFO received command=set_charging_amps body=map[charging_amps:4]
2024/08/20 15:32:36 INFO connecting to Vehicle ...
2024/08/20 15:32:36 DEBU trying connecting to vehicle attempt=1
2024/08/20 15:32:36 DEBU connecting to vehicle (A)...
2024-08-20T15:32:36+02:00 [debug] Reusing existing BLE device
2024-08-20T15:32:36+02:00 [debug] Searching for BLE beacon S20613d5100e9150eC...
2024-08-20T15:32:37+02:00 [debug] Connecting to BLE beacon 74:b8:39:60:94:0e...
2024-08-20T15:32:37+02:00 [warn ] BLE connection attempt failed: ble: failed to enumerate device services: ATT request failed: input channel closed: io: rea
d/write on closed pipe
2024-08-20T15:32:37+02:00 [debug] Reusing existing BLE device
2024-08-20T15:32:37+02:00 [debug] Searching for BLE beacon S20613d5100e9150eC...
2024-08-20T15:32:37+02:00 [debug] Connecting to BLE beacon 74:b8:39:60:94:0e...
2024-08-20T15:32:37+02:00 [info ] Connected to vehicle BLE
2024/08/20 15:32:37 DEBU create vehicle object ...
2024/08/20 15:32:37 DEBU connecting to vehicle (B)...
2024-08-20T15:32:37+02:00 [info ] Starting dispatcher service...
2024/08/20 15:32:37 DEBU start VCSEC session...
2024-08-20T15:32:37+02:00 [info ] Requesting session info from DOMAIN_VEHICLE_SECURITY
2024-08-20T15:32:37+02:00 [debug] TX: 320208023a1212103fef5c3a0ea184e3c8e4d9f0c7772da89a0310dee1df9812c629e91afba3840ec9012f72430a4104a3a786148880a88ff15d3b
6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d
2024-08-20T15:32:38+02:00 [debug] RX: 321212103fef5c3a0ea184e3c8e4d9f0c7772da83a0208027a5e081f124104052a16de96939b8d1f24deb5ed6ec07595bcee328d90c189781f3e2d
8e78a7f670f7d53c15aa0f8ae04115b426a1cda86c368e8842d00ce4abec541040023cc51a1011c62736e2e98c56c72973b4cf7ff0d1258f70000030076a2432220a205dd24451ccab9215001843
17fd051e7e29fa1b14fd7e8e775470ebddb3ef75cf920310dee1df9812c629e91afba3840ec9012f
2024-08-20T15:32:38+02:00 [info ] [dee1df9812c629e91afba3840ec9012f] Updated session info for DOMAIN_VEHICLE_SECURITY
2024-08-20T15:32:38+02:00 [debug] TX: 320208023a12121029437c7324008650947ee214561ee3e49a03102c44d524d682bd31687aa249e3f48b4e5202440a6a80010a430a4104a3a78614
8880a88ff15d3b6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d2a390a1011c62736e2e98c56c72973b4cf7f
f0d1120c7ce352b7a006c1611034bb521820259b7000002a10a3519e55c4874d483ce7352166f3ff19
2024-08-20T15:32:38+02:00 [debug] RX: 320208003a020802521f1a1d12160a141ec3a0923b69a4beb3cb0449b8d132ceb9601cc41802220101
2024-08-20T15:32:38+02:00 [debug] [00] Dropping message to DOMAIN_BROADCAST
2024-08-20T15:32:39+02:00 [debug] RX: 3212121029437c7324008650947ee214561ee3e43a0208029203102c44d524d682bd31687aa249e3f48b4e
2024/08/20 15:32:39 DEBU car successfully wakeup
2024/08/20 15:32:39 DEBU start Infotainment session...
2024-08-20T15:32:39+02:00 [info ] Requesting session info from DOMAIN_INFOTAINMENT
2024-08-20T15:32:39+02:00 [debug] TX: 320208033a121210efb8b8e43bc806c8c8642f92a116e6489a0310a4fb23305abd60de355317282d54f59972430a4104a3a786148880a88ff15d3b
6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d
2024-08-20T15:32:39+02:00 [info ] Session for DOMAIN_VEHICLE_SECURITY loaded from cache
2024-08-20T15:32:40+02:00 [debug] RX: 32121210efb8b8e43bc806c8c8642f92a116e6483a0208037a5f08e901124104944831bdf9849ad5fd19089e77def799ef9779664d7c3eb4d8d5b5
2e16e7f693a21f4a365f19214831f52fe1a8a8098e2b73ba60cc4f1ca714b373b37850cab21a101a019054164c37c886883a40d6539e6525c281050030076a2432220a2070ab1b60670bf4983e87
9d74a4db0e35a4837a33248dccca4fe7aa9f5b8587ef920310a4fb23305abd60de355317282d54f599
2024-08-20T15:32:40+02:00 [info ] [a4fb23305abd60de355317282d54f599] Updated session info for DOMAIN_INFOTAINMENT
2024/08/20 15:32:40 INFO connection established
2024/08/20 15:32:40 INFO sending command=set_charging_amps body=map[charging_amps:4]
2024-08-20T15:32:40+02:00 [debug] TX: 320208033a121210efb8b8e43bc806c8c8642f92a116e6489a0310ad6ffc42395770ea3a5f7db69688140e5207470fd736cf831a6a81010a430a41
04a3a786148880a88ff15d3b6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d2a3a0a101a019054164c37c886
883a40d6539e65120ca7c585280424de2c5cee397c18ea0125cc8105002a105670194257c844c0cf01aea8c759a3c7
2024-08-20T15:32:41+02:00 [debug] RX: 32121210efb8b8e43bc806c8c8642f92a116e6483a02080352020a00920310ad6ffc42395770ea3a5f7db69688140e9a03108fa506aa882ef7f7a8
f2aae45f1412b5
2024/08/20 15:32:41 INFO successfully executed command=set_charging_amps body=map[charging_amps:4]
2024/08/20 15:32:59 INFO received command=set_charging_amps body=map[charging_amps:3]
2024/08/20 15:32:59 INFO sending command=set_charging_amps body=map[charging_amps:3]
2024-08-20T15:32:59+02:00 [debug] TX: 320208033a121210efb8b8e43bc806c8c8642f92a116e6489a031048d4fca116dcccc75eb0ede0b24d07385207f23079ced393d56a81010a430a41
04a3a786148880a88ff15d3b6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d2a3a0a101a019054164c37c886
883a40d6539e65120c1fe5e19e60b47e31f2417b7d18eb0125de8105002a10bfbecde7364bd5d99922bda0d91ea7f0
2024-08-20T15:33:00+02:00 [debug] RX: 32121210efb8b8e43bc806c8c8642f92a116e6483a02080352020a0092031048d4fca116dcccc75eb0ede0b24d07389a03109e0c54e6fbcf4a3626
1b62597bd27217
2024/08/20 15:33:00 INFO successfully executed command=set_charging_amps body=map[charging_amps:3]
2024/08/20 15:33:10 DEBU connection Timeout
2024/08/20 15:33:10 DEBU disconnect vehicle (A)
2024/08/20 15:33:10 DEBU close connection (A)
2024/08/20 15:33:29 INFO received command=set_charging_amps body=map[charging_amps:4]
2024/08/20 15:33:29 INFO connecting to Vehicle ...
2024/08/20 15:33:29 DEBU trying connecting to vehicle attempt=1
2024/08/20 15:33:29 DEBU connecting to vehicle (A)...
2024-08-20T15:33:29+02:00 [debug] Reusing existing BLE device
2024-08-20T15:33:29+02:00 [debug] Searching for BLE beacon S20613d5100e9150eC...
2024-08-20T15:33:44+02:00 [warn ] BLE connection attempt failed: failed to find BLE beacon for XP7YGCEK7RB272570 (S20613d5100e9150eC): can't scan: context d
eadline exceeded
2024/08/20 15:33:44 WARN failed to connect to vehicle (A): context deadline exceeded
2024/08/20 15:33:44 INFO retrying in 3 seconds
2024/08/20 15:33:47 DEBU trying connecting to vehicle attempt=2
2024/08/20 15:33:47 DEBU connecting to vehicle (A)...
2024-08-20T15:33:47+02:00 [debug] Reusing existing BLE device
2024-08-20T15:33:47+02:00 [debug] Searching for BLE beacon S20613d5100e9150eC...
2024/08/20 15:34:01 INFO received command=set_charging_amps body=map[charging_amps:3]
2024-08-20T15:34:02+02:00 [warn ] BLE connection attempt failed: failed to find BLE beacon for XP7YGCEK7RB272570 (S20613d5100e9150eC): can't scan: context d
eadline exceeded
2024/08/20 15:34:02 WARN failed to connect to vehicle (A): context deadline exceeded
2024/08/20 15:34:02 INFO retrying in 6 seconds
2024/08/20 15:34:08 DEBU trying connecting to vehicle attempt=3
2024/08/20 15:34:08 DEBU connecting to vehicle (A)...
2024-08-20T15:34:08+02:00 [debug] Reusing existing BLE device
2024-08-20T15:34:08+02:00 [debug] Searching for BLE beacon S20613d5100e9150eC...
2024-08-20T15:34:08+02:00 [debug] Connecting to BLE beacon 74:b8:39:60:94:0e...
2024-08-20T15:34:08+02:00 [info ] Connected to vehicle BLE
2024/08/20 15:34:08 DEBU create vehicle object ...
2024/08/20 15:34:08 DEBU connecting to vehicle (B)...
2024-08-20T15:34:08+02:00 [info ] Starting dispatcher service...
2024/08/20 15:34:08 DEBU start VCSEC session...
2024-08-20T15:34:08+02:00 [info ] Requesting session info from DOMAIN_VEHICLE_SECURITY
2024-08-20T15:34:08+02:00 [debug] TX: 320208023a12121095ba3575c87e7bee0eee1414d22bf9c79a03102f23de90a898c66b7f60084b68042c3a72430a4104a3a786148880a88ff15d3b
6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d
2024-08-20T15:34:09+02:00 [debug] RX: 3212121095ba3575c87e7bee0eee1414d22bf9c73a0208027a5e0820124104052a16de96939b8d1f24deb5ed6ec07595bcee328d90c189781f3e2d
8e78a7f670f7d53c15aa0f8ae04115b426a1cda86c368e8842d00ce4abec541040023cc51a1011c62736e2e98c56c72973b4cf7ff0d125ea70000030076a2432220a20bf6ce9f4c5903f339f9976
06f247e34fc9b5fe109c9c82768ddf6c69cebe41629203102f23de90a898c66b7f60084b68042c3a
2024-08-20T15:34:09+02:00 [info ] [2f23de90a898c66b7f60084b68042c3a] Updated session info for DOMAIN_VEHICLE_SECURITY
2024-08-20T15:34:09+02:00 [debug] TX: 320208023a121210821ee513fc1670fc42f566112943ee129a0310fc899e2a5759a79ce46f5b6f9af2dbd35202d1ee6a80010a430a4104a3a78614
8880a88ff15d3b6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d2a390a1011c62736e2e98c56c72973b4cf7f
f0d1120ce65e2ceb21b5416bbcc1bdeb182125f77000002a10fa07c066c0f02c46ff4164abdd4adcc3
2024-08-20T15:34:09+02:00 [debug] RX: 320208003a020802521f1a1d12160a14a658702985beff76e368258a1a7708f7311436c21802220101
2024-08-20T15:34:09+02:00 [debug] [00] Dropping message to DOMAIN_BROADCAST
2024-08-20T15:34:10+02:00 [debug] RX: 32121210821ee513fc1670fc42f566112943ee123a020802920310fc899e2a5759a79ce46f5b6f9af2dbd3
2024/08/20 15:34:10 DEBU car successfully wakeup
2024/08/20 15:34:10 DEBU start Infotainment session...
2024-08-20T15:34:10+02:00 [info ] Requesting session info from DOMAIN_INFOTAINMENT
2024-08-20T15:34:10+02:00 [info ] Session for DOMAIN_VEHICLE_SECURITY loaded from cache
2024-08-20T15:34:10+02:00 [debug] TX: 320208033a1212109bc1aa750a9f81b80f1e1830ab76f1359a031022fadc35675d8ac8245ee94cdda06a9872430a4104a3a786148880a88ff15d3b
6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d
2024-08-20T15:34:11+02:00 [debug] RX: 321212109bc1aa750a9f81b80f1e1830ab76f1353a0208037a5f08eb01124104944831bdf9849ad5fd19089e77def799ef9779664d7c3eb4d8d5b5
2e16e7f693a21f4a365f19214831f52fe1a8a8098e2b73ba60cc4f1ca714b373b37850cab21a101a019054164c37c886883a40d6539e65251d82050030076a2432220a20f12d4f419a3a5663533f
7e2db47ee47856f6a4240ffe3c7269e27c632e5487b992031022fadc35675d8ac8245ee94cdda06a98
2024-08-20T15:34:11+02:00 [info ] [22fadc35675d8ac8245ee94cdda06a98] Updated session info for DOMAIN_INFOTAINMENT
2024/08/20 15:34:11 INFO connection established
2024/08/20 15:34:11 INFO sending command=set_charging_amps body=map[charging_amps:4]
2024-08-20T15:34:11+02:00 [debug] TX: 320208033a1212109bc1aa750a9f81b80f1e1830ab76f1359a0310d9938496121dfe6202e00903ce8ee1b45207b4c5b1fd5691116a81010a430a41
04a3a786148880a88ff15d3b6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d2a3a0a101a019054164c37c886
883a40d6539e65120ca4c524bae6c110c938e4fb0218ec0125278205002a10857a3dabcfc299baf32a0772a1891b31
2024-08-20T15:34:12+02:00 [debug] RX: 321212109bc1aa750a9f81b80f1e1830ab76f1353a02080352020a00920310d9938496121dfe6202e00903ce8ee1b49a0310401a326f2a27c28af2
ff5ebb172d134c
2024/08/20 15:34:12 INFO successfully executed command=set_charging_amps body=map[charging_amps:4]
2024/08/20 15:34:12 INFO sending command=set_charging_amps body=map[charging_amps:3]
2024-08-20T15:34:12+02:00 [debug] TX: 320208033a1212109bc1aa750a9f81b80f1e1830ab76f1359a0310c786c87ce7edd80e8d8f1f12df3dee9a52077832729c44957e6a81010a430a41
04a3a786148880a88ff15d3b6dd4f183a3b079b7dabf262bc75c807ae14944eee57d90c02f19520365c016ec2742026e988a14717ab7691e4ddd1e7af16a4e534d2a3a0a101a019054164c37c886
883a40d6539e65120c1a567cfc5b233a282d60b10c18ed0125278205002a108770f04da5e7870abf04bf725ca37fdd
2024-08-20T15:34:13+02:00 [debug] RX: 321212109bc1aa750a9f81b80f1e1830ab76f1353a02080352020a00920310c786c87ce7edd80e8d8f1f12df3dee9a9a03103357aa86bbe3206f7e
a00959c59eccfe
2024/08/20 15:34:13 INFO successfully executed command=set_charging_amps body=map[charging_amps:3]
2024/08/20 15:34:41 DEBU connection Timeout
2024/08/20 15:34:41 DEBU disconnect vehicle (A)
2024/08/20 15:34:41 DEBU close connection (A)
2024/08/20 15:34:58 INFO received command=set_charging_amps body=map[charging_amps:2]
2024/08/20 15:34:58 INFO connecting to Vehicle ... 
2024/08/20 15:34:58 DEBU trying connecting to vehicle attempt=1
2024/08/20 15:34:58 DEBU connecting to vehicle (A)... [--> function call: conn, err = ble.NewConnection(ctx, firstCommand.Vin)]
2024-08-20T15:34:58+02:00 [debug] Reusing existing BLE device
2024-08-20T15:34:58+02:00 [debug] Searching for BLE beacon S20613d5100e9150eC...
2024/08/20 15:35:29 INFO received command=set_charging_amps body=map[charging_amps:2]
2024/08/20 15:36:01 INFO received command=set_charging_amps body=map[charging_amps:2]
2024/08/20 15:36:29 INFO received command=set_charging_amps body=map[charging_amps:2]
2024/08/20 15:36:59 INFO received command=set_charging_amps body=map[charging_amps:2]
2024/08/20 15:37:31 INFO received command=set_charging_amps body=map[charging_amps:2]
2024/08/20 15:38:02 INFO received command=set_charging_amps body=map[charging_amps:2]
2024/08/20 15:38:34 INFO received command=set_charging_amps body=map[charging_amps:2]

So the last message from this library is [debug] Searching for BLE beacon S20613d5100e9150eC... ...

Edit: Running on Raspberry Pi 3+

@wimaha
Copy link
Author

wimaha commented Aug 22, 2024

I think I found the issue. It is in the underlaying bluetooth package.

In the ble.go we have the following code:
https://github.com/teslamotors/vehicle-command/blob/d4c0fedc4162bdb88ec2a35ce80aeb16ac686256/pkg/connector/ble/ble.go#L174C2-L186C3

There the ble package is called via client, err := ble.Connect(ctx, filter).

In the ble package we have the following code in the Connect function (glatt.go):
https://github.com/go-ble/ble/blob/8c5522f543335a80e18fc70e704b104cf3fcc606/gatt.go#L125C1-L149C2

So and here is a bug. When the vehicle can't be found, normally ctx2 fires bevor ctx, so that the function Scan returns context deadline exceeded. But sometimes (rarely but randomly) ctx fires and cancels ctx2 (see line 131). In this case Scan return with context canceled. This yields to the line 147 cln, err := Dial(ctx, (<-ch).Addr()) is executed and ist blocking, because of (<-ch).Addr().

So we need to propose a pull request on the ble package to solve this bug.

@wimaha
Copy link
Author

wimaha commented Aug 22, 2024

I've opened a PR on the ble package: go-ble/ble#112

@Jan21493
Copy link

@wimaha: I still have the issue described above when the vehicle can't be found with latest code from 'tesla-control' on a Raspberry PI 3B+. After a while the hci0 interface is busy and requires a reset.

So far I ended up by switching to BLE package from https://github.com/rigado/ble instead of go-ble/ble. The code for BLE has changed a lot and required minor changes in pkg/connector/ble, but now my issue is gone. To me the ble package from rigado looks to be better, but I'm wondering if that code will end up in go-ble some time in the future.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants