aggmode=MAX corrupts negative values (was: Negativ value will not shown correct)

[alexandergeiler]

Hi,

I use VZLogger with a TTL-IR infrared read/write head with a ISKRA MT681 power meter.

It works fine and I can see the reader gets the data from the power meter. vzlogger.log [Apr 24 07:41:53][mtr0] Reading: id=1-0:1.8.0255/ObisIdentifier:1-0:1.8.0255 value=1356603.90 ts=1587710513812 [Apr 24 07:41:53][mtr0] Reading: id=1-0:1.8.1255/ObisIdentifier:1-0:1.8.1255 value=1356603.90 ts=1587710513812 [Apr 24 07:41:53][mtr0] Reading: id=1-0:1.8.2255/ObisIdentifier:1-0:1.8.2255 value=0.00 ts=1587710513812 [Apr 24 07:41:53][mtr0] Reading: id=1-0:2.8.0255/ObisIdentifier:1-0:2.8.0255 value=34004.10 ts=1587710513812 [Apr 24 07:41:53][mtr0] Reading: id=1-0:2.8.1255/ObisIdentifier:1-0:2.8.1255 value=34004.10 ts=1587710513812 [Apr 24 07:41:53][mtr0] Reading: id=1-0:2.8.2255/ObisIdentifier:1-0:2.8.2255 value=0.00 ts=1587710513812 [Apr 24 07:41:53][mtr0] Reading: id=1-0:16.7.0255/ObisIdentifier:1-0:16.7.0255 value=38.00 ts=1587710513812

I would like to use the internal web server to use the data in another system. Negativ values will not shown correct in the internal web server. Any idea how I can get the negativ value with the internal web server?

[r00t-]

can you post a binary dump from your meter and your config, such that this can be reproduced?

does it works correctly when logging the data to an API? actually one can see in the log in your screenshot ("CURL:") that the same 2e-308 value is being submitted, so the error must be in the sml/D0(?) decoding, not in the local webserver.

[alexandergeiler]

can you post a binary dump from your meter and your config, such that this can be reproduced?

How can I send a binary from the meter? I deleted the config in vzlogger (because it was not working, but I can try to reproduce it, I would need better weather conditions for that :-))

does it works correctly when logging the data to an API?

Yes, Volkszaehler logs the data correct if I send the data via URL to the API. I use the following API: http://localhost/middleware.php/data/a277fce0-a0ed-11ea-b211-ff0a6ae34e3e.json?operation=add&value=-120

actually one can see in the log in your screenshot ("CURL:") that the same 2e-308 value is being submitted, so the error must be in the sml/D0(?) decoding, not in the local webserver.

I think thats true. The web server is working correct, because I can send the data with my own python script correct to volkszaehler.

[r00t-]

this does not only affect the local webserver, but also the reporting to the volkszaehler.org middlware by vzlogger:

you refuse to explain the setup you are using, but from your comments, it seems you are using some software other than vzlogger for logging to the volkszaehler middleware, and thus only notice it in attempts to use vzlogger with it's local webserver?

we cannot debug this without a copy of: your vzlogger.conf (or the relevant parts thereof). a dump of the input data that produces this issue, as sent by your meter (this can be created with the dump_file option for D0 meters, or simply using any terminal program and writing the data received from the meter to a file.)

[hydrocontrol]

Hello, I have the same problem, that negative power values are not transferred correctly to the JSON object. For positive values, everything works fine.

Below is an excerpt from my log.

The reading -360 from the meter is correct. In the JSON request body, the number is corrupted.

The relevant lines:

[Mar 14 08:35:50][chn0] Adding reading to queue (value=-360.00 ts=1615707350403) [Mar 14 08:35:50][MAX] -360.000000 @ 1615707350403 [Mar 14 08:35:50][MAX] RESULT 0.000000 @ 1615707350403 [Mar 14 08:35:50][chn0] ==> number of tuples: 1 [Mar 14 08:35:50][chn0] compare: 0 1615707350403 [Mar 14 08:35:50][chn0] JSON request body: [ [ 1615707350403, 2.2250738585072014e-308 ] ]

Am I right in assuming that the raw data, as produced by the meter, collected by /dev/ttyAMA0, and read by vzlogger, is not the problem? Because the reading in the queue is correct. If you still need a dump of the raw data, I will try to figure out, how to give it to you.

Here is my configuration file, as found in /etc/vzlogger.conf vzlogger.conf.txt

