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

Playback jitters with Samsung Galaxy Buds2 Pro over LE Audio #713

Open
tlvince opened this issue Jan 7, 2024 · 34 comments
Open

Playback jitters with Samsung Galaxy Buds2 Pro over LE Audio #713

tlvince opened this issue Jan 7, 2024 · 34 comments

Comments

@tlvince
Copy link

tlvince commented Jan 7, 2024

Per pipewire #3762, I experience frequent jitters/short breaks in playback using the Samsung Galaxy Buds2 Pro over LE Audio/bap. I can reproduce this reliably when a LE mouse (MX Master) is connected at the same time and is moved.

Thanks to analysis from @pv:

[...] the controller (AX210) seems to fail to keep up with the schedule required for ISO traffic, the Number of Completed Packets events for the ISO traffic start to lag more and more (cf btmon -r Latency: values) until the socket buffer fills up.

x

The kernel appears to fail to send packets to the adapter fast enough, it should be sending @ 1 packet / 10ms for each channel, but it slows down and then fails and this pattern repeats

I've tried a few different buffer sizes on the pipewire side to no avail.

@Vudentz
Copy link
Contributor

Vudentz commented Jan 8, 2024

btmon --analyze dump.btsnoop:

  Found LE-ISO connection with handle 2305
        Address: 00:00:00:00:00:00 (OUI 00-00-00)
        RX packets: 3050/3050
        RX Latency: 0-22 msec (~9 msec)
        RX size: 4-124 octets (~105 octets)
        RX speed: ~84 Kb/s

                                                                               
  1000 +-+-----------------------------------------------------------------+   
        +|                       + |                                       |   
        +|                       | |                            RX +-----+ |   
        +|                       | |                                       |   
        +|       +               | |  +                                    |   
   100 +-|       |  +         +  | |  |          + +                       |   
        +|    +  |  |         |  | |  |       +  | |  +                    |   
        +|  + |  |  |         |  | |  |       |  | |  |                    |   
        +|  | |  |  | +    +  |  | |  |  +    |  | |  |                    |   
        +|  | |  |  | |    |  |  | |  |  |    |  | |  |  +                 |   
         |  | |  |  | |  + |  |  | |  |  | +  |  | |  |  | +               |   
    10 +-|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |               |   
        +|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  +            |   
        +|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |            |   
        +|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |            |   
        +|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |            |   
     1 +-|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |    +       |   
        +|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |    |       |   
        ++-----------------------------------------------------------------+   
         +            +            +             +            +            +   
         0            5            10            15           20           25  
                                    Latency (ms)                               
                                                                               
        TX packets: 2087/2086
        TX Latency: 4-62 msec (~7 msec)
        TX size: 124-124 octets (~124 octets)
        TX speed: ~53 Kb/s

                                                                               
  10000 +-+----------------------------------------------------------------+   
         +|                                                                |   
         +|                                                     TX +-----+ |   
         +|                                                                |   
   1000 +-|      +                                                         |   
         +|      |                                                         |   
         +|      |                                               +         |   
         +|      |                                               |         |   
    100 +-|      |                                               |         |   
         +|    + |                                               |         |   
         +|    |++      +        +         +        +        +   |+        |   
         +|    |||      |        |         |        |        |   ||        |   
          |    |||      |        |         |        |        |   ||        |   
     10 +-|    |||      |        |         |        |        |   ||        |   
         +|   +|||      |        |         |        |        |  +||        |   
         +|   ||||     +|+ ++    |  +      |     + +|     +  |  |||++      |   
          |   ||||     ||| ||    |  |      |     | ||     |  |  |||||      |   
      1 +-|   ||||     ||| || + +|+ | + + ++ +   | ||     |  |+ |||||      |   
         ++----------------------------------------------------------------+   
          +        +         +        +        +        +         +        +   
          0        10        20       30       40       50        60       70  
                                    Latency (ms)                               
                                                                               
  Found LE-ISO connection with handle 2304
        Address: 00:00:00:00:00:00 (OUI 00-00-00)
        RX packets: 3008/3008
        RX Latency: 0-22 msec (~9 msec)
        RX size: 4-124 octets (~105 octets)
        RX speed: ~84 Kb/s

                                                                               
  1000 +-+-----------------------------------------------------------------+   
        +|                       + |                                       |   
        +|                       | |                            RX +-----+ |   
        +|                       | |                                       |   
        +|       +               | |               +                       |   
   100 +-|    +  |            +  | |  +            |  +                    |   
        +|    |  |  +         |  | |  |          + |  |                    |   
        +|  + |  |  |         |  | |  |          | |  |                    |   
        +|  | |  |  |    +    |  | |  |       +  | |  |                    |   
        +|  | |  |  | +  | +  |  | |  |  + +  |  | |  |  +                 |   
         |  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | +               |   
    10 +-|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  +            |   
        +|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |            |   
        +|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |            |   
        +|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |            |   
        +|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |            |   
     1 +-|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |    +       |   
        +|  | |  |  | |  | |  |  | |  |  | |  |  | |  |  | |  |    |       |   
        ++-----------------------------------------------------------------+   
         +            +            +             +            +            +   
         0            5            10            15           20           25  
                                    Latency (ms)                               
                                                                               
        TX packets: 2087/2086
        TX Latency: 4-89 msec (~7 msec)
        TX size: 124-124 octets (~124 octets)
        TX speed: ~53 Kb/s

                                                                               
  10000 +-+----------------------------------------------------------------+   
         +|                                                                |   
         +|                                                     TX +-----+ |   
         +|                                                                |   
   1000 +-|    +                                                           |   
         +|    |                                                           |   
         +|    |                                     +                     |   
         +|    |                                     |                     |   
    100 +-|    |                                     |                     |   
         +|   +|                                     |                     |   
         +|   +|+    +      +      +       +      +  +                     |   
         +|   |||    |      |      |       |      |  |                     |   
          |   |||    |      |      |       |      |  |                     |   
     10 +-|   |||    |      |      |       |      |  |                     |   
         +|  +|||    |      |      |       |      |  |                     |   
         +|  ||||   +|+++   | +    |       |      | +|++                   |   
          |  ||||   |||||   | |    |       |      | ||||                   |   
      1 +-|  ||||   |||||   |+| ++ + +  + +|    + + ||||    +    +        +|   
         ++----------------------------------------------------------------+   
          +      +      +       +      +      +      +       +      +      +   
          0      10     20      30     40     50     60      70     80     90  
                                    Latency (ms)

