Polyglot ISY requests timeout or return errors during the 3AM query

[mjwesterhof]

Multiple users have reported a cluster of HTTP REST requests that fail either due to timeout or other HTTP errors during the 3AM query processing.

This issue has been reproduced by running the query program "then" clause manually, and observing what happens to Polyglot. Similar issues appear randomly over time in the event log.

We need to investigate more deeply to determine if this is a problem in the data sent by Polyglot, or if this is an issue in the ISY, or if the issue is simply that the default 10 second timeout is insufficient during peak processing events on the ISY (such as might happen during the 3AM query).

[mkohanim]

Hi Mike,

Thanks so very much for all your efforts!

Please note the following: 3 AM query uses the D2D/Program thread. This thread is going to be blocked (and all communications to INSTEON/Z-Wave) till the query is finished. So, if you have requests that depends on programs (variables), then they will definitely timeout till the query is done. I am going to talk to Chris and see what would cause nodes from a node server respond when the query is being done.

One major question is: what do users see in ISY log?

With kind regards,

---

Michel Kohanim

[edited to remove excess email stuff for readability; github doesn't do a good job with that... - MW]

[mkohanim]

Hi Mike, more questions from Chris: What devices/protocols are being queried by ISY? Insteon, Z-Wave, node servers only, etc.? What exact REST command (any example) fails when reproducing the problem by running the query all?

With kind regards,

---

Michel Kohanim

[edited to remove excess email stuff for readability; github doesn't do a good job with that... - MW]

[mjwesterhof]

Thanks for the info - that explains the unusually-reliable failures for one of my test cases -- it updates a variable using the REST API, and unlike the Polyglot status updates which usually-but-not-always fail, the REST API update of the variable always failed during the query. I'll remove that from my test code since we know that doesn't currently work. (It should, though... IMO).

I'm going to dig in more deeply, but here's one item I've found. The log snip below shows an incoming status request from the ISY to the Kodi node server (node server 4 on my Polyglot) -- with request_id=667, meaning that Polyglot must respond with a success/fail message referencing that request_id. The next line shows the nodeserver_manager receiving the message from the node server -- it adds it to the REST API processing queue (in square brackets is the queue count - note that it goes from 0 to 1 by the next line in the log).

The next three lines are from the REST API request processor - it fetches the message, and sends it to the ISY. Note that the ISY returns an error - unauthorized -- that shouldn't be happening.

Indications strongly point to the ISY in this case - or perhaps something as simple as a syntax error in the URL (I'll check into that). This happens on all cases where the ISY passes in a request_id. There's only one spot in the code that handles REST calls to the ISY, and it clearly works for everything else. I've even swapped out the "requests" Python library with the standard "urllib2" library -- exactly the same results.

INFO     [04-07-2016 13:47:04] tornado.access: 200 GET /ns/7sRWw/nodes/n004_disco/query?requestId=667 (192.168.232.79) 2.62ms
INFO     [04-07-2016 13:47:04] polyglot.nodeserver_manager:   kodiak [0] ( 0.00) STDOUT: {"request": {"success": true, "request_id": "667"}}
INFO     [04-07-2016 13:47:04] polyglot.nodeserver_manager:   kodiak [1] ( 0.00)   Done: {"request": {"success": true, "request_id": "667"}}
INFO     [04-07-2016 13:47:04] polyglot.nodeserver_manager:   kodiak [0] ( 0.00) _request_handler: command=request
ERROR    [04-07-2016 13:47:04] polyglot.element_manager.isy: ISY:        ( 0.02) [401] OK: http://192.168.232.79:80/rest/ns/4/report/request/status/667/success
INFO     [04-07-2016 13:47:04] polyglot.nodeserver_manager:   kodiak [0] ( 0.03) _request_handler: completed.

[mjwesterhof]

Update: Checking on the validity of the URL was revealing - Polyglot is using the wrong URL for requests reports.

Alas, the documentation is not too clear. http://www.universal-devices.com/developers/wsdk/5.0.0/ISY-WS-SDK-Node-Server.pdf Page 15 give two possible urls:

/rest/ns/4/report/status/667/success is listed at the top of the section... /rest/ns/4/report/request/667/success would match the example at the bottom...

/rest/ns/4/report/request/status/667/success is what's in the log (previous message above), which matches neither. I'll try both others to see which one works, and retest.

[mjwesterhof]

Ok, the 401 errors caused by the bad REST url are fixed. Here's a snippet of the log with the timeouts - there are several of these (perhaps a dozen or more) that pop up during each run of the ISY's 3AM query program:

INFO     [04-07-2016 17:06:57] polyglot.nodeserver_manager:      Pex [5] ( 0.00) STDOUT: {"request": {"request_id": "706", "success": true}}
INFO     [04-07-2016 17:06:57] polyglot.nodeserver_manager:      Pex [6] ( 0.00)   Done: {"request": {"request_id": "706", "success": true}}
ERROR    [04-07-2016 17:06:57] polyglot.element_manager.isy: ISY:        (15.02) Timeout: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460066802/56
INFO     [04-07-2016 17:06:57] polyglot.nodeserver_manager:      Tex [0] (15.02) _request_handler: completed.
INFO     [04-07-2016 17:07:02] polyglot.nodeserver_manager:      Pex Writing STDIN: {"ping": {}}
INFO     [04-07-2016 17:07:02] polyglot.nodeserver_manager:      Pex [6] ( 0.00) STDOUT: {"pong": {}}

[mkohanim]

Hi Mike,

Thanks so very much. Can you please let me know what the time out value is for Polyglot? This should not timeout since it has nothing to do with programs.

With kind regards,

---

Michel Kohanim CEO

[cjudi]

Hi All ... Just popping in for a minute here :)

The api to report success/fail uses 'request', not 'status' i.e. /report/request/< requestId >/fail /report/request/< requestId >/success

I've updated the documentation for our next build v5.0.5

The only time the ISY currently uses a requestId is when it performs a query on a node in a node server.

Chris Jahn

[mjwesterhof]

Chris - thanks! Can you take a look at the following, and confirm the "fail" url? The log snippet shows a successful report for a working node, followed by a failed query on an offline Kodi node -- the last line is unexpected - a 401 error when trying to report the failed status.

INFO     [04-07-2016 22:25:26] polyglot.element_manager.isy: ISY:        ( 0.04) Success: http://192.168.232.79:80/rest/ns/4/report/request/757/success
INFO     [04-07-2016 22:25:27] tornado.access: 200 GET /ns/7sRWw/nodes/n004_69bcdee4685f26/query?requestId=758 (192.168.232.79) 3.52ms
ERROR    [04-07-2016 22:25:27] polyglot.nodeserver_manager: kodiak: Unsuccessful handling query in function on_query
ERROR    [04-07-2016 22:25:27] polyglot.element_manager.isy: ISY:        ( 0.02) [401] (OK) http://192.168.232.79:80/rest/ns/4/report/request/758/fail

Michel - the timeouts are set to 10 seconds in the released Polyglot source; I have experimented with 15 seconds and 30 seconds, and found no difference. In other words, if the REST call to the ISY doesn't succeed in one second or less, it never succeeds. I may try a shorter timeout with retries, though, and see if its better.

[cjudi]

Good catch Mike, its another documentation bug (now fixed for next build).

Its failed not fail /report/request/< requestId >/failed /report/request/< requestId >/success

[mkohanim]

Hi Mike,

That’s really odd. Do you know how long the queryall program takes?

Is it possible to check and see whether queryall was still running when timed out (the icon next to the program).

With kind regards,

---

Michel Kohanim CEO

[mjwesterhof]

I'm tightening things up, and will be building a custom version of the 3AM query that includes some actions on node servers that we can use as markers in the log files to denote the start and end of the queries. Automate everything, including gathering test logs. I'll post those results later today or tomorrow.

Below is an interesting set of log entries. With the work done so far, and the feedback from UDI on the error URLs, I've got the logs now free of all errors except legitimate network failures -- I've grepped out all the REST calls to the ISY from last night's log file, then removed all lines where the REST call itself took less than 200 milliseconds to complete. I left in the failed REST calls to fetch variable values -- although we know from earlier comments on this issue that those are expected to fail. So use those only as an easy way to know when that 3AM query is running, and nothing more. I've also bumped up the timeout to 30 seconds. You'll note that my earlier statement about things being binary was, in fact, wrong -- we do get a few long API calls in there. The numbers in parenthesis are the elapsed time for the REST API call, BTW.

INFO [04-07-2016 23:18:38] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV3/232/56
INFO [04-07-2016 23:18:39] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832a40b/report/status/GV2/0/56
INFO [04-07-2016 23:18:40] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832a40b/report/status/GV2/0.4148/56
INFO [04-07-2016 23:18:40] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100e70ade0b/report/status/ST/0/51
INFO [04-07-2016 23:22:09] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460089329/56
INFO [04-08-2016 00:02:51] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460091770/56
INFO [04-08-2016 00:13:50] ISY: ( 0.24) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460092430/56
INFO [04-08-2016 00:15:50] ISY: ( 0.24) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460092550/56
INFO [04-08-2016 00:21:50] ISY: ( 0.22) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 00:33:14] ISY: ( 0.24) Success: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460093593/56
INFO [04-08-2016 00:36:50] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460093810/56
INFO [04-08-2016 00:45:51] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460094350/56
INFO [04-08-2016 00:57:50] ISY: ( 0.22) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 00:58:15] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460095095/56
INFO [04-08-2016 01:15:52] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460096151/56
INFO [04-08-2016 01:21:51] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460096511/56
INFO [04-08-2016 01:21:51] ISY: ( 0.23) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 01:50:52] ISY: ( 0.22) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 01:57:19] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460098639/56
INFO [04-08-2016 02:14:51] ISY: ( 0.23) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 03:10:52] ISY: ( 0.23) Success: http://192.168.232.79:80/rest/vars/get/1/1
ERROR[04-08-2016 03:12:21] ISY: (30.03) Timeout: http://192.168.232.79:80/rest/vars/get/1/1
ERROR[04-08-2016 03:13:21] ISY: (30.04) Timeout: http://192.168.232.79:80/rest/vars/get/1/1
ERROR[04-08-2016 03:14:21] ISY: (30.06) Timeout: http://192.168.232.79:80/rest/vars/get/1/1
ERROR[04-08-2016 03:14:24] ISY: (30.03) Timeout: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460103234/56
ERROR[04-08-2016 03:14:54] ISY: (30.01) Timeout: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460103264/56
INFO [04-08-2016 03:15:01] ISY: (10.16) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460103291/56
INFO [04-08-2016 03:15:01] ISY: ( 7.65) Success: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460103294/56
INFO [04-08-2016 03:15:01] ISY: ( 0.32) Success: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV2/168/56
INFO [04-08-2016 03:15:02] ISY: ( 0.71) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 03:15:02] ISY: ( 0.77) Success: http://192.168.232.79:80/rest/ns/4/nodes/n004_906b6ed65d96e3/report/status/ST/2/25
INFO [04-08-2016 03:15:02] ISY: ( 0.75) Success: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460103301/56
INFO [04-08-2016 03:15:02] ISY: ( 0.75) Success: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV3/232/56
INFO [04-08-2016 03:15:03] ISY: ( 0.67) Success: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100e70ade0b/report/status/GV2/0.4148/56
INFO [04-08-2016 03:24:52] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460103891/56
INFO [04-08-2016 03:36:52] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460104611/56
INFO [04-08-2016 03:36:52] ISY: ( 0.22) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 03:55:52] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460105751/56
INFO [04-08-2016 04:11:52] ISY: ( 0.23) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 04:18:28] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460107108/56
INFO [04-08-2016 04:26:52] ISY: ( 0.29) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460107611/56
INFO [04-08-2016 05:02:51] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460109771/56
INFO [04-08-2016 05:03:52] ISY: ( 0.23) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 05:11:51] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460110311/56
INFO [04-08-2016 05:41:51] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460112111/56
INFO [04-08-2016 05:49:04] ISY: ( 0.24) Success: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460112543/56
INFO [04-08-2016 06:00:51] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460113251/56
INFO [04-08-2016 06:19:51] ISY: ( 0.43) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 06:41:51] ISY: ( 0.39) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460115711/56
INFO [04-08-2016 06:48:51] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460116131/56
INFO [04-08-2016 06:56:51] ISY: ( 0.22) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 06:59:52] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 07:31:52] ISY: ( 0.21) Success: http://192.168.232.79:80/rest/vars/get/1/1
INFO [04-08-2016 07:33:54] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100e70ade0b/report/status/ST/20/51
INFO [04-08-2016 07:34:53] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460118892/56
INFO [04-08-2016 07:39:16] ISY: ( 0.25) Success: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832cf0b/report/status/ST/30/51
INFO [04-08-2016 07:47:44] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832a40b/report/status/ST/57/51
INFO [04-08-2016 08:07:12] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460120832/56
INFO [04-08-2016 08:22:43] ISY: ( 0.26) Success: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460121763/56
INFO [04-08-2016 08:32:53] ISY: ( 0.29) Success: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460122373/56
INFO [04-08-2016 08:32:54] ISY: ( 0.28) Success: http://192.168.232.79:80/rest/vars/get/1/1

