azymohliad / watchmate

PineTime smart watch companion app for Linux phone and desktop
GNU General Public License v3.0
136 stars 4 forks source link

Unable to update firmware or flash resources on Mint 20.x (Ubuntu 20.04) with bluetooth 5.53. #19

Closed Jed28 closed 4 months ago

Jed28 commented 1 year ago

I'm trying to update to the new firmware 1.12 but I keep getting an error image

I also get failed to read battery level on boot. I don't care about the battery error but I figured you'll ask me to run it from terminal.

I'm using the flatpack version of watchmate. My system is Linux Mint 20.3, 5.4 kernel. I'm able to flash the firmware using AmazFish so I don't think it's a hardware issue.

When I run from terminal I get. I get no extra info in terminal when the flashing fails.

[INFO  watchmate::ui::devices] InfiniTime (F9:5C:B3:38:90:07) is already connected
[INFO  watchmate::ui] Device connected: F9:5C:B3:38:90:07
[INFO  watchmate::ui] PineTime recognized
[ERROR watchmate::ui::dashboard] Failed to read battery level: Characteristic not found by UUID: 00002a19-0000-1000-8000-00805f9b34fb

(watchmate:2): Gtk-WARNING **: 11:44:13.761: Failed to measure available space: Connection refused

(watchmate:2): Gtk-WARNING **: 11:44:13.769: Failed to measure available space: Connection refused

(watchmate:2): Gtk-WARNING **: 11:44:13.790: Failed to measure available space: Connection refused
[ERROR watchmate::ui::media_player] Media player control session error: Bluetooth operation not supported: Operation is not supported
[ERROR watchmate::ui::dashboard] Failed to create data stream: Characteristic not found by UUID: 00002a19-0000-1000-8000-00805f9b34fb

And a bunch of

The peer-to-peer connection failed: Error when getting information for file “/run/user/1000/gvfsd”: No such file or directory. Falling back to the session bus. Your application is probably missing --filesystem=xdg-run/gvfsd privilege
azymohliad commented 1 year ago

Hey, thanks for such a detailed bug-report.

The missing battery level characteristic seems very similar to this issue (older versions of watchmate rejected to connect when any of expected characteristics was missing), and I still have no idea how it could happen. But I'd assume firmware upgrade problem is tightly related to it.

Having the most detailed debug logs with RUST_LOG=trace environment variable might give some clues:

flatpak run --env=RUST_LOG=trace io.gitlab.azymohliad.WatchMate 2> log.txt

Also, #13 has similar GVFS related errors. I wonder, does time sync work for you?

Jed28 commented 1 year ago

I used the lastest version of WatchMate on flathub, there's no buttons to show version number. I also don't know any commands to show it. I think that cancels out the 1st issue you linked #7 and into #5?

I flashed 1.12 via Gadget Bridge (GB) and GB had connection issues. I tried Amazfish and the only app to work with time sync was WatchMate. GB issue once connected it timesynced. I haven't tested watchmate and infinitime 1.11 timesync, let me know if I should? AmazFish timesync issue with Infinitime 1.12.

I've rolled back to infinitime 1.11 and that's my log.txt. The filesystem mount errors are cifs network and ext4 local fstab mounts, I've omitted some due to privacy but the others show it well. My local Bluez version is 5.53not sure that if that helps. I don't use flatpaks often.

Thanks for all your hard work with WatchMate, it's my favourite of the Linux companion apps.

azymohliad commented 1 year ago

I used the lastest version of WatchMate on flathub, there's no buttons to show version number. I also don't know any commands to show it. I think that cancels out the 1st issue you linked #7 and into #5?

No no, I didn't mean that you have an outdated version of WatchMate. I mentioned about older version just to explain, that even though the Gitlab issue #7 resulted in connection failure, the fact that you can connect doesn't rule it out, because that older WatchMate version would reject connecting in your case too. But the underlying problem seems very similar: all characteristics are present, except the battery level. This is very strange.

Gitlab's #5 isn't relevant anymore (previously WatchMate had a button to start/stop bluetooth scanning manually).

I flashed 1.12 via Gadget Bridge (GB) and GB had connection issues. I tried Amazfish and the only app to work with time sync was WatchMate. https://github.com/InfiniTimeOrg/InfiniTime/issues/1724#issuecomment-1493457330once connected it timesynced. I haven't tested watchmate and infinitime 1.11 timesync, let me know if I should? https://github.com/piggz/harbour-amazfish/issues/260.

About time sync, no need to retry with 1.11. I was just curious if it could be related to the GVFS warning that both you and #13 have. But if it works for you, then that's not it. AmazFish timesync issue with 1.12 is due to the BLE protocol update, so #13 isn't related to that too. But thanks for the info. It helps to rule out GVFS for #13.

I've rolled back to infinitime 1.11 and that's my log.txt. The filesystem mount errors are cifs network and ext4 local fstab mounts, I've omitted some due to privacy but the others show it well. My local bluez version is 5.53 not sure that if that helps. I don't use flatpaks often.

Unfortunately, there's nothing that could give me any additional clues in the logs :/ I'm not familiar enough with bluez to make any useful assumptions from those errors. Bluez version is always good to know tho. But wait, you've said you rolled back to 1.11 to collect the logs. Does it mean the issue doesn't occur for you on 1.12?

Thanks for all your hard work with WatchMate, it's my favourite of the Linux companion apps.

Thank you! It's really heartwarming to receive comments like this <3

Jed28 commented 1 year ago

Does it mean the issue doesn't occur for you on 1.12?

I got the same errors when trying to flash resources on 1.12.

I'll spin up a live USB of the latest Mint 21.1 and EndeavourOS. That should rule out any local issues and out of date packages.

svmhdvn commented 9 months ago

I'm getting the same error on v0.4.6 on alpine linux aarch64, here's the trace log:

[TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE | WRITABLE
[DEBUG reqwest::connect] starting new connection: https://api.github.com/
[TRACE bluer::session] Connected to D-Bus with unique name :1.76
[TRACE mio::poll] registering event source with poller: token=Token(1), interests=READABLE
[TRACE bluer::session] Starting event loop for :1.76
[TRACE bluer::adapter] /org/bluez/hci0: org.bluez.Adapter1.Powered := true
[TRACE bluer::gatt::local] Publishing application at /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba
[TRACE bluer::gatt::local] Publishing service at /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0
[TRACE bluer::gatt::local] Publishing characteristic at /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0/char0
[TRACE bluer::gatt::local] Registering application at /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba
[TRACE mio::poll] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
[TRACE bluer::gatt::local] /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0: org.bluez.GattService1.UUID = Some("00001805-0000-1000-8000-00805f9b34fb")
[TRACE bluer::gatt::local] /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0: org.bluez.GattService1.Primary = Some(true)
[TRACE bluer::gatt::local] /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0/char0: org.bluez.GattCharacteristic1.UUID = Some("00002a2b-0000-1000-8000-00805f9b34fb")
[TRACE bluer::gatt::local] /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0/char0: org.bluez.GattCharacteristic1.WriteAcquired = None
[TRACE bluer::gatt::local] /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0/char0: org.bluez.GattCharacteristic1.NotifyAcquired = None
[TRACE bluer::gatt::local] /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0/char0: org.bluez.GattCharacteristic1.Flags = Some(["read"])
[TRACE bluer::gatt::local] /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0: org.bluez.GattService1.Handle <- 30
[TRACE bluer::gatt::local] /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0/char0: org.bluez.GattCharacteristic1.Handle <- 32
[TRACE bluer::device] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72: org.bluez.Device1.Name = "InfiniTime"
[TRACE bluer::device] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72: org.bluez.Device1.Connected = true
[TRACE bluer::device] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72: org.bluez.Device1.Alias = "InfiniTime"
[TRACE bluer::device] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72: org.bluez.Device1.RSSI = None
[INFO  watchmate::ui::devices] InfiniTime (CF:0F:DD:0D:2E:72) is already connected
[INFO  watchmate::ui] Device connected: CF:0F:DD:0D:2E:72
[TRACE bluer::session] Adding event subscription for /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72 with child_objects=false
[TRACE bluer::device] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72: org.bluez.Device1.ServicesResolved = true
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char002e: org.bluez.GattCharacteristic1.UUID = "00000008-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char0030: org.bluez.GattCharacteristic1.UUID = "00000009-78fc-48fe-8e23-433b3a1942d0"
[TRACE want] signal: Want
[TRACE want] signal found waiting giver, notifying
[TRACE want] poll_want: taker wants!
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char0032: org.bluez.GattCharacteristic1.UUID = "0000000a-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char0020: org.bluez.GattCharacteristic1.UUID = "00000002-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char0036: org.bluez.GattCharacteristic1.UUID = "0000000c-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char0022: org.bluez.GattCharacteristic1.UUID = "00000004-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char0028: org.bluez.GattCharacteristic1.UUID = "00000006-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char0026: org.bluez.GattCharacteristic1.UUID = "00000005-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char002c: org.bluez.GattCharacteristic1.UUID = "00000007-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char001d: org.bluez.GattCharacteristic1.UUID = "00000001-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char002a: org.bluez.GattCharacteristic1.UUID = "00000007-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char0034: org.bluez.GattCharacteristic1.UUID = "0000000b-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service001c/char0024: org.bluez.GattCharacteristic1.UUID = "00000003-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0054/char0055: org.bluez.GattCharacteristic1.UUID = "00002a19-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0066/char0069: org.bluez.GattCharacteristic1.UUID = "adaf0200-4669-6c65-5472-616e73666572"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0066/char0067: org.bluez.GattCharacteristic1.UUID = "adaf0100-4669-6c65-5472-616e73666572"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service000a/char000d: org.bluez.GattCharacteristic1.UUID = "00002a24-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service000a/char000b: org.bluez.GattCharacteristic1.UUID = "00002a29-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service000a/char0013: org.bluez.GattCharacteristic1.UUID = "00002a27-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service000a/char000f: org.bluez.GattCharacteristic1.UUID = "00002a25-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service000a/char0015: org.bluez.GattCharacteristic1.UUID = "00002a28-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service000a/char0011: org.bluez.GattCharacteristic1.UUID = "00002a26-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005b/char005c: org.bluez.GattCharacteristic1.UUID = "00002a37-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0038/char003b: org.bluez.GattCharacteristic1.UUID = "00040002-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0038/char0039: org.bluez.GattCharacteristic1.UUID = "00040001-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0058/char0059: org.bluez.GattCharacteristic1.UUID = "00002a06-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service004c/char0052: org.bluez.GattCharacteristic1.UUID = "00001534-1212-efde-1523-785feabcd123"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service004c/char004d: org.bluez.GattCharacteristic1.UUID = "00001532-1212-efde-1523-785feabcd123"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service004c/char004f: org.bluez.GattCharacteristic1.UUID = "00001531-1212-efde-1523-785feabcd123"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005f/char0060: org.bluez.GattCharacteristic1.UUID = "00030001-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005f/char0063: org.bluez.GattCharacteristic1.UUID = "00030002-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0006/char0007: org.bluez.GattCharacteristic1.UUID = "00002a05-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service003d/char0044: org.bluez.GattCharacteristic1.UUID = "00010004-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service003d/char0042: org.bluez.GattCharacteristic1.UUID = "00010003-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service003d/char0040: org.bluez.GattCharacteristic1.UUID = "00010002-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service003d/char003e: org.bluez.GattCharacteristic1.UUID = "00010001-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0046/char0047: org.bluez.GattCharacteristic1.UUID = "00002a46-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0046/char0049: org.bluez.GattCharacteristic1.UUID = "00020001-78fc-48fe-8e23-433b3a1942d0"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0017/char001a: org.bluez.GattCharacteristic1.UUID = "00002a2b-0000-1000-8000-00805f9b34fb"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0017/char0018: org.bluez.GattCharacteristic1.UUID = "00002a0f-0000-1000-8000-00805f9b34fb"
[DEBUG infinitime::bluetooth::device] Characteristics: [
        00000008-78fc-48fe-8e23-433b3a1942d0,
        00001532-1212-efde-1523-785feabcd123,
        00010003-78fc-48fe-8e23-433b3a1942d0,
        00010001-78fc-48fe-8e23-433b3a1942d0,
        00002a2b-0000-1000-8000-00805f9b34fb,
        00010004-78fc-48fe-8e23-433b3a1942d0,
        00000006-78fc-48fe-8e23-433b3a1942d0,
        00000001-78fc-48fe-8e23-433b3a1942d0,
        00002a24-0000-1000-8000-00805f9b34fb,
        00002a25-0000-1000-8000-00805f9b34fb,
        00000003-78fc-48fe-8e23-433b3a1942d0,
        00002a37-0000-1000-8000-00805f9b34fb,
        00040001-78fc-48fe-8e23-433b3a1942d0,
        00001534-1212-efde-1523-785feabcd123,
        00000005-78fc-48fe-8e23-433b3a1942d0,
        00002a28-0000-1000-8000-00805f9b34fb,
        00040002-78fc-48fe-8e23-433b3a1942d0,
        00002a19-0000-1000-8000-00805f9b34fb,
        0000000a-78fc-48fe-8e23-433b3a1942d0,
        00020001-78fc-48fe-8e23-433b3a1942d0,
        00030002-78fc-48fe-8e23-433b3a1942d0,
        00002a0f-0000-1000-8000-00805f9b34fb,
        00002a05-0000-1000-8000-00805f9b34fb,
        00000009-78fc-48fe-8e23-433b3a1942d0,
        00000004-78fc-48fe-8e23-433b3a1942d0,
        0000000b-78fc-48fe-8e23-433b3a1942d0,
        adaf0100-4669-6c65-5472-616e73666572,
        00002a27-0000-1000-8000-00805f9b34fb,
        00001531-1212-efde-1523-785feabcd123,
        00010002-78fc-48fe-8e23-433b3a1942d0,
        00002a26-0000-1000-8000-00805f9b34fb,
        00000002-78fc-48fe-8e23-433b3a1942d0,
        00002a29-0000-1000-8000-00805f9b34fb,
        00002a46-0000-1000-8000-00805f9b34fb,
        00000007-78fc-48fe-8e23-433b3a1942d0,
        adaf0200-4669-6c65-5472-616e73666572,
        00002a06-0000-1000-8000-00805f9b34fb,
        00030001-78fc-48fe-8e23-433b3a1942d0,
        0000000c-78fc-48fe-8e23-433b3a1942d0,
    ]
[INFO  watchmate::ui] PineTime recognized
[TRACE bluer::session] Adding event subscription for /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72 with child_objects=false
[TRACE bluer::device] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72: org.bluez.Device1.Alias = "InfiniTime"
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service000a/char0011: org.bluez.GattCharacteristic1.ReadValue ({"offset": Variant(0)},)
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service000a/char0011: org.bluez.GattCharacteristic1.ReadValue (...) -> Ok(([49, 46, 49, 51, 46, 48],))
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0054/char0055: org.bluez.GattCharacteristic1.ReadValue ({"offset": Variant(0)},)
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0054/char0055: org.bluez.GattCharacteristic1.ReadValue (...) -> Ok(([80],))
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005b/char005c: org.bluez.GattCharacteristic1.ReadValue ({"offset": Variant(0)},)
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005b/char005c: org.bluez.GattCharacteristic1.ReadValue (...) -> Ok(([0, 0],))
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005f/char0060: org.bluez.GattCharacteristic1.ReadValue ({"offset": Variant(0)},)
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005f/char0060: org.bluez.GattCharacteristic1.ReadValue (...) -> Ok(([0, 0, 0, 0],))
[TRACE bluer::session] Starting new single session for /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0054/char0055
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0054/char0055: org.bluez.GattCharacteristic1.StartNotify ()
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0054/char0055: org.bluez.GattCharacteristic1.StartNotify (...) -> Ok(())
[TRACE bluer::session] Adding event subscription for /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0054/char0055 with child_objects=false
[TRACE bluer::session] Starting new single session for /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005b/char005c
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005b/char005c: org.bluez.GattCharacteristic1.StartNotify ()
[TRACE want] signal: Want
[TRACE want] signal found waiting giver, notifying
[TRACE want] signal: Want
[TRACE want] poll_want: taker wants!
[TRACE mio::poll] deregistering event source from poller
[TRACE want] signal: Closed
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005b/char005c: org.bluez.GattCharacteristic1.StartNotify (...) -> Ok(())
[TRACE bluer::session] Adding event subscription for /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005b/char005c with child_objects=false
[TRACE bluer::session] Event: PropertiesChanged { object: Path("/org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005b/char005c\0"), interface: "org.bluez.GattCharacteristic1", changed: {"Notifying": Variant(true)} }
[TRACE bluer::session] Starting new single session for /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005f/char0060
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005f/char0060: org.bluez.GattCharacteristic1.StartNotify ()
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005f/char0060: org.bluez.GattCharacteristic1.StartNotify (...) -> Err(D-Bus error: Operation is not supported (org.bluez.Error.NotSupported))
[TRACE bluer] DBus error org.bluez.Error.NotSupported: Operation is not supported
[ERROR watchmate::ui::dashboard] Failed to create data stream: Bluetooth operation not supported: Operation is not supported
[DEBUG reqwest::connect] starting new connection: https://api.github.com/
[TRACE mio::poll] registering event source with poller: token=Token(16777218), interests=READABLE | WRITABLE
[TRACE want] signal: Want
[TRACE want] signal found waiting giver, notifying
[TRACE want] poll_want: taker wants!
[TRACE want] signal: Want
[TRACE want] signal: Want
[DEBUG reqwest::async_impl::client] redirecting 'https://api.github.com/repos/InfiniTimeOrg/InfiniTime/releases/assets/114166516' to 'https://objects.githubusercontent.com/github-production-release-asset-2e65be/226167620/2129553b-4543-4810-be22-44fba6a22947?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAIWNJYAX4CSVEH53A%2F20231010%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20231010T163505Z&X-Amz-Expires=300&X-Amz-Signature=1cdf359f69afaf442eaac7430566370f2d1b47b9b5ec38ec6ff02708b2e91784&X-Amz-SignedHeaders=host&actor_id=0&key_id=0&repo_id=226167620&response-content-disposition=attachment%3B%20filename%3Dinfinitime-resources-1.13.0.zip&response-content-type=application%2Foctet-stream'
[DEBUG reqwest::connect] starting new connection: https://objects.githubusercontent.com/
[TRACE mio::poll] registering event source with poller: token=Token(3), interests=READABLE | WRITABLE
[TRACE want] signal: Want
[TRACE want] signal found waiting giver, notifying
[TRACE want] poll_want: taker wants!
[TRACE want] signal: Want
[TRACE want] signal found waiting giver, notifying
[TRACE want] signal: Want
[TRACE want] poll_want: taker wants!
[TRACE mio::poll] deregistering event source from poller
[TRACE want] signal: Closed
[TRACE mio::poll] deregistering event source from poller
[TRACE want] signal: Closed
[INFO  infinitime::bluetooth::device::fs] Making dir: /fonts
[TRACE bluer::session] Starting new single session for /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0066/char0069
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0066/char0069: org.bluez.GattCharacteristic1.StartNotify ()
[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service0066/char0069: org.bluez.GattCharacteristic1.StartNotify (...) -> Err(D-Bus error: Operation is not supported (org.bluez.Error.NotSupported))
[TRACE bluer] DBus error org.bluez.Error.NotSupported: Operation is not supported
[TRACE bluer::gatt::local] Unregistering application at /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba
[TRACE bluer::gatt::local] Unpublishing /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0/char0
[TRACE bluer::gatt::local] Unpublishing /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba/service0
[TRACE bluer::gatt::local] Unpublishing /org/bluez/bluer/gatt/app/874deb8bca0b43348b080cffcc5f7fba
azymohliad commented 9 months ago

Thanks for the log. Hm..

[TRACE bluer::gatt::remote] /org/bluez/hci0/dev_CF_0F_DD_0D_2E_72/service005f/char0060: org.bluez.GattCharacteristic1.StartNotify (...) -> Err(D-Bus error: Operation is not supported (org.bluez.Error.NotSupported))

It fails to start notification session on a particular BLE characteristic, but your Bluez version or bluetooth adapter driver definitely supports that, because it started notification sessions for other characteristics. I'm not sure how Bluez assigns those 2-byte IDs to services and characteristics in the logs, but there's only one notification session in FW update procedure, so I assume it's this line failing.

Unfortunately, I've no idea what you could try...

kronn commented 5 months ago

Just to add to this: I have a similar issue as the battery level could not be read and flashing firmware (or resources) does not work and is aborted with the above error-message.

I assume that bluetuith reads the battery-level over some generic BT-way. I have the feeling (but no hard knowledge yet) that some profile for file-exchange is not activated somehow.

So far, I am left with

Another thing I have is watchmate-log-redacted.txt, from which I only removed some (hopefully unrelated) devices.

Do you have or know some tool to interact with bluetooth-devices? Something where I could try to find out if another UUID is the battery-level on my device? Or where I could try to determine the used profile/availables services? I really want to get my watch working again, and if that means learning rust and inspecting bluetooth, so be it. :-)

azymohliad commented 5 months ago

Thanks for kind words about Watchmate and a detailed description.

It is really interesting that Bluetuith can read the battery level. Means that the BLE characteristic is actually there, I didn't expect that. But it's still no less mysterious why Bluer cannot find it.

Afaik, the battery level UUID cannot be different, as it is a standard characteristic defined by Bluetooth Specification (see chapter 3.8). That's why it can be read by other software, not necessarily InfiniTime companion apps (as you correctly pointed out, over some generic BT way). File transfer is not standard btw, InfiniTime uses slightly modified Adafruit File Transfer protocol.

I just realised bluetoothctl (the official Bluez CLI) can examine all UUIDs and read the battery level too:

# Connect:
bluetoothctl connect <MAC-address>
# Get general device info
bluetoothctl info
# List all UUIDs (there's gonna be a lot):
bluetoothctl gatt list-attributes
# Find battery service and characteristics:
bluetoothctl gatt.list-attributes | grep -B3 Battery
# Battery service info:
bluetoothctl gatt.attribute-info 0000180f-0000-1000-8000-00805f9b34fb
# Battery level:
bluetoothctl gatt.attribute-info 00002a19-0000-1000-8000-00805f9b34fb

Could you pls share the outputs (except maybe full list-attributes output :D)?. If you are connected to multiple devices, you might need to add PineTime MAC address to each command to filter the output for it only. There's also an interactive console if you launch bluetoothctl with no arguments.

kronn commented 5 months ago

So I went down the rabbit-hole and could not easily determine the battery-level from bluetoothctl. It seems like the whole battery-service is not exposed. As bluetuith can read it (after connecting), I suspect that there is another profile being used to retrieve that inforamtion. I could however read the firmware-version from the watch, so at least something works.

I intentionally left the full list of attributes in the output, because it might help with debugging this: bluetoothctl-log.txt

The two attributes you mentioned, the battery service and its level, are not present in the list. Therefore it makes sense that they cannot be read.

As for the file transfer: I did not check if those are present or different in my firmware-version (1.14)

Jed28 commented 5 months ago

I've did a big update on my system over xmas break Mint 20 to 21. Today I updated to latest Mint 21.3 and watchmate to 0.5.1. I had issues testing in a live usb with arch, my bluetooth adapter wouldn't work.

After the update, I successfully flashed resources and the latest firmware. It also showed battery level on the main screen.

Jed28 commented 5 months ago

Gadgetbridge could flash the firmware, but cannot connect since (it goes downhill from here)

@kronn I found I had to disconnect the device from Gadgetbride (GB) and specifically go into GB's menu then click on quit. Check that pairing within your phone's bluetooth menu has it removed as well. Reopen GB and start pairing again. I've also moved to GB nightly to get the weather working. Otherwise I couldn't pair with the watch on changing firmware versions.

azymohliad commented 4 months ago

So it might be the issue with older bluez or its dependencies then. @kronn what is your bluetoothctl --version? Sorry for the long silence btw, I didn't have any ideas, and I thought I should look at bluetuith code first to understand how it reads the battery level, but still didn't manage to do it.

Jed28 commented 4 months ago

All good, I'm super stoked it's all working now. Here's my current version.

$ bluetoothctl --version
bluetoothctl: 5.64
kronn commented 4 months ago

@Jed28 Sadly, this did not work. My phone says that it is connected, but nothing else. GB does not show a tile for the watch.

Watchmate brings me the furthest, right now. Ideally, I can flash the firmware again and rescue the device somehow. Plan X (because, after W(atchmate) comes X, right?) would be acceptance that I just have a fancy watch with long battery-life, Plan Y (because Y not) would be a new watch.

@azymohliad first of all: no worries with a little radio silence. You provide this for free, and I have no right to demand anything. Any help with this is however highly appreciated.

I have a slightly older version on my machine:

❯ bluetoothctl --version
bluetoothctl: 5.53

I run Ubuntu 20.04.6 LTS until I get a new machine, which will then be Arch or so. I do not feel like breaking my work machine too early. :-)

