Re: [PATCH] usb: cdc-wdm: close race between read and workqueue

From: Aleksander Morgado
Date: Mon Apr 15 2024 - 01:42:21 EST

Next message: David Wronek: "Re: [PATCH 2/2] drm/panel: Add driver for EDO RM69380 OLED panel"
Previous message: Ze Gao: "Re: [PATCH] sched: Improve rq selection for a blocked task when its affinity changes"
Next in thread: Bjørn Mork: "Re: [PATCH] usb: cdc-wdm: close race between read and workqueue"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hey Oliver & Bjørn,

On 3/14/24 11:50, Oliver Neukum wrote:

wdm_read() cannot race with itself. However, in
service_outstanding_interrupt() it can race with the
workqueue, which can be triggered by error handling.

Hence we need to make sure that the WDM_RESPONDING
flag is not just only set but tested.

Fixes: afba937e540c9 ("USB: CDC WDM driver")
Signed-off-by: Oliver Neukum <oneukum@xxxxxxxx>

We are not aware of all the details involved in this patch, but we had to revert it in all the different ChromeOS kernel versions where we had it cherry-picked, because it broke the MBIM communication with the Intel XMM based Fibocomm L850 modem. Other modems shipped in Chromebooks like the QC based Fibocomm FM101 don't seem to be affected.

Attached is an example output of mbimcli talking directly to the cdc-wdm port (i.e. without ModemManager or the mbim-proxy). In the example, we are receiving a bunch of different messages from previous mbimcli runs. Looking at the timestamps, it looks as if we only receive a message right after we have sent one, e.g. after each "open request" we end up receiving responses for requests sent in earlier runs; or something along those lines.

Is this bad behavior of this specific modem chipset, and if so, how can we workaround it? If you need any additional information or help to test new patches, let us know.

Cheers!

--
Aleksander
metaknight-rev4 ~ # mbimcli -d /dev/cdc-wdm0 --query-device-services --verbose-full
[11 Apr 2024, 01:13:25] [Debug] [/dev/cdc-wdm0] opening device...
[11 Apr 2024, 01:13:25] [Debug] [/dev/cdc-wdm0] queried max control message size: 512
[11 Apr 2024, 01:13:25] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:01:00:00:00:00:02:00:00

[11 Apr 2024, 01:13:25] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 1
<<<<<< Contents:
<<<<<< max control transfer = 512

[11 Apr 2024, 01:13:25] [Debug] [/dev/cdc-wdm0] received message... (partial fragment)
>>>>>> RAW:
>>>>>> length = 168
>>>>>> data = 03:00:00:80:A8:00:00:00:05:00:00:00:03:00:00:00:02:00:00:00:00:00:00:00:00:00:00:00:01:00:00:00:01:00:00:00:3D:01:DC:C5:FE:F5:4D:05:0D:3A:BE:F7:05:8E:9A:AF:00:00:00:00:00:00:00:00:04:00:00:00:03:00:00:00:04:00:00:00:06:00:00:00:09:00:00:00:C2:F6:58:8E:F0:37:4B:C9:86:65:F4:D4:4B:D0:93:67:00:00:00:00:00:00:00:00:06:00:00:00:01:00:00:00:02:00:00:00:03:00:00:00:04:00:00:00:05:00:00:00:06:00:00:00:68:22:3D:04:9F:6C:4E:0F:82:2D:28:44:1F:B7:23:40:00:00:00:00:00:00:00:00:02:00:00:00:01:00:00:00:02:00:00:00

[11 Apr 2024, 01:13:25] [Debug] [/dev/cdc-wdm0] received message fragment (translated)...
>>>>>> Header:
>>>>>> length = 168
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 5
>>>>>> Fragment header:
>>>>>> total = 3
>>>>>> current = 2

