cdc_acm bug? read buffer bytes shifted

cdc_acm bug? read buffer bytes shifted

[Julio Guerra]

Hi,

I have noticed a problem using a usb device managed by the cdc_acm
driver. The data received from the device and copied to userspace ends
up being shifted by one byte again and again after some amount of calls
to read() and most importantly with previously read data. usbmon shows
the usb data payload is correct.

A small shell script is enough to make it happen fastly:
https://gist.github.com/Julio-Guerra/b6529994f814771c825649bdb8d927c2

It prints the buffer read with my device (a relay) and gives me things like:
> 00 01 01 01 00 01 00 01
...
> 01 00 01 01 01 00 01 00
...
> 00 01 00 01 01 01 00 01
after a random number of times, while usbmon shows the usb payload
"00 01 01 01 00 01 00 01"


Another example:
> 00 00 00 00 00 00 00 01
...
> 01 00 00 00 00 00 00 00
...
> 00 01 00 00 00 00 00 00
...
> 00 00 01 00 00 00 00 00
after a random number of times, while usbmon shows the usb payload
"00 00 00 00 00 00 00 01".

Any idea?

I currently use versions 4.5.0 and 4.7.1 to execute this script.

Thanks you

-- 
Julio Guerra
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: cdc_acm bug? read buffer bytes shifted

[Oliver Neukum]

On Sat, 2016-08-20 at 05:40 +0200, Julio Guerra wrote:

> Another example:
> > 00 00 00 00 00 00 00 01
> ...
> > 01 00 00 00 00 00 00 00
> ...
> > 00 01 00 00 00 00 00 00
> ...
> > 00 00 01 00 00 00 00 00
> after a random number of times, while usbmon shows the usb payload
> "00 00 00 00 00 00 00 01".

Hi, how many bytes does read() return?

	Regards
		Oliver


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: cdc_acm bug? read buffer bytes shifted

[Julio Guerra]

>> Another example:
>>> 00 00 00 00 00 00 00 01
>> ...
>>> 01 00 00 00 00 00 00 00
>> ...
>>> 00 01 00 00 00 00 00 00
>> ...
>>> 00 00 01 00 00 00 00 00
>> after a random number of times, while usbmon shows the usb payload
>> "00 00 00 00 00 00 00 01".
> 
> Hi, how many bytes does read() return?
> 

Exactly 8 bytes, always. I set the tty in raw non-canonical mode with
vmin = 8 and vtime = 0. I also tried with vmin = 1 and did the copy of
exactly 8 bytes by looping in userspace, without any improvement.

I wrote a small workaround for now that detects this problem (because I
exactly know what the buffer is supposed to look like) to close() and
re-open() the device. The next read buffer is then correct.

-- 
Julio Guerra
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: cdc_acm bug? read buffer bytes shifted

[Julio Guerra]

>>> Another example:
>>>> 00 00 00 00 00 00 00 01
>>> ...
>>>> 01 00 00 00 00 00 00 00
>>> ...
>>>> 00 01 00 00 00 00 00 00
>>> ...
>>>> 00 00 01 00 00 00 00 00
>>> after a random number of times, while usbmon shows the usb payload
>>> "00 00 00 00 00 00 00 01".
>>
>> Hi, how many bytes does read() return?
>>
> 
> Exactly 8 bytes, always. I set the tty in raw non-canonical mode with
> vmin = 8 and vtime = 0. I also tried with vmin = 1 and did the copy of
> exactly 8 bytes by looping in userspace, without any improvement.
> 
> I wrote a small workaround for now that detects this problem (because I
> exactly know what the buffer is supposed to look like) to close() and
> re-open() the device. The next read buffer is then correct.
> 

Some more precisions: I just had access to the FTDI version of the
device instead of the Microchip one and the bug did not appear under the
ftdi_sio driver, by running the previous script approx. 5 minutes.

-- 
Julio Guerra
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: cdc_acm bug? read buffer bytes shifted

[Oliver Neukum]

On Sat, 2016-08-20 at 14:14 +0200, Julio Guerra wrote:
> >> Another example:
> >>> 00 00 00 00 00 00 00 01
> >> ...
> >>> 01 00 00 00 00 00 00 00
> >> ...
> >>> 00 01 00 00 00 00 00 00
> >> ...
> >>> 00 00 01 00 00 00 00 00
> >> after a random number of times, while usbmon shows the usb payload
> >> "00 00 00 00 00 00 00 01".
> > 
> > Hi, how many bytes does read() return?
> > 
> 
> Exactly 8 bytes, always. I set the tty in raw non-canonical mode with
> vmin = 8 and vtime = 0. I also tried with vmin = 1 and did the copy of
> exactly 8 bytes by looping in userspace, without any improvement.
> 
> I wrote a small workaround for now that detects this problem (because I
> exactly know what the buffer is supposed to look like) to close() and
> re-open() the device. The next read buffer is then correct.
> 

