PG 3.1.13 update today killed things

[macjeff]

Was running 3.1.12   30 min ago and about an hour ago I had an alarm and it shows up in logs.

I updated PG3 and rebooted it and all node servers working but this one.

It says connected (And I have restarted it) but this is all I get in the log (xxxx for passwords but they are correct and I did not change them)

and then the log stops and nothing else happens.

in ISY it says Unknown/Not in User for my partition

2022-11-03 13:58:59,302 MainThread udi_interface      INFO     polylogger:set_basic_config: set_basic_config: enable=True level=30
2022-11-03 13:59:01,932 MainThread udi_interface      INFO     __init__:<module>: UDI Python Interface for Polyglot version 3 3.0.49 Starting...
2022-11-03 13:59:01,941 MainThread udi_interface.interface INFO     interface:__init__: Initialization received from Polyglot V3 3.1.13  [ISY: 5.4.4, Slot: 2]
2022-11-03 13:59:01,943 MainThread udi_interface.interface INFO     interface:__init__: Connect: Network Interface: {'addr': '172.16.1.210', 'netmask': '255.255.255.0', 'broadcast': '172.16.1.255'}
2022-11-03 13:59:01,944 Interface  udi_interface.interface INFO     interface:_startMqtt: Connecting to MQTT... localhost:1888
2022-11-03 13:59:01,947 MainThread udi_interface.interface WARNING  interface:_get_server_data: get_server_data: failed to read file server.json: [Errno 2] No such file or directory: 'server.json'
Traceback (most recent call last):
  File "/var/polyglot/.local/lib/python3.9/site-packages/udi_interface/interface.py", line 537, in _get_server_data
    with open(Interface.SERVER_JSON_FILE_NAME) as data:
FileNotFoundError: [Errno 2] No such file or directory: 'server.json'
2022-11-03 13:59:01,952 MainThread udi_interface      INFO     evlvistans:<module>: Starting EnvisaLink-HW node server...
2022-11-03 13:59:01,954 MainThread udi_interface.interface WARNING  interface:send: MQTT Send waiting on connection :: {'config': {'version': '3.0.3'}}
2022-11-03 13:59:02,001 MQTT       udi_interface.interface INFO     interface:_connect: MQTT Connected with result code 0 (Success)
2022-11-03 13:59:02,002 MQTT       udi_interface.interface INFO     interface:_connect: MQTT Subscribing to topic: udi/pg3/ns/clients/00:0d:b9:53:2c:34_2 -  MID: 1 Result: 0
2022-11-03 13:59:02,013 MQTT       udi_interface.interface INFO     interface:_subscribe: MQTT Subscribed Succesfully for Message ID: 1 - QoS: (0,)
2022-11-03 13:59:05,146 MQTT       udi_interface.interface DEBUG    interface:_message: QUEUING incoming message getAll
2022-11-03 13:59:05,148 Command    udi_interface.interface DEBUG    interface:_parseInput: DEQUEING getAll
2022-11-03 13:59:05,150 Thread-2   udi_interface.custom DEBUG    custom:load: CUSTOM: load {'hostname': '172.16.1.211', 'password': 'xxxxx', 'usercode': 'xxxx', 'numzones': '43', 'smartzonetracking': '1'}
2022-11-03 13:59:05,151 Command    udi_interface.custom DEBUG    custom:load: CUSTOM: load {}
2022-11-03 13:59:05,152 Thread-2   udi_interface.custom DEBUG    custom:load: CUSTOM:  -- checking hostname / 172.16.1.211
2022-11-03 13:59:05,154 Command    udi_interface.interface DEBUG    interface:_handleInput: Key nsdata should be passed to node server.
2022-11-03 13:59:05,155 Thread-2   udi_interface.custom DEBUG    custom:load: CUSTOM:  -- checking password / user
2022-11-03 13:59:05,158 Command    udi_interface.interface DEBUG    interface:_handleInput: Key oauth should be passed to node server.
2022-11-03 13:59:05,159 Thread-2   udi_interface.custom DEBUG    custom:load: CUSTOM:  -- checking usercode / 1226
2022-11-03 13:59:05,165 Thread-2   udi_interface.custom DEBUG    custom:load: CUSTOM:  -- checking numzones / 43
2022-11-03 13:59:05,165 Thread-2   udi_interface.custom DEBUG    custom:load: CUSTOM:  -- checking smartzonetracking / 1
2022-11-03 13:59:05,185 MQTT       udi_interface.interface DEBUG    interface:_message: QUEUING incoming message getNsInfo
2022-11-03 13:59:05,187 Command    udi_interface.interface DEBUG    interface:_parseInput: DEQUEING getNsInfo
2022-11-03 13:59:05,206 MainThread udi_interface.interface DEBUG    interface:setCustomParamsDoc: Sending customparamsdoc to Polyglot.
2022-11-03 13:59:05,207 MainThread udi_interface.interface DEBUG    interface:send: PUBLISHING {'set': [{'key': 'customparamsdoc', 'value': '<h2>EnvisaLink Vista Node server Configuration</h2>\n\n<h3>Advanced Configuration:</h3>\n\n<ul>\n<li>key: shortPoll, value: polling interval for connection status of Envisalink and zone timers (defaults to 30 seconds)</li>\n<li>key: longPoll, value: interval for watchdog timer resets if watchdog timer is disabled (see below, defaults to 600 seconds)</li>\n</ul>\n\n<p>NOTE: The alarm panel reports zone and partition status changes immediately and other state changes are reported in keypad updates every 4 or 5 seconds, so frequent polling for state in shortpoll is not required. longpoll needs to be less than 20 minutes to prevent EnvisaLink from rebooting.</p>\n\n<h3>Custom Configuration Parameters:</h3>\n\n<h4>Required:</h4>\n\n<ul>\n<li>key: hostname, value: locally accessible hostname or IP address of EnvisaLink or DUO device (e.g., "envisalink.local" or "192.168.1.145")</li>\n<li>key: password, value: password for EnvisaLink device</li>\n<li>key: usercode, value: user code for disarming alarm panel (e.g., "5555")</li>\n</ul>\n\n<h4>Optional:</h4>\n\n<ul>\n<li>key: numpartitions, value: number of partition nodes to generate (defaults to 1)</li>\n<li>key: numzones, value: number of zone nodes to generate (defaults to 8)</li>\n<li>key: disablewatchdog, value: 0 or 1 for whether EyezOn cloud service watchdog timer should be disabled (defaults to 0 - not disabled)</li>\n<li>key: zonetimerdumpflag, value: numeric flag indicating whether dumping of the zone timers should be done on shortpoll (1), longpoll (2), or disabled altogether (0) (defaults to 1 - shortpoll)</li>\n<li>key: smartzonetracking, value: 0 or 1 for whether Node server should use a heuristic to track zone status (open, closed) or just rely on EnvisaLink\'s zone status reporting (defaults to 0 - do not track)</li>\n</ul>\n\n<p>NOTE: On Node server start, the child nodes for the Alarm Panel are created based on the numbers configured. The disablewatchdog should be enabled if the EnvisaLink is firewalled to prevent the EnvsiaLink from rebooting after 20 minutes.</p>\n'}]}
2022-11-03 13:59:05,209 MainThread udi_interface.interface INFO     interface:updateProfile: Sending Install Profile command to Polyglot.
2022-11-03 13:59:05,210 MainThread udi_interface.interface DEBUG    interface:send: PUBLISHING {'installprofile': {'reboot': False}}
2022-11-03 13:59:05,251 MQTT       udi_interface.interface INFO     interface:_message: custom data response {'customparamsdoc': '<h2>EnvisaLink Vista Node server Configuration</h2>\n\n<h3>Advanced Configuration:</h3>\n\n<ul>\n<li>key: shortPoll, value: polling interval for connection status of Envisalink and zone timers (defaults to 30 seconds)</li>\n<li>key: longPoll, value: interval for watchdog timer resets if watchdog timer is disabled (see below, defaults to 600 seconds)</li>\n</ul>\n\n<p>NOTE: The alarm panel reports zone and partition status changes immediately and other state changes are reported in keypad updates every 4 or 5 seconds, so frequent polling for state in shortpoll is not required. longpoll needs to be less than 20 minutes to prevent EnvisaLink from rebooting.</p>\n\n<h3>Custom Configuration Parameters:</h3>\n\n<h4>Required:</h4>\n\n<ul>\n<li>key: hostname, value: locally accessible hostname or IP address of EnvisaLink or DUO device (e.g., "envisalink.local" or "192.168.1.145")</li>\n<li>key: password, value: password for EnvisaLink device</li>\n<li>key: usercode, value: user code for disarming alarm panel (e.g., "5555")</li>\n</ul>\n\n<h4>Optional:</h4>\n\n<ul>\n<li>key: numpartitions, value: number of partition nodes to generate (defaults to 1)</li>\n<li>key: numzones, value: number of zone nodes to generate (defaults to 8)</li>\n<li>key: disablewatchdog, value: 0 or 1 for whether EyezOn cloud service watchdog timer should be disabled (defaults to 0 - not disabled)</li>\n<li>key: zonetimerdumpflag, value: numeric flag indicating whether dumping of the zone timers should be done on shortpoll (1), longpoll (2), or disabled altogether (0) (defaults to 1 - shortpoll)</li>\n<li>key: smartzonetracking, value: 0 or 1 for whether Node server should use a heuristic to track zone status (open, closed) or just rely on EnvisaLink\'s zone status reporting (defaults to 0 - do not track)</li>\n</ul>\n\n<p>NOTE: On Node server start, the child nodes for the Alarm Panel are created based on the numbers configured. The disablewatchdog should be enabled if the EnvisaLink is firewalled to prevent the EnvsiaLink from rebooting after 20 minutes.</p>\n'}
2022-11-03 13:59:05,271 Thread-7   udi_interface      DEBUG    classes:start: In start()...
2022-11-03 13:59:05,293 MQTT       udi_interface.interface INFO     interface:_message: Successfully set key = customparamsdoc
2022-11-03 13:59:05,706 MQTT       udi_interface.interface INFO     interface:_message: Profile installation finished