[11 Apr 2024, 01:13:25] [Debug] [/dev/cdc-wdm0] no transaction matched in received message
[11 Apr 2024, 01:13:25] [Debug] [/dev/cdc-wdm0] received unexpected message (translated)...
>>>>>> Header:
>>>>>> length = 168
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 5
>>>>>> Fragment header:
>>>>>> total = 3
>>>>>> current = 2

[11 Apr 2024, 01:13:30] [Debug] [/dev/cdc-wdm0] number of consecutive timeouts: 1
[11 Apr 2024, 01:13:30] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:02:00:00:00:00:02:00:00

[11 Apr 2024, 01:13:30] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 2
<<<<<< Contents:
<<<<<< max control transfer = 512

[11 Apr 2024, 01:13:30] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 212
>>>>>> data = 03:00:00:80:D4:00:00:00:06:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:01:00:00:00:00:00:00:00:A4:00:00:00:01:00:00:00:01:00:00:00:01:00:00:00:02:00:00:00:3C:00:00:80:03:00:00:00:01:00:00:00:08:00:00:00:40:00:00:00:0A:00:00:00:4C:00:00:00:1E:00:00:00:6C:00:00:00:2C:00:00:00:98:00:00:00:0C:00:00:00:48:00:53:00:50:00:41:00:2B:00:00:00:38:00:36:00:37:00:35:00:38:00:30:00:30:00:35:00:30:00:37:00:37:00:39:00:34:00:31:00:35:00:00:00:31:00:38:00:35:00:30:00:30:00:2E:00:35:00:30:00:30:00:31:00:2E:00:30:00:30:00:2E:00:30:00:35:00:2E:00:32:00:37:00:2E:00:31:00:32:00:56:00:31:00:2E:00:30:00:2E:00:34:00

[11 Apr 2024, 01:13:30] [Debug] [/dev/cdc-wdm0] no transaction matched in received message
[11 Apr 2024, 01:13:30] [Debug] [/dev/cdc-wdm0] received unexpected message (translated)...
>>>>>> Header:
>>>>>> length = 212
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 6
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'device-caps' (0x00000001)
>>>>>> Fields:
>>>>>> DeviceType = 'embedded'
>>>>>> CellularClass = 'gsm'
>>>>>> VoiceClass = 'no-voice'
>>>>>> SimClass = 'removable'
>>>>>> DataClass = 'umts, hsdpa, hsupa, lte, custom'
>>>>>> SmsCaps = 'pdu-receive, pdu-send'
>>>>>> ControlCaps = 'reg-manual'
>>>>>> MaxSessions = '8'
>>>>>> CustomDataClass = 'HSPA+'
>>>>>> DeviceId = '867580050779415'
>>>>>> FirmwareInfo = '18500.5001.00.05.27.12'
>>>>>> HardwareInfo = 'V1.0.4'

[11 Apr 2024, 01:13:35] [Debug] [/dev/cdc-wdm0] number of consecutive timeouts: 2
[11 Apr 2024, 01:13:35] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:03:00:00:00:00:02:00:00

[11 Apr 2024, 01:13:35] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 3
<<<<<< Contents:
<<<<<< max control transfer = 512

[11 Apr 2024, 01:13:35] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 212
>>>>>> data = 03:00:00:80:D4:00:00:00:07:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:01:00:00:00:00:00:00:00:A4:00:00:00:01:00:00:00:01:00:00:00:01:00:00:00:02:00:00:00:3C:00:00:80:03:00:00:00:01:00:00:00:08:00:00:00:40:00:00:00:0A:00:00:00:4C:00:00:00:1E:00:00:00:6C:00:00:00:2C:00:00:00:98:00:00:00:0C:00:00:00:48:00:53:00:50:00:41:00:2B:00:00:00:38:00:36:00:37:00:35:00:38:00:30:00:30:00:35:00:30:00:37:00:37:00:39:00:34:00:31:00:35:00:00:00:31:00:38:00:35:00:30:00:30:00:2E:00:35:00:30:00:30:00:31:00:2E:00:30:00:30:00:2E:00:30:00:35:00:2E:00:32:00:37:00:2E:00:31:00:32:00:56:00:31:00:2E:00:30:00:2E:00:34:00

