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

At 3.30am this morning my self-build emoncms decided to stop logging data for some reason…
Checking the emonhub log, I can see the error -

2018-05-03 15:37:30,268 INFO emonCMS sending: https://digitalnut.co.uk/emoncms/input/bulk.json?time=0&apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1525358234.75,10,-2294,2549,1110,24740,1675,-77],[1525358235.38,23,221,0,483,28,1,0,-26],[1525358239.76,10,-2010,2253,1113,24769,1675,-80],[1525358244.73,10,-1882,2118,1111,24747,1681,-78],[1525358249.71,10,-1926,2163,1110,24733,1675,-79]]
2018-05-03 15:37:30,497 WARNING emonCMS couldn't send to server, HTTPError: 403
2018-05-03 15:37:30,501 WARNING emonCMS send failure: wanted 'ok' but got ''

Now strange as it may seem, if I copy from the above -

https://digitalnut.co.uk/emoncms/input/bulk.json?time=0&apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1525358234.75,10,-2294,2549,1110,24740,1675,-77],[1525358235.38,23,221,0,483,28,1,0,-26],[1525358239.76,10,-2010,2253,1113,24769,1675,-80],[1525358244.73,10,-1882,2118,1111,24747,1681,-78],[1525358249.71,10,-1926,2163,1110,24733,1675,-79]]

into a browser, and replace E-M-O-N-C-M-S-A-P-I-K-E-Y with my read/write api key, the input is accepted by emoncms, feed updated, and I get a reassuring ‘OK’.

Nothing is showing in the emoncms log, and yes, I have confirmed that my correct API key is listed in emonhub config.

Server Information
Emoncms Version 9.8.29 : 2018.05.01
Modules Administration : App v1.1.0 : Dashboard v1.1.1 : EventProcesses : Feed : Input : CoreProcess : Schedule : Time : User : Visualisation
Server OS Linux 4.9.59-v7+
Host raspberrypi raspberrypi (127.0.1.1)
Date 2018-05-03 15:43:33 BST
Uptime 15:43:33 up 6 min, 3 users, load average: 0.45, 0.98, 0.62
HTTP Server Apache/2.4.25 (Raspbian) HTTP/1.1 CGI/1.1 443
MySQL Version 5.5.5-10.1.23-MariaDB-9+deb9u1
Host localhost (127.0.0.1)
Date 2018-05-03 15:43:33 (UTC 01:00‌​)
Stats Uptime: 394 Threads: 3 Questions: 21 Slow queries: 0 Opens: 19 Flush tables: 1 Open tables: 13 Queries per second avg: 0.053
Redis Version 3.2.6
Host localhost:6379 (127.0.0.1)
Size 130 keys (701.08K)
Uptime 0 days
MQTT Version 1.4.10
Host localhost:1883 (127.0.0.1)
Pi CPU Temp 54.23°C
Memory RAM Used: 39.82% Total: 875.78 MB Used: 348.72 MB Free: 527.06 MB
Swap Used: 0.00% Total: 100 MB Used: 0 B Free: 100 MB
Disk Mount Stats
/ Used: 67.00% Total: 6.86 GB Used: 4.6 GB Free: 1.93 GB
/boot Used: 50.62% Total: 41.15 MB Used: 20.83 MB Free: 20.32 MB
/mnt/data Used: 17.82% Total: 458.49 GB Used: 81.71 GB Free: 376.78 GB
PHP Version 7.0.27-0+deb9u1 (Zend Version 3.0.0)
Modules apache2handler : bz2 v7.0.27-0+deb9u1 : calendar v7.0.27-0+deb9u1 : Core v7.0.27-0+deb9u1 : ctype v7.0.27-0+deb9u1 : curl v7.0.27-0+deb9u1 : date v7.0.27-0+deb9u1 : dio v0.1.0 : dom v20031129 : exif v7.0.27-0+deb9u1 : fileinfo v1.0.5 : filter v7.0.27-0+deb9u1 : ftp v7.0.27-0+deb9u1 : gd v7.0.27-0+deb9u1 : gettext v7.0.27-0+deb9u1 : hash v1.0 : iconv v7.0.27-0+deb9u1 : json v1.4.0 : libxml v7.0.27-0+deb9u1 : mbstring v7.0.27-0+deb9u1 : mcrypt v7.0.27-0+deb9u1 : mosquitto v0.4.0 : mysqli v7.0.27-0+deb9u1 : mysqlnd : openssl v7.0.27-0+deb9u1 : pcre v7.0.27-0+deb9u1 : PDO v7.0.27-0+deb9u1 : pdo_mysql v7.0.27-0+deb9u1 : Phar v2.0.2 : posix v7.0.27-0+deb9u1 : readline v7.0.27-0+deb9u1 : redis v3.1.6 : Reflection v7.0.27-0+deb9u1 : session v7.0.27-0+deb9u1 : shmop v7.0.27-0+deb9u1 : SimpleXML v7.0.27-0+deb9u1 : sockets v7.0.27-0+deb9u1 : SPL v7.0.27-0+deb9u1 : standard v7.0.27-0+deb9u1 : sysvmsg v7.0.27-0+deb9u1 : sysvsem v7.0.27-0+deb9u1 : sysvshm v7.0.27-0+deb9u1 : tokenizer v7.0.27-0+deb9u1 : wddx v7.0.27-0+deb9u1 : xml v7.0.27-0+deb9u1 : xmlreader v7.0.27-0+deb9u1 : xmlwriter v7.0.27-0+deb9u1 : xsl v7.0.27-0+deb9u1 : Zend OPcache v7.0.27-0+deb9u1 : zip v1.13.5 : zlib v7.0.27-0+deb9u1 :

