Print active sid information

[jimboca]

It would be nice if the library would print out the sid conneciton in mesages on initial conneciton and re-connection. Trying to debug 5012 errors on the ISY, and it looks like PyISY is loosing the connection, and around the same time the ISY error log shows

ISY Log:

Sun 2021/06/27 07:04:01 AM System -5012 38
Sun 2021/06/27 07:09:23 AM System -5006 uuid:41
Sun 2021/06/27 07:25:51 AM System -5012 41
Sun 2021/06/27 07:30:13 AM System -5012 44
Sun 2021/06/27 08:00:07 AM System -170001 [UDSockets] Net Module Rul:44 error:6
Sun 2021/06/27 08:23:39 AM System -5012 42
Sun 2021/06/27 08:26:41 AM System -100 [DHCP] state=RENEW
Sun 2021/06/27 09:00:06 AM System -170001 [UDSockets] Net Module Rul:44 error:6
Sun 2021/06/27 10:11:20 AM System -5012 47

Nodeserver Log showing one disconnect. The only reason I could know the sid is from the warning messages:

2021-06-27 07:03:41,945 Thread-1241 pyisy.events       WARNING  events:watch: PyISY encountered while routing message '<?xml version="1.0"?><Event seqnum="37294" sid="uuid:38"><control>_1</control><action>0</action><node></node><eventInfo><id>315</id><on /><nr /><r>210627 07:03:45</r><f>210627 07:03:45</f><s>31</s></eventInfo></Event>': 'NoneType' object has no attribute 'index'
2021-06-27 07:03:42,398 Thread-1241 pyisy.events       WARNING  events:watch: PyISY encountered while routing message '<?xml version="1.0"?><Event seqnum="37296" sid="uuid:38"><control>_1</control><action>0</action><node></node><eventInfo><id>316</id><on /><nr /><r>210627 07:03:45</r><f>210627 07:03:45</f><s>31</s></eventInfo></Event>': 'NoneType' object has no attribute 'index'
2021-06-27 07:03:44,469 Thread-1241 pyisy.events       WARNING  events:_lost_connection: PyISY lost connection to the ISY event stream.
2021-06-27 07:03:44,471 Thread-8422 pyisy              WARNING  isy:_auto_reconnecter: PyISY attempting stream reconnect.
2021-06-27 07:03:44,475 Thread-8422 pyisy              WARNING  isy:_auto_reconnecter: PyISY reconnected to the event stream.
2021-06-27 07:03:45,071 Thread-8424 hueUpnp            INFO     hueUpnp:info: hueUpnp:HTTP: 192.168.86.82: Sent all lights response
2021-06-27 07:03:48,891 Thread-8423 pyisy.events       WARNING  events:watch: PyISY encountered while routing message '<?xml version="1.0"?><Event seqnum="3" sid="uuid:40"><control>_1</control><action>8</action><node></node><eventInfo>593993.820CFA</eventInfo></Event>': argument of type 'NoneType' is not iterable
2021-06-27 07:03:48,953 Thread-8423 pyisy              WARNING  __init__:node_changed_received: ISY Could not communicate with device: 1F 1B C2 1
20

[shbatm]

@jimboca are you on V2 or V3?

You should be able to print the raw messages with the SID if you enable verbose logging (Level 5):

from pyisy.constants import LOG_VERBOSE
logging.basicConfig(format=LOG_FORMAT, datefmt=LOG_DATE_FORMAT, level=LOG_VERBOSE)

[jimboca]

Thanks, I'll try that, just will make logs go crazy

HueEmulator is still on latest v2.

Reason I need this is that the ISY error logs print the Sid for connection issues and I was debugging socket errors to see who the culprit was.

[shbatm]

Verbose was added in v2, so you should be able to adjust your logger to level 5 (logging.DEBUG is 10)

[shbatm]

@jimboca - Were you able to get what you need by changing the logging level? This had been dropped below debug just to minimize noise when doing other troubleshooting. Will close this if you got what you needed.

[jimboca]

I totally forgot about this until my ISY had issues again last week and Javi looked at the code. I've been too busy since to even think of it. I will try to enable it again over the holidays.

[jimboca]

What can I look for in the log, there's a lot of logging to sort thru with full debug on :)
I'm setting it with something like this:

        logging.getLogger('pyisy').setLevel(5)

I'm now seeing these errors in the log, not sure if they were there before because I cleared all the old logs, so it could be a known issue?

2021-12-22 21:00:40,770 Thread-1   pyisy.events       WARNING  events:watch: PyISY encountered while routing message '<?xml version="1.0"?><Event seqnum="3794" sid="uuid:39"><control>_1</control><action>0</action><node></node><eventInfo><id>2EF</id><on /><nr /><r>211222 21:00:41</r><f>211222 21:00:43</f><s>21</s></eventInfo></Event>': 'NoneType' object has no attribute 'index'

[shbatm]

comment moved to #199