[macjeff]

update- about 15 min later the log started again.  I have no other devices connecting to it.  Not sure what happened.  Maybe its a limit on how often it checks?

[bpwwer]

That appears to be a node server issue not a PG3 issue.  

[Goose66]

2 hours ago, bpwwer said:

That appears to be a node server issue not a PG3 issue.  

What are you seeing to suggest that? Because those log entries don’t seem to point to anything to me.

Edited November 3, 2022 by Goose66

[Goose66]

@macjeffIs the node server functioning?

[macjeff]

It is now.  Just when it restarts it gives the error reading the JSON file.

Then the log stops even in debug.  About 5 min later (and my polls are 300 and 600 so maybe that has something to do with it), the log starts back up and at that point it works. 

So I guess I just have to be patient but was concerned about the error

[Goose66]

The JSON file error is OK (always been there for this node server. Hope to see a a fix in an upcoming version of PG3. 
If you can DM me a log package, I can take a look and see what’s happening.

[bpwwer]

53 minutes ago, Goose66 said:

What are you seeing to suggest that? Because those log entries don’t seem to point to anything to me.

PG3 can't do anything to make the node server pause for 5+ minutes, that would have to be in the node server code.  Given that pause is about 5 minutes and the short poll is 5 minutes, I'd guess the node server is waiting for something that happens in in the short poll handler.

[Goose66]

Right. This a product of the connection to the EnvisaLink being checked in each shortpoll and being reestablished if the connection has been lost. From the Release Notes:

Quote

2. If the connection to the EnvisaLink is lost, or if the node server doesn't hear from the EnvisaLink for 20 seconds, then the connection is reset and the node server will attempt reconnect on the next short poll and every subsequent short poll until connection is reestablished or the node server is shutdown.

The node server relies on this for the initial connection as well. So when the node server restarts, the connection to the EnvisaLink and the processing of status messages won't start until the first shortpoll. 

Edited November 4, 2022 by Goose66

[macjeff]

so this is normal behavior and no way to fix it?  I guess I can deal with it.  I dont reboot PG3 much.

[Goose66]

Yes. I do something like this in most of my node servers. The idea is that if you have power failure, waiting until the first short poll gives other devices and network components a chance to settle before attempting connection. Also makes for automatic reconnect when a connection drops for some reason without the user having to restart the node server. Like you said, restarting the node server is an exception condition. It’s design just to run undisturbed for weeks.

Edited November 4, 2022 by Goose66