Inputs not processed - WARNING emonCMS send failure: wanted 'ok' but got ''

Paul · 2018-05-05T11:46:36.422Z

pi@raspberrypi:~ $ /home/pi/emonhub/src/emonhub.py --version
emonHub Pre-Release Development Version (rc1.2)

I believe that I installed this Sep14th 1017 (because that’s my oldest emoncms data)

pb66 · 2018-05-05T12:01:56.026Z

And the git branch?

Can you run git diff in the emonhub folder and show us the output?

Your url has “time=0” then “apikey=” then the data. emonhub original has the apikey then the data followed by “sentat=” (not “time=”) last.

I have no idea where those changes are from and I guess if wget can truncate the request at the “time=0”, maybe emonhub can do the same.

Paul · 2018-05-05T12:08:07.485Z

pi@raspberrypi:~/emonhub $ git diff
diff --git a/conf/emonhub.conf b/conf/emonhub.conf
deleted file mode 100644
index 881899f..0000000
--- a/conf/emonhub.conf
+++ /dev/null
@@ -1,67 +0,0 @@
-# SPECIMEN emonHub configuration file
-# Note that when installed from apt, a new config file is written
-# by the debian/postinst script, so changing this file will do
-# nothing in and of itself.
-
-# Each Interfacer and each Reporter has
-# - a [[name]]: a unique string
-# - a type: the name of the class it instantiates
-# - a set of init_settings (depends on the type)
-# - a set of runtimesettings (depends on the type)
-# Both init_settings and runtimesettings sections must be defined,
-# even if empty. Init settings are used at initialization,
-# and runtime settings are refreshed on a regular basis.
-
-# All lines beginning with a '#' are comments and can be safely removed.
-
-#######################################################################
:...skipping...
diff --git a/conf/emonhub.conf b/conf/emonhub.conf
deleted file mode 100644
index 881899f..0000000
--- a/conf/emonhub.conf
+++ /dev/null
@@ -1,67 +0,0 @@
-# SPECIMEN emonHub configuration file
-# Note that when installed from apt, a new config file is written
-# by the debian/postinst script, so changing this file will do
-# nothing in and of itself.
-
-# Each Interfacer and each Reporter has
-# - a [[name]]: a unique string
-# - a type: the name of the class it instantiates
-# - a set of init_settings (depends on the type)
-# - a set of runtimesettings (depends on the type)
-# Both init_settings and runtimesettings sections must be defined,
-# even if empty. Init settings are used at initialization,
-# and runtime settings are refreshed on a regular basis.
-
-# All lines beginning with a '#' are comments and can be safely removed.
-
-#######################################################################
-#######################    emonHub  settings    #######################
-#######################################################################
-[hub]
-
-# loglevel must be one of DEBUG, INFO, WARNING, ERROR, and CRITICAL
-# see here : http://docs.python.org/2/library/logging.html
-loglevel = WARNING
-
-
-#######################################################################
-#######################        Reporters        #######################
-#######################################################################
-[reporters]
-
-# This reporter sends data to emonCMS
:

pb66 · 2018-05-05T12:14:17.912Z

3rd time lucky? And the git branch?

Paul · 2018-05-05T12:15:22.538Z

pi@raspberrypi:~/emonhub $ git branch
* development

pb66 · 2018-05-05T12:32:51.869Z

Ok found the change, the one and only change since October 2015 and the only “real” code change since early 2014.

Can you try editing the reporter file

nano /home/pi/emonhub/src/emonhub_reporter.py

and remove ’ time=0& ’ from line 332 and add '+" &sentat="+str(sentat) ’ to line 333 so that you have

post_url = self._settings['url']+'/input/bulk'+'.json?apikey='
post_body = "data="+data_string+"&sentat="+str(sentat)

and restart emonhub. If that works ok then try using “time=0” again by editing to

post_url = self._settings['url']+'/input/bulk'+'.json?apikey='
post_body = "data="+data_string+"&time=0"

