ESP8266 disconnects from MQTT #157

TheCellMC · 2018-09-08T07:26:46Z

First of all, I'd like to thank every single contributor for creating this epic project.

Sadly, I'm having some trouble getting all of this to run smoothly.
A few minutes after every reboot, my MFRC522 stops scanning new cards. However, I can still access the web interface. Rebooting the ESP8266 solves the issue, but a few minutes later the issue arises again.

~~I'm running esp-rfid on an ESP8266 with an MFRC522.~~

~~If you need any sort of logging, please ask.~~

Please read comment below

TheCellMC · 2018-09-08T07:35:06Z

UPDATE: It turns out that the MFRC522 is still scanning cards as, when I swipe a card, is does a search for it in the Users page. However, it does not publish a message via MQTT. MQTT works again after a reboot but only for a few minutes. I have many devices connected to MQTT but I've never had this issue.

TheCellMC · 2018-09-08T08:09:02Z

I've tried again with the latest version and I'm still not getting any messages from MQTT accept from the boot message.

wamboin23 · 2018-09-08T08:34:32Z

I am having the same issue on 0.8.2.

It is sending the startup MQTT message with IP address etc, then the heartbeat message, but after that there is no more MQTT messages sent. Possibly something broken after the MQTT patch in this update.

Also, the heatbeat message is incorrectly title, 'hearthbeat'.

omersiar · 2018-09-08T09:30:45Z

Let me check this.

omersiar · 2018-09-08T09:35:56Z

Can you please check event log for MQTT events? Is there any info available there?

TheCellMC · 2018-09-08T09:54:29Z

I'm not able to access the event log. I'm stuck on a "Please wait while fetching data..." message.
I've tried on Safari 11.1.2 and on Chrome 69.0 on my iMac running High Sierra 10.13.6.

omersiar · 2018-09-08T09:55:57Z

What device do you have? And can you also make a backup and clear your flash before flashing the latest firmware?

TheCellMC · 2018-09-08T10:01:37Z

I have an ESP8266. What do you mean by

clear your flash

Do you want me to reset it via the UI or to flash the blank file onto my ESP8266.

wamboin23 · 2018-09-08T10:03:39Z

Event log shows an MQTT_DISCONNECTED message just after reboot, then no further mention.

omersiar · 2018-09-08T10:04:02Z

Which ESP8266 board do you have ? ESP8266 alone is not enough to understand what board you have.

Clearing flash can be done via on Web UI selecting factory reset or by flashing blank firmware with a tool, but i am afraid that i do not know any flasher for Mac

omersiar · 2018-09-08T10:04:32Z

@wamboin23 Any connected message? or just DISCONNECTED?

wamboin23 · 2018-09-08T10:10:18Z

Just a disconnected message. There is no connected message at any time.

wamboin23 · 2018-09-08T10:11:31Z

I also noticed I now get an 'Enabling WIFI' message in the event log everytime an admin user scans a tag.
I dont think it was like this before the update to 0.8.2 either. I have wifi set to Always On.

omersiar · 2018-09-08T10:18:50Z

I think it does not take into account "always on" setting when admin card is scanned, so it logs every time when admin card is scanned, i will open a separate issue for this.

TheCellMC · 2018-09-08T10:26:13Z

So, I've got a nodemcuv2.
I'm also getting an MQTT_DISCONNECTED message after boot.

wamboin23 · 2018-09-08T10:37:39Z

Just flashed it back to 0.8.1, and can confirm I now have MQTT messages been sent when a user scans a tag.

omersiar · 2018-09-17T07:51:12Z

So the bug introduced exactly at 0.8.2, interesting the only change is making the credentials global.

wamboin23 · 2018-09-17T09:57:58Z

It looks that way. Let me know if I can provide any more info, or test anything.

omersiar · 2018-10-07T12:23:47Z

Can someone please test this firmware? It has serial debug output, flash and look for messages on serial port. It should work with your 0.8.1 settings.
debug.zip

wamboin23 · 2018-10-07T17:34:49Z

Will test later on today.

wamboin23 · 2018-10-09T09:25:22Z

