St-Inventory crashes ISY

[johnnyt]

I moved to PG3 a couple weeks ago and installed ST-Inventory. My ISY crashed 3 times in 2 days so I decided to stop 1 NS at a time starting with ST-Inventory. Not only did ISY not crash again for the few days I tested but when I restarted it, it crashed again within hours.

Attached is ST-Inventory log. 

Here are the restarts in first round of testing (from ISY log)

Time	User	Log Type
Thu 2022/07/07 05:05:03 PM	System	Start
Fri 2022/07/08 02:40:52 AM	System	Start
Fri 2022/07/08 07:14:10 PM	System	Start

 

And here's the restart time related to the ST-Inventory flood of errors in the attached log file

Sun 2022/07/10 01:25:01 PM

System

Start

 

 

 

ST-Inventory_7-10-2022_25135_PM.zip

Edited July 14, 2022 by johnnyt

[simplextech]

22 hours ago, johnnyt said:

My ISY crashed 3 times in 2 days so I decided to stop 1 NS at a time starting with ST-Inventory.

I'm afraid I don't know how a NS is crashing the whole ISY.  I recommend you opening a ticket with UD support about the ISY crashes.

The log however does show that the Node.js Polyglot API is not a current version and needs to be updated.

Were you running ST-Inventory before and then updated to the newer version?  If so then it would seem that the Polyglot API is not being updated on NS updates or installs which is a problem outside of a single NS.

[johnnyt]

7 minutes ago, simplextech said:

I'm afraid I don't know how a NS is crashing the whole ISY.  I recommend you opening a ticket with UD support about the ISY crashes.

The log however does show that the Node.js Polyglot API is not a current version and needs to be updated.

Were you running ST-Inventory before and then updated to the newer version?  If so then it would seem that the Polyglot API is not being updated on NS updates or installs which is a problem outside of a single NS.

Ok i'll report to UD support but all I did was "purchase" and "install" NS on same day. I didn't think I had to do an update on the same day I installed it. Let's see what UD support says.

[simplextech]

4 hours ago, johnnyt said:

Ok i'll report to UD support but all I did was "purchase" and "install" NS on same day. I didn't think I had to do an update on the same day I installed it. Let's see what UD support says.

No the question was if you had a previous version of ST-Inventory running making this an upgrade to that pre-existing NS or if this was a new install.

Is the Polisy new?  Is it up to date?  Do you have any other NS running, specifically any other Simplex Technology NS defined with ST in the beginning of the name.

The error in the log is clear that the Polyglot API is not current which would cause the NS to fail on startup.  What is unknown is why this would crash the entire ISY as you have stated it did. 

[johnnyt]

12 hours ago, simplextech said:

No the question was if you had a previous version of ST-Inventory running making this an upgrade to that pre-existing NS or if this was a new install.

Is the Polisy new?  Is it up to date?  Do you have any other NS running, specifically any other Simplex Technology NS defined with ST in the beginning of the name.

The error in the log is clear that the Polyglot API is not current which would cause the NS to fail on startup.  What is unknown is why this would crash the entire ISY as you have stated it did. 

Polisy not new but move to PG3 is new. It is (was) up to date prior to move as far as I know. Below is what I have installed running (on PG3) along with PG3 and ISY version numbers (am still on 994i, not using IoP yet). I have no other ST NS's and nothing running under PG2. I did have ISY inventory installed on PG2 and it wasn't working properly. Would work for about a day than stop working. Would that have any relevance here?

 

 

 

Edited July 15, 2022 by johnnyt

[simplextech]

4 hours ago, johnnyt said:

I did have ISY inventory installed on PG2 and it wasn't working properly. Would work for about a day than stop working. Would that have any relevance here?

No they are not related.  However your previous problems tell me there's some other problem as I've not heard/seen this type of behavior from anyone else.

[johnnyt]

I've uninstalled and reinstalled NS in same slot. Should I have deleted the ISY nodes before reinstalling and/or used a different slot? (I didn't)

I'm working with Michel, who's mentioning I may have issues with power supply or PLM from looking at error log entries. But that wouldn't explain the wrong API's being used.

 

[johnnyt]

I just restarted NS and nothing is being written to the log. I had changed log level to "Debug" yesterday, started NS than stopped it (waiting for more info). I restarted just now (a day later) with log level "Info" (one level above Debug) and there's no data being written to the log - and it took several mins to update node data in ISY.

