Hi @ravibhagavandas,
Here’s a bigger section of the log:
{"id":"ID-00009-00037-015-P0N261Z","spd":0.0,"odo":0.0,"vb":0.000,"vg":3.777,"pwr":0.0,"cap":0.0,"cnt":168.0,"lat":51.410678863525391,"lon":5.401926517486572}
[INFO] [MQTT] [core_mqtt_agent_command_functions.c:76] Publishing message to iot/ID-00009-00037-015-P0N261Z.
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[INFO] [MQTT] [core_mqtt.c:1170] Ack packet deserialized with result: MQTTSuccess.
[INFO] [MQTT] [core_mqtt.c:1183] State record updated. New state=MQTTPublishDone.
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1679] Sent PUBLISH packet to topic iot/ID-00009-00037-015-P0N261Z.
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
{"id":"ID-00009-00037-015-P0N261Z","spd":0.0,"odo":0.0,"vb":0.000,"vg":3.782,"pwr":0.0,"cap":0.0,"cnt":169.0,"lat":51.410655975341797,"lon":5.401903152465820}
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[ERROR] [CellularLib] [cellular_pkthandler.c:335] pkt_recv status=1, data sending timed out
[ERROR] [CellularLib] [cellular_r4_api.c:748] Cellular_SocketSend: Data send fail, PktRet: 1
[ERROR] [TlsTransport] [using_mbedtls.c:840] Failed to send data: mbedTLSError= <No-High-Level-Code> : ERROR - Generic error.
[ERROR] [MQTT] [core_mqtt.c:625] Transport send failed. Error code=-1.
[ERROR] [MQTT] [core_mqtt.c:2034] Transport send failed for PINGREQ packet.
[ERROR] [MQTT] [core_mqtt.c:2200] Exiting process loop due to failure: ErrorStatus=MQTTSendFailed
[ERROR] [MQTT] [core_mqtt_agent.c:1022] MQTT operation failed with status MQTTSendFailed
[WARN] [OTA] [ota_os_freertos.c:310] OTA Timer handle NULL for Timerid=0, can't stop.
[INFO] [OTA] [ota.c:1350] OTA Agent is suspended.
[INFO] [OTA] [ota.c:2846] Current State=[Suspended], Event=[Suspend], New state=[Suspended]
[ERROR] [CellularLib] [cellular_pktio.c:722] recvdMsgType is AT_UNDEFINED for Message: OK, cmd NULL
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1835] Suspended OTA agent.
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1836] MQTT Agent disconnecting...
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1363] Disconnecting TLS connection.
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1842] TCP Connection closed...
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1273] Attempting to open TLS socket to broker...
Waiting on reconnect before attempting forced rescan [1/10]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Waiting on reconnect before attempting forced rescan [2/10]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Waiting on reconnect before attempting forced rescan [3/10]
[ERROR] [OTADemo] [OtaOverMqttDemoExample.c:1674] Failed to send PUBLISH packet to broker with error = 3.
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Waiting on reconnect before attempting forced rescan [4/10]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Waiting on reconnect before attempting forced rescan [5/10]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Waiting on reconnect before attempting forced rescan [6/10]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Waiting on reconnect before attempting forced rescan [7/10]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Waiting on reconnect before attempting forced rescan [8/10]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Waiting on reconnect before attempting forced rescan [9/10]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Waiting on reconnect before attempting forced rescan [10/10]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Turning RF off...
Waiting 1s...
[INFO] [CellularLib] [cellular_r4_urc_handler.c:341] _cellular_UrcProcessUupsmr: PSM_MODE_EXIT
#----------------------------------------------------------#
Unsolicited Network Registration Event Detected...
networkRegistrationMode==REGISTRATION_MODE_UNKNOWN
csRegistrationStatus==REGISTRATION_STATUS_NO_REGISTERED_SEARCHING
psRegistrationStatus==REGISTRATION_STATUS_ROAMING_REGISTERED
#----------------------------------------------------------#
#----------------------------------------------------------#
Unsolicited Network Registration Event Detected...
networkRegistrationMode==REGISTRATION_MODE_UNKNOWN
csRegistrationStatus==REGISTRATION_STATUS_NO_REGISTERED_SEARCHING
psRegistrationStatus==REGISTRATION_STATUS_NO_REGISTERED_SEARCHING
#----------------------------------------------------------#
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
Turning RF on...
[INFO] [CellularLib] [cellular_r4_urc_handler.c:341] _cellular_UrcProcessUupsmr: PSM_MODE_EXIT
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
#----------------------------------------------------------#
Unsolicited Network Registration Event Detected...
networkRegistrationMode==REGISTRATION_MODE_UNKNOWN
csRegistrationStatus==REGISTRATION_STATUS_NOT_REGISTERED_SEARCHING
psRegistrationStatus==REGISTRATION_STATUS_NO_REGISTERED_SEARCHING
#----------------------------------------------------------#
#----------------------------------------------------------#
Unsolicited Network Registration Event Detected...
networkRegistrationMode==REGISTRATION_MODE_UNKNOWN
csRegistrationStatus==REGISTRATION_STATUS_NOT_REGISTERED_SEARCHING
psRegistrationStatus==REGISTRATION_STATUS_NOT_REGISTERED_SEARCHING
#----------------------------------------------------------#
Waiting on reconnect before attempting forced rescan [1/30]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
#----------------------------------------------------------#
Unsolicited Network Registration Event Detected...
networkRegistrationMode==REGISTRATION_MODE_UNKNOWN
csRegistrationStatus==REGISTRATION_STATUS_ROAMING_REGISTERED
psRegistrationStatus==REGISTRATION_STATUS_NOT_REGISTERED_SEARCHING
#----------------------------------------------------------#
#----------------------------------------------------------#
Unsolicited Network Registration Event Detected...
networkRegistrationMode==REGISTRATION_MODE_UNKNOWN
csRegistrationStatus==REGISTRATION_STATUS_ROAMING_REGISTERED
psRegistrationStatus==REGISTRATION_STATUS_ROAMING_REGISTERED
#----------------------------------------------------------#
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1281] Waiting for cellular connection before creating the TLS connection...
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1284] Creating a TLS connection to a4gg9xlmdgdfgo34-ats.iot.eu-central-1.amazonaws.com:8883.
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1506] TCP socket connected!
[DEBUG] [OTADemo] [OtaOverMqttDemoExample.c:1386] Creating command queue.
[INFO] [MQTT] [core_mqtt.c:1838] MQTT connection established with the broker.
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1474] Session present: 0
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1521] MQTT connection successful!
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1848] MQTT Agent connected...
[INFO] [OTA] [ota.c:2846] Current State=[RequestingJob], Event=[Resume], New state=[RequestingJob]
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:1853] Resumed OTA agent.
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[INFO] [OTADemo] [OtaOverMqttDemoExample.c:2012] Received: 0 Queued: 0 Processed: 0 Dropped: 0
[ERROR] [MQTT] [freertos_command_pool.c:117] No command structure available.
[ERROR] [OTADemo] [OtaOverMqttDemoExample.c:1609] Failed to SUBSCRIBE to topic with error = 2.
[ERROR] [OTA] [ota_mqtt.c:390] Failed to subscribe to MQTT topic: subscribe returned error: OtaMqttStatus_t=OtaMqttSubscribeFailed, topic=$aws/things/ID-00009-00037-015-P0N261Z/jobs/notify-next
The line between { } is a message that I publish.
The strange thing is that after the disconnect the OTA state is:
[INFO] [OTA] [ota.c:2846] Current State=[Suspended], Event=[Suspend], New state=[Suspended]
Then after the reconnect the log gives:
[INFO] [OTA] [ota.c:2846] Current State=[RequestingJob], Event=[Resume], New state=[RequestingJob]
While in between the disconnect and reconnect there are no other state changes reported, so how did it go from [suspended] to [RequestingJob] without reporting a resume? I also question that log entry, why is the new state always the same as the current state? The code that makes that log entry in ota.c seems ok:
LogInfo( ( "Current State=[%s]"
", Event=[%s]"
", New state=[%s]",
pOtaAgentStateStrings[ otaAgent.state ],
pOtaEventStrings[ pEventMsg->eventId ],
pOtaAgentStateStrings[ otaTransitionTable[ index ].nextState ] ) );
So next to OTA, I do publish in another thread with QoS 1, but I make sure there I only publish when the MQTT Agent is connected.