EmonCMS uploader causing reboot loop - resolved

I have recently received my first IoTaWatt, and after configuring it today seem to have hit a bug with the EmonCMS upload script. At the moment if I attempt to use EmonCMS it causes IoTaWatt to reboot continuously.

This can only be interrupted by removing the 9V voltage reference, so that IoTaWatt stops attempting to upload data to EmonCMS.

After doing some Wireshark analysis it appears that IoTaWatt is attempting an invalid API query (sending a POST to an endpoint that only supports GET), and EmonCMS replies to this with the login page. That response is quite large (45K) and so I wonder if this is causing the exception, but that is a supposition.

My EmonCMS is run locally, and is the latest version (10.8.5). For now I’ve raised an issue on Github (here) but I wonder if there’s something else I’m missing? Extracts of the log & config.txt are below.

Sequence of Events

  • 19:45:41z: IoTaWatt was restarted manually
  • 19:54:00z: 9V voltage reference was connected to IoTaWatt, triggering an attempt to upload to EmonCMS
  • 19:54:01z: IotaWatt issues the POST query to EmonCMS
  • 19:54:02z: IoTaWatt reboots with an Exception
  • 19:54:06z: IoTaWatt attempts same POST query and reboots again, this continues until the 9V voltage reference is removed (breaking the reboot loop)
  • If the EmonCMS configuration is deleted then the 9V voltage reference can be connected continuously.

IoTaWatt Log

SD initialized.
2/19/22 19:45:41z Real Time Clock is running. Unix time 1645299941 
2/19/22 19:45:41z Reset reason: Software/System restart
2/19/22 19:45:41z Trace:  9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:2, 1:2, 1:3, 1:3, 1:1[1], 1:2[2], 9:0[2], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:3, 9:5, 9:9, 1:2, 1:3, 1:3, 1:1[2], 1:2, 9:0, 9:0, 8:2, 8:2, 1:2
2/19/22 19:45:41z ESP8266 ID: 523643, RTC M41T81 (68)
2/19/22 19:45:41z IoTaWatt 5.0, Firmware version 02_07_05
2/19/22 19:45:41z SPIFFS mounted.
2/19/22 19:45:41z Local time zone: +0:00, using DST/BST when in effect.
2/19/22 19:45:41z device name: IotaWatt
2/19/22 19:45:41z HTTP server started
2/19/22 19:54:00z emoncms: Starting, interval:10, url:http://192.168.1.17
2/19/22 19:54:00z WiFi connected. SSID=Wireless, IP=192.168.1.15, channel=11, RSSI -65db
2/19/22 19:54:00z MDNS responder started for hostname IotaWatt
2/19/22 19:54:00z LLMNR responder started for hostname IotaWatt
2/19/22 19:54:00z timeSync: service started.
2/19/22 19:54:01z statService: started.
2/19/22 19:54:01z Updater: service started. Auto-update class is MINOR
2/19/22 19:54:01z dataLog: service started.
2/19/22 19:54:01z dataLog: Last log entry 02/19/22 19:40:40
2/19/22 19:54:01z historyLog: service started.
2/19/22 19:54:01z historyLog: Last log entry 02/19/22 17:55:00

** Restart **

SD initialized.
2/19/22 19:54:02z Real Time Clock is running. Unix time 1645300442 
2/19/22 19:54:02z Reset reason: Exception
2/19/22 19:54:02z Trace:  8:8, 8:9, 9:3, 9:5, 9:9, 1:2, 1:3, 1:3, 1:1[1], 1:2[2], 9:0[2], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:3, 9:5, 9:9, 1:2, 1:3, 1:3, 1:1[2], 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 1:2
2/19/22 19:54:02z ESP8266 ID: 523643, RTC M41T81 (68)
2/19/22 19:54:02z IoTaWatt 5.0, Firmware version 02_07_05
2/19/22 19:54:02z SPIFFS mounted.
2/19/22 19:54:02z Local time zone: +0:00, using DST/BST when in effect.
2/19/22 19:54:02z device name: IotaWatt
2/19/22 19:54:02z HTTP server started
2/19/22 19:54:02z emoncms: Starting, interval:10, url:http://192.168.1.17
2/19/22 19:54:02z timeSync: service started.
2/19/22 19:54:02z statService: started.
2/19/22 19:54:02z dataLog: service started.
2/19/22 19:54:02z dataLog: Last log entry 02/19/22 19:40:40
2/19/22 19:54:02z historyLog: service started.
2/19/22 19:54:02z historyLog: Last log entry 02/19/22 17:57:00
2/19/22 19:54:06z WiFi connected. SSID=Wireless, IP=192.168.1.15, channel=11, RSSI -61db
2/19/22 19:54:06z MDNS responder started for hostname IotaWatt
2/19/22 19:54:06z LLMNR responder started for hostname IotaWatt
2/19/22 19:54:06z Updater: service started. Auto-update class is MINOR