[11 Apr 2024, 01:13:35] [Debug] [/dev/cdc-wdm0] no transaction matched in received message
[11 Apr 2024, 01:13:35] [Debug] [/dev/cdc-wdm0] received unexpected message (translated)...
>>>>>> Header:
>>>>>> length = 212
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 7
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'device-caps' (0x00000001)
>>>>>> Fields:
>>>>>> DeviceType = 'embedded'
>>>>>> CellularClass = 'gsm'
>>>>>> VoiceClass = 'no-voice'
>>>>>> SimClass = 'removable'
>>>>>> DataClass = 'umts, hsdpa, hsupa, lte, custom'
>>>>>> SmsCaps = 'pdu-receive, pdu-send'
>>>>>> ControlCaps = 'reg-manual'
>>>>>> MaxSessions = '8'
>>>>>> CustomDataClass = 'HSPA+'
>>>>>> DeviceId = '867580050779415'
>>>>>> FirmwareInfo = '18500.5001.00.05.27.12'
>>>>>> HardwareInfo = 'V1.0.4'

[11 Apr 2024, 01:13:40] [Debug] [/dev/cdc-wdm0] number of consecutive timeouts: 3
[11 Apr 2024, 01:13:40] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:04:00:00:00:00:02:00:00

[11 Apr 2024, 01:13:40] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 4
<<<<<< Contents:
<<<<<< max control transfer = 512

[11 Apr 2024, 01:13:40] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 212
>>>>>> data = 03:00:00:80:D4:00:00:00:08:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:01:00:00:00:00:00:00:00:A4:00:00:00:01:00:00:00:01:00:00:00:01:00:00:00:02:00:00:00:3C:00:00:80:03:00:00:00:01:00:00:00:08:00:00:00:40:00:00:00:0A:00:00:00:4C:00:00:00:1E:00:00:00:6C:00:00:00:2C:00:00:00:98:00:00:00:0C:00:00:00:48:00:53:00:50:00:41:00:2B:00:00:00:38:00:36:00:37:00:35:00:38:00:30:00:30:00:35:00:30:00:37:00:37:00:39:00:34:00:31:00:35:00:00:00:31:00:38:00:35:00:30:00:30:00:2E:00:35:00:30:00:30:00:31:00:2E:00:30:00:30:00:2E:00:30:00:35:00:2E:00:32:00:37:00:2E:00:31:00:32:00:56:00:31:00:2E:00:30:00:2E:00:34:00

[11 Apr 2024, 01:13:40] [Debug] [/dev/cdc-wdm0] no transaction matched in received message
[11 Apr 2024, 01:13:40] [Debug] [/dev/cdc-wdm0] received unexpected message (translated)...
>>>>>> Header:
>>>>>> length = 212
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 8
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'device-caps' (0x00000001)
>>>>>> Fields:
>>>>>> DeviceType = 'embedded'
>>>>>> CellularClass = 'gsm'
>>>>>> VoiceClass = 'no-voice'
>>>>>> SimClass = 'removable'
>>>>>> DataClass = 'umts, hsdpa, hsupa, lte, custom'
>>>>>> SmsCaps = 'pdu-receive, pdu-send'
>>>>>> ControlCaps = 'reg-manual'
>>>>>> MaxSessions = '8'
>>>>>> CustomDataClass = 'HSPA+'
>>>>>> DeviceId = '867580050779415'
>>>>>> FirmwareInfo = '18500.5001.00.05.27.12'
>>>>>> HardwareInfo = 'V1.0.4'

