by Paul Menzel

[permalink] [raw]

Subject: Re: Unable to transfer big files to Nokia N9

Dear Luiz,

Am 16.01.22 um 14:27 schrieb Paul Menzel:

[…]

> It turns out there was a regression in Linux 5.16-rc1.
>
>
> Am 20.12.21 um 22:31 schrieb Paul Menzel:
>
>> Am 01.12.21 um 23:07 schrieb Paul Menzel:
>>
>>> Am 01.12.21 um 19:29 schrieb Luiz Augusto von Dentz:
>>>
>>>> On Wed, Dec 1, 2021 at 9:39 AM Paul Menzel <[email protected]>
>>>> wrote:
>>>
>>>>> For the first time, I wanted to transfer a 2 MB PDF file from a Dell
>>>>> Latitude E7250 with Debian sid/unstable with Linux 5.16-rc1 to a Nokia
>>>>> N9 (MeeGo/Harmattan). Using the package *bluez-obexd* 5.61-1 and GNOME
>>>>> 41, the device was found, and paired fine. Then I selected to transfer
>>>>> the 2 MB file, and after starting for a second, it timed out after the
>>>>> progress bar moves forward ones and failed.
>>>>>
>>>>> The systemd journal contains:
>>>>>
>>>>>       obexd[21139]: Transfer(0x56243fe4f790) Error: Timed out
>>>>> waiting for response
>>>>>
>>>>> Testing with a a 5 byte test text file, worked fine. Also testing
>>>>> with a
>>>>> Galaly M32, both files were transferred without problems (though
>>>>> slowly
>>>>> with 32 KB/s.)
>>>>>
>>>>> Trying to connect to the device with bluetoothctl failed for me,
>>>>> and the
>>>>> journal contained, it failed.
>>>>>
>>>>>       $ bluetoothctl
>>>>>       Agent registered
>>>>>       [bluetooth]# connect 40:98:4E:5B:CE:XX
>>>>>       Attempting to connect to 40:98:4E:5B:CE:XX
>>>>>       Failed to connect: org.bluez.Error.Failed
>>>>>
>>>>>       bluetoothd[21104]: src/service.c:btd_service_connect()
>>>>> a2dp-source profile connect failed for 40:98:4E:5B:CE:B3: Protocol
>>>>> not available
>>>>>
>>>>> As the Nokia N9 was once pretty popular in the Linux community, I am
>>>>> pretty sure, it used to work fine in the past, and there is some
>>>>> regression. It’d be great, if you could give me some hints how to
>>>>> further debug the issue.
>>>>
>>>> We will need some logs, obexd and btmon, if possible.
>>>
>>> I only managed to get the btmon trace [1]. I did `sudo modprobe -r
>>> btusb` and `sudo btmon -w /dev/shm/trace.log`.
>>>
>>> Linux messages:
>>>
>>>      [29880.100381] calling btusb_driver_init+0x0/0x1000 [btusb] @
>>> 28716
>>>      [29880.239603] usbcore: registered new interface driver btusb
>>>      [29880.239608] initcall btusb_driver_init+0x0/0x1000 [btusb]
>>> returned 0 after 135952 usecs
>>>      [29880.240706] Bluetooth: hci0: unexpected event for opcode 0x0500
>>>      [29880.241598] Bluetooth: hci0: Legacy ROM 2.5 revision 1.0
>>> build 3 week 17 2014
>>>      [29880.241605] Bluetooth: hci0: Intel device is already patched.
>>> patch num: 32
>>>
>>> From the system journal:
>>>
>>>      Dez 01 22:52:19 ersatz obexd[21139]: Transfer(0x56243fe53dd0)
>>> Error: Timed out waiting for response
>>
>> Were you able to see anything in the attached logs? If the obexd logs
>> are missing, can you please tell how I should capture them?
>>
>> I also tested with Ubuntu 20.04 (*linux-image-5.11.0-27-generic*) and
>> 21.10 (*linux-image-5.13.0-19-generic*) live systems booted from a USB
>> storage device, and transferring `/usr/bin/systemctl`
>> (`/lib/systemd/systemd`) with size of 1.8 MB worked fine.
>>
>> Could there be a regression in that area? Unfortunately, it’s not easy
>> for me to do a bisection on the device at hand.
>>
>> (Would it be possible to do with QEMU and USB controller and Bluetooth
>> device passthrough? How can I transfer the file on the command line so
>> I wouldn’t need to install a desktop environment?)
>
> Turns out, that is indeed possible [2], but turned out to be cumbersome,
> as I hit the regression [3], which seems to have been fixed by commit
> 95655456e7ce (Bluetooth: btintel: Fix broken LED quirk for legacy ROM
> devices) merged in the current Linux 5.17 cycle this week.
>
> As a work around, I applied a hunk from Takashi’s patch.
>
> -       { USB_DEVICE(0x8087, 0x0a2a), .driver_info =
> BTUSB_INTEL_COMBINED },
> +       { USB_DEVICE(0x8087, 0x0a2a), .driver_info = BTUSB_INTEL_COMBINED |
> + BTUSB_INTEL_BROKEN_INITIAL_NCMD },
>
> My problem with the Nokia N9 is still present in Linus’ master branch.
>
> Then I built a minimal Linux kernel for QEMU, and ran:
>
>     qemu-system-x86_64 -cpu host -m 2G -enable-kvm \
>       -usb -device usb-host,vendorid=0x8087,productid=0x0a2a \
>       -drive file=/dev/shm/debian-64.img,format=raw,if=virtio \
>       -net nic -net user,hostfwd=tcp::22223-:22 \
>       -kernel /dev/shm/bzImage -append "root=/dev/vda1 rw quiet"
>
> In the Debian sid/unstable VM, I used
>
>     ssh root@localhost -p 22223
>
> I once had to pair the VM with the Nokia N9 in bluetoothctl, and then
> started `/usr/libexec/bluetooth/obexd`, and ran `obexctl`, and connected
> first with `connect`, and then ran `send /lib/systemd/systemd` to
> transfer the file. In the problematic cases it stopped/hung after the
> first progress message.
>
>     # obexctl
>     [NEW] Client /org/bluez/obex
>     [obex]# connect 40:98:4E:5B:CE:XX
>     Attempting to connect to 40:98:4E:5B:CE:XX
>     [NEW] Session /org/bluez/obex/client/session0 [default]
>     [NEW] ObjectPush /org/bluez/obex/client/session0
>     Connection successful
>     [40:98:4E:5B:CE:XX]# send /lib/systemd/systemd
>     Attempting to send /lib/systemd/systemd to /org/bluez/obex/client/session0
>     [NEW] Transfer /org/bluez/obex/client/session0/transfer0
>     Transfer /org/bluez/obex/client/session0/transfer0
>         Status: queued
>         Name: systemd
>         Size: 1841712
>         Filename: /lib/systemd/systemd
>         Session: /org/bluez/obex/client/session0
>     [CHG] Transfer /org/bluez/obex/client/session0/transfer0 Status: active
>     [CHG] Transfer /org/bluez/obex/client/session0/transfer0 Transferred: 32737 (@32KB/s 00:55)
>     [CHG] Transfer /org/bluez/obex/client/session0/transfer0 Status: error
>     [DEL] Transfer /org/bluez/obex/client/session0/transfer0
>
> Some manual bisection of Linux releases, verified, that the regression
> was introduced in Linux 5.16-rc1. (Lucky me, I started using Bluetooth
> with the Nokia with Linux 5.16-rc1.) Then I verified it was introduced
> by the Bluetooth pull request for Linux 5.16. Then I picked commit
> 81be03e026dc0c16dc1c64e088b2a53b73caa895 due to the commit message, and
> bisected from there, and it turns out, that this commit is actually
> introducing the regression.
>
>     $ git bisect good
>     81be03e026dc0c16dc1c64e088b2a53b73caa895 is the first bad commit
>     commit 81be03e026dc0c16dc1c64e088b2a53b73caa895
>     Author: Luiz Augusto von Dentz <[email protected]>
>     Date:   Fri Sep 3 15:27:32 2021 -0700
>
>         Bluetooth: RFCOMM: Replace use of memcpy_from_msg with bt_skb_sendmmsg
>
>         This makes use of bt_skb_sendmmsg instead using memcpy_from_msg which
>         is not considered safe to be used when lock_sock is held.
>
>         Also make rfcomm_dlc_send handle skb with fragments and queue them all
>         atomically.
>
>         Signed-off-by: Luiz Augusto von Dentz <[email protected]>
>         Signed-off-by: Marcel Holtmann <[email protected]>
>
>      net/bluetooth/rfcomm/core.c | 50 ++++++++++++++++++++++++++++++++++++++-------
>      net/bluetooth/rfcomm/sock.c | 46 +++++++++--------------------------------
>      2 files changed, 53 insertions(+), 43 deletions(-)
>
> Unfortunately, the patch does not cleanly revert, so users have to wait
> until an expert can take a look, and come up with a fix.