It won't be much use running this NS if there's no log data should ISY crash again (coincidentally or not)

I don't know if Polyglot log file is of any help but have attached it here.

 

pg3_7-15-2022_44844_PM.zip

[johnnyt]

Ok, might be browser caching - all I can think of - because I checked in again about 4 hours later (new browser session) and now the log does show info related to the restart I did 4 hours ago.

FWIW I tried doing upgrade from IoP (the recommended way to do it) and it didn't change anything or even do a Polisy reboot, which I assume means everything is up to date.

here's the before screenshot:

And the after:

 

Anyway, NS is running again. let's see what happens.

 

 

[johnnyt]

Didn't take long to report error again (with API, if I understand correctly):

2022-07-15 20:37:08 info: NS: Starting Node Server 2022-07-15 20:37:08 info: POLY: Interface starting 2022-07-15 20:37:08 info: POLY: Getting config from environment 2022-07-15 20:37:09 info: POLY: MQTT client connected 2022-07-15 20:37:09 info: NS: MQTT Connection started 2022-07-15 20:37:09 error: POLY: Config has logLevel: INFO 2022-07-15 20:37:09 info: POLY: Loglevel: info 2022-07-15 20:37:09 info: POLY: Setting node controller driver ST: 1 2022-07-15 20:37:09 info: NS: Config received has 1 nodes

2022-07-15 20:42:08 info: NS: Short poll

2022-07-15 20:42:08 info: NS: Short Poll: Inventory

2022-07-15 20:42:08 info: NS: Discovering

2022-07-15 20:42:20 error: POLY: getInv() Error: http://192.168.200.251:80/rest/programs?subfolders=true

2022-07-15 20:42:23 error: NS: Parsing Error: TypeError: Cannot read properties of undefined (reading 'toString')

at exports.Parser.Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:312:19)

at Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:5:59)

at _0x242b12.processPrograms (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:5651)

at _0x242b12.onDiscover (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3227)

at process.processTicksAndRejections (node:internal/process/task_queues:95:5)

2022-07-15 20:42:23 error: NS: Parsing Error: TypeError: Cannot read properties of undefined (reading 'program')

at /var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:5801

at Parser.<anonymous> (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:304:18)

at Parser.emit (node:events:539:35)

at SAXParser.onclosetag (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:262:26)

at emit (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:624:35)

at emitNode (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:629:5)

at closeTag (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:889:7)

at SAXParser.write (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:1436:13)

at exports.Parser.Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:323:31)

at Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:5:59)

2022-07-15 20:47:08 info: NS: Long poll

2022-07-15 20:47:08 info: NS: Long Poll: Inventory

2022-07-15 20:47:08 info: NS: Short poll

2022-07-15 20:47:08 info: NS: Short Poll: Inventory

2022-07-15 20:47:08 info: NS: Discovering

 

 

[simplextech]

13 hours ago, johnnyt said:

2022-07-15 20:42:20 error: POLY: getInv() Error: http://192.168.200.251:80/rest/programs?subfolders=true

It does not matter how many times you remove and install at this point as the Polyglot Node.js Interface is not the correct version on your Polisy.  

At this moment I do not know why the interface was not updated with the NS install.  I'll see if I can find some time this weekend to investigate and see if I can replicate the problem.

[johnnyt]

FWIW, some data is getting updated in ISY, The log file (at "info" level) is showing some successes and for sure I've seen the number of programs change as I add some. Probably others too (I see them in the log) but not looking too closely at those in ISY.

What's not working or not being updated due to the API error, which is still happening periodically? 

See attached log file.

 

ST-Inventory_7-16-2022_43224_PM.zip

[simplextech]

17 hours ago, johnnyt said:

FWIW, some data is getting updated in ISY, The log file (at "info" level) is showing some successes and for sure I've seen the number of programs change as I add some. Probably others too (I see them in the log) but not looking too closely at those in ISY.

What's not working or not being updated due to the API error, which is still happening periodically? 

See attached log file.

 

ST-Inventory_7-16-2022_43224_PM.zip 4.49 kB · 0 downloads

Now this log is much more interesting.

Are you running ISY on Polisy or a ISY994i?

This log is showing intermittent success/failures for various inventory aspects.  

[johnnyt]

10 minutes ago, simplextech said:

Are you running ISY on Polisy or a ISY994i?

994i, ver 5.3.4

[simplextech]

5 hours ago, johnnyt said:

994i, ver 5.3.4

I'll clean up my Polisy and setup an ISY994i and test against it to see if I can replicate the problems.

[simplextech]

6 hours ago, johnnyt said:

994i, ver 5.3.4

I've setup my isy994i and have had ST-Inventory (fresh install) running for the last hour without any problems.

I did go back and review the log that you sent and it is interesting

2022-07-16 00:47:18 error: POLY: getInv() Error: http://192.168.200.251:80/rest/programs?subfolders=true
2022-07-16 00:47:20 error: NS: Parsing Error: TypeError: Cannot read properties of undefined (reading 'toString')
    at exports.Parser.Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:312:19)
    at Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:5:59)
    at _0x242b12.processPrograms (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:5651)
    at _0x242b12.onDiscover (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3227)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)

This error repeats numerous times.  This is not the NS crashing as the log shows the NS continues running and works "most" of the time but then these errors again return.  This error is caused because the data received from the ISY is not valid.  Most of the time the ISY is returning valid XML data for the inventory calls.  However many times the ISY is not returning valid data that is causing parsing errors.

This could be resource contention on the ISY and processing of the network calls being made to it or it could be something else.

I will make note of this and clean up the error message to make it more friendly about what is happening.

[johnnyt]

3 hours ago, simplextech said:

This could be resource contention on the ISY and processing of the network calls being made to it or it could be something else.

 

It's certainly possible my ISY can't keep up. I've had lots of issues with the lack of horsepower over the years, despite efforts to try to keep things lean (including many hours spent redesigning things and asking help from UDI) and using lots of 'wait' commands to slow things down. I'm at 980 programs. 20 short of the max for the 994i so I'm effectively crippled until I move to IoP, which will support up to 2000 programs, but have a lot more ideas things I want to do. I really hope IoP will benefit from the Polisy horsepower and I will need it if I'm going to keep investing in ISY/IoP as my HA controller. For now I have to last until there's stable zwave migration capability to find out.

What's not clear to me is why I was getting tons of the errors (and ISY crashes than may or may not have been related - perhaps due to overload) when I first moved to PG3 and now it's down to only a few errors. If anything I've only added to the load by adding an Airthings NS and a Tempest Weather Station NS (which did not have PG2 offerings) - about 20-30 more programs, though they don't do that much.

This NS has been running for me with this lower rate of errors for a few days now with no ISY crashes, so not too worried about this anymore at this point. 

I would ask, though, that if there are things you can do to tolerate slower responses from ISY and/or try again 30 and/or 60 secs later and only report multiple subsequent errors, please consider doing that. There's no major rush to getting this data, with limited use cases (that I can think of) for use in programs. (Maybe a notification when some limit is close to being reached? I only know about the number of program limitation)

I can see from the logs the short poll is when ISY is queried. Can you tell me what the long poll does? Is it just a heart beat? Can the long poll be shorter than the short poll? It's not mentioned in the Config help.

Thanks

[simplextech]

2 hours ago, johnnyt said:

I would ask, though, that if there are things you can do to tolerate slower responses from ISY and/or try again 30 and/or 60 secs later and only report multiple subsequent errors, please consider doing that. There's no major rush to getting this data, with limited use cases (that I can think of) for use in programs. (Maybe a notification when some limit is close to being reached? I only know about the number of program limitation)

I can see from the logs the short poll is when ISY is queried. Can you tell me what the long poll does? Is it just a heart beat? Can the long poll be shorter than the short poll? It's not mentioned in the Config help.

I can look into timeout handling which is essentially just quieting the log message as it will retry on the next short poll interval.

Currently there's a short/long poll.  The short poll is the only thing that does anything which is query the ISY.  Default should be set to 5 minutes but in your case I recommend increasing that.  You'll have to change the long poll which must be greater than the short poll.  I have thought about swapping the short/long poll where only the long poll is used.  In most cases nobody needs 5 minutes updates to changes within their ISY (Unless they are testing something which they can then use the discover button).  So yes in your case I highly recommend you set the long poll to something like 24 hours and short poll to 1 hour or longer.  

24 Hours = 86400 seconds

1 Hour = 3600 seconds

 

 

[johnnyt]

Thanks. Good to learn about the Discover button and long poll. might be useful to add to config help in a future update.

I'm not so sure the issue is exclusively that ISY is busy. I just ran 4 discoveries in a row and 3 times an error occurred but ISY is really not busy right now - and there's nothing in the ISY error log.

