PublishQueueAsyncRK Hanging

StngBo · March 29, 2022, 9:39am

Hi All,

I am using the PublishQueueAsyncRK library to store publish strings in an SD, then we just let the library send at its convenience. Soon after our device starts up we collect some system data and store the data using the PublishQueueAsyncRK lib. Occasionally after sending new firmware to the device, after reset, the device seems to get stuck when trying to publish the event stored in SD. The logs show that the data was stored in the SD and that the Lib tries to then publish this statement.

0000015589 [app.pubq] TRACE: after writing numEvents=1 fileLength=252
0000015598 [app.pubq] INFO: publishing SysReadings { "f": "0.00", "b": "12.70", "t": "2022-03-29 09:25:17", "s": "10", "Em": "", "sd": "1", "tp": "0.00", "h": "0.00", "sp": "0", "st": "1~

The particle then gets stuck. It continues to breath cyan, but the vitals cannot be called from the console, nor do particle functions work. After 8 mins our hardware watchdog resets the device, after this subsequent reset the device does not get stuck and the previously stored SysReadings gets sent to the cloud successfully once the device has connected.

What’s the best way to troubleshoot this issue?

rickkas7 · March 29, 2022, 9:50am

That’s odd. So you’re not getting a publish canceled, published successfully, publish failed, will retry in message after the publishing message? The only thing that happens between those things is the real Particle.publish().

I’d up the logging level to LOG_LEVEL_TRACE to see what the system is doing during that time.

StngBo · March 29, 2022, 9:59am

Yeah I’m not getting any other messages, when it does happen, this seems to be where the device hangs

0000015598 [app.pubq] INFO: publishing SysReadings { "f": "0.00", "b": "12.70", "t": "2022-03-29 09:25:17", "s": "10", "Em": "", "sd": "1", "tp": "0.00", "h": "0.00", "sp": "0", "st": "1~

I will change Log Level as you advise and I guess I just have to wait for it to happen again.

StngBo · April 4, 2022, 8:35pm

I have done more than 60+ OTA updates on this device since my last post. The issue just happened again. Here is the Logs since restart:

Serial monitor opened successfully:
0000000961 [app.pubq] TRACE: numEvents=0 numSent=0
0000000961 [app.pubq] INFO: all events have been sent, reinitializing
0000000969 [app.pubq] INFO: initialized events file
0000000996 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000000996 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0000000997 [ncp.client] TRACE: Powering modem on, ncpId: 0x42
0000000997 [ncp.client] TRACE: Modem already on
0000000997 [ncp.client] TRACE: Setting UART voltage translator state 1
0000000998 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP
0000001002 [app] INFO: CHECKING EEPROM
0000001003 [app] INFO: sizeof(data)=76
0000001006 [app] INFO: MAGIC BYTES SAME - LOADED EEPROM VALUES
0000001007 [app] INFO: AFTER EEPROM READ
0000001009 [app] INFO: sizeof(data)=76
0000001097 [ncp.client] TRACE: Setting UART voltage translator state 0
0000001197 [ncp.client] TRACE: Setting UART voltage translator state 1
0000001197 [ncp.client] TRACE: Muxer is not currently running
0000001198 [ncp.client] TRACE: Initialized muxer @ 921600 baudrate
0000001199 [mux] INFO: Starting GSM07.10 muxer
0000001199 [mux] INFO: GSM07.10 muxer thread started
0000001201 [ncp.client] TRACE: Resumed muxed session
0000001201 [mux] INFO: Openning mux channel 1
0000001550 [mux] INFO: Closing mux channel 2
0000001602 [ncp.at] TRACE: > AT
0000002604 [ncp.at] TRACE: > AT
0000002734 [ncp.at] TRACE: < OK
0000002735 [ncp.at] TRACE: < +CGEV: ME DEACT "IP","10.162.14.127",1
0000002736 [ncp.at] TRACE: < +CGEV: ME DEACT "IP","0.0.0.0",1
0000003606 [ncp.at] TRACE: > AT
0000003608 [ncp.at] TRACE: < OK
0000003608 [ncp.client] TRACE: NCP ready to accept AT commands
0000003609 [ncp.at] TRACE: > AT
0000003610 [ncp.at] TRACE: < OK
0000003611 [ncp.at] TRACE: > ATI9
0000003624 [ncp.at] TRACE: < 23.60,A01.01
0000003625 [ncp.at] TRACE: < OK
0000003625 [ncp.client] TRACE: App firmware: 101
0000003626 [ncp.at] TRACE: > AT+UGPIOC?
0000003629 [ncp.at] TRACE: < +UGPIOC:
0000003629 [ncp.at] TRACE: < 16,255
0000003630 [ncp.at] TRACE: < 23,255
0000003630 [ncp.at] TRACE: < 24,4
0000003631 [ncp.at] TRACE: < 25,5
0000003631 [ncp.at] TRACE: < 34,12
0000003632 [ncp.at] TRACE: < 35,12
0000003632 [ncp.at] TRACE: < 36,12
0000003632 [ncp.at] TRACE: < 37,12
0000003633 [ncp.at] TRACE: < 42,7
0000003633 [ncp.at] TRACE: < OK
0000003634 [ncp.client] INFO: Using internal SIM card
0000003635 [ncp.at] TRACE: > AT+CPIN?
0000003638 [ncp.at] TRACE: < +CPIN: READY
0000003638 [ncp.at] TRACE: < OK
0000003639 [ncp.at] TRACE: > AT+CCID
0000003656 [ncp.at] TRACE: < +CCID: 89314404000710740227
0000003656 [ncp.at] TRACE: < OK
0000003657 [ncp.at] TRACE: > AT+IFC=2,2
0000003660 [ncp.at] TRACE: < OK
0000003661 [ncp.at] TRACE: > AT
0000003663 [ncp.at] TRACE: < OK
0000003663 [ncp.at] TRACE: > AT+COPS=3,2
0000003666 [ncp.at] TRACE: < OK
0000003666 [ncp.at] TRACE: > AT+CGEREP=1,0
0000003669 [ncp.at] TRACE: < OK
0000003669 [ncp.at] TRACE: > AT+UPSV=0
0000003673 [ncp.at] TRACE: < OK
0000003673 [mux] INFO: Mux channel 1 already opened
0000003674 [ncp.at] TRACE: > AT
0000003676 [ncp.at] TRACE: < OK
0000003676 [ncp.client] TRACE: NCP state changed: 1
0000003676 [net.pppncp] TRACE: NCP event 1
0000003677 [net.ppp.client] TRACE: PPP thread event ADM_UP
0000003677 [net.ppp.client] TRACE: State NONE -> READY
0000003680 [ncp.at] TRACE: > AT+CFUN?
0000003683 [ncp.at] TRACE: < +CFUN: 1,0
0000003684 [ncp.at] TRACE: < OK
0000003684 [ncp.at] TRACE: > AT+CCID
0000003702 [ncp.at] TRACE: < +CCID: 89314404000710740227
0000003703 [ncp.at] TRACE: < OK
0000003703 [ncp.at] TRACE: > AT+CIMI
0000003706 [ncp.at] TRACE: < 204047120764699
0000003707 [ncp.at] TRACE: < OK
0000003708 [ncp.at] TRACE: > AT+CGDCONT?
0000003711 [ncp.at] TRACE: < +CGDCONT: 1,"IP","vfd1.korem2m.com","0.0.0.0",0,0
0000003712 [ncp.at] TRACE: < OK
0000003713 [ncp.at] TRACE: > AT+CFUN?
0000003716 [ncp.at] TRACE: < +CFUN: 1,0
0000003716 [ncp.at] TRACE: < OK
0000003717 [ncp.at] TRACE: > AT+CREG=2
0000003719 [ncp.at] TRACE: < OK
0000003720 [ncp.at] TRACE: > AT+CGREG=2
0000003722 [ncp.at] TRACE: < OK
0000003722 [ncp.client] TRACE: NCP connection state changed: 1
0000003723 [net.pppncp] TRACE: NCP event 2
0000003723 [net.pppncp] TRACE: State changed event: 1
0000003724 [ncp.at] TRACE: > AT+COPS?
0000003724 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN
0000003727 [ncp.at] TRACE: < +COPS: 0,2,"27201",2
0000003728 [ncp.at] TRACE: < OK
0000003728 [ncp.at] TRACE: > AT+CREG?
0000003732 [ncp.at] TRACE: < +CREG: 2,5,"0BD5","CAB7C",6
0000003732 [ncp.at] TRACE: < OK
0000003733 [ncp.at] TRACE: > AT+CGREG?
0000003736 [ncp.at] TRACE: < +CGREG: 2,5,"0BD5","CAB7C",6,"0F"
0000003736 [ncp.at] TRACE: < OK
0000003737 [ncp.client] TRACE: NCP connection state changed: 2
0000003737 [mux] INFO: Openning mux channel 2
0000005002 [net.pppncp] TRACE: NCP event 100
0000005003 [net.pppncp] TRACE: New auth info
0000005005 [net.pppncp] TRACE: NCP event 2
0000005006 [net.pppncp] TRACE: State changed event: 2
0000005006 [net.ppp.client] TRACE: PPP thread event LOWER_UP
0000005006 [net.ppp.client] TRACE: State READY -> CONNECT
0000005007 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000005007 [ncp.at] TRACE: > AT+CIMI
0000005011 [ncp.at] TRACE: < 204047120764699
0000005011 [ncp.at] TRACE: < OK
0000006013 [ncp.at] TRACE: > AT
0000006015 [ncp.at] TRACE: < OK
0000006015 [ncp.at] TRACE: > ATH
0000006018 [ncp.at] TRACE: < OK
0000006019 [ncp.at] TRACE: > ATD*99***1#
0000006023 [ncp.at] TRACE: < CONNECT
0000006023 [net.ppp.client] TRACE: PPP phase -> 3
0000006024 [net.ppp.client] TRACE: PPP phase -> 6
0000006028 [net.ppp.client] TRACE: PPP phase -> 7
0000006032 [net.ppp.client] TRACE: PPP phase -> 9
0000012037 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000012038 [net.ppp.client] TRACE: PPP thread event UP
0000012038 [net.ppp.client] TRACE: State CONNECTING -> CONNECTED
0000012039 [net.pppncp] TRACE: Negotiated MTU: 1500
0000012039 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000012041 [net.ppp.client] TRACE: PPP phase -> 10
0000012042 [system] INFO: Cloud: connecting
0000012046 [system] INFO: Cloud socket connected
0000012046 [comm.protocol.handshake] INFO: Establish secure connection
0000012051 [comm.dtls] INFO: session has 0 uses
0000012066 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=0
0000012067 [comm.dtls] INFO: out_ctr 0,1,0,0,0,0,1,167, next_coap_id=193
0000012068 [comm.dtls] INFO: restored session from persisted session data. next_msg_id=403
0000012069 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 2
0000012435 [ncp.at] TRACE: > AT+CFUN?
0000012438 [ncp.at] TRACE: < +CFUN: 1,0
0000012439 [ncp.at] TRACE: < OK
0000012441 [ncp.at] TRACE: > AT+CCID
0000012457 [ncp.at] TRACE: < +CCID: 89314404000710740227
0000012458 [ncp.at] TRACE: < OK
0000012459 [ncp.at] TRACE: > AT+CGSN
0000012472 [ncp.at] TRACE: < 358887097724387
0000012472 [ncp.at] TRACE: < OK
0000012473 [ncp.at] TRACE: > ATI9
0000012484 [ncp.at] TRACE: < 23.60,A01.01
0000012484 [ncp.at] TRACE: < OK
0000012485 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000012485 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000012487 [comm.protocol.handshake] INFO: Sending HELLO message
0000013150 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000013151 [comm.protocol.handshake] INFO: Handshake completed
0000013151 [comm.protocol.handshake] TRACE: Updating cached session parameters
0000013152 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000013154 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000013517 [ncp.at] TRACE: > AT+CFUN?
0000013520 [ncp.at] TRACE: < +CFUN: 1,0
0000013521 [ncp.at] TRACE: < OK
0000013522 [ncp.at] TRACE: > AT+CCID
0000013540 [ncp.at] TRACE: < +CCID: 89314404000710740227
0000013540 [ncp.at] TRACE: < OK
0000013541 [ncp.at] TRACE: > AT+CGSN
0000013555 [ncp.at] TRACE: < 358887097724387
0000013555 [ncp.at] TRACE: < OK
0000013556 [ncp.at] TRACE: > ATI9
0000013567 [ncp.at] TRACE: < 23.60,A01.01
0000013568 [ncp.at] TRACE: < OK
0000013571 [comm.protocol] INFO: Posting 'S' describe message
0000013589 [comm.protocol] INFO: Posting 'A' describe message
0000013593 [comm.protocol] INFO: Sending subscriptions
0000014786 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000014787 [comm.protocol] TRACE: message id 405 complete with code 0.00
0000014787 [comm.protocol] TRACE: Updating system DESCRIBE checksum
0000014788 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000015162 [ncp.at] TRACE: > AT+CFUN?
0000015164 [ncp.at] TRACE: < +CFUN: 1,0
0000015165 [ncp.at] TRACE: < OK
0000015165 [ncp.at] TRACE: > AT+CCID
0000015187 [ncp.at] TRACE: < +CCID: 89314404000710740227
0000015188 [ncp.at] TRACE: < OK
0000015188 [ncp.at] TRACE: > AT+CGSN
0000015195 [ncp.at] TRACE: < 358887097724387
0000015195 [ncp.at] TRACE: < OK
0000015196 [ncp.at] TRACE: > ATI9
0000015203 [ncp.at] TRACE: < 23.60,A01.01
0000015203 [ncp.at] TRACE: < OK
0000015203 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000015204 [comm.protocol] TRACE: rcv'd message type=13
0000015205 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000015206 [comm.protocol] TRACE: message id 406 complete with code 0.00
0000015207 [comm.protocol] TRACE: rcv'd message type=13
0000015307 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000015308 [comm.protocol] TRACE: message id 407 complete with code 0.00
0000015309 [comm.protocol] TRACE: rcv'd message type=13
0000015409 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000015410 [comm.protocol] TRACE: message id 408 complete with code 0.00
0000015411 [comm.protocol] TRACE: rcv'd message type=13
0000015511 [comm.protocol] TRACE: Reply recieved: type=2, code=69
0000015512 [comm.protocol] TRACE: message id 409 complete with code 2.05
0000015513 [comm.protocol] INFO: Received TIME response: 1649103569
0000015514 [comm.protocol] TRACE: rcv'd message type=12
0000015613 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000015614 [comm.protocol] TRACE: message id 410 complete with code 0.00
0000015615 [comm.protocol] TRACE: Updating application DESCRIBE checksum
0000015616 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000015617 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000015618 [comm.protocol] TRACE: rcv'd message type=13
0000015717 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000015718 [comm.protocol] TRACE: message id 411 complete with code 0.00
0000015719 [comm.protocol] TRACE: rcv'd message type=13
0000015819 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000015820 [comm.protocol] TRACE: message id 412 complete with code 0.00
0000015821 [comm.protocol] TRACE: Updating subscriptions checksum
0000015822 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000015823 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000015824 [comm.protocol] TRACE: rcv'd message type=13
0000015886 [comm.protocol] TRACE: rcv'd message type=8
0000015886 [system] INFO: Cloud connected
0000015887 [app] INFO: connected to the cloud in 15887 ms
0000015888 [app] INFO: FIRST IDLE
0000015888 [app] INFO: CHECKING SYSTEM
0000015888 [app] INFO: STORING SYS READINGS
0000015890 [app] INFO: SIZE OF S: 400
0000015891 [app.pubq] TRACE: after writing numEvents=1 fileLength=252
0000015924 [app] INFO: CHECKING FOR ANIMAL
0000015926 [app.pubq] INFO: publishing SysReadings { "f": "0.00", "b": "12.69", "t": "2022-04-04 20:19:29", "s": "10", "Em": "", "sd": "1", "tp": "0.00", "h": "0.00", "sp": "0", "st": "6~

Just as before it hangs on the last log line above. Nothing further is sent down the serial line before it restarts due to external watchdog. The device stays breathing cyan, but does not respond to particle functions or vital refresh.

Once the particle resets due to the ext watchdog, the queued message from when it hangs gets sent with the latest startup publish.

system · June 3, 2022, 8:36pm

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
PublishQueue Library bug Firmware	4	608	June 7, 2018
PublishQuequeAsyncRK - WITH_ACK issue - any solution? Libraries	6	490	June 28, 2019
PublishQueueAsyncRK repeated old data Libraries	4	411	September 19, 2022
Check SD status before storing data Firmware	2	281	September 8, 2022
New library to delay Publish to cloud: PublishQueue Libraries	5	2985	January 20, 2017

PublishQueueAsyncRK Hanging

Related topics