vzlogger fails silently in curl'ing InfluxDB #386
Assignees
Labels
Comments
|
Can you curl from inside the vzlogger container?
Viele Grüße,
Andreas
… Am 29.07.2019 um 10:34 schrieb Daniel Messer ***@***.***>:
I am running vzlogger in a container on a Raspberry Pi using debian-stretch:slim. Until recently everything has been fine reading from my ISKRA MT681 meter into InfluxDB running on another machine. But since a couple of days no data has been sent and the vzlogger container keeps crash-looping. Running interactively I get this with log-level 30:
sudo docker run --name vzlogger --rm -it --device=/dev/ttyUSB0:rw -v /etc/vzlogger.conf:/etc/vzlogger.conf:ro -v /var/log/vzlogger.log:/var/log/vzlogger.log:rw dmesser/vzlogger:latest /usr/local/bin/vzlogger --config /etc/vzlogger.conf --verbose 30
[Jul 29 08:29:18][main] vzlogger v0.7.0 based on heads/master-0-g12e74ddd43 from Sun, 2 Jun 2019 20:48:14 +0200 started.
[Jul 29 08:29:18] Start parsing configuration from /etc/vzlogger.conf
[Jul 29 08:29:18][main] log level is 30
[Jul 29 08:29:18][main] daemon=0, local=0
[Jul 29 08:29:18] Process not daemonized...
[Jul 29 08:29:18] Opened logfile /var/log/vzlogger.log
[Jul 29 08:29:18][push] No pushDataServer defined.
[Jul 29 08:29:18][] ===> Start meters
[Jul 29 08:29:18][mtr0] Meter connection established
[Jul 29 08:29:18][mtr0] Meter thread started
[Jul 29 08:29:18][mtr0] Number of readers: 32
[Jul 29 08:29:18][mtr0] Meter is opened. Starting channels.
[Jul 29 08:29:18][mtr0] Config.daemon: 0
[Jul 29 08:29:18][mtr0] Config.local: 0
[Jul 29 08:29:18][chn0] Logging thread started
[Jul 29 08:29:18][chn0] Start logging thread for influxdb-api. Running as daemon: no
[Jul 29 08:29:18][chn1] Logging thread started
[Jul 29 08:29:18][chn0] InfluxDB API initialize
[Jul 29 08:29:18][] Startup done.
[Jul 29 08:29:18][chn0] api InfluxDB using host 192.168.1.35:8086
[Jul 29 08:29:18][chn1] Start logging thread for influxdb-api. Running as daemon: no
[Jul 29 08:29:18][chn0] api InfluxDB using username vzlogger-write
[Jul 29 08:29:18][chn1] InfluxDB API initialize
[Jul 29 08:29:18][chn0] api InfluxDB using database vzlogger
[Jul 29 08:29:18][chn1] api InfluxDB using host 192.168.1.35:8086
[Jul 29 08:29:18][chn1] api InfluxDB using username vzlogger-write
[Jul 29 08:29:18][chn0] api InfluxDB will use default measurement name "vzlogger"
[Jul 29 08:29:18][chn0] api InfluxDB using tags meter=gesamtverbrauch,unit=kwh
[Jul 29 08:29:18][chn0] api InfluxDB using curl timeout 30
[Jul 29 08:29:18][chn0] api InfluxDB will use default max_batch_inserts 4500
[Jul 29 08:29:18][chn0] api InfluxDB using max_buffer_size: 450000
[Jul 29 08:29:18][chn1] api InfluxDB using database vzlogger
[Jul 29 08:29:18][chn1] api InfluxDB will use default measurement name "vzlogger"
[Jul 29 08:29:18][chn0] api InfluxDB using url 192.168.1.35:8086/write?db=vzlogger&precision=ms
[Jul 29 08:29:18][chn1] api InfluxDB using tags meter=momentanverbrauch,unit=kw
[Jul 29 08:29:18][chn0] Using InfluxDB api
[Jul 29 08:29:18][chn1] api InfluxDB using curl timeout 30
[Jul 29 08:29:18][chn1] api InfluxDB will use default max_batch_inserts 4500
[Jul 29 08:29:18][chn1] api InfluxDB using max_buffer_size: 450000
[Jul 29 08:29:18][chn1] api InfluxDB using url 192.168.1.35:8086/write?db=vzlogger&precision=ms
[Jul 29 08:29:18][chn1] Using InfluxDB api
[Jul 29 08:29:19][mtr0] Got 4 new readings from meter:
[Jul 29 08:29:19][mtr0] Reading: id=1-0:1.8.0*255/ObisIdentifier:1-0:1.8.0*255 value=6771455.10 ts=1564388959918
[Jul 29 08:29:19][mtr0] Reading: id=1-0:1.8.1*255/ObisIdentifier:1-0:1.8.1*255 value=6771455.10 ts=1564388959918
[Jul 29 08:29:19][mtr0] Reading: id=1-0:1.8.2*255/ObisIdentifier:1-0:1.8.2*255 value=0.00 ts=1564388959918
[Jul 29 08:29:19][mtr0] Reading: id=1-0:16.7.0*255/ObisIdentifier:1-0:16.7.0*255 value=363.00 ts=1564388959918
[Jul 29 08:29:19][chn0] Adding reading to queue (value=6771455.10 ts=1564388959918)
[Jul 29 08:29:19][chn1] Adding reading to queue (value=363.00 ts=1564388959918)
[Jul 29 08:29:19][mtr0] Stopped reading.
[Jul 29 08:29:19][chn0] Buffer has 1 items
[Jul 29 08:29:19][chn1] Buffer has 1 items
[Jul 29 08:29:19][chn0] Reading buffer: timestamp 1564388959918 value 6771455.100000
[Jul 29 08:29:19][chn1] Reading buffer: timestamp 1564388959918 value 363.000000
[Jul 29 08:29:19][chn0] request body is vzlogger,uuid=a1839c70-e946-11e8-8e20-b52cd95d444d,meter=gesamtverbrauch,unit=kwh value=6771455.100000 1564388959918
[Jul 29 08:29:19][chn1] request body is vzlogger,uuid=6c5a4660-e943-11e8-bb86-ad8d84144e21,meter=momentanverbrauch,unit=kw value=363.000000 1564388959918
[Jul 29 08:29:19][CURL] CURL: Trying 192.168.1.35...
[Jul 29 08:29:19][CURL] CURL: Trying 192.168.1.35...
[Jul 29 08:29:19][CURL] CURL: TCP_NODELAY set
[Jul 29 08:29:19][] Server stopped.
[Jul 29 08:29:19][] Trying to delete curlSessionProvider...
[Jul 29 08:29:19][CURL] CURL: Curl_http_done: called premature == 1
[Jul 29 08:29:19][CURL] CURL: stopped the pause stream!
[Jul 29 08:29:19][CURL] CURL: Closing connection 0
[Jul 29 08:29:19][CURL] CURL: Curl_http_done: called premature == 1
[Jul 29 08:29:19][CURL] CURL: stopped the pause stream!
[Jul 29 08:29:19][CURL] CURL: Closing connection 0
[Jul 29 08:29:19][] deleted curlSessionProvider
This is my vzlogger.conf with redacted passwords:
{
"retry" : 3,
"daemon": false,
"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" : -1,
"aggfixedinterval" : true,
"channels": [{
"api" : "influxdb",
"host": "192.168.1.35:8086",
"database" : "vzlogger",
"username" : "vzlogger-write",
"password" : "*******",
"max_buffer_size" : 450000,
"timeout": 30,
"uuid": "a1839c70-e946-11e8-8e20-b52cd95d444d",
"identifier" : "1-0:1.8.0",
"tags" : "meter=gesamtverbrauch,unit=kwh"
},
{
"api" : "influxdb",
"host": "192.168.1.35:8086",
"database" : "vzlogger",
"username" : "vzlogger-write",
"password" : "*******",
"max_buffer_size" : 450000,
"timeout": 30,
"uuid": "6c5a4660-e943-11e8-bb86-ad8d84144e21",
"identifier" : "1-0:16.7.0",
"tags" : "meter=momentanverbrauch,unit=kw"
}]
}
]
}
Parsing the source I narrowed it down to curl not working. I can curl the InfluxDB from the PI itself fine, and it appears in InfluxDB logs. Running vzlogger there are no log entries on the InfluxDB side and I presume it's failing silently somewhere trying to curl. Any ideas?
—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or mute the thread.
|
|
Yep, when passing thru the binary from the host OS (because |
|
ping @mbehr1 any idea what to make of the logfile? |
|
Funny enough, repeated runs of above containers produce different output in regards to Examples: Looks like some sort of race condition is kicking in. |
|
The problem is also reproducible outside of the container environment, on an up-to-date Raspbian (Debian Stretch). |
|
I‘m confused by the „server stopped“ messages too. Which server? Why?
Looks like we‘d need better instrumentation in the influx provider to see whats going on.
Viele Grüße,
Andreas
… Am 05.08.2019 um 10:50 schrieb Daniel Messer ***@***.***>:
The problem is also reproducible outside of the container environment, on an up-to-date Raspbian (Debian Stretch).
—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub, or mute the thread.
|
|
I was watching the network stack via |
|
Then https://github.com/volkszaehler/vzlogger/blob/master/src/api/InfluxDB.cpp would be the place to start and add more logging. cc'ing anyone who has worked on influx. |
@dmesser you might also just implement a "dumb" PHP endpoint that accepts and logs any GET and POST request- I feel influxdb is not much more than that. See if that works, if not its probably not specific to influxdb but rather network-related. |
|
Yeah, I've found the |
|
I am an deliberate C++ noob, so I am of little help. The logs show that both channels often get data at the same time and two vz::api::InfluxDB::send() are running in parallel. I would suggest the do another test with only chn0 configured (comment out the other channel in vzlogger.conf). If it is a race condition in vz::api::InfluxDB::send(), it should work with only one channel configured. Then I would assume it is connected to buf handling. If it still fails, I would argue that the problem it is not in vz::api::InfluxDB::send(), but in the layers below (curl, network). |
|
@okrause thanks for the suggestion. I tried with a single channel only and the result is the same. I concur this seems like a problem at some lower level (IMHO Whereas this RPI environment has the following: |
|
I think the problem is the following:
you’re not running vzlogger as a daemon. So it will try to do just one reading and then exit.
But the sendind is done async.
This sending is aborted by the shutdown after the one readings have been read.
[Jul 29 08:29:19][] Trying to delete curlSessionProvider… <- here the two requests are still pending and get cancelled.
[Jul 29 08:29:19][CURL] CURL: Curl_http_done: called premature == 1
[Jul 29 08:29:19][CURL] CURL: stopped the pause stream!
[Jul 29 08:29:19][CURL] CURL: Closing connection 0
[Jul 29 08:29:19][CURL] CURL: Curl_http_done: called premature == 1
[Jul 29 08:29:19][CURL] CURL: stopped the pause stream!
[Jul 29 08:29:19][CURL] CURL: Closing connection 0
[Jul 29 08:29:19][] deleted curlSessionProvider
This is my vzlogger.conf with redacted passwords:
{
"retry" : 3,
"daemon": false, <- not as daemon
Can you try to enable daemon mode and see whether that removes/hides the problem?
Am 10.08.2019 um 22:56 schrieb Daniel Messer ***@***.***>:
@okrause <https://github.com/okrause> thanks for the suggestion. I tried with a single channel only and the result is the same. I concur this seems like a problem at some lower level (IMHO curl). Interestingly enough this was working on an x86_64 machine with the same OS (Debian 9 Stretch). It had the following versions of libcurl installed:
libcurl3/stable,stable,now 7.52.1-5+deb9u8 amd64 [installed,automatic]
libcurl4-openssl-dev/stable,stable,now 7.52.1-5+deb9u8 amd64 [installed]
Whereas this RPI environment has the following:
libcurl3/oldstable,now 7.52.1-5+deb9u9 armhf [installed,automatic]
libcurl3-gnutls/oldstable,now 7.52.1-5+deb9u9 armhf [installed,automatic]
libcurl4-openssl-dev/oldstable,now 7.52.1-5+deb9u9 armhf [installed]
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub <#386?email_source=notifications&email_token=AAY3UC3Q6H5KXHOY33GY6GTQD4TRHA5CNFSM4IHQAUZ2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD4AU3EA#issuecomment-520179088>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAY3UCZNYYFUKAYS7APQKGTQD4TRHANCNFSM4IHQAUZQ>.
Gruß
Matthias
|
|
A better fix would be to wait a few seconds at shutdown if the connection is still in use:
CurlSessionProvider::~CurlSessionProvider()
{
// curl_easy_cleanup for each CURL*
timespec ts;
clock_gettime(CLOCK_REALTIME , &ts);
ts.tv_sec+=1;
pthread_mutex_timedlock(&_map_mutex, &ts); // try max 1s to acquire the lock. There might have been another thread pthread_cancelled while owning the lock.
for (map_it it = _easy_handle_map.begin(); it!=_easy_handle_map.end(); ++it)
{
CurlUsage cu = (*it).second;
would need to wait here is cu.inUse!
curl_easy_cleanup(cu.eh);
}
curl_global_cleanup();
pthread_mutex_unlock(&_map_mutex);
pthread_mutex_destroy(&_map_mutex);
}
I can add a patch for waiting a few seconds at shutdown until the connection is not in use any longer.
How long does the access to your database usually take? (How long shall we wait at shutdown?)
Am 11.08.2019 um 06:59 schrieb Matthias Behr ***@***.***>:
I think the problem is the following:
you’re not running vzlogger as a daemon. So it will try to do just one reading and then exit.
But the sendind is done async.
This sending is aborted by the shutdown after the one readings have been read.
[Jul 29 08:29:19][] Trying to delete curlSessionProvider… <- here the two requests are still pending and get cancelled.
> [Jul 29 08:29:19][CURL] CURL: Curl_http_done: called premature == 1
> [Jul 29 08:29:19][CURL] CURL: stopped the pause stream!
> [Jul 29 08:29:19][CURL] CURL: Closing connection 0
> [Jul 29 08:29:19][CURL] CURL: Curl_http_done: called premature == 1
> [Jul 29 08:29:19][CURL] CURL: stopped the pause stream!
> [Jul 29 08:29:19][CURL] CURL: Closing connection 0
> [Jul 29 08:29:19][] deleted curlSessionProvider
> This is my vzlogger.conf with redacted passwords:
>
> {
> "retry" : 3,
> "daemon": false, <- not as daemon
Can you try to enable daemon mode and see whether that removes/hides the problem?
> Am 10.08.2019 um 22:56 schrieb Daniel Messer ***@***.*** ***@***.***>>:
>
> @okrause <https://github.com/okrause> thanks for the suggestion. I tried with a single channel only and the result is the same. I concur this seems like a problem at some lower level (IMHO curl). Interestingly enough this was working on an x86_64 machine with the same OS (Debian 9 Stretch). It had the following versions of libcurl installed:
>
> libcurl3/stable,stable,now 7.52.1-5+deb9u8 amd64 [installed,automatic]
> libcurl4-openssl-dev/stable,stable,now 7.52.1-5+deb9u8 amd64 [installed]
> Whereas this RPI environment has the following:
>
> libcurl3/oldstable,now 7.52.1-5+deb9u9 armhf [installed,automatic]
> libcurl3-gnutls/oldstable,now 7.52.1-5+deb9u9 armhf [installed,automatic]
> libcurl4-openssl-dev/oldstable,now 7.52.1-5+deb9u9 armhf [installed]
> —
> You are receiving this because you were mentioned.
> Reply to this email directly, view it on GitHub <#386?email_source=notifications&email_token=AAY3UC3Q6H5KXHOY33GY6GTQD4TRHA5CNFSM4IHQAUZ2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD4AU3EA#issuecomment-520179088>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAY3UCZNYYFUKAYS7APQKGTQD4TRHANCNFSM4IHQAUZQ>.
>
Gruß
Matthias
Gruß
Matthias
|
mbehr1
added a commit
to mbehr1/vzlogger
that referenced
this issue
Aug 11, 2019
To fix volkszaehler#386 we wait up to 5 times with 1sec in between (so max 4s) at shutdown before we cancel the pending curl sessions. Issue: volkszaehler#386
|
See (potential) fix in PR#387. Can you give it a try? (@dmesser) |
|
@mbehr1 thanks for that PR - I can confirm that it's now sending data. Also in daemon mode it's not working at least on the PI itself (outside a container). Will report back when it's also working when running in a container. |
|
So it's working in the container again now as well, from the original source code base. I am not entirely sure what was wrong in the end - it works flawlessly now. Thank you for bearing with me. I guess I got confused with your meaning of the term I opened #389 and will close this issue. Thanks for all your help. |
mbehr1
added a commit
that referenced
this issue
Aug 11, 2019
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
I am running vzlogger in a container on a Raspberry Pi using debian-stretch:slim. Until recently everything has been fine reading from my ISKRA MT681 meter into InfluxDB running on another machine. But since a couple of days no data has been sent and the vzlogger container keeps crash-looping. Running interactively I get this with log-level 30:
This is my vzlogger.conf with redacted passwords:
Parsing the source I narrowed it down to curl not working. I can curl the InfluxDB from the PI itself fine, and it appears in InfluxDB logs. Running vzlogger there are no log entries on the InfluxDB side and I presume it's failing silently somewhere trying to curl. Any ideas?
The text was updated successfully, but these errors were encountered: