[vz-users] Problem Middleware ??!!

Mon Feb 11 12:18:17 CET 2013

On Sun, 10 Feb 2013 16:09:27 +0100
Thorben Thuermer <r00t at constancy.org> wrote:
> On Sun, 10 Feb 2013 15:18:37 +0100
> "Heiko W." <luckyheiko at hotmail.com> wrote:
> > hab ja seit gestern den Zähler nun so am laufen wie ich das gerne hätte .. 
> > auch die ganze Nacht ohne Probleme geloggt usw .. 
> > 
> > nun hab ich heute morgen das 'frontend' aufgerufen .. 
> > und siehe da, genau ab da, keine Daten mehr geloggt .. 
> 
> das scheint dem merkwuerdigen problem aus
> "[vz-users] frontend tot nach refresh button in IE oder FF"
> http://volkszaehler.org/pipermail/volkszaehler-users/2013-February/001418.html
> aehnlich zu sein...
> vielleicht kommen wir dem hier mal naeher...

so, wo ich jetzt zugriff auf deinen system habe zeigt sich, dass
das der arme rechnerchen wohl etwas ueberfordert ist...

jedesmal wenn die daten eines kanals mit der 4h-standardansicht geladen werden,
laeuft eine derartige anfrage:
mysql> SELECT timestamp, value, 1 AS count FROM data WHERE channel_id='28' AND timestamp >= '1360490872286';
58523 rows in set (48.83 sec)

und wenn dann noch das frontend kommt, und die daten deiner _acht_ kanaele
_gleichzeitig_ laden will, wird's arg langsam...
... aber doch irgendwann fertig...

aber in der zwischenzeit koennen die anfragen von vzlogger nicht
beantwortet werden, wohl weil die anzahl der php-prozesse auf 4 begrenzt ist,
und danach beantwortet der webserver die anfragen dann nichtmehr:

[pid  4113] send(12, "POST /middleware.php/data/04456200-713d-11e2-9b56-234cc60a13ef.json HTTP/1.1\r\nHost: localhost\r\nContent-type: application/json\r\nAccept: application/json\r\nUser-Agent: vzlogger/0.3.3 (libcurl/7.26.0 OpenSSL/1.0.1c zlib/1.2.7 libidn/1.25 libssh2/1.4.1 librtmp/2.3)\r\nContent-Length: 162\r\n\r\n[ [ 1360579446054.120117, -3791.400000 ], [ 1360579447429.320068, -3803.300000 ], [ 1360579448920.097168, -3791.100000 ], [ 1360579450179.183105, -3801.200000 ] ]", 447, MSG_NOSIGNAL) = 447
[pid  4112] recv(11, "HTTP/1.1 200 OK\r\nX-Powered-By: PHP/5.4.4-12\r\nContent-type: application/json\r\nTransfer-Encoding: chunked\r\nDate: Mon, 11 Feb 2013 10:44:11 GMT\r\nServer: lighttpd/1.4.31\r\n\r\n11\r\n{\"version\":\"0.2\"}\r\n0\r\n\r\n", 16384, 0) = 197

das war der letzte verarbeitete request...

[pid  4112] send(11, "POST /middleware.php/data/0e2c3850-713d-11e2-a384-4bda743e342c.json HTTP/1.1\r\nHost: localhost\r\nContent-type: application/json\r\nAccept: application/json\r\nUser-Agent: vzlogger/0.3.3 (libcurl/7.26.0 OpenSSL/1.0.1c zlib/1.2.7 libidn/1.25 libssh2/1.4.1 librtmp/2.3)\r\nContent-Length: 170\r\n\r\n[ [ 1360579446046.865967, 1365814.300000 ], [ 1360579447422.274170, 1365815.800000 ], [ 1360579448914.128174, 1365817.300000 ], [ 1360579450174.973877, 1365818.800000 ] ]", 455, MSG_NOSIGNAL) = 455
[pid  4107] send(7, "POST /middleware.php/data/ebdae520-713c-11e2-84eb-c1884cb92d66.json HTTP/1.1\r\nHost: localhost\r\nContent-type: application/json\r\nAccept: application/json\r\nUser-Agent: vzlogger/0.3.3 (libcurl/7.26.0 OpenSSL/1.0.1c zlib/1.2.7 libidn/1.25 libssh2/1.4.1 librtmp/2.3)\r\nContent-Length: 42\r\n\r\n[ [ 1360579448026.369141, -2954.700000 ] ]", 326, MSG_NOSIGNAL) = 326