and restarting emonhub again.

There are advantages to using the “time=0” rather than “sentat=” but (based on the behavior seen when using wget) the issue might be the position in the request rather than the option used.

Still not sure why this has become a problem now, this change was made in February 2017.

pb66 · 2018-05-05T12:39:38.494Z

Actually before you change emonhub you should try backdating emoncms to see if it’s a recent change that triggered the issue eg

git checkout 9.8.28

going back to a version you know worked ok ie what ever you were running a week a go.

Looking at the emoncmc commit history, there are a fair few changes that have been made to the bulk api in the input module and there are changes in the index.php and params.php that affect the input api’s too, so it would be of great value to know if backdating resolves the issue. (Here’s the 9.8.28 to current changes https://github.com/emoncms/emoncms/compare/9.8.28...master#diff-828e0013b8f3bc1bb22b4f57172b019d)

Paul · 2018-05-05T13:15:45.844Z

I didn’t see your later post until after I had made the changes, but…
making the changes to;

pb66:

post_url = self._settings[‘url’]+‘/input/bulk’+‘.json?apikey=’
post_body = “data=”+data_string+“&sentat=”+str(sentat)

resulted in no 403 errors in the emonhub log, but emoncms inputs were not updated (I assume that was the expected behaviour)

but adding in ‘time=0’ again brought back the 403 error

pb66 · 2018-05-05T13:27:01.320Z

Paul:

resulted in no 403 errors in the emonhub log, but emoncms inputs were not updated (I assume that was the expected behaviour)

My bad! We also needed " sentat = int(time.time()) " added around line 330. The no 403 errors is reassuring, but the no input updates will undoubtedly be due to the missing sentat time (eg "sentat= null ") .

You should end up with

# time that the request was sent at
sentat = int(time.time())

# Construct post_url (without apikey)
post_url = self._settings['url']+'/input/bulk'+'.json?apikey='
post_body = "data="+data_string+"&sentat="+str(sentat)

Paul:

but adding in ‘time=0’ again brought back the 403 error

Can you stash the above changes made in emonhub and backdate emoncms just to see if it’s recent changes affecting the use of “time=0”?

Paul · 2018-05-05T14:08:15.095Z

Well adding;

post_url = self._settings['url']+'/input/bulk'+'.json?apikey='
post_body = "data="+data_string+"&sentat="+str(sentat)

to emonhub_reporter.py gives the log;

2018-05-05 15:01:41,494 DEBUG 5 NEW FRAME : 1525528901.49 OK 10 170 255 162 9 80 4 97 96 8 8 (-72)
2018-05-05 15:01:41,496 DEBUG 5 Timestamp : 1525528901.49
2018-05-05 15:01:41,497 DEBUG 5      Node : 10
2018-05-05 15:01:41,498 DEBUG 5    Values : [-86, 2466, 1104, 24673, 2056]
2018-05-05 15:01:41,500 DEBUG 5      RSSI : -72
2018-05-05 15:01:46,473 DEBUG 6 NEW FRAME : 1525528906.47 OK 10 172 255 154 9 80 4 95 96 8 8 (-76)
2018-05-05 15:01:46,475 DEBUG 6 Timestamp : 1525528906.47
2018-05-05 15:01:46,478 DEBUG 6      Node : 10
2018-05-05 15:01:46,480 DEBUG 6    Values : [-84, 2458, 1104, 24671, 2056]
2018-05-05 15:01:46,482 DEBUG 6      RSSI : -76

Whilst adding;

# time that the request was sent at
sentat = int(time.time())

# Construct post_url (without apikey)
post_url = self._settings['url']+'/input/bulk'+'.json?apikey='
post_body = "data="+data_string+"&sentat="+str(sentat)

gives this;

2018-05-05 15:06:17,744 WARNING emonCMS couldn't send to server, HTTPError: 403
2018-05-05 15:06:17,747 WARNING emonCMS send failure: wanted 'ok' but got ''
2018-05-05 15:06:17,849 INFO emonCMS sending: https://digitalnut.co.uk/emoncms/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1525529171.26,9,1111,24741,2493,-75],[1525529176.45,10,-1206,2417,1109,24724,2512,-77]]&sentat=1525529177

pb66:

Can you stash the above changes made in emonhub and backdate emoncms just to see if it’s recent changes affecting the use of “time=0”?

Tried that, but I’m still getting the 403 error rolling back emoncms, and stashing the emonhub changes.

pb66 · 2018-05-05T14:31:19.635Z

Paul:

to emonhub_reporter.py gives the log;

Ok, it looks like the

Paul:

resulted in no 403 errors in the emonhub log

was a red herring, it looks like the reporter isn’t sending, i thought you meant you were getting a “ok” when you said no 403 errors.

Paul:

Tried that, but I’m still getting the 403 error rolling back emoncms, and stashing the emonhub changes.

How far did you roll back? The edit’s you’ve made to emonhub revert the Feb 2017 change to use “time=” and is using code that’s worked since 2014 and I am currently using on many devices out in the field reporting back to my server running 9.8.18, I’m always slow and very reluctant to update my live server because it always seems to end in disaster.

Do you know for sure what version you were using a week or so ago?

Back in Jan you were running 9.8.27, I can find any other confirmations (Copy system info to clipboard).

Paul · 2018-05-05T14:36:01.039Z

pb66:

Do you know for sure what version you were using a week or so ago?

I can’t check at the moment (visitors) but will make further checks this evening, and get back to you.

pb66 · 2018-05-05T14:39:05.776Z

Yeah, I’m supposed to be painting the garden fences, so that’s fine by me

borpin · 2018-05-05T15:15:32.752Z

I’d be inclined to use tshark to check the emoncms box and see if the HTTP request is being received or not. Only used it once when I was working on the node-red node but was very enlightening! The 403 error seemed to come from the python call to the http library which implies the request was sent, just not understood by the receiving HTTP server (rather than emoncms).

For me tshark -Y http.request -T fields -e http.request.full_uri did the job, Took a while to work out the correct command!

I’d also not want to question either of your knowledge on these things, but the call/syntax bulk.json appears to be undocumented in the input API.

pb66 · 2018-05-05T18:26:10.422Z

Something like wireshark might help if Paul is willing to give it a whirl, I do not know it well enough to suggest if/how it might be useful.

borpin:

I’d also not want to question either of your knowledge on these things, but the call/syntax bulk.json appears to be undocumented in the input API.

Well that’s an interesting observation!

emonhub has always used bulk.json since inception. In fact OEMG used it prior to that.

Looking at the emoncms commits it seems it was first seen in emoncms March 2013 and as far as I can tell it’s still with us today I believe.

The confusion (at least for me, having looked at this for an hour now) seems to stem from the “emoncms input improvements” commit on 18 Aug 2017 which lists “removal of .json requirement” as one of the improvements. And in that commit it seems to remove all the “.json” strings from the documentation but they remain in the actual code. So I’m not sure if anything changed or if it was only removed from the documentation. As a side note the “JSON like format” appears to get un-deprecated in this commit too.

Looking at the feed api’s they all still have “.json” in both the documentation and the code so I’m not clear what should be happening there at all.

I get the impression the “.json” strings might be superfluous and perhaps it doesn’t even matter if the’re used or not but I haven’t tested or confirmed in any way.

But I believe (but I’m far from certain) these changes (if in deed there are any actual changes) were far enough back that it’s unlikely to be just coming to the surface now. If it is due to a change, I would expect it to be a more recent one.

[edit] Found a forum thread and the PR notes for that commit, but no explanation of the “.json” thing.

borpin · 2018-05-05T21:25:18.575Z

pb66:

Something like wireshark might help if Paul is willing to give it a whirl, I do not know it well enough to suggest if/how it might be useful.

Key thing it does is tell you what is actually being passed across the network on the specified protocol/port. You might think that a certain URI is being sent (as per the log) but actually the server is receiving something different (for whatever reason). It will then confirm that the python script is really sending what you think it is sending and eliminates that from the equation.

If the web server really is getting the right URI and is sending back a 403, that is probably more problematic to debug! As the URI logged works directly from the browser, that seems unlikely. However, once you eliminate the impossible…

Trawled through the thread;

pb66:

Is emonhub still reporting a 403 response? Odd that you get a 200 response to wget and yet the inputs don’t update.

I have pointed out before (when doing the node-red node) that a 200 code simply means the server didn’t have a problem not that the application didn’t have a problem.

TrystanLea:

It sounds to me thought that the data is not getting as far as your server.

Could it be a local DNS cache issue? Am I correct in understanding that your server is in a different location to your monitoring hardware?

That error is coming from the target server as an exception code (I’d only include that line but I don’t know how!).

github.com

openenergymonitor/emonhub/blob/195cc2f0a629fefe3e0a5683c0ca7b612ef78c00/src/emonhub_interfacer.py#L256


      
          
          return True if data sent correctly
          
          """
          
          reply = ""
          request = urllib2.Request(post_url, post_body)
          try:
              response = urllib2.urlopen(request, timeout=60)
          except urllib2.HTTPError as e:
              self._log.warning(self.name + " couldn't send to server, HTTPError: " +
                                str(e.code))
          except urllib2.URLError as e:
              self._log.warning(self.name + " couldn't send to server, URLError: " +
                                str(e.reason))
          except httplib.HTTPException:
              self._log.warning(self.name + " couldn't send to server, HTTPException")
          except Exception:
              import traceback
              self._log.warning(self.name + " couldn't send to server, Exception: " +
                                traceback.format_exc())

Paul:

but I’m still getting the 403 error

Is the 403 error continuous or do some posts get through?

@Paul The time it started is odd. Have you checked to see if Cloudflare made any changes at this time? I really think you need to use wireshark or tshark to see what is actually received (and then possibly what is actually sent).

Paul · 2018-05-05T22:12:06.068Z

borpin:

Is the 403 error continuous or do some posts get through?

Constant for emoncms. On the same apache server I run a blog which is still working fine.

borpin:

Have you checked to see if Cloudflare made any changes at this time?

Yep, checked Cloudflare Status and also their blog.

borpin:

I really think you need to use wireshark or tshark to see what is actually received

Easier said than done!!! I’ve installed tshark and read ‘tshark for dummies’ but over the past hour have struggling to get any sensible results. Is it more difficult because I’m using https?

I’ve rolled back emoncms to 17th Aug 2017, and it is still not working (although there has been MYSQL changes in that time) & also stashed the emonhub changes I’ve made today, which suggests that it’s something to do with my system or environment, and not changes in either software?
I can positively confirm that emonhub was installed 12th Sept 2017.

The most promising pointer IMO so far seems to be;

pb66:

What happens if you copy’n’paste the url from the emonhub log to wget and then edit the apikey only by copy’n’pasting the one from the emonhub.conf so that it is exactly as sent by emonhub?

in that a wget command works, but the same url in emonhub doesn’t???
What’s different?

EDIT - I’ve attached a chunk of tshark data, which maybe mean more to you than I!

tshark.txt (5.5 KB)

borpin · 2018-05-06T13:34:13.389Z

Paul:

Easier said than done!!! I’ve installed tshark and read ‘tshark for dummies’ but over the past hour have struggling to get any sensible results. Is it more difficult because I’m using https?

Agreed. Took me a while. Yes it is more difficult. If you have a GUi desktop, wireshark may be easier. The wireshark wiki talks about being able to use it with SSL.

What command did you use for the output you got?

I think the first thing will be to filter on the port you use for the https connection. Try

tshark -f "port XX" (with your https port) which should give you a load of entries. For my http setup tshark -f "port 80" -Y http will show me all the http traffic so if I browse a page, I see an output in the tshark output.

    1 0.000000000 XXX.XXX.XXX.206 → XXX.XXX.XXX.103 HTTP 573 GET /emoncms/feed/list.json HTTP/1.1
    2 0.030982394 XXX.XXX.XXX.103 → XXX.XXX.XXX.206 HTTP 606 HTTP/1.1 200 OK  (application/json)
    4 5.001883927 XXX.XXX.XXX.206 → XXX.XXX.XXX.103 HTTP 573 GET /emoncms/feed/list.json HTTP/1.1
    5 5.031144162 XXX.XXX.XXX.103 → XXX.XXX.XXX.206 HTTP 606 HTTP/1.1 200 OK  (application/json)
    7 9.683417430 XXX.XXX.XXX.206 → XXX.XXX.XXX.103 HTTP 582 GET /emoncms/admin/view HTTP/1.1
   12 10.006709375 XXX.XXX.XXX.206 → XXX.XXX.XXX.103 HTTP 573 GET /emoncms/feed/list.json HTTP/1.1
   22 11.091991141 XXX.XXX.XXX.103 → XXX.XXX.XXX.206 HTTP 1757 HTTP/1.1 200 OK  (text/html)
   23 11.096420693 XXX.XXX.XXX.103 → XXX.XXX.XXX.206 HTTP 606 HTTP/1.1 200 OK  (application/json)
   26 11.380951291 XXX.XXX.XXX.206 → XXX.XXX.XXX.103 HTTP 549 GET /emoncms/admin/getlog HTTP/1.1
   29 11.403802288 XXX.XXX.XXX.103 → XXX.XXX.XXX.206 HTTP 727 HTTP/1.1 200 OK  (text)
   34 16.644273308 XXX.XXX.XXX.30 → XXX.XXX.XXX.103 HTTP 400 GET /emoncms/input/post?fulljson=%7B%22Total%22%3A653.352%2C%22Yesterday%22%3A1.841%2C%22Today%22%3A1.003%2C%22Period%22%3A1%2C%22Power%22%3A80%2C%22Factor%22%3A0.64%2C%22Voltage%22%3A233%2C%22Current%22%3A0.535%7D&node=test2&apikey=A-P-I-K-E-Y&time=1525608222 HTTP/1.1
   36 16.647054210 XXX.XXX.XXX.103 → XXX.XXX.XXX.30 HTTP 205 HTTP/1.1 200 OK

Looking at your output, try filtering on “TLSv1.2” as those seem to correspond with my HTTP entries (If I look at the full output for port 80 I see a lot of TCP entries as well).

You can use this to confirm the emonhub is sending the data and the server is responding (although you will only see entries, you will not be able to actually read the data).

Trouble with HTTPS, is of course, all you see is encrypted data. It seems it is possible with the right build of wireshark to enter the keys and decrypt the data Stackexchange item. Sorry I do not have an HTTPS setup so cannot test this

I also found this which might help. https://techzone.ergon.ch/tcpdump

Oh and also try the wget and see if there is any obvious difference in the response from the server.

borpin · 2018-05-06T13:38:09.468Z

One other thought, have you updated Raspbian on the Pi?

Paul · 2018-05-06T18:30:33.843Z

borpin:

have you updated Raspbian on the Pi?

Yes, it was updated just 2 days ago (after the problem started).

I’ve made some headway with tshark - thanks @borpin but not enough to help identify what the issue is, so we have all spent far too much time on this now, i’m admitting defeat and moving to plan B.

Plan B was to add a Port 80 apache config, and instead of using my domain url in emonhub, I’m using http://localhost/emoncms which works OK.
As external http traffic is blocked by both Cloudflare and my router firewall, it will not/should not affect my overall system security.

I was hoping to resolve this both through curiosity, and to head off possible future problems ahead, but there we go

PS, thanks for the help here @pb66, @borpin