[mkohanim]

Thank you!

With kind regards,

---

Michel Kohanim CEO

[mjwesterhof]

Committed the latest changes; they won't fix any of the remaining errors described on this thread, but it does add better logging of same. (And yes, the log file is very noisy right now - we do have to comment out a lot of the log messages once were all confident that this code is working as best as it can).

So far, with today's testing, there doesn't appear to be any significant difference in the timeouts when using the current requests library code (which is what's currently in git), versus a slightly modified version of the code that enables sessions with the requests library (I was hoping that keeping the connection to the ISY open might allow us to get messages through, but it doesn't make a significant difference it seems). I also heavily tested a totally different library - urllib2, again with little difference.

Next up in terms of changes are to add retries and see if that helps.

(Oh - forgot to add that the latest commit also includes the experimental rest call and response APIs into the core code - they're only available on the STDIO API, so not very useful yet. However, that code is so intertwined with the network logging changes that I'm pushing them together - it's faster and easier than untangling the code, testing all over again, and committing in two chunks. Sorry.)

[mkohanim]

Hi Mike,

Thank you. We’ll have to take a look at ISY and see what’s going on.

With kind regards,

---

Michel Kohanim CEO

(p) 818.631.0333 (f) 818.436.0702 http://www.universal-devices.comhttp://www.universal-devices.com/

---

From: Mike Westerhof [mailto:notifications@github.com] Sent: Friday, April 8, 2016 2:55 PM To: UniversalDevicesInc/Polyglot Polyglot@noreply.github.com Cc: Michel Kohanim michel@universal-devices.com Subject: Re: [UniversalDevicesInc/Polyglot] Polyglot ISY requests timeout or return errors during the 3AM query (#38)

Committed the latest changes; they won't fix any of the remaining errors described on this thread, but it does add better logging of same. (And yes, the log file is very noisy right now - we do have to comment out a lot of the log messages once were all confident that this code is working as best as it can).

So far, with today's testing, there doesn't appear to be any significant difference in the timeouts when using the current requests library code (which is what's currently in git), versus a slightly modified version of the code that enables sessions with the requests library (I was hoping that keeping the connection to the ISY open might allow us to get messages through, but it doesn't make a significant difference it seems). I also heavily tested a totally different library - urllib2, again with little difference.

Next up in terms of changes are to add retries and see if that helps.

— You are receiving this because you commented. Reply to this email directly or view it on GitHubhttps://github.com/UniversalDevicesInc/Polyglot/issues/38#issuecomment-207622311

[mjwesterhof]

With session support things still fail on the real 3AM query program. However, here's what one sees doing the same query but instead of querying the "ISY" scene, it queries (at 3:11 PM) a scene containing only all of the Polyglot node servers. Note the burst of incoming requests followed by the responses in this unedited log snippet - clearly there's no problems handling bursts of heavy network traffic. So at this point, I'm going to go out on a limb and say that there's nothing more that can be done on the Polyglot side; the issues need to be investigated on the ISY side at this point.

INFO     [04-10-2016 15:11:03] polyglot.element_manager.isy: ISY:        ( 0.05) 200  OK: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460319063/56
INFO     [04-10-2016 15:11:17] tornado.access: 200 GET /ns/vzWHQ/nodes/n002_tex_t/cmd/ST (192.168.232.79) 3.81ms
INFO     [04-10-2016 15:11:17] tornado.access: 200 GET /ns/E5VTW/nodes/n001_hub/cmd/ST (192.168.232.79) 3.73ms
INFO     [04-10-2016 15:11:17] tornado.access: 200 GET /ns/E5VTW/nodes/n001_880100f832a40b/cmd/ST (192.168.232.79) 3.87ms
INFO     [04-10-2016 15:11:17] tornado.access: 200 GET /ns/E5VTW/nodes/n001_880100e70ade0b/cmd/ST (192.168.232.79) 3.76ms
INFO     [04-10-2016 15:11:17] requests.packages.urllib3.connectionpool: Resetting dropped connection: 192.168.232.79
INFO     [04-10-2016 15:11:17] tornado.access: 200 GET /ns/E5VTW/nodes/n001_880100f832cf0b/cmd/ST (192.168.232.79) 13.47ms
INFO     [04-10-2016 15:11:17] tornado.access: 200 GET /ns/7sRWw/nodes/n004_disco/cmd/ST (192.168.232.79) 5.38ms
INFO     [04-10-2016 15:11:17] requests.packages.urllib3.connectionpool: Resetting dropped connection: 192.168.232.79
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.05) 200  OK: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460319077/56
INFO     [04-10-2016 15:11:17] tornado.access: 200 GET /ns/VY5ug/nodes/n003_pex_t/cmd/ST (192.168.232.79) 5.89ms
INFO     [04-10-2016 15:11:17] tornado.access: 200 GET /ns/VY5ug/nodes/n003_pex_cd0/cmd/ST (192.168.232.79) 4.21ms
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.08) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV2/168/56
INFO     [04-10-2016 15:11:17] tornado.access: 200 GET /ns/VY5ug/nodes/n003_pex_cd1/cmd/ST (192.168.232.79) 4.82ms
INFO     [04-10-2016 15:11:17] tornado.access: 200 GET /ns/E5VTW/nodes/n001_6b001400623d01/cmd/ST (192.168.232.79) 3.98ms
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.08) 200  OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460319077/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.07) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV3/232/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.04) 200  OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_cd0/report/status/ST/0/2
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.04) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV1/192/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.04) 200  OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_cd0/report/status/GV1/0/58
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.06) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV4/14/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.05) 200  OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_cd1/report/status/ST/0/2
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.04) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV5/1/2
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.05) 200  OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_cd1/report/status/GV1/0/58
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.04) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832a40b/report/status/GV2/0.4148/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.04) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832a40b/report/status/GV1/0.51/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.04) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832a40b/report/status/ST/0/51
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.03) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100e70ade0b/report/status/GV2/0.4148/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.05) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100e70ade0b/report/status/GV1/0.51/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.03) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100e70ade0b/report/status/ST/0/51
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.03) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832cf0b/report/status/GV2/0.4148/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.03) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832cf0b/report/status/GV1/0.51/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.03) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832cf0b/report/status/ST/0/51
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.03) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_6b001400623d01/report/status/GV2/0/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.03) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_6b001400623d01/report/status/GV1/0/56
INFO     [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY:        ( 0.03) 200  OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_6b001400623d01/report/status/ST/0/51
INFO     [04-10-2016 15:11:33] requests.packages.urllib3.connectionpool: Resetting dropped connection: 192.168.232.79
INFO     [04-10-2016 15:11:33] polyglot.element_manager.isy: ISY:        ( 0.06) 200  OK: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460319093/56
INFO     [04-10-2016 15:12:01] requests.packages.urllib3.connectionpool: Resetting dropped connection: 192.168.232.79
INFO     [04-10-2016 15:12:01] polyglot.element_manager.isy: ISY:        ( 0.04) 200  OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460319121/56

[mkohanim]

Hi Mike,

Thanks SO very much for the details based on which we found the root cause (a critical section in the code). We are going to look into it closer to see why it’s there in the first place and, if needed, whether or not we can make it shorter in duration based on what’s being changed.

THANKS again.

With kind regards,

---

Michel Kohanim CEO

(p) 818.631.0333 (f) 818.436.0702 http://www.universal-devices.comhttp://www.universal-devices.com/

---

From: Mike Westerhof [mailto:notifications@github.com] Sent: Sunday, April 10, 2016 2:15 PM To: UniversalDevicesInc/Polyglot Polyglot@noreply.github.com Cc: Michel Kohanim michel@universal-devices.com Subject: Re: [UniversalDevicesInc/Polyglot] Polyglot ISY requests timeout or return errors during the 3AM query (#38)

With session support things still fail on the real 3AM query program. However, here's what one sees doing the same query but instead of querying the "ISY" scene, it queries (at 3:11 PM) a scene containing only all of the Polyglot node servers. Note the burst of incoming requests followed by the responses in this unedited log snippet - clearly there's no problems handling bursts of heavy network traffic. So at this point, I'm going to go out on a limb and say that there's nothing more that can be done on the Polyglot side; the issues need to be investigated on the ISY side at this point.

INFO [04-10-2016 15:11:03] polyglot.element_manager.isy: ISY: ( 0.05) 200 OK: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460319063/56

INFO [04-10-2016 15:11:17] tornado.access: 200 GET /ns/vzWHQ/nodes/n002_tex_t/cmd/ST (192.168.232.79) 3.81ms

INFO [04-10-2016 15:11:17] tornado.access: 200 GET /ns/E5VTW/nodes/n001_hub/cmd/ST (192.168.232.79) 3.73ms

INFO [04-10-2016 15:11:17] tornado.access: 200 GET /ns/E5VTW/nodes/n001_880100f832a40b/cmd/ST (192.168.232.79) 3.87ms

INFO [04-10-2016 15:11:17] tornado.access: 200 GET /ns/E5VTW/nodes/n001_880100e70ade0b/cmd/ST (192.168.232.79) 3.76ms

INFO [04-10-2016 15:11:17] requests.packages.urllib3.connectionpool: Resetting dropped connection: 192.168.232.79

INFO [04-10-2016 15:11:17] tornado.access: 200 GET /ns/E5VTW/nodes/n001_880100f832cf0b/cmd/ST (192.168.232.79) 13.47ms

INFO [04-10-2016 15:11:17] tornado.access: 200 GET /ns/7sRWw/nodes/n004_disco/cmd/ST (192.168.232.79) 5.38ms

INFO [04-10-2016 15:11:17] requests.packages.urllib3.connectionpool: Resetting dropped connection: 192.168.232.79

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.05) 200 OK: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460319077/56

INFO [04-10-2016 15:11:17] tornado.access: 200 GET /ns/VY5ug/nodes/n003_pex_t/cmd/ST (192.168.232.79) 5.89ms

INFO [04-10-2016 15:11:17] tornado.access: 200 GET /ns/VY5ug/nodes/n003_pex_cd0/cmd/ST (192.168.232.79) 4.21ms

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.08) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV2/168/56

