search

eclipse-paho / paho.mqtt.c

An Eclipse Paho C client library for MQTT for Windows, Linux and MacOS. API documentation: https://eclipse.github.io/paho.mqtt.c/
https://eclipse.org/paho
Other
1.98k stars 1.1k forks source link

Socket error on client X, disconnecting. #898

Closed brianreinhold closed 4 years ago

brianreinhold commented 4 years ago

Describe the bug I'm not sure this is a problem on the PAHO client or the Mosquitto broker. What I DO know is that the error is not caused by a keep-alive problem. The client-broker exchange continues for quite a long time before this event happens. It does not happen consistently in the same place.

Here is the log from Mosquitto: `1590354870: Sending PUBREL to ExampleClientSub (m248)

1590354870: Received PUBCOMP from ExampleClientSub (Mid: 248, RC:0) 1590354870: Received PUBLISH from ExampleClientSub (d0, q2, r0, m332, 'pcha/response/WAN/Gyannea/CODE', ... (82 bytes)) 1590354870: Sending PUBREC to ExampleClientSub (m332, rc0) 1590354870: Received PUBREL from ExampleClientSub (Mid: 332) 1590354870: Sending PUBCOMP to ExampleClientSub (m332) 1590354870: Sending PUBLISH to orchestrator (d0, q2, r0, m331, 'pcha/response/WAN/Gyannea/CODE', ... (82 bytes)) 1590354870: Received PUBREC from orchestrator (Mid: 331) 1590354870: Sending PUBREL to orchestrator (m331) 1590354870: Received PUBCOMP from orchestrator (Mid: 331, RC:0) 1590354871: Received PUBLISH from orchestrator (d0, q2, r0, m252, 'pcha/message/WAN/Gyannea/CODE', ... (3248 bytes)) 1590354871: Sending PUBREC to orchestrator (m252, rc0) 1590354871: Received PUBREL from orchestrator (Mid: 252) 1590354871: Sending PUBCOMP to orchestrator (m252) 1590354871: Sending PUBLISH to ExampleClientSub (d0, q2, r0, m249, 'pcha/message/WAN/Gyannea/CODE', ... (3248 bytes)) 1590354871: Received PUBREC from ExampleClientSub (Mid: 249) 1590354871: Sending PUBREL to ExampleClientSub (m249) 1590354871: Received PUBCOMP from ExampleClientSub (Mid: 249, RC:0) 1590354872: Socket error on client ExampleClientSub, disconnecting. 1590354881: Received PUBLISH from orchestrator (d0, q2, r0, m253, 'pcha/message/WAN/Gyannea/CODE', ... (52 bytes)) 1590354881: Sending PUBREC to orchestrator (m253, rc0)`

