search

eclipse / 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.95k stars 1.09k forks source link

SSL_write blocks after "Partial write: ..." error occurs. #1153

Closed AleksaJanjatovic closed 2 years ago

AleksaJanjatovic commented 3 years ago

Hello everyone,

I've encountered a problem in Paho library related to the SSL_write function. Namely, after trying to publish on a relatively large packet (198183 bytes), next logs can be seen.

2021-09-01 15:46:00,948 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 0 qos: 0 retained: 0 payload len(198182): { "code" : 0, "param 2021-09-01 15:46:00,990 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 15:46:01,178 [omb] [E81B6974F3C9] I [Paho] 40: 4 g-E81B6974F3C9 -> PUBLISH qos: 0 retained: 0 rc: 0 payload len(198182): { "code" : 0, "param 2021-09-01 15:46:01,187 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 0 qos: 0 retained: 0 payload len(198183): { "code" : 0, "param 2021-09-01 15:46:01,190 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 15:46:01,295 [omb] [E81B6974F3C9] D [Paho] 40: SSLSocket error WANT_READ/WANT_WRITE 2021-09-01 15:46:01,296 [omb] [E81B6974F3C9] D [Paho] 40: Partial write: incomplete write of 198251 bytes on SSL socket 4 2021-09-01 15:46:01,299 [omb] [E81B6974F3C9] I [Paho] 40: 4 g-E81B6974F3C9 -> PUBLISH qos: 0 retained: 0 rc: -22 payload len(198183): { "code" : 0, "param 2021-09-01 15:46:01,300 [omb] [E81B6974F3C9] D [Paho] 40: Storing unsent QoS 0 message

The number (40, 0) before the log strings is the number of the thread that is executing the functions.

After that, the publishing of the client g-E81B6974F3C9 seems to be blocked up until 15 minutes later, when a timeout on the socket is reached:

2021-09-01 16:01:43,242 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59928 (0) 2021-09-01 16:01:43,265 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:01:43,270 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59929 qos: 1 retained: 0 payload len(373): { "name" : "property 2021-09-01 16:01:43,271 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59929 (0) 2021-09-01 16:01:43,272 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:01:43,279 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59930 qos: 1 retained: 0 payload len(373): { "name" : "property 2021-09-01 16:01:43,281 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59930 (0) 2021-09-01 16:01:43,282 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:01:43,288 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59931 qos: 1 retained: 0 payload len(375): { "name" : "property 2021-09-01 16:01:43,289 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59931 (0) 2021-09-01 16:01:43,290 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:01:43,297 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59932 qos: 1 retained: 0 payload len(373): { "name" : "property 2021-09-01 16:01:43,299 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59932 (0) 2021-09-01 16:01:43,300 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:01:43,306 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59933 qos: 1 retained: 0 payload len(372): { "name" : "property 2021-09-01 16:01:43,308 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59933 (0) 2021-09-01 16:01:43,309 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:01:44,533 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59934 qos: 1 retained: 0 payload len(363): { "name" : "property 2021-09-01 16:01:44,535 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59934 (0) 2021-09-01 16:01:44,536 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:01:44,541 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59935 qos: 1 retained: 0 payload len(341): { "name" : "device_p 2021-09-01 16:01:44,546 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59935 (0) 2021-09-01 16:01:44,547 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:01:48,454 [omb] [E81B6974F3C9] D [Paho] 0: SSLSocket error (5) in SSL_write for socket 4 rc -1 errno 145 Connection timed out

2021-09-01 16:01:48,458 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 <- PUBLISH msgid: 58 qos: 1 retained: 0 payload len(42): { "online": false, 2021-09-01 16:01:48,460 [omb] [E81B6974F3C9] D [Paho] 0: SSLSocket error (1) in SSL_write for socket 4 rc -1 errno 0 Success

2021-09-01 16:01:48,461 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 -> PUBACK msgid: 58 (-1) 2021-09-01 16:01:48,461 [omb] [E81B6974F3C9] D [Paho] 0: SSLSocket error (1) in SSL_write for socket 4 rc -1 errno 0 Success

2021-09-01 16:01:48,463 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 -> DISCONNECT (-1) 2021-09-01 16:01:48,465 [omb] [E81B6974F3C9] D [Paho] 0: Removed socket 4 2021-09-01 16:01:48,467 [omb] [E81B6974F3C9] D [Paho] 0: Conn_count is 3 2021-09-01 16:01:48,468 [omb] [E81B6974F3C9] D [Paho] 0: Calling connectionLost for client g-E81B6974F3C9

After which it can be seen in logs the SSL cipher reinitialization and successful publishing by the g-E81B6974F3C9 client:

2021-09-01 16:02:10,579 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBACK msgid: 85 2021-09-01 16:02:10,580 [omb] [E81B6974F3C9] D [Paho] 0: PUBACK received from client stratus for message id 85 - removing publication 2021-09-01 16:02:10,581 [omb] [E81B6974F3C9] D [Paho] 0: Calling deliveryComplete for client stratus, msgid 85 2021-09-01 16:02:10,584 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 0:ECDHE-RSA-AES256-GCM-SHA384 2021-09-01 16:02:10,585 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 1:ECDHE-ECDSA-AES256-GCM-SHA384 2021-09-01 16:02:10,586 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 2:ECDHE-RSA-AES256-SHA384 2021-09-01 16:02:10,587 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 3:ECDHE-ECDSA-AES256-SHA384 2021-09-01 16:02:10,588 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 4:ECDHE-RSA-AES256-SHA 2021-09-01 16:02:10,589 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 5:ECDHE-ECDSA-AES256-SHA 2021-09-01 16:02:10,590 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 6:SRP-DSS-AES-256-CBC-SHA 2021-09-01 16:02:10,591 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 7:SRP-RSA-AES-256-CBC-SHA 2021-09-01 16:02:10,591 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 8:SRP-AES-256-CBC-SHA 2021-09-01 16:02:10,592 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 9:DHE-DSS-AES256-GCM-SHA384 2021-09-01 16:02:10,594 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 10:DHE-RSA-AES256-GCM-SHA384 2021-09-01 16:02:10,595 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 11:DHE-RSA-AES256-SHA256 2021-09-01 16:02:10,596 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 12:DHE-DSS-AES256-SHA256 2021-09-01 16:02:10,597 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 13:DHE-RSA-AES256-SHA 2021-09-01 16:02:10,598 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 14:DHE-DSS-AES256-SHA 2021-09-01 16:02:10,599 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 15:DHE-RSA-CAMELLIA256-SHA 2021-09-01 16:02:10,601 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 16:DHE-DSS-CAMELLIA256-SHA 2021-09-01 16:02:10,602 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 17:ECDH-RSA-AES256-GCM-SHA384 2021-09-01 16:02:10,604 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 18:ECDH-ECDSA-AES256-GCM-SHA384 2021-09-01 16:02:10,605 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 19:ECDH-RSA-AES256-SHA384 2021-09-01 16:02:10,606 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 20:ECDH-ECDSA-AES256-SHA384 2021-09-01 16:02:10,607 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 21:ECDH-RSA-AES256-SHA 2021-09-01 16:02:10,609 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 22:ECDH-ECDSA-AES256-SHA 2021-09-01 16:02:10,610 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 23:AES256-GCM-SHA384 2021-09-01 16:02:10,611 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 24:AES256-SHA256 2021-09-01 16:02:10,612 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 25:AES256-SHA 2021-09-01 16:02:10,614 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 26:CAMELLIA256-SHA 2021-09-01 16:02:10,615 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 27:PSK-AES256-CBC-SHA 2021-09-01 16:02:10,617 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 28:ECDHE-RSA-AES128-GCM-SHA256 2021-09-01 16:02:10,618 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 29:ECDHE-ECDSA-AES128-GCM-SHA256 2021-09-01 16:02:10,619 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 30:ECDHE-RSA-AES128-SHA256 2021-09-01 16:02:10,620 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 31:ECDHE-ECDSA-AES128-SHA256 2021-09-01 16:02:10,621 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 32:ECDHE-RSA-AES128-SHA 2021-09-01 16:02:10,623 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 33:ECDHE-ECDSA-AES128-SHA 2021-09-01 16:02:10,624 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 34:SRP-DSS-AES-128-CBC-SHA 2021-09-01 16:02:10,625 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 35:SRP-RSA-AES-128-CBC-SHA 2021-09-01 16:02:10,626 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 36:SRP-AES-128-CBC-SHA 2021-09-01 16:02:10,627 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 37:DHE-DSS-AES128-GCM-SHA256 2021-09-01 16:02:10,629 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 38:DHE-RSA-AES128-GCM-SHA256 2021-09-01 16:02:10,630 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 39:DHE-RSA-AES128-SHA256 2021-09-01 16:02:10,631 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 40:DHE-DSS-AES128-SHA256 2021-09-01 16:02:10,632 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 41:DHE-RSA-AES128-SHA 2021-09-01 16:02:10,634 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 42:DHE-DSS-AES128-SHA 2021-09-01 16:02:10,635 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 43:DHE-RSA-SEED-SHA 2021-09-01 16:02:10,636 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 44:DHE-DSS-SEED-SHA 2021-09-01 16:02:10,637 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 45:DHE-RSA-CAMELLIA128-SHA 2021-09-01 16:02:10,638 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 46:DHE-DSS-CAMELLIA128-SHA 2021-09-01 16:02:10,640 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 47:ECDH-RSA-AES128-GCM-SHA256 2021-09-01 16:02:10,641 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 48:ECDH-ECDSA-AES128-GCM-SHA256 2021-09-01 16:02:10,642 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 49:ECDH-RSA-AES128-SHA256 2021-09-01 16:02:10,643 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 50:ECDH-ECDSA-AES128-SHA256 2021-09-01 16:02:10,645 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 51:ECDH-RSA-AES128-SHA 2021-09-01 16:02:10,646 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 52:ECDH-ECDSA-AES128-SHA 2021-09-01 16:02:10,647 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 53:AES128-GCM-SHA256 2021-09-01 16:02:10,648 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 54:AES128-SHA256 2021-09-01 16:02:10,649 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 55:AES128-SHA 2021-09-01 16:02:10,651 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 56:SEED-SHA 2021-09-01 16:02:10,652 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 57:CAMELLIA128-SHA 2021-09-01 16:02:10,653 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 58:IDEA-CBC-SHA 2021-09-01 16:02:10,654 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 59:PSK-AES128-CBC-SHA 2021-09-01 16:02:10,655 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 60:ECDHE-RSA-RC4-SHA 2021-09-01 16:02:10,656 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 61:ECDHE-ECDSA-RC4-SHA 2021-09-01 16:02:10,657 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 62:ECDH-RSA-RC4-SHA 2021-09-01 16:02:10,657 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 63:ECDH-ECDSA-RC4-SHA 2021-09-01 16:02:10,658 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 64:RC4-SHA 2021-09-01 16:02:10,659 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 65:RC4-MD5 2021-09-01 16:02:10,660 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 66:PSK-RC4-SHA 2021-09-01 16:02:10,661 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 67:ECDHE-RSA-DES-CBC3-SHA 2021-09-01 16:02:10,662 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 68:ECDHE-ECDSA-DES-CBC3-SHA 2021-09-01 16:02:10,669 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 69:SRP-DSS-3DES-EDE-CBC-SHA 2021-09-01 16:02:10,670 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 70:SRP-RSA-3DES-EDE-CBC-SHA 2021-09-01 16:02:10,671 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 71:SRP-3DES-EDE-CBC-SHA 2021-09-01 16:02:10,672 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 72:EDH-RSA-DES-CBC3-SHA 2021-09-01 16:02:10,674 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 73:EDH-DSS-DES-CBC3-SHA 2021-09-01 16:02:10,675 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 74:ECDH-RSA-DES-CBC3-SHA 2021-09-01 16:02:10,676 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 75:ECDH-ECDSA-DES-CBC3-SHA 2021-09-01 16:02:10,677 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 76:DES-CBC3-SHA 2021-09-01 16:02:10,678 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 77:PSK-3DES-EDE-CBC-SHA 2021-09-01 16:02:10,680 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 78:EDH-RSA-DES-CBC-SHA 2021-09-01 16:02:10,681 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 79:EDH-DSS-DES-CBC-SHA 2021-09-01 16:02:10,682 [omb] [E81B6974F3C9] I [Paho] 43: SSL cipher available: 80:DES-CBC-SHA 2021-09-01 16:02:10,684 [omb] [E81B6974F3C9] D [Paho] 43: the src string is truncated 2021-09-01 16:02:10,685 [omb] [E81B6974F3C9] I [Paho] 43: SSL handshake started write:unknown:unknown 2021-09-01 16:02:10,686 [omb] [E81B6974F3C9] I [Paho] 43: SSL state connect:before/connect initialization:(NONE) 2021-09-01 16:02:10,688 [omb] [E81B6974F3C9] D [Paho] 43: sent 771 22 buflen 314 2021-09-01 16:02:10,690 [omb] [E81B6974F3C9] I [Paho] 43: SSL state connect:SSLv2/v3 write client hello A:(NONE) 2021-09-01 16:02:10,691 [omb] [E81B6974F3C9] I [Paho] 43: SSL connect:SSLv2/v3 read server hello A 2021-09-01 16:02:10,692 [omb] [E81B6974F3C9] D [Paho] 43: SSLSocket error WANT_READ/WANT_WRITE 2021-09-01 16:02:10,729 [omb] [E81B6974F3C9] D [Paho] 0: received 771 22 buflen 89 2021-09-01 16:02:10,730 [omb] [E81B6974F3C9] I [Paho] 0: SSL state connect:SSLv3 read server hello A:(NONE) 2021-09-01 16:02:10,731 [omb] [E81B6974F3C9] D [Paho] 0: received 771 22 buflen 2577 2021-09-01 16:02:10,742 [omb] [E81B6974F3C9] I [Paho] 0: SSL state connect:SSLv3 read server certificate A:(NONE) 2021-09-01 16:02:10,744 [omb] [E81B6974F3C9] D [Paho] 0: received 771 22 buflen 333 2021-09-01 16:02:10,751 [omb] [E81B6974F3C9] I [Paho] 0: SSL state connect:SSLv3 read server key exchange A:(NONE) 2021-09-01 16:02:10,753 [omb] [E81B6974F3C9] D [Paho] 0: received 771 22 buflen 4 2021-09-01 16:02:10,754 [omb] [E81B6974F3C9] I [Paho] 0: SSL state connect:SSLv3 read server done A:(NONE) 2021-09-01 16:02:10,786 [omb] [E81B6974F3C9] D [Paho] 0: sent 771 22 buflen 70 2021-09-01 16:02:10,787 [omb] [E81B6974F3C9] I [Paho] 0: SSL state connect:SSLv3 write client key exchange A:(NONE) 2021-09-01 16:02:10,788 [omb] [E81B6974F3C9] D [Paho] 0: sent 771 20 buflen 1 2021-09-01 16:02:10,789 [omb] [E81B6974F3C9] I [Paho] 0: SSL state connect:SSLv3 write change cipher spec A:ECDHE-RSA-AES128-GCM-SHA256 2021-09-01 16:02:10,791 [omb] [E81B6974F3C9] D [Paho] 0: sent 771 22 buflen 16 2021-09-01 16:02:10,792 [omb] [E81B6974F3C9] I [Paho] 0: SSL state connect:SSLv3 write finished A:ECDHE-RSA-AES128-GCM-SHA256 2021-09-01 16:02:10,793 [omb] [E81B6974F3C9] I [Paho] 0: SSL state connect:SSLv3 flush data:ECDHE-RSA-AES128-GCM-SHA256 2021-09-01 16:02:10,794 [omb] [E81B6974F3C9] I [Paho] 0: SSL connect:SSLv3 read finished A 2021-09-01 16:02:10,795 [omb] [E81B6974F3C9] I [Paho] 0: SSL connect:SSLv3 read finished A 2021-09-01 16:02:10,796 [omb] [E81B6974F3C9] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-01 16:02:10,834 [omb] [E81B6974F3C9] D [Paho] 0: received 771 20 buflen 1 2021-09-01 16:02:10,836 [omb] [E81B6974F3C9] D [Paho] 0: received 771 22 buflen 16 2021-09-01 16:02:10,837 [omb] [E81B6974F3C9] I [Paho] 0: SSL state connect:SSLv3 read finished A:ECDHE-RSA-AES128-GCM-SHA256 2021-09-01 16:02:10,838 [omb] [E81B6974F3C9] I [Paho] 0: SSL handshake done write:unknown:unknown 2021-09-01 16:02:10,839 [omb] [E81B6974F3C9] I [Paho] 0: SSL certificate verification: X509_V_OK 2021-09-01 16:02:10,840 [omb] [E81B6974F3C9] I [Paho] 0: SSL connect:SSL negotiation finished successfully 2021-09-01 16:02:10,841 [omb] [E81B6974F3C9] D [Paho] 0: Posting connect semaphore for SSL client g-E81B6974F3C9 rc 1 2021-09-01 16:02:10,844 [omb] [E81B6974F3C9] I [Paho] 43: 4 g-E81B6974F3C9 -> CONNECT version 4 clean: 0 (0) 2021-09-01 16:02:10,934 [omb] [E81B6974F3C9] D [Paho] 0: Posting connack semaphore for client g-E81B6974F3C9 2021-09-01 16:02:10,939 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 <- PUBLISH msgid: 58 qos: 1 retained: 0 payload len(42): { "online": false, 2021-09-01 16:02:10,941 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 -> PUBACK msgid: 58 (0) 2021-09-01 16:02:10,942 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client g-E81B6974F3C9, queue depth 1 2021-09-01 16:02:10,945 [omb] [E81B6974F3C9] I [Paho] 16: 13 stratus -> PUBLISH msgid: 86 qos: 1 retained: 0 rc 0 payload len(42): { "online": false, 2021-09-01 16:02:10,956 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 <- PUBLISH msgid: 59 qos: 1 retained: 0 payload len(41): { "online": true,

2021-09-01 16:02:10,957 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 -> PUBACK msgid: 59 (0) 2021-09-01 16:02:10,958 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client g-E81B6974F3C9, queue depth 1 2021-09-01 16:02:10,960 [omb] [E81B6974F3C9] I [Mosquitto] 41: Status changed (id='cli/19cb82d8aac3d604', s=0) 2021-09-01 16:02:10,961 [omb] [E81B6974F3C9] I [Paho] 16: 13 stratus -> PUBLISH msgid: 87 qos: 1 retained: 0 rc 0 payload len(41): { "online": true,

2021-09-01 16:02:10,963 [omb] [E81B6974F3C9] I [Paho] 43: 4 g-E81B6974F3C9 <- CONNACK rc: 0 2021-09-01 16:02:10,964 [omb] [E81B6974F3C9] I [Bridge] 43: (cld) Session will be updated with new subscriptions (s=17, u=1) 2021-09-01 16:02:10,965 [omb] [E81B6974F3C9] I [Paho] 43: 4 g-E81B6974F3C9 -> SUBSCRIBE msgid: 36476 (0) 2021-09-01 16:02:10,969 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 <- PUBLISH msgid: 60 qos: 1 retained: 0 payload len(42): { "online": false,

Ignore the prefix [omb] [E81B6974F3C9], it's related to my project.

AleksaJanjatovic commented 3 years ago

This was noticed on Paho Client version 1.3.5

icraggs commented 3 years ago

From the limited information you've shown here, I don't think it's related to the partial write. After that partial write, your trace shows PUBACKS being sent on the same socket until the timeout occurs and you omit the part of the trace where it could show whether the packet is completely written or not.

If it happened all the time on sending that sized message without doing anything else, then that would be easy to try out and take a trace of.

It's possible it's related to a change I've just added to the develop branch #1131, but I'm not sure. I would suggest trying that out, or at least the latest version, 1.3.9, and taking a trace of that if it still occurs.

AleksaJanjatovic commented 3 years ago

PUBACKS are not actually sent from the same socket, because a new socket under the same number is created after this one is closed.

2021-09-01 16:01:48,454 [omb] [E81B6974F3C9] D [Paho] 0: SSLSocket error (5) in SSL_write for socket 4 rc -1 errno 145 Connection timed out

2021-09-01 16:01:48,458 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 <- PUBLISH msgid: 58 qos: 1 retained: 0 payload len(42): { "online": false, 2021-09-01 16:01:48,460 [omb] [E81B6974F3C9] D [Paho] 0: SSLSocket error (1) in SSL_write for socket 4 rc -1 errno 0 Success

2021-09-01 16:01:48,461 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 -> PUBACK msgid: 58 (-1) 2021-09-01 16:01:48,461 [omb] [E81B6974F3C9] D [Paho] 0: SSLSocket error (1) in SSL_write for socket 4 rc -1 errno 0 Success

2021-09-01 16:01:48,463 [omb] [E81B6974F3C9] I [Paho] 0: 4 g-E81B6974F3C9 -> DISCONNECT (-1) 2021-09-01 16:01:48,465 [omb] [E81B6974F3C9] D [Paho] 0: Removed socket 4 2021-09-01 16:01:48,467 [omb] [E81B6974F3C9] D [Paho] 0: Conn_count is 3 2021-09-01 16:01:48,468 [omb] [E81B6974F3C9] D [Paho] 0: Calling connectionLost for client g-E81B6974F3C9 2021-09-01 16:01:48,469 [omb] [E81B6974F3C9] I [Bridge] 42: (cld) Connection lost reported: unknown cause 2021-09-01 16:01:48,470 [omb] [E81B6974F3C9] I [Bridge] 42: (cld) Resurrector initialized. 2021-09-01 16:01:48,486 [omb] [E81B6974F3C9] I [Paho] 10: 11 app/omb -> PUBLISH msgid: 14 qos: 1 retained: 0 rc 0 payload len(127): { "name" : "cloud_st 2021-09-01 16:01:48,491 [omb] [E81B6974F3C9] I [Paho] 0: 11 app/omb <- PUBACK msgid: 14 2021-09-01 16:01:48,493 [omb] [E81B6974F3C9] D [Paho] 0: PUBACK received from client app/omb for message id 14 - removing publication 2021-09-01 16:01:48,494 [omb] [E81B6974F3C9] D [Paho] 0: Calling deliveryComplete for client app/omb, msgid 14 2021-09-01 16:01:48,500 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59936 qos: 1 retained: 0 payload len(127): { "name" : "cloud_st 2021-09-01 16:01:48,502 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59936 (0) 2021-09-01 16:01:48,504 [omb] [E81B6974F3C9] D [Paho] 40: Conn_count is 3 2021-09-01 16:01:48,504 [omb] [E81B6974F3C9] E [Bridge] 40: (cld) Publish failed (c=-1, t=oblo/5e660b855a658c7a42b9996e/cli/5e660b855a658c7a42b9996e/rsp). 2021-09-01 16:01:48,514 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:02:03,870 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59937 qos: 1 retained: 0 payload len(373): { "name" : "property 2021-09-01 16:02:03,872 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59937 (0) 2021-09-01 16:02:03,872 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:02:03,900 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59938 qos: 1 retained: 0 payload len(333): { "name" : "device_p 2021-09-01 16:02:03,901 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59938 (0) 2021-09-01 16:02:03,940 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:02:03,965 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59939 qos: 1 retained: 0 payload len(341): { "name" : "device_p 2021-09-01 16:02:03,967 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59939 (0) 2021-09-01 16:02:03,968 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:02:06,457 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59940 qos: 1 retained: 0 payload len(362): { "name" : "property 2021-09-01 16:02:06,458 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59940 (0) 2021-09-01 16:02:06,459 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:02:06,472 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBLISH msgid: 59941 qos: 1 retained: 0 payload len(341): { "name" : "device_p 2021-09-01 16:02:06,483 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus -> PUBACK msgid: 59941 (0) 2021-09-01 16:02:06,484 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-01 16:02:10,033 [omb] [E81B6974F3C9] D [Paho] 43: Connecting to serverURI $IP_REPLACED:$PORT_REPLACED with MQTT version 4 2021-09-01 16:02:10,034 [omb] [E81B6974F3C9] D [Paho] 43: New socket 4 for $IP_REPLACED:$PORT_REPLACED, port 8884 2021-09-01 16:02:10,035 [omb] [E81B6974F3C9] D [Paho] 43: Connect pending 2021-09-01 16:02:10,563 [omb] [E81B6974F3C9] D [Paho] 0: Calling messageArrived for client g-E81B6974F3C9, queue depth 1 2021-09-01 16:02:10,564 [omb] [E81B6974F3C9] D [Paho] 0: Posting connect semaphore for client g-E81B6974F3C9 rc 0 2021-09-01 16:02:10,567 [omb] [E81B6974F3C9] I [Paho] 16: 13 stratus -> PUBLISH msgid: 85 qos: 1 retained: 0 rc 0 payload len(42): { "online": false, 2021-09-01 16:02:10,579 [omb] [E81B6974F3C9] I [Paho] 0: 13 stratus <- PUBACK msgid: 85 2021-09-01 16:02:10,580 [omb] [E81B6974F3C9] D [Paho] 0: PUBACK received from client stratus for message id 85 - removing publication 2021-09-01 16:02:10,581 [omb] [E81B6974F3C9] D [Paho] 0: Calling deliveryComplete for client stratus, msgid 85

String $IP_REPLACED:$PORT_REPLACED is filled with correct values in the real logs. Regarding the logs that show whether or not the packet was completely written, they DO NOT appear, as if a deadlock appeared that prevented the continueWrite function execution. While testing on the PC, we were able to see that even though large packets failed with WANT_READ/WANT_WRITE error, they were completed with the continueWrite function

Next logs are from a successful large packet transmission, that was run on the host/PC setup

2021-09-15 16:29:16,781 [omb] [FFAAFFAAFFBB] I [Paho] 0: 14 stratus <- PUBLISH msgid: 0 qos: 0 retained: 0 payload len(1263770): { "code" : 0, "param 2021-09-15 16:29:16,781 [omb] [FFAAFFAAFFBB] D [Paho] 0: Calling messageArrived for client stratus, queue depth 1 2021-09-15 16:29:16,783 [omb] [FFAAFFAAFFBB] T [Bridge] 18: (cld) Publishing to: oblo/5f23f1cbb7d888103a200e46/cli/5f23f1cbb7d888103a200e46/rsp 2021-09-15 16:29:16,783 [omb] [FFAAFFAAFFBB] T [Bridge] 18: (cld) Publish done for: oblo/5f23f1cbb7d888103a200e46/cli/5f23f1cbb7d888103a200e46/rsp 2021-09-15 16:29:16,784 [omb] [FFAAFFAAFFBB] D [Paho] 29: sent 0 256 buflen 5 2021-09-15 16:29:16,784 [omb] [FFAAFFAAFFBB] D [Paho] 29: sent 0 256 buflen 5 2021-09-15 16:29:16,784 [omb] [FFAAFFAAFFBB] D [Paho] 29: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:16,784 [omb] [FFAAFFAAFFBB] D [Paho] 29: Partial write: incomplete write of 1263838 bytes on SSL socket 3 2021-09-15 16:29:16,784 [omb] [FFAAFFAAFFBB] I [Paho] 29: 3 g-FFAAFFAAFFBB -> PUBLISH qos: 0 retained: 0 rc: -22 payload len(1263770): { "code" : 0, "param 2021-09-15 16:29:16,785 [omb] [FFAAFFAAFFBB] D [Paho] 29: Storing unsent QoS 0 message 2021-09-15 16:29:17,784 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,784 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,784 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,784 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:17,817 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,817 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:17,848 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,848 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,848 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:17,850 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,850 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,850 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:17,881 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,881 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,881 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,881 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:17,908 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,908 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,908 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,908 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:17,918 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,918 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,918 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:17,945 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,945 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,945 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,945 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:17,970 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,971 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,971 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,971 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:17,982 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,982 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,982 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:17,983 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,008 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,008 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,008 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,008 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,032 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,033 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,033 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,033 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,045 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,045 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,045 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,045 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,070 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,070 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,070 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,070 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,094 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,094 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,094 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,094 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,107 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,107 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,107 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,107 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,107 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,131 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,131 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,131 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,131 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,145 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,145 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,145 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,145 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,145 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,169 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,169 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,169 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,169 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,169 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,194 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,194 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,194 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,194 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,194 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,208 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,208 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,208 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,208 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,208 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,232 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,232 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,232 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,232 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,232 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,256 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,257 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,257 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,257 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,257 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,270 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,270 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,270 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,270 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,271 [omb] [FFAAFFAAFFBB] D [Paho] 0: sent 0 256 buflen 5 2021-09-15 16:29:18,271 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSLSocket error WANT_READ/WANT_WRITE 2021-09-15 16:29:18,295 [omb] [FFAAFFAAFFBB] D [Paho] 0: SSL continueWrite: partial write now complete for socket 3

We have tested the issue with packets as large or larger than the one that was causing issues, and WANT_READ/WANT_WRITE did appear although the Paho was able to recover via the continueWrite mechanism. Also, this issue appeared only once on the native MIPS platform on which the bug first appeared, and we were unable to reproduce it since.

icraggs commented 3 years ago

Please don't paste log contents directly into the issue - it makes the issues hard to read. Rather attach them as files, as requested in the issue template.

Is it a bug? It doesn't look abnormal, unless there's a section of the trace missing. If there is no signal from the socket, then the write can't continue. Do you have an MQTT keepalive timeout set? If you have your keepalive timeout set to less than 10 minutes (50% grace period), then that should trigger the connection lost if nothing can be written to the socket.

I would also suggest switching to the latest release 1.3.9.

AleksaJanjatovic commented 3 years ago

Apologies for the logs in the ticket. This is definitely an issue but happens very rarely, we have observed it only once and only on one platform. In this case, it happened with MQTT QoS0 publish that needed two writes to the socket but we can not confirm if it may happen with smaller messages too. Problem is that publishing a message got stuck until someone entity broke the TCP connection, either networking stack or some network router that detected established connection without any traffic. In this specific case, the broker did trigger the LWM message as after the problem occurred no other message was sent to the broker, including the keep-alive.

We would suggest leaving it open and monitoring it in the hope to get more detailed logs or some clear reproduction steps. In the mean while we will update to Paho 1.3.9.

icraggs commented 2 years ago

There's at least one change in the current develop branch which may affect this.

icraggs commented 2 years ago

Closing as no more info received.