The revert required one more revert [4]. You asked for logs, which I had
already provided in my response to your request. I tried it again, and
attached it to [5]. As written there, I failed to get logs for obexd.

Kind regards,

Paul

> PS: For the records:
>
>     $ git bisect log
>     # bad: [81be03e026dc0c16dc1c64e088b2a53b73caa895] Bluetooth: RFCOMM: Replace use of memcpy_from_msg with bt_skb_sendmmsg
>     # good: [49d8a5606428ca0962d09050a5af81461ff90fbb] Bluetooth: fix init and cleanup of sco_conn.timeout_work
>     git bisect start '81be03e026dc0' 'HEAD^'
>     # good: [904c139a2517191e48f9cb1bb2d611ae59434009] Bluetooth: Add support for msbc coding format
>     git bisect good 904c139a2517191e48f9cb1bb2d611ae59434009
>     # good: [8bba13b1d08d42e2e8308924fa5c1551a7b2b011] Bluetooth: btintel: Fix incorrect out of memory check
>     git bisect good 8bba13b1d08d42e2e8308924fa5c1551a7b2b011
>     # good: [38f64f650dc0e44c146ff88d15a7339efa325918] Bluetooth: Add bt_skb_sendmsg helper
>     git bisect good 38f64f650dc0e44c146ff88d15a7339efa325918
>     # good: [0771cbb3b97d3c1d68eecd7f00055f599954c34e] Bluetooth: SCO: Replace use of memcpy_from_msg with bt_skb_sendmsg
>     git bisect good 0771cbb3b97d3c1d68eecd7f00055f599954c34e
>     # first bad commit: [81be03e026dc0c16dc1c64e088b2a53b73caa895] Bluetooth: RFCOMM: Replace use of memcpy_from_msg with bt_skb_sendmmsg

>>> [1]: https://owww.molgen.mpg.de/~pmenzel/trace.log.7z
> [2]: https://lore.kernel.org/linux-bluetooth/[email protected]/T/#u
> [3]: https://lore.kernel.org/linux-bluetooth/[email protected]/ [4]:
https://lore.kernel.org/linux-bluetooth/[email protected]/
[5]: https://bugzilla.kernel.org/show_bug.cgi?id=215594