** Restart **

SD initialized.
2/19/22 19:54:07z Real Time Clock is running. Unix time 1645300447 
2/19/22 19:54:07z Reset reason: Exception
2/19/22 19:54:07z Trace:  9:0, 8:4, 8:6, 8:8, 8:9, 1:2, 1:3, 1:3, 1:6[1], 1:6[2], 1:6[3], 1:5[14], 1:6[4], 14:0, 14:4, 14:5, 14:7, 14:8, 1:6[6], 1:1, 1:2[1], 9:0[1], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:3, 9:5, 9:9, 1:2
2/19/22 19:54:07z ESP8266 ID: 523643, RTC M41T81 (68)
2/19/22 19:54:07z IoTaWatt 5.0, Firmware version 02_07_05
2/19/22 19:54:07z SPIFFS mounted.
2/19/22 19:54:07z Local time zone: +0:00, using DST/BST when in effect.
2/19/22 19:54:07z device name: IotaWatt
2/19/22 19:54:07z HTTP server started
2/19/22 19:54:07z emoncms: Starting, interval:10, url:http://192.168.1.17
2/19/22 19:54:07z timeSync: service started.
2/19/22 19:54:07z statService: started.
2/19/22 19:54:07z dataLog: service started.
2/19/22 19:54:07z dataLog: Last log entry 02/19/22 19:54:05
2/19/22 19:54:07z historyLog: service started.
2/19/22 19:54:07z historyLog: Last log entry 02/19/22 19:45:00
2/19/22 19:54:11z WiFi connected. SSID=Wireless, IP=192.168.1.15, channel=11, RSSI -60db
2/19/22 19:54:11z MDNS responder started for hostname IotaWatt
2/19/22 19:54:11z LLMNR responder started for hostname IotaWatt
2/19/22 19:54:11z Updater: service started. Auto-update class is MINOR

config.txt

{
	"format": 2,
	"timezone": 0,
	"update": "MINOR",
	"device": {
		"name": "IotaWatt",
		"version": 3,
		"channels": "15",
		"burden": [
			0,
			20,
			20,
			20,
			20,
			20,
			20,
			20,
			20,
			20,
			20,
			20,
			20,
			20,
			20
		]
	},
	"inputs": [
		{
			"channel": 0,
			"name": "Voltage",
			"type": "VT",
			"model": "Ideal 77DB-06-09(UK)",
			"cal": 20.01
		},
		{
			"channel": 1,
			"name": "Input_1",
			"type": "CT",
			"model": "HWCT-004",
			"phase": 0.1,
			"turns": 1000,
			"cal": 50
		},
		{
			"channel": 2,
			"name": "Input_2",
			"type": "CT",
			"model": "SCT013-000",
			"phase": 2.3,
			"turns": 2000,
			"cal": 100
		},
		null,
		null,
		null,
		null,
		null,
		null,
		null,
		null,
		null,
		null,
		null,
		null
	],
	"outputs": [
		{
			"name": "Voltage",
			"units": "Volts",
			"script": "@0"
		}
	],
	"dstrule": {
		"adj": 60,
		"utc": true,
		"begin": {
			"month": 3,
			"weekday": 1,
			"instance": -1,
			"time": 60
		},
		"end": {
			"month": 10,
			"weekday": 1,
			"instance": -1,
			"time": 60
		}
	},
	"emoncms": {
		"type": "emoncms",
		"revision": 0,
		"node": "IotaWatt",
		"postInterval": 10,
		"bulksend": 1,
		"url": "http://192.168.1.17",
		"apikey": "EMONCMS_READ_WRITE_API_KEY",
		"user": "",
		"pwd": "",
		"outputs": [
			{
				"name": 1,
				"script": "@0",
				"units": ""
			},
			{
				"name": 2,
				"script": "@1",
				"units": ""
			},
			{
				"name": 3,
				"script": "@2",
				"units": ""
			},
			{
				"name": 4,
				"script": "@3",
				"units": ""
			},
			{
				"name": 5,
				"script": "@4",
				"units": ""
			},
			{
				"name": 6,
				"script": "@5",
				"units": ""
			},
			{
				"name": 7,
				"script": "@6",
				"units": ""
			},
			{
				"name": 8,
				"script": "@7",
				"units": ""
			},
			{
				"name": 9,
				"script": "@8",
				"units": ""
			},
			{
				"name": 10,
				"script": "@9",
				"units": ""
			},
			{
				"name": 11,
				"script": "@10",
				"units": ""
			},
			{
				"name": 12,
				"script": "@11",
				"units": ""
			},
			{
				"name": 13,
				"script": "@12",
				"units": ""
			},
			{
				"name": 14,
				"script": "@13",
				"units": ""
			},
			{
				"name": 15,
				"script": "@14",
				"units": ""
			}
		],
		"userid": "",
		"begdate": 1645228800
	}
}

