EmonService: Invalid response

Simsala · June 30, 2018, 6:35pm

I run emoncms on a server behind the web server NGINX (I can’t use Apache here). However, there is the problem that NGINX does not seem to send the correct OK signal to the Iotawatt. The first data package arrives on the server, but then no more. The Iotawatt log shows the following:

6/30/18 18:20:41z EmonService: started. url:my.rexometer.de:80,node:IotaWatt,interval:10, encrypted POST
6/30/18 18:20:42z EmonService: Node doesn't yet exist.
6/30/18 18:20:42z EmonService: Start posting at 6/30/18 18:20:50 
6/30/18 18:21:30z EmonService: Invalid response, Retrying.
6/30/18 18:21:31z EmonService: Invalid response, Retrying.
6/30/18 18:21:32z EmonService: Invalid response, Retrying.
6/30/18 18:21:33z EmonService: Invalid response, Retrying.
6/30/18 18:21:34z EmonService: Invalid response, Retrying.
6/30/18 18:21:35z EmonService: Invalid response, Retrying.
6/30/18 18:21:36z EmonService: Invalid response, Retrying.
6/30/18 18:21:37z EmonService: Invalid response, Retrying.
6/30/18 18:21:38z EmonService: Invalid response, Retrying.
6/30/18 18:21:39z EmonService: Invalid response, Retrying.
6/30/18 18:21:40z EmonService: Invalid response, Retrying.
6/30/18 18:21:41z EmonService: Invalid response, Retrying.
6/30/18 18:21:42z EmonService: Invalid response, Retrying.
6/30/18 18:21:43z EmonService: Invalid response, Retrying.
6/30/18 18:21:44z EmonService: Invalid response, Retrying.
6/30/18 18:21:45z EmonService: Invalid response, Retrying.
6/30/18 18:21:46z EmonService: Invalid response, Retrying.
6/30/18 18:21:47z EmonService: Invalid response, Retrying.
6/30/18 18:21:48z EmonService: Invalid response, Retrying.
6/30/18 18:21:49z EmonService: Invalid response, Retrying.
6/30/18 18:21:50z EmonService: Invalid response, Retrying.
6/30/18 18:21:51z EmonService: Invalid response, Retrying.
6/30/18 18:21:52z EmonService: Invalid response, Retrying.
6/30/18 18:21:53z EmonService: Invalid response, Retrying.
6/30/18 18:21:54z EmonService: Invalid response, Retrying.
6/30/18 18:21:55z EmonService: Invalid response, Retrying.
6/30/18 18:21:56z EmonService: Invalid response, Retrying.
6/30/18 18:21:57z EmonService: Invalid response, Retrying.
6/30/18 18:21:58z EmonService: Invalid response, Retrying.
6/30/18 18:21:59z EmonService: Invalid response, Retrying.
6/30/18 18:22:00z EmonService: Invalid response, Retrying.
6/30/18 18:22:01z EmonService: Invalid response, Retrying.
6/30/18 18:22:02z EmonService: Invalid response, Retrying.
6/30/18 18:22:03z EmonService: Invalid response, Retrying.
6/30/18 18:22:04z EmonService: Invalid response, Retrying.
6/30/18 18:22:05z EmonService: Invalid response, Retrying.
6/30/18 18:22:06z EmonService: Invalid response, Retrying.
6/30/18 18:22:07z EmonService: Invalid response, Retrying.
6/30/18 18:22:08z EmonService: Invalid response, Retrying.
6/30/18 18:22:09z EmonService: Invalid response, Retrying.
6/30/18 18:22:10z EmonService: Invalid response, Retrying.
6/30/18 18:22:11z EmonService: Invalid response, Retrying.
6/30/18 18:22:12z EmonService: Invalid response, Retrying.
6/30/18 18:22:13z EmonService: Invalid response, Retrying.
6/30/18 18:22:14z EmonService: Invalid response, Retrying.
6/30/18 18:22:15z EmonService: Invalid response, Retrying.
6/30/18 18:22:16z EmonService: Invalid response, Retrying.
6/30/18 18:22:17z EmonService: Invalid response, Retrying.
6/30/18 18:22:18z EmonService: Invalid response, Retrying.
6/30/18 18:22:19z EmonService: Invalid response, Retrying.
6/30/18 18:22:20z EmonService: Invalid response, Retrying.
6/30/18 18:22:21z EmonService: Invalid response, Retrying.
6/30/18 18:22:22z EmonService: Invalid response, Retrying.
6/30/18 18:22:23z EmonService: Invalid response, Retrying.
6/30/18 18:22:24z EmonService: Invalid response, Retrying.
6/30/18 18:22:25z EmonService: Invalid response, Retrying.
6/30/18 18:22:26z EmonService: Invalid response, Retrying.
6/30/18 18:22:27z EmonService: Invalid response, Retrying.

