Question about MQTT Log lines

General
1

I saw this issue a few months ago and promptly forgot about it.
My log files are full of lines like the dump below. Can anyone suggest how I can determine why so many of my client devices are trying to reconnect?

sudo cat /var/log/mosquitto/mosquitto.log

1546338709: Client DVES_8674B8 already connected, closing old connection.
1546363026: Client ds18b20x2temperature already connected, closing old connection.
1546369779: Client ds18b20x2temperature already connected, closing old connection.
1546435361: Client temperature01temperature already connected, closing old connection.
1546539829: Client ds18b20x2temperature already connected, closing old connection.
1546615416: Client ds18b20x2temperature already connected, closing old connection.
1546660698: Client DVES_6936DF already connected, closing old connection.
1546696947: Client ds18b20x2temperature already connected, closing old connection.
1546739026: Client DVES_6936DF already connected, closing old connection.
1546739228: Client DVES_6936DF already connected, closing old connection.
1546739252: Client ESP8266Attic already connected, closing old connection.
1546739300: Client DVES_0416EC already connected, closing old connection.
1546739304: Client DVES_0680D2 already connected, closing old connection.
1546739452: Client DVES_AB4590 already connected, closing old connection.
1546739919: Client DVES_066D93 already connected, closing old connection.
1546739933: Client ESP8266Attic already connected, closing old connection.
1546740028: Client DVES_693697 already connected, closing old connection.
1546740498: Client mqtt_3571bf40.de007 already connected, closing old connection.
1546740627: Client DVES_8674B8 already connected, closing old connection.
1546740922: Client ds18b20x2temperature already connected, closing old connection.
1546740951: Client DVES_0416EC already connected, closing old connection.
1546741136: Client familyroomlight already connected, closing old connection.
1546741183: Client ds18b20x2temperature already connected, closing old connection.
1546741227: Client temperature01temperature already connected, closing old connection.
1546741334: Client DVES_0416EC already connected, closing old connection.
1546741400: Client DVES_557013 already connected, closing old connection.
1546742288: Client DVES_0416EC already connected, closing old connection.
1546742333: Client roomlight already connected, closing old connection.
1546742370: Client DVES_66AD29 already connected, closing old connection.
1546743583: Client DVES_6936DF already connected, closing old connection.
pi@Marvin:/var/log/mosquitto $
2

That suggests you have multiple mqtt config nodes with the same client id. Each config node must have a separate id (or must be blank in which case node-RED will autogenerate one.
Have you removed lines from that log? The connecting event should also be there so you can check which ip address each one is on.

3

This is interesting. I have another question on the forum regarding my config nodes (Question about MQTT config nodes), which may be the problem.

My MQTT broker is on a separate Pi, but according to the config tab, I have the broker defined multiple times. And I don't know why. Could this be causing the problem? (My client ID is always blank, but that's no guarantee that multiple config nodes could not auto-create the same client ID).

4

The nodes use their ID as part of the clientid, so there is a guarantee that each generated client ID (within a single NR instance) will be unique.

5

I am sorry, but I suspect that you are mistaken there. The log line

Client DVES_8674B8 already connected, closing old connection.

indicates that you have a node with that client id. Search for that id using the node-red search facility to check. Similarly with the other lines in the log. If you look at the mosquitto log (or whatever server you are using) you can check with machine is connecting with those ids.
[Edit] That was a stupid thing to say, that is the mosquitto log. I would have expected to see the ip address there, perhaps that is controlled by a mosquitto config option.

6

Or a device outside of Node-RED entirely.

7

Colin- when I said: "My client ID is always blank", I mean in the MQTT Config nodes in Node-Red.
It would be nice if the IP of the node was in the log file, but it's loaded with "xyzzy already connected, closing old connection."

Heres the most recent:

1546177364: Client esp8266-5c:cf:7f:34:6f:56 already connected, closing old connection.
1546178129: Client ds18b20x2temperature already connected, closing old connection.
1546239929: Client temperature01temperature already connected, closing old connection.
1546318541: Client DVES_8674B8 already connected, closing old connection.
1546338709: Client DVES_8674B8 already connected, closing old connection.
1546363026: Client ds18b20x2temperature already connected, closing old connection.
1546369779: Client ds18b20x2temperature already connected, closing old connection.
1546435361: Client temperature01temperature already connected, closing old connection.
1546539829: Client ds18b20x2temperature already connected, closing old connection.
1546615416: Client ds18b20x2temperature already connected, closing old connection.
1546660698: Client DVES_6936DF already connected, closing old connection.
1546696947: Client ds18b20x2temperature already connected, closing old connection.
1546739026: Client DVES_6936DF already connected, closing old connection.
1546739228: Client DVES_6936DF already connected, closing old connection.
1546739252: Client ESP8266Attic already connected, closing old connection.
1546739300: Client DVES_0416EC already connected, closing old connection.
1546739304: Client DVES_0680D2 already connected, closing old connection.
1546739452: Client DVES_AB4590 already connected, closing old connection.
1546739919: Client DVES_066D93 already connected, closing old connection.
1546739933: Client ESP8266Attic already connected, closing old connection.
1546740028: Client DVES_693697 already connected, closing old connection.
1546740498: Client mqtt_3571bf40.de007 already connected, closing old connection.
1546740627: Client DVES_8674B8 already connected, closing old connection.
1546740922: Client ds18b20x2temperature already connected, closing old connection.
1546740951: Client DVES_0416EC already connected, closing old connection.
1546741136: Client familyroomlight already connected, closing old connection.
1546741183: Client ds18b20x2temperature already connected, closing old connection.
1546741227: Client temperature01temperature already connected, closing old connection.
1546741334: Client DVES_0416EC already connected, closing old connection.
1546741400: Client DVES_557013 already connected, closing old connection.
1546742288: Client DVES_0416EC already connected, closing old connection.
1546742333: Client roomlight already connected, closing old connection.
1546742370: Client DVES_66AD29 already connected, closing old connection.
1546743583: Client DVES_6936DF already connected, closing old connection.
1546789948: Client ds18b20x2temperature already connected, closing old connection.
1546794099: Client temperature01temperature already connected, closing old connection.
1546816124: Client DVES_8674B8 already connected, closing old connection.
1546878859: Client temperature01temperature already connected, closing old connection.
1546901109: Client temperature01temperature already connected, closing old connection.

Some of these I recognize, but the search in Home Assistant didn't help with those that I can't identify from the log. Do you mean "search flows" in the hamburger menu? Knolleary may be on to something because a couple of the devices I recognize are running Arduino code using the esphelper.h library. Most of my esp stuff have been switched to Tasmota, but there's a few that are still running my old code.

But, you have both given me something to research. The DVES lines are likely devices running Tasmota, but are you saying, Colin, that I have the same Client ID, like "DVES_0416EC" used in two devices? I thought that Tasmota generated a random ID number, but if I change one character like "DVEX_0416EC", then I should stop seeing it in the log files?

Thanks,
Steve

8

I should have recognised the DVES ids, they are, as you say, the default ids used by Tasmota. If you have not explicitly provided an id in Tasmota then the number after DVES should use the last 6 digits of the MAC address, so should be unique.
If all your node-red brokers have blank client id then that suggests they are all from other devices. I think you need to find why your mosquitto log is lacking in detail, for example mine shows stuff like

1546881095: New connection from 192.168.xx.xx on port 1883.
1546881095: New client connected from 192.168.xx.xx as DVES_98974A (c1, k10).

The default mosquitto configuration file is /etc/mosquitto/mosquitto.conf and in addition any .conf files in /etc/mosquitto/conf.d/ will be included. Have a look at those files and if you can't see anything obvious then post them here. I have checked mine and there doesn't seem to be anything that might make the logging more detailed, so perhaps yours has something that lowers the logging level.
What version of mosquitto are you running? If on a Pi or other Debian based OS then run in a terminal
apt-cache policy mosquitto
and post the result here.

[Edit] I meant the default conf file for mosquitto is /etc/mosquitto/mosquitto.conf. I have editted the above text accordingly.
Also corrected apt-cache policy command.

9

Hi Colin,
I think the path for the default log for mosquitto is...

/var/log/mosquitto/mosquitto.log

10

Yes, sorry, I meant the default conf file, I have editted the earlier post to correct it.
I have also corrected the apt-cache policy command which was wrong.

11

Thanks for sticking with me here.
/etc/mosquitto/conf.d only contains the README file.

pi@Marvin:~ $ sudo apt-cache policy gnucash
gnucash:
Installed: (none)
Candidate: 1:2.6.4-3
Version table:
1:2.6.4-3 0
500 http://mirrordirector.raspbian.org/raspbian/ jessie/main armhf Packages

My log files are full of "already connected, closing old connection." lines, and not one with "New Client..." or "New Connection...".

I would not be surprised that I have an older version of the Mosquitto broker- it's never received an upgrade since installing it early last year.

About upgrading Mosquitto:
When I do a sudo apt-get update -y on the Pi, I get this warning about Mosquitto:

Reading package lists... Done
W: An error occurred during the signature verification. The repository is not updated and the previous index files will                         be used. GPG error: http://repo.mosquitto.org jessie InRelease: The following signatures were invalid: KEYEXPIRED 151501                        7477 KEYEXPIRED 1515017477 KEYEXPIRED 1515017477

W: Failed to fetch http://repo.mosquitto.org/debian/dists/jessie/InRelease

