Hello,
we are facing problem while using radio connection, it is not obvious what leads to this.
Log is attached.
logread_sn010_13102020.txt (437.1 KB)
Legato version is 19.11.0-7
You can see some analysis below from log extracts.
We are attached to NW and successfully communicate with our MQTT server, so our communication is up and running.
For some reason, we are informed that communication is down, but we are not able to recover radio.
Can someone explain what happens ?
Thank you.
First everything is OK, we are communicating with our
Oct 12 08:37:20 wblgt01_010 user.info Legato: INFO | mqttClient[1087] | clientId : 9c762710-d800-11ea-be03-27d5417c7cae
Oct 12 08:37:20 wblgt01_010 user.info Legato: INFO | mqttClient[1087] | username : PHetYa9k0aseGIHdRW9H
Oct 12 08:37:20 wblgt01_010 user.info Legato: INFO | mqttClient[1087] | Attempting (1/3) to connect to tcp://iot.wiifor.com:1883...
Oct 12 08:37:20 wblgt01_010 user.info Legato: INFO | mqttClient[1087] | bytes sent: 74
Oct 12 08:37:20 wblgt01_010 user.info Legato: INFO | mqttClient[1087] | total bytes sent: 74 of 74
Oct 12 08:37:20 wblgt01_010 user.info Legato: INFO | mqttClient[1087] | ***CONNACK***
Oct 12 08:37:20 wblgt01_010 user.info Legato: INFO | mqttClient[1087] | OK
Oct 12 06:37:20 wblgt01_010 user.info Legato: INFO | protocolService[1132]/protocolServiceComponent T=main | protocolService.c dcsStateHandler() 471 | [PROTOCOL STATE] - Protocol is ready!
A bunch of things happen as we are expecting GNSS fix to happen .
Oct 12 08:37:21 wblgt01_010 user.err qti: QMUXD: WARNING qmi_qmux_if_pwr_up_init failed! rc=-6
Oct 12 08:37:21 wblgt01_010 user.warn kernel: [ 37.939396] USB QCMAP NL IOCTL Snd GETNEIGH Succ
Oct 12 08:37:21 wblgt01_010 user.warn Legato: -WRN- | posDaemon[1114]/le_pa_gnss T=main | pa_gnss_qmi.c pa_gnss_GetTtff() 4120 | TTFF not available
Oct 12 08:37:21 wblgt01_010 user.info Legato: INFO | gnssService[1036]/gnssServiceComponent T=main | gnssService.c positionHandler() 292 | Fix is not accurate enough (21474836) ! Waiting for next fix...
Oct 12 08:37:21 wblgt01_010 user.warn kernel: [ 38.056754] USB QCMAP NL IOCTL Snd GETNEIGH Succ
Oct 12 08:37:22 wblgt01_010 user.warn Legato: -WRN- | posDaemon[1114]/le_pa_gnss T=main | pa_gnss_qmi.c pa_gnss_GetTtff() 4120 | TTFF not available
Oct 12 08:37:22 wblgt01_010 user.info Legato: INFO | gnssService[1036]/gnssServiceComponent T=main | gnssService.c positionHandler() 292 | Fix is not accurate enough (21474836) ! Waiting for next fix...
…
Oct 12 08:37:48 wblgt01_010 user.warn Legato: -WRN- | posDaemon[1114]/le_pa_gnss T=main | pa_gnss_qmi.c pa_gnss_GetTtff() 4120 | TTFF not available
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | gnssService[1036]/gnssServiceComponent T=main | gnssService.c positionHandler() 292 | Fix is not accurate enough (21474836) ! Waiting for next fix...
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcsCellular T=main | dcsCellular.c DcsCellularConnEventStateHandler() 254 | State of connection 1 transitioned from up to down
DCS Cellular daemon informs us that connection is going from up to down
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcsCellular T=main | dcsCellular.c le_dcsCellular_RetryConn() 1300 | Initiated retrying connection 1; retry attempt 1, backoff 1 secs
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcsCellular T=main | dcsCellular.c DcsCellularConnEventStateHandler() 311 | Wait for the next retry before failing connection 1
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcsDaemon T=main | dcsServer.c ChannelEventHandler() 780 | Received for channel reference 0x16d event Temporary Down
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcsNet T=main | dcsNet.c le_net_RestoreDefaultGW() 658 | Default IPv4 GW address on interface restored
Oct 12 06:37:48 wblgt01_010 user.warn Legato: -WRN- | protocolService[1132]/protocolServiceComponent T=main | protocolService.c dcsStateHandler() 480 | [DATA CONNEXION STATE] - Disconnected
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | mqttClient[1087]/mqttClientApiComponent T=main | mqttClientApi.c mqttClient_Delete() 572 | Deleting MQTT instance mqttClientRef : 0x45
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | mqttClient[1087] | bytes sent: 2
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | mqttClient[1087] | total bytes sent: 2 of 2
Oct 12 08:37:48 wblgt01_010 user.notice kernel: [ 65.113200] audit: type=1400 audit(1602484668.312:3): lsm=SMACK fn=smack_inode_getattr action=denied subject="_" object="app.dataConnectionService" requested=r pid=1502 comm="dnsmasq" path="/var/resolv.conf" dev="tmpfs" ino=
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | mqttClient[1087]/mqttClientApiComponent T=main | mqttClientApi.c mqttClient_Delete() 575 | Deleting mqttClientRef : 0x45
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | mqttClient[1087]/mqttClientApiComponent T=main | mqttClientApi.c mqttClient_Delete() 578 | Releasing memory : 0x7f57eef0
Oct 12 06:37:48 wblgt01_010 user.warn Legato: -WRN- | protocolService[1132]/protocolServiceComponent T=main | protocolService.c dcsStateHandler() 482 | [PROTOCOL STATE] - Protocol session has been stopped
Oct 12 08:37:48 wblgt01_010 user.warn Legato: -WRN- | posDaemon[1114]/le_pa_gnss T=unknown | pa_gnss_qmi.c PositionHandler() 1509 | Bad position indication
Oct 12 08:37:48 wblgt01_010 user.warn kernel: [ 65.265366] PSM: Modem oprt mode - 1
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcsCellular T=main | dcsCellular.c DcsCellularPacketSwitchHandler() 726 | Packet switch state: previous 1, new 0
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcs T=main | dcs_db.c le_dcs_EventNotifierTechStateTransition() 310 | Notify all channels of technology 2 of system state transition to down
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcsDaemon T=main | dcsServer.c ChannelEventHandler() 780 | Received for channel reference 0x16d event Temporary Down
Oct 12 06:37:48 wblgt01_010 user.warn Legato: -WRN- | protocolService[1132]/protocolServiceComponent T=main | protocolService.c dcsStateHandler() 480 | [DATA CONNEXION STATE] - Disconnected
Oct 12 06:37:48 wblgt01_010 user.warn Legato: -WRN- | protocolService[1132]/protocolServiceComponent T=main | protocolService.c dcsStateHandler() 482 | [PROTOCOL STATE] - Protocol session has been stopped
Oct 12 06:37:48 wblgt01_010 user.info Legato: INFO | protocolService[1132]/protocolServiceComponent T=main | protocolService.c cellnetStateHandler() 414 | [CELLULAR NETWORK STATE] - The radio is switched-off
Oct 12 08:37:48 wblgt01_010 user.err Legato: =ERR= | modemDaemon[1073]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 799 | Sending QMI_DMS_SET_OPERATING_MODE_REQ_V01 failed: rc=0 (), resp.result=1.[0x01], resp.error=60.[0x3c]
Oct 12 06:37:48 wblgt01_010 user.emerg Legato: *EMR* | protocolService[1132]/protocolServiceComponent T=main | protocolService.c cellnetStateHandler() 420 | Couldn't switch on radio power: error LE_FAULT
We are not able to switch ON radio, we have a LE_FAULT on this which leads to our application not able to recover.
Oct 12 06:37:48 wblgt01_010 user.debug Legato: DBUG | lpmService[1061]/framework T=main | lpm_server.c CleanupClientData() 98 | Client 0x7f56b068 is closed !!!
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcsDaemon T=main | dcsServer.c CloseSessionEventHandler() 1329 | Client 0x7f5aaa58 killed, remove allocated resources
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcs T=main | dcs.c le_dcs_Stop() 538 | Stopping channel 1 of technology cellular
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcs T=main | dcs.c le_dcs_Stop() 563 | Channel 1 requested to be stopped
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcsDaemon T=main | dcsServer.c TryStopTechSession() 1157 | Successfully initiated stopping active data connection 1 of technology 1
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | dcsDaemon[1017]/dcs T=main | dcsTech.c le_dcsTech_Stop() 399 | Request to stop channel 1 of technology cellular
Oct 12 06:37:48 wblgt01_010 user.debug Legato: DBUG | lpmService[1061]/framework T=main | lpm_server.c CleanupClientData() 98 | Client 0x7f56afd8 is closed !!!
Oct 12 08:37:48 wblgt01_010 user.emerg Legato: *EMR* | tracker[1150]/framework T=main | messagingSession.c ClientSocketHangUp() 873 | Session closed by server (tracker.trackerComponent.protocol:4810fe5026b7d15b8e790b2731dd333c).
Oct 12 08:37:48 wblgt01_010 user.debug Legato: DBUG | gnssService[1036]/framework T=main | gnss_server.c CleanupClientData() 163 | Client 0x7f56c388 is closed !!!
Oct 12 06:37:48 wblgt01_010 user.debug Legato: DBUG | lpmService[1061]/framework T=main | lpm_server.c CleanupClientData() 98 | Client 0x7f56b0f8 is closed !!!
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | gpioService[1045]/sysfsGpio T=main | gpioSysfsUtils.c gpioSysfs_SessionCloseHandlerFunc() 1215 | Releasing GPIO 38
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | gpioService[1045]/sysfsGpio T=main | gpioSysfsUtils.c gpioSysfs_SessionCloseHandlerFunc() 1215 | Releasing GPIO 36
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | modemDaemon[1073]/modemDaemon T=main | le_mdc.c CloseSessionEventHandler() 961 | SessionRef 0x7f5fb970 has been closed
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | supervisor[875]/supervisor T=main | proc.c proc_SigChildHandler() 2079 | Process 'tracker' (PID: 1150) has exited with exit code 1.
Oct 12 08:37:48 wblgt01_010 user.err Legato: =ERR= | modemDaemon[1073]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 799 | Sending QMI_WDS_GET_PKT_STATISTICS_REQ_V01 failed: rc=0 (), resp.result=1.[0x01], resp.error=70.[0x46]
Oct 12 08:37:48 wblgt01_010 user.crit Legato: *CRT* | supervisor[875]/supervisor T=main | app.c app_SigChildHandler() 4087 | Process 'tracker' in app 'tracker' faulted: Restarting app.
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | supervisor[875]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'tracker'
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | supervisor[875]/supervisor T=main | proc.c proc_SigChildHandler() 2079 | Process 'protocolService' (PID: 1132) has exited with exit code 1.
Oct 12 08:37:48 wblgt01_010 user.err Legato: =ERR= | modemDaemon[1073]/le_pa T=main | pa_mdc_qmi.c pa_mdc_StopSession() 3378 | Bad input parameter
Oct 12 08:37:48 wblgt01_010 user.err Legato: =ERR= | dcsDaemon[1017]/dcsCellular T=main | dcsCellular.c le_dcsCellular_Stop() 1156 | Failed to stop cellular connection 1; error: -15
Oct 12 08:37:48 wblgt01_010 user.err Legato: =ERR= | dcsDaemon[1017]/dcs T=main | dcsTech.c le_dcsTech_Stop() 422 | Failed to stop channel 1; error: -15
Oct 12 08:37:48 wblgt01_010 user.warn Legato: -WRN- | supervisor[875]/supervisor T=main | app.c app_SigChildHandler() 4066 | Process 'protocolService' in app 'protocolService' faulted: Ignored.
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | supervisor[875]/supervisor T=main | app.c app_StopComplete() 4753 | app 'protocolService' has stopped.
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | supervisor[875]/supervisor T=main | apps.c DeactivateAppContainer() 374 | Application 'protocolService' has stopped.
Oct 12 08:37:48 wblgt01_010 user.info Legato: INFO | supervisor[875]/supervisor T=main | app.c app_StopComplete() 4753 | app 'tracker' has stopped.