I think there may be multiple things going on here. Addressing your issue with Emoncms, usually a local URL includes the path /emoncms. How are you hosted, on a Pi?

It’s not clear to me if the message log showing exceptions that you posted is with or without the VT connected. All bets are off with the VT disconnected. Was there a point early on when it was running reliably, maybe before you configured emoncms? If so, can you get back there?

My EmonCMS install is locally hosted from a dedicated VM on one of my servers (not on a Pi). It runs from the root of an Apache VirtualHost and therefore doesn’t need a /emoncms subfolder. I have several other devices (including an EmonPi) sending data into this EmonCMS instance which are working correctly.

The log excerpt starts out at 19:45:41 with the VT disconnected and EmonCMS configured. At that point there is no data available in the IoTaWatt console, and Wireshark shows no communication between IoTaWatt and EmonCMS.

At 19:54:00Z I connected the VT, the EmonCMS uploader service then starts, makes an invalid API call and then IoTaWatt reboots immediately. This continues in a loop, with IoTaWatt starting, sending one POST to EmonCMS, receiving a reply and then rebooting.

The only way I can get back into IoTaWatt (to remove the EmonCMS configuration) is to unplug the VT - as that stops it generating statistics (and the uploader service doesn’t start on next boot).

If EmonCMS uploader is unconfigured then IoTaWatt runs normally with the VT connected.

As mentioned in my Github Issue it appears to be the emoncms_uploader::handle_query_s() method that is sending the invalid API call. It sends a POST to “/input/get” which, according to the EmonCMS docs, isn’t a valid method. The response is the HTML of the EmonCMS login page - some 46KB of data. An example from my Wireshark capture is in the Issue.

Wireshark showed no other traffic between IoTaWatt and EmonCMS apart from this POST request & response - occurring every time though the loop described above.

That POST query has been working for a long time. Years actually.

It would be more helpful if you posted the wireshark response that you are seeing, maybe it has some clues as to why the transaction is being rejected. The POST transaction will have your APIKEY in an authorization header. Is it possible you are using the read key or an invalid read-write key?

UPDATE: Sorry, didn’t catch the reference to the github issue. I see the wireshark now. Still think you should check your apikey.

@dakaix, Sometimes no news is good news. What is the status of this issue?

Sorry for the delay! Been slammed the last day or so here.

Apologies for the earlier confusion, I was trying to avoid spamming the forum with a wall of technical detail - hence keeping that on GitHub!

The API key I’m using is definitely correct - I recreated exactly the same query from Curl to validate the API; and I also tried manually POSTing some dummy data to create the “IotaWatt” node in EmonCMS. That worked fine with Curl, but still no change with Iotawatt.

Is there a debug firmware that can be applied to get more details on the exception? I tried connecting via Serial but got much the same as on the Message Log.

The wire shark doesn’t show enough content on the return but I think you said it was an eMoncms login. So It looks to me that the authorization is not right. Clearly the IoTaWatt needs to not choke on such a large response, and I’ll look into that, but the immediate problem appears to be authorization. Whether there is a problem with something not passing through to eMoncms I don’t know, but that’s how it looks to me right now.

To be clear it’s just returning the index.php, which just happens to double as the login screen for EmonCMS.

Having successfully POSTed data via Curl to /input/post with the same Authorization header (as IotaWatt is attempting) I don’t see an actual login problem.

If I exactly recreate IoTaWatt’s attempted query (POST to /input/get) via Curl then I see the same index.php response as Wireshark shows IotaWatt got. Whereas with /input/post I’d get a JSON formatted response.

OK, not an expert at apache, php, etc. but this is code that has been working for years. As I read the eMoncms specs, the /input/get endpoint is used to get a list of all inputs for the specified node. The /input/get has nothing to do with the http method GET or POST used.

Similarly, when you GET or POST a transaction to the /input/post endpoint, you are sending data to Emoncms.

That you can use curl to post a /input/post transaction isn’t surprising. What would be surprising is if the /input/post?node= transaction returned a list of inputs.

There is something going on with your eMoncms, but I don’t think changing the IoTaWatt to issue a /input/post to get a list of the inputs is going to help. eMoncms is going to expect that transaction to send data. BTW IoTaWatt uses /input/bulk to send data.

For some reason, your eMoncms does not respond to the /input/get endpoint as expected. I’m not familiar with how the transactions are routed to a VM on your server, or how your Apache Virtual Host handles these transactions, but there is some difference. That you have other applications successfully working with the eMoncms instance is encouraging, but do any of them do /input/get requests? Have you tried doing a /input/get request using the GET method with CURL?

Yep I realise the endpoint name isn’t related to the HTTP method, I have experience with both embedded & web development (along with too many painful years as a Sysadmin! :face_with_peeking_eye:).

However obviously each endpoint differs in which methods they accept - some are GET, others POST or both. In the case of the /input/get endpoint the documentation only mentions the GET method.

Surely the purpose of the emoncms_uploader::handle_query_s() function is to get the details of the node, so that handle_checkQuery() can check that the node exists? Why then would that request be sent as a POST, instead of a GET?

Yes I have tested doing a GET request to the /input/get endpoint, it’s working fine. See below a couple of examples tested against my EmonCMS:

  • First sending a GET to the /input/get endpoint. It returns the expected JSON response. Note that the Authorization Header is not applicable here, and so the “apikey” parameter is used instead.
  • Second I have repeated the same as the emoncms_uploader::handle_query_s() function is doing - same endpoint, but as a POST query.
  • Lastly, an example of a GET request with an Invalid Node Name

1) GET Request to /input/get, using apikey parameter
curl -X GET -H 'User-Agent:' -H 'Accept:' "http://192.168.1.17:80/input/get?node=IotaWatt&apikey=<READ/WRITE API KEY>"
EmonCMS Response

{"1":{"time":1645290101,"value":1,"processList":""}}

GET with the Node name in the URI
curl -X GET -H 'User-Agent:' -H 'Accept:' "http://192.168.1.17:80/input/get/IotaWatt&apikey=<READ/WRITE API KEY>"
EmonCMS Response

{"1":{"time":1645290101,"value":1,"processList":""}}

2) POST Request to /input/get
curl -X POST -H "content-type:application/x-www-form-urlencoded" -H "Authorization:Bearer <READ/WRITE API KEY>" -H 'User-Agent:' -H 'Accept:' -H 'Content-Length:0' "http://192.168.1.17:80/input/get?node=IotaWatt"
EmonCMS Response

<!doctype html>
<html class="theme-blue sidebar-dark">
<head>
    <meta http-equiv="content-type" content="text/html; charset=UTF-8">
    <meta name="viewport" content="width=device-width, initial-scale=1.0, minimum-scale=1">
    <title>Emoncms - user login </title>
    <link rel="shortcut icon" href="http://192.168.1.17/Theme/favicon.png" />
    <meta name="apple-mobile-web-app-capable" content="yes">
    <meta name="apple-mobile-web-app-status-bar-style" content="black">
    <link rel="apple-touch-startup-image" href="http://192.168.1.17/Theme/ios_load.png">
    <link rel="apple-touch-icon" href="http://192.168.1.17/Theme/logo_normal.png">
... Output Omitted ...

3) GET query to an invalid node name
curl -X GET -H 'User-Agent:' -H 'Accept:' "http://192.168.1.17:80/input/get/SomeOtherDevice&apikey=<READ/WRITE API KEY>"
EmonCMS Response

"Node does not exist"

The underlying platform it’s running on is not wholly relevant to this particular issue, the EmonCMS PHP script is being called and that’s what is determining the response. It just looks like the API is being strict - enforcing valid queries, with others being bounced to the homepage (as the catchall else statement).

Just as a further datapoint here, reading back through the EmonCMS Github commits there seems to have been quite a significant refactoring of the Input API around v9.9.1. The two below contain fairly significant re-writes to the code handling GET & POST queries.

It could well be the case that a POST used to work just as well - but that these (or other) changes ended up breaking that.

Even more curiously - I’ve just signed up for an account with the hosted EmonCMS.org instance and tested again. In that instance they are still accepting POST to /input/get - which suggests a difference between the published Community release on Github and that which is being run on their backend. So likely neither of us are going crazy! :smiley:

