[vz-users] Fehlermeldungen in vzlogger.log
Maik Weidemann
m+vz at weidemann.online
So Feb 20 14:49:48 CET 2022
Moin Tilmann,
hmm...
Was steht denn noch im Log?
> [Feb 20 14:34:11][exec] MeterExec::read: Calling 'solaredge.py'
> [Feb 20 14:34:14][exec] MeterExec::read: Reading line: '1645364054138:
> Battery1_Temperature = 16.399999618530273'
> [Feb 20 14:34:14][exec] MeterExec::read: string: Battery1_Temperature,
> value: 16.400000, timestamp: 1645364054138.000000
> [Feb 20 14:34:14][exec] MeterExec::read: Reading line: '1645364054138:
> Battery1_SOE = 15.0'
> [Feb 20 14:34:14][exec] MeterExec::read: string: Battery1_SOE, value:
> 15.000000, timestamp: 1645364054138.000000
> [Feb 20 14:34:14][exec] MeterExec::read: Closing process 'solaredge.py'
Da sieht ja eigentlich ganz gut aus. In der 3. und 5. Zeile wurde das
gelesene auch richtig interpretiert.
Wie geht es dann weiter im Log? Irgendwann muss ja die Übertragung der
Daten an die Middleware noch kommen...
Gruß
Maik
Am 20.02.22 um 14:40 schrieb Tilman Glötzner:
> Hallo Maik
>
> Ich habe die beiden Einträge für Channel 20 und 21 aus der Datenbank
> entfernt, das Logfile gelöscht und den Loglevel erhöht.
>
> >Du lieferst ja mit $t den Timestamp aus dem Pyhton-Script mit. Und
> der Timestamp ist auch immer unterschiedlich? Im Logfile müssten bei
> >höhrem Loglevel die Ausgaben des Python-Scriptes zu sehen sein. Passt
> das?
>
> Ich denke:
>
> [Feb 20 14:34:11][exec] MeterExec::read: Calling 'solaredge.py'
> [Feb 20 14:34:14][exec] MeterExec::read: Reading line: '1645364054138:
> Battery1_Temperature = 16.399999618530273'
> [Feb 20 14:34:14][exec] MeterExec::read: string: Battery1_Temperature,
> value: 16.400000, timestamp: 1645364054138.000000
> [Feb 20 14:34:14][exec] MeterExec::read: Reading line: '1645364054138:
> Battery1_SOE = 15.0'
> [Feb 20 14:34:14][exec] MeterExec::read: string: Battery1_SOE, value:
> 15.000000, timestamp: 1645364054138.000000
> [Feb 20 14:34:14][exec] MeterExec::read: Closing process 'solaredge.py'
> [Feb 20 14:34:29][exec] MeterExec::read: Calling 'solaredge.py'
> [Feb 20 14:34:31][exec] MeterExec::read: Reading line: '1645364071822:
> Battery1_Temperature = 16.399999618530273'
> [Feb 20 14:34:31][exec] MeterExec::read: string: Battery1_Temperature,
> value: 16.400000, timestamp: 1645364071822.000000
> [Feb 20 14:34:31][exec] MeterExec::read: Reading line: '1645364071822:
> Battery1_SOE = 15.0'
> [Feb 20 14:34:31][exec] MeterExec::read: string: Battery1_SOE, value:
> 15.000000, timestamp: 1645364071822.000000
> [Feb 20 14:34:32][exec] MeterExec::read: Closing process 'solaredge.py'
> [Feb 20 14:34:47][exec] MeterExec::read: Calling 'solaredge.py'
> [Feb 20 14:34:51][exec] MeterExec::read: Reading line: '1645364091269:
> Battery1_Temperature = 16.399999618530273'
> [Feb 20 14:34:51][exec] MeterExec::read: string: Battery1_Temperature,
> value: 16.400000, timestamp: 1645364091269.000000
> [Feb 20 14:34:51][exec] MeterExec::read: Reading line: '1645364091269:
> Battery1_SOE = 15.0'
> [Feb 20 14:34:51][exec] MeterExec::read: string: Battery1_SOE, value:
> 15.000000, timestamp: 1645364091269.000000
> [Feb 20 14:34:51][exec] MeterExec::read: Closing process 'solaredge.py'
> [Feb 20 14:35:06][exec] MeterExec::read: Calling 'solaredge.py'
> [Feb 20 14:35:09][exec] MeterExec::read: Reading line: '1645364109509:
> Battery1_Temperature = 16.399999618530273'
> [Feb 20 14:35:09][exec] MeterExec::read: string: Battery1_Temperature,
> value: 16.400000, timestamp: 1645364109509.000000
> [Feb 20 14:35:09][exec] MeterExec::read: Reading line: '1645364109509:
> Battery1_SOE = 15.0'
> [Feb 20 14:35:09][exec] MeterExec::read: string: Battery1_SOE, value:
> 15.000000, timestamp: 1645364109509.000000
> [Feb 20 14:35:09][exec] MeterExec::read: Closing process 'solaredge.py'
> [Feb 20 14:35:24][exec] MeterExec::read: Calling 'solaredge.py'
> [Feb 20 14:35:27][exec] MeterExec::read: Reading line: '1645364127057:
> Battery1_Temperature = 16.399999618530273'
> [Feb 20 14:35:27][exec] MeterExec::read: string: Battery1_Temperature,
> value: 16.400000, timestamp: 1645364127057.000000
> [Feb 20 14:35:27][exec] MeterExec::read: Reading line: '1645364127057:
> Battery1_SOE = 15.0'
> [Feb 20 14:35:27][exec] MeterExec::read: string: Battery1_SOE, value:
> 15.000000, timestamp: 1645364127057.000000
> [Feb 20 14:35:27][exec] MeterExec::read: Closing process 'solaredge.py'
> [Feb 20 14:35:42][exec] MeterExec::read: Calling 'solaredge.py'
>
> > Interessant ist, dass die beiden Einträge nun wieder in der
> Datenbank sind. Das legt nahe, dass es beim Interpretieren der
> übergebenen Werte aus dem Python-Script schief geht
>
> MariaDB [volkszaehler]> select * from data where channel_id = 20;
> +---------------+------------+----------------+
> | timestamp | channel_id | value |
> +---------------+------------+----------------+
> | 2147483647000 | 20 | 16.39999961853 |
> +---------------+------------+----------------+
> 1 row in set (0.012 sec)
>
> MariaDB [volkszaehler]> select * from data where channel_id = 21;
> +---------------+------------+-------+
> | timestamp | channel_id | value |
> +---------------+------------+-------+
> | 2147483647000 | 21 | 15 |
> +---------------+------------+-------+
> 1 row in set (0.013 sec)
>
>
> >Überigens benutzt VZ nicht den Standard-Unix-Timestamp, der in
> Sekunden ist, sondern einen Timestamp in Milisekunden.
>
> Das berücksichtige ich durch die Multiplication des Timestamps mit 1000:
>
> now = str(int( datetime.datetime.now().timestamp() * 1000 ))
>
>
>
>> "enabled": true,
> >Statt den JSON-Teil auszukommentieren, kannst du einfach enable auf
> false setzten. Das JSON ist ja wohl nicht das Problem.
>
> Stimmt, mache ich das nächste Mal. Danke für den Hinweis.
>
>
> Gruß
>
> Tilman
>
> On 20.02.22 14:22, Maik Weidemann wrote:
>> Hallo Tilman,
>>
>>> "protocol": "exec",
>>> "command": "solaredge.py",
>>> "format": "$t: $i = $v",
>> Du lieferst ja mit $t den Timestamp aus dem Pyhton-Script mit. Und
>> der Timestamp ist auch immer unterschiedlich? Im Logfile müssten bei
>> höhrem Loglevel die Ausgaben des Python-Scriptes zu sehen sein. Passt
>> das?
>>
>> In der Datenbank hat die Daten-Tabelle nämlich die Regel, dass es nur
>> einen Eintrag je (Zeitstempel und Kanal) geben darf. Wenn du nun für
>> einen Kanal einen neuen Datenpunkt hinzufügen möchtest und dabei
>> einen schon verwendeten Zeitstempel verwendet, kommt deine
>> Fehlermeldung: 'UniqueConstraintViolationException'
>>
>>
>> Überigens benutzt VZ nicht den Standard-Unix-Timestamp, der in
>> Sekunden ist, sondern einen Timestamp in Milisekunden.
>>
>>
>>> "enabled": true,
>> Statt den JSON-Teil auszukommentieren, kannst du einfach enable auf
>> false setzten. Das JSON ist ja wohl nicht das Problem.
>>
>>
>> Gruß
>> Maik
>>
>>
>>
>> Am 20.02.22 um 12:57 schrieb Tilman Glötzner:
>>> Hallo Maik
>>>
>>> Klar kann ich die posten. Der Aufruf des Python-scripts mittels exec
>>> ist ganz unten und auskommentiert. Ich probiere jetzt gleich den
>>> Hinweis von Daniel bezüglich der Rechte von /var/log/vzlogger.log
>>> aus -- vielleicht hat das auch einen Einfluss auf den Aufruf des
>>> Python-Scripts.
>>>
>>>
>>> Gruß
>>>
>>> Tilman
>>>
>>> pi:~ $ cat /etc/vzlogger.conf
>>> {
>>> "retry" : 3,
>>> "daemon": true,
>>> "verbosity" : 3,
>>> "log" : "/var/log/vzlogger.log",
>>>
>>> "local" : {
>>> "enabled" : false,
>>> "port" : 8080,
>>> "index" : true,
>>> "timeout" : 30,
>>> "buffer" : 600
>>> },
>>>
>>> "meters" : [
>>> {
>>> "enabled" : true,
>>> "device" : "/dev/ttyUSB0",
>>> "protocol" : "sml",
>>> "parity" : "8N1",
>>> "baudrate" : 9600,
>>> "aggtime" : 60,
>>> "aggfixedinterval" : true,
>>> "channels": [{
>>> "uuid" : "aa7aa260-9d5f-11eb-9ee7-8354e1848012",
>>> "middleware" : "http://localhost/middleware.php",
>>> "identifier" : "1-0:2.8.0", /* energy provided to grid */
>>> "aggmode" : "MAX"
>>> }, {
>>> "uuid" : "e6981cd0-9d5d-11eb-ae08-3bff1417be58",
>>> "middleware" : "http://localhost/middleware.php",
>>> "identifier" : "1-0:1.8.0", /* energy taken from grid */
>>> "aggmode" : "MAX"
>>> }, {
>>> "uuid" : "8611bb00-ab89-11eb-a169-25b5fbc43e2c",
>>> "middleware" : "http://localhost/middleware.php",
>>> "identifier" : "1-0:16.7.0", /* Leistung */
>>> "aggmode" : "none"
>>> }]
>>> },
>>> {
>>> "enabled": true,
>>> "allowskip": false,
>>> "interval": -1,
>>> "aggtime": 60,
>>> "aggfixedinterval": false,
>>> "channels": [{
>>> "uuid": "4d1483b0-d75a-11eb-af5d-4d208cf02964",
>>> "identifier": "Impulse",
>>> "api": "volkszaehler",
>>> "middleware": "http://localhost/middleware.php",
>>> "aggmode": "sum",
>>> "duplicates": 0
>>> }],
>>> "protocol": "s0",
>>> "gpio": 4,
>>> "configureGPIO": true,
>>> "debounce_delay": 0,
>>> "resolution": 1000
>>> },
>>> {
>>> "enabled": true,
>>> "allowskip": false,
>>> "interval": -1,
>>> "aggtime": 60,
>>> "aggfixedinterval": false,
>>> "channels": [{
>>> "uuid": "418ddf40-d802-11eb-b35f-5da471488f6e",
>>> "identifier": "Impulse",
>>> "api": "volkszaehler",
>>> "middleware": "http://localhost/middleware.php",
>>> "aggmode": "sum",
>>> "duplicates": 0
>>> }],
>>> "protocol": "s0",
>>> "gpio": 14,
>>> "configureGPIO": true,
>>> "debounce_delay": 0,
>>> "resolution": 1000
>>> },
>>> {
>>> "enabled": true,
>>> "allowskip": false,
>>> "interval": -1,
>>> "aggtime": 60,
>>> "aggfixedinterval": false,
>>> "channels": [{
>>> "uuid": "1f87bb00-d7d7-11eb-9970-fb2bc024173c",
>>> "identifier": "Impulse",
>>> "api": "volkszaehler",
>>> "middleware": "http://localhost/middleware.php",
>>> "aggmode": "sum",
>>> "duplicates": 0
>>> }],
>>> "protocol": "s0",
>>> "gpio": 15,
>>> "configureGPIO": true,
>>> "debounce_delay": 0,
>>> "resolution": 2000
>>> },
>>> {
>>> "enabled": true,
>>> "allowskip": false,
>>> "interval": -1,
>>> "aggtime": 60,
>>> "aggfixedinterval": false,
>>> "channels": [{
>>> "uuid": "a5989d90-d828-11eb-b73f-9fcefccaa74b",
>>> "identifier": "Impulse",
>>> "api": "volkszaehler",
>>> "middleware": "http://localhost/middleware.php",
>>> "aggmode": "sum",
>>> "duplicates": 0
>>> }],
>>> "protocol": "s0",
>>> "gpio": 17,
>>> "configureGPIO": true,
>>> "debounce_delay": 0,
>>> "resolution": 1000
>>> },
>>> {
>>> "enabled": true,
>>> "allowskip": false,
>>> "interval": -1,
>>> "aggtime": 60,
>>> "aggfixedinterval": false,
>>> "channels": [{
>>> "uuid": "0a2ab800-dd2a-11eb-8cab-375d0acdab21",
>>> "identifier": "Impulse",
>>> "api": "volkszaehler",
>>> "middleware": "http://localhost/middleware.php",
>>> "aggmode": "sum",
>>> "duplicates": 0
>>> }],
>>> "protocol": "s0",
>>> "gpio": 18,
>>> "configureGPIO": true,
>>> "debounce_delay": 30,
>>> "resolution": 200,
>>> "nonblocking_delay": 100000
>>> }
>>> /*,
>>> {
>>> // pv inverter via modbus on tcp an python script
>>> "enabled": true,
>>> "allowskip": true,
>>> "protocol": "exec",
>>> "command": "solaredge.py",
>>> "format": "$t: $i = $v",
>>> "channels": [{
>>> "uuid": "0a2ab800-dd2a-11eb-8cab-375d0acdab22",
>>> "identifier": "Battery1_SOE",
>>> "api": "volkszaehler",
>>> "middleware": "http://localhost/middleware.php",
>>> "aggmode": "none",
>>> "duplicates": 14400
>>> },
>>> {
>>> "uuid": "d55f9f40-91e2-11ec-adc5-c55c95f1d814",
>>> "identifier": "Battery1_Temperature",
>>> "api": "volkszaehler",
>>> "middleware": "http://localhost/middleware.php",
>>> "aggmode": "none",
>>> "duplicates": 14400
>>> }]
>>> }
>>> */
>>> ]
>>> }
>>>
>>> On 20.02.22 12:10, Maik Weidemann wrote:
>>>> Hi Tilmann,
>>>>
>>>>
>>>>> 'UniqueConstraintViolationException': 'An exception occurred while
>>>>> executing 'INSERT INTO data (channel_id, timestamp, value) VALUES
>>>>> (5,?,?)' with params [1645320720000, 2171064]:
>>>> Die Fehlermeldung sagt, dass du einen Wert oder Werte-Paar doppelt
>>>> in die DB eintragen möchtest du das ist nicht erlaubt, da dieser
>>>> Wert / Werte-Paar nur einmal in der Datenbank vorkommen darf.
>>>>
>>>> Kannst du mal deine ganze Konfig posten? Das Problem hängt ggf.
>>>> damit zusammen, dass etwas im "neuen" und "alten" Bereich deiner
>>>> Konfiguration nicht passt.
>>>>
>>>> Gruß
>>>> Maik
>>>>
>>>>
>>>>
>>>> Am 20.02.22 um 03:18 schrieb Tilman Glötzner:
>>>>> Hallo nochmal,
>>>>>
>>>>> ich habe herausgefunden, dass das erste Problem mit dem zweiten
>>>>> zusammenhängt. Wenn ich den Aufruf des Pythonscripts entferne,
>>>>> kömmen keine Fehlermeldungen "Middleware says duplicate value"
>>>>> mehr. Hier deswegen der Teil der Konfig, den ich auskommentiert
>>>>> habe und das Script:
>>>>>
>>>>> ========== /etc/vzlogger.conf ==========
>>>>>
>>>>> /*,
>>>>> {
>>>>> // pv inverter via modbus on tcp an python script
>>>>> "enabled": true,
>>>>> "allowskip": true,
>>>>> "protocol": "exec",
>>>>> "command": "solaredge.py",
>>>>> "format": "$t: $i = $v",
>>>>> "channels": [{
>>>>> "uuid": "0a2ab800-dd2a-11eb-8cab-375d0acdab22",
>>>>> "identifier": "Battery1_SOE",
>>>>> "api": "volkszaehler",
>>>>> "middleware": "http://localhost/middleware.php",
>>>>> "aggmode": "none",
>>>>> "duplicates": 14400
>>>>> },
>>>>> {
>>>>> "uuid": "d55f9f40-91e2-11ec-adc5-c55c95f1d814",
>>>>> "identifier": "Battery1_Temperature",
>>>>> "api": "volkszaehler",
>>>>> "middleware": "http://localhost/middleware.php",
>>>>> "aggmode": "none",
>>>>> "duplicates": 14400
>>>>> }]
>>>>> }
>>>>> */
>>>>> ========END /etc/vzlogger.conf ==========
>>>>>
>>>>> ======== /usr/local/bin/solaredge.py ========
>>>>>
>>>>> !/usr/bin/python3
>>>>> import solaredge_modbus
>>>>> import datetime
>>>>>
>>>>> inverter = solaredge_modbus.Inverter(host="se7rws.fritz.box",
>>>>> port=1502)
>>>>> battery1 = inverter.batteries()["Battery1"]
>>>>> meter1 = solaredge_modbus.Meter(parent=inverter, offset=0)
>>>>>
>>>>> inverter.connect()
>>>>> if inverter.connected():
>>>>> data0 = inverter.read_all()
>>>>> data1 = battery1.read_all()
>>>>>
>>>>> inverter.disconnect()
>>>>> now = str(int( datetime.datetime.now().timestamp() * 1000 ))
>>>>> soe = str(data1["soe"])
>>>>> temperature = str(data1["average_temperature"])
>>>>> print(now + ': Battery1_Temperature = ' + temperature)
>>>>> print(now + ': Battery1_SOE = ' + str(data1["soe"]))
>>>>>
>>>>> inverter.disconnect()
>>>>>
>>>>> ========END /usr/local/bin/solaredge.py ========
>>>>>
>>>>> Danke und viele Grüße
>>>>>
>>>>> Tilman
>>>>>
>>>>> On 20.02.22 02:45, Tilman Glötzner wrote:
>>>>>> Hallo
>>>>>>
>>>>>> 1) in /var/log/vzlogger.log finde ich nach einen restart des
>>>>>> vzlogger viele Message mit unterschiedlichen ChannelIDs wie
>>>>>> folgt. Was will mir das Log sagen?
>>>>>>
>>>>>> SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate
>>>>>> entry '
>>>>>> [Feb 20 02:33:30][chn1] Middleware says duplicated value.
>>>>>> Removing first entry!
>>>>>> [Feb 20 02:33:30][chn1] CURL Error from middleware:
>>>>>> 'UniqueConstraintViolationException': 'An exception occurred
>>>>>> while executing 'INSERT INTO data (channel_id, timestamp, value)
>>>>>> VALUES (5,?,?)' with params [1645320720000, 2171064]:
>>>>>>
>>>>>>
>>>>>> 2) Ausserdem habe ich ein Mini-Pythonscript geschrieben, dass mir
>>>>>> die Temperature und den Ladezustand der Battery von unserer
>>>>>> Solaranlage ausgibt und durch vzlogger (exec) gestartet wird. Die
>>>>>> folgende Fehlermeldung scheint sich darauf zu beziehen. Ich habe
>>>>>> vzlogger über service logger start vom Benutzeraccount pi
>>>>>> gestartet. Das Serviceprogram scheint aber automatisch einen sudo
>>>>>> zu starten und fragt nach dem Benutzerpassword.
>>>>>>
>>>>>> Mir ist daher nicht klar, wie ich vzlogger nicht als root starten
>>>>>> kann -- zumindest wenn "service" verwendet werden soll.
>>>>>>
>>>>>>
>>>>>> Feb 20 02:25:59][main] vzlogger v0.8.0 based on
>>>>>> heads/master-0-gfe937770e4 from Sat, 3 Apr 2021 19:40:20 +0200
>>>>>> started.
>>>>>> [Feb 20 02:25:59][main] log level is 3
>>>>>> [Feb 20 02:25:59][exec] MeterExec::open: MeterExec protocol
>>>>>> cannot be run with root privileges!
>>>>>> [Feb 20 02:25:59][exec] If you really want this,
>>>>>> compile vzlogger with:
>>>>>> [Feb 20 02:25:59][exec] 'cmake -D
>>>>>> METEREXEC_ROOTACCESS=true .'
>>>>>> [Feb 20 02:25:59][mtr6] Cannot open meter
>>>>>> [Feb 20 02:25:59] Skipping meter mtr6
>>>>>> [Feb 20 02:26:22][chn5] Middleware says duplicated value.
>>>>>> Removing first entry!
>>>>>> [Feb 20 02:26:22][chn5] CURL Error from middleware:
>>>>>> 'UniqueConstraintViolationException': 'An exception occurred
>>>>>> while execu
>>>>>> ting 'INSERT INTO data (channel_id, timestamp, value) VALUES
>>>>>> (13,?,?)' with params [1645320382057, 1]:
>>>>>>
>>>>>> Danke und Gruß
>>>>>>
>>>>>> Tilman
Mehr Informationen über die Mailingliste volkszaehler-users