MQTT log entries

Emoncms
1

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

pi@raspberrypi:~ $ sudo tail -F /var/log/mosquitto/mosquitto.log
1530348187: New connection from ::1 on port 1883.
1530348187: Client mosq/1q\1tBDnbeH\k2@JiL already connected, closing old connection.
1530348187: Client mosq/1q\1tBDnbeH\k2@JiL disconnected.
1530348187: New client connected from ::1 as mosq/1q\1tBDnbeH\k2@JiL (c1, k60, u'emoncms').
1530348187: Client mosq/1q\1tBDnbeH\k2@JiL 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

2

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.

3

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

4

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
5

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.

6

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

7

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

8

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