Watchmate runs (fine) as flatpak.

It does not seem like a generic InfiniTime 1.14-issue, as others seem to have a working installation. I feel like something went wrong with the firmware upgrade and I validated/locked too soon. Hence, plans X and Y above.

That being said: I am a tinkerer and would like to solve this issue because it feels somewhat doable.

kronn commented 4 months ago

I think I need to test this from a different machine, maybe my setup is too old. I might have access to one in a few weeks.

azymohliad commented 4 months ago

Yeah, I think it makes sense to try a more recent distro first of all. Maybe a live bootable from USB if you're not ready to upgrade yet but don't want to wait.

If this turns out to be some firmware corruption issue, as a last resort you could unseal your watch, flash it over the wire, and then glue it back. But I strongly doubt it's a corrupted firmware. PineTime bootloader verifies the checksum before applying a new image, so you wouldn't be able to boot a faulty one.

Jed28 commented 4 months ago

@Jed28 Sadly, this did not work. My phone says that it is connected, but nothing else. GB does not show a tile for the watch.

I had the same issue, have you tried GB nightly build? Every time I've updated my watch firmware, I had issues connecting. There's other variations like unpairing within phone bluetooth, then disconnecting, quiting in GB. Oddly enough, after flashing the firmware with Watchmate, it connected easily with GB nightly.

