Re: Unable to transfer big files to Nokia N9

[Thorsten Leemhuis <regressions@leemhuis.info>]

Hi, this is your Linux kernel regression tracker speaking. Top-posting
for once, to make this easy accessible to everyone.

Hey bluetooth-maintainers, what's the status here? I already asked for a
status update more that a week ago and didn't get a reply. Paul also
confirmed recently the issue is still present and no reply either. IOW:
this is talking way to long for a issue that was bisected?

Could you please comment on this? What can be done to get this rolling?
Or do I have to ask upstream maintainers to revert the culprit?

Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker' hat)

P.S.: As the Linux kernel's regression tracker I'm getting a lot of
reports on my table. I can only look briefly into most of them and lack
knowledge about most of the areas they concern. I thus unfortunately
will sometimes get things wrong or miss something important. I hope
that's not the case here; if you think it is, don't hesitate to tell me
in a public reply, it's in everyone's interest to set the public record
straight.

#regzbot poke

On 08.02.22 08:49, Paul Menzel wrote:
> Dear Thorsten, dear Luiz,
> 
> 
> Am 07.02.22 um 14:14 schrieb Paul Menzel:
> 
>> Am 28.01.22 um 11:36 schrieb Thorsten Leemhuis:
>>> Hi, this is your Linux kernel regression tracker speaking.
>>
>> Thorsten, thank you for following up on this.
>>
>>> On 16.01.22 14:27, Paul Menzel wrote:
>>>> #regzbot introduced: 81be03e026dc0c16dc1c64e088b2a53b73caa895
>>>
>>> thx for getting regzbot involved, much appreciated!
>>>
>>>> Dear Luiz,
>>>>
>>>> It turns out there was a regression in Linux 5.16-rc1.
>>>
>>> @bt-maintaners, what's the status here? Paul reported that over ten days
>>> ago and there wasn't a single reply. Or did the discussion move
>>> somewhere else?
>>>
>>> @Paul: just wondering, did you give 5.17-rc1 a try? Might be worth a
>>> shot, if only to confirm the issue is still present.
>>
>> I just tried with 5.17-rc3, and the issue is still present.
> 
> Merging 4840aa67576b (Bluetooth: hci_core: Fix leaking sent_cmd skb) from
> 
> https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git
> 
> 
> into Linux 5.17-rc3, the resulting Linux kernel also has the problem.
> 
> 
> Kind regards,
> 
> Paul
> 
> 
>>>> 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 <pmenzel@molgen.mpg.de>
>>>>>>> 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 <luiz.von.dentz@intel.com>
>>>>      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
>>>> <luiz.von.dentz@intel.com>
>>>>          Signed-off-by: Marcel Holtmann <marcel@holtmann.org>
>>>>
>>>>       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.
>>>>
>>>>
>>>> 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
>>>>
>>>>
>>>> Kind regards,
>>>>
>>>> Paul
>>>>
>>>>
>>>>>> [1]: https://owww.molgen.mpg.de/~pmenzel/trace.log.7z
>>>> [2]:
>>>> https://lore.kernel.org/linux-bluetooth/5891f0d5-8d51-9da5-7663-718f301490b1@molgen.mpg.de/T/#u
>>>> [3]:
>>>> https://lore.kernel.org/linux-bluetooth/20211202162256.31837-1-tiwai@suse.de/
>>>>
>