MQTT log entries

Just looking at my MQTT log, and there seems to be a lot of ‘already connected, closing old connection’ entries.

Is this expected??

I’m publishing 3 separate feeds from emoncms every 5 seconds, and node-red is subscribing to the data.
My MQTT username is emoncms

[email protected]:~ $ sudo tail -F /var/log/mosquitto/mosquitto.log
1530348187: New connection from ::1 on port 1883.
1530348187: Client mosq/1q\1tBDnbeH\[email protected] already connected, closing old connection.
1530348187: Client mosq/1q\1tBDnbeH\[email protected] disconnected.
1530348187: New client connected from ::1 as mosq/1q\1tBDnbeH\[email protected] (c1, k60, u'emoncms').
1530348187: Client mosq/1q\1tBDnbeH\[email protected] disconnected.
1530348192: New connection from ::1 on port 1883.
1530348192: New client connected from ::1 as mosq/bKvPuPSL?Ac\]PE0N8 (c1, k60, u'emoncms').
1530348192: Client mosq/bKvPuPSL?Ac\]PE0N8 disconnected.
1530348192: New connection from ::1 on port 1883.
1530348192: New client connected from ::1 as mosq/bKvPuPSL?Ac\]PE0N8 (c1, k60, u'emoncms').
1530348192: Client mosq/bKvPuPSL?Ac\]PE0N8 disconnected.
1530348192: New connection from ::1 on port 1883.
1530348192: New client connected from ::1 as mosq/bKvPuPSL?Ac\]PE0N8 (c1, k60, u'emoncms').
1530348192: Client mosq/bKvPuPSL?Ac\]PE0N8 disconnected.
1530348197: New connection from ::1 on port 1883.
1530348197: New client connected from ::1 as mosq/^?o0EGYXu:fai]fOZ\ (c1, k60, u'emoncms').
1530348197: New connection from ::1 on port 1883.
1530348197: Client mosq/^?o0EGYXu:fai]fOZ\ already connected, closing old connection.
1530348197: Client mosq/^?o0EGYXu:fai]fOZ\ disconnected.
1530348197: New client connected from ::1 as mosq/^?o0EGYXu:fai]fOZ\ (c1, k60, u'emoncms').
1530348197: New connection from ::1 on port 1883.
1530348197: Client mosq/^?o0EGYXu:fai]fOZ\ already connected, closing old connection.
1530348197: Client mosq/^?o0EGYXu:fai]fOZ\ disconnected.
1530348197: New client connected from ::1 as mosq/^?o0EGYXu:fai]fOZ\ (c1, k60, u'emoncms').
1530348197: Client mosq/^?o0EGYXu:fai]fOZ\ disconnected.

mqtt

I’ve seen this post - MQTT - too much subscriptions to local broker which doesn’t really come to a conclusion.