Maybe I'm having network issues with NS related network errors presumably not showing up in ISY error log. I'll do a little forensic research and, if I can't tell, send logs to UDI to see if there are indications of abnormal network related issues in other circumstances.

 

2022-07-18 11:18:45 info: NS: Discovering
2022-07-18 11:20:01 info: NS: Discovering
2022-07-18 11:20:01 info: NS: Discovering Nodes
2022-07-18 11:20:09 error: POLY: getInv() Error: http://192.168.200.251:80/rest/nodes
2022-07-18 11:20:29 error: NS: Parsing Error: TypeError: Cannot read properties of undefined (reading 'toString')
    at exports.Parser.Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:312:19)
    at Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:5:59)
    at _0x242b12.processNodes (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3482)
    at _0x242b12.onDiscover (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3126)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
2022-07-18 11:20:30 error: NS: Parsing Error: TypeError: Cannot read properties of undefined (reading 'node')
    at /var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3650
    at Parser.<anonymous> (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:304:18)
    at Parser.emit (node:events:539:35)
    at SAXParser.onclosetag (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:262:26)
    at emit (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:624:35)
    at emitNode (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:629:5)
    at closeTag (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:889:7)
    at SAXParser.write (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:1436:13)
    at exports.Parser.Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:323:31)
    at Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:5:59)
2022-07-18 11:20:53 info: NS: Discovering
2022-07-18 11:20:53 info: NS: Discovering Nodes
2022-07-18 11:21:00 error: POLY: getInv() Error: http://192.168.200.251:80/rest/nodes
2022-07-18 11:21:09 error: NS: Parsing Error: TypeError: Cannot read properties of undefined (reading 'toString')
    at exports.Parser.Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:312:19)
    at Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:5:59)
    at _0x242b12.processNodes (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3482)
    at _0x242b12.onDiscover (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3126)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
2022-07-18 11:21:09 error: NS: Parsing Error: TypeError: Cannot read properties of undefined (reading 'node')
    at /var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3650
    at Parser.<anonymous> (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:304:18)
    at Parser.emit (node:events:539:35)
    at SAXParser.onclosetag (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:262:26)
    at emit (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:624:35)
    at emitNode (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:629:5)
    at closeTag (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:889:7)
    at SAXParser.write (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:1436:13)
    at exports.Parser.Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:323:31)
    at Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:5:59)
2022-07-18 11:21:31 info: NS: Discovering
2022-07-18 11:21:31 info: NS: Discovering Nodes
2022-07-18 11:22:53 info: NS: Discovering
2022-07-18 11:22:53 info: NS: Discovering Nodes
2022-07-18 11:23:07 error: POLY: getInv() Error: http://192.168.200.251:80/rest/nodes
2022-07-18 11:23:13 error: NS: Parsing Error: TypeError: Cannot read properties of undefined (reading 'toString')
    at exports.Parser.Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:312:19)
    at Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:5:59)
    at _0x242b12.processNodes (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3482)
    at _0x242b12.onDiscover (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3126)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
2022-07-18 11:23:13 error: NS: Parsing Error: TypeError: Cannot read properties of undefined (reading 'node')
    at /var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/Nodes/ControllerNode.js:1:3650
    at Parser.<anonymous> (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:304:18)
    at Parser.emit (node:events:539:35)
    at SAXParser.onclosetag (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:262:26)
    at emit (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:624:35)
    at emitNode (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:629:5)
    at closeTag (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:889:7)
    at SAXParser.write (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/sax/lib/sax.js:1436:13)
    at exports.Parser.Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:323:31)
    at Parser.parseString (/var/polyglot/pg3/ns/00:21:b9:02:55:cd_7/node_modules/xml2js/lib/parser.js:5:59)

 

 

 

 

[johnnyt]

Hi @simplextech I've decided to leave ST-Inventory off for now after discussing my crash issues with UDI. You'll find the rationale at the post below after I got into talking about ST-Inventory with @bpwwer.

 

 

[simplextech]

On 7/19/2022 at 4:11 PM, johnnyt said:

I've decided to leave ST-Inventory off for now after discussing my crash issues with UDI. You'll find the rationale at the post below after I got into talking about ST-Inventory with @bpwwer.

Given the amount of programs and activity that could happen at any time on your poor ISY994i I understand.  I have made some updates to ST-Inventory adding a 2 second delay between each of the calls and processing to try and reduce load on the ISY994i.