Client Information
HTTP Browser Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.139 Safari/537.36
Screen Resolution 1366 x 768
Window Size 1349 x 675

Seems that error is generated out of a call in the emonhub emonhub_interfacer.py. Not sure what version of emonhub you will be running :smile:. I just put “WARNING emonCMS couldn’t send to server” into the GitHub search.

Looks like an Apache server error. Anything in the webserver log? I am not sure if a 403 gets past the server and into the application. I’d guess (as a 404 obviously does not get to the application) it is a server level error.

Did you keep getting that error or does the code in emonhub_interfacer.py cause the script to die on the error (my python is not good enough to know)?

Strange that you can post via external URL but emonhub cant post, did it restart after restarting emonhub? or does the same error continue? 403 = Forbidden error, it sounds like something went wrong with apache somehow?

Could it be something to do with Cloudflare? Do you still use it @Paul?

The fact the same url didn’t work for emonhub but did work for your browser, when presumably they are the same IP suggests something about the host device was blocked, by mac id or by browser type perhaps?

Also what is odd is that there is only a few frames in the emonhub url, that should have a hundred or so frames if it’s been unable to post since 3am, emonhub shouldn’t delete data without the “ok” reply, or is that emonhub log excerpt from after the reboot (all the run times in your emoncms info are short).

What version emoncms were you running at the time? I see you have 9.8.29 now, but have you just updated now, or did you update yesterday?

No, I did a reboot a few minutes earlier, to see if would resolve itself, that’s why there is only a few frames.

Not sure, but I am never far behind Master. I only updated to day (again in the hope that it may fix things).

I am still using Cloudflare, but strange as I’ve made no system changes over the past week or so, yet it stops in the middle of the night when I’m knocking out zzzz’s!

I’m not back home until tomorrow, and I’ll have more time then to look in a bit more detail.

Any pointers how to identify the problem please.

Things I’ve tried;

  • Disabled UFW - still same
  • Checked Apache logs - nothing unusual showing, no errors
  • Created fresh install of emoncms from git - still same
  • Reviewed Cloudflare - difficult to isolate as it’s integrated into the domain & firewall, but checked their status, blog & google search

Paul

Perhaps you could enable the apache access log to see if there is anything being received by apache on your system?

sudo nano /etc/apache2/sites-available/000-default.conf

Uncomment CustomLog and reload apache, I then see a log of requests to feed/list and UI navigation as Im posting data via MQTT:

192.168.1.65 - - [05/May/2018:08:29:25 +0000] "GET /emoncms/feed/list.json HTTP/1.1" 200 1196 "http://emonpi.local/emoncms/feed/list" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:58.0) Gecko/20100101 Firefox/58.0"
192.168.1.65 - - [05/May/2018:08:29:30 +0000] "GET /emoncms/feed/list.json HTTP/1.1" 200 1195 "http://emonpi.local/emoncms/feed/list" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:58.0) Gecko/20100101 Firefox/58.0"
192.168.1.65 - - [05/May/2018:08:29:35 +0000] "GET /emoncms/feed/list.json HTTP/1.1" 200 1199 "http://emonpi.local/emoncms/feed/list" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:58.0) Gecko/20100101 Firefox/58.0"
192.168.1.65 - - [05/May/2018:08:29:40 +0000] "GET /emoncms/feed/list.json HTTP/1.1" 200 1197 "http://emonpi.local/emoncms/feed/list" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:58.0) Gecko/20100101 Firefox/58.0"

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?

Thanks Trystan.

No, everything is run on a Raspberry Pi within my local network, except I have it configured to route all traffic via Full Strict Cloudflare (and has worked fine this way for a couple of years).
I have never allowed http access, and my server is https only.
So in sites-enabled, I just have one config - cloudflare-ssl.conf which is https.
The logging function is already uncommented;

ErrorLog ${APACHE_LOG_DIR}/error.log
CustomLog ${APACHE_LOG_DIR}/access.log combined

If I look at the access log, I can see 2 types of entries (correct api key obfuscated!);