Please activate dynamic debugging for the tty and cdc_acm driver.
We need to know where the corruption happens.

	Regards
		Oliver


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: cdc_acm bug? read buffer bytes shifted

[Julio Guerra]

[-- Attachment #1.1: Type: text/plain, Size: 1562 bytes --]

> On Sat, 2016-08-20 at 14:14 +0200, Julio Guerra wrote:
>>>> Another example:
>>>>> 00 00 00 00 00 00 00 01
>>>> ...
>>>>> 01 00 00 00 00 00 00 00
>>>> ...
>>>>> 00 01 00 00 00 00 00 00
>>>> ...
>>>>> 00 00 01 00 00 00 00 00
>>>> after a random number of times, while usbmon shows the usb payload
>>>> "00 00 00 00 00 00 00 01".
>>>
>>> Hi, how many bytes does read() return?
>>>
>>
>> Exactly 8 bytes, always. I set the tty in raw non-canonical mode with
>> vmin = 8 and vtime = 0. I also tried with vmin = 1 and did the copy of
>> exactly 8 bytes by looping in userspace, without any improvement.
>>
>> I wrote a small workaround for now that detects this problem (because I
>> exactly know what the buffer is supposed to look like) to close() and
>> re-open() the device. The next read buffer is then correct.
>>
> 
> Please activate dynamic debugging for the tty and cdc_acm driver.
> We need to know where the corruption happens.
> 

I didn't find anything helpful in /sys/kernel/debug/dynamic_debug
regarging the tty module (I enabled tty_io debugs and it doesn't appear
in the logs), but I enabled cdc_acm debugs. Nothing is observable in the
logs when the bug appears. I logged everything as a comment of the gist:
https://gist.github.com/Julio-Guerra/b6529994f814771c825649bdb8d927c2#gistcomment-1875985

Note that re-running the script restarts the underlying kernel buffer
correctly, it does not restart from its previous bugged state.

Let me know if you want other debug traces enabled.

-- 
Julio Guerra


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 842 bytes --]

Re: cdc_acm bug? read buffer bytes shifted

[Oliver Neukum]

On Fri, 2016-09-16 at 18:24 +0200, Julio Guerra wrote:
> > On Sat, 2016-08-20 at 14:14 +0200, Julio Guerra wrote:
> >>>> Another example:
> >>>>> 00 00 00 00 00 00 00 01
> >>>> ...
> >>>>> 01 00 00 00 00 00 00 00
> >>>> ...
> >>>>> 00 01 00 00 00 00 00 00
> >>>> ...
> >>>>> 00 00 01 00 00 00 00 00
> >>>> after a random number of times, while usbmon shows the usb payload
> >>>> "00 00 00 00 00 00 00 01".
> >>>
> >>> Hi, how many bytes does read() return?
> >>>
> >>
> >> Exactly 8 bytes, always. I set the tty in raw non-canonical mode with
> >> vmin = 8 and vtime = 0. I also tried with vmin = 1 and did the copy of
> >> exactly 8 bytes by looping in userspace, without any improvement.
> >>
> >> I wrote a small workaround for now that detects this problem (because I
> >> exactly know what the buffer is supposed to look like) to close() and
> >> re-open() the device. The next read buffer is then correct.
> >>
> > 
> > Please activate dynamic debugging for the tty and cdc_acm driver.
> > We need to know where the corruption happens.
> > 
> 
> I didn't find anything helpful in /sys/kernel/debug/dynamic_debug
> regarging the tty module (I enabled tty_io debugs and it doesn't appear
> in the logs), but I enabled cdc_acm debugs. Nothing is observable in the
> logs when the bug appears. I logged everything as a comment of the gist:
> https://gist.github.com/Julio-Guerra/b6529994f814771c825649bdb8d927c2#gistcomment-1875985
> 
> Note that re-running the script restarts the underlying kernel buffer
> correctly, it does not restart from its previous bugged state.
> 
> Let me know if you want other debug traces enabled.
> 

Can you modify the tty layer to print out the buffer?
It is unclear from the logs where the shift happens.

	Regards
		Oliver


--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html