webserial return wrong data but other methods works fine

[demonguy]

I'm trying to use webserial to connect android phone with Qualcomm chips. It's EDL mode is a serial port with 0x9008 product ID.
the port is supposed to send 48 bytes data at first time. When i communicate it with python or sudo minicom --device /dev/ttyUSB0. i always have 48 bytes data.

however when i use code snippet below on chrom console. sometimes it return 103 bytes wrong data. And if i tried on another computer everything works fine.
I'm not sure if i provide enough information, if anything i can provide, please feel free to ask.

const f = { usbVendorId: 0x05c6, usbProductId: 0x9008 };
a = await navigator.serial.requestPort({filters: [f]})
await a.open({baudRate: 115200});
b = a.readable.getReader()
r = await b.read();
r["value"]

[reillyeon]

What is the structure of the 103 bytes of data returned? Is it the expected 48 bytes followed by garbage? Is it two or more 48 byte chunks concatenated together?

When getReader() is called the browser starts reading from the port and adding any data that is received to the stream. When read() is called any data received so far is returned. In general, rather than calling read() and expecting it to contain exactly the data it is looking for a program should call read() until it gets all the data it expects, process that, and then continue reading until it gets the next expected piece of data.

[demonguy]

when 103 bytes returned, it's totally wrong data. the first 48 bytes of the 103 bytes are different than the correct data. even rebooting the PC doesn't work
Here is the detail

if i run javascript in crhome console with the computer which works fine

const f = { usbVendorId: 0x05c6, usbProductId: 0x9008 };
a = await navigator.serial.requestPort({filters: [f]})
await a.open({baudRate: 115200});
b = a.readable.getReader()
r = await b.read();
r["value"]

the result is

{value: Uint8Array(48), done: false}
r["value"]
Uint8Array(48) [1, 0, 0, 0, 48, 0, 0, 0, 2, 0, 0, 0, 1, 0, 0, 0, 0, 4, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, buffer: ArrayBuffer(48), byteLength: 48, byteOffset: 0, length: 48]

However on the problem computer, there is 90% of time i will get data like this

const f = { usbVendorId: 0x05c6, usbProductId: 0x9008 };
a = await navigator.serial.requestPort({filters: [f]})
await a.open({baudRate: 115200});
b = a.readable.getReader()
r = await b.read();
r["value"]

the result is

{value: Uint8Array(103), done: false}
done: false
value: Uint8Array(103) [0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 4, 0, 0, 0, 16, 0, 0, 0, 13, 0, 0, 0, 1, 0, 0, 0, 4, 0, 0, 0, 16, 0, 0, 0, 13, 0, 0, 0, 1, 0, 0, 0, 4, 0, 0, 0, 16, 0, 0, 0, 13, 0, 0, 0, 1, 0, 0, 0, 4, 0, 0, 0, 16, 0, 0, 0, 13, 0, 0, 0, 1, …]
[[Prototype]]: Object

if i run
minicom --device /dev/ttyUSB0 -b 115200 -H on the problem PC
the result is good

Welcome to minicom 2.7.1

OPTIONS: I18n 
Compiled on Dec 23 2019, 02:06:26.
Port /dev/ttyUSB0, 10:25:56

Press CTRL-A Z for help on special keys

01 00 00 00 30 00 00 00 02 00 00 00 01 00 00 00 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 

[reillyeon]

If this is only happening on some Linux systems try disabling the "ModemManager" service. This service is known to try to open and communicate with serial devices and cause problems.

[demonguy]

If this is only happening on some Linux systems try disabling the "ModemManager" service. This service is known to try to open and communicate with serial devices and cause problems.

it doesn't work even i run

systemctl disable ModemManager.service
systemctl stop ModemManager.service

and it cannot explain why minicom works fine, because it also works on serial port.
However i tried another thing. i disable serial driver on the problem PC, so webusb can claim on my original USB interface. and i found it also works fine

device = await navigator.usb.requestDevice({
                filters: [
                            {
                              vendorId: 0x05c6,
                              productId: 0x9008
                            }
                         ]})

await device.open();
await device.selectConfiguration(1);
await device.claimInterface(0); // fastboot
let response = await device.transferIn(1, 64);
new Uint8Array(response.data.buffer)
Uint8Array(48) [1, 0, 0, 0, 48, 0, 0, 0, 3, 0, 0, 0, 1, 0, 0, 0, 0, 4, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, buffer: ArrayBuffer(48), byteLength: 48, byteOffset: 0, length: 48]

[reillyeon]

What are the differences between the working PC and the problem PC? Processor type, kernel version, Linux distribution, etc.

[demonguy]

nearly same. it's our company Dell PC for business. the only difference is the problem PC is newer.

And both of them are installed ubuntu 20.04 with linux 5.11.0-40 and latest chrome. Details are listed below

