Mosquitto not starting after emonSD update & upgrade

nicklaws · 21 September 2016 01:43

Hello, I have purchased the pre-loaded SD card for my RPi 3, a RFM69, and a emonTx. The emonTx CTs are all hooked up and it is plugged in. I have followed all of the steps and trouble shooting tips, but it appears that my emonBase (updated today) is not connecting to the emonTx:

tail /var/log/emoncms.log

2016-09-21 01:40:40.000|WARN|phpmqtt_input.php|Not connected, retrying connection

sudo service emonhub status

● emonhub.service - LSB: Start/stop emonHub
   Loaded: loaded (/etc/init.d/emonhub)
   Active: active (running) since Wed 2016-09-21 01:17:15 UTC; 4min 40s ago
  Process: 496 ExecStart=/etc/init.d/emonhub start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/emonhub.service
           └─681 python /usr/share/emonhub/emonhub.py --logfile /var/log/emonhub/emonhub.log --c...

Sep 21 01:17:15 emonpi sudo[526]: pam_unix(sudo:session): session opened for user root by (uid=0)
Sep 21 01:17:15 emonpi sudo[526]: pam_unix(sudo:session): session closed for user root
Sep 21 01:17:15 emonpi sudo[626]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chow...nhub
Sep 21 01:17:15 emonpi sudo[626]: pam_unix(sudo:session): session opened for user root by (uid=0)
Sep 21 01:17:15 emonpi sudo[626]: pam_unix(sudo:session): session closed for user root
Sep 21 01:17:15 emonpi sudo[636]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chow...nhub
Sep 21 01:17:15 emonpi sudo[636]: pam_unix(sudo:session): session opened for user root by (uid=0)
Sep 21 01:17:15 emonpi sudo[636]: pam_unix(sudo:session): session closed for user root
Sep 21 01:17:15 emonpi emonhub[496]: Starting OpenEnergyMonitor emonHub: emonhub has been st... ok.
Sep 21 01:17:15 emonpi systemd[1]: Started LSB: Start/stop emonHub.

tail /var/log/emonhub/emonhub.log

2016-09-21 01:22:26,309 INFO     MQTT       Could not connect...
2016-09-21 01:22:26,969 DEBUG    RFM2Pi     72 NEW FRAME : OK 8 0 0 232 255 114 0 4 0 223 48 184 11 184 11 184 11 184 11 184 11 184 11 1 0 0 0 (-37)
2016-09-21 01:22:26,971 DEBUG    RFM2Pi     72 Timestamp : 1474420946.97
2016-09-21 01:22:26,971 DEBUG    RFM2Pi     72 From Node : 8
2016-09-21 01:22:26,972 DEBUG    RFM2Pi     72    Values : [0, -24, 114, 4, 125.11, 300, 300, 300, 300, 300, 300, 1]
2016-09-21 01:22:26,972 DEBUG    RFM2Pi     72      RSSI : -37
2016-09-21 01:22:26,973 DEBUG    RFM2Pi     72 adding frame to buffer => [1474420946, 8, 0, -24, 114, 4, 125.11, 300, 300, 300, 300, 300, 300, 1, -37]
2016-09-21 01:22:26,973 DEBUG    RFM2Pi     72 Sent to channel' : ToEmonCMS
2016-09-21 01:22:27,419 INFO     MQTT       Connecting to MQTT Server
2016-09-21 01:22:27,420 INFO     MQTT       Could not connect...

Any tips?

nicklaws · 21 September 2016 02:27

PS emoncms shows “n/a” and “NaN” for the updated and value columns in inputs.

and minicom looks good?:
OK 8 0 0 246 255 53 0 5 0 6 49 184 11 184 11 184 11 184 11 184 11 184 11 1 0 0 0 (-53)
OK 8 0 0 245 255 52 0 5 0 254 48 184 11 184 11 184 11 184 11 184 11 184 11 1 0 0 0 (-53)
OK 8 0 0 246 255 52 0 5 0 5 49 184 11 184 11 184 11 184 11 184 11 184 11 1 0 0 0 (-54)
OK 8 0 0 245 255 51 0 5 0 22 49 184 11 184 11 184 11 184 11 184 11 184 11 1 0 0 0 (-50)

pb66 · 21 September 2016 07:28

Hi Nick,

I moved your posts to this new thread (from Connecting emonBase and emonTx) as the issue isn’t an emontx to emonbase issue, but a problem with MQTT, Your first log shows emoncms is not connected to MQTT and the 3rd one shows emonhub cannot connect either.

The minicom output and the emonhub logs both show the emontx data is being received by the emonbase, but there is an issue with the connection between emonhub and emoncms via the MQTT broker.

Hopefully someone with some experience of the emonSD and this MQTT issue in particular can jump in and advise you.

jeremypoulter · 21 September 2016 10:14

That sounds similar to the problems I had.

Log in to the console and see if Mosquitto is running;

pi@home:~ $ ps aux | grep mosquitto
mosquit+  1185  0.1  0.3   5436  3876 ?        S    Sep14  12:24 /usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf
pi       15793  0.0  0.2   4280  2016 pts/0    S+   10:11   0:00 grep --color=auto mosquitto

Don’t trust service mosquitto status it lied to me and caused me to waste lots of time looking for an alternative problem.

nicklaws · 21 September 2016 12:50

Thanks so much Paul and Jeremy!

Looks like mosquitto is not running:

pi@emonpi:~ $ ps aux | grep mosquitto
pi 12218 0.0 0.1 5976 1956 pts/0 S+ 08:16 0:00 grep --color=auto mosquitto

I did some searching around, and read through emoncms/MQTT.md at master · emoncms/emoncms · GitHub, but that doesn’t seem to be my problem.

The only piece that I was missing was (which I did):
“If PHP extension config files /etc/php5/cli/conf.d/20-mosquitto.ini and /etc/php5/apache2/conf.d/20-mosquitto.ini don’t exist then create with:”

sudo sh -c ‘echo “extension=mosquitto.so” > /etc/php5/cli/conf.d/20-mosquitto.ini’
sudo sh -c ‘echo “extension=mosquitto.so” > /etc/php5/apache2/conf.d/20-mosquitto.ini’

Did a reboot and checked: Mosquitto still not running. What do you suggest a try next?

jeremypoulter · 21 September 2016 23:12

Just try running it on the command line.

sudo mosquitto

If it complains about not being able to write to /var/log/mosquitto/... then it is the same issue I had, and the fix is in the thread I posted.

glyn.hudson · 22 September 2016 08:20

Hi Nick,

Sorry to hear your having trouble. Are you running the stock emonSD-08May16 sd card? I’ve not experienced this issue, I’m running mosquitto version 1.4.9. Could you check what version your running?

$ mosquitto -h

nicklaws · 24 September 2016 00:27

I am running the stock SD card (that I just received in the mail). I have mosquitto version 1.4.10:

pi@emonpi:~ $ sudo mosquitto
1474676184: mosquitto version 1.4.10 (build date Thu, 25 Aug 2016 10:12:09 +0100) starting
1474676184: Using default config.
1474676184: Opening ipv4 listen socket on port 1883.
1474676184: Opening ipv6 listen socket on port 1883.
1474676184: New connection from 127.0.0.1 on port 1883.
1474676184: New client connected from 127.0.0.1 as paho/828FDA3EF4EC95567D (c1, k60, u’emonpi’).
1474676185: Socket error on client paho/828FDA3EF4EC95567D, disconnecting.
1474676185: New connection from 127.0.0.1 on port 1883.
1474676185: New client connected from 127.0.0.1 as paho/828FDA3EF4EC95567D (c1, k60, u’emonpi’).
1474676185: New connection from 127.0.0.1 on port 1883.
1474676185: New client connected from 127.0.0.1 as openhab.1474676185586 (c1, k60, u’emonpi’).
1474676187: New connection from ::1 on port 1883.
1474676187: New client connected from ::1 as mosq/Jq=j?h77ej=UO>9:_s (c1, k5, u’emonpi’).
1474676191: Socket error on client mosq/Jq=j?h77ej=UO>9:_s, disconnecting.
1474676192: New connection from ::1 on port 1883.
1474676192: New client connected from ::1 as mosq/`02FPtT\2DnaWvp]m] (c1, k5, u’emonpi’).
1474676194: New connection from 127.0.0.1 on port 1883.
1474676194: New client connected from 127.0.0.1 as mqtt_f54f1159.0ab0f (c1, k15, u’emonpi’).

It just seems to hang after giving the above output. Sorry I’m unfamiliar with mosquitto. Perhaps I should revert to version 1.4.9?

I tried:
pi@emonpi:~ $ sudo apt-get install mosquitto=1.4.9
W: Not using locking for read only lock file /var/lib/dpkg/lock
E: Unable to write to /var/cache/apt/
E: The package lists or status file could not be parsed or opened.

nicklaws · 24 September 2016 02:35

Hooray! I flashed another SD card with the latest image, and then DID NOT UPDATE: getting numbers in emoncms now!

So perhaps an issue with mosquitto 1.4.10?

nicklaws · 24 September 2016 04:06

However… the numbers are not refreshing in emoncms. The RFM69Pi V3 led is not flashing every 10 seconds, though it did in the past (when I was getting n/a’s in emoncms). Should I try updating?

It seems (from minicom) that any signals are being discarded except the very first signal received after a reboot.

jeremypoulter · 24 September 2016 15:25

Yeah, I think that 1.4.10 is a bit more picky about the creating the log files. I will create a PR for the changes that fixed this issue.

glyn.hudson · 25 September 2016 00:37

Could you post the Minicom output?

Its fine to run emonpi update (be emoncms admin web interface) but hold off running any system upgrades until your up and running so we can limit the number of variables.

I will try and investigate mosquitto 1.4.10 next week

nicklaws · 25 September 2016 00:47

Hi Glyn, sorry I didn’t post it sooner, but I’m fully operational now.

I believe that the issue was interference from my wireless router: the emonbase was plugged into the router with ethernet so the two were very close to eachother (and the emonTx was only ~4m and one wall away).

So I unplugged the emonbase (have RPi3 so using wireless now) and put it much closer to the emonTx, and further from the wireless router.

Thanks for all your help. I hope to contribute to development in the future (I’m handy with python) and if you’re ever climbing in Colorado look me up!

Nick

Bill.Thomson · 25 September 2016 00:51

Hi Nick,

Your post doesn’t quite make sense as emonhub is software.
Perhaps you have it confused with something else?

nicklaws · 25 September 2016 00:54

Sorry, I meant emonBase

glyn.hudson · 25 September 2016 00:55

I think @nicklaws means emonBase (raspi + rfm69pi) when he says emonhub? Is this correct?

Good to hear you’re up and running

I will report mosquitto logfile investigation. @jeremypoulter did you hint that you’ve got a fix for this? What was the issue?

We should split this topic into a new one to continue discussion.

Bill.Thomson · 25 September 2016 00:58

Not a problem. I fixed it for you.

jeremypoulter · 25 September 2016 10:26

Have a look at MQTT Log files:

glyn.hudson · 28 September 2016 09:48

This issue has now been fixed:

Xino · 13 November 2016 13:05

Having the same issue after apt-get update & upgrade. I have also run the emonPi update and reboot but the mosquitto folder and log files have not been created.

I can only get the MQTT Server started via command prompt, ie. mosquitto &
It then works as normal.

TIA