search

eclipse / mosquitto

Eclipse Mosquitto - An open source MQTT broker
https://mosquitto.org
Other
8.91k stars 2.37k forks source link

Socket error but CONNACK is 0,0 #1667

Closed bortek closed 4 years ago

bortek commented 4 years ago

Whats really going on here? I am getting CONNACK (0, 0) but all ends up in socket error and the messages is discarded.

I use authentication and it works fine. Tested to set wrong pwd and I get authenication error.

I have already debug enabled but it still does not print the actual cause of the error.

Any idea what could it be or how else can enable even more debug? Will tcpdump show more details?

I am using the latest mosquitto version 1.6.8

2020-04-27T22:14:22: New connection from 192.168.0.215 on port 8883. 2020-04-27T22:14:22: New client connected from 192.168.0.215 as auto-30F517E5-CB39-CAE0-7CB6-62E580408C39 (p2, c1, k15, u'radmon'). 2020-04-27T22:14:22: No will message specified. 2020-04-27T22:14:22: Sending CONNACK to auto-30F517E5-CB39-CAE0-7CB6-62E580408C39 (0, 0) 2020-04-27T22:14:22: Received PUBLISH from auto-30F517E5-CB39-CAE0-7CB6-62E580408C39 (d0, q0, r0, m0, 'radmon/js/cpm', ... (2 bytes)) 2020-04-27T22:14:22: Received PUBLISH from auto-30F517E5-CB39-CAE0-7CB6-62E580408C39 (d0, q0, r0, m0, 'radmon/js/dose', ... (4 bytes)) 2020-04-27T22:14:22: Received PUBLISH from auto-30F517E5-CB39-CAE0-7CB6-62E580408C39 (d0, q0, r0, m0, 'radmon/js/rssi', ... (6 bytes)) 2020-04-27T22:14:22: Received PUBLISH from auto-30F517E5-CB39-CAE0-7CB6-62E580408C39 (d0, q0, r0, m0, 'radmon/js/temp', ... (5 bytes)) 2020-04-27T22:14:22: Received PUBLISH from auto-30F517E5-CB39-CAE0-7CB6-62E580408C39 (d0, q0, r0, m0, 'radmon/js/humid', ... (2 bytes)) 2020-04-27T22:14:22: Received PUBLISH from auto-30F517E5-CB39-CAE0-7CB6-62E580408C39 (d0, q0, r0, m0, 'radmon/js/pressure', ... (7 bytes)) 2020-04-27T22:14:24: Socket error on client auto-30F517E5-CB39-CAE0-7CB6-62E580408C39, disconnecting. 2020-04-27T22:14:25: Saving in-memory database to /var/lib/mosquitto/mosq

ralight commented 4 years ago

"Socket error on client" pretty much means that the client closed the connection, although it could also be a read/write failure for some other reason. Using tcpdump is unlikely to be straightforward if you're using TLS, but if this behaviour is repeatable and does repeat when not using TLS, I'd be interested to see a tcpdump/wireshark log.

bortek commented 4 years ago

I am not using TLS and here comes the tcpdump capture file which can be opened in Wireshark.

192.168.0.215 is the client publishing 192.168.0.223 is a MQTT server

Don't see anything wrong in the Wireshark. There are FIN ACK messages both way at the end.

What do you think ?

conn_err.zip

ralight commented 4 years ago

It seems pretty clear, at packet 11 the client sends a FIN, which is its request to close the connection. Packet 12 is the server replying with a FIN, which closes its half of the connection. This will result in the server seeing the client close its connection, and hence the socket error message.

What client are you using?

bortek commented 4 years ago

This is interesting. Isn't this how the normal communication goes?

Packet 9 : Client is Publishing the payload Packet10: Server AKCs a payload Packet11: Client sends FIN/ACK because it has nothing else to send Packet12: Server sends its FIN/ACK¨ Packet13: Client ACKs the last FIN from server.

I have captured and looked a simple curl communication and it looks similar with last 2 FIN,ACK and 1 ACK.

My client is code (not mine) in ESP8266 utilizing some of the MQTT libs available.

ralight commented 4 years ago

I think we might be asking different questions of each other. My understanding of what you were asking was "I don't know why my client is disconnecting".

What your logs show is:

The wireshark logs match that.

Is it the "socket error" text that is bothering you?

bortek commented 4 years ago

Let me rephrase my question, sorry that it wasn't clear in the first place :) Why am I getting error from the server when everything seems to work as expected?

In my understanding there should not have been any socket errors despite that there are no subscribers receiving the message. But I have even tested with the subscriber connected and receiving the message successfully. But the server was still spotting out "socket error" in the logs. Below are the logs for that scenario.

2020-04-28T07:56:16: New connection from 192.168.0.215 on port 8883. 2020-04-28T07:56:16: New client connected from 192.168.0.215 as auto-6A825A0C-693B-D278-EDB8-0D69B4820FAD (p2, c1, k15, u'radmon'). 2020-04-28T07:56:16: No will message specified. 2020-04-28T07:56:16: Sending CONNACK to auto-6A825A0C-693B-D278-EDB8-0D69B4820FAD (0, 0) 2020-04-28T07:56:16: Received PUBLISH from auto-6A825A0C-693B-D278-EDB8-0D69B4820FAD (d0, q0, r0, m0, 'radmon/js/cpm', ... (2 bytes)) 2020-04-28T07:56:16: Sending PUBLISH to RadmonReader (d0, q0, r0, m0, 'radmon/js/cpm', ... (2 bytes)) 2020-04-28T07:56:16: Received PUBLISH from auto-6A825A0C-693B-D278-EDB8-0D69B4820FAD (d0, q0, r0, m0, 'radmon/js/dose', ... (4 bytes)) 2020-04-28T07:56:16: Sending PUBLISH to RadmonReader (d0, q0, r0, m0, 'radmon/js/dose', ... (4 bytes)) 2020-04-28T07:56:16: Received PUBLISH from auto-6A825A0C-693B-D278-EDB8-0D69B4820FAD (d0, q0, r0, m0, 'radmon/js/rssi', ... (6 bytes)) 2020-04-28T07:56:16: Sending PUBLISH to RadmonReader (d0, q0, r0, m0, 'radmon/js/rssi', ... (6 bytes)) 2020-04-28T07:56:16: Received PUBLISH from auto-6A825A0C-693B-D278-EDB8-0D69B4820FAD (d0, q0, r0, m0, 'radmon/js/temp', ... (5 bytes)) 2020-04-28T07:56:16: Sending PUBLISH to RadmonReader (d0, q0, r0, m0, 'radmon/js/temp', ... (5 bytes)) 2020-04-28T07:56:16: Received PUBLISH from auto-6A825A0C-693B-D278-EDB8-0D69B4820FAD (d0, q0, r0, m0, 'radmon/js/humid', ... (2 bytes)) 2020-04-28T07:56:16: Sending PUBLISH to RadmonReader (d0, q0, r0, m0, 'radmon/js/humid', ... (2 bytes)) 2020-04-28T07:56:16: Received PUBLISH from auto-6A825A0C-693B-D278-EDB8-0D69B4820FAD (d0, q0, r0, m0, 'radmon/js/pressure', ... (7 bytes)) 2020-04-28T07:56:16: Sending PUBLISH to RadmonReader (d0, q0, r0, m0, 'radmon/js/pressure', ... (7 bytes)) 2020-04-28T07:56:18: Socket error on client auto-6A825A0C-693B-D278-EDB8-0D69B4820FAD, disconnecting. 2020-04-28T07:56:58: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.

ralight commented 4 years ago

"Socket error on client" here just means "the client has disconnected". It used to cover a wide variety of reasons for why that was the case, but now it basically just means that the client has closed the connection. I've pushed a commit that changes the wording of that log message to make it obvious that it is the client that has disconnected.

bortek commented 4 years ago

oh.. well.. thanks!