Server Information
Emoncms Version 9.8.31 : 2018.06.21
Modules Administration : Dashboard v1.3.0 : EventProcesses : Feed : Input : CoreProcess : Schedule : Time : User : Visualisation
Server OS Linux 4.14.34-v7+
Host raspberrypi raspberrypi (127.0.1.1)
Date 2018-06-30 10:27:06 BST
Uptime 10:27:06 up 12:36, 2 users, load average: 0.20, 0.19, 0.20
HTTP Server Apache/2.4.25 (Raspbian) HTTP/1.1 CGI/1.1 443
MySQL Version 5.5.5-10.1.23-MariaDB-9+deb9u1
Host localhost (127.0.0.1)
Date 2018-06-30 10:27:06 (UTC 01:00‌​)
Stats Uptime: 45408 Threads: 2 Questions: 44282 Slow queries: 0 Opens: 33 Flush tables: 1 Open tables: 27 Queries per second avg: 0.975
Redis Version 3.2.6
Host localhost:6379 (127.0.0.1)
Size 71 keys (693.81K)
Uptime 0 days
MQTT Version 1.4.10
Host localhost:1883 (127.0.0.1)
Pi Model Raspberry Pi 3 Model B Rev 1.2 - 1 GB (Sony UK)
SoC Broadcom BCM2835
Serial num. 60B48D30
Temperature CPU: 50.46°C - GPU: N/A (to show GPU temp execute this command from the console “sudo usermod -G video www-data” )
Memory RAM Used: 53.34% Total: 875.66 MB Used: 467.04 MB Free: 408.62 MB
Swap Used: 0.00% Total: 100 MB Used: 0 B Free: 100 MB
Disk Mount Stats
/ Used: 74.33% Total: 6.86 GB Used: 5.1 GB Free: 1.42 GB
/boot Used: 52.54% Total: 41.15 MB Used: 21.62 MB Free: 19.53 MB
/mnt/data Used: 17.82% Total: 458.49 GB Used: 81.72 GB Free: 376.77 GB
PHP Version 7.0.27-0+deb9u1 (Zend Version 3.0.0)
Modules apache2handler : bz2 v7.0.27-0+deb9u1 : calendar v7.0.27-0+deb9u1 : Core v7.0.27-0+deb9u1 : ctype v7.0.27-0+deb9u1 : curl v7.0.27-0+deb9u1 : date v7.0.27-0+deb9u1 : dio v0.1.0 : dom v20031129 : exif v7.0.27-0+deb9u1 : fileinfo v1.0.5 : filter v7.0.27-0+deb9u1 : ftp v7.0.27-0+deb9u1 : gd v7.0.27-0+deb9u1 : gettext v7.0.27-0+deb9u1 : hash v1.0 : iconv v7.0.27-0+deb9u1 : json v1.4.0 : libxml v7.0.27-0+deb9u1 : mbstring v7.0.27-0+deb9u1 : mcrypt v7.0.27-0+deb9u1 : mosquitto v0.4.0 : mysqli v7.0.27-0+deb9u1 : mysqlnd vmysqlnd 5.0.12-dev - 20150407 - $Id: b5c5906d452ec590732a93b051f3827e02749b83 $ : openssl v7.0.27-0+deb9u1 : pcre v7.0.27-0+deb9u1 : PDO v7.0.27-0+deb9u1 : pdo_mysql v7.0.27-0+deb9u1 : Phar v2.0.2 : posix v7.0.27-0+deb9u1 : readline v7.0.27-0+deb9u1 : redis v3.1.6 : Reflection v7.0.27-0+deb9u1 : session v7.0.27-0+deb9u1 : shmop v7.0.27-0+deb9u1 : SimpleXML v7.0.27-0+deb9u1 : sockets v7.0.27-0+deb9u1 : SPL v7.0.27-0+deb9u1 : standard v7.0.27-0+deb9u1 : sysvmsg v7.0.27-0+deb9u1 : sysvsem v7.0.27-0+deb9u1 : sysvshm v7.0.27-0+deb9u1 : tokenizer v7.0.27-0+deb9u1 : wddx v7.0.27-0+deb9u1 : xml v7.0.27-0+deb9u1 : xmlreader v7.0.27-0+deb9u1 : xmlwriter v7.0.27-0+deb9u1 : xsl v7.0.27-0+deb9u1 : Zend OPcache v7.0.27-0+deb9u1 : zip v1.13.5 : zlib v7.0.27-0+deb9u1

Client Information
HTTP Browser Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36
Screen Resolution 1366 x 768
Window Size 1499 x 748

The publish to mqtt was a quick fix to get MQTT out of emoncms, because it is a process that gets triggered each and every update rather than a single continuous loop, it just tries to connect at each update iteration (publish). It could be that the connection isn’t being closed after each iteration or that overlapping/simultaneous publishes are occurring on separate threads (inputs).

The subscription and publishing parts of emoncms are quite separate and unlikely to influence each other.

That’s the conclusion I came to also.

Yes, but maybe it’s time that MQTT was looked at again @TrystanLea
Although MQTT works… it’s surely not working efficiently if it has to client connect/disconnect before/after every message.

Paul

Agreed, It might be as simple as replacing the “publish to mqtt” process functions code to just add the value to a redis queue using the topic as a key and then adapting the phpmqtt_input.php script to use the existing (subscription) connection to keep checking that queue and just publish any values to the topic (key) as and when they appear, in between processing inputs.

1 Like

I wonder if this is related to @ian’s post Strange Emoncms MQTT publish phenomena (not solved but the reasons understood see https://community.openenergymonitor.org/t/mqtt-log-entries/7784). Looking again at the code, perhaps the process model can reuse the existing mqtt connection started by the phpmqtt_input script or it could start a single publishing client if connect was called in the _construct rather than the publish_to_mqtt method itself:

I will raise as an issue.

Thanks Trystan

Using this configuration;
mqtt
All three processes are trying are trying to connect, publish & disconnect at the same time (or thereabouts) which results in chaos!
In actual fact very few of the mqtt messages get actually sent, sometimes just the diverted, or sometimes diverted & solar, but extremely rarely are all three received.

Paul

Hi

I can confirm the issue reported by @Paul , only noticed this morning.
See Strange Emoncms MQTT publish phenomena (not solved but the reasons understood see https://community.openenergymonitor.org/t/mqtt-log-entries/7784)

Ian

This might be caused by the change in MQTT lib recently.