Emon MQTT data incomplete

Darren · 2019-05-18T14:16:58.113Z

Hi, I recently updated my raspberrypi (self install) that hosts emoncms, since then I have started to lose individual input/feeds in emoncms after a couple of hours of restarting the emonhub service.
It had worked faultlessly for many months before this.

If I subscribe to the MQTT broker looking at emonhub and emon when the inputs aren’t working I get:

pi@raspberrypi:~ $ mosquitto_sub -v -u 'emonpi' -P 'emonpimqtt2016' -t 'emonhub/#'
emonhub/rx/8/values 509,0,0,2,235.39,300,300,300,300,300,300,563425,-35
emonhub/rx/8/values 324,0,0,437,234.26,300,300,300,300,300,300,580618,-36

pi@raspberrypi:~ $ mosquitto_sub -v -u 'emonpi' -P 'emonpimqtt2016' -t 'emon/#'
emon/emontx3/power2 0
emon/emontx3/power3 0
emon/emontx3/power4 435
emon/emontx3/vrms 233.85
emon/emontx3/temp1 300
emon/emontx3/temp2 300
emon/emontx3/temp3 300
emon/emontx3/temp4 300
emon/emontx3/temp5 300
emon/emontx3/temp6 300
emon/emontx3/pulse 580625
emon/emontx3/rssi -36
emon/emontx3/power2 0
emon/emontx3/power3 0
emon/emontx3/power4 433
emon/emontx3/vrms 233.14
emon/emontx3/temp1 300
emon/emontx3/temp2 300
emon/emontx3/temp3 300
emon/emontx3/temp4 300
emon/emontx3/temp5 300
emon/emontx3/temp6 300
emon/emontx3/pulse 580627
emon/emontx3/rssi -37

So the data is there in emonhub, but not in emon (emon/emontx3/power1), which is what I believe emoncms uses.

In the emoncms.log it aappears that the data is published:

2019-05-18 12:57:44,708 DEBUG    RFM2Pi     5426 NEW FRAME : OK 8 94 1 0 0 0 0 179 1 89 91 184 11 184 11 184 11 184 11 184 11 184 11 17 220 8 0 (-36)
2019-05-18 12:57:44,713 DEBUG    RFM2Pi     5426 Timestamp : 1558180664.71
2019-05-18 12:57:44,713 DEBUG    RFM2Pi     5426 From Node : 8
2019-05-18 12:57:44,714 DEBUG    RFM2Pi     5426    Values : [350, 0, 0, 435, 233.85, 300, 300, 300, 300, 300, 300, 580625]
2019-05-18 12:57:44,715 DEBUG    RFM2Pi     5426      RSSI : -36
2019-05-18 12:57:44,715 DEBUG    RFM2Pi     5426 Sent to channel(start)' : ToEmonCMS
2019-05-18 12:57:44,716 DEBUG    RFM2Pi     5426 Sent to channel(end)' : ToEmonCMS
2019-05-18 12:57:44,803 DEBUG    MQTT       Publishing: emon/emontx3/power1 350
2019-05-18 12:57:44,805 DEBUG    MQTT       Publishing: emon/emontx3/power2 0
2019-05-18 12:57:44,808 DEBUG    MQTT       Publishing: emon/emontx3/power3 0
2019-05-18 12:57:44,810 DEBUG    MQTT       Publishing: emon/emontx3/power4 435
2019-05-18 12:57:44,813 DEBUG    MQTT       Publishing: emon/emontx3/vrms 233.85
2019-05-18 12:57:44,815 DEBUG    MQTT       Publishing: emon/emontx3/temp1 300
2019-05-18 12:57:44,818 DEBUG    MQTT       Publishing: emon/emontx3/temp2 300
2019-05-18 12:57:44,820 DEBUG    MQTT       Publishing: emon/emontx3/temp3 300
2019-05-18 12:57:44,823 DEBUG    MQTT       Publishing: emon/emontx3/temp4 300
2019-05-18 12:57:44,825 DEBUG    MQTT       Publishing: emon/emontx3/temp5 300
2019-05-18 12:57:44,828 DEBUG    MQTT       Publishing: emon/emontx3/temp6 300
2019-05-18 12:57:44,830 DEBUG    MQTT       Publishing: emon/emontx3/pulse 580625
2019-05-18 12:57:44,833 DEBUG    MQTT       Publishing: emon/emontx3/rssi -36
2019-05-18 12:57:44,835 INFO     MQTT       Publishing: emonhub/rx/8/values 350,0,0,435,233.85,300,300,300,300,300,300,580625,-36
2019-05-18 12:57:47,560 DEBUG    emoncmsorg Buffer size: 3
2019-05-18 12:57:54,596 DEBUG    RFM2Pi     5427 NEW FRAME : OK 8 162 0 0 0 0 0 177 1 18 91 184 11 184 11 184 11 184 11 184 11 184 11 19 220 8 0 (-37)
2019-05-18 12:57:54,603 DEBUG    RFM2Pi     5427 Timestamp : 1558180674.6
2019-05-18 12:57:54,604 DEBUG    RFM2Pi     5427 From Node : 8
2019-05-18 12:57:54,606 DEBUG    RFM2Pi     5427    Values : [162, 0, 0, 433, 233.14000000000001, 300, 300, 300, 300, 300, 300, 580627]
2019-05-18 12:57:54,607 DEBUG    RFM2Pi     5427      RSSI : -37
2019-05-18 12:57:54,608 DEBUG    RFM2Pi     5427 Sent to channel(start)' : ToEmonCMS
2019-05-18 12:57:54,609 DEBUG    RFM2Pi     5427 Sent to channel(end)' : ToEmonCMS
2019-05-18 12:57:54,720 DEBUG    MQTT       Publishing: emon/emontx3/power1 162
2019-05-18 12:57:54,726 DEBUG    MQTT       Publishing: emon/emontx3/power2 0
2019-05-18 12:57:54,733 DEBUG    MQTT       Publishing: emon/emontx3/power3 0
2019-05-18 12:57:54,740 DEBUG    MQTT       Publishing: emon/emontx3/power4 433
2019-05-18 12:57:54,747 DEBUG    MQTT       Publishing: emon/emontx3/vrms 233.14
2019-05-18 12:57:54,753 DEBUG    MQTT       Publishing: emon/emontx3/temp1 300
2019-05-18 12:57:54,760 DEBUG    MQTT       Publishing: emon/emontx3/temp2 300
2019-05-18 12:57:54,763 DEBUG    MQTT       Publishing: emon/emontx3/temp3 300
2019-05-18 12:57:54,766 DEBUG    MQTT       Publishing: emon/emontx3/temp4 300
2019-05-18 12:57:54,769 DEBUG    MQTT       Publishing: emon/emontx3/temp5 300
2019-05-18 12:57:54,772 DEBUG    MQTT       Publishing: emon/emontx3/temp6 300
2019-05-18 12:57:54,776 DEBUG    MQTT       Publishing: emon/emontx3/pulse 580627
2019-05-18 12:57:54,778 DEBUG    MQTT       Publishing: emon/emontx3/rssi -37
2019-05-18 12:57:54,781 INFO     MQTT       Publishing: emonhub/rx/8/values 162,0,0,433,233.14,300,300,300,300,300,300,580627,-37
2019-05-18 12:57:57,106 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 27 225 253 189 83 250 7 255 41 237 249 195 215 111 182 83 155 222 255 245 151 (-95)
2019-05-18 12:57:57,759 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 31 215 199 166 255 63 194 118 247 22 94 59 171 119 249 147 123 221 84 239 237 (-90)

If I restart emonhub the inputs and feeds update correctly again and emon/emontx3/power1 is present.

Any ideas why the MQTT emon data is incomplete?

Thanks

Darren

borpin · 2019-05-18T21:15:35.321Z

First question, when it isn’t working, is the log folder full. Do

df -h

and if any of the mounts show 100% that may be the issue (unlikely though).

Anything in the mosquitto log?


/var/log/mosquitto/mosquitto.log`

Darren:

If I restart emonhub the inputs and feeds update correctly again and emon/emontx3/power1 is present.

Do you just restart emonhub to make it all work again?

Could you go into the admin screen and next to server information click on copy as markdown (or copy to clipboard) then paste that here please.

Darren · 2019-05-18T22:44:59.878Z

It’s currently all working at the moment, and the df -h looks like:

pi@raspberrypi:~ $ df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/root       917G  8.0G  862G   1% /
devtmpfs        425M     0  425M   0% /dev
tmpfs           430M     0  430M   0% /dev/shm
tmpfs           430M   17M  413M   4% /run
tmpfs           5.0M  4.0K  5.0M   1% /run/lock
tmpfs           430M     0  430M   0% /sys/fs/cgroup
/dev/mmcblk0p6   68M   23M   46M  33% /boot
tmpfs            86M     0   86M   0% /run/user/1000

I don’t think it’s much different when it’s not working. I’ll post an update later.

In /var/log/mosquitto/mosquitto.log I have many warnings like:

1558217088: Warning: Received PUBREL from 3A622A34-1351-AFEB-8806-6D0B8EAA02C7 for an unknown packet identifier 49701.
1558217097: Warning: Received PUBREL from 3A622A34-1351-AFEB-8806-6D0B8EAA02C7 for an unknown packet identifier 49715.
1558217108: Warning: Received PUBREL from 3A622A34-1351-AFEB-8806-6D0B8EAA02C7 for an unknown packet identifier 49729.
1558217117: Warning: Received PUBREL from 3A622A34-1351-AFEB-8806-6D0B8EAA02C7 for an unknown packet identifier 49743.

but these also occur when everything is working.

I’m now questioning myself whether a restart of just the emonhub service is all it takes to get it working again, but I’m sure I’ve just pressed the ‘Restart’ button on the EmonHub page to get it working. I’ll let you know.

As requested, here is the server information.

Server Information

Services

emonhub :- Active Running
emoncms_mqtt :- Active Running
feedwriter :- Inactive DeadService is not runningloading…
service-runner :- Active Running
redis-server :- Active Running
mosquitto :- Active Running

Emoncms

Version :- 10.0.2-beta
Modules :- Administration | App v2.0.0 | Backup v2.0.0 | EmonHub Config v2.0.0 | Dashboard v2.0.1 | Device v2.0.0 | EventProcesses | Feed | Graph v2.0.0 | Input | Postprocess v2.0.0 | CoreProcess | Schedule | sync | Time | User | Visualisation
Git :-
- URL :- GitHub - emoncms/emoncms: Web-app for processing, logging and visualising energy, temperature and other environmental data
- Branch :- * master
- Describe :- 9.9.9-162-g4b7ec56f

Server

OS :- Linux 4.19.42-v7+
Host :- raspberrypi | raspberrypi | (192.168.1.31)
Date :- 2019-05-18 23:03:15 BST
Uptime :- 23:03:15 up 1 day, 1:05, 2 users, load average: 0.44, 0.36, 0.35

Memory

RAM :- Used: 24.49%
- Total :- 858.68 MB
- Used :- 210.27 MB
- Free :- 648.41 MB
Swap :- Used: 0.00%
- Total :- 1024 MB
- Used :- 0 B
- Free :- 1024 MB

Disk

/ :- Used: 0.86%
- Total :- 916.39 GB
- Used :- 7.91 GB
- Free :- 861.89 GB
/boot :- Used: 32.62%
- Total :- 67.92 MB
- Used :- 22.16 MB
- Free :- 45.77 MB

HTTP

Server :- Apache/2.4.25 (Raspbian) HTTP/1.1 CGI/1.1 80

MySQL

Version :- 5.5.5-10.1.38-MariaDB-0+deb9u1
Host :- localhost:6379 (127.0.0.1)
Date :- 2019-05-18 22:03:14 (UTC 00:00‌)
Stats :- Uptime: 90317 Threads: 2 Questions: 96514 Slow queries: 0 Opens: 23 Flush tables: 1 Open tables: 17 Queries per second avg: 1.068

Redis

Version :- 3.2.6
Host :- localhost:6379
Size :- 95 keys (741.60K)
Uptime :- 1 days

MQTT Server

Version :- Mosquitto 1.6.2
Host :- localhost:1883 (127.0.0.1)

PHP

Version :- 7.0.33-0+deb9u3 (Zend Version 3.0.0)
Modules :- apache2handler | calendar v7.0.33-0+deb9u3 | Core v7.0.33-0+deb9u3 | ctype v7.0.33-0+deb9u3 | curl v7.0.33-0+deb9u3 | date v7.0.33-0+deb9u3 | dio v0.1.0 | dom v20031129 | exif v7.0.33-0+deb9u3 | fileinfo v1.0.5 | filter v7.0.33-0+deb9u3 | ftp v7.0.33-0+deb9u3 | gd v7.0.33-0+deb9u3 | gettext v7.0.33-0+deb9u3 | hash v1.0 | iconv v7.0.33-0+deb9u3 | igbinary v2.0.1 | json v1.4.0 | libxml v7.0.33-0+deb9u3 | mbstring v7.0.33-0+deb9u3 | mcrypt v7.0.33-0+deb9u3 | mosquitto v0.4.0 | mysqli v7.0.33-0+deb9u3 | mysqlnd vmysqlnd 5.0.12-dev - 20150407 - $Id: b5c5906d452ec590732a93b051f3827e02749b83 $ | openssl v7.0.33-0+deb9u3 | pcre v7.0.33-0+deb9u3 | PDO v7.0.33-0+deb9u3 | pdo_mysql v7.0.33-0+deb9u3 | Phar v2.0.2 | posix v7.0.33-0+deb9u3 | readline v7.0.33-0+deb9u3 | redis v3.1.1 | Reflection v7.0.33-0+deb9u3 | session v7.0.33-0+deb9u3 | shmop v7.0.33-0+deb9u3 | SimpleXML v7.0.33-0+deb9u3 | sockets v7.0.33-0+deb9u3 | SPL v7.0.33-0+deb9u3 | standard v7.0.33-0+deb9u3 | sysvmsg v7.0.33-0+deb9u3 | sysvsem v7.0.33-0+deb9u3 | sysvshm v7.0.33-0+deb9u3 | tokenizer v7.0.33-0+deb9u3 | wddx v7.0.33-0+deb9u3 | xml v7.0.33-0+deb9u3 | xmlreader v7.0.33-0+deb9u3 | xmlwriter v7.0.33-0+deb9u3 | xsl v7.0.33-0+deb9u3 | Zend OPcache v7.0.33-0+deb9u3 | zlib v7.0.33-0+deb9u3

Pi

Model :- Raspberry Pi 2 Model B Rev 1.1 - 1 GB (Sony UK)
SoC :- Broadcom BCM2835
Serial num. :- F48BB43A
Temperature :- 42.24°C - 42.2°C
emonpiRelease :- - File-system :- read-only

Client Information

HTTP

Browser :- Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:66.0) Gecko/20100101 Firefox/66.0
Language :- en-GB,en;q=0.5

Window

Size :- 1903 x 1036

Screen

Resolution :- 1920 x 1200

borpin · 2019-05-19T08:50:34.732Z

Darren:

feedwriter :- Inactive DeadService is not running

I note that feedwriter is not running but Redis is installed. Is this deliberate? If running on an SD card this increases the likelihood of SD card failure. However, I think you are running on a HDD (judging by the free size of /).

Change the emoncms logging level to DEBUG and see if there are any messages there when it fails.

The only other suggestion is to run mosquitto_sub with -d and leave an SSH window open so you can see if there are any messages when it fails.

It is odd.

Darren · 2019-05-19T10:47:15.108Z

Thanks for you help.

Yes, not using feedwriter is deliberate. As I’m running on a HDD I haven’t enabled any of the low write mode options.

I have changed the logging to 1:INFO (I couldn’t find a DEBUG option) and started a terminal with mosquitto_sub -d -v -u 'emonpi' -P 'emonpimqtt2016' -t 'emon/#'.

I’ll update when it fails.

Do you have any ideas regarding the warnings in /var/log/mosquitto/mosquitto.log? A quick google search didn’t point me in any particular direction to investigate further. Maybe, I should look a bit longer.

borpin · 2019-05-19T14:17:22.917Z

Darren:

mosquitto_sub -d -v -u 'emonpi' -P 'emonpimqtt2016' -t 'emon/#' .

I’d just do it on the topic in question, it will be more obvious when it fails.

Darren · 2019-05-19T16:27:17.396Z

Thanks for the tip. I’ll try it next time.

Going back to your previous question, just restarting the emonhub service makes it all work again.

It failed again around 14:41.

The mosquitto_sub output around that time, just stopped logging the power1 data, there were no errors

Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power1', ... (4 bytes))
emon/emontx3/power1 -208
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power2', ... (1 bytes))
emon/emontx3/power2 0
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power3', ... (1 bytes))
emon/emontx3/power3 0
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power4', ... (3 bytes))
emon/emontx3/power4 702
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/vrms', ... (6 bytes))
emon/emontx3/vrms 234.98
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp1', ... (3 bytes))
emon/emontx3/temp1 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp2', ... (3 bytes))
emon/emontx3/temp2 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp3', ... (3 bytes))
emon/emontx3/temp3 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp4', ... (3 bytes))
emon/emontx3/temp4 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp5', ... (3 bytes))
emon/emontx3/temp5 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp6', ... (3 bytes))
emon/emontx3/temp6 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/pulse', ... (6 bytes))
emon/emontx3/pulse 624645
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/rssi', ... (3 bytes))
emon/emontx3/rssi -35
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power1', ... (4 bytes))
emon/emontx3/power1 -265
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power2', ... (1 bytes))
emon/emontx3/power2 0
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power3', ... (1 bytes))
emon/emontx3/power3 0
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power4', ... (3 bytes))
emon/emontx3/power4 693
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/vrms', ... (6 bytes))
emon/emontx3/vrms 235.11
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp1', ... (3 bytes))
emon/emontx3/temp1 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp2', ... (3 bytes))
emon/emontx3/temp2 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp3', ... (3 bytes))
emon/emontx3/temp3 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp4', ... (3 bytes))
emon/emontx3/temp4 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp5', ... (3 bytes))
emon/emontx3/temp5 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp6', ... (3 bytes))
emon/emontx3/temp6 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/pulse', ... (6 bytes))
emon/emontx3/pulse 624645
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/rssi', ... (3 bytes))
emon/emontx3/rssi -36
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power2', ... (1 bytes))
emon/emontx3/power2 0
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power3', ... (1 bytes))
emon/emontx3/power3 0
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power4', ... (3 bytes))
emon/emontx3/power4 681
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/vrms', ... (6 bytes))
emon/emontx3/vrms 234.84
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp1', ... (3 bytes))
emon/emontx3/temp1 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp2', ... (3 bytes))
emon/emontx3/temp2 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp3', ... (3 bytes))
emon/emontx3/temp3 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp4', ... (3 bytes))
emon/emontx3/temp4 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp5', ... (3 bytes))
emon/emontx3/temp5 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp6', ... (3 bytes))
emon/emontx3/temp6 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/pulse', ... (6 bytes))
emon/emontx3/pulse 624645
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/rssi', ... (3 bytes))
emon/emontx3/rssi -35
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power2', ... (1 bytes))
emon/emontx3/power2 0
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power3', ... (1 bytes))
emon/emontx3/power3 0
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/power4', ... (3 bytes))
emon/emontx3/power4 675
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/vrms', ... (5 bytes))
emon/emontx3/vrms 235.2
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp1', ... (3 bytes))
emon/emontx3/temp1 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp2', ... (3 bytes))
emon/emontx3/temp2 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp3', ... (3 bytes))
emon/emontx3/temp3 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp4', ... (3 bytes))
emon/emontx3/temp4 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp5', ... (3 bytes))
emon/emontx3/temp5 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/temp6', ... (3 bytes))
emon/emontx3/temp6 300
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/pulse', ... (6 bytes))
emon/emontx3/pulse 624645
Client mosq/axHA4VTQqsB2ZQ8efv received PUBLISH (d0, q0, r0, m0, 'emon/emontx3/rssi', ... (3 bytes))
emon/emontx3/rssi -36
Client mosq/axHA4VTQqsB2ZQ8efv sending PINGREQ
Client mosq/axHA4VTQqsB2ZQ8efv received PINGRESP

My untrained eye can’t see anything in the emoncms.log around then either.

2019-05-19 13:40:38.388|INFO|index.php|input/post
2019-05-19 13:40:38.427|INFO|index.php|input/post
2019-05-19 13:40:38.443|INFO|feed_model.php|insert_data() feedid=20 updatetime=1558273238 feedtime=1558273238 value=651 arg=
2019-05-19 13:40:38.444|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:40:38.445|INFO|PHPFina.php|post() id=20 timestamp=1558273238 value=651 padding=
2019-05-19 13:40:38.448|INFO|process_processlist.php|power_to_kwh() feedid=21 last_kwh=8134.0217635915 kwh_inc=0.00217 new_kwh=8134.0239335915 last_time=1558273226 time_now=1558273238
2019-05-19 13:40:38.448|INFO|feed_model.php|insert_data() feedid=21 updatetime=1558273238 feedtime=1558273238 value=8134.0239335915 arg=join
2019-05-19 13:40:38.449|INFO|PHPFina.php|post() id=21 timestamp=1558273238 value=8134.0239335915 padding=join
2019-05-19 13:40:38.451|INFO|feed_model.php|insert_data() feedid=22 updatetime=1558273238 feedtime=1558273238 value=0 arg=
2019-05-19 13:40:38.452|INFO|PHPFina.php|post() id=22 timestamp=1558273238 value=0 padding=
2019-05-19 13:40:38.454|INFO|process_processlist.php|power_to_kwh() feedid=23 last_kwh=5700.969026205 kwh_inc=0 new_kwh=5700.969026205 last_time=1558273226 time_now=1558273238
2019-05-19 13:40:38.454|INFO|feed_model.php|insert_data() feedid=23 updatetime=1558273238 feedtime=1558273238 value=5700.969026205 arg=join
2019-05-19 13:40:38.455|INFO|PHPFina.php|post() id=23 timestamp=1558273238 value=5700.969026205 padding=join
2019-05-19 13:40:38.480|INFO|index.php|input/post
2019-05-19 13:40:39.358|INFO|index.php|input/post
2019-05-19 13:40:39.372|INFO|feed_model.php|insert_data() feedid=24 updatetime=1558273239 feedtime=1558273239 value=676 arg=
2019-05-19 13:40:39.373|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:40:39.374|INFO|PHPFina.php|post() id=24 timestamp=1558273239 value=676 padding=
2019-05-19 13:40:39.376|INFO|process_processlist.php|power_to_kwh() feedid=25 last_kwh=4839.2179388633 kwh_inc=0.0022533333333333 new_kwh=4839.2201921966 last_time=1558273227 time_now=1558273239
2019-05-19 13:40:39.377|INFO|feed_model.php|insert_data() feedid=25 updatetime=1558273239 feedtime=1558273239 value=4839.2201921966 arg=join
2019-05-19 13:40:39.377|INFO|PHPFina.php|post() id=25 timestamp=1558273239 value=4839.2201921966 padding=join
2019-05-19 13:40:39.403|INFO|index.php|input/post
2019-05-19 13:40:50.388|INFO|index.php|input/post
2019-05-19 13:40:50.427|INFO|index.php|input/post
2019-05-19 13:40:50.443|INFO|feed_model.php|insert_data() feedid=20 updatetime=1558273250 feedtime=1558273250 value=634 arg=
2019-05-19 13:40:50.444|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:40:50.445|INFO|PHPFina.php|post() id=20 timestamp=1558273250 value=634 padding=
2019-05-19 13:40:50.448|INFO|process_processlist.php|power_to_kwh() feedid=21 last_kwh=8134.0239335915 kwh_inc=0.0021133333333333 new_kwh=8134.0260469248 last_time=1558273238 time_now=1558273250
2019-05-19 13:40:50.448|INFO|feed_model.php|insert_data() feedid=21 updatetime=1558273250 feedtime=1558273250 value=8134.0260469248 arg=join
2019-05-19 13:40:50.449|INFO|PHPFina.php|post() id=21 timestamp=1558273250 value=8134.0260469248 padding=join
2019-05-19 13:40:50.451|INFO|feed_model.php|insert_data() feedid=22 updatetime=1558273250 feedtime=1558273250 value=0 arg=
2019-05-19 13:40:50.452|INFO|PHPFina.php|post() id=22 timestamp=1558273250 value=0 padding=
2019-05-19 13:40:50.455|INFO|process_processlist.php|power_to_kwh() feedid=23 last_kwh=5700.969026205 kwh_inc=0 new_kwh=5700.969026205 last_time=1558273238 time_now=1558273250
2019-05-19 13:40:50.456|INFO|feed_model.php|insert_data() feedid=23 updatetime=1558273250 feedtime=1558273250 value=5700.969026205 arg=join
2019-05-19 13:40:50.456|INFO|PHPFina.php|post() id=23 timestamp=1558273250 value=5700.969026205 padding=join
2019-05-19 13:40:50.482|INFO|index.php|input/post
2019-05-19 13:40:51.354|INFO|index.php|input/post
2019-05-19 13:40:51.369|INFO|feed_model.php|insert_data() feedid=24 updatetime=1558273251 feedtime=1558273251 value=676 arg=
2019-05-19 13:40:51.372|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:40:51.373|INFO|PHPFina.php|post() id=24 timestamp=1558273251 value=676 padding=
2019-05-19 13:40:51.375|INFO|process_processlist.php|power_to_kwh() feedid=25 last_kwh=4839.2201921966 kwh_inc=0.0022533333333333 new_kwh=4839.2224455299 last_time=1558273239 time_now=1558273251
2019-05-19 13:40:51.376|INFO|feed_model.php|insert_data() feedid=25 updatetime=1558273251 feedtime=1558273251 value=4839.2224455299 arg=join
2019-05-19 13:40:51.376|INFO|PHPFina.php|post() id=25 timestamp=1558273251 value=4839.2224455299 padding=join
2019-05-19 13:40:51.402|INFO|index.php|input/post
2019-05-19 13:41:14.396|INFO|index.php|input/post
2019-05-19 13:41:14.453|INFO|index.php|input/post
2019-05-19 13:41:14.469|INFO|feed_model.php|insert_data() feedid=20 updatetime=1558273274 feedtime=1558273274 value=705 arg=
2019-05-19 13:41:14.471|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:41:14.471|INFO|PHPFina.php|post() id=20 timestamp=1558273274 value=705 padding=
2019-05-19 13:41:14.474|INFO|process_processlist.php|power_to_kwh() feedid=21 last_kwh=8134.0260469248 kwh_inc=0.0047 new_kwh=8134.0307469248 last_time=1558273250 time_now=1558273274
2019-05-19 13:41:14.475|INFO|feed_model.php|insert_data() feedid=21 updatetime=1558273274 feedtime=1558273274 value=8134.0307469248 arg=join
2019-05-19 13:41:14.475|INFO|PHPFina.php|post() id=21 timestamp=1558273274 value=8134.0307469248 padding=join
2019-05-19 13:41:14.477|INFO|feed_model.php|insert_data() feedid=22 updatetime=1558273274 feedtime=1558273274 value=29 arg=
2019-05-19 13:41:14.478|INFO|PHPFina.php|post() id=22 timestamp=1558273274 value=29 padding=
2019-05-19 13:41:14.481|INFO|process_processlist.php|power_to_kwh() feedid=23 last_kwh=5700.969026205 kwh_inc=0.00019333333333333 new_kwh=5700.9692195383 last_time=1558273250 time_now=1558273274
2019-05-19 13:41:14.482|INFO|feed_model.php|insert_data() feedid=23 updatetime=1558273274 feedtime=1558273274 value=5700.9692195383 arg=join
2019-05-19 13:41:14.482|INFO|PHPFina.php|post() id=23 timestamp=1558273274 value=5700.9692195383 padding=join
2019-05-19 13:41:14.511|INFO|index.php|input/post
2019-05-19 13:41:15.363|INFO|index.php|input/post
2019-05-19 13:41:15.382|INFO|feed_model.php|insert_data() feedid=24 updatetime=1558273275 feedtime=1558273275 value=660 arg=
2019-05-19 13:41:15.384|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:41:15.385|INFO|PHPFina.php|post() id=24 timestamp=1558273275 value=660 padding=
2019-05-19 13:41:15.389|INFO|process_processlist.php|power_to_kwh() feedid=25 last_kwh=4839.2224455299 kwh_inc=0.0044 new_kwh=4839.2268455299 last_time=1558273251 time_now=1558273275
2019-05-19 13:41:15.389|INFO|feed_model.php|insert_data() feedid=25 updatetime=1558273275 feedtime=1558273275 value=4839.2268455299 arg=join
2019-05-19 13:41:15.390|INFO|PHPFina.php|post() id=25 timestamp=1558273275 value=4839.2268455299 padding=join
2019-05-19 13:41:15.427|INFO|index.php|input/post
2019-05-19 13:41:26.397|INFO|index.php|input/post
2019-05-19 13:41:26.450|INFO|index.php|input/post
2019-05-19 13:41:26.471|INFO|feed_model.php|insert_data() feedid=20 updatetime=1558273286 feedtime=1558273286 value=598 arg=
2019-05-19 13:41:26.473|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:41:26.473|INFO|PHPFina.php|post() id=20 timestamp=1558273286 value=598 padding=
2019-05-19 13:41:26.477|INFO|process_processlist.php|power_to_kwh() feedid=21 last_kwh=8134.0307469248 kwh_inc=0.0019933333333333 new_kwh=8134.0327402581 last_time=1558273274 time_now=1558273286
2019-05-19 13:41:26.478|INFO|feed_model.php|insert_data() feedid=21 updatetime=1558273286 feedtime=1558273286 value=8134.0327402581 arg=join
2019-05-19 13:41:26.479|INFO|PHPFina.php|post() id=21 timestamp=1558273286 value=8134.0327402581 padding=join
2019-05-19 13:41:26.482|INFO|feed_model.php|insert_data() feedid=22 updatetime=1558273286 feedtime=1558273286 value=0 arg=
2019-05-19 13:41:26.483|INFO|PHPFina.php|post() id=22 timestamp=1558273286 value=0 padding=
2019-05-19 13:41:26.489|INFO|process_processlist.php|power_to_kwh() feedid=23 last_kwh=5700.9692195383 kwh_inc=0 new_kwh=5700.9692195383 last_time=1558273274 time_now=1558273286
2019-05-19 13:41:26.490|INFO|feed_model.php|insert_data() feedid=23 updatetime=1558273286 feedtime=1558273286 value=5700.9692195383 arg=join
2019-05-19 13:41:26.490|INFO|PHPFina.php|post() id=23 timestamp=1558273286 value=5700.9692195383 padding=join
2019-05-19 13:41:26.526|INFO|index.php|input/post
2019-05-19 13:41:27.362|INFO|index.php|input/post
2019-05-19 13:41:27.384|INFO|feed_model.php|insert_data() feedid=24 updatetime=1558273287 feedtime=1558273287 value=644 arg=
2019-05-19 13:41:27.386|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:41:27.386|INFO|PHPFina.php|post() id=24 timestamp=1558273287 value=644 padding=
2019-05-19 13:41:27.391|INFO|process_processlist.php|power_to_kwh() feedid=25 last_kwh=4839.2268455299 kwh_inc=0.0021466666666667 new_kwh=4839.2289921966 last_time=1558273275 time_now=1558273287
2019-05-19 13:41:27.392|INFO|feed_model.php|insert_data() feedid=25 updatetime=1558273287 feedtime=1558273287 value=4839.2289921966 arg=join
2019-05-19 13:41:27.392|INFO|PHPFina.php|post() id=25 timestamp=1558273287 value=4839.2289921966 padding=join
2019-05-19 13:41:27.427|INFO|index.php|input/post
2019-05-19 13:41:38.389|INFO|index.php|input/post
2019-05-19 13:41:38.427|INFO|index.php|input/post
2019-05-19 13:41:38.442|INFO|feed_model.php|insert_data() feedid=20 updatetime=1558273298 feedtime=1558273298 value=634 arg=
2019-05-19 13:41:38.444|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:41:38.444|INFO|PHPFina.php|post() id=20 timestamp=1558273298 value=634 padding=
2019-05-19 13:41:38.446|INFO|process_processlist.php|power_to_kwh() feedid=21 last_kwh=8134.0327402581 kwh_inc=0.0021133333333333 new_kwh=8134.0348535914 last_time=1558273286 time_now=1558273298
2019-05-19 13:41:38.447|INFO|feed_model.php|insert_data() feedid=21 updatetime=1558273298 feedtime=1558273298 value=8134.0348535914 arg=join
2019-05-19 13:41:38.447|INFO|PHPFina.php|post() id=21 timestamp=1558273298 value=8134.0348535914 padding=join
2019-05-19 13:41:38.449|INFO|feed_model.php|insert_data() feedid=22 updatetime=1558273298 feedtime=1558273298 value=0 arg=
2019-05-19 13:41:38.450|INFO|PHPFina.php|post() id=22 timestamp=1558273298 value=0 padding=
2019-05-19 13:41:38.452|INFO|process_processlist.php|power_to_kwh() feedid=23 last_kwh=5700.9692195383 kwh_inc=0 new_kwh=5700.9692195383 last_time=1558273286 time_now=1558273298
2019-05-19 13:41:38.453|INFO|feed_model.php|insert_data() feedid=23 updatetime=1558273298 feedtime=1558273298 value=5700.9692195383 arg=join
2019-05-19 13:41:38.453|INFO|PHPFina.php|post() id=23 timestamp=1558273298 value=5700.9692195383 padding=join
2019-05-19 13:41:38.479|INFO|index.php|input/post
2019-05-19 13:41:39.365|INFO|index.php|input/post
2019-05-19 13:41:39.386|INFO|feed_model.php|insert_data() feedid=24 updatetime=1558273299 feedtime=1558273299 value=644 arg=
2019-05-19 13:41:39.389|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:41:39.389|INFO|PHPFina.php|post() id=24 timestamp=1558273299 value=644 padding=
2019-05-19 13:41:39.393|INFO|process_processlist.php|power_to_kwh() feedid=25 last_kwh=4839.2289921966 kwh_inc=0.0021466666666667 new_kwh=4839.2311388633 last_time=1558273287 time_now=1558273299
2019-05-19 13:41:39.394|INFO|feed_model.php|insert_data() feedid=25 updatetime=1558273299 feedtime=1558273299 value=4839.2311388633 arg=join
2019-05-19 13:41:39.395|INFO|PHPFina.php|post() id=25 timestamp=1558273299 value=4839.2311388633 padding=join
2019-05-19 13:41:39.433|INFO|index.php|input/post
2019-05-19 13:41:50.397|INFO|index.php|input/post
2019-05-19 13:41:50.450|INFO|index.php|input/post
2019-05-19 13:41:50.469|INFO|feed_model.php|insert_data() feedid=20 updatetime=1558273310 feedtime=1558273310 value=705 arg=
2019-05-19 13:41:50.471|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:41:50.472|INFO|PHPFina.php|post() id=20 timestamp=1558273310 value=705 padding=
2019-05-19 13:41:50.475|INFO|process_processlist.php|power_to_kwh() feedid=21 last_kwh=8134.0348535914 kwh_inc=0.00235 new_kwh=8134.0372035914 last_time=1558273298 time_now=1558273310
2019-05-19 13:41:50.476|INFO|feed_model.php|insert_data() feedid=21 updatetime=1558273310 feedtime=1558273310 value=8134.0372035914 arg=join
2019-05-19 13:41:50.476|INFO|PHPFina.php|post() id=21 timestamp=1558273310 value=8134.0372035914 padding=join
2019-05-19 13:41:50.479|INFO|feed_model.php|insert_data() feedid=22 updatetime=1558273310 feedtime=1558273310 value=61 arg=
2019-05-19 13:41:50.481|INFO|PHPFina.php|post() id=22 timestamp=1558273310 value=61 padding=
2019-05-19 13:41:50.484|INFO|process_processlist.php|power_to_kwh() feedid=23 last_kwh=5700.9692195383 kwh_inc=0.00020333333333333 new_kwh=5700.9694228716 last_time=1558273298 time_now=1558273310
2019-05-19 13:41:50.485|INFO|feed_model.php|insert_data() feedid=23 updatetime=1558273310 feedtime=1558273310 value=5700.9694228716 arg=join
2019-05-19 13:41:50.485|INFO|PHPFina.php|post() id=23 timestamp=1558273310 value=5700.9694228716 padding=join
2019-05-19 13:41:50.524|INFO|index.php|input/post
2019-05-19 13:41:51.366|INFO|index.php|input/post
2019-05-19 13:41:51.386|INFO|feed_model.php|insert_data() feedid=24 updatetime=1558273311 feedtime=1558273311 value=628 arg=
2019-05-19 13:41:51.388|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:41:51.389|INFO|PHPFina.php|post() id=24 timestamp=1558273311 value=628 padding=
2019-05-19 13:41:51.393|INFO|process_processlist.php|power_to_kwh() feedid=25 last_kwh=4839.2311388633 kwh_inc=0.0020933333333333 new_kwh=4839.2332321966 last_time=1558273299 time_now=1558273311
2019-05-19 13:41:51.394|INFO|feed_model.php|insert_data() feedid=25 updatetime=1558273311 feedtime=1558273311 value=4839.2332321966 arg=join
2019-05-19 13:41:51.394|INFO|PHPFina.php|post() id=25 timestamp=1558273311 value=4839.2332321966 padding=join
2019-05-19 13:41:51.429|INFO|index.php|input/post
2019-05-19 13:42:14.398|INFO|index.php|input/post
2019-05-19 13:42:14.455|INFO|index.php|input/post
2019-05-19 13:42:14.475|INFO|feed_model.php|insert_data() feedid=20 updatetime=1558273334 feedtime=1558273334 value=634 arg=
2019-05-19 13:42:14.477|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:42:14.477|INFO|PHPFina.php|post() id=20 timestamp=1558273334 value=634 padding=
2019-05-19 13:42:14.481|INFO|process_processlist.php|power_to_kwh() feedid=21 last_kwh=8134.0372035914 kwh_inc=0.0042266666666667 new_kwh=8134.0414302581 last_time=1558273310 time_now=1558273334
2019-05-19 13:42:14.482|INFO|feed_model.php|insert_data() feedid=21 updatetime=1558273334 feedtime=1558273334 value=8134.0414302581 arg=join
2019-05-19 13:42:14.482|INFO|PHPFina.php|post() id=21 timestamp=1558273334 value=8134.0414302581 padding=join
2019-05-19 13:42:14.485|INFO|feed_model.php|insert_data() feedid=22 updatetime=1558273334 feedtime=1558273334 value=6 arg=
2019-05-19 13:42:14.486|INFO|PHPFina.php|post() id=22 timestamp=1558273334 value=6 padding=
2019-05-19 13:42:14.490|INFO|process_processlist.php|power_to_kwh() feedid=23 last_kwh=5700.9694228716 kwh_inc=4.0E-5 new_kwh=5700.9694628716 last_time=1558273310 time_now=1558273334
2019-05-19 13:42:14.490|INFO|feed_model.php|insert_data() feedid=23 updatetime=1558273334 feedtime=1558273334 value=5700.9694628716 arg=join
2019-05-19 13:42:14.491|INFO|PHPFina.php|post() id=23 timestamp=1558273334 value=5700.9694628716 padding=join
2019-05-19 13:42:14.525|INFO|index.php|input/post
2019-05-19 13:42:15.365|INFO|index.php|input/post
2019-05-19 13:42:15.384|INFO|feed_model.php|insert_data() feedid=24 updatetime=1558273335 feedtime=1558273335 value=612 arg=
2019-05-19 13:42:15.386|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:42:15.387|INFO|PHPFina.php|post() id=24 timestamp=1558273335 value=612 padding=
2019-05-19 13:42:15.391|INFO|process_processlist.php|power_to_kwh() feedid=25 last_kwh=4839.2332321966 kwh_inc=0.00408 new_kwh=4839.2373121966 last_time=1558273311 time_now=1558273335
2019-05-19 13:42:15.391|INFO|feed_model.php|insert_data() feedid=25 updatetime=1558273335 feedtime=1558273335 value=4839.2373121966 arg=join
2019-05-19 13:42:15.392|INFO|PHPFina.php|post() id=25 timestamp=1558273335 value=4839.2373121966 padding=join
2019-05-19 13:42:15.428|INFO|index.php|input/post
2019-05-19 13:42:26.400|INFO|index.php|input/post
2019-05-19 13:42:26.454|INFO|index.php|input/post
2019-05-19 13:42:26.474|INFO|feed_model.php|insert_data() feedid=20 updatetime=1558273346 feedtime=1558273346 value=669 arg=
2019-05-19 13:42:26.476|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:42:26.477|INFO|PHPFina.php|post() id=20 timestamp=1558273346 value=669 padding=
2019-05-19 13:42:26.481|INFO|process_processlist.php|power_to_kwh() feedid=21 last_kwh=8134.0414302581 kwh_inc=0.00223 new_kwh=8134.0436602581 last_time=1558273334 time_now=1558273346
2019-05-19 13:42:26.482|INFO|feed_model.php|insert_data() feedid=21 updatetime=1558273346 feedtime=1558273346 value=8134.0436602581 arg=join
2019-05-19 13:42:26.482|INFO|PHPFina.php|post() id=21 timestamp=1558273346 value=8134.0436602581 padding=join
2019-05-19 13:42:26.484|INFO|feed_model.php|insert_data() feedid=22 updatetime=1558273346 feedtime=1558273346 value=57 arg=
2019-05-19 13:42:26.486|INFO|PHPFina.php|post() id=22 timestamp=1558273346 value=57 padding=
2019-05-19 13:42:26.490|INFO|process_processlist.php|power_to_kwh() feedid=23 last_kwh=5700.9694628716 kwh_inc=0.00019 new_kwh=5700.9696528716 last_time=1558273334 time_now=1558273346
2019-05-19 13:42:26.490|INFO|feed_model.php|insert_data() feedid=23 updatetime=1558273346 feedtime=1558273346 value=5700.9696528716 arg=join
2019-05-19 13:42:26.491|INFO|PHPFina.php|post() id=23 timestamp=1558273346 value=5700.9696528716 padding=join
2019-05-19 13:42:26.530|INFO|index.php|input/post
2019-05-19 13:42:27.365|INFO|index.php|input/post
2019-05-19 13:42:27.384|INFO|feed_model.php|insert_data() feedid=24 updatetime=1558273347 feedtime=1558273347 value=612 arg=
2019-05-19 13:42:27.386|INFO|feed_model.php|EngineClass() Autoloaded new instance of 'PHPFina'.
2019-05-19 13:42:27.387|INFO|PHPFina.php|post() id=24 timestamp=1558273347 value=612 padding=
2019-05-19 13:42:27.390|INFO|process_processlist.php|power_to_kwh() feedid=25 last_kwh=4839.2373121966 kwh_inc=0.00204 new_kwh=4839.2393521966 last_time=1558273335 time_now=1558273347
2019-05-19 13:42:27.391|INFO|feed_model.php|insert_data() feedid=25 updatetime=1558273347 feedtime=1558273347 value=4839.2393521966 arg=join
2019-05-19 13:42:27.392|INFO|PHPFina.php|post() id=25 timestamp=1558273347 value=4839.2393521966 padding=join
2019-05-19 13:42:27.431|INFO|index.php|input/post

But interestingly, the mosquitto.log has

1558273243: Warning: Received PUBREL from auto-70BDB998-C262-945B-C9B2-D1AE66230DE9 for an unknown packet identifier 65493.
1558273253: Warning: Received PUBREL from auto-70BDB998-C262-945B-C9B2-D1AE66230DE9 for an unknown packet identifier 65507.
1558273263: Warning: Received PUBREL from auto-70BDB998-C262-945B-C9B2-D1AE66230DE9 for an unknown packet identifier 65521.
1558273272: Warning: Received PUBREL from auto-70BDB998-C262-945B-C9B2-D1AE66230DE9 for an unknown packet identifier 65535.
1558273282: Warning: Received PUBREL from auto-70BDB998-C262-945B-C9B2-D1AE66230DE9 for an unknown packet identifier 14.
1558273292: Warning: Received PUBREL from auto-70BDB998-C262-945B-C9B2-D1AE66230DE9 for an unknown packet identifier 15.
1558273292: Warning: Received PUBREL from auto-70BDB998-C262-945B-C9B2-D1AE66230DE9 for an unknown packet identifier 28.
1558273302: Warning: Received PUBREL from auto-70BDB998-C262-945B-C9B2-D1AE66230DE9 for an unknown packet identifier 29.
1558273302: Warning: Received PUBREL from auto-70BDB998-C262-945B-C9B2-D1AE66230DE9 for an unknown packet identifier 42.
1558273312: Warning: Received PUBREL from auto-70BDB998-C262-945B-C9B2-D1AE66230DE9 for an unknown packet identifier 43.

The unix time 1558273272 => Sun, 19 May 2019 14:41:12 +0100 and the possible rollover of the packet id from 65535 to 14 may be significant.

With the current content of the mosquitto.log I expect another rollover to occur around 4:15am tomorrow morning, It’ll be interesting to see if any inputs stop updating around then.

Is it possible to enable more logging (debug/verbose) in the mosquitto.log?

borpin · 2019-05-19T21:37:32.379Z

Darren:

Warning: Received PUBREL

There has been a very similar issue logged recently with Eclipse Warning: Received PUBREL from 866971030943919 for an unknown packet identifier 1 · Issue #1243 · eclipse/mosquitto · GitHub

Could be an incompatibility between the latest Mosquitto package and the MQTT python library in use. @glyn.hudson @TrystanLea you might want to not this.

pb66 · 2019-05-19T21:48:49.451Z

Darren:

Is it possible to enable more logging (debug/verbose) in the mosquitto.log ?

Yes, you would need to add “log_type all” to the config file and then signal mosquitto to reload the conf.

printf "\nlog_type all\n" | sudo tee -a /etc/mosquitto/mosquitto.conf > /dev/null
sudo /usr/bin/killall -HUP mosquitto

Darren · 2019-05-20T06:24:42.459Z

‘power1’ input failed again @04:14 with a corresponding rollover in the mosquitto.log 1558322087 => Mon, 20 May 2019 03:14:47 +0000.

1558322077: Warning: Received PUBREL from 77498E03-4D2E-1A4A-2186-30B4E66791BB for an unknown packet identifier 65521.
1558322087: Warning: Received PUBREL from 77498E03-4D2E-1A4A-2186-30B4E66791BB for an unknown packet identifier 65535.
1558322097: Warning: Received PUBREL from 77498E03-4D2E-1A4A-2186-30B4E66791BB for an unknown packet identifier 14.
1558322107: Warning: Received PUBREL from 77498E03-4D2E-1A4A-2186-30B4E66791BB for an unknown packet identifier 15.

I have enabled the additional logging, here’s a sample

1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m380, 'emon/emontx3/power1', ... (4 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m380, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m381, 'emon/emontx3/power2', ... (1 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m381, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m382, 'emon/emontx3/power3', ... (1 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m382, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m383, 'emon/emontx3/power4', ... (4 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m383, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m384, 'emon/emontx3/vrms', ... (6 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m384, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m385, 'emon/emontx3/temp1', ... (3 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m385, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m386, 'emon/emontx3/temp2', ... (3 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m386, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m387, 'emon/emontx3/temp3', ... (3 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m387, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m388, 'emon/emontx3/temp4', ... (3 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m388, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m389, 'emon/emontx3/temp5', ... (3 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m389, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m390, 'emon/emontx3/temp6', ... (3 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m390, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m391, 'emon/emontx3/pulse', ... (6 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m391, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m392, 'emon/emontx3/rssi', ... (3 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m392, rc0)
1558332558: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m393, 'emonhub/rx/8/values', ... (55 bytes))
1558332558: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m393, rc0)
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 380)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m380)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6914, 'emon/emontx3/power1', ... (4 bytes))
1558332558: Received PUBREC from emoncms (Mid: 6914)
1558332558: Sending PUBREL to emoncms (m6914)
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 381)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m381)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6915, 'emon/emontx3/power2', ... (1 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 382)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m382)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6916, 'emon/emontx3/power3', ... (1 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 383)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m383)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6917, 'emon/emontx3/power4', ... (4 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 384)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m384)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6918, 'emon/emontx3/vrms', ... (6 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 385)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m385)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6919, 'emon/emontx3/temp1', ... (3 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 386)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m386)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6920, 'emon/emontx3/temp2', ... (3 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 387)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m387)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6921, 'emon/emontx3/temp3', ... (3 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 388)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m388)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6922, 'emon/emontx3/temp4', ... (3 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 389)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m389)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6923, 'emon/emontx3/temp5', ... (3 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 390)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m390)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6924, 'emon/emontx3/temp6', ... (3 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 391)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m391)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6925, 'emon/emontx3/pulse', ... (6 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 392)
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m392)
1558332558: Sending PUBLISH to emoncms (d0, q2, r0, m6926, 'emon/emontx3/rssi', ... (3 bytes))
1558332558: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 393)
1558332558: Warning: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 for an unknown packet identifier 393.
1558332558: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m393)
1558332558: Received PUBCOMP from emoncms (Mid: 6914, RC:0)
1558332558: Received PUBREC from emoncms (Mid: 6915)
1558332558: Sending PUBREL to emoncms (m6915)
1558332558: Received PUBREC from emoncms (Mid: 6916)
1558332558: Sending PUBREL to emoncms (m6916)
1558332558: Received PUBREC from emoncms (Mid: 6917)
1558332558: Sending PUBREL to emoncms (m6917)
1558332558: Received PUBREC from emoncms (Mid: 6918)
1558332558: Sending PUBREL to emoncms (m6918)
1558332558: Received PUBREC from emoncms (Mid: 6919)
1558332558: Sending PUBREL to emoncms (m6919)
1558332558: Received PUBREC from emoncms (Mid: 6920)
1558332558: Sending PUBREL to emoncms (m6920)
1558332558: Received PUBREC from emoncms (Mid: 6921)
1558332558: Sending PUBREL to emoncms (m6921)
1558332558: Received PUBREC from emoncms (Mid: 6922)
1558332558: Sending PUBREL to emoncms (m6922)
1558332558: Received PUBREC from emoncms (Mid: 6923)
1558332558: Sending PUBREL to emoncms (m6923)
1558332558: Received PUBREC from emoncms (Mid: 6924)
1558332558: Sending PUBREL to emoncms (m6924)
1558332558: Received PUBREC from emoncms (Mid: 6925)
1558332558: Sending PUBREL to emoncms (m6925)
1558332558: Received PUBREC from emoncms (Mid: 6926)
1558332558: Sending PUBREL to emoncms (m6926)
1558332558: Received PUBCOMP from emoncms (Mid: 6915, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6916, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6917, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6918, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6919, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6920, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6921, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6922, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6923, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6924, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6925, RC:0)
1558332558: Received PUBCOMP from emoncms (Mid: 6926, RC:0)
1558332563: Received PINGREQ from emoncms
1558332563: Sending PINGRESP to emoncms
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m394, 'emon/emontx3/power1', ... (4 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m394, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m395, 'emon/emontx3/power2', ... (1 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m395, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m396, 'emon/emontx3/power3', ... (1 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m396, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m397, 'emon/emontx3/power4', ... (4 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m397, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m398, 'emon/emontx3/vrms', ... (5 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m398, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m399, 'emon/emontx3/temp1', ... (3 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m399, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m400, 'emon/emontx3/temp2', ... (3 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m400, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m401, 'emon/emontx3/temp3', ... (3 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m401, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m402, 'emon/emontx3/temp4', ... (3 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m402, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m403, 'emon/emontx3/temp5', ... (3 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m403, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m404, 'emon/emontx3/temp6', ... (3 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m404, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m405, 'emon/emontx3/pulse', ... (6 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m405, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m406, 'emon/emontx3/rssi', ... (3 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m406, rc0)
1558332567: Received PUBLISH from 134D58AA-81B8-9486-B250-8ED34480A943 (d0, q2, r0, m407, 'emonhub/rx/8/values', ... (54 bytes))
1558332567: Sending PUBREC to 134D58AA-81B8-9486-B250-8ED34480A943 (m407, rc0)
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 394)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m394)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6927, 'emon/emontx3/power1', ... (4 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 395)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m395)
1558332568: Received PUBREC from emoncms (Mid: 6927)
1558332568: Sending PUBREL to emoncms (m6927)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6928, 'emon/emontx3/power2', ... (1 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 396)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m396)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6929, 'emon/emontx3/power3', ... (1 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 397)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m397)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6930, 'emon/emontx3/power4', ... (4 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 398)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m398)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6931, 'emon/emontx3/vrms', ... (5 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 399)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m399)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6932, 'emon/emontx3/temp1', ... (3 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 400)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m400)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6933, 'emon/emontx3/temp2', ... (3 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 401)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m401)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6934, 'emon/emontx3/temp3', ... (3 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 402)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m402)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6935, 'emon/emontx3/temp4', ... (3 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 403)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m403)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6936, 'emon/emontx3/temp5', ... (3 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 404)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m404)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6937, 'emon/emontx3/temp6', ... (3 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 405)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m405)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6938, 'emon/emontx3/pulse', ... (6 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 406)
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m406)
1558332568: Sending PUBLISH to emoncms (d0, q2, r0, m6939, 'emon/emontx3/rssi', ... (3 bytes))
1558332568: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 (Mid: 407)
1558332568: Warning: Received PUBREL from 134D58AA-81B8-9486-B250-8ED34480A943 for an unknown packet identifier 407.
1558332568: Sending PUBCOMP to 134D58AA-81B8-9486-B250-8ED34480A943 (m407)
1558332568: Received PUBCOMP from emoncms (Mid: 6927, RC:0)
1558332568: Received PUBREC from emoncms (Mid: 6928)
1558332568: Sending PUBREL to emoncms (m6928)
1558332568: Received PUBREC from emoncms (Mid: 6929)
1558332568: Sending PUBREL to emoncms (m6929)
1558332568: Received PUBREC from emoncms (Mid: 6930)
1558332568: Sending PUBREL to emoncms (m6930)
1558332568: Received PUBREC from emoncms (Mid: 6931)
1558332568: Sending PUBREL to emoncms (m6931)
1558332568: Received PUBREC from emoncms (Mid: 6932)
1558332568: Sending PUBREL to emoncms (m6932)
1558332568: Received PUBREC from emoncms (Mid: 6933)
1558332568: Sending PUBREL to emoncms (m6933)
1558332568: Received PUBREC from emoncms (Mid: 6934)
1558332568: Sending PUBREL to emoncms (m6934)
1558332568: Received PUBREC from emoncms (Mid: 6935)
1558332568: Sending PUBREL to emoncms (m6935)
1558332568: Received PUBREC from emoncms (Mid: 6936)
1558332568: Sending PUBREL to emoncms (m6936)
1558332568: Received PUBREC from emoncms (Mid: 6937)
1558332568: Sending PUBREL to emoncms (m6937)
1558332568: Received PUBREC from emoncms (Mid: 6938)
1558332568: Sending PUBREL to emoncms (m6938)
1558332568: Received PUBREC from emoncms (Mid: 6939)
1558332568: Sending PUBREL to emoncms (m6939)
1558332568: Received PUBCOMP from emoncms (Mid: 6928, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6929, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6930, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6931, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6932, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6933, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6934, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6935, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6936, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6937, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6938, RC:0)
1558332568: Received PUBCOMP from emoncms (Mid: 6939, RC:0)

I think the next failure will occur around 7pm.

pb66 · 2019-05-20T10:54:23.154Z

Darren:

MQTT Version: Mosquitto 1.6.2

I think it is likely to be because you are running such a cutting edge version of Mosquitto, this would not be the first time users (or this project) have had to back pedal a little to an earlier version of mosquitto.

The current “supported” versions are mosquitto v1.4.10, mosquitto-php v0.4.0 and paho-mqtt v1.4.0

pi@emonpi:~ $ mosquitto -h
mosquitto version 1.4.10 (build date Wed, 13 Feb 2019 00:45:38 +0000)

mosquitto is an MQTT v3.1 broker.

Usage: mosquitto [-c config_file] [-d] [-h] [-p port]

 -c : specify the broker config file.
 -d : put the broker into the background after starting.
 -h : display this help.
 -p : start the broker listening on the specified port.
      Not recommended in conjunction with the -c option.
 -v : verbose mode - enable all logging types. This overrides
      any logging options given in the config file.

See http://mosquitto.org/ for more information.


pi@emonpi:~ $ pecl info mosquitto
About pecl.php.net/Mosquitto-0.4.0
==================================
Release Type          PECL-style PHP extension (source code)
Name                  Mosquitto
Channel               pecl.php.net
Summary               Extension for libmosquitto
Description           Mosquitto provides support for the MQTT
                      protocol, including publishing, subscribing, and
                      an event loop.
Maintainers           Michael Maclean <mgdm@php.net> (lead)
Release Date          2017-03-13 21:17:22
Release Version       0.4.0 (beta)
API Version           0.4.0 (beta)
License               BSD 3-Clause License
                      (http://opensource.org/licenses/BSD-3-Clause)
Release Notes         * PHP 7 support thanks to Sara Golemon
                      * Improved docs hosted on ReadTheDocs
                      * Some memory usage fixes
Required Dependencies PHP version 5.3.0
                      PEAR installer version 1.4.0 or newer
package.xml version   2.0
Last Modified         2018-08-02 12:45
Previous Installed    - None -
Version


pi@emonpi:~ $ sudo pip show paho-mqtt
Name: paho-mqtt
Version: 1.4.0
Summary: MQTT version 3.1.1 client class
Home-page: http://eclipse.org/paho
Author: Roger Light
Author-email: roger@atchoo.org
License: Eclipse Public License v1.0 / Eclipse Distribution License v1.0
Location: /usr/local/lib/python2.7/dist-packages
Requires:

I can see you are running v0.4.0 mosquitto-php but can you please confirm what version of paho-mqtt you are running?

Is there a reason you’ve opted for a bleeding edge version of mosquitto rather than a tried and tested “stable” version? Are there specific features you need? I think you should possibly try installing mosquitto via a package manager eg Debian using apt-get etc (even the unstable distros haven’t progressed beyond 1.5.7 yet Debian -- Package Search Results -- mosquitto). You seem to be using all expected versions for other packages eg php v7, redis v3.2.6 and mariadb 10.1 etc.

Even if you fix this, you should possibly expect other issues to crop up too, even if the latest mosquitto release was 100% tickety-boo the other parts that need to work with the broker are not as advanced.

[edit]

BTW by “supported” I only mean, the versions currently in use and confirmed to greater degree as compatible and working as expected. Many of us would always try to offer support even with “unsupported” packages and versions, although our knowledge and experience will probably be somewhat limited and there are of course no guarantee’s that any OEM component will definitely work with the “unsupported” stuff.

Darren · 2019-05-20T13:31:08.165Z

sudo pip show paho-mqtt
Name: paho-mqtt
Version: 1.4.0
Summary: MQTT version 3.1.1 client class
Home-page: http://eclipse.org/paho
Author: Roger Light
Author-email: roger@atchoo.org
License: Eclipse Public License v1.0 / Eclipse Distribution License v1.0
Location: /usr/local/lib/python2.7/dist-packages
Requires:

I personally don’t need any particular version of mosquitto. I just followed the instructions on GitHub - openenergymonitor/emonhub: Python service linking and decoding input to MQTT & Emoncms and emoncms/MQTT.md at master · emoncms/emoncms · GitHub on how to install MQTT. I think when it all worked I might have had version 1.4 or 1.5. It was after an apt-get update/upgrade that I was given 1.6, when it may have started to go wrong.

I’m happy to try and roll back to a “supported” version if that’s the next step.

Darren · 2019-05-20T14:22:00.250Z

I think the reason why I had the bleeding edge mosquitto was because I had installed the mosquitto-debian-repository as suggested by the setup guides as I was getting some error when I tried to initially install mosquitto.

I’ve purged mosquitto, removed the debian repository and re-installed mosquitto (no errors this time). I am now running the “supported” v1.4.10 version and everything is working fine with no warnings in the mosquitto.log.

I’ll report back in a couple of days if everything is still working.

Thanks for all your help.

borpin · 2019-05-20T14:36:20.459Z

Darren:

I think the reason why I had the bleeding edge mosquitto was because I had installed the mosquitto-debian-repository as suggested by the setup guides

That is a legacy instruction from when the raspbian mosquitto package was way behind. Needs removing!

Darren · 2019-05-22T18:52:50.360Z

FYI - It’s been 2 days without further incident.

I think it’s fixed