141.101.98.206 - - [05/May/2018:09:45:55 +0100] "GET /emoncms/feed/value.json?id=15&apikey=b8ceiofihhuhdflsfsljsljfljsl3b03 HTTP/1.1" 200 2139 "-" "-"
141.101.98.206 - - [05/May/2018:09:45:55 +0100] "GET /emoncms/feed/value.json?id=19&apikey=b8ceiofihhuhdflsfsljsljfljsl3b03 HTTP/1.1" 200 2138 "-" "-"
141.101.98.206 - - [05/May/2018:09:45:55 +0100] "GET /emoncms/feed/value.json?id=17&apikey=b8ceiofihhuhdflsfsljsljfljsl3b03 HTTP/1.1" 200 2138 "-" "-"
141.101.98.206 - - [05/May/2018:09:45:55 +0100] "GET /emoncms/feed/list.json HTTP/1.1" 200 2927 "https://digitalnut.co.uk/emoncms/feed/list" "Mozilla/5.0 (Windows NT 1 0.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.139 Safari/537.36"
141.101.98.206 - - [05/May/2018:09:46:00 +0100] "GET /emoncms/feed/list.json HTTP/1.1" 200 1030 "https://digitalnut.co.uk/emoncms/feed/list" "Mozilla/5.0 (Windows NT 1 0.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.139 Safari/537.36"
141.101.98.206 - - [05/May/2018:09:46:05 +0100] "GET /emoncms/feed/list.json HTTP/1.1" 200 2927 "https://digitalnut.co.uk/emoncms/feed/list" "Mozilla/5.0 (Windows NT 1 0.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.139 Safari/537.36"

As you can see, they originate from 141.101.98.206 which is a Cloudflare IP.

Paul

I didn’t realize it was still a current fault, for some reason I thought it had resolved and you were trying to find out why and prevent a reoccurance.

Have you tried restarting your router?

Can you lift the failed url from the emonhub.log (edit/add the apikey) and try using it via wget or curl from the commandline of the same machine?

If that doesn’t work it points to the machine most likely being blocked by mac or IP.

If that does work it might suggest a Python/emonhub issue (although I can’t imagine why or what that might be) so you could try posting that same url via Python, by writing a test script or using the Python command line just to test the code and Libs, but I doubt you will need to go this route.

Just saw your last post before I pressed “reply” and see there are no input api calls so the requests look like they are getting rejected before they reach Apache2,

Anything in the error.log ?

[edit] Anything in your routers logs?

Yes, several times

[email protected]:~ $ wget https://digitalnut.co.uk/emoncms/input/bulk.json?time=0&apikey=11uhe76efse7se7ffsfsyfgysdfse&data=[[1525513551.83,10,-1337,1734,1088,24488,1918,-78]]
[1] 1638
[2] 1639
[email protected]:~ $ --2018-05-05 10:47:23--  https://digitalnut.co.uk/emoncms/input/bulk.json?time=0
Resolving digitalnut.co.uk (digitalnut.co.uk)... 104.24.106.246, 104.24.107.246, 2400:cb00:2048:1::6818:6af6, ...
Connecting to digitalnut.co.uk (digitalnut.co.uk)|104.24.106.246|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 56 [application/json]
Saving to: ‘bulk.json?time=0.2’

bulk.json?time=0.2                        100%[=====================================================================================>]      56  --.-KB/s    in 0s

2018-05-05 10:47:24 (7.71 MB/s) - ‘bulk.json?time=0.2’ saved [56/56]

That’s what I get, but the input is not updated in emoncms. Putting the same url (less the wget) into a browser in the same network results in ‘ok’ and the emoncms input updated.

Nothing in either.

Hhmm, python… never knowingly used python… perhaps a job after a bit of googling!!

What are the contents of the “bulk.json?time=0.2” file? Is it just “ok”?

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

Now that’s interesting…
{"success":false,"message":"Username or password empty"}

Yes

Assuming there’s no copy’n’paste errors and you haven’t changed your apikey, I would have said emoncms is unable to lookup and translate the apikey, but it works from a browser, so that makes me think the apikey is wrong in emonhub, but who would of changed that in the middle of the night? It doesn’t make much sense.

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?

Exactly the same, I’ve also compared the emonhub apikey, the emoncms ‘user/view’ apikey and also the emoncms input/api apikey, and all are identical. (read/write apikey).

Edit - As I’ve said above, I’ve also tried renaming my existing emoncms installation and git installed it again as a fresh installation, and still get the same errors from the new installation.

Just realized the wget url is not working as expected, wget uses the end of the url as a file name, so it is apparently blind to what is after the “bulk.json?time=0”, ie the apikey and data try the tests again with the url in quotes eg

wget "https://digitalnut.co.uk/emoncms/input/bulk.json?time=0&apikey=11uhe76efse7se7ffsfsyfgysdfse&data=[[1525513551.83,10,-1337,1734,1088,24488,1918,-78]]" -O reply.txt

the -O I’ve added should save the file as “reply.txt” this time.

[edit] I just tried it with your fudged apikey and got a 401 “unauthorized” response which is more appropriate.

We’ll spotted!
That results in the inputs being updated and no 403 error.
The reply.txt contains ‘ok’

Which variant of emonhub are you running? which version? Is it stock?

It’s stock, as installed via the emoncms build guide.

Can you please run

path/to/emonhub/src/emonhub.py --version

and also confirm which git branch it’s on, it’s been a very long time since I had to think about any non-emonpi variant emonhub issue’s so I want to be sure what it is you have.

When did you install this set up? I’m just wondering whether there have been any changes in Lib versions etc over the years, odd this issue should pop up now when there have been no changes to the original emonhub code in years.

[email protected]:~ $ /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)