I do not feel like breaking my work machine too early. :-)

That's why I updated over the holidays, It's a personal and work machine.

When I made the bug report I was running Mint 20.3 (Ubuntu 20.04) and had bluetooth version 5.53. I called it Bluez but I meant bluetooth.

Jed28 commented 4 months ago

Updated the title to help others with the same setup find the issue. There's 2 common factors with my old setup and @kronn 's setup, Ubuntu and Bluetooth version.

azymohliad commented 4 months ago

Nice, thanks!

I called it Bluez but I meant bluetooth.

You were actually correct, the project is called Bluez, as well as distro packages usually. It's just that its service name is bluetooth and the CLI is bluetoothctl. bluetooth package in Ubuntu seems to be just a meta-package wrapper for bluez.

kronn commented 4 months ago

Upgrading the machine I have was not recommended to me, especially since my device is deemed EOL anyway.

The current state of things we know makes me hopeful that drastic measures like disassembly of the watch are not needed.

I'll look into a Linux on a USB-drive and try a newer bluez. Otherwise, I can still sing the Blues 😉

kronn commented 4 months ago

Also, @Jed28, yes, I switched to GB nightly very soon after I got my PineTime, which helped with infinitime 1.12 and 1.13. After the upgrade to 1.14 something went wrong. If everything goes as planned, I will only update the watch with Watchmate and use Gadgetbridge only for daily use and such.