W: Failed to fetch http://repo.mosquitto.org/debian/dists/wheezy/main/binary-armhf/Packages  404  Not Found [IP: 85.119.                        83.194 80]

W: Some index files failed to download. They have been ignored, or old ones used instead.

I don't know why it's trying to fetch wheezy files. This Pi is running Jessie:

cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 8 (jessie)"
NAME="Raspbian GNU/Linux"
VERSION_ID="8"
VERSION="8 (jessie)"
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

I know I should be running Stretch, but the last time I tried upgrading Jessie to Stretch, it took me most of the day. I have a lot of flows on this Pi that I fear would break because they have nodes installed from NPM.

12

check in your /etc/apt/sources.list or /etc/apt/sources.list.d directory so see if any file there contains wheezy. For things like mqtt it should just be a matter of editing it to say jessie , then re-run sudo apt-get update && sudo apt-get upgrade to get the newer versions.

13

I amended my post, that should have been
apt-cache policy mosquitto
also /etc/mosquitto/mosquitto.conf is the default config file, could you paste that here please.

14

The problem with the signature is that they changed the signing key. You need to

wget http://repo.mosquitto.org/debian/mosquitto-repo.gpg.key
sudo apt-key add mosquitto-repo.gpg.key

However that is separate from the fact you seem to have something installed from wheezy, so follow @dceejay's advice to sort that out. That may not be mosquitto of course, the apt-cache policy command will tell you that.

15

Thanks, but those files/folders don't exist here.

16

sorry - I'm losing it.... /etc/apt/sources.list file and /etc/apt/sources.list.d dir

cd /etc/apt && grep -r wheezy

should show them

17

I was scratching my head over gnucache... :thinking:

Here's policy mosquitto:

pi@Marvin:/etc $ apt-cache policy mosquitto
mosquitto:
  Installed: 1.4.14-0mosquitto1~nows1
  Candidate: 1.4.14-0mosquitto1~nows1
  Version table:
 *** 1.4.14-0mosquitto1~nows1 0
        500 http://repo.mosquitto.org/debian/ wheezy/main armhf Packages
        100 /var/lib/dpkg/status
     1.4.14-0mosquitto1~jessie2 0
        500 http://repo.mosquitto.org/debian/ jessie/main armhf Packages
     1.3.4-2+deb8u3 0
        500 http://mirrordirector.raspbian.org/raspbian/ jessie/main armhf Packages

And here is mosquitto.conf:

pi@Marvin:/etc $ sudo cat /etc/mosquitto/mosquitto.conf
# Place your local configuration in /etc/mosquitto/conf.d/
#
# A full description of the configuration file is at
# /usr/share/doc/mosquitto/examples/mosquitto.conf.example

pid_file /var/run/mosquitto.pid

persistence true
persistence_location /var/lib/mosquitto/

log_dest file /var/log/mosquitto/mosquitto.log
# You can choose which event types to log.
# By default error, information, notice and warning events are logged.
#
log_type error
log_type warning
#log_type notice
#log_type informaton

#For debugging, use:
#log_type all


include_dir /etc/mosquitto/conf.d

Hmm, maybe I need to change the log_type.
So, using log_type all, I am getting a lot more data in the log file including IP addresses, so it will be easier to identify the problem nodes.

18

Getting the new key fixed one of the warnings, but still getting this one:

W: Failed to fetch http://repo.mosquitto.org/debian/dists/wheezy/main/binary-armhf/Packages 404 Not Found [IP: 85.119.83.194 80]

Following dceejay's input:

pi@Marvin:~ $ cd /etc/apt && grep -r wheezy
sources.list.d/mosquitto-wheezy.list:deb http://repo.mosquitto.org/debian wheezy main
pi

This pointed me to the sources.list.d directory where I find:

-rw-r--r-- 1 root  49 May  3  2015 mosquitto-jessie.list
-rw-r--r-- 1 root  49 May  3  2015 mosquitto-wheezy.list
-rw-r--r-- 1 root 108 Nov 23  2017 nodesource.list
-rw-r--r-- 1 root 193 Mar  3  2017 raspi.list

Since this Pi is running Jessie, should the mosquitto.wheezy.list file even exist? Would it be safe to just delete it?

19

Yes just delete it

20

Thanks Colin and Cdeejay for your assistance. Also Knolleary, and you, too Dynamicdave.

Deleting the Wheezy line from sources.list.d fixed the Update/Upgrade warnings about Wheezy.
Getting the latest signing key from Mosquitto.org fixed the update warning about the Mosquitto key.
Changing the log_type in /etc/mosquitto/mosquitto.conf to: log_type all now gives me more information to track down the original problem.

This thread has been very helpful, and I took copious notes. But since I've drifted from the original topic and you have given me much to research, unless either of you have additional information for me, I think this thread can be closed.

Sig

1 Like