[11 Apr 2024, 01:13:44] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 212
>>>>>> data = 03:00:00:80:D4:00:00:00:09:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:01:00:00:00:00:00:00:00:A4:00:00:00:01:00:00:00:01:00:00:00:01:00:00:00:02:00:00:00:3C:00:00:80:03:00:00:00:01:00:00:00:08:00:00:00:40:00:00:00:0A:00:00:00:4C:00:00:00:1E:00:00:00:6C:00:00:00:2C:00:00:00:98:00:00:00:0C:00:00:00:48:00:53:00:50:00:41:00:2B:00:00:00:38:00:36:00:37:00:35:00:38:00:30:00:30:00:35:00:30:00:37:00:37:00:39:00:34:00:31:00:35:00:00:00:31:00:38:00:35:00:30:00:30:00:2E:00:35:00:30:00:30:00:31:00:2E:00:30:00:30:00:2E:00:30:00:35:00:2E:00:32:00:37:00:2E:00:31:00:32:00:56:00:31:00:2E:00:30:00:2E:00:34:00

[11 Apr 2024, 01:13:44] [Debug] [/dev/cdc-wdm0] no transaction matched in received message
[11 Apr 2024, 01:13:44] [Debug] [/dev/cdc-wdm0] received unexpected message (translated)...
>>>>>> Header:
>>>>>> length = 212
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 9
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'device-caps' (0x00000001)
>>>>>> Fields:
>>>>>> DeviceType = 'embedded'
>>>>>> CellularClass = 'gsm'
>>>>>> VoiceClass = 'no-voice'
>>>>>> SimClass = 'removable'
>>>>>> DataClass = 'umts, hsdpa, hsupa, lte, custom'
>>>>>> SmsCaps = 'pdu-receive, pdu-send'
>>>>>> ControlCaps = 'reg-manual'
>>>>>> MaxSessions = '8'
>>>>>> CustomDataClass = 'HSPA+'
>>>>>> DeviceId = '867580050779415'
>>>>>> FirmwareInfo = '18500.5001.00.05.27.12'
>>>>>> HardwareInfo = 'V1.0.4'

[11 Apr 2024, 01:13:45] [Debug] [/dev/cdc-wdm0] number of consecutive timeouts: 4
[11 Apr 2024, 01:13:45] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:05:00:00:00:00:02:00:00

[11 Apr 2024, 01:13:45] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 5
<<<<<< Contents:
<<<<<< max control transfer = 512

[11 Apr 2024, 01:13:45] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 212
>>>>>> data = 03:00:00:80:D4:00:00:00:0A:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:01:00:00:00:00:00:00:00:A4:00:00:00:01:00:00:00:01:00:00:00:01:00:00:00:02:00:00:00:3C:00:00:80:03:00:00:00:01:00:00:00:08:00:00:00:40:00:00:00:0A:00:00:00:4C:00:00:00:1E:00:00:00:6C:00:00:00:2C:00:00:00:98:00:00:00:0C:00:00:00:48:00:53:00:50:00:41:00:2B:00:00:00:38:00:36:00:37:00:35:00:38:00:30:00:30:00:35:00:30:00:37:00:37:00:39:00:34:00:31:00:35:00:00:00:31:00:38:00:35:00:30:00:30:00:2E:00:35:00:30:00:30:00:31:00:2E:00:30:00:30:00:2E:00:30:00:35:00:2E:00:32:00:37:00:2E:00:31:00:32:00:56:00:31:00:2E:00:30:00:2E:00:34:00

[11 Apr 2024, 01:13:45] [Debug] [/dev/cdc-wdm0] no transaction matched in received message
[11 Apr 2024, 01:13:45] [Debug] [/dev/cdc-wdm0] received unexpected message (translated)...
>>>>>> Header:
>>>>>> length = 212
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 10
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'device-caps' (0x00000001)
>>>>>> Fields:
>>>>>> DeviceType = 'embedded'
>>>>>> CellularClass = 'gsm'
>>>>>> VoiceClass = 'no-voice'
>>>>>> SimClass = 'removable'
>>>>>> DataClass = 'umts, hsdpa, hsupa, lte, custom'
>>>>>> SmsCaps = 'pdu-receive, pdu-send'
>>>>>> ControlCaps = 'reg-manual'
>>>>>> MaxSessions = '8'
>>>>>> CustomDataClass = 'HSPA+'
>>>>>> DeviceId = '867580050779415'
>>>>>> FirmwareInfo = '18500.5001.00.05.27.12'
>>>>>> HardwareInfo = 'V1.0.4'

