Here are the radio logs. The only thing I can think of that might be wrong is the HIDL interface definition? It looks like some of the telephony commands are not supported.
04-23 02:59:06.599 D/Phone ( 3924): updateImsPhone mImsServiceReady=true
04-23 02:59:06.599 D/TelephonyTester( 3924): register for intent action=com.android.internal.telephony.imsphone.action_detached
04-23 02:59:06.599 D/TelephonyTester( 3924): register for intent action=com.android.internal.telephony.imsphone.action_attached
04-23 02:59:06.599 D/TelephonyTester( 3924): register for intent action=com.android.internal.telephony.TestConferenceEventPackage
04-23 02:59:06.601 D/Phone ( 3924): mDoesRilSendMultipleCallRing=false
04-23 02:59:06.601 D/Phone ( 3924): mCallRingDelay=3000
04-23 02:59:06.601 D/QtiTelephonyComponentFactory( 3924): makeImsPhoneCallTracker
04-23 02:59:06.601 D/TelephonyComponentFactory( 3924): makeImsPhoneCallTracker
04-23 02:59:06.603 E/ImsPhoneCallTracker( 3924): [0] cacheCarrierConfiguration: No carrier config service found or not active subId = 2147483643
04-23 02:59:06.606 D/SST ( 3924): [0] notifyDataRegStateRilRadioTechnologyChanged: drs=1 rat=0
04-23 02:59:06.607 D/ImsPhone( 3924): [0] updateDataServiceState: defSs = {mVoiceRegState=1(OUT_OF_SERVICE), mDataRegState=1(OUT_OF_SERVICE), mChannelNumber=0, duplexMode()=0, mCellBandwidths=[], mVoiceRoamingType=home, mDataRoamingType=home, mVoiceOperatorAlphaLong=null, mVoiceOperatorAlphaShort=null, mDataOperatorAlphaLong=null, mDataOperatorAlphaShort=null, isManualNetworkSelection=false(automatic), mRilVoiceRadioTechnology=0(Unknown), mRilDataRadioTechnology=0(Unknown), mCssIndicator=unsupported, mNetworkId=0, mSystemId=0, mCdmaRoamingIndicator=0, mCdmaDefaultRoamingIndicator=0, mIsEmergencyOnly=false, mIsDataRoamingFromRegistration=false, mIsUsingCarrierAggregation=false, mLteEarfcnRsrpBoost=0, mNetworkRegistrationStates=[]} imsSs = {mVoiceRegState=1(OUT_OF_SERVICE), mDataRegState=1(OUT_OF_SERVICE), mChannelNumber=-1, duplexMode()=0, mCellBandwidths=[], mVoiceRoamingType=home, mDataRoamingType=home, mVoiceOperatorAlphaLong=null, mVoiceOperatorAlphaShort=null, mDataOperatorAlphaLong=null, mDataOperatorAlphaShort=null, isManualNetworkSelection=false(automatic), mRilVoiceRadioTechnology=0(Unknown), mRilDataRadioTechnology=0(Unknown), mCssIndicator=unsupported, mNetworkId=-1, mSystemId=-1, mCdmaRoamingIndicator=-1, mCdmaDefaultRoamingIndicator=-1, mIsEmergencyOnly=false, mIsDataRoamingFromRegistration=false, mIsUsingCarrierAggregation=false, mLteEarfcnRsrpBoost=0, mNetworkRegistrationStates=[]}
04-23 02:59:06.608 D/CallManager( 3924): registerPhone(ImsPhone Handler (com.android.internal.telephony.imsphone.ImsPhone) {35596a1})
04-23 02:59:06.609 D/TelephonyRegistry( 1158): listen oscl: hasNotifySubscriptionInfoChangedOccurred==false no callback
04-23 02:59:06.610 D/SubscriptionController( 3924): [getPhoneId]- invalid subId return=-1
04-23 02:59:06.611 D/QtiTelephonyComponentFactory( 3924): makeQtiPhoneSwitcher
04-23 02:59:06.615 D/TelephonyRegistry( 1158): listen oscl: hasNotifySubscriptionInfoChangedOccurred==false no callback
04-23 02:59:06.618 D/PhoneSwitcher( 3924): PhoneSwitcher started
04-23 02:59:06.622 D/ProxyController( 3924): Constructor - Enter
04-23 02:59:06.624 D/ProxyController( 3924): clearTransaction
04-23 02:59:06.624 D/ProxyController( 3924): clearTransaction: phoneId=0 status=IDLE
04-23 02:59:06.624 D/ProxyController( 3924): Constructor - Exit
04-23 02:59:06.629 D/TelephonyNetworkFactory[0]( 3924): Registering NetworkFactory
04-23 02:59:06.630 D/QtiTelephonyComponentFactory( 3924): makeExtTelephonyClasses
04-23 02:59:06.635 D/QtiUiccCardProvisioner( 3924): Invoking constructor, no of phones = 1
04-23 02:59:06.641 D/QtiRadioCapabilityController( 3924): getInstance
04-23 02:59:06.643 D/QtiRadioCapabilityController( 3924): Constructor - Exit
04-23 02:59:06.653 D/ExtTelephonyServiceImpl( 3924): init constructor
04-23 02:59:06.657 D/CallManager( 3924): registerPhone(GSM Handler (com.qualcomm.qti.internal.telephony.QtiGsmCdmaPhone) {1faf54c})
04-23 02:59:06.676 D/TelephonyRegistry( 1158): listen oscl: hasNotifySubscriptionInfoChangedOccurred==false no callback
04-23 02:59:06.677 D/CallManager( 3924): registerForMmiComplete
04-23 02:59:06.689 D/RILJ ( 3924): [3654]> RIL_REQUEST_SET_TTY_MODE ttyMode = 0 [SUB0]
04-23 02:59:06.689 D/use-Rlog/RLOG-RIL RILC( 606): onRequest: SET_TTY_MODE datalen=4
04-23 02:59:06.690 D/RILJ ( 3924): [3654]< RIL_REQUEST_SET_TTY_MODE [SUB0]
04-23 02:59:06.691 D/ImsPhone( 3924): [0] sendErrorResponse
04-23 02:59:06.693 D/TelephonyRegistry( 1158): listen oscl: hasNotifySubscriptionInfoChangedOccurred==false no callback
04-23 02:59:06.695 D/SubscriptionController( 3924): [getPhoneId] asked for default subId=2147483643
04-23 02:59:06.695 D/QtiSubscriptionController( 3924): getPhoneId, received dummy subId 2147483643
04-23 02:59:06.700 D/DebugService( 3924): DebugService DebugService:
04-23 02:59:06.700 D/SubscriptionManager( 3924): [getSubId]- fail
04-23 02:59:06.708 D/UiccController( 3924): Received EVENT_RADIO_AVAILABLE/EVENT_RADIO_ON, calling getIccCardStatus
04-23 02:59:06.709 D/RILJ ( 3924): [3655]> GET_SIM_STATUS [SUB0]
04-23 02:59:06.709 D/UiccController( 3924): Received EVENT_RADIO_AVAILABLE/EVENT_RADIO_ON for phoneId 0, calling getIccSlotsStatus
04-23 02:59:06.709 D/use-Rlog/RLOG-RIL RILC( 606): onRequest: GET_SIM_STATUS
04-23 02:59:06.710 D/use-Rlog/RLOG-RIL ATC( 606): AT> AT+CPIN?
04-23 02:59:06.713 D/use-Rlog/RLOG-RIL ATC( 606): AT< +CPIN: READY
04-23 02:59:06.713 D/use-Rlog/RLOG-RIL ATC( 606): AT< OK
04-23 02:59:06.713 D/use-Rlog/RLOG-RIL ATC( 606): AT> AT+CSQ
04-23 02:59:06.713 D/RILJ ( 3924): IccCardApplicationStatus 0:{APPTYPE_SIM,APPSTATE_READY} [SUB0]
04-23 02:59:06.713 D/RILJ ( 3924): responseIccCardStatus: from HIDL: IccCardState {CARDSTATE_PRESENT,PINSTATE_UNKNOWN,num_apps=1,gsm_id=0{APPTYPE_SIM,APPSTATE_READY},cdma_id=-1,ims_id=-1,physical_slot_id=-1,atr=null,iccid=null} [SUB0]
04-23 02:59:06.713 D/RILJ ( 3924): [3655]< GET_SIM_STATUS IccCardState {CARDSTATE_PRESENT,PINSTATE_UNKNOWN,num_apps=1,gsm_id=0{APPTYPE_SIM,APPSTATE_READY},cdma_id=-1,ims_id=-1,physical_slot_id=-1,atr=null,iccid=null} [SUB0]
04-23 02:59:06.714 D/use-Rlog/RLOG-RIL ATC( 606): AT< +CSQ: 16,99
04-23 02:59:06.714 D/use-Rlog/RLOG-RIL ATC( 606): AT< OK
04-23 02:59:06.714 D/use-Rlog/RLOG-RIL ATC( 606): AT> AT+CGREG?
04-23 02:59:06.716 D/use-Rlog/RLOG-RIL ATC( 606): AT< +CGREG: 2,1,"7879","0F18F02",7
04-23 02:59:06.716 D/use-Rlog/RLOG-RIL ATC( 606): AT< OK
04-23 02:59:06.716 D/RILJ ( 3924): [UNSL]< UNSOL_RESPONSE_NETWORK_STATE_CHANGED [SUB0]
04-23 02:59:06.730 D/use-Rlog/RLOG-RIL ATC( 606): AT> at+qcfg="dbgctl",1
04-23 02:59:06.732 D/use-Rlog/RLOG-RIL ATC( 606): AT< ERROR
04-23 02:59:07.733 D/use-Rlog/RLOG-RIL ATC( 606): AT> at+qcfg="dbgctl",1
04-23 02:59:07.736 D/use-Rlog/RLOG-RIL ATC( 606): AT< ERROR
04-23 02:59:08.738 D/use-Rlog/RLOG-RIL ATC( 606): AT> at+qcfg="dbgctl",1
04-23 02:59:08.740 D/use-Rlog/RLOG-RIL ATC( 606): AT< ERROR
04-23 02:59:09.445 D/GsmCellBroadcastHandler( 3924): mWakeLock released
04-23 02:59:09.452 D/CellBroadcastHandler( 3924): mWakeLock released
04-23 02:59:09.460 D/CdmaServiceCategoryProgramHandler( 3924): mWakeLock released
04-23 02:59:09.742 D/use-Rlog/RLOG-RIL ATC( 606): AT> at+qcfg="dbgctl",1
04-23 02:59:09.747 D/use-Rlog/RLOG-RIL ATC( 606): AT< ERROR
04-23 02:59:10.147 D/SST ( 3924): [0] mDeviceShuttingDown=true, mDesiredPowerState=false, getRadioState=RADIO_ON, mPowerOffDelayNeed=true, mAlarmSwitch=false, mRadioDisabledByCarrier=false
04-23 02:59:10.148 D/SubscriptionController( 3924): [getPhoneId]- invalid subId return=-1
04-23 02:59:10.148 D/QtiDCT ( 3924): [0]cleanUpAllConnections
04-23 02:59:10.149 D/SST ( 3924): [0] Data disconnected, turn off radio right away.
04-23 02:59:10.153 D/RILJ ( 3924): [3656]> RADIO_POWER on = false [SUB0]
04-23 02:59:10.153 D/RILC ( 606): setRadioPower: serial 8 on 0
04-23 02:59:10.154 D/use-Rlog/RLOG-RIL RILC( 606): onRequest: RADIO_POWER datalen=4
04-23 02:59:10.154 E/use-Rlog/RLOG-RIL RILC( 606): requestRadioPower begin.
04-23 02:59:10.154 D/use-Rlog/RLOG-RIL RILC( 606): requestRadioPower shutdownAction is 1recovery
this is the dmesg output:
[ 230.228873] usb 1-1.1: new high-speed USB device number 3 using msm_hsusb_host
[ 230.340243] usb 1-1.1: New USB device found, idVendor=2c7c, idProduct=0125
[ 230.340262] usb 1-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 230.340271] usb 1-1.1: Product: Android
[ 230.340281] usb 1-1.1: Manufacturer: Android
[ 230.352454] option 1-1.1:1.0: GSM modem (1-port) converter detected
[ 230.353624] usb 1-1.1: GSM modem (1-port) converter now attached to ttyUSB0
[ 230.357157] option 1-1.1:1.1: GSM modem (1-port) converter detected
[ 230.357723] usb 1-1.1: GSM modem (1-port) converter now attached to ttyUSB1
[ 230.358644] option 1-1.1:1.2: GSM modem (1-port) converter detected
[ 230.359542] usb 1-1.1: GSM modem (1-port) converter now attached to ttyUSB2
[ 230.360679] option 1-1.1:1.3: GSM modem (1-port) converter detected
[ 230.361553] usb 1-1.1: GSM modem (1-port) converter now attached to ttyUSB3
[ 230.363896] qmi_wwan 1-1.1:1.4: cdc-wdm0: USB WDM device
[ 230.363915] qmi_wwan 1-1.1:1.4: Quectel EC21&EC25 work on RawIP mode
[ 230.372692] qmi_wwan 1-1.1:1.4 wwan0: register 'qmi_wwan' at usb-msm_hsusb_host-1.1, WWAN/QMI device, 0000000000000000
[ 231.900222] type=1400 audit(1587652551.489:31): avc: denied { read } for pid=1592 comm="ndroid.settings" name="mm_stat" dev="sysfs" ino=23226 scontext=u:r:system_app:s0 tcontext=u:object_r:sysfs_zram:s0 tclass=file permissive=1
[ 231.900271] type=1400 audit(1587652728.529:40): avc: denied { read write } for pid=607 comm="rild" name="ttyUSB2" dev="tmpfs" ino=36857 scontext=u:r:rild:s0 tcontext=u:object_r:device:s0 tclass=chr_file permissive=1
[ 231.900938] type=1400 audit(1587652728.529:40): avc: denied { read write } for pid=607 comm="rild" name="ttyUSB2" dev="tmpfs" ino=36857 scontext=u:r:rild:s0 tcontext=u:object_r:device:s0 tclass=chr_file permissive=1
[ 231.900968] type=1400 audit(1587652728.529:41): avc: denied { open } for pid=607 comm="rild" path="/dev/ttyUSB2" dev="tmpfs" ino=36857 scontext=u:r:rild:s0 tcontext=u:object_r:device:s0 tclass=chr_file permissive=1
[ 231.901269] type=1400 audit(1587652728.529:41): avc: denied { open } for pid=607 comm="rild" path="/dev/ttyUSB2" dev="tmpfs" ino=36857 scontext=u:r:rild:s0 tcontext=u:object_r:device:s0 tclass=chr_file permissive=1
[ 231.901297] type=1400 audit(1587652728.533:42): avc: denied { ioctl } for pid=607 comm="rild" path="/dev/ttyUSB2" dev="tmpfs" ino=36857 ioctlcmd=5401 scontext=u:r:rild:s0 tcontext=u:object_r:device:s0 tclass=chr_file permissive=1
[ 233.248418] binder: unexpected work type, 4, not freed
[ 233.248433] binder: undelivered TRANSACTION_COMPLETE
[ 233.248440] binder: undelivered transaction 75162, process died.
[ 233.844790] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 234.360465] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 234.861091] init: Received control message 'interface_start' for 'android.hardware.secure_element@1.0::ISecureElement/eSE1' from pid: 330 (/system/bin/hwservicemanager)
[ 234.861153] init: Could not find service hosting interface android.hardware.secure_element@1.0::ISecureElement/eSE1
[ 234.863830] init: Received control message 'interface_start' for 'android.hardware.secure_element@1.0::ISecureElement/SIM1' from pid: 330 (/system/bin/hwservicemanager)
[ 234.863887] init: Could not find service hosting interface android.hardware.secure_element@1.0::ISecureElement/SIM1
[ 234.864214] init: Received control message 'interface_start' for 'android.hardware.secure_element@1.0::ISecureElement/SIM1' from pid: 330 (/system/bin/hwservicemanager)
[ 234.864256] init: Could not find service hosting interface android.hardware.secure_element@1.0::ISecureElement/SIM1
[ 234.875648] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 235.411231] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 235.860161] binder: unexpected work type, 4, not freed
[ 235.860177] binder: undelivered TRANSACTION_COMPLETE
[ 235.860185] binder: undelivered transaction 79734, process died.
[ 235.940857] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 236.453928] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 236.977529] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 237.407873] binder: undelivered TRANSACTION_COMPLETE
[ 237.407888] binder: undelivered transaction 82433, process died.
[ 237.994958] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 238.513840] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 239.033206] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 239.466951] binder: unexpected work type, 4, not freed
[ 239.466966] binder: undelivered TRANSACTION_COMPLETE
[ 239.466973] binder: undelivered transaction 85976, process died.
[ 240.527294] binder: undelivered transaction 87785, process died.
[ 240.587085] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 241.138834] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 242.224666] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 242.739885] binder: 1157:1179 transaction failed 29189/-22, size 280-8 line 3015
[ 243.158984] init: Received control message 'start' for 'setup-bcb' from pid: 1157 (system_server)
[ 243.160282] init: starting service 'setup-bcb'...
[ 243.164736] init: Created socket '/dev/socket/uncrypt', mode 600, user 1000, group 1000
[ 243.190366] init: Received control message 'interface_start' for 'android.hardware.radio.config@1.0::IRadioConfig/default' from pid: 330 (/system/bin/hwservicemanager)
[ 243.190425] init: Could not find service hosting interface android.hardware.radio.config@1.0::IRadioConfig/default
[ 243.191706] init: Received control message 'interface_start' for 'android.hardware.radio.config@1.0::IRadioConfig/default' from pid: 330 (/system/bin/hwservicemanager)
[ 243.191766] init: Could not find service hosting interface android.hardware.radio.config@1.0::IRadioConfig/default
[ 244.183068] init: Service 'setup-bcb' (pid 3775) exited with status 0
[ 244.230524] init: processing action (sys.shutdown.requested=*) from (/vendor/etc/init/hw/init.qcom.rc:861)
[ 244.232807] init: processing action (sys.shutdown.requested=*) from (/vendor/etc/init/hw/init.target.rc:339)
[ 244.233039] init: Sending signal 9 to service 'vendor.per_proxy' (pid 488) process group...
[ 244.239576] libprocessgroup: Successfully killed process cgroup uid 1000 pid 488 in 6ms
[ 244.240472] init: Service 'vendor.per_proxy' (pid 488) received signal 9
[ 244.241108] init: Sending signal 9 to service 'vendor.ims_rtp_daemon' (pid 614) process group...
[ 244.252146] libprocessgroup: Successfully killed process cgroup uid 1000 pid 614 in 10ms
[ 244.252577] init: Service 'vendor.ims_rtp_daemon' (pid 614) received signal 9
[ 244.367436] rmt_storage:INFO:rmt_storage_rw_iovec_cb: Write iovec request received for /boot/modem_fs2
[ 244.368063] rmt_storage:INFO:rmt_storage_client_thread: Calling Write [offset=0, size=1572864]for /boot/modem_fs2!
[ 244.436939] rmt_storage:INFO:rmt_storage_client_thread: Done Write (bytes = 1572864) for /boot/modem_fs2!
[ 244.510414] ipa_get_ipc_logbuf_low:2802 IPA HW is not supported
[ 244.535487] pil-q6v5-mss 4080000.qcom,mss: Port 0000000000000000 halt timeout
[ 244.560550] pil-q6v5-mss 4080000.qcom,mss: Port 0000000000000000 halt timeout
[ 244.562778] ipa_get_ipc_logbuf_low:2802 IPA HW is not supported
[ 258.605452] init: Received sys.powerctl='reboot,recovery' from pid: 1157 (system_server)
[ 258.605617] init: Clear action queue and start shutdown trigger
[ 258.605895] init: processing action (shutdown_done) from (<Builtin Action>:0)
[ 258.605944] init: Reboot start, reason: reboot,recovery, rebootTarget: recovery
It looks like another RIL is still running / trying to run instead of the one that the Quectel modem needs / expects