search

volkszaehler / vzlogger

Logging utility for various meters & sensors
http://wiki.volkszaehler.org/software/controller/vzlogger
GNU General Public License v3.0
145 stars 124 forks source link

MQTT Error Codes #468

Closed Sieboldianus closed 2 years ago

Sieboldianus commented 3 years ago

Is there any guidance towards error codes of vzlogger mqtt implementation? I only found named errors on the docs, but vzlogger gives me numbers:

[Mar 23 22:28:50][mqtt] mosquitto_publish returned 4
[Mar 23 22:28:50][mqtt] mosquitto_reconnect succeeded
[Mar 23 22:28:50][mqtt] disconnect_callback called, res=6
[Mar 23 22:28:50][mqtt] mosquitto_loop returned 6. trying reconnect
[Mar 23 22:28:51][mqtt] publish vzlogger/data/chn0/raw=438.000000
[Mar 23 22:28:51][mqtt] mosquitto_publish returned 4
[Mar 23 22:28:51][mqtt] publish vzlogger/data/chn1/raw=998546.400000
[Mar 23 22:28:51][mqtt] mosquitto_publish returned 4
[Mar 23 22:28:51][mqtt] publish vzlogger/data/chn2/raw=1864560.800000
[Mar 23 22:28:51][mqtt] mosquitto_publish returned 4
[Mar 23 22:28:51][mqtt] mosquitto_reconnect succeeded
[Mar 23 22:28:51][mqtt] disconnect_callback called, res=6
[Mar 23 22:28:51][mqtt] mosquitto_loop returned 6. trying reconnect

I tried several config versions for /etc/mosquitto/conf.d/default.conf:

1. No certs, no sockets ``` allow_anonymous false password_file /etc/mosquitto/passwd listener 1883 protocol websockets ```
2. With socket support ``` allow_anonymous false password_file /etc/mosquitto/passwd listener 1883 ```
3. With certs (no socket) ``` listener 8883 certfile /etc/nginx/ssl/wildcard.local.mytld.com.fullchain keyfile /etc/nginx/ssl/wildcard.local.mytld.com.key ```
4. With certs and socket support ``` listener 8083 protocol websockets cafile /etc/nginx/ssl/wildcard.local.mytld.com.ca certfile /etc/nginx/ssl/wildcard.local.mytld.com.crt keyfile /etc/nginx/ssl/wildcard.local.mytld.com.key ```

All of this with adjusted settings in MQTT of /etc/vzlogger.conf.

To no avail. The messages from vzlogger do not reach the MQTT Broker.

Depending on my settings above (with/without socket), I get slightly different error numbers:

This is with socket: ``` [Mar 23 22:28:45][mqtt] mosquitto_publish announce vzlogger/data/chn0/id returned 4 [Mar 23 22:28:45][mqtt] mosquitto_publish announce vzlogger/data/chn0/uuid returned 4 [Mar 23 22:28:45][mqtt] mosquitto_publish announce vzlogger/data/chn1/id returned 4 [Mar 23 22:28:45][mqtt] mosquitto_publish announce vzlogger/data/chn1/uuid returned 4 [Mar 23 22:28:45][mqtt] mosquitto_publish announce vzlogger/data/chn2/id returned 4 [Mar 23 22:28:45][mqtt] mosquitto_publish announce vzlogger/data/chn2/uuid returned 4 [Mar 23 22:28:45][mqtt] mosquitto_reconnect succeeded [Mar 23 22:28:45][mqtt] disconnect_callback called, res=6 [Mar 23 22:28:45][mqtt] mosquitto_loop returned 6. trying reconnect [Mar 23 22:28:46][mqtt] mosquitto_publish announce vzlogger/data/chn0/id returned 4 [Mar 23 22:28:46][mqtt] mosquitto_publish announce vzlogger/data/chn0/uuid returned 4 [Mar 23 22:28:46][mqtt] publish vzlogger/data/chn0/raw=438.000000 [Mar 23 22:28:46][mqtt] mosquitto_publish returned 4 [Mar 23 22:28:46][mqtt] mosquitto_publish announce vzlogger/data/chn1/id returned 4 [Mar 23 22:28:46][mqtt] mosquitto_publish announce vzlogger/data/chn1/uuid returned 4 [Mar 23 22:28:46][mqtt] publish vzlogger/data/chn1/raw=998545.800000 [Mar 23 22:28:46][mqtt] mosquitto_publish returned 4 [Mar 23 22:28:46][mqtt] mosquitto_publish announce vzlogger/data/chn2/id returned 4 [Mar 23 22:28:46][mqtt] mosquitto_publish announce vzlogger/data/chn2/uuid returned 4 [Mar 23 22:28:46][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 ```
This is with certs: ``` [Mar 23 22:18:28][mqtt] mosquitto_publish returned 4 [Mar 23 22:18:28][mqtt] mosquitto_reconnect succeeded [Mar 23 22:18:28][mqtt] disconnect_callback called, res=6 [Mar 23 22:18:28][mqtt] mosquitto_loop returned 6. trying reconnect [Mar 23 22:18:29][mqtt] publish vzlogger/data/chn0/raw=569.000000 [Mar 23 22:18:29][mqtt] mosquitto_publish returned 4 [Mar 23 22:18:29][mqtt] publish vzlogger/data/chn1/raw=998453.200000 [Mar 23 22:18:29][mqtt] mosquitto_publish returned 4 [Mar 23 22:18:29][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:18:29][mqtt] mosquitto_publish returned 4 [Mar 23 22:18:29][mqtt] mosquitto_reconnect succeeded [Mar 23 22:18:29][mqtt] disconnect_callback called, res=6 ```
This was with certs and web socket support ``` [Mar 23 22:04:23][mqtt] publish vzlogger/data/chn1/raw=998327.200000 [Mar 23 22:04:23][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:24][mqtt] publish vzlogger/data/chn0/raw=558.000000 [Mar 23 22:04:24][mqtt] publish vzlogger/data/chn1/raw=998327.400000 [Mar 23 22:04:24][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:25][mqtt] publish vzlogger/data/chn0/raw=558.000000 [Mar 23 22:04:25][mqtt] publish vzlogger/data/chn1/raw=998327.400000 [Mar 23 22:04:25][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:26][mqtt] publish vzlogger/data/chn0/raw=557.000000 [Mar 23 22:04:26][mqtt] publish vzlogger/data/chn1/raw=998327.600000 [Mar 23 22:04:26][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:27][mqtt] publish vzlogger/data/chn0/raw=557.000000 [Mar 23 22:04:27][mqtt] publish vzlogger/data/chn1/raw=998327.800000 [Mar 23 22:04:27][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:28][mqtt] publish vzlogger/data/chn0/raw=557.000000 [Mar 23 22:04:28][mqtt] publish vzlogger/data/chn1/raw=998328.000000 [Mar 23 22:04:28][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:29][mqtt] publish vzlogger/data/chn0/raw=558.000000 [Mar 23 22:04:29][mqtt] publish vzlogger/data/chn1/raw=998328.000000 [Mar 23 22:04:29][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:30][mqtt] publish vzlogger/data/chn0/raw=558.000000 [Mar 23 22:04:30][mqtt] publish vzlogger/data/chn1/raw=998328.200000 [Mar 23 22:04:30][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 ``` No error messages, but I also did not see the data coming in at the MQTT Broker. No output here: ``` mosquitto_sub -h mqtt.local.mytld.com -t "vzlogger/#" -p 8883 -u "telegraf" -P "..." ```
r00t- commented 3 years ago

this lists the error codes returned by mosquitto_publish(): https://mosquitto.org/api/files/mosquitto-h.html#mosquitto_publish and this lists the numeric values: https://github.com/eclipse/mosquitto/blob/master/include/mosquitto.h#L87

4 == MOSQ_ERR_NO_CONN

vzlogger should probably decode those codes for the user, using https://mosquitto.org/api/files/mosquitto-h.html#mosquitto_strerror

Sieboldianus commented 3 years ago

Great, thanks! So the MOSQ_ERR Codes and the List of names are ordered in the docs. This helps!

However, with my last settings, it obvisoully works from the vzlogger site:

With certs and **without** web socket support ``` [Mar 23 22:04:23][mqtt] publish vzlogger/data/chn1/raw=998327.200000 [Mar 23 22:04:23][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:24][mqtt] publish vzlogger/data/chn0/raw=558.000000 [Mar 23 22:04:24][mqtt] publish vzlogger/data/chn1/raw=998327.400000 [Mar 23 22:04:24][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:25][mqtt] publish vzlogger/data/chn0/raw=558.000000 [Mar 23 22:04:25][mqtt] publish vzlogger/data/chn1/raw=998327.400000 [Mar 23 22:04:25][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:26][mqtt] publish vzlogger/data/chn0/raw=557.000000 [Mar 23 22:04:26][mqtt] publish vzlogger/data/chn1/raw=998327.600000 [Mar 23 22:04:26][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:27][mqtt] publish vzlogger/data/chn0/raw=557.000000 [Mar 23 22:04:27][mqtt] publish vzlogger/data/chn1/raw=998327.800000 [Mar 23 22:04:27][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:28][mqtt] publish vzlogger/data/chn0/raw=557.000000 [Mar 23 22:04:28][mqtt] publish vzlogger/data/chn1/raw=998328.000000 [Mar 23 22:04:28][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:29][mqtt] publish vzlogger/data/chn0/raw=558.000000 [Mar 23 22:04:29][mqtt] publish vzlogger/data/chn1/raw=998328.000000 [Mar 23 22:04:29][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 [Mar 23 22:04:30][mqtt] publish vzlogger/data/chn0/raw=558.000000 [Mar 23 22:04:30][mqtt] publish vzlogger/data/chn1/raw=998328.200000 [Mar 23 22:04:30][mqtt] publish vzlogger/data/chn2/raw=1864560.800000 ```