kronn commented 4 months ago

So, I started a PopOS/Ubuntu 22.04 liveusb-setup. Here is what I now know:

So, since GB does not want to play along, I will postpone that problem to next week. The battery-level and the ... "secure location" of my charger demand to disable BT anyway.

However, I feels really nice to have a way to update the watch. Thanks for the the journey.

Side note: since I now contributed (in a way) to a rust-project, I can put "Rust" on my LinkedIn, right? :joy:

kronn commented 4 months ago

As for the issue of broken connection via bluetooth 5.53: is there anything we can need or should do to fix this issue?

Does bluetuith bring its own bluetooth-stack?

Is there a "caniuse" or bluetooth-features?

kronn commented 4 months ago

Is there a "caniuse" or bluetooth-features?

Oh wow...

https://caniuse.com/?search=bluetooth

I will pretend I did not see that.

azymohliad commented 4 months ago

Nice! Another confirmation it's related to bluez version or its dependencies.

Does bluetuith bring its own bluetooth-stack?

That's a good question, but no. Looks like it talks to it over D-Bus like everything else. It probably wouldn't be good idea for an app to bring its own bluetooth stack because bluetooth devices are system-wide resources, so you need a single service to manage them. I don't know if it's even technically possible (parts of bluez are kernel-space).

Regarding the battery level, the main difference is that Bluetuith seems to read it via special D-Bus interface org.bluez.Battery1, rather than directly from the BLE characteristic. You can try to verify if you can read it from D-Bus on your Ubuntu 20.04 with the following command (replace dev_XX_XX_XX_XX_XX_XX with your PineTime BLE MAC address):