..
[ INFO ] Client IP address: 192.168.55.19
[ INFO ] Trying to setup NTP Server
[ INFO ] Trying to setup MQTT
[ INFO ] try to call mqttconnect
[ INFO ] try to connect mqtt
[ INFO ] Configuration done.
[ INFO ] MQTT Connected session
[ INFO ] Mqtt Publish:{"type":"boot","time":1539079184,"Wifi SSID":"IoTKalinda", "Local IP":"192.168.55.19"}
[ INFO ] Mqtt Publish:{"type":"hearthbeat","time":1539079184}
[ INFO ] Nextbeat=1539080984
[ INFO ] PICC's UID: 4ac8f12ff3880 = known PICC
[ INFO ] User Name: Brendan have admin access, enable wifi
[ INFO ] Mqtt Publish:{"type":"access","time":1539079247,"isKnown":"true","access":"Admin","username":"Brendan","uid":"4ac8f12ff3880"}
mili : 65881
activating relay now
67907
65881
2000
0
deactivate relay after this
mili : 68085
[ INFO ] PICC's UID: 4ac8f12ff3880 = known PICC
[ INFO ] User Name: Brendan have admin access, enable wifi
[ INFO ] Mqtt Publish:{"type":"access","time":1539079297,"isKnown":"true","access":"Admin","username":"Brendan","uid":"4ac8f12ff3880"}
mili : 115852
activating relay now
118012
115852
2000
0
deactivate relay after this
mili : 118187

Seems to be working, at this time....

MQTT messages are been published correctly. Will flash back to current release tomorrow and see if it was just a glitch.

Is this serial debug output not normally available in a standard build?

wamboin23 · 2018-10-09T10:11:27Z

After posting I did another scan of tag, still reads and turns on relay, but no MQTT messages sent.

Confirmed the debug output is now missing the Mqtt publish line. No other errors seen.

..
[ INFO ] Client IP address: 192.168.55.19
[ INFO ] Trying to setup NTP Server
[ INFO ] Trying to setup MQTT
[ INFO ] try to call mqttconnect
[ INFO ] try to connect mqtt
[ INFO ] Configuration done.
[ INFO ] MQTT Connected session
[ INFO ] Mqtt Publish:{"type":"boot","time":1539079184,"Wifi SSID":"IoTKalinda", "Local IP":"192.168.55.19"}
[ INFO ] Mqtt Publish:{"type":"hearthbeat","time":1539079184}
[ INFO ] Nextbeat=1539080984
[ INFO ] PICC's UID: 4ac8f12ff3880 = known PICC
[ INFO ] User Name: Brendan have admin access, enable wifi
[ INFO ] Mqtt Publish:{"type":"access","time":1539079247,"isKnown":"true","access":"Admin","username":"Brendan","uid":"4ac8f12ff3880"}
mili : 65881
activating relay now
67907
65881
2000
0
deactivate relay after this
mili : 68085
[ INFO ] PICC's UID: 4ac8f12ff3880 = known PICC
[ INFO ] User Name: Brendan have admin access, enable wifi
[ INFO ] Mqtt Publish:{"type":"access","time":1539079297,"isKnown":"true","access":"Admin","username":"Brendan","uid":"4ac8f12ff3880"}
mili : 115852
activating relay now
118012
115852
2000
0
deactivate relay after this
mili : 118187
[ INFO ] PICC's UID: 4ac8f12ff3880 = known PICC
[ INFO ] User Name: Brendan have admin access, enable wifi
mili : 518216
activating relay now
520385
518216
2000
0
deactivate relay after this
mili : 520562
[ INFO ] PICC's UID: 4ac8f12ff3880 = known PICC
[ INFO ] User Name: Brendan have admin access, enable wifi
mili : 531032
activating relay now
533200
531032
2000
0
deactivate relay after this
mili : 533375

benlongjohn · 2018-10-23T17:01:59Z

Any update on getting this bug fixed? Been using this program to control my electronic door lock and now it's unable to be used. Will an update for this MQTT disconnection error be released anytime soon? Would even be willing to pay someone for a release/fix.

egebaek · 2018-10-31T18:16:24Z

Same problem here on nodemcu please help....

egebaek · 2018-11-01T07:05:22Z

What about this they have the same problem
knolleary/pubsubclient#250
Or the basic
https://github.com/knolleary/pubsubclient/blob/master/examples/mqtt_basic/mqtt_basic.ino#L50