The RX is pretty much the same but the TX of the second connection is falling behind (@pv not sure how you plot them together though, might be a good addition to btmon --analyze), also there seems to be a considerable about of packets failing to be delivered before the presentation delay (which I assume is 40ms?).

@tlvince
Copy link
Author

tlvince commented Jan 8, 2024

Thanks for having a look @Vudentz. What'd be your suggestion here? Presumably, this'd need addressing at the controller (AX210) level?

@Vudentz
Copy link
Contributor

Vudentz commented Jan 8, 2024

Thanks for having a look @Vudentz. What'd be your suggestion here? Presumably, this'd need addressing at the controller (AX210) level?

Yes, something at link-layer is not quite right it seems.

@tlvince
Copy link
Author

tlvince commented Jan 8, 2024

Where'd be the best place to report this?

@Vudentz
Copy link
Contributor

Vudentz commented Jan 8, 2024

Where'd be the best place to report this?

I talking to our (Intel) firmware folks, looks like it is not a good idea to have the ISO interval at 10ms if the HID is at 7.5ms since their intervals would eventually collide, now where we put such a policy may be the problem, because it is pipewire that is selecting 10ms interval perhaps it should check if there is anything else already connected, like HID, that said when it is the opposite we would have to adjust the HID to 10ms if there is already an ISO at 10ms.

@Vudentz
Copy link
Contributor

Vudentz commented Jan 8, 2024

Where'd be the best place to report this?

I talking to our (Intel) firmware folks, looks like it is not a good idea to have the ISO interval at 10ms if the HID is at 7.5ms since their intervals would eventually collide, now where we put such a policy may be the problem, because it is pipewire that is selecting 10ms interval perhaps it should check if there is anything else already connected, like HID, that said when it is the opposite we would have to adjust the HID to 10ms if there is already an ISO at 10ms.

According to some folks we shall prefer 7.5ms whenever possible since its better for coexisting scenarious and it does have the added benefit of being lower latency as well.

@pv
Copy link
Contributor

pv commented Jan 8, 2024

Well pipewire can choose 7.5ms as well, https://gitlab.freedesktop.org/pvir/pipewire/-/commit/6510420dd12546021c5d4924fd1a85a91ca5bf90 and maybe @tlvince can try to see if that helps.

If the sound server has to choose 10ms in some cases and 7.5ms in other cases depending on what else is connected, then it sounds like BlueZ should decide or at least suggest the right value to the sound server. Maybe PreferredFrameDuration in SelectProperties or something like that.

@Vudentz
Copy link
Contributor

Vudentz commented Jan 8, 2024

Well pipewire can choose 7.5ms as well, gitlab.freedesktop.org/pvir/pipewire/-/commit/6510420dd12546021c5d4924fd1a85a91ca5bf90 and maybe @tlvince can try to see if that helps.

If the sound server has to choose 10ms in some cases and 7.5ms in other cases depending on what else is connected, then it sounds like BlueZ should decide or at least suggest the right value to the sound server. Maybe PreferredFrameDuration in SelectProperties or something like that.

Yeah, we can do something like that, the tricky part is if the peripheral asks to change the ACL interval later, well perhaps we should reject that.

@tlvince
Copy link
Author

tlvince commented Jan 9, 2024

The immediate issue (of playback breaking up) has certainly improved with https://gitlab.freedesktop.org/pvir/pipewire/-/commit/6510420dd12546021c5d4924fd1a85a91ca5bf90. I can't reliably trigger it by moving the mouse as I could before.

However, the general usability is flakey. My initial experience was the ear buds often would fail to connect and/or be listed as a playback device/sink. Restarting bluetooth.service helped, but then the microphone/source wasn't listed. Playback would work for a few minutes until one or both buds disconnected/reconnected. I managed to capture dump.btsnoop when it dropped off after around 2 mins / somewhere around event 70000+ in case it's of use.

I'd have to do more testing to isolate different factors - I'm unsure how much of this would have been introduced by https://gitlab.freedesktop.org/pvir/pipewire/-/commit/6510420dd12546021c5d4924fd1a85a91ca5bf90 if at all.

ford-prefect pushed a commit to PipeWire/pipewire that referenced this issue Jan 9, 2024
According to Intel people this is better for their hardware.

Link: bluez/bluez#713
@joakim-tjernlund
Copy link
Contributor

linux-firmware just got new FW for Intel AX chips, maybe these work better?

@tlvince
Copy link
Author

tlvince commented Jan 10, 2024

With linux-firmware 4f3022dc1f90e29705d892996b89a9cec3e183c4 (which includes the AX210 update), I experience similar behavior. Playback works for a few minutes until the ear buds disconnect/reconnect. (A secondary issue - the microphone does not show up in GNOME sound settings, but does in pavucontrol as "Bluetooth (unplugged)").

