Issue when using QoS1 for sending data through MQTT

[Adeel]

Hi Dev Team,

I am enhancing my Thingy91 application using the mqtt_simple sample and NCS v1.5.0. I am basically connecting to the MQTT broker, sending data and then disconnecting MQTT broker.

I am facing a peculiar issue when sending my data through MQTT. When I send my data through QoS0, the data is sent perfectly without any hassles.

But when I change my QoS to QoS1 and send the data, the code hangs in between sending the data. 

I can attach the code as well as the log file for you to check it out.

Log when code runs with QoS0 : 

Fullscreen Perfectly runnning QoS0.txt Download

2021-04-12T14:06:05.069Z INFO Application data folder: C:\Users\adeel\AppData\Roaming\nrfconnect\pc-nrfconnect-linkmonitor
2021-04-12T14:06:05.091Z VERBOSE Could not fetch serial number for serial port at COM3
2021-04-12T14:06:05.092Z VERBOSE Could not fetch serial number for serial port at COM1
2021-04-12T14:06:26.431Z INFO Modem port is opened
2021-04-12T14:06:26.437Z DEBUG modem >> AT+CFUN?
2021-04-12T14:06:26.445Z DEBUG modem << +CFUN: 1
2021-04-12T14:06:26.447Z DEBUG modem << OK
2021-04-12T14:06:26.482Z DEBUG modem >> AT+CGSN=1
2021-04-12T14:06:26.491Z DEBUG modem << +CGSN: "352656101119801"
2021-04-12T14:06:26.492Z DEBUG modem << OK
2021-04-12T14:06:26.495Z DEBUG modem >> AT+CGMI
2021-04-12T14:06:26.504Z DEBUG modem << Nordic Semiconductor ASA
2021-04-12T14:06:26.505Z DEBUG modem << OK
2021-04-12T14:06:26.509Z DEBUG modem >> AT+CGMM
2021-04-12T14:06:26.516Z DEBUG modem << nRF9160-SICA
2021-04-12T14:06:26.518Z DEBUG modem << OK
2021-04-12T14:06:26.520Z DEBUG modem >> AT+CGMR
2021-04-12T14:06:26.529Z DEBUG modem << mfw_nrf9160_1.2.2-FOTA-TEST
2021-04-12T14:06:26.530Z DEBUG modem << OK
2021-04-12T14:06:26.532Z INFO Nordic Semiconductor ASA nRF9160-SICA [mfw_nrf9160_1.2.2-FOTA-TEST] SerNr: 352656101119801
2021-04-12T14:06:26.535Z DEBUG modem >> AT+CEMODE?
2021-04-12T14:06:26.543Z DEBUG modem << +CEMODE: 2
2021-04-12T14:06:26.545Z DEBUG modem << OK
2021-04-12T14:06:26.555Z DEBUG modem >> AT%XCBAND=?
2021-04-12T14:06:26.567Z DEBUG modem << %XCBAND: (1,2,3,4,5,8,12,13,18,19,20,25,26,28,66)
2021-04-12T14:06:26.569Z DEBUG modem << OK
2021-04-12T14:06:26.575Z DEBUG modem >> AT+CMEE?
2021-04-12T14:06:26.583Z DEBUG modem << +CMEE: 0
2021-04-12T14:06:26.585Z DEBUG modem << OK
2021-04-12T14:06:26.587Z DEBUG modem >> AT+CMEE=1
2021-04-12T14:06:26.593Z DEBUG modem << OK
2021-04-12T14:06:26.595Z DEBUG modem >> AT+CNEC?
2021-04-12T14:06:26.603Z DEBUG modem << +CNEC: 0
2021-04-12T14:06:26.604Z DEBUG modem << OK
2021-04-12T14:06:26.606Z DEBUG modem >> AT+CNEC=24
2021-04-12T14:06:26.611Z DEBUG modem << OK
2021-04-12T14:06:26.616Z DEBUG modem >> AT+CGEREP?
2021-04-12T14:06:26.623Z DEBUG modem << +CGEREP: 0,0
2021-04-12T14:06:26.626Z DEBUG modem << OK
2021-04-12T14:06:26.629Z DEBUG modem >> AT+CGDCONT?
2021-04-12T14:06:26.636Z DEBUG modem << OK
2021-04-12T14:06:26.639Z DEBUG modem >> AT+CGACT?
2021-04-12T14:06:26.645Z DEBUG modem << OK
2021-04-12T14:06:26.649Z DEBUG modem >> AT+CGEREP=1
2021-04-12T14:06:26.655Z DEBUG modem << OK
2021-04-12T14:06:26.657Z DEBUG modem >> AT+CIND=1,1,1
2021-04-12T14:06:26.666Z DEBUG modem << OK
2021-04-12T14:06:26.668Z DEBUG modem >> AT+CEREG=5
2021-04-12T14:06:26.676Z DEBUG modem << OK
2021-04-12T14:06:26.680Z DEBUG modem >> AT+CEREG?
2021-04-12T14:06:26.691Z DEBUG modem << +CEREG: 5,4,"FFFE","FFFFFFFF",7,0,0,"00000000","00000000"
2021-04-12T14:06:26.693Z DEBUG modem << OK
2021-04-12T14:06:26.702Z DEBUG modem >> AT%CESQ=1
2021-04-12T14:06:26.707Z DEBUG modem << OK
2021-04-12T14:06:26.711Z DEBUG modem >> AT+CESQ
2021-04-12T14:06:26.720Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-04-12T14:06:26.722Z DEBUG modem << OK
2021-04-12T14:06:26.725Z DEBUG modem >> AT%XSIM=1
2021-04-12T14:06:26.733Z DEBUG modem << OK
2021-04-12T14:06:26.735Z DEBUG modem >> AT%XSIM?
2021-04-12T14:06:26.741Z DEBUG modem << %XSIM: 0
2021-04-12T14:06:26.742Z DEBUG modem << OK
2021-04-12T14:06:27.271Z DEBUG modem << [00:00:00.216,552] [0m<inf> at_host: UART check failed: 12. Dropping buffer and retrying.[0m
2021-04-12T14:06:27.386Z DEBUG modem << %XSIM: 1
2021-04-12T14:06:27.394Z DEBUG modem >> AT+CPIN?
2021-04-12T14:06:27.401Z DEBUG modem << +CPIN: READY
2021-04-12T14:06:27.403Z DEBUG modem << OK
2021-04-12T14:06:27.406Z DEBUG modem >> AT+CPINR="SIM PIN"
2021-04-12T14:06:27.421Z DEBUG modem << +CPINR: "SIM PIN",3
2021-04-12T14:06:27.422Z DEBUG modem << OK
2021-04-12T14:06:27.426Z DEBUG modem >> AT+CIMI
2021-04-12T14:06:27.434Z DEBUG modem << 901405101086994
2021-04-12T14:06:27.436Z DEBUG modem << OK
2021-04-12T14:06:27.436Z INFO IMSIdentity: 901405101086994
2021-04-12T14:06:27.637Z DEBUG modem << %CESQ: 39,1,19,2
2021-04-12T14:06:27.642Z DEBUG modem << +CEREG: 2,"5226","029E6004",7,0,0,"11100000","11100000"
2021-04-12T14:06:27.685Z DEBUG modem << +CSCON: 1
2021-04-12T14:06:27.885Z DEBUG modem << %CESQ: 41,2,24,3
2021-04-12T14:06:28.598Z DEBUG modem << +CGEV: ME PDN ACT 0,0
2021-04-12T14:06:28.603Z DEBUG modem << +CNEC_ESM: 50,0
2021-04-12T14:06:28.609Z DEBUG modem >> AT+CGDCONT?
2021-04-12T14:06:28.611Z DEBUG modem << +CEREG: 5,"5226","029E6004",7,,,"00000001","00111000"
2021-04-12T14:06:28.612Z DEBUG modem << LTE Link Connected!
2021-04-12T14:06:28.613Z DEBUG modem << +CIND: "service",1
2021-04-12T14:06:28.615Z DEBUG modem << +CIND: "roam",1
2021-04-12T14:06:28.617Z DEBUG modem << Busy-wait 2 s
2021-04-12T14:06:30.651Z DEBUG modem << [00:00:02.551,269] [0m<dbg> date_time.date_time_update_async: No handler re+CGDCONT: 0,"IP","iot.1nce.net","10.205.85.10",0,0
2021-04-12T14:06:30.653Z DEBUG modem << OK
2021-04-12T14:06:30.654Z DEBUG modem << gistered[0m
2021-04-12T14:06:30.654Z DEBUG modem << [00:00:04.562,286] [0m<dbg> date_time.new_date_time_get: Updating date time UTC...[0m
2021-04-12T14:06:30.654Z DEBUG modem << [00:00:04.562,286] [0m<dbg> date_time.current_time_check: Date time never set[0m
2021-04-12T14:06:30.659Z DEBUG modem >> AT+CGACT?
2021-04-12T14:06:30.660Z DEBUG modem << [00:00:04.562,286] [0m<dbg> date_time.new_date_time_get: Current time not valid[0m
2021-04-12T14:06:30.661Z DEBUG modem << [00:00:04.562,286] [0m<dbg> date_time.new_date_time_get: Fallback on NTP server[0m
2021-04-12T14:06:30.675Z DEBUG modem << +CGACT: 0,1
2021-04-12T14:06:30.677Z DEBUG modem << OK
2021-04-12T14:06:31.979Z DEBUG modem << [00:00:04.915,649] [0m<dbg> date_time.time_NTP_server_get: Got time response from NTP server ntp.uio.no[0m
2021-04-12T14:06:31.980Z DEBUG modem << [00:00:04.915,679] [0m<dbg> date_time.new_date_time_get: Time from NTP server obtained[0m
2021-04-12T14:06:40.654Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:06:40.656Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:06:40.658Z DEBUG modem << Getting latest time...
2021-04-12T14:06:40.659Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:06:40.669Z DEBUG modem << Zephyr Readout T: 24.300000; P: 96.131000; H: 27.490000
2021-04-12T14:06:40.671Z DEBUG modem << Our Readout T: 24.300; P: 96.131; H: 27.490
2021-04-12T14:06:40.673Z DEBUG modem << Current sensor values:
2021-04-12T14:06:40.674Z DEBUG modem << TimerVal : 2021-04-12 14:06:40
2021-04-12T14:06:40.676Z DEBUG modem << Temperature : 24.300
2021-04-12T14:06:40.679Z DEBUG modem << Pressure : 96.131
2021-04-12T14:06:40.682Z DEBUG modem << Humidity : 27.490
2021-04-12T14:06:40.687Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:06:40.689Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:06:40.690Z DEBUG modem << Length of message queue : 1
2021-04-12T14:06:47.804Z DEBUG modem << +CSCON: 0
2021-04-12T14:06:49.830Z DEBUG modem << %CESQ: 255,0,255,0
2021-04-12T14:06:50.652Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:06:50.653Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:06:50.654Z DEBUG modem << Getting latest time...
2021-04-12T14:06:50.655Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:06:50.656Z DEBUG modem << Zephyr Readout T: 24.360000; P: 96.133000; H: 27.476000
2021-04-12T14:06:50.656Z DEBUG modem << Our Readout T: 24.360; P: 96.133; H: 27.476
2021-04-12T14:06:50.657Z DEBUG modem << Current sensor values:
2021-04-12T14:06:50.657Z DEBUG modem << TimerVal : 2021-04-12 14:06:50
2021-04-12T14:06:50.658Z DEBUG modem << Temperature : 24.360
2021-04-12T14:06:50.658Z DEBUG modem << Pressure : 96.133
2021-04-12T14:06:50.659Z DEBUG modem << Humidity : 27.476
2021-04-12T14:06:50.659Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:06:50.660Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:06:50.660Z DEBUG modem << Length of message queue : 2
2021-04-12T14:07:00.652Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:07:00.654Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:07:00.655Z DEBUG modem << Getting latest time...
2021-04-12T14:07:00.656Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:07:00.659Z DEBUG modem << Zephyr Readout T: 24.380000; P: 96.131000; H: 27.423000
2021-04-12T14:07:00.661Z DEBUG modem << Our Readout T: 24.380; P: 96.131; H: 27.423
2021-04-12T14:07:00.662Z DEBUG modem << Current sensor values:
2021-04-12T14:07:00.663Z DEBUG modem << TimerVal : 2021-04-12 14:07:00
2021-04-12T14:07:00.664Z DEBUG modem << Temperature : 24.380
2021-04-12T14:07:00.665Z DEBUG modem << Pressure : 96.131
2021-04-12T14:07:00.666Z DEBUG modem << Humidity : 27.423
2021-04-12T14:07:00.667Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:07:00.668Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:07:00.669Z DEBUG modem << Length of message queue : 3
2021-04-12T14:07:10.652Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:07:10.653Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:07:10.654Z DEBUG modem << Getting latest time...
2021-04-12T14:07:10.655Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:07:10.656Z DEBUG modem << Zephyr Readout T: 24.390000; P: 96.133000; H: 27.381000
2021-04-12T14:07:10.657Z DEBUG modem << Our Readout T: 24.390; P: 96.133; H: 27.381
2021-04-12T14:07:10.658Z DEBUG modem << Current sensor values:
2021-04-12T14:07:10.658Z DEBUG modem << TimerVal : 2021-04-12 14:07:10
2021-04-12T14:07:10.659Z DEBUG modem << Temperature : 24.390
2021-04-12T14:07:10.659Z DEBUG modem << Pressure : 96.133
2021-04-12T14:07:10.660Z DEBUG modem << Humidity : 27.381
2021-04-12T14:07:10.660Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:07:10.661Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:07:10.662Z DEBUG modem << Length of message queue : 4
2021-04-12T14:07:20.651Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:07:20.653Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:07:20.653Z DEBUG modem << Getting latest time...
2021-04-12T14:07:20.654Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:07:20.655Z DEBUG modem << Zephyr Readout T: 24.370000; P: 96.131000; H: 27.379000
2021-04-12T14:07:20.656Z DEBUG modem << Our Readout T: 24.370; P: 96.131; H: 27.379
2021-04-12T14:07:20.657Z DEBUG modem << Current sensor values:
2021-04-12T14:07:20.657Z DEBUG modem << TimerVal : 2021-04-12 14:07:20
2021-04-12T14:07:20.658Z DEBUG modem << Temperature : 24.370
2021-04-12T14:07:20.659Z DEBUG modem << Pressure : 96.131
2021-04-12T14:07:20.659Z DEBUG modem << Humidity : 27.379
2021-04-12T14:07:20.660Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:07:20.660Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:07:20.661Z DEBUG modem << Length of message queue : 5
2021-04-12T14:07:30.650Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:07:30.656Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:07:30.657Z DEBUG modem << Getting latest time...
2021-04-12T14:07:30.658Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:07:30.658Z DEBUG modem << Zephyr Readout T: 24.350000; P: 96.131000; H: 27.371000
2021-04-12T14:07:30.660Z DEBUG modem << Our Readout T: 24.350; P: 96.131; H: 27.371
2021-04-12T14:07:30.660Z DEBUG modem << Current sensor values:
2021-04-12T14:07:30.661Z DEBUG modem << TimerVal : 2021-04-12 14:07:30
2021-04-12T14:07:30.662Z DEBUG modem << Temperature : 24.350
2021-04-12T14:07:30.662Z DEBUG modem << Pressure : 96.131
2021-04-12T14:07:30.663Z DEBUG modem << Humidity : 27.371
2021-04-12T14:07:30.664Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:07:30.664Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:07:30.665Z DEBUG modem << Length of message queue : 6
2021-04-12T14:07:32.920Z DEBUG modem << %CESQ: 30,1,0,0
2021-04-12T14:07:32.924Z DEBUG modem << +CEREG: 5,"5226","029E6002",7,,,"00000001","00111000"
2021-04-12T14:07:32.930Z DEBUG modem >> AT+COPS=3,2
2021-04-12T14:07:32.935Z DEBUG modem << OK
2021-04-12T14:07:32.942Z DEBUG modem >> AT+COPS?
2021-04-12T14:07:32.951Z DEBUG modem << +COPS: 0,2,"26201",7
2021-04-12T14:07:32.953Z DEBUG modem << OK
2021-04-12T14:07:32.964Z DEBUG modem >> AT%XCBAND
2021-04-12T14:07:32.974Z DEBUG modem << %XCBAND: 3
2021-04-12T14:07:32.975Z DEBUG modem << OK
2021-04-12T14:07:32.978Z DEBUG modem >> AT+CGDCONT?
2021-04-12T14:07:32.990Z DEBUG modem << +CGDCONT: 0,"IP","iot.1nce.net","10.205.85.10",0,0
2021-04-12T14:07:32.991Z DEBUG modem << OK
2021-04-12T14:07:32.994Z DEBUG modem >> AT+CGACT?
2021-04-12T14:07:33.000Z DEBUG modem << +CGACT: 0,1
2021-04-12T14:07:33.001Z DEBUG modem << OK
2021-04-12T14:07:33.618Z DEBUG modem << %CESQ: 32,1,5,0
2021-04-12T14:07:33.630Z DEBUG modem << +CSCON: 1
2021-04-12T14:07:33.845Z DEBUG modem << IPv4 Address found 3.121.128.112
2021-04-12T14:07:34.198Z DEBUG modem << [mqtt_evt_handler:285] MQTT client connected!
2021-04-12T14:07:34.205Z DEBUG modem << Subscribing to: my/subscribe/topic len 18
2021-04-12T14:07:34.206Z DEBUG modem << After peeking, #messages has not changed: 6
2021-04-12T14:07:34.254Z DEBUG modem << Publishing: {
2021-04-12T14:07:34.257Z DEBUG modem << "Time":"2021-04-12 14:06:40",
2021-04-12T14:07:34.277Z DEBUG modem << "value":96.131
2021-04-12T14:07:34.279Z DEBUG modem << }
2021-04-12T14:07:34.282Z DEBUG modem << to topic: check/pressure len: 14
2021-04-12T14:07:34.309Z DEBUG modem << Publishing: {
2021-04-12T14:07:34.311Z DEBUG modem << "Time":"2021-04-12 14:06:40",
2021-04-12T14:07:34.314Z DEBUG modem << "value":27.49
2021-04-12T14:07:34.317Z DEBUG modem << }
2021-04-12T14:07:34.318Z DEBUG modem << to topic: check/humidity len: 14
2021-04-12T14:07:34.368Z DEBUG modem << Publishing: {
2021-04-12T14:07:34.373Z DEBUG modem << "Time":"2021-04-12 14:06:40",
2021-04-12T14:07:34.377Z DEBUG modem << "value":24.3
2021-04-12T14:07:34.382Z DEBUG modem << }
2021-04-12T14:07:34.385Z DEBUG modem << to topic: check/temp len: 10
2021-04-12T14:07:34.389Z DEBUG modem << After getting, #messages has changed: 5
2021-04-12T14:07:34.471Z DEBUG modem << After peeking, #messages has not changed: 5
2021-04-12T14:07:34.526Z DEBUG modem << Publishing: {
2021-04-12T14:07:34.527Z DEBUG modem << "Time":"2021-04-12 14:06:50",
2021-04-12T14:07:34.528Z DEBUG modem << "value":96.133
2021-04-12T14:07:34.529Z DEBUG modem << }
2021-04-12T14:07:34.529Z DEBUG modem << to topic: check/pressure len: 14
2021-04-12T14:07:34.583Z DEBUG modem << Publishing: {
2021-04-12T14:07:34.584Z DEBUG modem << "Time":"2021-04-12 14:06:50",
2021-04-12T14:07:34.591Z DEBUG modem << "value":27.476
2021-04-12T14:07:34.592Z DEBUG modem << }
2021-04-12T14:07:34.594Z DEBUG modem << to topic: check/humidity len: 14
2021-04-12T14:07:34.641Z DEBUG modem << Publishing: {
2021-04-12T14:07:34.642Z DEBUG modem << "Time":"2021-04-12 14:06:50",
2021-04-12T14:07:34.643Z DEBUG modem << "value":24.36
2021-04-12T14:07:34.653Z DEBUG modem << }
2021-04-12T14:07:34.654Z DEBUG modem << to topic: check/temp len: 10
2021-04-12T14:07:34.655Z DEBUG modem << After getting, #messages has changed: 4
2021-04-12T14:07:34.745Z DEBUG modem << After peeking, #messages has not changed: 4
2021-04-12T14:07:34.800Z DEBUG modem << Publishing: {
2021-04-12T14:07:34.801Z DEBUG modem << "Time":"2021-04-12 14:07:00",
2021-04-12T14:07:34.813Z DEBUG modem << "value":96.131
2021-04-12T14:07:34.815Z DEBUG modem << }
2021-04-12T14:07:34.817Z DEBUG modem << to topic: check/pressure len: 14
2021-04-12T14:07:34.856Z DEBUG modem << Publishing: {
2021-04-12T14:07:34.857Z DEBUG modem << "Time":"2021-04-12 14:07:00",
2021-04-12T14:07:34.865Z DEBUG modem << "value":27.423
2021-04-12T14:07:34.866Z DEBUG modem << }
2021-04-12T14:07:34.867Z DEBUG modem << to topic: check/humidity len: 14
2021-04-12T14:07:34.915Z DEBUG modem << Publishing: {
2021-04-12T14:07:34.916Z DEBUG modem << "Time":"2021-04-12 14:07:00",
2021-04-12T14:07:34.917Z DEBUG modem << "value":24.38
2021-04-12T14:07:34.927Z DEBUG modem << }
2021-04-12T14:07:34.929Z DEBUG modem << to topic: check/temp len: 10
2021-04-12T14:07:34.930Z DEBUG modem << After getting, #messages has changed: 3
2021-04-12T14:07:35.018Z DEBUG modem << After peeking, #messages has not changed: 3
2021-04-12T14:07:35.074Z DEBUG modem << Publishing: {
2021-04-12T14:07:35.081Z DEBUG modem << "Time":"2021-04-12 14:07:10",
2021-04-12T14:07:35.085Z DEBUG modem << "value":96.133
2021-04-12T14:07:35.089Z DEBUG modem << }
2021-04-12T14:07:35.091Z DEBUG modem << to topic: check/pressure len: 14
2021-04-12T14:07:35.129Z DEBUG modem << Publishing: {
2021-04-12T14:07:35.131Z DEBUG modem << "Time":"2021-04-12 14:07:10",
2021-04-12T14:07:35.132Z DEBUG modem << "value":27.381
2021-04-12T14:07:35.133Z DEBUG modem << }
2021-04-12T14:07:35.134Z DEBUG modem << to topic: check/humidity len: 14
2021-04-12T14:07:35.189Z DEBUG modem << Publishing: {
2021-04-12T14:07:35.190Z DEBUG modem << "Time":"2021-04-12 14:07:10",
2021-04-12T14:07:35.191Z DEBUG modem << "value":24.39
2021-04-12T14:07:35.193Z DEBUG modem << }
2021-04-12T14:07:35.194Z DEBUG modem << to topic: check/temp len: 10
2021-04-12T14:07:35.195Z DEBUG modem << After getting, #messages has changed: 2
2021-04-12T14:07:35.292Z DEBUG modem << After peeking, #messages has not changed: 2
2021-04-12T14:07:35.348Z DEBUG modem << Publishing: {
2021-04-12T14:07:35.349Z DEBUG modem << "Time":"2021-04-12 14:07:20",
2021-04-12T14:07:35.352Z DEBUG modem << "value":96.131
2021-04-12T14:07:35.353Z DEBUG modem << }
2021-04-12T14:07:35.355Z DEBUG modem << to topic: check/pressure len: 14
2021-04-12T14:07:35.403Z DEBUG modem << Publishing: {
2021-04-12T14:07:35.405Z DEBUG modem << "Time":"2021-04-12 14:07:20",
2021-04-12T14:07:35.414Z DEBUG modem << "value":27.379
2021-04-12T14:07:35.416Z DEBUG modem << }
2021-04-12T14:07:35.416Z DEBUG modem << to topic: check/humidity len: 14
2021-04-12T14:07:35.462Z DEBUG modem << Publishing: {
2021-04-12T14:07:35.464Z DEBUG modem << "Time":"2021-04-12 14:07:20",
2021-04-12T14:07:35.464Z DEBUG modem << "value":24.37
2021-04-12T14:07:35.465Z DEBUG modem << }
2021-04-12T14:07:35.466Z DEBUG modem << to topic: check/temp len: 10
2021-04-12T14:07:35.466Z DEBUG modem << After getting, #messages has changed: 1
2021-04-12T14:07:35.565Z DEBUG modem << After peeking, #messages has not changed: 1
2021-04-12T14:07:35.621Z DEBUG modem << Publishing: {
2021-04-12T14:07:35.622Z DEBUG modem << "Time":"2021-04-12 14:07:30",
2021-04-12T14:07:35.631Z DEBUG modem << "value":96.131
2021-04-12T14:07:35.632Z DEBUG modem << }
2021-04-12T14:07:35.632Z DEBUG modem << to topic: check/pressure len: 14
2021-04-12T14:07:35.677Z DEBUG modem << Publishing: {
2021-04-12T14:07:35.678Z DEBUG modem << "Time":"2021-04-12 14:07:30",
2021-04-12T14:07:35.680Z DEBUG modem << "value":27.371
2021-04-12T14:07:35.681Z DEBUG modem << }
2021-04-12T14:07:35.682Z DEBUG modem << to topic: check/humidity len: 14
2021-04-12T14:07:35.736Z DEBUG modem << Publishing: {
2021-04-12T14:07:35.737Z DEBUG modem << "Time":"2021-04-12 14:07:30",
2021-04-12T14:07:35.738Z DEBUG modem << "value":24.35
2021-04-12T14:07:35.749Z DEBUG modem << }
2021-04-12T14:07:35.750Z DEBUG modem << to topic: check/temp len: 10
2021-04-12T14:07:35.751Z DEBUG modem << After getting, #messages has changed: 0
2021-04-12T14:07:35.848Z DEBUG modem << Job done 
2021-04-12T14:07:35.849Z DEBUG modem << Disconnecting MQTT client...
2021-04-12T14:07:35.859Z DEBUG modem << [mqtt_evt_handler:296] MQTT client disconnected 0
2021-04-12T14:07:35.860Z DEBUG modem << ERROR: mqtt_live -128
2021-04-12T14:07:35.861Z DEBUG modem << ERROR: mqtt_input -13
2021-04-12T14:07:38.073Z DEBUG modem << %CESQ: 31,1,0,0
2021-04-12T14:07:39.993Z DEBUG modem << %CESQ: 32,1,5,0
2021-04-12T14:07:40.653Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:07:40.658Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:07:40.662Z DEBUG modem << Getting latest time...
2021-04-12T14:07:40.664Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:07:40.667Z DEBUG modem << Zephyr Readout T: 24.330000; P: 96.129000; H: 27.385000
2021-04-12T14:07:40.669Z DEBUG modem << Our Readout T: 24.330; P: 96.129; H: 27.385
2021-04-12T14:07:40.672Z DEBUG modem << Current sensor values:
2021-04-12T14:07:40.677Z DEBUG modem << TimerVal : 2021-04-12 14:07:40
2021-04-12T14:07:40.681Z DEBUG modem << Temperature : 24.330
2021-04-12T14:07:40.685Z DEBUG modem << Pressure : 96.129
2021-04-12T14:07:40.688Z DEBUG modem << Humidity : 27.385
2021-04-12T14:07:40.710Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:07:40.712Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:07:40.716Z DEBUG modem << Length of message queue : 1

Log when code runs with QoS1 : 

Fullscreen Stuck code QoS1.txt Download

2021-04-12T14:03:19.668Z INFO Application data folder: C:\Users\adeel\AppData\Roaming\nrfconnect\pc-nrfconnect-linkmonitor
2021-04-12T14:03:19.731Z DEBUG App pc-nrfconnect-linkmonitor v1.1.10 official
2021-04-12T14:03:19.731Z DEBUG App path: C:\Users\adeel\.nrfconnect-apps\node_modules\pc-nrfconnect-linkmonitor
2021-04-12T14:03:19.731Z DEBUG nRFConnect 3.6.1 is supported by the app (^3.6.0)
2021-04-12T14:03:19.731Z DEBUG nRFConnect path: C:\Users\adeel\AppData\Local\Programs\nrfconnect\resources\app.asar
2021-04-12T14:03:19.731Z DEBUG HomeDir: C:\Users\adeel
2021-04-12T14:03:19.731Z DEBUG TmpDir: C:\Users\adeel\AppData\Local\Temp
2021-04-12T14:03:19.737Z VERBOSE Could not fetch serial number for serial port at COM3
2021-04-12T14:03:19.738Z VERBOSE Could not fetch serial number for serial port at COM1
2021-04-12T14:03:41.309Z INFO Modem port is opened
2021-04-12T14:03:41.316Z DEBUG modem >> AT+CFUN?
2021-04-12T14:03:41.345Z DEBUG modem << +CFUN: 1
2021-04-12T14:03:41.347Z DEBUG modem << OK
2021-04-12T14:03:41.361Z DEBUG modem >> AT+CGSN=1
2021-04-12T14:03:41.370Z DEBUG modem << +CGSN: "352656101119801"
2021-04-12T14:03:41.371Z DEBUG modem << OK
2021-04-12T14:03:41.377Z DEBUG modem >> AT+CGMI
2021-04-12T14:03:41.385Z DEBUG modem << Nordic Semiconductor ASA
2021-04-12T14:03:41.386Z DEBUG modem << OK
2021-04-12T14:03:41.390Z DEBUG modem >> AT+CGMM
2021-04-12T14:03:41.397Z DEBUG modem << nRF9160-SICA
2021-04-12T14:03:41.398Z DEBUG modem << OK
2021-04-12T14:03:41.401Z DEBUG modem >> AT+CGMR
2021-04-12T14:03:41.410Z DEBUG modem << mfw_nrf9160_1.2.2-FOTA-TEST
2021-04-12T14:03:41.412Z DEBUG modem << OK
2021-04-12T14:03:41.413Z INFO Nordic Semiconductor ASA nRF9160-SICA [mfw_nrf9160_1.2.2-FOTA-TEST] SerNr: 352656101119801
2021-04-12T14:03:41.414Z DEBUG modem >> AT+CEMODE?
2021-04-12T14:03:41.421Z DEBUG modem << +CEMODE: 2
2021-04-12T14:03:41.423Z DEBUG modem << OK
2021-04-12T14:03:41.434Z DEBUG modem >> AT%XCBAND=?
2021-04-12T14:03:41.445Z DEBUG modem << %XCBAND: (1,2,3,4,5,8,12,13,18,19,20,25,26,28,66)
2021-04-12T14:03:41.447Z DEBUG modem << OK
2021-04-12T14:03:41.453Z DEBUG modem >> AT+CMEE?
2021-04-12T14:03:41.461Z DEBUG modem << +CMEE: 0
2021-04-12T14:03:41.462Z DEBUG modem << OK
2021-04-12T14:03:41.465Z DEBUG modem >> AT+CMEE=1
2021-04-12T14:03:41.471Z DEBUG modem << OK
2021-04-12T14:03:41.477Z DEBUG modem >> AT+CNEC?
2021-04-12T14:03:41.483Z DEBUG modem << +CNEC: 0
2021-04-12T14:03:41.485Z DEBUG modem << OK
2021-04-12T14:03:41.487Z DEBUG modem >> AT+CNEC=24
2021-04-12T14:03:41.494Z DEBUG modem << OK
2021-04-12T14:03:41.497Z DEBUG modem >> AT+CGEREP?
2021-04-12T14:03:41.504Z DEBUG modem << +CGEREP: 0,0
2021-04-12T14:03:41.509Z DEBUG modem << OK
2021-04-12T14:03:41.514Z DEBUG modem >> AT+CGDCONT?
2021-04-12T14:03:41.520Z DEBUG modem << OK
2021-04-12T14:03:41.522Z DEBUG modem >> AT+CGACT?
2021-04-12T14:03:41.528Z DEBUG modem << OK
2021-04-12T14:03:41.530Z DEBUG modem >> AT+CGEREP=1
2021-04-12T14:03:41.536Z DEBUG modem << OK
2021-04-12T14:03:41.539Z DEBUG modem >> AT+CIND=1,1,1
2021-04-12T14:03:41.545Z DEBUG modem << OK
2021-04-12T14:03:41.548Z DEBUG modem >> AT+CEREG=5
2021-04-12T14:03:41.556Z DEBUG modem << OK
2021-04-12T14:03:41.562Z DEBUG modem >> AT+CEREG?
2021-04-12T14:03:41.573Z DEBUG modem << +CEREG: 5,4,"FFFE","FFFFFFFF",7,0,0,"00000000","00000000"
2021-04-12T14:03:41.575Z DEBUG modem << OK
2021-04-12T14:03:41.584Z DEBUG modem >> AT%CESQ=1
2021-04-12T14:03:41.593Z DEBUG modem << OK
2021-04-12T14:03:41.598Z DEBUG modem >> AT+CESQ
2021-04-12T14:03:41.607Z DEBUG modem << +CESQ: 99,99,255,255,255,255
2021-04-12T14:03:41.608Z DEBUG modem << OK
2021-04-12T14:03:41.615Z DEBUG modem >> AT%XSIM=1
2021-04-12T14:03:41.620Z DEBUG modem << OK
2021-04-12T14:03:41.623Z DEBUG modem >> AT%XSIM?
2021-04-12T14:03:41.629Z DEBUG modem << %XSIM: 0
2021-04-12T14:03:41.631Z DEBUG modem << OK
2021-04-12T14:03:41.990Z DEBUG modem << [00:00:00.216,583] [0m<inf> at_host: UART check failed: 12. Dropping buffer and retrying.[0m
2021-04-12T14:03:42.104Z DEBUG modem << %XSIM: 1
2021-04-12T14:03:42.113Z DEBUG modem >> AT+CPIN?
2021-04-12T14:03:42.120Z DEBUG modem << +CPIN: READY
2021-04-12T14:03:42.121Z DEBUG modem << OK
2021-04-12T14:03:42.128Z DEBUG modem >> AT+CPINR="SIM PIN"
2021-04-12T14:03:42.157Z DEBUG modem << +CPINR: "SIM PIN",3
2021-04-12T14:03:42.159Z DEBUG modem << OK
2021-04-12T14:03:42.165Z DEBUG modem >> AT+CIMI
2021-04-12T14:03:42.172Z DEBUG modem << 901405101086994
2021-04-12T14:03:42.173Z DEBUG modem << OK
2021-04-12T14:03:42.174Z INFO IMSIdentity: 901405101086994
2021-04-12T14:03:42.518Z DEBUG modem << %CESQ: 39,1,19,2
2021-04-12T14:03:42.522Z DEBUG modem << +CEREG: 2,"5226","029E6004",7,0,0,"11100000","11100000"
2021-04-12T14:03:42.566Z DEBUG modem << +CSCON: 1
2021-04-12T14:03:42.966Z DEBUG modem << %CESQ: 40,2,24,3
2021-04-12T14:03:44.118Z DEBUG modem << +CGEV: ME PDN ACT 0,0
2021-04-12T14:03:44.121Z DEBUG modem << +CNEC_ESM: 50,0
2021-04-12T14:03:44.125Z DEBUG modem >> AT+CGDCONT?
2021-04-12T14:03:44.130Z DEBUG modem << +CEREG: 5,"5226","029E6004",7,,,"00000001","00111000"
2021-04-12T14:03:44.131Z DEBUG modem << LTE Link Connected!
2021-04-12T14:03:44.132Z DEBUG modem << +CIND: "service",1
2021-04-12T14:03:44.135Z DEBUG modem << +CIND: "roam",1
2021-04-12T14:03:44.136Z DEBUG modem << Busy-wait 2 s
2021-04-12T14:03:46.171Z DEBUG modem << [00:00:03.351,837] [0m<dbg> date_time.date_time_update_async: No handler r+CGDCONT: 0,"IP","iot.1nce.net","10.205.85.10",0,0
2021-04-12T14:03:46.172Z DEBUG modem << OK
2021-04-12T14:03:46.174Z DEBUG modem << egistered[0m
2021-04-12T14:03:46.175Z DEBUG modem << [00:00:05.362,274] [0m<dbg> date_time.new_date_time_get: Updating date time UTC...[0m
2021-04-12T14:03:46.176Z DEBUG modem << [00:00:05.362,274] [0m<dbg> date_time.current_time_check: Date time never set[0m
2021-04-12T14:03:46.176Z DEBUG modem << [00:00:05.362,274] [0m<dbg> date_time.new_date_time_get: Current time not valid[0m
2021-04-12T14:03:46.187Z DEBUG modem >> AT+CGACT?
2021-04-12T14:03:46.189Z DEBUG modem << [00:00:05.362,274] [0m<dbg> date_time.new_date_time_get: Fallback on NTP server[0m
2021-04-12T14:03:46.202Z DEBUG modem << +CGACT: 0,1
2021-04-12T14:03:46.204Z DEBUG modem << OK
2021-04-12T14:03:47.405Z DEBUG modem << [00:00:05.623,046] [0m<dbg> date_time.time_NTP_server_get: Got time response from NTP server ntp.uio.no[0m
2021-04-12T14:03:47.407Z DEBUG modem << [00:00:05.623,077] [0m<dbg> date_time.new_date_time_get: Time from NTP server obtained[0m
2021-04-12T14:03:56.172Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:03:56.174Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:03:56.174Z DEBUG modem << Getting latest time...
2021-04-12T14:03:56.175Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:03:56.176Z DEBUG modem << Zephyr Readout T: 24.470000; P: 96.131000; H: 27.286000
2021-04-12T14:03:56.177Z DEBUG modem << Our Readout T: 24.470; P: 96.131; H: 27.286
2021-04-12T14:03:56.178Z DEBUG modem << Current sensor values:
2021-04-12T14:03:56.178Z DEBUG modem << TimerVal : 2021-04-12 14:03:55
2021-04-12T14:03:56.179Z DEBUG modem << Temperature : 24.470
2021-04-12T14:03:56.179Z DEBUG modem << Pressure : 96.131
2021-04-12T14:03:56.180Z DEBUG modem << Humidity : 27.286
2021-04-12T14:03:56.180Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:03:56.181Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:03:56.183Z DEBUG modem << Length of message queue : 1
2021-04-12T14:03:57.820Z DEBUG modem << +CSCON: 0
2021-04-12T14:03:59.846Z DEBUG modem << %CESQ: 255,0,255,0
2021-04-12T14:04:06.172Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:04:06.173Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:04:06.173Z DEBUG modem << Getting latest time...
2021-04-12T14:04:06.174Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:04:06.175Z DEBUG modem << Zephyr Readout T: 24.490000; P: 96.133000; H: 27.324000
2021-04-12T14:04:06.176Z DEBUG modem << Our Readout T: 24.490; P: 96.133; H: 27.324
2021-04-12T14:04:06.176Z DEBUG modem << Current sensor values:
2021-04-12T14:04:06.177Z DEBUG modem << TimerVal : 2021-04-12 14:04:05
2021-04-12T14:04:06.178Z DEBUG modem << Temperature : 24.490
2021-04-12T14:04:06.180Z DEBUG modem << Pressure : 96.133
2021-04-12T14:04:06.181Z DEBUG modem << Humidity : 27.324
2021-04-12T14:04:06.182Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:04:06.183Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:04:06.184Z DEBUG modem << Length of message queue : 2
2021-04-12T14:04:16.171Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:04:16.172Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:04:16.173Z DEBUG modem << Getting latest time...
2021-04-12T14:04:16.173Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:04:16.175Z DEBUG modem << Zephyr Readout T: 24.510000; P: 96.135000; H: 27.265000
2021-04-12T14:04:16.175Z DEBUG modem << Our Readout T: 24.510; P: 96.135; H: 27.265
2021-04-12T14:04:16.176Z DEBUG modem << Current sensor values:
2021-04-12T14:04:16.176Z DEBUG modem << TimerVal : 2021-04-12 14:04:15
2021-04-12T14:04:16.177Z DEBUG modem << Temperature : 24.510
2021-04-12T14:04:16.177Z DEBUG modem << Pressure : 96.135
2021-04-12T14:04:16.177Z DEBUG modem << Humidity : 27.265
2021-04-12T14:04:16.178Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:04:16.178Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:04:16.179Z DEBUG modem << Length of message queue : 3
2021-04-12T14:04:26.173Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:04:26.178Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:04:26.182Z DEBUG modem << Getting latest time...
2021-04-12T14:04:26.185Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:04:26.188Z DEBUG modem << Zephyr Readout T: 24.490000; P: 96.131000; H: 27.249000
2021-04-12T14:04:26.192Z DEBUG modem << Our Readout T: 24.490; P: 96.131; H: 27.249
2021-04-12T14:04:26.196Z DEBUG modem << Current sensor values:
2021-04-12T14:04:26.199Z DEBUG modem << TimerVal : 2021-04-12 14:04:25
2021-04-12T14:04:26.212Z DEBUG modem << Temperature : 24.490
2021-04-12T14:04:26.214Z DEBUG modem << Pressure : 96.131
2021-04-12T14:04:26.215Z DEBUG modem << Humidity : 27.249
2021-04-12T14:04:26.218Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:04:26.219Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:04:26.222Z DEBUG modem << Length of message queue : 4
2021-04-12T14:04:36.171Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:04:36.172Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:04:36.173Z DEBUG modem << Getting latest time...
2021-04-12T14:04:36.174Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:04:36.175Z DEBUG modem << Zephyr Readout T: 24.470000; P: 96.129000; H: 27.244000
2021-04-12T14:04:36.175Z DEBUG modem << Our Readout T: 24.470; P: 96.129; H: 27.244
2021-04-12T14:04:36.176Z DEBUG modem << Current sensor values:
2021-04-12T14:04:36.177Z DEBUG modem << TimerVal : 2021-04-12 14:04:35
2021-04-12T14:04:36.178Z DEBUG modem << Temperature : 24.470
2021-04-12T14:04:36.178Z DEBUG modem << Pressure : 96.129
2021-04-12T14:04:36.178Z DEBUG modem << Humidity : 27.244
2021-04-12T14:04:36.179Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:04:36.179Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:04:36.180Z DEBUG modem << Length of message queue : 5
2021-04-12T14:04:46.170Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:04:46.177Z DEBUG modem << my_sensor_work_handler started!
2021-04-12T14:04:46.183Z DEBUG modem << Getting latest time...
2021-04-12T14:04:46.193Z DEBUG modem << Reading out bosch sensor...
2021-04-12T14:04:46.202Z DEBUG modem << Zephyr Readout T: 24.440000; P: 96.131000; H: 27.278000
2021-04-12T14:04:46.208Z DEBUG modem << Our Readout T: 24.440; P: 96.131; H: 27.278
2021-04-12T14:04:46.212Z DEBUG modem << Current sensor values:
2021-04-12T14:04:46.216Z DEBUG modem << TimerVal : 2021-04-12 14:04:45
2021-04-12T14:04:46.218Z DEBUG modem << Temperature : 24.440
2021-04-12T14:04:46.221Z DEBUG modem << Pressure : 96.131
2021-04-12T14:04:46.224Z DEBUG modem << Humidity : 27.278
2021-04-12T14:04:46.227Z DEBUG modem << ----------------------------------------------------------------
2021-04-12T14:04:46.230Z DEBUG modem << my_mqtt_work_handler started!
2021-04-12T14:04:46.232Z DEBUG modem << Length of message queue : 6
2021-04-12T14:04:46.272Z DEBUG modem << %CESQ: 41,2,25,3
2021-04-12T14:04:46.985Z DEBUG modem << +CSCON: 1
2021-04-12T14:04:47.173Z DEBUG modem << IPv4 Address found 3.121.128.112
2021-04-12T14:04:47.363Z DEBUG modem << [mqtt_evt_handler:285] MQTT client connected!
2021-04-12T14:04:47.365Z DEBUG modem << Subscribing to: my/subscribe/topic len 18
2021-04-12T14:04:47.367Z DEBUG modem << After peeking, #messages has not changed: 6
2021-04-12T14:04:47.418Z DEBUG modem << Publishing: {
2021-04-12T14:04:47.422Z DEBUG modem << "Time":"2021-04-12 14:03:55",
2021-04-12T14:04:47.424Z DEBUG modem << "value":96.131
2021-04-12T14:04:47.424Z DEBUG modem << }
2021-04-12T14:04:47.425Z DEBUG modem << to topic: check/pressure len: 14
2021-04-12T14:04:47.473Z DEBUG modem << Publishing: {
2021-04-12T14:04:47.475Z DEBUG modem << "Time":"2021-04-12 14:03:55",
2021-04-12T14:04:47.476Z DEBUG modem << "value":27.286
2021-04-12T14:04:47.476Z DEBUG modem << }
2021-04-12T14:04:47.477Z DEBUG modem << to topic: check/humidity len: 14
2021-04-12T14:04:47.532Z DEBUG modem << Publishing: {
2021-04-12T14:04:47.533Z DEBUG modem << "Time":"2021-04-12 14:03:55",
2021-04-12T14:04:47.535Z DEBUG modem << "value":24.47
2021-04-12T14:04:47.536Z DEBUG modem << }
2021-04-12T14:04:47.537Z DEBUG modem << to topic: check/temp len: 10
2021-04-12T14:04:47.538Z DEBUG modem << After getting, #messages has changed: 5
2021-04-12T14:04:47.636Z DEBUG modem << After peeking, #messages has not changed: 5
2021-04-12T14:04:47.692Z DEBUG modem << Publishing: {
2021-04-12T14:04:47.693Z DEBUG modem << "Time":"2021-04-12 14:04:05",
2021-04-12T14:04:47.694Z DEBUG modem << "value":96.133
2021-04-12T14:04:47.694Z DEBUG modem << }
2021-04-12T14:04:47.695Z DEBUG modem << to topic: check/pressure len: 14
2021-04-12T14:04:47.747Z DEBUG modem << Publishing: {
2021-04-12T14:04:47.749Z DEBUG modem << "Time":"2021-04-12 14:04:05",
2021-04-12T14:04:47.750Z DEBUG modem << "value":27.324
2021-04-12T14:04:47.751Z DEBUG modem << }
2021-04-12T14:04:47.752Z DEBUG modem << to topic: check/humidity len: 14
2021-04-12T14:04:47.805Z DEBUG modem << Publishing: {
2021-04-12T14:04:47.806Z DEBUG modem << "Time":"2021-04-12 14:04:05",
2021-04-12T14:04:47.807Z DEBUG modem << "value":24.49
2021-04-12T14:04:47.808Z DEBUG modem << }
2021-04-12T14:04:47.809Z DEBUG modem << to topic: check/temp len: 10
2021-04-12T14:04:47.810Z DEBUG modem << After getting, #messages has changed: 4
2021-04-12T14:04:47.910Z DEBUG modem << After peeking, #messages has not changed: 4
2021-04-12T14:04:47.965Z DEBUG modem << Publishing: {
2021-04-12T14:04:47.966Z DEBUG modem << "Time":"2021-04-12 14:04:15",
2021-04-12T14:04:47.968Z DEBUG modem << "value":96.135
2021-04-12T14:04:47.969Z DEBUG modem << }
2021-04-12T14:04:47.970Z DEBUG modem << to topic: check/pressure len: 14

The code is attached here : mqtt_simple_test_v1_5_0.rar

Its based on the mqtt_simple sample of NCS v1.5.0.

Could you replicate it at your end to let me know what could be the issue here.

Regards,

Adeel.

[Carl Richard]

Hello, Adeel!

The behavior you are describing is interesting. I will do some testing, but from what I can see in your logs it doesn't hang anywhere. Could you please elaborate on the issue? 

In addition, when using QoS1, you should receive MQTT_EVT_PUBACK for each message, but I can't see any of those. Please make sure that the broker actually receives and responds properly to you MQTT messages. You can try to increase the message buffer as well using CONFIG_MQTT_MESSAGE_BUFFER_SIZE.

Best regards,
Carl Richard

[Adeel]

Hi Carl,

Carl Richard said:

Could you please elaborate on the issue? 

Sure. If you see in the QoS0 log that I posted, the MQTT connects, sends the data and then disconnects. After that , the process of logging the data is started again. This is perfect as it should happen.

But in the QoS1 log, the data sending stops in between. All the data is not sent and the program does nothing after that. It is just stuck as seen in the log. Normally, I hoped that it did the same functionality of sending the data and disconnecting the MQTT and then start logging data again as is happening with QoS0 log. But it gets stuck in the process of data sending.

Carl Richard said:

In addition, when using QoS1, you should receive MQTT_EVT_PUBACK for each message, but I can't see any of those.

Do I receive this from my broker ? I am using broker.hivemq.com (HIVE MQ) as my broker along with the MQTT.fx software. Do I need to do any configurations there ? I have set the QoS in the MQTT.fx to QoS1.

Regards,

Adeel.

[Carl Richard]

Hello again!

Understood. As you may know QoS1 means that the message is required to arrive "at least once" and a transaction is not considered finished before MQTT_EVT_PUBACK is received. The sender retains the message during this time. The issue likely stems from how the application currently releases the message data after it's sent and then proceed with queuing up new messages. 

I suggest making sure that a MQTT_EVT_PUBACK event is received before transmitting the next message. This can be done by taking a semaphore after the message is sent, and giving it when the PUBACK is received. It could be a good idea that messages are sent successfully as well by printing the return code from data_publish.

Best regards,
Carl Richard

[Adeel]

Hi Carl,

Carl Richard said:

The issue likely stems from how the application currently releases the message data after it's sent and then proceed with queuing up new messages. 

You are right. That is the exact reason.

I tried to take a look at the example in this link : https://github.com/crfosse/ncs_projects/blob/779ccbf1a58bb2ecef45f2aa1e2c100698e0f034/cellular/mqtt_work/src/main.c

I implemented the semaphores in the way its done but I noticed that I don't receive the MQTT_EVT_PUBACK at all. Could you let me know what could be the issue with my code. 

I expected that once I change my QoS in data_publish() function to QoS1, I should get the MQTT_EVT_PUCKACK automatically. But I dont get any PUBACK messages for some reason I do not understand. 

[Carl Richard]

Hi!

The reason why you aren't getting the MQTT_EVT_PUBACK messages is that you're only checking incoming MQTT traffic using mqtt_run. You probably can solve this by calling this function each time you have used data_publish, but ideally I would have the this kind of functionality in a separate thread. 

Best regards,
Carl Richard

[Adeel]

Hi Carl,

Yes, the solution you offer works for now. I am able to get the data through QoS1.

I will try to get this functionality in a separate thread. Thanks for the help on this .

Regards,

Adeel.