No error messages, but I also do not see the data coming in at the MQTT Broker.

No output here:

mosquitto_sub -h mqtt.local.mytld.com -t "vzlogger/#" -p 8883 -u "telegraf" -P "..."

Below are my configs for the above vzlogger logs. Perhaps someone can see any obvious mistake.

/etc/vzlogger.conf ```conf /** * vzlogger configuration * */ { // General settings "daemon": true, // run periodically "verbosity": 15, // log verbosity (0=log_alert, 1=log_error, 3=log_warning, 5=log_info, 10=log_debug, 15=log_finest) "log": "/var/log/vzlogger.log", // log file, optional "retry": 30, // http retry delay in #seconds // Build-in HTTP server "local": { "enabled": false, // enable local HTTPd for serving live readings "port": 8080, // TCP port for local HTTPd "index": true, // provide index listing of available channels if no UUID was requested "timeout": 30, // timeout for long polling comet requests in seconds (0 disables comet) "buffer": -1 // HTTPd buffer configuration for serving readings, default -1 // >0: number of seconds of readings to serve // <0: number of tuples to server per channel (e.g. -3 will serve 3 tuples) }, // realtime notification settings "push": [ { "url": "http://127.0.0.1:5582" // notification destination, e.g. frontend push-server } ], // mqtt client support (if ENABLE_MQTT set at cmake generation) "mqtt": { "enabled": true, // enable mqtt client. needs host and port as well "host": "mqtt.local.mytld.com", // mqtt server addr "port": 8883, // 1883 for unencrypted, 8883 enc, 8884 enc cert needed, "cafile": "/etc/nginx/ssl/wildcard.local.mytld.com.ca", // optional file with server CA "capath": "", // optional path for server CAs. see mosquitto.conf. Specify only cafile or capath "certfile": "/etc/nginx/ssl/wildcard.local.mytld.com.crt", // optional file for your client certificate (e.g. client.crt) "keyfile": "/etc/nginx/ssl/wildcard.local.mytld.com.key", // optional path for your client certficate private key (e.g. client.key) "keypass": "", // optional password for your private key "keepalive": 30, // optional keepalive in seconds. "topic": "vzlogger/data", // optional topic dont use $ at start and no / at end "user": "smartmeter", // optional user name for the mqtt server "pass": "...", // optional password for the mqtt server "retain": false, // optional use retain message flag "rawAndAgg": false, // optional publish raw values even if agg mode is used }, // Meter configuration "meters": [ { } ], ... } ```
/etc/mosquitto/conf.d/default.conf ```conf allow_anonymous false password_file /etc/mosquitto/passwd listener 1883 localhost listener 8883 certfile /etc/nginx/ssl/wildcard.local.mytld.com.fullchain keyfile /etc/nginx/ssl/wildcard.local.mytld.com.key ```
/etc/telegraf/telegraf.conf ```conf [global_tags] [agent] interval = "10s" round_interval = true metric_batch_size = 1000 metric_buffer_limit = 10000 collection_jitter = "0s" flush_interval = "10s" flush_jitter = "0s" precision = "" debug = true hostname = "" omit_hostname = false [[inputs.mqtt_consumer]] servers = ["tcp://localhost:1883"] topics = [ "vzlogger/#", ] qos = 0 connection_timeout = "30s" persistent_session = true client_id = "influx_telegraf" username = "telegraf" password = "..." data_format = "value" ```
Output/log of telegraf -config /etc/telegraf/telegraf.conf ```conf 2021-03-24T06:07:51Z I! Starting Telegraf 1.18.0 2021-03-24T06:07:51Z I! Loaded inputs: mqtt_consumer 2021-03-24T06:07:51Z I! Loaded aggregators: 2021-03-24T06:07:51Z I! Loaded processors: 2021-03-24T06:07:51Z I! Loaded outputs: influxdb_v2 2021-03-24T06:07:51Z I! Tags enabled: host=iot 2021-03-24T06:07:51Z I! [agent] Config: Interval:10s, Quiet:false, Hostname:"iot", Flush Interval:10s 2021-03-24T06:07:51Z D! [agent] Initializing plugins 2021-03-24T06:07:51Z D! [agent] Connecting outputs 2021-03-24T06:07:51Z D! [agent] Attempting connection to [outputs.influxdb_v2] 2021-03-24T06:07:51Z D! [agent] Successfully connected to outputs.influxdb_v2 2021-03-24T06:07:51Z D! [agent] Starting service inputs 2021-03-24T06:08:00Z D! [inputs.mqtt_consumer] Connecting [tcp://localhost:1883] 2021-03-24T06:08:02Z D! [outputs.influxdb_v2] Buffer fullness: 0 / 10000 metrics 2021-03-24T06:08:10Z D! [inputs.mqtt_consumer] Connecting [tcp://localhost:1883] 2021-03-24T06:08:12Z D! [outputs.influxdb_v2] Buffer fullness: 0 / 10000 metrics ``` -> No messages