Some logs (I'll get capture some debug logs later):

Jan 10 12:34:18 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:18 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:18 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:18 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:18 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:19 framework wireplumber[2729]: Failed to release transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd35: Operation Not Authorized
Jan 10 12:34:28 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:28 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:29 framework boltd[1267]: probing: started [1000]
Jan 10 12:34:30 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xe421e0: out of playback buffers: Broken pipe
Jan 10 12:34:30 framework wireplumber[2729]: 0xf10240: out of playback buffers: Broken pipe
Jan 10 12:35:33 framework wireplumber[2729]: 0x1762628: error 24
Jan 10 12:35:33 framework .gsd-media-keys[2436]: Unable to get default sink
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:33 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:40 framework boltd[1267]: probing: started [1000]
Jan 10 12:35:40 framework bluetoothd[1309]: profiles/battery/battery.c:foreach_batt_service() More than one BATT service exists for this device
Jan 10 12:35:42 framework bluetoothd[1309]: /org/bluez/hci0/dev_18_26_54_C7_6C_F0/pac_sink0/fd39: fd(41) ready
Jan 10 12:35:42 framework bluetoothd[1309]: /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd35: fd(39) ready
Jan 10 12:35:42 framework bluetoothd[1309]: /org/bluez/hci0/dev_18_26_54_C7_6C_F0/pac_source0/fd38: fd(41) ready
Jan 10 12:35:43 framework bluetoothd[1309]: /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd34: fd(39) ready
Jan 10 12:35:45 framework boltd[1267]: probing: timeout, done: [2974255] (2000000)
Jan 10 12:35:49 framework wireplumber[2729]: 0x114f358: error 24
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework .gsd-media-keys[2436]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
Jan 10 12:35:49 framework wireplumber[2729]: error id:4 seq:65 res:-2 (No such file or directory): target not found
Jan 10 12:35:49 framework wireplumber[2729]: error id:4 seq:88 res:-2 (No such file or directory): target not found
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:69 res:-2 (No such file or directory): unknown resource 4 op:2
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:70 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:71 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:72 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:73 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:74 res:-2 (No such file or directory): unknown resource 4 op:4
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:75 res:-2 (No such file or directory): unknown resource 4 op:7
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:92 res:-2 (No such file or directory): unknown resource 4 op:2
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:93 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:94 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:95 res:-2 (No such file or directory): unknown resource 4 op:3
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:96 res:-2 (No such file or directory): unknown resource 4 op:4
Jan 10 12:35:49 framework wireplumber[2729]: error id:0 seq:97 res:-2 (No such file or directory): unknown resource 4 op:7
Jan 10 12:35:51 framework bluetoothd[1309]: profiles/battery/battery.c:foreach_batt_service() More than one BATT service exists for this device
Jan 10 12:35:53 framework bluetoothd[1309]: profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:9C: Cannot allocate memory (12)
Jan 10 12:35:53 framework kernel: Bluetooth: hci0: Opcode 0x2062 failed: -12
Jan 10 12:35:53 framework kernel: Bluetooth: hci0: Opcode 0x2065 failed: -107
Jan 10 12:35:53 framework bluetoothd[1309]: profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:9C: Cannot allocate memory (12)
Jan 10 12:35:53 framework .gsd-media-keys[2436]: Unable to get default sink
Jan 10 12:35:53 framework pipewire[2723]: mod.client-node: 0x557053a08b70: unknown peer 0x557053e26170 fd:73
Jan 10 12:35:53 framework kernel: Bluetooth: hci0: Opcode 0x2062 failed: -12
Jan 10 12:35:53 framework kernel: Bluetooth: hci0: Opcode 0x2065 failed: -107
Jan 10 12:35:53 framework wireplumber[2729]: 0xe44eb0: out of playback buffers: Broken pipe
Jan 10 12:35:53 framework wireplumber[2729]: 0xe44eb0: out of playback buffers: Broken pipe
Jan 10 12:35:53 framework bluetoothd[1309]: profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:9C: Cannot allocate memory (12)
Jan 10 12:35:53 framework kernel: Bluetooth: hci0: Opcode 0x2062 failed: -12
Jan 10 12:35:54 framework kernel: Bluetooth: hci0: Opcode 0x2065 failed: -107
Jan 10 12:35:54 framework bluetoothd[1309]: profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:9C: Cannot allocate memory (12)

tlvince added a commit to tlvince/nixos-config that referenced this issue Jan 10, 2024
@mishurov
Copy link

slightly off topic
@pv are you planning implementing HFP 1.9, the specification enables superwideband via LC3 without LE Audio. In the specification it is Appendix E: Technical Specification of LC3-SWB. As I understand Google implemented it for Pixel Buds Pro, they're Bluetooth 5.0 and can't into real LE Audio.
https://android.googlesource.com/platform/packages/modules/Bluetooth/+/refs/heads/main/system/stack/btm/btm_sco.h

@pv
Copy link
Contributor

pv commented Jan 13, 2024

Yes, we can add support for SWB in Pipewire, afaics it uses same esco modes as msbc so might not require changes on kernel side. I'll need to get a test device though to make it easier.

EDIT: done https://gitlab.freedesktop.org/pipewire/pipewire/-/merge_requests/1856

@tlvince
Copy link
Author

tlvince commented Jan 15, 2024

Gave it another test. Same overall behaviour as before - playback's fine for a minute or two, intermittently with stutters, until one or both of the ear buds eventually disconnects.

Debug logs:

Versions:

@Vudentz
Copy link
Contributor

Vudentz commented Jan 16, 2024

< HCI Command: LE Set Extended Scan Enable (0x08|0x0042) plen 6                                                                                                                                                                                                          #728 [hci0] 7.898382
        Extended scan: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
        Duration: 0 msec (0x0000)
        Period: 0.00 sec (0x0000)
< ISO Data TX: Handle 2304 flags 0x02 dlen 124                                                                                                                                                                                                                           #729 [hci0] 7.898898
< ISO Data TX: Handle 2305 flags 0x02 dlen 124                                                                                                                                                                                                                           #730 [hci0] 7.898905
> HCI Event: Command Complete (0x0e) plen 4                                                                                                                                                                                                                              #731 [hci0] 7.904357
      LE Set Extended Scan Enable (0x08|0x0042) ncmd 2
        Status: Success (0x00)
> HCI Event: Number of Completed Packets (0x13) plen 9                                                                                                                                                                                                                   #732 [hci0] 7.907357
        Num handles: 2
        Handle: 2304 Address: 75:2F:34:49:80:21 (Resolvable)
        Count: 1
        #723: len 124 (62 Kb/s)
        Latency: 16 msec (6-16 msec ~11 msec)
        Handle: 2305 Address: 75:6A:23:8B:75:B6 (Resolvable)
        Count: 1
        #724: len 124 (62 Kb/s)
        Latency: 16 msec (6-16 msec ~11 msec)

Looks like things starts to go wrong when scan is enabled after connecting the mouse, they it goes into a pretty bad latency over time:

> HCI Event: Number of Completed Packets (0x13) plen 9                                                                                                                                                                                                                  #1765 [hci0] 9.954397
        Num handles: 2
        Handle: 2304 Address: 75:2F:34:49:80:21 (Resolvable)
        Count: 1
        #1746: len 124 (16 Kb/s)
        Latency: 60 msec (5-60 msec ~59 msec)
        Handle: 2305 Address: 75:6A:23:8B:75:B6 (Resolvable)
        Count: 1
        #1747: len 124 (16 Kb/s)
        Latency: 60 msec (5-60 msec ~59 msec)

They do seem to be in sync, it just the TX latency is way too big.

@Vudentz
Copy link
Contributor

Vudentz commented Jan 16, 2024

< HCI Command: LE Set Connected Isochronous Group Parameters (0x08|0x0062) plen 24                                                                                                                                                                                    #58678 [hci0] 87.974437
        CIG ID: 0x00
        Central to Peripheral SDU Interval: 7500 us (0x001d4c)
        Peripheral to Central SDU Interval: 7500 us (0x001d4c)
        SCA: 201 - 500 ppm (0x00)
        Packing: Sequential (0x00)
        Framing: Unframed (0x00)
        Central to Peripheral Maximum Latency: 75 ms (0x004b)
        Peripheral to Central Maximum Latency: 75 ms (0x004b)
        Number of CIS: 1
        CIS ID: 0x00
        Central to Peripheral Maximum SDU Size: 117
        Peripheral to Central Maximum SDU Size: 117
        Central to Peripheral PHY: LE 2M (0x02)
        Peripheral to Central PHY: LE 2M (0x02)
        Central to Peripheral Retransmission attempts: 0x0d
        Peripheral to Central Retransmission attempts: 0x0d

Retransmission and Maximum Latency are rather big though, @pv how do you choose these parameters? This is sort of high reliability territory which I don't think it is recommended for the general use cases, we should probably go for balanced for general use which is more inline with the testing presets e.g. 48_1_1 latency 15 ms rtn 5.

@pv
Copy link
Contributor

pv commented Jan 16, 2024

We set RTN and latency to the preferred values the device suggests in its ASE. I think this device produced at least in its first firmware revision broken sound if the small latency values from BAP were used.

(This happens when BlueZ fails to report the preferred QoS values due to the API issue in SelectProperties; as a workaround I changed also the fallback values to the high-reliability ones, but I think in the case here the values come from the device.)

Here:

> ACL Data RX: Handle 2049 flags 0x02 dlen 51                                                                   #564 [hci0] 23.629854
      ATT: Handle Value Notification (0x1b) len 46
        Handle: 0x0046 Type: Sink ASE (0x2bc4)
          Data: 010100020d4b00409c00409c00409c00409c0006000000001302010802020005030100000003047500020501
            ASE ID: 1
            State: Codec Configured (0x01)
            Framing: Unframed PDUs supported (0x00)
            PHY: 0x02
            LE 2M PHY preffered (0x02)
            RTN: 13
            Max Transport Latency: 75
            Presentation Delay Min: 40000 us
            Presentation Delay Max: 40000 us
            Preferred Presentation Delay Min: 40000 us
            Preferred Presentation Delay Max: 40000 us
            Codec: LC3 (0x06)
            Codec Specific Configuration: #0: len 0x02 type 0x01
              Sampling Frequency: 48 Khz (0x08)
            Codec Specific Configuration: #1: len 0x02 type 0x02
              Frame Duration: 7.5 ms (0x00)
            Codec Specific Configuration: #2: len 0x05 type 0x03
           Location: 0x00000001
              Front Left (0x00000001)
            Codec Specific Configuration: #3: len 0x03 type 0x04
              Frame Length: 117 (0x0075)
            Codec Specific Configuration: #4: len 0x02 type 0x05
              Frame Blocks per SDU: 1 (0x01)

@Vudentz
Copy link
Contributor

Vudentz commented Jan 16, 2024

We set RTN and latency to the preferred values the device suggests in its ASE. I think this device produced at least in its first firmware revision broken sound if the small latency values from BAP were used.

(This happens when BlueZ fails to report the preferred QoS values due to the API issue in SelectProperties; as a workaround I changed also the fallback values to the high-reliability ones, but I think in the case here the values come from the device.)

You meant the values from https://github.com/bluez/bluez/blob/master/doc/org.bluez.MediaEndpoint.rst#dict-qos-readonly-optional-iso-only-experimental? Are they reporting PreferredRetransmissions as 13?

@pv
Copy link
Contributor

pv commented Jan 16, 2024

They do seem to be in sync, it just the TX latency is way too big.

TX latency can grow if there is clock drift between controller and host, and controller clock runs a bit slower. Or (which looks like occurred here) if the controller leaves packets in the queue without sending them.

If the TX latency / packet queue depth is made visible to userspace (without monitor), Pipewire can rate match to compensate for clock drift and dropouts like this. (This would be useful to have also for A2DP in principle.) This sort of matching is also made with ALSA and is necessary as sound card clocks are not necessarily in sync with host or with each other, or with machines over network etc.

EDIT: actually, not sure they help in this case since latency growth here appears fast enough for Pipewire to get EAGAIN from the socket, in which case we stop sending for a while (500ms) to avoid losing sync between the earbud CIS.

In principle Core spec has the TX Sync command but I don't see how it can be used for TX synchronization without direct access to controller clock --- and AFAIK we can only communicate with it over HCI...


On the disconnections: I have not seen disconnections in my tests (over long times), but I don't have other devices connected than these earbuds.

In the above dumps, the disconnections are as

> ISO Data RX: Handle 2305 flags 0x02 dlen 4            #54466 [hci0] 77.480574 (last RX for the ISO handle)
...
< ISO Data TX: Handle 2305 flags 0x02 dlen 121          #54481 [hci0] 77.496099  (last TX for the ISO handle)
...
> HCI Event: Disconnect Complete (0x05) plen 4          #54484 [hci0] 77.501807
        Status: Success (0x00)
        Handle: 2305 Address: 00:00:00:00:00:00 (OUI 00-00-00)
        Reason: Connection Timeout (0x08)
> HCI Event: Disconnect Complete (0x05) plen 4          #54485 [hci0] 77.503816
        Status: Success (0x00)
        Handle: 2048
        Reason: Connection Timeout (0x08)
@ MGMT Event: Device Disconnected (0x000c) plen 8     {0x0001} [hci0] 77.531699
        LE Address: 18:26:54:C7:6C:9C (Samsung Electronics Co.,Ltd)
        Reason: Connection timeout (0x01)/2

They come from controller (don't know why they occur).

@pv
Copy link
Contributor

pv commented Jan 16, 2024

You meant the values from https://github.com/bluez/bluez/blob/master/doc/org.bluez.MediaEndpoint.rst#dict-qos-readonly-optional-iso-only-experimental? Are they reporting PreferredRetransmissions as 13?

Yes, see #713 (comment) where I added now the values the ASE reports

@Vudentz
Copy link
Contributor

Vudentz commented Jan 16, 2024

Tried it here:

< ACL Data TX: Handle 2049 flags 0x00 dlen 59                                                                     #1601 [hci3] 15:40:20.012757
      ATT: Write Command (0x52) len 54
        Handle: 0x0043 Type: ASE Control Point (0x2bc6)
          Data: 01020302020600000000100201030202010304280005030100000001020206000000001002010302020103042800050301000000
            Opcode: Codec Configuration (0x01)
            Number of ASE(s): 2
            ASE: #0
            ASE ID: 0x03
            Target Latency: Balance Latency/Reliability (0x02)
            PHY: 0x02
            LE 2M PHY (0x02)
            Codec: LC3 (0x06)
            Codec Specific Configuration: #0: len 0x02 type 0x01
              Sampling Frequency: 16 Khz (0x03)
            Codec Specific Configuration: #1: len 0x02 type 0x02
              Frame Duration: 10 ms (0x01)
            Codec Specific Configuration: #2: len 0x03 type 0x04
              Frame Length: 40 (0x0028)
            Codec Specific Configuration: #3: len 0x05 type 0x03
           Location: 0x00000001
              Front Left (0x00000001)
            ASE: #1
            ASE ID: 0x01
            Target Latency: Balance Latency/Reliability (0x02)
            PHY: 0x02
            LE 2M PHY (0x02)
            Codec: LC3 (0x06)
            Codec Specific Configuration: #0: len 0x02 type 0x01
              Sampling Frequency: 16 Khz (0x03)
            Codec Specific Configuration: #1: len 0x02 type 0x02
              Frame Duration: 10 ms (0x01)
            Codec Specific Configuration: #2: len 0x03 type 0x04
              Frame Length: 40 (0x0028)
            Codec Specific Configuration: #3: len 0x05 type 0x03
           Location: 0x00000001
              Front Left (0x00000001)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                            #1602 [hci3] 15:40:20.022346
        Num handles: 1
        Handle: 2049 Address: 75:B9:7A:EF:D4:4A (Resolvable)
          Identity type: Public (0x00)
          Identity: F0:CD:31:8F:CC:4E (Samsung Electronics Co.,Ltd)
        Count: 1
        #1601: len 59 (52 Kb/s)
        Latency: 9 msec (5-86 msec ~12 msec)
> ACL Data RX: Handle 2049 flags 0x02 dlen 15                                                                     #1603 [hci3] 15:40:20.052542
      ATT: Handle Value Notification (0x1b) len 10
        Handle: 0x0043 Type: ASE Control Point (0x2bc6)
          Data: 0102030000010000
            Opcode: Codec Configuration (0x01)
            Number of ASE(s): 2
            ASE: #0
            ASE ID: 0x03
            ASE Response Code: Success (0x00)
            ASE Response Reason: None (0x00)
            ASE: #1
            ASE ID: 0x01
            ASE Response Code: Success (0x00)
            ASE Response Reason: None (0x00)
> ACL Data RX: Handle 2049 flags 0x02 dlen 51                                                                     #1604 [hci3] 15:40:20.052544
      ATT: Handle Value Notification (0x1b) len 46
        Handle: 0x004c Type: Source ASE (0x2bc5)
          Data: 030100020d5f00409c00409c00409c00409c0006000000001302010302020105030100000003042800020501
            ASE ID: 3
            State: Codec Configured (0x01)
            Framing: Unframed PDUs supported (0x00)
            PHY: 0x02
            LE 2M PHY preffered (0x02)
            RTN: 13
            Max Transport Latency: 95
            Presentation Delay Min: 40000 us
            Presentation Delay Max: 40000 us
            Preferred Presentation Delay Min: 40000 us
            Preferred Presentation Delay Max: 40000 us
            Codec: LC3 (0x06)
            Codec Specific Configuration: #0: len 0x02 type 0x01
              Sampling Frequency: 16 Khz (0x03)
            Codec Specific Configuration: #1: len 0x02 type 0x02
              Frame Duration: 10 ms (0x01)
            Codec Specific Configuration: #2: len 0x05 type 0x03
           Location: 0x00000001
              Front Left (0x00000001)
            Codec Specific Configuration: #3: len 0x03 type 0x04
              Frame Length: 40 (0x0028)
            Codec Specific Configuration: #4: len 0x02 type 0x05
              Frame Blocks per SDU: 1 (0x01)

It indeed does return RTN as 13 and latency as 95?? Even though I requested Balance Latency/Reliability (0x02), now the problem seems to be that we have no means to communicate this back to the endpoint without triggering another round of QoS settings, and to be honest this is sort of bogus because they are not a range but a specific value and at this point I don't think the headset can possible tell what the source is going to transmit, so I think it is actually best to ignore these and try to come up with the best settings per context/target latency.

@pv
Copy link
Contributor

pv commented Jan 16, 2024

For me, 48_5_1 on this device produces broken audio while 48_5_2 works (as do the "preferred" QoS values). The smaller SDU, 48_1_1 and 48_3_1 both work.

@Vudentz
Copy link
Contributor

Vudentz commented Jan 16, 2024

Earfun is even worse in picking up preferred settings:

> ACL Data RX: Handle 2048 flags 0x02 dlen 48                                                                      #450 [hci3] 16:04:33.328529
      ATT: Handle Value Notification (0x1b) len 43
        Handle: 0x0092 Type: Source ASE (0x2bc5)
          Data: 050100020fa00f409c00409c0000000000000006000000001002010302020103042800050301000000
            ASE ID: 5
            State: Codec Configured (0x01)
            Framing: Unframed PDUs supported (0x00)
            PHY: 0x02
            LE 2M PHY preffered (0x02)
            RTN: 15
            Max Transport Latency: 4000
            Presentation Delay Min: 40000 us
            Presentation Delay Max: 40000 us
            Preferred Presentation Delay Min: 0 us
            Preferred Presentation Delay Max: 0 us
            Codec: LC3 (0x06)
            Codec Specific Configuration: #0: len 0x02 type 0x01
              Sampling Frequency: 16 Khz (0x03)
            Codec Specific Configuration: #1: len 0x02 type 0x02
              Frame Duration: 10 ms (0x01)
            Codec Specific Configuration: #2: len 0x03 type 0x04
              Frame Length: 40 (0x0028)
            Codec Specific Configuration: #3: len 0x05 type 0x03
           Location: 0x00000001
              Front Left (0x00000001)

RTN 15 and Latency 400ms, I think they are just hardcoding the values for the worse case, instead of given their best guess for the target latency, the spec is also pretty vague in how these values should be interpreted, but so far these don't give me high hopes they are going to be useful.

@pv
Copy link
Contributor

pv commented Jan 16, 2024

I guess this means it has to be done exactly like what Android does, as the manufacturers probably are going to test with that, and anything else is crapshoot.

@pv
Copy link
Contributor

pv commented Jan 16, 2024

@tlvince you can try the smaller SDU/RTN/latency values in case it changes something https://gitlab.freedesktop.org/pvir/pipewire/-/commit/f95bbce59a62b29887b335f669bcfae6a32ac20e

Also try if changing input stream from 48kHz to 16kHz helps: https://gitlab.freedesktop.org/pvir/pipewire/-/commits/lc3-workaround-3 (for me, this makes a faint buzzing sound that comes from the left earbud during playback to go away)

... or maybe both: https://gitlab.freedesktop.org/pvir/pipewire/-/commits/lc3-workaround-4

@Vudentz
Copy link
Contributor

Vudentz commented Jan 17, 2024

I guess this means it has to be done exactly like what Android does, as the manufacturers probably are going to test with that, and anything else is crapshoot.

Ive been thinking on contact the peripheral companies because it makes sense to expose their stack to more implementation making it more robust in the process, perhaps we could create a database of devices and then describe their status since at some point that shall reach the manufactorer.

@tlvince
Copy link
Author

tlvince commented Jan 17, 2024

Unfortunately the same symptoms (playback until one ear bud drops) persisted with all three options:

Could you verify my system's using the correct pipewire builds from those?

These (and all earlier tests) we done with buds firmware R510XXU0AWI2. I've just noticed there's an update R510XXU0AXA2, which I'll try.

@tlvince
Copy link
Author

tlvince commented Jan 17, 2024

Same with R510XXU0AXA2 and smaller latency + 16khz: smaller-latency-16khz-xa2-firmware.btsnoop

@tlvince
Copy link
Author

tlvince commented Jan 17, 2024

Here's another sample dump without the keyboard and mouse connected in case it shows anything useful. Playback's fine with these disconnected (and was before any of the previous changes).

smaller-latency-16khz-xa2-firmware-without-hid.btsnoop

@pv
Copy link
Contributor

pv commented Jan 17, 2024

@tlvince: those btsnoop seem to all use the larger latency. You can check the transport configuration in bluetoothctl with transport.list, transport.show /org/.... You should see 16khz, QoS.Retransmissions = 2, QoS.Latency = 8 for pac_sources, and for pac_sinks they are 48khz, 5, and 15. This works for me when building Pipewire from c720ed38fb0d74e6778541896aa1b53f69f40b7b

In btmon you should see

< HCI Command: LE Set Connected Isochronous Group Parameters (0x08|0x0062) plen 33                             #1524 [hci0] 88.378109
        CIG ID: 0x00
        Central to Peripheral SDU Interval: 7500 us (0x001d4c)
        Peripheral to Central SDU Interval: 7500 us (0x001d4c)
        SCA: 201 - 500 ppm (0x00)
        Packing: Sequential (0x00)
        Framing: Unframed (0x00)
        Central to Peripheral Maximum Latency: 15 ms (0x000f)
        Peripheral to Central Maximum Latency: 8 ms (0x0008)
        Number of CIS: 2
        CIS ID: 0x00
        Central to Peripheral Maximum SDU Size: 117
        Peripheral to Central Maximum SDU Size: 30
        Central to Peripheral PHY: LE 2M (0x02)
        Peripheral to Central PHY: LE 2M (0x02)
        Central to Peripheral Retransmission attempts: 0x05
        Peripheral to Central Retransmission attempts: 0x02
        CIS ID: 0x01
        Central to Peripheral Maximum SDU Size: 117
        Peripheral to Central Maximum SDU Size: 30
        Central to Peripheral PHY: LE 2M (0x02)
        Peripheral to Central PHY: LE 2M (0x02)
        Central to Peripheral Retransmission attempts: 0x05
        Peripheral to Central Retransmission attempts: 0x02

@tlvince
Copy link
Author

tlvince commented Jan 17, 2024

Thanks. An old build was still use in my last test.

All 3 fared better this time.

Force 48_1_1 for LC3

f95bbce59a62b29887b335f669bcfae6a32ac20e: smaller-latency.btsnoop

bluetoothctl transport.show
[Galaxy Buds2 Pro]# transport.show /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd16
Transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd16
        UUID: 00002bc9-0000-1000-8000-00805f9b34fb
        Codec: 0x06 (6)
        Configuration.#0: len 0x02 type 0x01
        Configuration.Sampling Frequency: 48 Khz (0x08)
        Configuration.#1: len 0x02 type 0x02
        Configuration.Frame Duration: 7.5 ms (0x00)
        Configuration.#2: len 0x05 type 0x03
        Configuration.Location: 0x00000001
        Configuration.Location: Front Left (0x00000001)
        Configuration.#3: len 0x03 type 0x04
        Configuration.Frame Length: 75 (0x004b)
        Configuration.#4: len 0x02 type 0x05
        Configuration.Frame Blocks per SDU: 1 (0x01)
        Device: /org/bluez/hci0/dev_18_26_54_C7_6C_9C
        State: active
        Endpoint: /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0
        QoS.CIG: 0x00 (0)
        QoS.CIS: 0x01 (1)
        QoS.Framing: 0x00 (0)
        QoS.PresentationDelay: 0x00009c40 (40000)
        QoS.Interval: 0x00001d4c (7500)
        QoS.Latency: 0x000f (15)
        QoS.SDU: 0x004b (75)
        QoS.PHY: 0x02 (2)
        QoS.Retransmissions: 0x05 (5)
        Location: 0x00000401 (1025)
        Links: /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd17

2nd attempt, I got a disconnection soon after restarting bluetoothd with bluetoothd: profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:F0: Function not implemented (38)

3rd attempt was mostly stable until a bit of break up around event ~80000, smaller-latency-3.btsnoop

prefer 16khz input for LE Audio

bluetoothctl transport.show
[Galaxy Buds2 Pro]# transport.show /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd22
Transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd22
        UUID: 00002bc9-0000-1000-8000-00805f9b34fb
        Codec: 0x06 (6)
        Configuration.#0: len 0x02 type 0x01
        Configuration.Sampling Frequency: 16 Khz (0x03)
        Configuration.#1: len 0x02 type 0x02
        Configuration.Frame Duration: 7.5 ms (0x00)
        Configuration.#2: len 0x05 type 0x03
        Configuration.Location: 0x00000001
        Configuration.Location: Front Left (0x00000001)
        Configuration.#3: len 0x03 type 0x04
        Configuration.Frame Length: 30 (0x001e)
        Configuration.#4: len 0x02 type 0x05
        Configuration.Frame Blocks per SDU: 1 (0x01)
        Device: /org/bluez/hci0/dev_18_26_54_C7_6C_9C
        State: active
        Endpoint: /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0
        QoS.CIG: 0x00 (0)
        QoS.CIS: 0x00 (0)
        QoS.Framing: 0x00 (0)
        QoS.PresentationDelay: 0x00009c40 (40000)
        QoS.Interval: 0x00001d4c (7500)
        QoS.Latency: 0x004b (75)
        QoS.SDU: 0x001e (30)
        QoS.PHY: 0x02 (2)
        QoS.Retransmissions: 0x0d (13)
        Location: 0x00000401 (1025)
        Links: /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd23

combined

bluetoothctl transport.show
[Galaxy Buds2 Pro]# transport.show /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd6
Transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd6
        UUID: 00002bc9-0000-1000-8000-00805f9b34fb
        Codec: 0x06 (6)
        Configuration.#0: len 0x02 type 0x01
        Configuration.Sampling Frequency: 16 Khz (0x03)
        Configuration.#1: len 0x02 type 0x02
        Configuration.Frame Duration: 7.5 ms (0x00)
        Configuration.#2: len 0x05 type 0x03
        Configuration.Location: 0x00000001
        Configuration.Location: Front Left (0x00000001)
        Configuration.#3: len 0x03 type 0x04
        Configuration.Frame Length: 30 (0x001e)
        Configuration.#4: len 0x02 type 0x05
        Configuration.Frame Blocks per SDU: 1 (0x01)
        Device: /org/bluez/hci0/dev_18_26_54_C7_6C_9C
        State: active
        Endpoint: /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0
        QoS.CIG: 0x00 (0)
        QoS.CIS: 0x00 (0)
        QoS.Framing: 0x00 (0)
        QoS.PresentationDelay: 0x00009c40 (40000)
        QoS.Interval: 0x00001d4c (7500)
        QoS.Latency: 0x0008 (8)
        QoS.SDU: 0x001e (30)
        QoS.PHY: 0x02 (2)
        QoS.Retransmissions: 0x02 (2)
        Location: 0x00000401 (1025)
        Links: /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd7

@tlvince
Copy link
Author

tlvince commented Jan 17, 2024

Hit another disconnect with the combined 48_1_1 + 16KHz branch after ~1 hour of playback. Unfortunately don't have a btsnoop dump, but repeated profiles/audio/bap.c:iso_connect_cb() connect to 18:26:54:C7:6C:9C: Cannot allocate memory (12) errors from bluetoothd and

pipewire stderr
M 21:20:47.785353 spa.bluez5.sink.me ../spa/plugins/bluez5/media-sink.c:1041:media_on_flush_error: 0x555555a6fd18: error 24
W 21:20:47.785404 spa.bluez5.source. ../spa/plugins/bluez5/media-source.c:469:media_on_ready_read: source is not an input, rmask=24
W 21:20:47.817916 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:4 seq:89 res:-2 (No such file or directory): target not found
W 21:20:47.818791 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:5 seq:1011 res:-2 (No such file or directory): target not found
W 21:20:47.821805 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:93 res:-2 (No such file or directory): unknown resource 4 op:2
W 21:20:47.821822 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:94 res:-2 (No such file or directory): unknown resource 4 op:3
W 21:20:47.821829 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:95 res:-2 (No such file or directory): unknown resource 4 op:3
W 21:20:47.821835 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:96 res:-2 (No such file or directory): unknown resource 4 op:3
W 21:20:47.821840 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:97 res:-2 (No such file or directory): unknown resource 4 op:3
W 21:20:47.821849 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:98 res:-2 (No such file or directory): unknown resource 4 op:4
W 21:20:47.821858 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:99 res:-2 (No such file or directory): unknown resource 4 op:7
W 21:20:47.822015 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:1015 res:-2 (No such file or directory): unknown resource 5 op:2
W 21:20:47.822022 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:1016 res:-2 (No such file or directory): unknown resource 5 op:3
W 21:20:47.822028 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:1017 res:-2 (No such file or directory): unknown resource 5 op:3
W 21:20:47.822038 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:1018 res:-2 (No such file or directory): unknown resource 5 op:3
W 21:20:47.822047 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:1019 res:-2 (No such file or directory): unknown resource 5 op:4
W 21:20:47.822056 mod.combine-stream ../src/modules/module-combine-stream.c:1336:core_error: error id:0 seq:1020 res:-2 (No such file or directory): unknown resource 5 op:7
W 21:21:17.934486         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:3538:transport_acquire_reply: Acquire /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4 returned error: org.freedesktop.DBus.Error.NoReply
W 21:21:17.934683            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_input.18_26_54_C7_6C_9C.0-111) running -> error (Received error event)
W 21:21:17.934728         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4
W 21:21:17.934798            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
W 21:21:17.934815         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd5
[E][27846.735173] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_input.18_26_54_C7_6C_9C.0-111) running -> error (Received error event)
[E][27846.735350] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
W 21:21:48.039099         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:3538:transport_acquire_reply: Acquire /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4 returned error: org.freedesktop.DBus.Error.NoReply
W 21:21:48.039309            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_input.18_26_54_C7_6C_9C.0-111) running -> error (Received error event)
W 21:21:48.039366         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4
W 21:21:48.039518            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
W 21:21:48.039559         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd5
[E][27876.840163] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_input.18_26_54_C7_6C_9C.0-111) suspended -> error (Received error event)
[E][27876.840697] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
W 21:22:18.098576         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:3538:transport_acquire_reply: Acquire /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4 returned error: org.freedesktop.DBus.Error.NoReply
W 21:22:18.098703            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_input.18_26_54_C7_6C_9C.0-111) running -> error (Received error event)
W 21:22:18.098746         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4
W 21:22:18.098795            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
W 21:22:18.098810         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd5
[E][27906.899507] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_input.18_26_54_C7_6C_9C.0-111) suspended -> error (Received error event)
[E][27906.899669] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
W 21:22:23.218516   spa.audioadapter ../spa/plugins/audioconvert/audioadapter.c:951:impl_node_send_command: 0x555555a7b858: can't send command 2: Input/output error
W 21:22:23.218585            pw.node ../src/pipewire/impl-node.c:285:start_node: (bluez_output.18_26_54_C7_6C_9C.1-63) start node error -5: Input/output error
M 21:22:23.218594    mod.client-node ../src/modules/module-client-node/remote-node.c:475:client_node_command: node 0x5555559dcb80: start failed
W 21:22:23.219089   spa.audioadapter ../spa/plugins/audioconvert/audioadapter.c:951:impl_node_send_command: 0x5555560656e8: can't send command 2: Input/output error
W 21:22:23.219142            pw.node ../src/pipewire/impl-node.c:285:start_node: (bluez_input.18_26_54_C7_6C_9C.0-111) start node error -5: Input/output error
M 21:22:23.219151    mod.client-node ../src/modules/module-client-node/remote-node.c:475:client_node_command: node 0x555555939bb0: start failed
[E][27912.019840] pw.core      | [     impl-core.c:  219 core_error()] 0x55555556b9f0: error -5 for resource 9: start failed
[E][27912.019959] mod.client-node | [   client-node.c: 1222 client_node_resource_error()] 0x5555557aeec0: error seq:3429 -5 (start failed)
[E][27912.020028] pw.core      | [     impl-core.c:  219 core_error()] 0x55555556b9f0: error -5 for resource 8: start failed
[E][27912.020057] mod.client-node | [   client-node.c: 1222 client_node_resource_error()] 0x555555806d90: error seq:3438 -5 (start failed)
W 21:24:29.140317         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:3538:transport_acquire_reply: Acquire /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd5 returned error: org.freedesktop.DBus.Error.NoReply
W 21:24:29.140511            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
W 21:24:29.140556         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd5
W 21:24:29.140701            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_input.18_26_54_C7_6C_9C.0-111) running -> error (Received error event)
W 21:24:29.140734         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4
[E][28037.942379] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
[E][28037.942577] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_input.18_26_54_C7_6C_9C.0-111) running -> error (Received error event)
W 21:24:59.291745         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:3538:transport_acquire_reply: Acquire /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4 returned error: org.freedesktop.DBus.Error.NoReply
W 21:24:59.291873            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_input.18_26_54_C7_6C_9C.0-111) running -> error (Received error event)
W 21:24:59.291924         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4
W 21:24:59.291993            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
W 21:24:59.292010         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd5
[E][28068.093851] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_input.18_26_54_C7_6C_9C.0-111) running -> error (Received error event)
[E][28068.094054] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_output.18_26_54_C7_6C_9C.1-63) suspended -> error (Received error event)
W 21:25:29.410214         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:3538:transport_acquire_reply: Acquire /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4 returned error: org.freedesktop.DBus.Error.NoReply
W 21:25:29.410345            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_input.18_26_54_C7_6C_9C.0-111) running -> error (Received error event)
W 21:25:29.410384         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_source0/fd4
W 21:25:29.410463            pw.node ../src/pipewire/impl-node.c:409:node_update_state: (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
W 21:25:29.410484         spa.bluez5 ../spa/plugins/bluez5/bluez5-dbus.c:2808:spa_bt_transport_set_state: Failure in Bluetooth audio transport /org/bluez/hci0/dev_18_26_54_C7_6C_9C/pac_sink0/fd5
[E][28098.212527] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_input.18_26_54_C7_6C_9C.0-111) suspended -> error (Received error event)
[E][28098.212769] pw.node      | [     impl-node.c:  409 node_update_state()] (bluez_output.18_26_54_C7_6C_9C.1-63) running -> error (Received error event)
W 21:25:34.470576   spa.audioadapter ../spa/plugins/audioconvert/audioadapter.c:951:impl_node_send_command: 0x5555560656e8: can't send command 2: Input/output error
W 21:25:34.470664            pw.node ../src/pipewire/impl-node.c:285:start_node: (bluez_input.18_26_54_C7_6C_9C.0-111) start node error -5: Input/output error
M 21:25:34.470680    mod.client-node ../src/modules/module-client-node/remote-node.c:475:client_node_command: node 0x555555939bb0: start failed
W 21:25:34.471406   spa.audioadapter ../spa/plugins/audioconvert/audioadapter.c:951:impl_node_send_command: 0x555555a7b858: can't send command 2: Input/output error
W 21:25:34.471476            pw.node ../src/pipewire/impl-node.c:285:start_node: (bluez_output.18_26_54_C7_6C_9C.1-63) start node error -5: Input/output error
M 21:25:34.471490    mod.client-node ../src/modules/module-client-node/remote-node.c:475:client_node_command: node 0x5555559dcb80: start failed
[E][28103.273451] pw.core      | [     impl-core.c:  219 core_error()] 0x55555556b9f0: error -5 for resource 8: start failed
[E][28103.273513] mod.client-node | [   client-node.c: 1222 client_node_resource_error()] 0x555555806d90: error seq:3601 -5 (start failed)
[E][28103.273572] pw.core      | [     impl-core.c:  219 core_error()] 0x55555556b9f0: error -5 for resource 9: start failed
[E][28103.273595] mod.client-node | [   client-node.c: 1222 client_node_resource_error()] 0x5555557aeec0: error seq:3605 -5 (start failed)

@pv
Copy link
Contributor

pv commented Jan 21, 2024

Cannot allocate memory (12)

That means there is still some race where tearing down the old CIG does not complete before bluez tries to set it up again. If you have the bluetoothd logs from before that error it might tell something.

@tlvince
Copy link
Author

tlvince commented Jan 21, 2024

Unfortunately no logs for that one. Will re-test next week.

ford-prefect pushed a commit to PipeWire/pipewire that referenced this issue Jan 23, 2024
Don't believe QoS values recommended by the device, which may be
suboptimal.  Instead, pick the values from the BAP v1.0.1 Table 5.2.

Link: bluez/bluez#713
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

5 participants