ULPM does not work properly when USB CF3 not connected


#1

Hello,

I read somewhere, do not remember where, that there was a bug with USB and ULPM in some firmware version. I am experiencing this issue right now, the module does not want to enter ULPM properly, meaning sometimes it might enter for a few seconds but then wake up again. I have tried on both WP8548 (Release 14) and WP7702 (Release 8). Below are logs taken from serial (USB console):

WP8548:

[ 20.082008] mbim_open: Open mbim driver
[ 20.084846] mbim_open: Lock mbim_dev->open_excl for open
[ 20.091652] mbim_open: USB cable not connected
[ 20.095070] mbim_open: Exit, mbim file opened
[ 20.104135] mbim_read: Requests list is empty. Wait.
[ 21.178666] i2c i2c-0: Added multiplexed i2c bus 1
[ 21.198809] i2c i2c-0: Added multiplexed i2c bus 2
[ 21.228689] i2c i2c-0: Added multiplexed i2c bus 3
[ 21.244437] i2c i2c-0: Added multiplexed i2c bus 4
[ 21.248374] pca954x 0-0071: registered 4 multiplexed busses for I2C switch pca9546
[ 21.433267] 0-0076 supply vddd not found, using dummy regulator
[ 21.438425] 0-0076 supply vdda not found, using dummy regulator
[ 24.256249] softdog: Software Watchdog Timer: 0.08 initialized. soft_noboot=0 soft_margin=60 sec soft_panic=0 (nowayout=0)
[ 27.900289] gpio_sync_ri: RI owner is Modem
[ 28.608271] PM: Syncing filesystems … done.
[ 28.709507] Freezing user space processes …
[ 28.714512] mbim_read: Waiting failed
[ 28.752296] (elapsed 0.039 seconds) done.
[ 28.755287] Freezing remaining freezable tasks … (elapsed 0.001 seconds) done.
[ 28.763192] Suspending console(s) (use no_console_suspend to debug)

As soon as USB CF3 is connected:

[ 28.782511] msm_hsic_host msm_hsic_host: HSIC-USB in low power mode
[ 28.782847] PM: suspend of devices complete after 11.750 msecs
[ 28.784953] PM: late suspend of devices complete after 2.075 msecs
[ 28.786815] PM: noirq suspend of devices complete after 1.861 msecs
[ 28.787059] msm_pm_enter
[ 28.787059] msm_pm_enter: power collapse
[ 28.787059] msm_mpm_irqs_detectable: cannot monitor 000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000
[ 28.787059] msm_pm_enter: return
[ 28.788524] PM: noirq resume of devices complete after 1.373 msecs
[ 28.790599] PM: early resume of devices complete after 1.556 msecs
[ 28.792308] msm_otg msm_otg: USB exited from low power mode
[ 28.792430] msm_hsic_host msm_hsic_host: HSIC-USB exited from low power mode
[ 28.827987] PM: resume of devices complete after 37.387 msecs
[ 28.907950] Restarting tasks …
[ 28.916587] mbim_read: Requests list is empty. Wait.
[ 28.920860] ci_hdrc ci_hdrc.0: CI_HDRC_CONTROLLER_RESUME_EVENT received
[ 28.927361] android_disconnect: android_disconnect: Disconnected
[ 28.957668] android_work: android_work: sent uevent USB_STATE=DISCONNECTED
[ 28.966549] done.
[ 29.047398] android_setup: android_setup: Connected
[ 29.056432] android_disconnect: android_disconnect: Disconnected
[ 29.061620] android_work: android_work: did not send uevent (0 0 (null))
[ 29.199359] android_setup: android_setup: Connected
[ 29.204700] android_work: android_work: sent uevent USB_STATE=CONNECTED
[ 29.210407] android_usb gadget: high-speed config #1: android_usb
[ 29.216664] msm_otg msm_otg: Avail curr from USB = 500
[ 29.221516] android_setup: android_setup: Configured
[ 29.228078] sps:REVISION of BAM 0xd0360000 is 0x5.
[ 29.242362] IPv6: ADDRCONF(NETDEV_CHANGE): usb0: link becomes ready
[ 29.301480] android_work: android_work: sent uevent USB_STATE=CONFIGURED
[ 32.151045] NOHZ: local_softirq_pending 08
[ 32.233023] NOHZ: local_softirq_pending 08
[ 35.487990] NOHZ: local_softirq_pending 08
[ 36.706210] NOHZ: local_softirq_pending 08
[ 36.911887] NOHZ: local_softirq_pending 08
[ 37.105844] NOHZ: local_softirq_pending 08
[ 37.160323] qup_i2c qup_i2c.0: QUP: I2C status flags :0x1300c8, irq:187
[ 37.165969] qup_i2c qup_i2c.0: I2C slave addr:0x3a not connected
[ 37.180802] gpio_check_and_wake: wake-n_gpio77 STATE=WAKEUP
[ 37.202197] gpio_check_and_wake: wake-n_gpio77 STATE=SLEEP
[ 37.421883] NOHZ: local_softirq_pending 08
[ 37.615840] NOHZ: local_softirq_pending 08
[ 44.262994] nmea: smd opened
[ 47.204211] qup_i2c qup_i2c.0: QUP: I2C status flags :0x1300c8, irq:187
[ 47.210376] qup_i2c qup_i2c.0: I2C slave addr:0x3a not connected
[ 51.873828] SysRq : Emergency Sync
[ 51.877826] SysRq : Power Off
[ 51.882740] reboot: Power down
[ 51.884785] Powering of