Here is the log from PAHO client side `Cleaned up shut down specialization

Sending payload {"event":"EvtDisconnect","params":{"evtId":3}} {"id":245,"success":true,"body":{"message":"Specialization stopped"}} Waiting on MQTT Message with token value 330 delivery confirmed Message arrived topic: pcha/message/WAN/Gyannea/CODE message: Payload: {"id":246,"operation":"stopBluetooth","params":null}

Sending payload {"id":246,"success":true,"body":{"message":"Responding to command stopBluetooth"}} MQTT Signaled Mqtt queue entry signaled jsonString read from MQTT queue =========> Handling command 'stopBluetooth' {"id":246,"success":true,"body":{"message":"No specialization to stop"}} Waiting on MQTT Message with token value 331 delivery confirmed Message arrived topic: pcha/message/WAN/Gyannea/CODE message: Payload: {"id":247,"operation":"stopBluetooth","params":null}

Sending payload {"id":247,"success":true,"body":{"message":"Responding to command stopBluetooth"}} MQTT Signaled Mqtt queue entry signaled jsonString read from MQTT queue =========> Handling command 'stopBluetooth' {"id":247,"success":true,"body":{"message":"No specialization to stop"}} Waiting on MQTT Message with token value 332 delivery confirmed Message arrived topic: pcha/message/WAN/Gyannea/CODE message: Payload: {"id":248,"operation":"setConfig","params":{"config":{"pulseOxConfig":{"poFeatureChar":{"trapRead":false,"msmtStatus":true,"devStatus":true,"msmtStorage":true,"ti ,"fastMetric":true,"slowMetric":true,"pulseAmp":true,"multipleBonds":false,"measurementStatus":{"statusMsmtOngoing":true,"statusEarlyEstimate":true,"statusValidatedData":true,"statusF :true,"statusFromStoredData":true,"statusDemoData":true,"statusTestData":true,"statusCalibrationOngoing":true,"statusUnavailable":true,"statusQuestionable":true,"statusInvalid":true}, Status":{"devExtDisplayOngoing":true,"devEquipMalfunction":true,"devSigProcIrregular":true,"devInadequateSig":true,"devPoorSig":true,"devLowPerfusion":true,"devErraticSig":true,"devNo ":true,"devQuestionablePulse":true,"devSigAnalysisOngoing":true,"devSensorInterference":true,"devSensorNotConnToUser":true,"devUnknownSensor":true,"devSensorDisplaced":true,"devSensor true,"devSensorDisconnected":true}},"pulseOxMsmtChars":[{"spot":{"hasTimeStamp":true,"needClockSet":false,"spo2":"NAN","pulseRate":"39","devAndSensorStatus":{"devExtDisplayOngoing":fa Malfunction":true,"devSigProcIrregular":false,"devInadequateSig":false,"devPoorSig":false,"devLowPerfusion":false,"devErraticSig":false,"devNonPulsatileSig":false,"devQuestionablePuls SigAnalysisOngoing":false,"devSensorInterference":false,"devSensorNotConnToUser":true,"devUnknownSensor":false,"devSensorDisplaced":true,"devSensorMalfunction":false,"devSensorDisconn "pulseAmp":"7.14"},"contRepeats":1,"delay":1000},{"spot":{"hasTimeStamp":true,"needClockSet":false,"spo2":"95","pulseRate":"NAN","devAndSensorStatus":{"devExtDisplayOngoing":true,"dev ion":false,"devSigProcIrregular":false,"devInadequateSig":true,"devPoorSig":false,"devLowPerfusion":false,"devErraticSig":true,"devNonPulsatileSig":false,"devQuestionablePulse":false, isOngoing":false,"devSensorInterference":true,"devSensorNotConnToUser":false,"devUnknownSensor":true,"devSensorDisplaced":false,"devSensorMalfunction":false,"devSensorDisconnected":fa p":"3.14"},"contRepeats":1,"delay":1000},{"spot":{"hasTimeStamp":true,"needClockSet":false,"spo2":"95","pulseRate":"55","devAndSensorStatus":{"devExtDisplayOngoing":false,"devEquipMal se,"devSigProcIrregular":true,"devInadequateSig":false,"devPoorSig":true,"devLowPerfusion":true,"devErraticSig":false,"devNonPulsatileSig":true,"devQuestionablePulse":true,"devSigAnal true,"devSensorInterference":false,"devSensorNotConnToUser":false,"devUnknownSensor":false,"devSensorDisplaced":false,"devSensorMalfunction":true,"devSensorDisconnected":false},"pulse contRepeats":1,"delay":1000}],"setRepeats":1,"racpChar":{"trapRead":false},"supportsSpot":true,"supportsCont":true,"specializationType":"PULSE_OX","trapMsmtCharRead":false},"common":{ "POOne","btAddress":"E00000000001","dis":{"useDefaultRegCert":true,"systemId":"FEEDABEEDEAD4001","serialNumber":"snPo0001","firmware":"fw0.5.1","manufacturer":"LNI, Inc.","modelNumber trapRead":false},"cts":{"currentTimeChar":{"trapRead":true,"allowWrite":true,"adjustReason":"None"}},"invokeServiceChanged":false}}}}êêêêN/╓Q*t♠

E:\projects\BleTester\BtleTester\exe>` The program just exits on the disconnect. Must call a system.exit down there because there is nothing my code can do.

To Reproduce The procedures to set this up is complicated. So I am only asking if someone has any ideas as to what could cause this error BESIDES a keep alive timeout. Its definitely not that as it is 20 seconds and the error was immediate. One notes that a rather large JSON string was just received on the PAHO subscription channel but it is not the size causing the problem. It just happened after a large transfer in this case. The keep alive timeout is 20 seconds.

Expected behavior Simply to keep going. No socket error. Screenshots If applicable, add screenshots to help explain your problem.

Environment (please complete the following information):

Additional context Its a complicated system. The PAHO client is being run as part of a BLE test engine using the Nordic dongle to simulate BTLE health devices. A second program is communicating with the BTLE test engine via MQTT. A third program sends controls to the second program.

icraggs commented 4 years ago

There's no sys.exit(). I was going to say can you run it under gdb, but I see you're on Windows. DrWatson or similar on Windows?

jumoog commented 4 years ago

there was time issue.. after ~35 days the client stopped working #927