Good PC:
Manufacturer: Dell Inc.
Product Name: OptiPlex 9020
CPU: Intel i7-4790
Ubuntu: 20.04.3
Linux: 5.11.0-40-generic
Chrome: Version 96.0.4664.45 (Official Build) (64-bit)

Bad PC:
Manufacturer: Dell Inc.
Product Name: OptiPlex 7080
CPU: Inteli7-10700
Ubuntu: 20.04.2
Linux: 5.11.0-41-generic
Chrome: Version Version 96.0.4664.45 (Official Build) (64-bit)

I also tried another pc which has exactly same hardware and software. also works fine. it feels like one of userspace program problem or bug.

[demonguy]

Is there any further debug or experiment i can do? i run out of my methods

[demonguy]

I use auditd to check if someone else is using /dev/ttyUSB
But it seems that everything is OK

----
time->Tue Dec  7 11:53:15 2021
type=PROCTITLE msg=audit(1638849195.377:401): proctitle="/lib/systemd/systemd-udevd"
type=PATH msg=audit(1638849195.377:401): item=0 name="/dev/ttyUSB5" inode=637 dev=00:05 mode=020600 ouid=0 ogid=0 rdev=bc:05 nametype=NORMAL cap_fp=0 cap_fi=0 cap_fe=0 cap_fver=0 cap_frootid=0
type=CWD msg=audit(1638849195.377:401): cwd="/"
type=SYSCALL msg=audit(1638849195.377:401): arch=c000003e syscall=257 success=yes exit=6 a0=ffffff9c a1=5650f918fb60 a2=2a0000 a3=0 items=1 ppid=6474 pid=6540 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="systemd-udevd" exe="/usr/lib/systemd/systemd-udevd" subj=unconfined key=(null)
----
time->Tue Dec  7 11:53:18 2021
type=PROCTITLE msg=audit(1638849198.965:404): proctitle=6C73002D2D636F6C6F723D6175746F002D616C46002F6465762F74747955534235
type=PATH msg=audit(1638849198.965:404): item=0 name="/dev/ttyUSB5" inode=637 dev=00:05 mode=020660 ouid=0 ogid=20 rdev=bc:05 nametype=NORMAL cap_fp=0 cap_fi=0 cap_fe=0 cap_fver=0 cap_frootid=0
type=CWD msg=audit(1638849198.965:404): cwd="/etc/udev"
type=SYSCALL msg=audit(1638849198.965:404): arch=c000003e syscall=192 success=no exit=-61 a0=7fff45ceb2a0 a1=7f63f8fb06f6 a2=55e87b2f06d0 a3=ff items=1 ppid=5605 pid=6577 auid=1000 uid=1000 gid=1000 euid=1000 suid=1000 fsuid=1000 egid=1000 sgid=1000 fsgid=1000 tty=pts3 ses=3 comm="ls" exe="/usr/bin/ls" subj=unconfined key=(null)
----
time->Tue Dec  7 11:53:18 2021
type=PROCTITLE msg=audit(1638849198.965:405): proctitle=6C73002D2D636F6C6F723D6175746F002D616C46002F6465762F74747955534235
type=PATH msg=audit(1638849198.965:405): item=0 name="/dev/ttyUSB5" inode=637 dev=00:05 mode=020660 ouid=0 ogid=20 rdev=bc:05 nametype=NORMAL cap_fp=0 cap_fi=0 cap_fe=0 cap_fver=0 cap_frootid=0
type=CWD msg=audit(1638849198.965:405): cwd="/etc/udev"
type=SYSCALL msg=audit(1638849198.965:405): arch=c000003e syscall=191 success=no exit=-61 a0=7fff45ceb2a0 a1=55e87abdfeab a2=0 a3=0 items=1 ppid=5605 pid=6577 auid=1000 uid=1000 gid=1000 euid=1000 suid=1000 fsuid=1000 egid=1000 sgid=1000 fsgid=1000 tty=pts3 ses=3 comm="ls" exe="/usr/bin/ls" subj=unconfined key=(null)
----
time->Tue Dec  7 11:53:48 2021
type=PROCTITLE msg=audit(1638849228.649:418): proctitle=2F6F70742F676F6F676C652F6368726F6D652F6368726F6D65202D2D656E61626C652D6372617368706164
type=PATH msg=audit(1638849228.649:418): item=0 name="/dev/ttyUSB5" inode=637 dev=00:05 mode=020660 ouid=0 ogid=20 rdev=bc:05 nametype=NORMAL cap_fp=0 cap_fi=0 cap_fe=0 cap_fver=0 cap_frootid=0
type=CWD msg=audit(1638849228.649:418): cwd="/home/cassie"
type=SYSCALL msg=audit(1638849228.649:418): arch=c000003e syscall=257 success=yes exit=191 a0=ffffff9c a1=1158039e90a8 a2=902 a3=0 items=1 ppid=1547 pid=3356 auid=1000 uid=1000 gid=1000 euid=1000 suid=1000 fsuid=1000 egid=1000 sgid=1000 fsgid=1000 tty=(none) ses=3 comm="ThreadPoolForeg" exe="/opt/google/chrome/chrome" subj=unconfined key=(null)