[11 Apr 2024, 01:13:50] [Debug] [/dev/cdc-wdm0] number of consecutive timeouts: 5
[11 Apr 2024, 01:13:50] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:00:00:00:10:00:00:00:06:00:00:00:00:02:00:00

[11 Apr 2024, 01:13:50] [Debug] [/dev/cdc-wdm0] sent message (translated)...
<<<<<< Header:
<<<<<< length = 16
<<<<<< type = open (0x00000001)
<<<<<< transaction = 6
<<<<<< Contents:
<<<<<< max control transfer = 512

[11 Apr 2024, 01:13:54] [Debug] [/dev/cdc-wdm0] received message...
>>>>>> RAW:
>>>>>> length = 212
>>>>>> data = 03:00:00:80:D4:00:00:00:0D:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:01:00:00:00:00:00:00:00:A4:00:00:00:01:00:00:00:01:00:00:00:01:00:00:00:02:00:00:00:3C:00:00:80:03:00:00:00:01:00:00:00:08:00:00:00:40:00:00:00:0A:00:00:00:4C:00:00:00:1E:00:00:00:6C:00:00:00:2C:00:00:00:98:00:00:00:0C:00:00:00:48:00:53:00:50:00:41:00:2B:00:00:00:38:00:36:00:37:00:35:00:38:00:30:00:30:00:35:00:30:00:37:00:37:00:39:00:34:00:31:00:35:00:00:00:31:00:38:00:35:00:30:00:30:00:2E:00:35:00:30:00:30:00:31:00:2E:00:30:00:30:00:2E:00:30:00:35:00:2E:00:32:00:37:00:2E:00:31:00:32:00:56:00:31:00:2E:00:30:00:2E:00:34:00

[11 Apr 2024, 01:13:54] [Debug] [/dev/cdc-wdm0] no transaction matched in received message
[11 Apr 2024, 01:13:54] [Debug] [/dev/cdc-wdm0] received unexpected message (translated)...
>>>>>> Header:
>>>>>> length = 212
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 13
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'device-caps' (0x00000001)
>>>>>> Fields:
>>>>>> DeviceType = 'embedded'
>>>>>> CellularClass = 'gsm'
>>>>>> VoiceClass = 'no-voice'
>>>>>> SimClass = 'removable'
>>>>>> DataClass = 'umts, hsdpa, hsupa, lte, custom'
>>>>>> SmsCaps = 'pdu-receive, pdu-send'
>>>>>> ControlCaps = 'reg-manual'
>>>>>> MaxSessions = '8'
>>>>>> CustomDataClass = 'HSPA+'
>>>>>> DeviceId = '867580050779415'
>>>>>> FirmwareInfo = '18500.5001.00.05.27.12'
>>>>>> HardwareInfo = 'V1.0.4'

[11 Apr 2024, 01:13:55] [Debug] [/dev/cdc-wdm0] number of consecutive timeouts: 6
[11 Apr 2024, 01:13:55] [Debug] [/dev/cdc-wdm0] open operation timed out: closed
error: couldn't open the MbimDevice: Operation timed out: device is closed

Attachment: OpenPGP_0xAECE0239C6606AD5.asc
Description: OpenPGP public key

Attachment: OpenPGP_signature.asc
Description: OpenPGP digital signature

Next message: David Wronek: "Re: [PATCH 2/2] drm/panel: Add driver for EDO RM69380 OLED panel"
Previous message: Ze Gao: "Re: [PATCH] sched: Improve rq selection for a blocked task when its affinity changes"
Next in thread: Bjørn Mork: "Re: [PATCH] usb: cdc-wdm: close race between read and workqueue"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]