hier haengt's dann fuer eine weile,
weil die erlaubten php-prozesse alle mit frontend-requests beschaeftigt
sind, und auf daten von der datenbank warten...

[pid  4110] recv(9, "HTTP/1.1 200 OK\r\nX-Powered-By: PHP/5.4.4-12\r\nContent-type: application/json\r\nTransfer-Encoding: chunked\r\nDate: Mon, 11 Feb 2013 10:45:43 GMT\r\nServer: lighttpd/1.4.31\r\n\r\n11\r\n{\"version\":\"0.2\"}\r\n0\r\n\r\n", 16384, 0) = 197
[pid  4110] write(3, "[Feb 11 11:45:44][ch3]  CURL: HTTP 1.1 or later with persistent connection, pipelining supported\n", 97) = 97
[pid  4110] send(9, "POST /middleware.php/data/ddfea5f0-713c-11e2-8667-8d4b408bc4f7.json HTTP/1.1\r\nHost: localhost\r\nContent-type: application/json\r\nAccept: application/json\r\nUser-Agent: vzlogger/0.3.3 (libcurl/7.26.0 OpenSSL/1.0.1c zlib/1.2.7 libidn/1.25 libssh2/1.4.1 librtmp/2.3)\r\nContent-Length: 2093\r\nExpect: 100-continue\r\n\r\n", 308, MSG_NOSIGNAL) = 308
[pid  4110] recv(9, "HTTP/1.1 417 Expectation Failed\r\nContent-Type: text/html\r\nContent-Length: 363\r\nConnection: close\r\nDate: Mon, 11 Feb 2013 10:45:44 GMT\r\nServer: lighttpd/1.4.31\r\n\r\n<?xml version=\"1.0\" encoding=\"iso-8859-1\"?>\n<!DOCTYPE html PUBLIC \"-//W3C//DTD XHTML 1.0 Transitional//EN\"\n         \"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd\">\n<html xmlns=\"http://www.w3.org/1999/xhtml\" xml:lang=\"en\" lang=\"en\">\n <head>\n  <title>417 - Expectation Failed</title>\n </head>\n <body>\n  <h1>417 - Expectation Failed</h1>\n </body>\n</html>\n", 16384, 0) = 525

und jetzt faengt libcurl aus irgendeinem grund an, mit requests "Expect: 100"
header zu senden, wohl weil die requests wegen den
in der "pause" angefallenen daten groesser ausfallen als sonst...

was lighthttpd dann wohl nicht unterstuetzt...
das problem ist wohl bekannt:
http://www.google.com/search?q=lighthttpd+expect+header
http://redmine.lighttpd.net/issues/1017

als WORKAROUND habe ich mal in vzlogger code eingebaut,
der curl die verwendung von Expect: verbietet:
http://curl.haxx.se/libcurl/c/curl_easy_setopt.html

root at raspberrypi:~/vzlogger# git diff src/api.c

diff --git a/src/api.c b/src/api.c
index 9515e49..2ac0055 100644
--- a/src/api.c
+++ b/src/api.c
@@ -119,6 +119,9 @@ int api_init(channel_t *ch, api_handle_t *api) {
        api->headers = curl_slist_append(api->headers, "Accept: application/json");
        api->headers = curl_slist_append(api->headers, agent);
 
+       // WORKAROUND for lighthttp not supporting Expect: properly
+       api->headers = curl_slist_append(api->headers, "Expect: ");
+
        api->curl = curl_easy_init();
        if (!api->curl) {
                return EXIT_FAILURE;


damit funktioniert vzlogger dann nach der durch den frontend-reload verursachten
zwangspause anstandslos weiter.

- Thorben


