EG915U-EU Android 10 in deep-sleep usb errors

Marcin · May 27, 2022, 7:17am

Hi,

I have problem with EG915U-EU on Android 10 when system is going into deep-sleep.
After it wakes up from deep-sleep I can see usb disconnected and a lot of errors, then mobile icon disappeared
and gsm module is unusable.

I have tested others modules EG912Y-EU and UG95 with Android 10 and they are working.
All modules are connected with pppd.

Kernel version: 4.19.111
libquectel ril: 3.3.58

Entering deep-sleep:

05-26 13:17:21.526 D/use-Rlog/RLOG-RIL ATC(  309): AT> AT+COPS=3,2;+COPS?
05-26 13:17:21.574 D/use-Rlog/RLOG-RIL ATC(  309): AT< +COPS: 0,2,"26001",7
05-26 13:17:21.574 D/use-Rlog/RLOG-RIL ATC(  309): AT< OK
05-26 13:17:21.574 D/use-Rlog/RLOG-RIL ATC(  309): AT> AT+QCSQ
05-26 13:17:21.599 D/use-Rlog/RLOG-RIL ATC(  309): AT< +QCSQ: "LTE",82,-117,41,-16
05-26 13:17:21.599 D/use-Rlog/RLOG-RIL ATC(  309): AT< OK
05-26 13:17:21.600 D/use-Rlog/RLOG-RIL ATC(  309): AT> AT+CGREG?
05-26 13:17:21.601 D/SST     (  677): [0] received event 12
05-26 13:17:21.624 D/use-Rlog/RLOG-RIL ATC(  309): AT< +CGREG: 2,1,"521E","061150C",7
05-26 13:17:21.624 D/use-Rlog/RLOG-RIL ATC(  309): AT< OK
05-26 13:17:37.681 D/RILJ    (  677): [0097]> RIL_REQUEST_SEND_DEVICE_STATE 2:true [SUB0]
05-26 13:17:37.681 D/RILC    (  309): sendDeviceState: calling screen state 0
05-26 13:17:37.681 D/use-Rlog/RLOG-RIL RILC(  309): onRequest: SCREEN_STATE datalen=4
05-26 13:17:37.685 D/RILJ    (  677): [0098]> RIL_REQUEST_SET_UNSOLICITED_RESPONSE_FILTER 0 [SUB0]
05-26 13:17:37.721 D/SubscriptionController(  677): [getActiveSubscriptionInfo]+ subId=1 subInfo={id=1, iccId=8948011417270563989 simSlotIndex=0 carrierId=1658 displayName=Plus carrierName=Plus nameSource=0 iconTint=-16746133 mNumber=null dataRoaming=0 iconBitmap=android.graphics.Bitmap@6fc2a84 mcc 260 mnc 01mCountryIso=pl isEmbedded false nativeAccessRules null cardString=8948011417270563989 cardId=-1 isOpportunistic false mGroupUUID=null mIsGroupDisabled=false profileClass=-1 ehplmns = [] hplmns = [26001, 26001, 26001, 26001] subscriptionType=0 mGroupOwner=null carrierConfigAccessRules=null}
05-26 13:17:37.725 D/use-Rlog/RLOG-RIL RILU(  309): echo auto > /sys/bus/usb/devices/2-1.3/power/control
05-26 13:17:37.725 D/use-Rlog/RLOG-RIL RILU(  309): ql_set_autosuspend auto
05-26 13:17:37.726 D/RILJ    (  677): [0097]< RIL_REQUEST_SEND_DEVICE_STATE  [SUB0]
05-26 13:17:37.726 D/RILJ    (  677): [0098]< RIL_REQUEST_SET_UNSOLICITED_RESPONSE_FILTER error 6 [SUB0]
05-26 13:17:37.726 D/RilRequest(  677): [0098]< RIL_REQUEST_SET_UNSOLICITED_RESPONSE_FILTER error: com.android.internal.telephony.CommandException: REQUEST_NOT_SUPPORTED ret=
05-26 13:17:37.790 D/DCT-C   (  677): screen on
05-26 13:17:37.790 D/DCT-C   (  677): stopNetStatPoll
05-26 13:17:37.792 D/DCT-C   (  677): startNetStatPoll
05-26 13:17:37.796 D/SubscriptionController(  677): [getActiveSubscriptionInfo]+ subId=1 subInfo={id=1, iccId=8948011417270563989 simSlotIndex=0 carrierId=1658 displayName=Plus carrierName=Plus nameSource=0 iconTint=-16746133 mNumber=null dataRoaming=0 iconBitmap=android.graphics.Bitmap@6fc2a84 mcc 260 mnc 01mCountryIso=pl isEmbedded false nativeAccessRules null cardString=8948011417270563989 cardId=-1 isOpportunistic false mGroupUUID=null mIsGroupDisabled=false profileClass=-1 ehplmns = [] hplmns = [26001, 26001, 26001, 26001] subscriptionType=0 mGroupOwner=null carrierConfigAccessRules=null}
05-26 13:17:37.837 D/DCT-C   (  677): screen off
05-26 13:17:37.837 D/DCT-C   (  677): stopNetStatPoll
05-26 13:17:37.839 D/DCT-C   (  677): startNetStatPoll
[  394.835354] Suspending console(s) (use no_console_suspend to debug)

Wake-up form deep-sleep:

[  395.340819] Enabling non-boot CPUs ...
[  395.341279] Detected VIPT I-cache on CPU1
[  395.341403] CPU1: Booted secondary processor 0x0000000001 [0x410fd042]
[  395.342732] CPU1 is up
[  395.343376] Detected VIPT I-cache on CPU2
[  395.343493] CPU2: Booted secondary processor 0x0000000002 [0x410fd042]
[  395.344520] CPU2 is up
[  395.345070] Detected VIPT I-cache on CPU3
[  395.345182] CPU3: Booted secondary processor 0x0000000003 [0x410fd042]
[  395.346491] CPU3 is up
[  395.351191] usb usb2: root hub lost power or was reset
[  395.410219] usb usb3: root hub lost power or was reset
[  395.417079] rk_gmac-dwmac ff360000.ethernet: init for RMII
[  395.540391] rk_gmac-dwmac ff360000.ethernet eth0: No Safety Features support found
[  395.544000] dwc2 ff300000.usb: resuming usb gadget configfs-gadget
[  395.580353] rockchip-vop ff460000.vop: [drm:vop_crtc_atomic_enable] Update mode to 720x1280p58, type: 16
[  395.580626] dw-mipi-dsi ff450000.dsi: [drm:dw_mipi_dsi_encoder_enable] final DSI-Link bandwidth: 822 x 2 Mbps
[  395.699466] usb 2-1: reset high-speed USB device number 2 using ehci-platform
[  396.064991] OOM killer enabled.
[  396.065007] Restarting tasks ... done.
[  396.067509] PM: suspend exit
[  396.073148] init: Received control message 'interface_start' for 'android.hardware.radio.deprecated@1.0::IOemHook/slot1' from pid: 125 (/system/bin/hwservicemanager)
[  396.073271] init: Could not find 'android.hardware.radio.deprecated@1.0::IOemHook/slot1' for ctl.interface_start
[  396.145808] usb 2-1.3: new full-speed USB device number 21 using ehci-platform
[  396.226002] usb 2-1.3: device descriptor read/64, error -32
[  396.410220] usb 2-1.3: device descriptor read/64, error -32
[  396.589166] usb 2-1.3: new full-speed USB device number 22 using ehci-platform
[  396.621078] healthd: battery l=100 v=11506 t=18.8 h=2 st=5 c=594 fc=2900000 chg=
[  396.662484] usb 2-1.3: device descriptor read/64, error -32
[  397.049518] usb 2-1.3: device descriptor read/64, error -32
[  397.078148] init: Received control message 'interface_start' for 'android.hardware.radio.deprecated@1.0::IOemHook/slot1' from pid: 125 (/system/bin/hwservicemanager)
[  397.156525] usb 2-1-port3: attempt power cycle
[  397.749527] usb 2-1.3: new full-speed USB device number 23 using ehci-platform
[  398.162850] usb 2-1.3: device not accepting address 23, error -32
[  398.442943] usb 2-1.3: new full-speed USB device number 24 using ehci-platform
[  398.855997] usb 2-1.3: device not accepting address 24, error -32
[  398.856425] usb 2-1-port3: unable to enumerate USB device
05-26 13:20:07.493 D/use-Rlog/RLOG-RIL RILU( 1426): find_pci_device is 0
05-26 13:20:07.497 E/use-Rlog/RLOG-RIL RILU( 1426): cannot find ttyname for AT Port
05-26 13:20:07.497 D/use-Rlog/RLOG-RIL RILC( 1426): USB can't find at device
[  399.086125] init: Received control message 'interface_start' for 'android.hardware.radio.deprecated@1.0::IOemHook/slot1' from pid: 125 (/system/bin/hwservicemanager)
[  399.086408] init: Could not find 'android.hardware.radio.deprecated@1.0::IOemHook/slot1' for ctl.interface_start
[  400.089606] init: Received control message 'interface_start' for 'android.hardware.radio.deprecated@1.0::IOemHook/slot1' from pid: 125 (/system/bin/hwservicemanager)
[  400.089861] init: Could not find 'android.hardware.radio.deprecated@1.0::IOemHook/slot1' for ctl.interface_start
[  401.093444] init: Received control message 'interface_start' for 'android.hardware.radio.deprecated@1.0::IOemHook/slot1' from pid: 125 (/system/bin/hwservicemanager)
[  401.093701] init: Could not find 'android.hardware.radio.deprecated@1.0::IOemHook/slot1' for ctl.interface_start
05-26 13:20:10.499 D/use-Rlog/RLOG-RIL RILU( 1426): find_pci_device is 0
05-26 13:20:10.503 E/use-Rlog/RLOG-RIL RILU( 1426): cannot find ttyname for AT Port
05-26 13:20:10.503 D/use-Rlog/RLOG-RIL RILC( 1426): USB can't find at device

Bean.Wang-Q · April 18, 2023, 9:07am

When the AP enters sleep, some APs will cut off the power of the usb host controller or usb hub for power saving or some bugs cannot be solved.
Then when AP resumes, you must reset these usb host controller or usb hub.
The following can be seen in the kernel log of the AP:
[ 1034.284930] usb usb1: root hub lost power or was reset
Since the usb host controller or usb hub has been reset, it needs to re-enumerate our module
The following can be seen in the kernel log of the AP:
[ 1034.609288] usb 1-1: reset high-speed USB device number 3 using ehci-platform

Bean.Wang-Q · April 18, 2023, 9:07am

Maybe you foget to add:

#if 1 //Added by Quectel
.reset_resume = usb_wwan_resume,
#endif

Marcin · April 18, 2023, 1:50pm

I have all modification in kernel.
Power is applied to usb.
I have changed system to Embedded Linux with diffrent cpu, because it is easier to debug problems.
I was thinking how to reproduce the same effect in Embedded Linux and I can get same effect.
Try this:

Connect modem with ppp
Try resume/suspend system (echo mem > /sys/power/state) - modem is working
Then before suspend run $ wget -O /dev/null http://speedtest.wdc01.softlayer.com/downloads/test10.zip &
After few time modem disconnect from usb bus and not connect again.

I have tried with UG95 and EG915U-EU and UG95 is working all the time.