Edit 2:
Same with insecure get, only the message is a little different:

6/30/18 19:14:54z EmonService: started. url:my.rexometer.de:80,node:IotaWatt,interval:10, unsecure GET
6/30/18 19:14:55z EmonService: Start posting at 6/30/18 19:15:05 
6/30/18 19:15:50z EmonService: response not ok. Retrying.
6/30/18 19:15:51z EmonService: response not ok. Retrying.
6/30/18 19:15:52z EmonService: response not ok. Retrying.
6/30/18 19:15:53z EmonService: response not ok. Retrying.
6/30/18 19:15:54z EmonService: response not ok. Retrying.
6/30/18 19:15:55z EmonService: response not ok. Retrying.

How can I best debug this? I’m a little at a loss right now.

Edit 1:

This is the corresponding NGINX access log entry:

212.161.162.87 - - [30/Jun/2018:20:20:42 +0200] "GET HTTP://my.rexometer.de/input/get?node=IotaWatt HTTP/1.1" 200 32 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:11 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 55 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:30 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:31 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:32 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:33 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:34 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:35 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:36 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:37 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:38 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:39 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:41 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:41 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:42 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:43 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:44 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:46 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:46 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:47 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:48 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"
212.161.162.87 - - [30/Jun/2018:20:21:50 +0200] "POST HTTP://my.rexometer.de/input/bulk HTTP/1.1" 200 67 "-" "-"

overeasy · June 30, 2018, 7:21pm

Good question. I haven’t actually used nginx explicitely, but I’ve looked at it and my understanding is that in this scenario, it’s just a proxy server.

The first thing I’d like to know is if you are using the secure encrypted protocol (specify an account ID in IoTaWatt config). If so, it looks like you are using a local instance of Emoncms and your version may not support the secure encrypted protocol as my understanding is that it was merged fairly recently. So there’s that. If you are doing that, try removing the account ID to use the unencrypted protocol.

If that’s not it, I have to say that the Emoncms response is just a response payload just like any other transaction with Emoncms. The initial transaction is a query to determine the time of the last successful entry, From what I can see, it looks like that worked. The only difference is that one is a GET and the others are POST, but the return HTTP formatted the same. I don’t see any reason for nginx to get involved in the intimacy of the transaction payload.

So take a look at the secure protocol thing, then if the problem persists, can you give me a screenshot of the Emoncms config, the status screen, and the message log segment at the most recent startup. You know the drill.

Simsala · June 30, 2018, 7:27pm

Thank you for the quick answer! The emoncms version used is 9.8.31 | 2018.06.21, so it should contain the encrypted protocol. In the meantime I had added the error message which is displayed with the unencrypted connection to the first post. Here are the screenshots:

overeasy · June 30, 2018, 8:20pm

Notwithstanding the messages, the status indicates that Emoncms is up to date, in fact into the future at 21:23:35.That could just be your browser in a different timezone from the IoTaWatt (2 hrs?)…
It’s 20:18zulu here now and you posted this about an hour ago, so can you check Emoncms and see if it has been recording any data?

Simsala · June 30, 2018, 8:34pm

The time displayed in the status menu under emoncms is indeed my local time, so also the time of the browser. No, emoncms only recorded the one successful data point. How can I display the status message of emoncms manually to check if there is a difference to emoncms.org?

overeasy · June 30, 2018, 8:47pm

