search

Biktorgj / quectel_eg25_recovery

Stock firmware recovery packages for Quectel EG25-G
78 stars 15 forks source link

ioctl USBDEVFS_GETDRIVER failed, kernel driver may be inactive #18

Closed Zapeth closed 2 years ago

Zapeth commented 2 years ago

While trying to update the modem firmware to the latest EG25GGBR07A08M2G_30.006.30.006 version I got this:

$ sudo ./qfirehose -f ./
[000.000]: QFirehose Version: Quectel_LTE&5G_QFirehose_Linux&Android_V1.2.3
[000.000]: Builded: Oct 21 2020 19:13:31
[000.000]: Find md5 check file <./md5.txt>
[000.004]: md5 checking: ./contents.xml pass
[000.039]: md5 checking: ./update/appsboot.mbn pass
[000.052]: md5 checking: ./update/ENPRG9x07.mbn pass
[000.054]: md5 checking: ./update/firehose/partition_complete_p2K_b128K.mbn pass
[000.055]: md5 checking: ./update/firehose/patch_p2K_b128K.xml pass
[000.063]: md5 checking: ./update/firehose/prog_nand_firehose_9x07.mbn pass
[000.064]: md5 checking: ./update/firehose/rawprogram_nand_p2K_b128K_update.xml pass
[000.350]: md5 checking: ./update/mdm9607-boot.img pass
[000.830]: md5 checking: ./update/mdm9607-recovery.ubi pass
[003.512]: md5 checking: ./update/mdm9607-sysfs.ubi pass
[005.334]: md5 checking: ./update/NON-HLOS.ubi pass
[005.346]: md5 checking: ./update/NPRG9x07.mbn pass
[005.347]: md5 checking: ./update/partition.mbn pass
[005.350]: md5 checking: ./update/partition_nand.xml pass
[005.360]: md5 checking: ./update/rpm.mbn pass
[005.370]: md5 checking: ./update/sbl1.mbn pass
[005.396]: md5 checking: ./update/tz.mbn pass
[005.482]: md5 checking: ./update/usrdata.ubi pass
[005.482]: Totals checking 18 files md5 value, 0 file fail!
[005.482]: [1] /sys/bus/usb/devices/2-1 5c6/9008/0
[005.483]: P: /dev/bus/usb/002/003 idVendor=05c6 idProduct=9008
[005.483]: C: /dev/bus/usb/002/003 bNumInterfaces: 1
[005.483]: I: If#= 0 Alt= 0 #EPs= 2 Cls=ff Sub=ff Prot=ff
[005.483]: E: Ad=81 Atr=02 MxPS= 512 Ivl=0ms
[005.483]: E: Ad=01 Atr=02 MxPS= 512 Ivl=0ms
[005.483]: usbfs_is_kernel_driver_alive ioctl USBDEVFS_GETDRIVER failed, kernel driver may be inactive
[005.483]: Fail to claim interface 0, errno: 2 (No such file or directory)
[005.483]: Error: when module in 'Emergency download mode', should not register any usb driver

with the last 8 lines repeating every second or so.

There were no issues during preparation of the modem for the update (ie adb reboot edl), this is the lsusb output before executing qfirehorse:

$ lsusb
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 003: ID 05c6:9008 Qualcomm, Inc. Gobi Wireless Modem (QDL mode)
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

Considering the error mentions a missing/inactive kernel driver I guess the issue is related to the kernel? I currently have pmOS v21.12 installed (fully updated), though I was able to upgrade the modem firmware at some point with an older version (I think it was v20.05), so I'm not sure what changed.

Any pointers towards troubleshooting/fixing this issue would be appreciated, thanks

Zapeth commented 2 years ago

I tried to update the modem now without manually changing into edl mode, and this is the output (I slightly modified some debug output in qfirehose to make sure the correct interface was being called)

$sudo ./qfirehose -f ./
[000.000]: QFirehose Version: Quectel_LTE&5G_QFirehose_Linux&Android_V1.2.3
[000.001]: Builded: Jun 30 2022 21:28:42
[000.001]: Find md5 check file <./md5.txt>
[000.005]: md5 checking: ./contents.xml pass
[000.035]: md5 checking: ./update/appsboot.mbn pass
[000.048]: md5 checking: ./update/ENPRG9x07.mbn pass
[000.050]: md5 checking: ./update/firehose/partition_complete_p2K_b128K.mbn pass
[000.051]: md5 checking: ./update/firehose/patch_p2K_b128K.xml pass
[000.061]: md5 checking: ./update/firehose/prog_nand_firehose_9x07.mbn pass
[000.062]: md5 checking: ./update/firehose/rawprogram_nand_p2K_b128K_update.xml pass
[000.313]: md5 checking: ./update/mdm9607-boot.img pass
[000.804]: md5 checking: ./update/mdm9607-recovery.ubi pass
[002.813]: md5 checking: ./update/mdm9607-sysfs.ubi pass
[004.213]: md5 checking: ./update/NON-HLOS.ubi pass
[004.224]: md5 checking: ./update/NPRG9x07.mbn pass
[004.225]: md5 checking: ./update/partition.mbn pass
[004.227]: md5 checking: ./update/partition_nand.xml pass
[004.234]: md5 checking: ./update/rpm.mbn pass
[004.244]: md5 checking: ./update/sbl1.mbn pass
[004.270]: md5 checking: ./update/tz.mbn pass
[004.362]: md5 checking: ./update/usrdata.ubi pass
[004.362]: Totals checking 18 files md5 value, 0 file fail!
[004.363]: [1] /sys/bus/usb/devices/2-1 2c7c/125/318
[004.430]: P: /dev/bus/usb/002/002 idVendor=2c7c idProduct=0125
[004.430]: C: /dev/bus/usb/002/002 bNumInterfaces: 6
[004.430]: I: If#= 0 Alt= 0 #EPs= 2 Cls=ff Sub=ff Prot=ff
[004.430]: E: Ad=81 Atr=02 MxPS= 512 Ivl=0ms
[004.430]: E: Ad=01 Atr=02 MxPS= 512 Ivl=0ms
[004.430]: I: If#= 1 Alt= 0 #EPs= 3 Cls=ff Sub=00 Prot=00
[004.430]: I: If#= 2 Alt= 0 #EPs= 3 Cls=ff Sub=00 Prot=00
[004.430]: I: If#= 3 Alt= 0 #EPs= 3 Cls=ff Sub=00 Prot=00
[004.431]: I: If#= 4 Alt= 0 #EPs= 3 Cls=ff Sub=ff Prot=ff
[004.431]: I: If#= 5 Alt= 0 #EPs= 2 Cls=ff Sub=42 Prot=01
[004.431]: [quectel_get_usb_device_info] name: /dev/bus/usb/002/002, fd: 3, if: 5
[004.431]: qusb_noblock_open port_name = /dev/ttyUSB0
[009.605]: old software version: EG25GGBR07A08M2G
[010.607]: poll_wait events=POLLIN msec=1000 timeout
[010.607]: qusb_noblock_read cur=0, min_size=1
[010.607]: switch to 'Emergency download mode'
[010.610]: successful, wait module reboot
[011.693]: P: /dev/bus/usb/002/003 idVendor=05c6 idProduct=9008
[011.694]: C: /dev/bus/usb/002/003 bNumInterfaces: 1
[011.694]: I: If#= 0 Alt= 0 #EPs= 2 Cls=ff Sub=ff Prot=ff
[011.694]: E: Ad=81 Atr=02 MxPS= 512 Ivl=0ms
[011.694]: E: Ad=01 Atr=02 MxPS= 512 Ivl=0ms
[011.694]: [quectel_get_usb_device_info] name: /dev/bus/usb/002/003, fd: 3, if: 0
[011.694]: usbfs_is_kernel_driver_alive ioctl USBDEVFS_GETDRIVER failed, kernel driver may be inactive (fd: 3, if: 0, ret: -1, errno: 61, str: No data available)
[011.694]: dir=./update/firehose
[011.694]: d_name=prog_nand_firehose_9x07.mbn
[011.694]: prog_nand_firehose_filename = prog_nand_firehose_9x07.mbn
[011.694]: STATE <-- SAHARA_WAIT_HELLO
[011.695]: RECEIVED <--  SAHARA_HELLO_ID
[011.695]: RECEIVED <-- SAHARA_MODE_IMAGE_TX_PENDING
[011.695]: SENDING --> SAHARA_HELLO_RESPONSE
[011.695]: STATE <-- SAHARA_WAIT_COMMAND
[011.695]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.695]: 0x0000000d 0x00000000 0x00000034
[011.695]: STATE <-- SAHARA_WAIT_COMMAND
[011.695]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.695]: 0x0000000d 0x00000034 0x00000060
[011.696]: STATE <-- SAHARA_WAIT_COMMAND
[011.696]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.696]: 0x0000000d 0x00001000 0x00000088
[011.696]: STATE <-- SAHARA_WAIT_COMMAND
[011.696]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.696]: 0x0000000d 0x00002000 0x00001000
[011.697]: STATE <-- SAHARA_WAIT_COMMAND
[011.697]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.697]: 0x0000000d 0x00003000 0x00001000
[011.698]: STATE <-- SAHARA_WAIT_COMMAND
[011.698]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.698]: 0x0000000d 0x00004000 0x00001000
[011.698]: STATE <-- SAHARA_WAIT_COMMAND
[011.699]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.699]: 0x0000000d 0x00005000 0x00001000
[011.699]: STATE <-- SAHARA_WAIT_COMMAND
[011.700]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.700]: 0x0000000d 0x00006000 0x00001000
[011.700]: STATE <-- SAHARA_WAIT_COMMAND
[011.700]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.700]: 0x0000000d 0x00007000 0x00001000
[011.701]: STATE <-- SAHARA_WAIT_COMMAND
[011.701]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.701]: 0x0000000d 0x00008000 0x00001000
[011.701]: STATE <-- SAHARA_WAIT_COMMAND
[011.702]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.702]: 0x0000000d 0x00009000 0x00001000
[011.702]: STATE <-- SAHARA_WAIT_COMMAND
[011.703]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.703]: 0x0000000d 0x0000a000 0x00001000
[011.703]: STATE <-- SAHARA_WAIT_COMMAND
[011.703]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.703]: 0x0000000d 0x0000b000 0x00001000
[011.704]: STATE <-- SAHARA_WAIT_COMMAND
[011.704]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.704]: 0x0000000d 0x0000c000 0x00001000
[011.705]: STATE <-- SAHARA_WAIT_COMMAND
[011.705]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.705]: 0x0000000d 0x0000d000 0x00001000
[011.705]: STATE <-- SAHARA_WAIT_COMMAND
[011.706]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.706]: 0x0000000d 0x0000e000 0x00001000
[011.706]: STATE <-- SAHARA_WAIT_COMMAND
[011.707]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.707]: 0x0000000d 0x0000f000 0x00001000
[011.707]: STATE <-- SAHARA_WAIT_COMMAND
[011.707]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.708]: 0x0000000d 0x00010000 0x00001000
[011.708]: STATE <-- SAHARA_WAIT_COMMAND
[011.708]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.708]: 0x0000000d 0x00011000 0x00001000
[011.709]: STATE <-- SAHARA_WAIT_COMMAND
[011.709]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.709]: 0x0000000d 0x00012000 0x00001000
[011.710]: STATE <-- SAHARA_WAIT_COMMAND
[011.710]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.710]: 0x0000000d 0x00013000 0x00001000
[011.710]: STATE <-- SAHARA_WAIT_COMMAND
[011.711]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.711]: 0x0000000d 0x00014000 0x00001000
[011.711]: STATE <-- SAHARA_WAIT_COMMAND
[011.712]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.712]: 0x0000000d 0x00015000 0x00001000
[011.712]: STATE <-- SAHARA_WAIT_COMMAND
[011.713]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.713]: 0x0000000d 0x00016000 0x00001000
[011.713]: STATE <-- SAHARA_WAIT_COMMAND
[011.714]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.714]: 0x0000000d 0x00017000 0x00001000
[011.714]: STATE <-- SAHARA_WAIT_COMMAND
[011.715]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.715]: 0x0000000d 0x00018000 0x00001000
[011.715]: STATE <-- SAHARA_WAIT_COMMAND
[011.716]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.716]: 0x0000000d 0x00019000 0x00001000
[011.716]: STATE <-- SAHARA_WAIT_COMMAND
[011.716]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.716]: 0x0000000d 0x0001a000 0x00001000
[011.717]: STATE <-- SAHARA_WAIT_COMMAND
[011.717]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.717]: 0x0000000d 0x0001b000 0x00001000
[011.718]: STATE <-- SAHARA_WAIT_COMMAND
[011.718]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.718]: 0x0000000d 0x0001c000 0x00001000
[011.719]: STATE <-- SAHARA_WAIT_COMMAND
[011.719]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.719]: 0x0000000d 0x0001d000 0x00001000
[011.719]: STATE <-- SAHARA_WAIT_COMMAND
[011.720]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.720]: 0x0000000d 0x0001e000 0x00001000
[011.721]: STATE <-- SAHARA_WAIT_COMMAND
[011.721]: RECEIVED <-- SAHARA_READ_DATA_ID
[011.721]: 0x0000000d 0x0001f000 0x00000578
[011.721]: STATE <-- SAHARA_WAIT_COMMAND
[011.747]: RECEIVED <-- SAHARA_END_IMAGE_TX_ID
[011.748]: image_id = 13, status = 0
[011.748]: SENDING --> SAHARA_DONE
[011.748]: STATE <-- SAHARA_WAIT_DONE_RESP
[011.748]: RECEIVED <-- SAHARA_DONE_RESP_ID
[011.748]: image_tx_status = 0
[011.748]: Sahara protocol completed
[011.748]: dir=./update/firehose
[011.748]: d_name=rawprogram_nand_p2K_b128K_update.xml
[012.874]: inf[0] ep_in -1/1024, errno = 108 (Cannot send after socket shutdown)
[012.874]: qusb_noblock_read read=-1, errno: 108 (Cannot send after socket shutdown)
[012.874]: qusb_noblock_read cur=0, min_size=1
[012.874]: firehose_protocol.c fh_recv_cmd 309 fail
[012.875]: inf[0] ep_in -1/1024, errno = 19 (No such device)
[012.876]: qusb_noblock_read read=-1, errno: 19 (No such device)
[012.876]: qusb_noblock_read cur=0, min_size=1
[012.876]: firehose_protocol.c fh_recv_cmd 309 fail
[012.876]: <configure MemoryName="nand" Verbose="0" AlwaysValidate="0" MaxDigestTableSizeInBytes="2048" MaxPayloadSizeToTargetInBytes="8192"  ZlpAwareHost="1" SkipStorageInit="0" />
[012.876]: inf[0] USBDEVFS_SUBMITURB -1/225, errno = 19 (No such device)
[012.876]: qusb_noblock_write write=-1, errno: 19 (No such device)
[012.876]: qusb_noblock_write cur=0, min_size=225
[012.876]: firehose_protocol.c fh_send_cmd 464 fail
[012.876]: inf[0] ep_in -1/1024, errno = 19 (No such device)
[012.876]: qusb_noblock_read read=-1, errno: 19 (No such device)
[012.876]: qusb_noblock_read cur=0, min_size=1
[012.876]: firehose_protocol.c fh_recv_cmd 309 fail
[012.876]: firehose_protocol.c fh_wait_response_cmd 375 fail
[012.876]: firehose_protocol.c fh_send_cfg_cmd 493 fail
[012.876]: firehose_protocol.c firehose_main 652 fail
[012.876]: Upgrade module failed.

So it looks like automatic edl mode switching works, but then it runs into the original issue again (ENODATA for USBDEVFS_GETDRIVER and ENOENT for other requests).

Zapeth commented 2 years ago

Also just noticed an error in dmesg when executing adb reboot edl (last line)

[ 1517.632650] usb 2-1: USB disconnect, device number 3
[ 1517.633504] option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
[ 1517.633614] option 2-1:1.0: device disconnected
[ 1517.634384] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
[ 1517.634484] option 2-1:1.1: device disconnected
[ 1517.643921] option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
[ 1517.644066] option 2-1:1.2: device disconnected
[ 1517.645474] option1 ttyUSB3: GSM modem (1-port) converter now disconnected from ttyUSB3
[ 1517.645626] option 2-1:1.3: device disconnected
[ 1517.648443] qmi_wwan 2-1:1.4 wwan0: unregister 'qmi_wwan' usb-1c1b000.usb-1, WWAN/QMI device
[ 1518.018629] usb 2-1: new high-speed USB device number 4 using ehci-platform
[ 1525.329892] usb 2-1: can't set config #1, error -110

Which apparently could be power related?

Though this even happened with battery at ~70% and being connected to a USB charger, so not sure if thats the reason for the error (I also don't remember this being an issue when I first updated the firmware).

Biktorgj commented 2 years ago

This is a timeout: usb 2-1: can't set config #1, error -110, which I wouldn't pay much attention to, because when you reboot to edl mode the modem basically just kills itself without going through a normal reboot process.

I think what is happening is that something is rebooting the modem or playing with the port while you're trying to flash. Please try doing the following:

  1. With the modem booted normally, stop ModemManager via systemd
  2. Prevent eg25-manager from restarting (systemctl disable) without stopping it normally
  3. Kill eg25-manager (killall -9 eg25-manager), so it doesn't go through the process of powering the modem down
  4. With both eg25-manager and modemmanager out of the way, rerun qfirehose.

Does it change the behaviour? You also have a script called flashstock in the repo, so you can flash the firmware with fastboot instead of qfirehose if it's misbehaving

Zapeth commented 2 years ago

Please try doing the following:

Thanks, that solved the issue! I still got the USBDEVFS_GETDRIVER failed message at the beginning, but this time the update process started after the SAHARA_ data exchange, so I guess that was a red herring.

Also, maybe this should be reported as an eg25-manager issue, so it doesn't interfere with communication when the modem is in edl mode?