[demonguy]

What is the structure of the 103 bytes of data returned? Is it the expected 48 bytes followed by garbage? Is it two or more 48 byte chunks concatenated together?

When getReader() is called the browser starts reading from the port and adding any data that is received to the stream. When read() is called any data received so far is returned. In general, rather than calling read() and expecting it to contain exactly the data it is looking for a program should call read() until it gets all the data it expects, process that, and then continue reading until it gets the next expected piece of data.

for normal real serial port it may be true. However for virtual serial port from USB. i don't think there should be garbege.

[reillyeon]

I'd like to try to reproduce this myself but haven't had time. Something else I'd look at to see if anything is unexpectedly communicating with the device before Chrome opens it is to collect a USB packet trace with Wireshark. You can then line up the USB packets with the data returned by the Web Serial API. That could at least show whether or not something is being corrupted within Chrome.

[demonguy]

Here is the info i captured from wireshark. which indeed provide some information.
wireshark.zip

1. in good.pcapng

with filter usb.dst == host and usb.transfer_type == 3. ignore the first 4 packet, that's android fastboot protocol. i use fastboot command to enter into serial mode of my phone.
you can see i do have correct packet here, and in browser, i also have good data.

This is what i capture in chrome
Uint8Array(48) [1, 0, 0, 0, 48, 0, 0, 0, 3, 0, 0, 0, 1, 0, 0, 0, 0, 4, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, buffer: ArrayBuffer(48), byteLength: 48, byteOffset: 0, length: 48]

---

---

---

---

---

---

---

2. in bad.pcapng
   However when problem occurs, use the same filter, we can see there are redundant data.
   
   

This is what i capture in chrome
value: Uint8Array(103) [0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 4, 0, 0, 0, 16, 0, 0, 0, 13, 0, 0, 0, 1, 0, 0, 0, 4, 0, 0, 0, 16, 0, 0, 0, 13, 0, 0, 0, 1, 0, 0, 0, 4, 0, 0, 0, 16, 0, 0, 0, 13, 0, 0, 0, 1, 0, 0, 0, 4, 0, 0, 0, 16, 0, 0, 0, 13, 0, 0, 0, 1, …]

So , now i have 2 questions here.

1. it seems that my PC automatically send back something to my phone, so my phone response with the redandunt packet. I'm not sure who did it. (but i strongly suspect it's web serial who did it, because the phone serial mode is used for flashing roms, and we have been using it for years)
2. Even though, web serial should be able to read the all data and return it to me. but web serial only return me the last 103 bytes to me. why? the first 9 bytes are discarded. totally there are 112 bytes (48 bytes good data, the 4 * 16 bytes redandunt data)

[reillyeon]

There's no reason why Web Serial would send any data not written to the WritableStream to the device. The behavior you are seeing is consistent with another application opening the TTY device, sending some data, reading 9 bytes and then closing it. When Chrome the opens the device it reads the remaining 39 bytes originally sent by the device plus the 80 bytes sent in response to the data written by the other program.

You can see from the auditd log in your previous comment that systemd-udevd also opened /dev/ttyUSB5 before Chrome did.

My guess is that when you disable the serial driver in order to WebUSB instead it means that the /dev/ttyUSB5 device doesn't get created and so whatever is opening it doesn't get a chance to.

Something you can test is performing a Wireshark capture when Chrome isn't running to see if this communication still happens.

[demonguy]

My guess is that when you disable the serial driver in order to WebUSB instead it means that the /dev/ttyUSB5 device doesn't get created and so whatever is opening it doesn't get a chance to.
Something you can test is performing a Wireshark capture when Chrome isn't running to see if this communication still happens.

Basically, i have 2 proofs point to chrome:

1. other serial tools like minicom doesn't have this problem, like i mentioned above. So i've already done the test you said.
2. maybe you can notice that, in bad.pcapng, the timestamp of packet 1827 and 1833 is really close to each other. That's consistent to what i see, "if i don't call webserial, wireshark shows no one is reading from the serial. And as soon as i call it, it return wrong data."

If it's really something who read the first 9 bytes, it's really strange that it always read just after i call webserial API.

[demonguy]

I upload a screencast as evidence.

1. you can see, the serial port is already there after i type "fastboot oem edl" command. this tells my phone to enter into serial mode. (10 seconds of the video)
2. wireshark shows 4 packet, and there are all fastboot packet, has nothing to do with serial.
3. before i call webserial API, wireshark shows nothing. if someone else is reading it, the wireshark should show it.
4. after i wait sometime, i call webserial, the it immediately shows good data and wrong data all together. and the data returned by webserial is wrong. (25 seconds of the video)