omersiar · 2018-11-01T10:10:57Z

We do not use pubsubclient

fivosg · 2018-11-07T14:57:55Z

I was having the same problem running it on a Wemos d1 mini. It was disconnecting from MQTT broker.
Commenting out(deleting) the mqttClient.setServer(mhs, mport); line in void onMqttDisconnect routine seems to fix it for me. Can someone confirm this?
`
void onMqttDisconnect(AsyncMqttClientDisconnectReason reason) {
#ifdef DEBUG
Serial.println("[ Error ] Mqtt disconected ");
#endif
String reasonstr = "";
switch (reason) {
case (AsyncMqttClientDisconnectReason::TCP_DISCONNECTED):
reasonstr = "TCP_DISCONNECTED";
break;
case (AsyncMqttClientDisconnectReason::MQTT_UNACCEPTABLE_PROTOCOL_VERSION):
reasonstr = "MQTT_UNACCEPTABLE_PROTOCOL_VERSION";
break;
case (AsyncMqttClientDisconnectReason::MQTT_IDENTIFIER_REJECTED):
reasonstr = "MQTT_IDENTIFIER_REJECTED";
break;
case (AsyncMqttClientDisconnectReason::MQTT_SERVER_UNAVAILABLE):
reasonstr = "MQTT_SERVER_UNAVAILABLE";
break;
case (AsyncMqttClientDisconnectReason::MQTT_MALFORMED_CREDENTIALS):
reasonstr = "MQTT_MALFORMED_CREDENTIALS";
break;
case (AsyncMqttClientDisconnectReason::MQTT_NOT_AUTHORIZED):
reasonstr = "MQTT_NOT_AUTHORIZED";
break;
case (AsyncMqttClientDisconnectReason::ESP8266_NOT_ENOUGH_SPACE):
reasonstr = "ESP8266_NOT_ENOUGH_SPACE";
break;
default:
reasonstr = "Unknown";
break;
}
writeEvent("WARN", "mqtt", "Disconnected from MQTT server", reasonstr);

if (WiFi.isConnected()) {
//	mqttClient.setServer(mhs, mport);
	mqttReconnectTimer.once(2, connectToMqtt);
}

}

`
generic_firmware.zip

benlongjohn · 2018-11-07T18:50:01Z

For some reason no fix has been found for this error. This is a pretty flawless system if this worked. Not sure how its been this long and a bug fix hasn't been release yet though.

omersiar · 2018-11-07T19:04:56Z

@benlongjohn I am sorry that this is not fixed yet. It's simply because of i do not have time to setup MQTT test environment.

@fivosg What happens when you shutdown MQTT broker and esp-rfid disconnects?
and when MQTT server is available again after the esp-rfid disconnects?

benlongjohn · 2018-11-07T19:41:39Z

@omersiar Its okay. I apologize if i sound hostile. I realize you provide this program free of charge. Ill be more than happy to make a small contribution to you if the bug is fixed for all of your hard work and just to say thanks. I do appreciate you taking the time to create this program.

fivosg · 2018-11-07T21:42:38Z

@omersiar I tried rebooting the mqtt broker. It reconnected as it should.
Thats the log file:

54	WARN	mqtt	Disconnected from MQTT server	TCP_DISCONNECTED	2018-11-07-23:31:27
53	WARN	mqtt	Disconnected from MQTT server	TCP_DISCONNECTED	2018-11-07-23:31:25
And the serial DEBUG:
[ Error ] Mqtt disconected
[ INFO ] try to connect mqtt
[ Error ] Mqtt disconected
[ INFO ] try to connect mqtt
[ INFO ] MQTT Connected session
[ INFO ] Mqtt Publish:{"type":"boot","time":1541626296,"Wifi SSID":"******","Local IP":"********"}

omersiar · 2018-11-08T19:28:43Z

@fivosg nice thank you i will prepare a new release soon™️

benlongjohn · 2018-11-09T01:21:53Z

@omersiar Cant even connect to WiFi anymore unfortunately. Each time I enter my credentials, save, and reboot, it just reverts back to the default AP settings.

omersiar · 2018-11-09T11:00:12Z