I can confirm that both of these queries, copied directly from your post (but with my ip and apikey), GET and POST, return the same data for me.

{"1":{"time":1645290101,"value":1,"processList":""}}

I am running a self-hosted emoncms.

commit 8cd7eb79117c417bc723f4c707ae6eac63e4802b (HEAD → stable, tag: 1.4.0, origin/stable)

Thanks for the datapoint, just to confirm - your self-hosted EmonCMS version (on the current release shown at the bottom of every page) is 1.4.0?

Those commits are dated 2017. IoTaWatt didn’t exist then. My money is on something in your environment.

Could be the flood is coming, but there are probably more than a thousand IoTaWatt uploading to eMoncms, and this is the only currently reported instance of POST rejection. I’ll talk to the eMoncms folks. Still need to bulletproof against the large response.

Long term, I’ll look into switching to the GET http method, but that will take some time to see the light of day.

The query isn’t so much to determine if the node exists, but to find the timestamp of the last entry so that uploading can resume where it left off seamlessly.

Thanks @dakaix for your input. I see that you are on 1.4.0.

I’ll look to comb through the EmonCMS PHP in my self-hosted install (10.8.5) to trace where the POST is getting rejected in the /input/get endpoint. Won’t get to it though until the weekend unfortunately!

Edit: Corrected version string.

Glad to say I have now gotten EmonCMS & IoTaWatt to play happily together. Thanks to @overeasy and @timb for your assistance!

I went through the EmonCMS logs and authentication code, and was able to find the difference between the working test queries I had done and the POST to /input/get.

The root cause was the “HTTP_AUTHENTICATION” header not being passed through from Apache to PHP (“Authorization: Bearer APIKEY”).

This is disabled by default (as a security measure) but EmonCMS tries to enable it via htaccess. While other parts of that .htaccess were working, the specific Authorization statement wasn’t. I have now instead configured it in the main Apache Virtualhost configuration, and after retesting I can confirm that the authenetication header is being passed through - and both EmonCMS and IoTaWatt are working.

This was an unfortunate combination of factors since other authentication sources (those not using the “Authorization” header) were working, such as the “apikey” variable set via GET or POST. If the goal for IoTaWatt is to try and bulletproof this integration it would be worth considering whether to deprecate use of the authentication method as it isn’t enabled in Apache by default, and as I’ve found the supplied EmonCMS htaccess doesn’t always work. The easiest route would be for IoTaWatt to use the “apikey” variable instead, and would be straightforward to implement.

emoncms.log:

2022-02-19 19:50:52.021|ERROR|index.php|Not Authenticated|input/get
2022-02-19 19:54:01.581|ERROR|index.php|Not Authenticated|input/get
2022-02-19 19:54:06.466|ERROR|index.php|Not Authenticated|input/get
2022-02-19 19:54:11.379|ERROR|index.php|Not Authenticated|input/get
2022-02-19 20:02:44.001|ERROR|index.php|Not Authenticated|input/get
2022-02-19 20:08:35.998|ERROR|index.php|Not Authenticated|input/get

EmonCMS Authentication:

$apikey = false;
$devicekey = false;
if (isset($_GET['apikey'])) {
    $apikey = $_GET['apikey'];
} elseif (isset($_POST['apikey'])) {
    $apikey = $_POST['apikey'];
} elseif (isset($_GET['devicekey'])) {
    $devicekey = $_GET['devicekey'];
} elseif (isset($_POST['devicekey'])) {
    $devicekey = $_POST['devicekey'];
} elseif (isset($_SERVER["HTTP_AUTHORIZATION"])) {
    // Support passing apikey on Authorization header per rfc6750, like example:
    //      GET /resource HTTP/1.1
    //      Host: server.example.com
    //      Authorization: Bearer THE_API_KEY_HERE
    
    if (isset($_SERVER["CONTENT_TYPE"]) && $_SERVER["CONTENT_TYPE"]=="aes128cbc") {
        // If content_type is AES128CBC
    } else {
        $apikey = str_replace('Bearer ', '', $_SERVER["HTTP_AUTHORIZATION"]);
    }
}

EmonCMS Standard .htaccess:

... Output Truncated ... 

# ------------------------------------------------------------------------------
# Rewrite auth header. Fix Authorization: Bearer
# https://cweiske.de/tagebuch/php-apache-authorization.htm
# ------------------------------------------------------------------------------
<IfModule mod_setenvif.c>
  SetEnvIf Authorization "(.*)" HTTP_AUTHORIZATION=$1
</IfModule>

... Output Truncated ...