INFO [04-10-2016 15:11:17] tornado.access: 200 GET /ns/VY5ug/nodes/n003_pex_cd1/cmd/ST (192.168.232.79) 4.82ms

INFO [04-10-2016 15:11:17] tornado.access: 200 GET /ns/E5VTW/nodes/n001_6b001400623d01/cmd/ST (192.168.232.79) 3.98ms

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.08) 200 OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460319077/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.07) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV3/232/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.04) 200 OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_cd0/report/status/ST/0/2

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.04) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV1/192/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.04) 200 OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_cd0/report/status/GV1/0/58

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.06) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV4/14/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.05) 200 OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_cd1/report/status/ST/0/2

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.04) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_hub/report/status/GV5/1/2

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.05) 200 OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_cd1/report/status/GV1/0/58

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.04) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832a40b/report/status/GV2/0.4148/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.04) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832a40b/report/status/GV1/0.51/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.04) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832a40b/report/status/ST/0/51

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.03) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100e70ade0b/report/status/GV2/0.4148/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.05) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100e70ade0b/report/status/GV1/0.51/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.03) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100e70ade0b/report/status/ST/0/51

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.03) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832cf0b/report/status/GV2/0.4148/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.03) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832cf0b/report/status/GV1/0.51/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.03) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_880100f832cf0b/report/status/ST/0/51

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.03) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_6b001400623d01/report/status/GV2/0/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.03) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_6b001400623d01/report/status/GV1/0/56

INFO [04-10-2016 15:11:17] polyglot.element_manager.isy: ISY: ( 0.03) 200 OK: http://192.168.232.79:80/rest/ns/1/nodes/n001_6b001400623d01/report/status/ST/0/51

INFO [04-10-2016 15:11:33] requests.packages.urllib3.connectionpool: Resetting dropped connection: 192.168.232.79

INFO [04-10-2016 15:11:33] polyglot.element_manager.isy: ISY: ( 0.06) 200 OK: http://192.168.232.79:80/rest/ns/2/nodes/n002_tex_t/report/status/ST/1460319093/56

INFO [04-10-2016 15:12:01] requests.packages.urllib3.connectionpool: Resetting dropped connection: 192.168.232.79

INFO [04-10-2016 15:12:01] polyglot.element_manager.isy: ISY: ( 0.04) 200 OK: http://192.168.232.79:80/rest/ns/3/nodes/n003_pex_t/report/status/ST/1460319121/56

— You are receiving this because you commented. Reply to this email directly or view it on GitHubhttps://github.com/UniversalDevicesInc/Polyglot/issues/38#issuecomment-208073767

[mkohanim]

Thank you Mike. We'll take a look.