cast.mp4

[reillyeon]

That screen capture is interesting because it looks like the full 112 bytes are received by Chrome this time.

[demonguy]

That screen capture is interesting because it looks like the full 112 bytes are received by Chrome this time.

emmmm. i didn't notice it. strange. normally chrome cannot receive everything. Let me try again

[reillyeon]

I've been reading through qcserial.c to see if there's anything interesting about this USB serial driver. I wonder if it uses some kind of in-band signaling for doing things like setting baud rate and so the system calls Chrome is making to configure the port on connect are causing this data to be sent. Are you using the stock Qualcomm serial driver that comes with that version of Ubuntu?

[demonguy]

I didn't install any qualcomm driver manually. It should come with my ubuntu distribution.

lsmod | grep qc
qcserial               24576  0
usb_wwan               28672  1 qcserial
usbserial              53248  2 qcserial,usb_wwan

lsusb
Bus 002 Device 002: ID 8087:8000 Intel Corp. 
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
**Bus 001 Device 005: ID 05c6:9008 Qualcomm, Inc. Gobi Wireless Modem (QDL mode)**
Bus 001 Device 004: ID 0a12:0001 Cambridge Silicon Radio, Ltd Bluetooth Dongle (HCI mode)
Bus 001 Device 003: ID 0451:8044 Texas Instruments, Inc. 
Bus 001 Device 002: ID 8087:8008 Intel Corp. 
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

[demonguy]

This time, the crhome receive wrong data.

cast.mp4

[demonguy]

Is this issue solved?

while i cannot get the correct data. I tried another way: just reset the device state machine by sending a reset command to it.
However it also has problem, when i reset, the ttyUSB re-emulate a new device, which cause webserial crash and report Uncaught (in promise) DOMException: The device has been lost.

Now we really run out of ways. So we just tell our users to set a udev rule, run a script to detach qcserial driver every time they plug the device in

[reillyeon]

That's the best workaround I have for now as I haven't had time to dive into what is going on with this particular device and driver combination.

[demonguy]

That's the best workaround I have for now as I haven't had time to dive into what is going on with this particular device and driver combination.

Well. Understood. Thanks for you help :)
Please let me know if we can do any experiment or provide any information

[demonguy]

Despite we can take advantage of udev on ubuntu
How can we use webUSB on windows for a usb-serial device?
It shows "access denied

[reillyeon]

Similar to Linux, you can manually replace the Qualcomm serial driver with the WinUSB driver so that Chrome can get low-level access to the USB device. The tool for that on Windows is called Zadig. This may not be necessary however and I would check first to see whether you observe the same problem you encountered on Linux when using Windows.

[demonguy]

I'will take a look at windows and make sure. Then feedback ASAP.

[demonguy]

Per "#166".
It seems that windows can receive from webserial correctly.

So far, we tell our users to modify /etc/udev/rules.d to remove qcserial driver.
But i think it's really odd to let user modify a so low-level program to use a web app.

We found on mac, WebUSB can work directly. Maybe there is no qcserial driver on it.

[demonguy]

BTW. This issue is a little bit similar with #166 .
To be more clear, let me explain the protocol when this issue happen.

1. once the device boot, it sends hello packet, which is "Uint8Array(48) [1, 0, 0, 0, 48, 0, 0, 0, 3, 0, 0, 0, 1, 0, 0, 0, 0, 4, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]", first 4 bytes means "id", hence "hello packet", second 4 bytes is packet length]
2. Then i need to response something, and if my response is wrong, then the device sends me 'end packet' "Uint8Array(16) [4, 0, 0, 0, 16, 0, 0, 0, 13, 0, 0, 0, 1, 0, 0, 0]". also, first 4 bytes means "end".

when i encouter issue in #166 , the device also sends me "end packet". Which means the device thinks i finish the communication and my response is wrong.

Also , in this issue, the device thinks i send something wrong. Though i didn't send anything. Just read from the device.

So the problem above is

1. sometimes the data webserial received is truncated. Just like Webserial must open a large size buffer to transmit data #166 when i send.
2. something i don't know what sends empty usb packet after i read from device.

[demonguy]

We decide to download chronium and build ourselves to check where is the problem.
But we're not familiar with chronium codes and C++.
Would mind giving us some hints? for example which file or which function should we check first?

[reillyeon]

The data read path for Linux and macOS is implemented in serial_port_underlying_source.cc (in the renderer), serial_port_impl.cc and serial_io_handler_posix.cc. The data write path is the same but starts with serial_port_underlying_sink.cc (in the renderer). Windows is the same but ends with serial_io_handler_win.cc