UsbSerial
UsbSerial copied to clipboard
felHR85
Device Re-Connection
If connected device is restarted or disconnected via cable, application not able to send/receive data. to fix this, user need to re-plug-in USB cable to work app properly.
I believe I've reproduced this issue with the standard serialportexample code. I setup a serial port with a device that generates a series of messages continuously. The first time the serial port example code is executed, it detects the USB/Serial bridge device (CP2102 in this case), connects & displays data. If I exit the app, remove it from the 'recently used' list (to ensure it a true/clean 're-start'), then re-launch the app, it appears to connect to the USB device, but no data is displayed. Please note I added some diagnostic log messages to help trace execution flow (seen in the traces below).
On the first execution of the app:
2019-01-07 14:04:44.176 21564-21564/? D/UsbService: findSerialPortDevice() pEA60:v10C4 class:0:0
2019-01-07 14:04:44.176 21564-21564/? D/UsbService: requestUserPermission()
2019-01-07 14:04:44.188 21564-21564/? D/UsbService: findSerialPortDevice() keep==false
2019-01-07 14:04:49.366 669-1183/? I/[email protected]: partner added
2019-01-07 14:04:49.367 669-1183/? I/[email protected]: uevent received DEVTYPE=typec_partner
2019-01-07 14:04:49.371 669-1183/? I/[email protected]: port0
2019-01-07 14:04:49.374 669-1183/? I/[email protected]: connected:1 canChangeMode:1 canChagedata:0 canChangePower:0
2019-01-07 14:04:49.375 880-1132/? I/UsbPortManager: ClientCallback: port0
2019-01-07 14:04:49.377 880-935/? I/UsbPortManager: USB port changed: port=UsbPort{id=port0, supportedModes=dual}, status=UsbPortStatus{connected=true, currentMode=dfp, currentPowerRole=source, currentDataRole=host, supportedRoleCombinations=[source:host, sink:device]}, canChangeMode=true, canChangePowerRole=false, canChangeDataRole=false
2019-01-07 14:04:50.387 880-935/? D/UsbDeviceManager: push notification:Charging connected device via USB
2019-01-07 14:04:50.882 880-938/? I/ActivityManager: Displayed com.android.systemui/.usb.UsbConfirmActivity: +6s694ms (total +75ms)
2019-01-07 14:04:51.045 21564-21564/? D/UsbService: usbReceiver(ACTION_USB_PERMISSION) granted:true
2019-01-07 14:04:51.057 21564-21668/? D/UsbSerialDevice: createUsbSerialDevice() vid:10C4 pid:EA60 name:'/dev/bus/usb/001/002'
2019-01-07 14:04:51.071 21564-21668/? I/CP2102SerialDevice: Interface succesfully claimed
2019-01-07 14:04:51.071 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: 0
2019-01-07 14:04:51.073 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: 4
2019-01-07 14:04:51.073 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: 0
2019-01-07 14:04:51.075 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: 16
2019-01-07 14:04:51.076 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: 0
2019-01-07 14:04:51.076 21564-21668/? D/UsbRequestJNI: init
2019-01-07 14:04:51.079 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: 4
2019-01-07 14:04:51.080 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: 2
2019-01-07 14:04:51.081 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: -1
2019-01-07 14:04:51.082 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: 2
2019-01-07 14:04:51.085 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: -1
2019-01-07 14:04:51.086 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: 2
2019-01-07 14:04:51.087 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: -1
2019-01-07 14:04:51.088 21564-21668/? I/CP2102SerialDevice: Control Transfer Response: 16
2019-01-07 14:04:51.088 21564-21668/? W/rialportexampl: Accessing hidden field Landroid/hardware/usb/UsbRequest;->mBuffer:Ljava/nio/ByteBuffer; (light greylist, reflection)
2019-01-07 14:04:51.088 21564-21668/? W/rialportexampl: Accessing hidden field Landroid/hardware/usb/UsbRequest;->mLength:I (light greylist, reflection)
Log messages following this point contain serial stream data (so it is clear the connection is complete & active.
On subsequent attempts to launch the app, I get:
2019-01-07 14:05:21.004 21737-21737/? D/UsbService: findSerialPortDevice() pEA60:v10C4 class:0:0
2019-01-07 14:05:21.004 21737-21737/? D/UsbService: requestUserPermission()
2019-01-07 14:05:21.006 21737-21737/? D/UsbService: findSerialPortDevice() keep==false
2019-01-07 14:05:21.075 21737-21737/? D/UsbService: usbReceiver(ACTION_USB_PERMISSION) granted:true
2019-01-07 14:05:21.081 21737-21759/? D/UsbSerialDevice: createUsbSerialDevice() vid:10C4 pid:EA60 name:'/dev/bus/usb/001/002'
2019-01-07 14:05:21.088 21737-21737/? D/MainActivity: mUSBReceiver(ACTION_NO_USB)
2019-01-07 14:05:21.089 21737-21759/? I/CP2102SerialDevice: Interface succesfully claimed
2019-01-07 14:05:21.090 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: 0
2019-01-07 14:05:21.091 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: 4
2019-01-07 14:05:21.092 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: 0
2019-01-07 14:05:21.093 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: 16
2019-01-07 14:05:21.094 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: 0
2019-01-07 14:05:21.094 21737-21759/? D/UsbRequestJNI: init
2019-01-07 14:05:21.096 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: 4
2019-01-07 14:05:21.097 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: 2
2019-01-07 14:05:21.098 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: -1
2019-01-07 14:05:21.099 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: 2
2019-01-07 14:05:21.100 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: -1
2019-01-07 14:05:21.102 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: 2
2019-01-07 14:05:21.103 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: -1
2019-01-07 14:05:21.105 21737-21759/? I/CP2102SerialDevice: Control Transfer Response: 16
2019-01-07 14:05:21.105 21737-21759/? W/rialportexampl: Accessing hidden field Landroid/hardware/usb/UsbRequest;->mBuffer:Ljava/nio/ByteBuffer; (light greylist, reflection)
2019-01-07 14:05:21.105 21737-21759/? W/rialportexampl: Accessing hidden field Landroid/hardware/usb/UsbRequest;->mLength:I (light greylist, reflection)
2019-01-07 14:05:21.151 492-546/? W/SurfaceFlinger: Attempting to set client state on removed layer: Surface(name=AppWindowToken{11c6c66 token=Token{de60cc1 ActivityRecord{b68d9a8 u0 com.felhr.serialportexample/.MainActivity t132}}})/@0xe05edec - animation-leash#0
2019-01-07 14:05:21.151 492-546/? W/SurfaceFlinger: Attempting to set client state on removed layer: Surface(name=AppWindowToken{93a59ab token=Token{75ffffa ActivityRecord{cfc2225 u0 com.google.android.apps.nexuslauncher/.NexusLauncherActivity t2}}})/@0xfc621d3 - animation-leash#0
2019-01-07 14:05:21.151 492-546/? W/SurfaceFlinger: Attempting to destroy on removed layer: Surface(name=AppWindowToken{11c6c66 token=Token{de60cc1 ActivityRecord{b68d9a8 u0 com.felhr.serialportexample/.MainActivity t132}}})/@0xe05edec - animation-leash#0
2019-01-07 14:05:21.151 492-546/? W/SurfaceFlinger: Attempting to destroy on removed layer: Surface(name=AppWindowToken{93a59ab token=Token{75ffffa ActivityRecord{cfc2225 u0 com.google.android.apps.nexuslauncher/.NexusLauncherActivity t2}}})/@0xfc621d3 - animation-leash#0
Subsequent log entries show no serial stream data. The four log entries at the bottom refering to 'SurfaceFlinger:' consistently appear after the two entries referencing reflection, ONLY on events that fail to re-establish data flow with the USB/Serial bridge. Serial data connection is ONLY re-established if I disconnect & re-connect the USB/Serial bridge (- Note that this will also re-display the OS dialog requesting user permission to access this device, which IS NOT DISPLAYED if the app is re-started).
Please note that the entry 'D/MainActivity: mUSBReceiver(ACTION_NO_USB)' is a bit confusing, since it appears shortly after 'D/UsbService: usbReceiver(ACTION_USB_PERMISSION) granted:true'. This is in reponse to the ACTION_NO_USB message sent by 'D/UsbService: findSerialPortDevice() keep==false'. There is a log entry for 'D/MainActivity: mUSBReceiver(ACTION_USB_PERMISSION_GRANTED)' that appears further down in the log, in reponse to the 'D/UsbService: usbReceiver(ACTION_USB_PERMISSION) granted:true' status.
I hope this provides required clues to help resolve this issue.
I should have added: The above results were on a Google Pixel running Android 9.
Any progress on this? I'm happy to test &/or help by providing additional diagnostics...?
@mws-rmain I did some testing and I didnt see anything wrong but It is true that is not closing the port when the service is destroyed. I added that in the master branch. Please give it a try.
I re-ran tests yesterday, with the patch in place to close the port in onDestroy(), but I still see the same problem. The process I'm following is:
- Execute the standard 'example' module (not 'examplemultipleports', 'examplestreams', or 'examplesync').
- Plug in the USB-Serial adapter. Verify receipt of serial data (I have a device that streams data over the port).
- Stop the app, and remove it from the 'recent apps' list to ensure it is purged from memory & will get a 'clean' restart.
- Restart the app. Log messages indicate interface is sucessfully claimed & CP2102 init matches that from first invokation of app. NO serial data is received.
I get the same behaviour on a Google Pixel running Android 9, and a Panasonic FZ-B2 tablet running Android 6.
The Pixel is a little annoying to work with, as it has only one USB port, so I download the app using Android Studio, remove the cable to the PC, insert the USB-Serial cable, run my test, then remove the USB-Serial cable, and re-insert the PC USB cable. This relies on android to buffer Logcat, which is dumped to Android Studio when re-connected.
The Panasonic Tablet has a USB-C connection for the PC, and a second USB-A connector that can be used for the USB-Serial adapter. This provides immediate visibility of Logcat.
Do either of the above hardware arrangements reflect you you test?
UPDATE: I have confirmed that the 'failure to restart' only occurs when the app receives a stream of serial data. My setup runs at 115200,8,N,1, and receives 'packets' of data (132 bytes, every 200ms). Connecting the 'device end' of my USB-Serial adapter to a PC running a terminal operates properly when shutting down & restarting the app.
I did note a message on shutdown of the app:
W/ActivityManager: Scheduling restart of crashed service com.felhr.serialportexample/.UsbService in 1000ms
Perhaps this is some kind of race condition when receiving data, such that the USB service fails to shut down properly (crashes), and therefore is unable to restart properly? Since disconnecting & re-connecting the cable is required to get the app working again, perhaps it's the CP2102 that is 'hung' (?).
I have confirmed that the 'failure to restart' only occurs when the app receives a stream of serial data. My setup runs at 115200,8,N,1, and receives 'packets' of data (132 bytes, every 200ms). Connecting the 'device end' of my USB-Serial adapter to a PC running a terminal operates properly when shutting down & restarting the app.
@mws-rmain Very good hint. It is probably something CP2102 related. I am adding purging to the CP2102 chipset https://github.com/felHR85/UsbSerial/commits/cp2012_improvs Could you try with this branch?
Unfortunately, issuing the 'purge' command when closing the port does not resolve the problem.
It seems to me that the call to unbindService(usbConnection) in MainActivity.onPause() is not invoking UsbService.onDestroy(). According to the documentation I read, onDestroy() should be called (by the system) when unbindService() is called if there are no more bound clients (and at this point there should not be - this is the one & only client). I placed a log message in UsbService.onDestroy() & it does not appear in Logcat when I close the app, although MainActivity.onPause() is called. Since UsbService.onDestroy() is required to disconnect & shutdown the USB service, this would explain the usbservice crash error I mentioned in an earlier post. Could you please confirm my findings?
@mws-rmain onDestroy not being called is probably what is going on. I would try putting open/close in onBind/onUnbind because those calls are always executed
