I have a problem with Emoncms 8.08 running on WAMP (on a Windows Home server) which happens every now and then (roughly one to two times a day in irregular intervals).
I am measuring consumption with an Emontx, send this to a Jeelink (mounted to my Home server) via RF and then use a script to send the data to the Emoncms running on this same server.
First thing I can see is that there is missing data in the graphs (straight line). The data is missing for exactly two hours (~+0-3 minutes) then everything works as before. If I look into the log of the python script, I see that the data is send every 10 seconds (my measuring interval on the EmonTx) to the apache server and the server responds correctly with an 'ok'.
In the apache access log I see the following (just a snippet):
127.0.0.1 - - [07/Apr/2014:08:46:19 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=25,67,195,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:08:46:29 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=24,67,194,226 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:08:46:39 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=21,67,193,226 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:08:46:49 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=20,66,193,226 HTTP/1.1" 200 2 192.168.0.111 - - [07/Apr/2014:08:46:58 +0200] "GET /emoncms/feed/timevalue.json ?id=20 HTTP/1.1" 200 33 192.168.0.111 - - [07/Apr/2014:08:46:58 +0200] "GET /emoncms/feed/list.json ?userid=1 HTTP/1.1" 200 876 127.0.0.1 - - [07/Apr/2014:10:15:55 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=13,67,193,226 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:55 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=10,67,194,226 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:55 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=8,66,193,226 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:55 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=7,66,194,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:55 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=5,66,194,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:56 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=3,67,194,228 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:56 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=1,66,195,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:56 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-1,66,194,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:56 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-3,66,194,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:56 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-5,66,194,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:56 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-7,66,193,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:56 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-7,67,194,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:56 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-10,66,223,228 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:56 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-11,66,222,228 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-12,66,191,228 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-14,67,278,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-15,66,314,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-16,78,326,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-16,92,335,227 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-16,93,332,228 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-16,92,330,228 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-16,92,325,228 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-16,92,315,228 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-15,94,331,228 HTTP/1.1" 200 2 127.0.0.1 - - [07/Apr/2014:10:15:57 +0200] "GET /emoncms/input/post.json ?apikey=5049a05b53942b6ac122351be5f4f02c&node=10&csv=-15,94,334,228 HTTP/1.1" 200 2
So, until 8:46 the data is received every 10 seconds. Then no access any more (apart from the two requests by 192.168.0.111, my mobile phone). Then, suddenly at ~ 10:15:55 (at this time, I did a 'restart all services' on the apache), all the 'missing' data seems to 'stream in' within seconds (I have already seen one data message every ~15ms) . Even worse, the data is not even in the correct sequence!!! I can tell this by comparing to the python log.
Does anybody have an idea how this can happen? Where is this data 'stored' in the mean time (between 'transmission' in the Python script (plus ACK!)and 'reception' by the apache server)?
The apache server is unresponsive during these two hours, means that I get no response in the browser.
(Is it possible to format the log so that it is readable but does not overwrite the 'Active forum topics'?)
[Edited - line breaks added between "json" & "?" - Moderator (RW)]
Re: Emoncms WAMP problem
The oem_gateway buffers the requests in memory when they can't be delivered to the server. When connectivity is restored it then submits all backed up transactions in chronological order.
If you deliberately took Apache down for 2h maintenance this is the behaviour you would see. In your case you need to establish why Apache is dropping out for these periods. At least because you're using the gateway you don't actually lose any data :)
Re: Emoncms WAMP problem
This is problematic. I fixed a bug in the gateway a long time ago to make sure the data is sent in the correct order, since some post-processing actions rely on this order. I understand your gateway log attests this is done correctly. But if the http GET are treated in random order, the processing chain is spoiled.
I don't know what we can do about that. Add a small interval between two data posts and cross fingers (scary) ? Modify the post-processing to allow data insertion (breaks everything) ? Forget about data buffering (too bad) ?
Re: Emoncms WAMP problem
Sorry, Dave, Jérôme, I am not yet using the OEM-Gateway :-(
And, because all the (held back) data arrives within a few seconds (without the original time information), they are actually 'lost' (they will not correctly 'fill up' the gap). This might be different with the OEM-Gateway, though.
Is there an explanation why apache answers with an 'ok'? But does not notify the 'access' in the acces.log? And the data is actually not written to the data base?
Thank you very much for your assistance!
Re: Emoncms WAMP problem
OK, you confused me by referring to Python. The emoncms Pi module is written in PHP, I think?
To be honest I would just switch to the oem_gateway. It's a lot more robust and I think you may find it back-fills the data to the correct time slots after an outage.
Re: Emoncms WAMP problem
Sorry Dave, did not want to confuse you :-)
I am referring to a Python script that is used to read serial data from a Jeelink (usb module with RFM12B transceiver). From here: https://github.com/emoncms/development/blob/master/Tutorials/Python/PyLink/pylink.py
I have to find out how to use the OEM Gateway on my Windows home server. Then I might switch to that.
I am still wondering why apache (or who?) is answering the GET request with 'ok' but does not 'process' it.
part of the Python script:
while(1) .... req = "node="+str(nodeid)+"&csv="+','.join(datacsv) print req,": ", # Send to emoncms conn = httplib.HTTPConnection(domain) try: conn.request("GET", "/"+emoncmspath+"/input/post.json?apikey="+apikey+"&"+req) response = conn.getresponse() except: print "Emoncms server not available!" else: print response.read()always shows:
in the console output.
Re: Emoncms WAMP problem
Oh, so your base is a Windows PC with a Jeelink USB module.
I suppose you could have the OEM Gateway run on that. I don't expect blocking issues.
Well, in fact, it depends how you communicate with the Jeelink module (how you setup groupe, node id and freq), but I think the RFM2Pi is based on Jeelink, so I'm quite confident.
Re: Emoncms WAMP problem
I just 'saw' it happen again!
Now what I saw is a bit different to what I thought before (just not enough info in the logs). It seems that the Python script is 'stalled' for just a while. It prints:
and is stuck there. No response ('ok') and also no error message. Then after a bit more than two minutes it sent out all the data that was in the input buffer (serial input buffer?) within a few seconds. Does it run with such a low priority that it does not get any processing time?
Re: Emoncms WAMP problem
Could be a connection issue, script stalled waiting for an answer, timeout too long.
Timeout are not as simple as it seems. I have a timeout issue in the OEM Gateway, too:
https://github.com/Jerome-github/oem_gateway/issues/1
Re: Emoncms WAMP problem
I am not sure if it really matters, but I am now running the Python shell with administrative rights ('start as administrator'). Possibly coincidence, but I have not had any of the above mentioned problems since then.
(the other change I made was to set a timeout in HTTPConnection():
I have no idea if this really does something)
Jörg.
Re: Emoncms WAMP problem
Isn't the timeout change enough to solve the issue ?
Re: Emoncms WAMP problem
Hello everyone.
I am having a very similar problem on my local installation. Apache stops responding, the browser disconnects emoncms or waits indefinitely.
If Apache restart everything works again, after a very long time not happen again.
I'm using Windows XP, Wamp. Emoncms 8.0.6 and 8.1.1 give the same fault on two different PC, the other is in Windows 7.
The apache log shows:
[Fri Apr 11 08:38:45.671875 2014] [mpm_winnt:notice] [pid 2656:tid 264] AH00422: Parent: Received shutdown signal -- Shutting down the server.
[Fri Apr 11 08:38:54.656250 2014] [mpm_winnt:notice] [pid 2948:tid 1884] AH00364: Child: All worker threads have exited.
[Fri Apr 11 08:38:59.703125 2014] [mpm_winnt:notice] [pid 2656:tid 264] AH00430: Parent: Child process 2948 exited successfully.
[Fri Apr 11 10:33:09.171875 2014] [ssl:warn] [pid 2340:tid 264] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Fri Apr 11 10:33:10.296875 2014] [mpm_winnt:notice] [pid 2340:tid 264] AH00455: Apache/2.4.4 (Win32) OpenSSL/0.9.8y PHP/5.4.16 configured -- resuming normal operations
[Fri Apr 11 10:33:10.312500 2014] [mpm_winnt:notice] [pid 2340:tid 264] AH00456: Server built: Feb 23 2013 13:07:34
[Fri Apr 11 10:33:10.312500 2014] [core:notice] [pid 2340:tid 264] AH00094: Command line: 'c:\\wamp\\bin\\apache\\apache2.4.4\\bin\\httpd.exe -d C:/wamp/bin/apache/Apache2.4.4'
[Fri Apr 11 10:33:10.328125 2014] [mpm_winnt:notice] [pid 2340:tid 264] AH00418: Parent: Created child process 532
[Fri Apr 11 10:33:12.921875 2014] [ssl:warn] [pid 532:tid 1884] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Fri Apr 11 10:33:13.109375 2014] [mpm_winnt:notice] [pid 532:tid 1884] AH00354: Child: Starting 150 worker threads.
[Fri Apr 11 10:48:11.343750 2014] [:error] [pid 532:tid 580] [client 192.168.0.13:1084] Message sent
[Fri Apr 11 10:48:53.046875 2014] [:error] [pid 532:tid 612] [client 192.168.0.13:1088] Message sent
[Fri Apr 11 10:53:12.718750 2014] [mpm_winnt:notice] [pid 2340:tid 264] AH00422: Parent: Received shutdown signal -- Shutting down the server.
[Fri Apr 11 10:53:14.734375 2014] [mpm_winnt:notice] [pid 532:tid 1884] AH00364: Child: All worker threads have exited.
[Fri Apr 11 10:53:15.031250 2014] [mpm_winnt:notice] [pid 2340:tid 264] AH00430: Parent: Child process 532 exited successfully.
[Fri Apr 11 10:53:21.359375 2014] [ssl:warn] [pid 2940:tid 264] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Fri Apr 11 10:53:21.828125 2014] [mpm_winnt:notice] [pid 2940:tid 264] AH00455: Apache/2.4.4 (Win32) OpenSSL/0.9.8y PHP/5.4.16 configured -- resuming normal operations
[Fri Apr 11 10:53:21.828125 2014] [mpm_winnt:notice] [pid 2940:tid 264] AH00456: Server built: Feb 23 2013 13:07:34
[Fri Apr 11 10:53:21.828125 2014] [core:notice] [pid 2940:tid 264] AH00094: Command line: 'c:\\wamp\\bin\\apache\\apache2.4.4\\bin\\httpd.exe -d C:/wamp/bin/apache/Apache2.4.4'
[Fri Apr 11 10:53:21.828125 2014] [mpm_winnt:notice] [pid 2940:tid 264] AH00418: Parent: Created child process 2240
[Fri Apr 11 10:53:25.484375 2014] [ssl:warn] [pid 2240:tid 1884] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Fri Apr 11 10:53:25.687500 2014] [mpm_winnt:notice] [pid 2240:tid 1884] AH00354: Child: Starting 150 worker threads.
[Fri Apr 11 10:53:35.281250 2014] [:error] [pid 2240:tid 584] [client 192.168.0.13:1127] Message sent
[Fri Apr 11 10:58:12.718750 2014] [mpm_winnt:notice] [pid 2940:tid 264] AH00422: Parent: Received shutdown signal -- Shutting down the server.
[Fri Apr 11 10:58:14.718750 2014] [mpm_winnt:notice] [pid 2240:tid 1884] AH00364: Child: All worker threads have exited.
[Fri Apr 11 10:58:15.078125 2014] [mpm_winnt:notice] [pid 2940:tid 264] AH00430: Parent: Child process 2240 exited successfully.
[Fri Apr 11 10:59:39.187500 2014] [ssl:warn] [pid 2560:tid 264] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Fri Apr 11 10:59:39.953125 2014] [mpm_winnt:notice] [pid 2560:tid 264] AH00455: Apache/2.4.4 (Win32) OpenSSL/0.9.8y PHP/5.4.16 configured -- resuming normal operations
[Fri Apr 11 10:59:39.953125 2014] [mpm_winnt:notice] [pid 2560:tid 264] AH00456: Server built: Feb 23 2013 13:07:34
[Fri Apr 11 10:59:39.953125 2014] [core:notice] [pid 2560:tid 264] AH00094: Command line: 'c:\\wamp\\bin\\apache\\apache2.4.4\\bin\\httpd.exe -d C:/wamp/bin/apache/Apache2.4.4'
[Fri Apr 11 10:59:39.953125 2014] [mpm_winnt:notice] [pid 2560:tid 264] AH00418: Parent: Created child process 2408
[Fri Apr 11 10:59:41.968750 2014] [ssl:warn] [pid 2408:tid 1884] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Fri Apr 11 10:59:42.093750 2014] [mpm_winnt:notice] [pid 2408:tid 1884] AH00354: Child: Starting 150 worker threads.
[Fri Apr 11 11:04:05.218750 2014] [:error] [pid 2408:tid 596] [client 192.168.0.13:1202] Message sent
[Fri Apr 11 11:04:47.437500 2014] [:error] [pid 2408:tid 580] [client 192.168.0.13:1205] Message sent
[Fri Apr 11 11:05:29.906250 2014] [:error] [pid 2408:tid 612] [client 192.168.0.13:1210] Message sent
[Fri Apr 11 11:06:00.281250 2014] [mpm_winnt:warn] [pid 2408:tid 280] (OS 64)El nombre de red especificado ya no est\E1 disponible. : AH00341: winnt_accept: Asynchronous AcceptEx failed.
[Fri Apr 11 11:06:11.843750 2014] [:error] [pid 2408:tid 580] [client 192.168.0.13:1215] Message sent
[Fri Apr 11 11:06:54.062500 2014] [:error] [pid 2408:tid 580] [client 192.168.0.13:1218] Message sent
[Fri Apr 11 11:13:59.437500 2014] [mpm_winnt:notice] [pid 2560:tid 264] AH00422: Parent: Received shutdown signal -- Shutting down the server.
[Fri Apr 11 11:14:01.437500 2014] [mpm_winnt:notice] [pid 2408:tid 1884] AH00364: Child: All worker threads have exited.
[Fri Apr 11 11:14:01.656250 2014] [mpm_winnt:notice] [pid 2560:tid 264] AH00430: Parent: Child process 2408 exited successfully.
[Fri Apr 11 11:14:04.687500 2014] [ssl:warn] [pid 4032:tid 264] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Fri Apr 11 11:14:05.000000 2014] [mpm_winnt:notice] [pid 4032:tid 264] AH00455: Apache/2.4.4 (Win32) OpenSSL/0.9.8y PHP/5.4.16 configured -- resuming normal operations
[Fri Apr 11 11:14:05.000000 2014] [mpm_winnt:notice] [pid 4032:tid 264] AH00456: Server built: Feb 23 2013 13:07:34
[Fri Apr 11 11:14:05.000000 2014] [core:notice] [pid 4032:tid 264] AH00094: Command line: 'c:\\wamp\\bin\\apache\\apache2.4.4\\bin\\httpd.exe -d C:/wamp/bin/apache/Apache2.4.4'
[Fri Apr 11 11:14:05.000000 2014] [mpm_winnt:notice] [pid 4032:tid 264] AH00418: Parent: Created child process 2416
[Fri Apr 11 11:14:06.921875 2014] [ssl:warn] [pid 2416:tid 1884] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Fri Apr 11 11:14:07.046875 2014] [mpm_winnt:notice] [pid 2416:tid 1884] AH00354: Child: Starting 150 worker threads.
[Fri Apr 11 11:16:26.812500 2014] [:error] [pid 2416:tid 604] [client 127.0.0.1:1805] 0, referer: http://localhost/emoncms/event
[Fri Apr 11 11:16:52.062500 2014] [:error] [pid 2416:tid 612] [client 127.0.0.1:1819] Message sent, referer: http://localhost/emoncms/event
[Fri Apr 11 11:21:24.625000 2014] [mpm_winnt:warn] [pid 2416:tid 208] (OS 64)El nombre de red especificado ya no est\E1 disponible. : AH00341: winnt_accept: Asynchronous AcceptEx failed.
[Fri Apr 11 11:27:48.062500 2014] [mpm_winnt:warn] [pid 2416:tid 208] (OS 64)El nombre de red especificado ya no est\E1 disponible. : AH00341: winnt_accept: Asynchronous AcceptEx failed.
[Fri Apr 11 11:27:48.062500 2014] [mpm_winnt:warn] [pid 2416:tid 208] (OS 64)El nombre de red especificado ya no est\E1 disponible. : AH00341: winnt_accept: Asynchronous AcceptEx failed.
[Fri Apr 11 11:28:38.062500 2014] [mpm_winnt:warn] [pid 2416:tid 208] (OS 64)El nombre de red especificado ya no est\E1 disponible. : AH00341: winnt_accept: Asynchronous AcceptEx failed.
Any tips?
Re: Emoncms WAMP problem
"Isn't the timeout change enough to solve the issue ?"
Possibly yes, but I do not know!?
System was running ok during the last few days, but today I had a similar problem again. Apache stopped responding to the messages again. If I look into the apache access log (the error log shows nothing) then I see that it became unresponsive again after the following:
(Messages from 127.0.0.1 come from the Python script sending data received from a Jeelink, 192.168.0.122 is my mobile phone)
It seems that apache always stops responding only after these accesses by another client (or other clients in general ?). Is there any good reason for this?