I'm sorry that i can not test it myself because i do not have any esp8266 board right now. I will try get one.

fivosg · 2018-11-09T12:42:28Z

I tried 0.9.0 firmware. I could connect to WiFi by loading the backup settings( I didn't try to manually enter them). The problem I had was that it defaults to Wiegand hardware and the menu option to change it to MFRC522 was grey and not working. Changed back to my version of firmware and it worked.
Only problem is that every now and then it disconnects from MQTT the broker log says:

1541766367: Socket error on client esp82660405e4, disconnecting.
1541766367: New connection from 192.168.1.36 on port 1883.
[INFO] found username on local database
1541766367: New client connected from 192.168.1.36 as esp82660405e4 (c1, k15, u'username').

But it connects again. I can't figure out why that happens. All my other MQTT clients never disconnect from the server.

omersiar · 2018-11-09T13:00:03Z

Configuration file structure is changed and i think we do not handle the differences in the right way.

@fivosg Is your version is based on 0.8.2 right? (stable branch)

fivosg · 2018-11-09T14:09:09Z

@omersiar Yes it's based on the 0.8.2 release

omersiar · 2018-11-09T14:25:13Z

@fivosg If you flash forV2board.bin the other options are grayed-out, you need to flash generic.bin or debug.bin

I think there is no easy way to use old configuration file on 0.9.0.

Please erase your flash or format flash via WebUI by selecting factory reset and then flash version 0.9.0 and configure it manually

You Need To Clear Browser's Cache or Open ESP-RFID Web UI on Browser's Incognito Mode

Make sure you have a user's backup ( do not back up settings )
Before upgrading make a factory reset.
After factory reset connect to esp-rfid's Access Point.
Do not setup any configuration
Do firmware upgrade
Configure your newly upgraded device
Save and Reboot
Restore Users back.

Or Windows PC users can use flash tool which is available on /bin folder

Make sure you have a user's backup ( do not back up settings )
use flash.bat and select erase flash

fivosg · 2018-11-09T15:17:45Z

followed the procedure and I have the same problem as @benlongjohn (Each time I enter my credentials, save, and reboot, it just reverts back to the default AP settings).

omersiar · 2018-11-09T19:08:38Z

Sorry for the any inconvenience, i will prepare a reliable, tested release soon™️

egebaek · 2018-11-09T20:29:42Z

i have now flashed the newest version on a NodeMCU and it worked with wifi and the reader, lets see how it goes with MQTT, and stability.

omersiar · 2018-11-11T10:48:05Z

Please see https://github.com/esprfid/esp-rfid/releases/latest

v0.8.3 is a bug fix release.

v0.9.0 is not ready yet

egebaek · 2018-11-15T22:55:35Z

keep getting this on the MQTT on version 0.8.3: (and then it don't connect anymore)

2018-11-15 20:36:24	stdout	1542314184: New client connected from 192.168.87.54 as esp82666e2e37 (c1, k15, u'egebaek').
2018-11-15 20:36:24	stdout	1542314184: New connection from 192.168.87.54 on port 1883.
2018-11-15 20:36:20	stdout	1542314180: Socket error on client esp82666e2e37, disconnecting.
2018-11-15 20:36:20	stdout	1542314180: Client esp82666e2e37 has exceeded timeout, disconnecting.
2018-11-15 20:35:37	stdout	1542314137: New client connected from 192.168.87.54 as esp82666e2e37 (c1, k15, u'egebaek').
2018-11-15 20:35:37	stdout	1542314137: Client esp82666e2e37 disconnected.
2018-11-15 20:35:37	stdout	1542314137: Client esp82666e2e37 already connected, closing old connection.
2018-11-15 20:35:37	stdout	1542314137: New connection from 192.168.87.54 on port 1883.
2018-11-15 20:34:48	stdout	1542314088: New client connected from 192.168.87.54 as esp82666e2e37 (c1, k15, u'egebaek').
2018-11-15 20:34:48	stdout	1542314088: Client esp82666e2e37 disconnected.
2018-11-15 20:34:48	stdout	1542314088: Client esp82666e2e37 already connected, closing old connection.
2018-11-15 20:34:48	stdout	1542314088: New connection from 192.168.87.54 on port 1883.
2018-11-15 20:34:04	stdout	1542314044: New client connected from 192.168.87.54 as esp82666e2e37 (c1, k15, u'egebaek').
2018-11-15 20:34:04	stdout	1542314044: New connection from 192.168.87.54 on port 1883.
2018-11-15 20:31:56	stdout	1542313916: Saving in-memory database to /mqtt/data/mosquitto.db.
2018-11-15 20:28:43	stdout	1542313723: Socket error on client esp82666e2e37, disconnecting.
2018-11-15 20:28:43	stdout	1542313723: Client esp82666e2e37 has exceeded timeout, disconnecting.
2018-11-15 20:24:49	stdout	1542313489: New client connected from 192.168.87.54 as esp82666e2e37 (c1, k15, u'egebaek').
2018-11-15 20:24:49	stdout	1542313489: Client esp82666e2e37 disconnected.
2018-11-15 20:24:49	stdout	1542313489: Client esp82666e2e37 already connected, closing old connection.
2018-11-15 20:24:49	stdout	1542313489: New connection from 192.168.87.54 on port 1883.

TheCellMC changed the title ~~MFRC522 Stops scanning cards after a few minutes~~ ESP8266 disconnects from MQTT Sep 8, 2018

TheCellMC closed this as completed Sep 8, 2018

TheCellMC reopened this Sep 8, 2018

omersiar added bug confirmed labels Sep 17, 2018

omersiar added the help wanted label Nov 1, 2018

omersiar added the investigate label Nov 1, 2018

omersiar added this to the 0.9 milestone Nov 8, 2018

omersiar mentioned this issue Nov 9, 2018

Reintegration of the RDM6300 (and RF125-PS) solution #181

Merged

omersiar closed this as completed Nov 13, 2018

ESP8266 disconnects from MQTT #157

ESP8266 disconnects from MQTT #157

Comments

TheCellMC commented Sep 8, 2018 • edited Loading

TheCellMC commented Sep 8, 2018

TheCellMC commented Sep 8, 2018

wamboin23 commented Sep 8, 2018

omersiar commented Sep 8, 2018

omersiar commented Sep 8, 2018

TheCellMC commented Sep 8, 2018 • edited Loading

omersiar commented Sep 8, 2018

TheCellMC commented Sep 8, 2018

wamboin23 commented Sep 8, 2018

omersiar commented Sep 8, 2018

omersiar commented Sep 8, 2018

wamboin23 commented Sep 8, 2018

wamboin23 commented Sep 8, 2018

omersiar commented Sep 8, 2018

TheCellMC commented Sep 8, 2018

wamboin23 commented Sep 8, 2018

omersiar commented Sep 17, 2018

wamboin23 commented Sep 17, 2018

omersiar commented Oct 7, 2018

wamboin23 commented Oct 7, 2018

wamboin23 commented Oct 9, 2018 • edited Loading

wamboin23 commented Oct 9, 2018

benlongjohn commented Oct 23, 2018

egebaek commented Oct 31, 2018

egebaek commented Nov 1, 2018 • edited Loading

omersiar commented Nov 1, 2018

fivosg commented Nov 7, 2018 • edited Loading

benlongjohn commented Nov 7, 2018

omersiar commented Nov 7, 2018

benlongjohn commented Nov 7, 2018

fivosg commented Nov 7, 2018

omersiar commented Nov 8, 2018

benlongjohn commented Nov 9, 2018

omersiar commented Nov 9, 2018

fivosg commented Nov 9, 2018

omersiar commented Nov 9, 2018

fivosg commented Nov 9, 2018

omersiar commented Nov 9, 2018

fivosg commented Nov 9, 2018

omersiar commented Nov 9, 2018

egebaek commented Nov 9, 2018

omersiar commented Nov 11, 2018 • edited Loading

egebaek commented Nov 15, 2018

TheCellMC commented Sep 8, 2018 •

edited

Loading

TheCellMC commented Sep 8, 2018 •

edited

Loading

wamboin23 commented Oct 9, 2018 •

edited

Loading

egebaek commented Nov 1, 2018 •

edited

Loading

fivosg commented Nov 7, 2018 •

edited

Loading

omersiar commented Nov 11, 2018 •

edited

Loading