And the logs with no certs, no socket, directly connecting to port 1883 on the MQTT broker host (listener set to listener 1883 0.0.0.0):

tail -f /var/log/vzlogger.log | grep mqtt ```conf [Mar 24 07:45:54][mqtt] disconnect_callback called, res=5 [Mar 24 07:45:54][mqtt] mosquitto_loop returned 5. trying reconnect [Mar 24 07:45:55][mqtt] publish vzlogger/data/chn0/raw=-1548.000000 [Mar 24 07:45:55][mqtt] mosquitto_publish returned 4 [Mar 24 07:45:55][mqtt] publish vzlogger/data/chn1/raw=1003517.800000 [Mar 24 07:45:55][mqtt] mosquitto_publish returned 4 [Mar 24 07:45:55][mqtt] mosquitto_publish announce vzlogger/data/chn2/id returned 4 [Mar 24 07:45:55][mqtt] mosquitto_publish announce vzlogger/data/chn2/uuid returned 4 [Mar 24 07:45:55][mqtt] publish vzlogger/data/chn2/raw=1864894.600000 [Mar 24 07:45:55][mqtt] mosquitto_publish returned 4 [Mar 24 07:45:55][mqtt] mosquitto_publish announce vzlogger/data/chn2/id returned 4 [Mar 24 07:45:55][mqtt] mosquitto_publish announce vzlogger/data/chn2/uuid returned 4 [Mar 24 07:45:55][mqtt] mosquitto_reconnect succeeded [Mar 24 07:45:55][mqtt] connect_callback called, res=5 [Mar 24 07:45:55][mqtt] disconnect_callback called, res=5 [Mar 24 07:45:55][mqtt] mosquitto_loop returned 5. trying reconnect ```
Sieboldianus commented 3 years ago

I think I isolated the error.

Using:

allow_anonymous true

in /etc/mosquitto/conf.d/default.conf, the vzlogger MQTT messages arrive:

tail -f /var/log/mosquitto/mosquitto.log
1616568634: Received PUBLISH from vzlogger_4467 (d0, q0, r0, m0, 'vzlogger/data/chn2/raw', ... (14 bytes))
1616568635: Received PUBLISH from vzlogger_4467 (d0, q0, r0, m0, 'vzlogger/data/chn0/raw', ... (12 bytes))
1616568635: Received PUBLISH from vzlogger_4467 (d0, q0, r0, m0, 'vzlogger/data/chn1/raw', ... (14 bytes))
1616568635: Received PUBLISH from vzlogger_4467 (d0, q0, r0, m0, 'vzlogger/data/chn2/raw', ... (14 bytes))
1616568636: Received PUBLISH from vzlogger_4467 (d0, q0, r0, m0, 'vzlogger/data/chn0/raw', ... (12 bytes))
tail -f /var/log/vzlogger.log | grep mqtt
[Mar 24 07:50:39][mqtt] publish vzlogger/data/chn1/raw=1003517.800000
[Mar 24 07:50:39][mqtt] publish vzlogger/data/chn2/raw=1865034.000000
[Mar 24 07:50:40][mqtt] publish vzlogger/data/chn0/raw=-1941.000000
[Mar 24 07:50:40][mqtt] publish vzlogger/data/chn1/raw=1003517.800000
[Mar 24 07:50:40][mqtt] publish vzlogger/data/chn2/raw=1865034.600000
[Mar 24 07:50:41][mqtt] publish vzlogger/data/chn0/raw=-1942.000000
[Mar 24 07:50:41][mqtt] publish vzlogger/data/chn1/raw=1003517.800000
[Mar 24 07:50:41][mqtt] publish vzlogger/data/chn2/raw=1865035.200000