busctl get-property org.bluez /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX org.bluez.Battery1 Percentage

I don't think there's a point in switching to this D-Bus interface in Watchmate. It wouldn't help with firmware updates on bluez 5.53 anyway, and the implementation would be more complicated, because bluer (bluez library used by Watchmate) doesn't seem expose access this D-Bus interface.

As for the issue of broken connection via bluetooth 5.53: is there anything we can need or should do to fix this issue?

I don't think anything can be done on the Watchmate side. As for bluez, it's been fixed in newer versions, so I guess if it was considered critical enough to be backported to 5.53 then it would be.

Is there a "caniuse" or bluetooth-features? https://caniuse.com/?search=bluetooth

It would be nice if there's anything like this for bluez versions, but I'm not aware. There's the changelog tho.

Jed28 commented 4 months ago

Congrats @kronn ! Thanks @azymohliad Watchmate is great it's clean, simple, very easy to use and my favourite desktop companion app. You should add a "buy me a coffee" link.

azymohliad commented 4 months ago

Thank you! It's a great pleasure to hear that <3 I don't want to set up donations for now, because I work on Watchmate very rarely and it will add some pressure to deliver more. Maybe some day, if I ever start working on it more actively for a long time.

kronn commented 4 months ago

Just for completeness and those wanting have a happy end. I managed to downgrade my pinetime with the help of watchmate (with a newer Bluetooth-stack).

Now both gadgetbridge and sleep for android can connect again.

And so he tracked his movements happily ever after...

(black screen)

(ominous silence)

By now I suspect that my phone has an outdated or buggy Bluetooth-stack. This then lead all apps on my phone to having difficulties connecting.