WP7702:

[ 24.899398] msm-pcm-routing soc:qcom,msm-pcm-routing: ASoC: mux SLIM_0_RX AANC MUX has no paths
[ 24.997222] msm-dai-stub-dev soc:qcom,msm-dai-stub:qcom,msm-dai-stub-dtmf-tx: ASoC: no sink widget found for STUB_DTMF_TX
[ 25.025138] msm-dai-stub-dev soc:qcom,msm-dai-stub:qcom,msm-dai-stub-dtmf-tx: ASoC: Failed to add route DTMF TX -> direct -> STUB_DTMF_TX
[ 25.052593] msm-dai-stub-dev soc:qcom,msm-dai-stub:qcom,msm-dai-stub-host-rx-capture-tx: ASoC: no sink widget found for STUB_HOST_RX_CAPTURE_TX
[ 25.075378] msm-dai-stub-dev soc:qcom,msm-dai-stub:qcom,msm-dai-stub-host-rx-capture-tx: ASoC: Failed to add route CS-VOICE HOST RX CAPTURE -> direct -> STUB_HOST_RX_CAPTURE_TX
[ 25.090487] msm-dai-stub-dev soc:qcom,msm-dai-stub:qcom,msm-dai-stub-host-rx-playback-rx: ASoC: no source widget found for STUB_HOST_RX_PLAYBACK_RX
[ 25.103743] msm-dai-stub-dev soc:qcom,msm-dai-stub:qcom,msm-dai-stub-host-rx-playback-rx: ASoC: Failed to add route STUB_HOST_RX_PLAYBACK_RX -> direct -> CS-VOICE HOST RX PLAYBACK
[ 25.123122] msm-dai-stub-dev soc:qcom,msm-dai-stub:qcom,msm-dai-stub-host-tx-capture-tx: ASoC: no sink widget found for STUB_HOST_TX_CAPTURE_TX
[ 25.160301] msm-dai-stub-dev soc:qcom,msm-dai-stub:qcom,msm-dai-stub-host-tx-capture-tx: ASoC: Failed to add route CS-VOICE HOST TX CAPTURE -> direct -> STUB_HOST_TX_CAPTURE_TX
[ 25.198738] msm-dai-stub-dev soc:qcom,msm-dai-stub:qcom,msm-dai-stub-host-tx-playback-rx: ASoC: no source widget found for STUB_HOST_TX_PLAYBACK_RX
[ 25.230340] msm-dai-stub-dev soc:qcom,msm-dai-stub:qcom,msm-dai-stub-host-tx-playback-rx: ASoC: Failed to add route STUB_HOST_TX_PLAYBACK_RX -> direct -> CS-VOICE HOST TX PLAYBACK
[ 25.932646] adm_callback: cmd = 0x10322 returned error = 0x16
[ 25.937359] adm_callback: ADM map error, resuming
[ 25.944754] adm_memory_map_regions: DSP returned error[ADSP_ERR_MAX]
[ 25.962667] adm_map_cal_data: map did not work! cal_type 0 ret -68
[ 25.967818] map_memory: map_cal failed, cal type 10, ret = -19!
[ 25.990218] adm_alloc_cal: cal_utils_alloc_block failed, ret = -19, cal type = 10!
[ 25.996756] call_allocs: alloc failed!
[ 30.139542] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
[ 36.224052] sierra_pm_resume, total sleep time = 77, startup_timer expired

After USB CF3 connected:

[ 38.092096] msm_otg 78d9000.usb: SM WORK: USB is in LPM
[ 38.518961] gbam_connect_work: gbam_connect_work: Bam channel is not ready
[ 40.208761] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
rcK: Executing run_K_scripts…
Stopping linkmon: no linkmon found; none killed
done
Stopping port_bridge: no port_bridge found; none killed
Stopping qmi_ip: no qmi_ip_multiclient found; none killed
Stopping netmgrd: stopped netmgrd (pid 926)
done
Stopping qmuxd: stopped qmuxd (pid 880)
done
no QCMAP_ConnectionManager found; none killed
Stopping fs-scrub-daemon: no fs-scrub-daemon found; none killed
Stopping thermal-engine: stopped thermal-engine (pid 887)
done
stopped qti (pid 1172)
Stopping reboot daemon: stopped reboot-daemon (pid 711)
done
Legato shutdown sequence
Stopping Legato…rmmod: can’t unload ‘2_iio_triggered_buffer’: unknown symbol in module, or unknown parameter
rmmod: can’t unload ‘1_iio_kfifo_buf’: unknown symbol in module, or unknown parameter
rmmod: can’t unload ‘0_iio’: unknown symbol in module, or unknown parameter
DONE.
Finished Legato stop Sequence
stopping time daemon
Stopping time_services: stopped time_daemon (pid 586)
done
stopping ntpd
no ntpd found; none killed
Stopping diagrebootapp: stopped diagrebootapp (pid 576)
done
stopping DNS forwarder and DHCP server: dnsmasq… stopped /usr/bin/dnsmasq (pid 1151)
done.
Deconfiguring network interfaces… ifdown: interface eth0 not configured
done.
Stopping syslogd/klogd: stopped syslogd (pid 559)
stopped klogd (pid 565)
done
Stopping Dropbear SSH server: stopped /usr/sbin/dropbear (pid 1114)
dropbear.
K96mount_unionfs: RO rootfs fudge allowed.
Stopping system message bus: dbus.
K98mount_early: Executing mount_early_user_stop…
K98mount_early: RO rootfs fudge allowed.
sh: /mnt/flash: unknown operand
K98mount_early: Executing mount_early_legato_stop…
K98mount_early: Executing mount_early_userrw_stop…
rcK: Executing kill_all_proc…
rcK: Executing umount_fs_generic…
rcK: Executing print_shutdown_msg…
** SYSTEM SHUTDOWN COMPLETE **
The system is going down NOW!
Sent SIGTERM to all processes
[ 49.416163] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister rmnet0
[ 50.063960] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister rmnet_data0
[ 50.189397] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister rmnet0
[ 50.284050] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister rmnet_data0
[ 50.381231] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister rmnet_data1
[ 50.461524] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister bridge0
[ 50.520163] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister rmnet_data1
[ 50.527797] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister rmnet_data2
Sent SIGKILL to all processes
Requesting system poweroff
[ 50.650927] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister bridge0
[ 50.679524] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister rmnet_data2
[ 50.687184] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister rmnet_data3
[ 50.839483] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister rmnet_data3
[ 51.558360] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:14) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
[ 51.587763] reboot: Power down
[ 51.589973] Failed to disable secure wdog debug: -4
[ 51.595246] Calling SCM to disable SPMI PMI