Apparently, it has something to do with the user auth. I checked passwords several times and they are ok. I tested connecting locally with those credentials to the MQTT host, and it worked. Clueless as to now, but it does work for now..

Did anyone get vzlogger with MQTT user-pw auth to work? Perhaps there is an issue with this feature.

Sieboldianus commented 3 years ago

With the anonymous login it now works. I also had to set the following telegraf configs:

[[inputs.mqtt_consumer]]
servers = ["tcp://localhost:1883"]
topics = [
    "vzlogger/#",
]
qos = 0
connection_timeout = "30s"
client_id = "influx_telegraf"
data_format = "value"
data_type = "float"

Note the data_type = "float", which was initially missing and the final issue that prevented values to flow to influxdb2.

r00t- commented 3 years ago

to debug your authentication issues... we should enable detailed logging of the http requests (via curl debug option) in vzlogger.

alternatively, point vzlogger at a tcp listener (nc -vlp 1884 or such) to intercept the data vzlogger is sending, and compare it with a working request from another utility.

Sieboldianus commented 3 years ago

I will try and report.. many thanks!

Sieboldianus commented 3 years ago

Well, it was a user error.

In most guides for setting up MQTT broker, the following command is used to add user/pw:

sudo mosquitto_passwd -c /etc/mosquitto/passwd smartmeter

Of course, I did this twice:

What they don't tell you is that -c flag silently overwrites the passwd file, deleting the first user.

I found out through following the nc rabbit hole - thanks!

Everything looked fine, wich is why I finally checked the /etc/mosquitto/passwd, to find it contained only one user.

Start netcat:

nc -vlp 1884

.. and change vzlogger.conf to use 1884 on the RPi, I get from nc:

connect to [192.168.60.10] from (UNKNOWN) [192.168.60.16] 52912
<MQTT▒vzlogger_14807
smartmeterlk8wwefewf7uZF7NoZLk0%vzlogger/data/chn0/id1-0:16.7.0*2550=vzlogger/data/chn0/uuiddcdbec30-87f6-11eb-bf60-e5d3715178680$vzlogger/data/chn0/raw-6330.0000000$vzlogger/data/chn1/id1-0:1.8.0*2550=vzlogger/data/chn1/uuidbd6c93b0-87f4-11eb-9599-a1e7fb6c47040&vzlogger/data/chn1/raw1011852.8000000$vzlogger/data/chn2/id1-0:2.8.0*2550=vzlogger/data/chn2/uuid2ebb8470-87f7-11eb-8877-3198b438162f0&vzlogger/data/chn2/raw1999996.6000000$v

And in vzlogger logs:

[Mar 25 13:46:04][mqtt] mosquitto_loop returned 4. trying reconnect
[Mar 25 13:46:05][mqtt] mosquitto_reconnect returned 14
[Mar 25 13:46:05][mqtt] mosquitto_loop returned 4. trying reconnect
[Mar 25 13:46:06][mqtt] mosquitto_reconnect returned 14
[Mar 25 13:46:06][mqtt] mosquitto_loop returned 4. trying reconnect
[Mar 25 13:46:07][mqtt] mosquitto_reconnect returned 14
[Mar 25 13:46:07][mqtt] mosquitto_loop returned 4. trying reconnect

Test the same nc connection with mosquitto_pub:

mosquitto_pub -h 192.168.60.10 -t test -m "hello world" -p 1884 -u "smartmeter" -P "lk8wwefewf7uZF7NoZLk"
connect to [192.168.60.10] from 192.168.60.10 [192.168.60.10] 52172
?MQTT▒<mosqpub|17462-iot
smartmeterlk8wwefewf7uZF7NoZLk

Many thanks! And many apologies for this unecessary issue report.

I still leave it open if you want to reference it when error codes are decoded. Feel free to close it though.

r00t- commented 3 years ago

What they don't tell you is that -c flag silently overwrites the passwd file, deleting the first user.

so the root cause is that mosquitto_passwd copies the syntax of htpasswd, which has the bad design decision that -c means "create password file", not "create user"... (and adding a user to a nonexistent file does not implicitly create the file but fails, and asking to create over an existing file will overwrite it without warning.)

not sure what 0% is

most likely the data is binary (i never used mqtt), you should add | xxd to have it dumped in hex.

i will try to create an MR for adding 'mosquitto_strerror()', and you can then help by testing it.