I’m a little confused now. Are you using Emoncms.org or a private instance? It’s not crucial to know, but I like to have the big picture. ARe you asking me how to display the status of Emoncms or the Emoncms service on the IoTaWatt?
Pretty sure you know that the Emoncms inputs and feeds displays will show the Emoncms status. You must have a feed defined to be able to tell me that Emoncms only has one data point. The inputs are always just the most recent data point.

The status of the IoTaWatt Emoncms Service is what you see in the status display under the Emoncms tab. It should be updated regularly along with everything else but you may need to refresh it manually from time to time if there is a lot of error retry going on.

Simsala · June 30, 2018, 8:54pm

Sorry for the confusion. I use a private emoncms server that uses NGINX to host emoncms and to which I cannot send data with the iotawatt, for the reasons described above. emoncms.org, on the other hand, works fine, as well as a local emonpi. The only difference seems to be the web server, so NGINX instead of Apache. To debug this I would have to manually send the command the iotawatt sends to emoncms and compare the response of the emoncms on my own server with that of emoncms.org or emonpi. I just haven’t figured out how to do it yet.

overeasy · June 30, 2018, 9:00pm

Let me put my ignorance on full display here. You are using NGINX as a proxy, but then say that you are using NGINX as a web server instead of Apache. Is that to host Emoncms?

Simsala · June 30, 2018, 9:05pm

Ah ok, now I understand the misunderstanding. Proxy is in fact the wrong term here, I actually only use NGINX to host emoncms, without Apache being involved.

overeasy · June 30, 2018, 9:07pm

And that works fine with other devices sending data?

Simsala · June 30, 2018, 9:12pm

At least I haven’t noticed any problems yet. I actually had some serious problems some time ago when an emonpi tried to load its buffer to the server after a network failure. I had suspected the problem here rather on the part of the emonpi-emonhub variant, but of course it is quite possible that this is also connected with my server configuration which deviates from the standard.

The hint with the proxy is definitely good, I will try to put NGINX only as proxy before Apache. Maybe this already fixes the problem.

overeasy · June 30, 2018, 9:18pm

In the first post, IoTaWatt reported that the node didn’t exist yet, then set the start time to 18:20:50 and you start to get the error messages.
In EDIT 2: The Emonservice starts up and queries Emoncms to find that the node exists and the last posting was at 19:15:05, less than a minute prior.
Later on in another post, IoTaWatt reports on startup that Emoncms is current to 19:23:45.

So that’s at least two data points that appear to have been received, and they are not timestamped as the first after a reboot, but look more like the last just before the most recent restart.

So if you have a feed defined for say voltage, or can define one and run it for awhile, and see if it gets populated at all and then plot it.

You can generate transactions like IoTaWatt but they are POST transactions and you would need to use CURL, which I’m not that good at.

Another approach is to hook up a serial monitor to the IoTaWatt. The invalid responses should be logged.

Simsala · June 30, 2018, 9:26pm

Excellent hint, these are the messages of the serial output:

6/30/18 21:22:56z You can now connect to http://IotaWatt.local
6/30/18 21:22:56z HTTP server started
6/30/18 21:22:56z dataLog: service started.
6/30/18 21:22:57z dataLog: Last log entry 6/30/18 21:22:55 
6/30/18 21:22:57z statService: started.
6/30/18 21:22:57z timeSync: service started.
6/30/18 21:22:57z WiFi connected. SSID: rexoweb, IP: 192.168.11.117
6/30/18 21:22:57z Updater: service started. Auto-update class is ALPHA
6/30/18 21:22:57z historyLog: service started.
6/30/18 21:22:57z historyLog: Last log entry 6/30/18 21:22:00 
6/30/18 21:23:01z EmonService: started. url:my.rexometer.de:80,node:IotaWatt,interval:10, encrypted POST
6/30/18 21:23:02z EmonService: Start posting at 6/30/18 21:22:40 
6/30/18 21:23:13z updater: Auto-update is current for class ALPHA.
6/30/18 21:23:20z EmonService: Invalid response, Retrying.
zjP11fHZ461R5ZiXR1aCra-PrBKCSY2FF64k05EtJVE=
{"success":false,"message":"Username or password empty"}
6/30/18 21:23:21z EmonService: Invalid response, Retrying.
zjP11fHZ461R5ZiXR1aCra-PrBKCSY2FF64k05EtJVE=
{"success":false,"message":"Username or password empty"}
6/30/18 21:23:22z EmonService: Invalid response, Retrying.
zjP11fHZ461R5ZiXR1aCra-PrBKCSY2FF64k05EtJVE=
{"success":false,"message":"Username or password empty"}
6/30/18 21:23:23z EmonService: Invalid response, Retrying.
zjP11fHZ461R5ZiXR1aCra-PrBKCSY2FF64k05EtJVE=
{"success":false,"message":"Username or password empty"}
6/30/18 21:23:24z EmonService: Invalid response, Retrying.
zjP11fHZ461R5ZiXR1aCra-PrBKCSY2FF64k05EtJVE=
{"success":false,"message":"Username or password empty"}
6/30/18 21:23:25z EmonService: Invalid response, Retrying.
7wSiS0sqrWPsZrxp-XxSagIh_qNPLQyiIAJ1pDqVOrY=
{"success":false,"message":"Username or password empty"}
6/30/18 21:23:26z EmonService: Invalid response, Retrying.
7wSiS0sqrWPsZrxp-XxSagIh_qNPLQyiIAJ1pDqVOrY=

overeasy · June 30, 2018, 9:28pm

That’s the encrypted protocol. Looks like it’s not supported. Try the unencrypted.

Simsala · June 30, 2018, 9:36pm

You are right, these are the serial output messages using the unencrypted one:

Upload: START, filename: config.txt
Upload: END, Size: 1740
6/30/18 21:29:34z EmonService: started. url:my.rexometer.de:80,node:IotaWatt,interval:10, unsecure GET
6/30/18 21:29:35z EmonService: Start posting at 6/30/18 21:29:45 
6/30/18 21:30:30z EmonService: response not ok. Retrying.
{"success":false,"message":"Username or password empty"}
6/30/18 21:30:31z EmonService: response not ok. Retrying.
{"success":false,"message":"Username or password empty"}
6/30/18 21:30:32z EmonService: response not ok. Retrying.
{"success":false,"message":"Username or password empty"}
6/30/18 21:30:33z EmonService: response not ok. Retrying.
{"success":false,"message":"Username or password empty"}

Looks like it’s either not a good idea with NGINX or my NGINX configuration is just incomplete. Probably the latter. I don’t understand why the first post attempt arrives at the server, but it is still acknowledged with an error message, but now I know at least how I can see the error messages. Thank you for your support!

overeasy · June 30, 2018, 9:48pm

I think I know what’s might be happening. IoTaWatt sends the api key in a header rather than plaintext in the body. I suspect that NGINX doesn’t pass it through. I can look further into it this evening but won’t be available at all tomorrow. Give me a shout if you solve or workaround before then. Gotta go now.

Simsala · June 30, 2018, 11:34pm

Thank you for your help, that actually seems to be the problem. I am very glad that IotaWatt has made the errors in my setup visible.

Unfortunately, it doesn’t work even if NGINX really only functions as a proxy and forwards the traffic with proxy_pass.

As a workaround I now have Apache running on a different port and configured the IotaWatt to use this port. Even if that’s not very pretty, it works.

SandyB · July 1, 2018, 2:29pm

I’m getting a similar result using IIS as a web server. EmonTXs post fine, “EmonService: response not ok, Retrying.” from IoTaWatt.

overeasy · July 2, 2018, 5:12pm

I’m following up on this, and there is something fishy here. Are you saying the problem happens when the posts are passed through an NGINX proxy to Emoncms on Apache? And that the same Apache works fine when you send it directly? (not through the proxy).

In retrospect after reviewing this, I don’t think it’s a problem with passing the Authorization header because:

The initial GET to fetch the time of last update works fine and it uses the same Authorization header.
If I remove the Authorization header on one of my test systems and try to post to Emoncms, the failure mode is a HTTP 302 (No idea why but it’s not a 200, would expect a 401).

overeasy · July 2, 2018, 5:15pm

Are you able to connect a serial monitor and verify that the response is the same?