My meter is ISKRA MT681, (but as mentioned, I don't think this is relevant for the problem :-) I don't plan to use the middleware. The plan is to use the information about the currently available power for controlling a photovoltaic charging station.

In the controlling software for the charging station, I use this http get request: localhost:8081

And I get this response: { "version": "0.8.0", "generator": "vzlogger", "data": [ { "uuid": "29c36640-7e99-11eb-ba3e-a7203e53d9c2", "last": 1615718715537, "interval": -1, "protocol": "sml", "tuples": [ [ 1615718715537, 2.2250738585072014e-308 ] ] } ] }

Thank you for your help.

[Mar 14 08:35:48][main] vzlogger v0.8.0 based on heads/master-0-g7787266915 from Thu, 11 Mar 2021 03:20:12 +0100 started.
[Mar 14 08:35:48][mtr0] Creating new meter with protocol sml.
[Mar 14 08:35:48][mtr0] Meter configured, enabled.
[Mar 14 08:35:48]       New meter initialized (protocol=sml)
[Mar 14 08:35:48]       Configure channel.
[Mar 14 08:35:48][chn0] New channel initialized (uuid=...53d9c2 api=volkszaehler id=1-0:16.7.0*255)
[Mar 14 08:35:48]       Have 1 meters.
[Mar 14 08:35:48][main] log level is 10
[Mar 14 08:35:48][main] local=1
[Mar 14 08:35:48]       Daemonize process...
[Mar 14 08:35:48]       Opened logfile /var/log/vzlogger.log
[Mar 14 08:35:48][]     ===> Start meters
[Mar 14 08:35:48][mtr0] Meter connection established
[Mar 14 08:35:48][mtr0] Meter thread started
[Mar 14 08:35:48][mtr0] Meter is opened. Starting channels.
[Mar 14 08:35:48][chn0] Logging thread started
[Mar 14 08:35:48][http] Starting local interface HTTPd on port 8081
[Mar 14 08:35:48][mtr0] Number of readers: 32
[Mar 14 08:35:48][mtr0] Config.local: 1
[Mar 14 08:35:48][]     Startup done.
[Mar 14 08:35:48][chn0] Start logging thread for volkszaehler-api.
[Mar 14 08:35:48][chn0] Using default volkszaehler api.
[Mar 14 08:35:50][chn0] Adding reading to queue (value=-360.00 ts=1615707350403)
[Mar 14 08:35:50][MAX]  -360.000000 @ 1615707350403
[Mar 14 08:35:50][MAX]  RESULT 0.000000 @ 1615707350403
[Mar 14 08:35:50][chn0] ==> number of tuples: 1
[Mar 14 08:35:50][chn0] compare: 0 1615707350403
[Mar 14 08:35:50][chn0] JSON request body: [ [ 1615707350403, 2.2250738585072014e-308 ] ]
[Mar 14 08:35:50][chn0] CURL: Couldn't resolve host name
[Mar 14 08:35:50][chn0] Waiting 30 secs for next request due to previous failure
[Mar 14 08:35:52][chn0] Adding reading to queue (value=-398.00 ts=1615707352297)
[Mar 14 08:35:52][MAX]  -398.000000 @ 1615707352297
[Mar 14 08:35:52][MAX]  RESULT 0.000000 @ 1615707352297
[Mar 14 08:35:53][http] Local request received: method=GET url=/ mode=(null)
[Mar 14 08:35:53][29c366==> number of tuples: 1
[Mar 14 08:35:54][chn0] Adding reading to queue (value=-413.00 ts=1615707354084)
[Mar 14 08:35:54][MAX]  0.000000 @ 1615707352297
[Mar 14 08:35:54][MAX]  -413.000000 @ 1615707354084
[Mar 14 08:35:54][MAX]  RESULT 0.000000 @ 1615707354084
[Mar 14 08:35:55][chn0] Adding reading to queue (value=-388.00 ts=1615707355824)
[Mar 14 08:35:55][MAX]  0.000000 @ 1615707354084
[Mar 14 08:35:55][MAX]  -388.000000 @ 1615707355824
[Mar 14 08:35:55][MAX]  RESULT 0.000000 @ 1615707355824
[Mar 14 08:35:55][http] Local request received: method=GET url=/ mode=(null)
[Mar 14 08:35:55][29c366==> number of tuples: 1
[Mar 14 08:35:57][http] Local request received: method=GET url=/ mode=(null)
[Mar 14 08:35:57][29c366==> number of tuples: 1
[Mar 14 08:35:57][chn0] Adding reading to queue (value=-453.00 ts=1615707357491)
[Mar 14 08:35:57][MAX]  0.000000 @ 1615707355824
[Mar 14 08:35:57][MAX]  -453.000000 @ 1615707357491
[Mar 14 08:35:57][MAX]  RESULT 0.000000 @ 1615707357491
[Mar 14 08:35:58][http] Local request received: method=GET url=/ mode=(null)
[Mar 14 08:35:58][29c366==> number of tuples: 1
[Mar 14 08:35:59][chn0] Adding reading to queue (value=-472.00 ts=1615707359065)
[Mar 14 08:35:59][MAX]  0.000000 @ 1615707357491
[Mar 14 08:35:59][MAX]  -472.000000 @ 1615707359065
[Mar 14 08:35:59][MAX]  RESULT 0.000000 @ 1615707359065
[Mar 14 08:35:59][http] Local request received: method=GET url=/ mode=(null)
[Mar 14 08:35:59][29c366==> number of tuples: 1
[Mar 14 08:36:00][chn0] Adding reading to queue (value=-490.00 ts=1615707360564)
[Mar 14 08:36:00][MAX]  0.000000 @ 1615707359065

[r00t-]

I have the same problem, that negative power values are not transferred correctly to the JSON object.

interesting to know that more than one user is affected. but still the problem must be relatively rare, given that it wasn't reported earlier.

Am I right in assuming that the raw data, as produced by the meter, collected by /dev/ttyAMA0, and read by vzlogger, is not the problem? Because the reading in the queue is correct.

i do not know. if i had both the config and the input data, it should be possible to reproduce the issue on my computer, and then i can simply run vzlogger in a debugger, and inspect it's internal variables to see at which point the value is corrupted. that's way more straightforward than staring at a log and scratching one's head until the solution magically appears.

[hydrocontrol]

Ok, thank you for the input. I will provide the input data. I hope to get it done tomorrow.

[hydrocontrol]

Hi r00t, I have attached 2 files. The first is created with cat /dev/ttyAMA0 >> /home/pi/serial from ISKRA MT681.txt the 2nd is a copy from the command window from xxd </dev/ttyAMA0

I just tried to capture a longer serial data flow, but now the sun is gone :-( I hope it's enough...

serial from ISKRA MT681.txt xxd output.txt

[mbehr1]

I think the problem is the "aggmode":"max". This does not get ignored! Try to set it to "none".

[hydrocontrol]

Ok, I would like to try aggmode "none". However, the sun is gone now :-) How do i feed the serial data, which I captured earlier today, into vzlogger?

[alexandergeiler]

you refuse to explain the setup you are using, but from your comments, it seems you are using some software other than >vzlogger for logging to the volkszaehler middleware, and thus only notice it in attempts to use vzlogger with it's local webserver?

refuse is not correct. I tested it with vzlogger but I was not able to send negativ values to the middleware. For that reason, I developed my own python script, that is reading my ISKRA MT681 vial SML prococal and send it to the middleware by myself.

As I have already written, I need favorable weather conditions to be able to reproduce the effect. only then can I configure vzlogger again.

we cannot debug this without a copy of: your vzlogger.conf (or the relevant parts thereof). a dump of the input data that produces this issue, as sent by your meter (this can be created with the dump_file option for D0 >meters, or simply using any terminal program and writing the data received from the meter to a file.)

That´s clear. May be you found the issue already. Otherwise I will try to reproduce the issue again in some days. Weather forcast is not that good :-)

[mbehr1]

@hydrocontrol I never tried it / never checked whether letting libsml "device" point simply to an existing (capture) file. You can give it a try but it might fail (due to e.g. not being able to set speed,...).

[r00t-]

@alexandergeiler: well, you still didn't post your config. do you also have aggmode: max in there? (to fit mbehr1's theory)

[r00t-]

@hydrocontrol: thanks, but it seems both dumps you posted are corrupt. :
valid sml messages should have a header and footer of three times 0x1b, which your dumps are clearly lacking.

@mbehr1: i just tried, pointing "device" to a file seems to work fine (= we lack error checking), just that vzlogger is royally confused by hitting EOF, and will re-open the file and loop over it forever. but it's sufficient for debugging - if i had a valid dump.

[hydrocontrol]

Okay, it seems I had bad luck with my first attempts. Apparently I started somewhere randomly in the bit stream. I tried again, and most of the times the dump starts with 1b1b1b1b01010101 now, which is the start of an SML file. It seems I need to start the dump during a break, while the smart meter is not broadcasting.

I used xxd -p </dev/ttyAMA0, and then copied the content from the command line interface to a text file, and then removed all the CRLF line breaks. The result is attached. It will not show the "negative value" error - it is simply to verify that I am able to deliver valid dumps. xxd_output_better.txt

The file created with the cat command is probably binary. If I use xxd to convert it to hex, it also starts with 1b1b1b1b01010101 serial_created_with_cat.txt

[hydrocontrol]

Hi guys, I changed the aggmode to "none", and now negative values show correctly! Thank you all for your help. In the volkzähler Wiki software:controller:vzlogger:vzlogger_conf_parameter https://wiki.volkszaehler.org/software/controller/vzlogger/vzlogger_conf_parameter

it says:

aggtime -1 deaktiviert die Funktion sicher

and

aggmode Mathematische Art der Aggregation die der vzlogger vornehmen soll. Nur wirksam in Verbindung mit aggtime größer als 0.

This is apparently not entirely correct, or at least misleading.

I have added the below sentences to the wiki. Please feel free to correct and specifiy my additions.

aggtime: "aggtime" arbeitet zusammen mit ''aggmode''. bei -1: Bitte auch ''aggmode'' auf "none" setzen, um undefiniertes Verhalten zu vermeiden.

aggmode: Wenn aggtime auf -1 steht (deaktiviert), dann bitte auch aggmode auf „none“ setzen, um undefiniertes Verhalten zu vermeiden.

[r00t-]

indeed...

in the reading_thread, buffer->aggregate() is called unconditionally: https://github.com/volkszaehler/vzlogger/blob/master/src/threads.cpp#L122

buffer::agregate() only does nothing if_aggmode == NONE: https://github.com/volkszaehler/vzlogger/blob/master/src/Buffer.cpp#L52

if aggmode==MAX, it will calculate the max of the value(s) and DBL_MIN: https://github.com/volkszaehler/vzlogger/blob/master/src/Buffer.cpp#L58

and i guess DBL_MIN==2.2250738585072014e-308

actually this looks like a BUG to me, aggregation should not introduce some random value into the aggregation. starting the aggregation for max with "the smallest possible value" is just some way to simplify the code, and it's bugged because DBL_MIN is the smallest positive value, so it arbitrarily breaks aggregation of negative values.

we should either initialize the aggregate with the first reading, or with the actual smallest (negative) value.

as for the wiki, it's REALLY unfortunate that the wiki explicitly stated that aggtime=-1 is a SAFE way to disable aggregation. i checked the history, and that statement has been there since the page was initially created:

2017/03/14 17:56 software:controller:vzlogger:conf_parameter – angelegt jau +18.4 KB https://wiki.volkszaehler.org/software/controller/vzlogger/conf_parameter?rev=1489510606 (@J-A-U : was this you? it's all your fault! ;) )

[r00t-]

https://bytes.com/topic/c/answers/216260-most-negative-double-value so it should be -DBL_MAX, instead of DBL_MIN (and should previouslyh have been 0, if anything, not DBL_MIN)

[r00t-]

it remains an open question if that aggregation mode actually makes sense for negative values.

it should probably use the largest absolute value, ignoring the sign. (but return it with it's sign.) just that we're out of luck if the aggregation timeframe contains both positive and negative values. (falling back to average seems the most sensible option?)

[J-A-U]

What solution you prefer. Aggmode MAX is mostly suited for continuously increasing meters, there will be no negative values. For powersensor with possible negative values everybody should use AVG! Or NONE...

[r00t-]

@J-A-U: i only mentioned you because it seems you authored the wiki entry that claims that setting aggtime to -1 is a safe way to disable aggregations. can you maybe still tell where that came from? (i'm not complaining, just curious.)

(while it does not actually disable aggregation, but aggregates groups of size 1, which should be NOP anyway, but is/was broken for MAX if values are negative, which should be fixed, regardless of the mode making sense in any particular situation.)

[J-A-U]

It was an assumption on basis of the (usual) behavior.

[r00t-]

should we maybe really disable aggregatiof if aggtime is <1? while with #464, it should no longer corrupt any data. we could still either of:

• automatically set aggmode=none if aggtime <1
• log a warning if aggmode!=none and aggtime <1
• error out startup if aggmode!=none and aggtime <1