search

kk7ds / pynx584

Python library and server for talking to NX584/NX8E interfaces
GNU General Public License v3.0
29 stars 26 forks source link

Exception when running nx584_server #2

Closed nauticus25 closed 8 years ago

nauticus25 commented 8 years ago

Ok, I switched my configuration around and am now connecting the nx584 to a Mac Mini via the Sabrent FTDI USB to serial cable. I think I've confirmed that I'm getting data from the panel by running screen pointing to my usbserial in /dev. I'm getting 0C8804000000000000000000710AA0 printed to the screen every 3 seconds if the nx584 is in ascii mode, a weird ~q if it's in binary mode. It stops when I unplug the serial cable from the port on the nx584 but leave the cable plugged into the Mac, so I'm assuming that's not random noise from the ftdi chip in the cable. Installation of pynx584 went without error. Running nx584_server while in binary mode gives the following output:

$ nx584_server --serial /dev/tty.usbserial-A900KMXY
2016-05-08 16:07:13,016 main INFO Ready
2016-05-08 16:07:13,495 controller INFO Loaded extensions []
2016-05-08 16:07:15,215 _internal INFO  * Running on http://127.0.0.1:5007/ (Press CTRL+C to quit)
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/threading.py", line 914, in _bootstrap_inner
    self.run()
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/threading.py", line 862, in run
    self._target(*self._args, **self._kwargs)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 576, in controller_loop
    self._run_queue()
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 552, in _run_queue
    self._send(msg)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 236, in _send
    self._ser.write('\n%s\r' % make_ascii(data))
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/serial/serialposix.py", line 518, in write
    d = to_bytes(data)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/serial/serialutil.py", line 58, in to_bytes
    raise TypeError('unicode strings are not supported, please encode to bytes: %r' % (seq,))
TypeError: unicode strings are not supported, please encode to bytes: '\n073B10050810070177AF\r'

The following error is from being in ascii mode:

$ nx584_server --serial /dev/tty.usbserial-A900KMXY
2016-05-08 15:46:46,367 main INFO Ready
2016-05-08 15:46:46,412 controller INFO Loaded extensions []
2016-05-08 15:46:48,063 _internal INFO  * Running on http://127.0.0.1:5007/ (Press CTRL+C to quit)
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/threading.py", line 914, in _bootstrap_inner
    self.run()
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/threading.py", line 862, in run
    self._target(*self._args, **self._kwargs)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 572, in controller_loop
    frame = self.process_next()
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 227, in process_next
    line = parse_ascii(self._ser.readline().strip())
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 24, in parse_ascii
    data_bytes.append(int(data[i:i + 2], 16))
ValueError: invalid literal for int() with base 16: b'\x80x'

I'm not sure how to proceed with troubleshooting. I have the nx584 programmed as specified by the https://github.com/tjko/nxgipd project:

LOCATION #0: -------- (all off, binary protocol)
LOCATION #1: 4------- (9600 baud)
LOCATION #2 SEGMENT #1: -2--5-7-
LOCATION #2 SEGMENT #2: 1234----
LOCATION #3 SEGMENT #1: -2-3-45678
LOCATION #3 SEGMENT #2: 1234----
LOCATION #3 SEGMENT #3: 12------
LOCATION #3 SEGMENT #4: ---45-78

Do you see anything amiss with the programming of the nx584 board? Anything else I can try? (Sorry for the wall of text)

kk7ds commented 8 years ago

You need to be in ascii mode for my stuff to work for you, so the second traceback is what we need to look at.

Can you run with --debug and paste what you get?

nauticus25 commented 8 years ago

Here's the result:

$ nx584_server --debug --serial /dev/tty.usbserial-A900KMXY
2016-05-09 19:04:43,051 main INFO Ready
2016-05-09 19:04:43,107 controller INFO Loaded extensions []
2016-05-09 19:04:44,626 _internal INFO  * Running on http://127.0.0.1:5007/ (Press CTRL+C to quit)
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/threading.py", line 914, in _bootstrap_inner
    self.run()
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/threading.py", line 862, in run
    self._target(*self._args, **self._kwargs)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 572, in controller_loop
    frame = self.process_next()
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 227, in process_next
    line = parse_ascii(self._ser.readline().strip())
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 24, in parse_ascii
    data_bytes.append(int(data[i:i + 2], 16))
ValueError: invalid literal for int() with base 16: b'\x80x'

For fun, I ran that a few times. It would alternate between the above error and a version of the below:

$ nx584_server --debug --serial /dev/tty.usbserial-A900KMXY
2016-05-09 19:06:39,318 main INFO Ready
2016-05-09 19:06:39,369 controller INFO Loaded extensions []
2016-05-09 19:06:40,890 _internal INFO  * Running on http://127.0.0.1:5007/ (Press CTRL+C to quit)
2016-05-09 19:06:42,140 controller DEBUG Sending queued [59, 16, 5, 9, 19, 6, 2]
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/threading.py", line 914, in _bootstrap_inner
    self.run()
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/threading.py", line 862, in run
    self._target(*self._args, **self._kwargs)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 576, in controller_loop
    self._run_queue()
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 552, in _run_queue
    self._send(msg)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 236, in _send
    self._ser.write('\n%s\r' % make_ascii(data))
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/serial/serialposix.py", line 518, in write
    d = to_bytes(data)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/serial/serialutil.py", line 58, in to_bytes
    raise TypeError('unicode strings are not supported, please encode to bytes: %r' % (seq,))
TypeError: unicode strings are not supported, please encode to bytes: '\n073B1005091306027BBB\r'
\n073B100509

appears to be consistent from error to error in that last bit, while

1306027BBB\r

changes each time I run it.

kk7ds commented 8 years ago

Okay, the second one is another python3 gotcha, but one I don't hit here because I'm using a network connection instead of a serial one. The first one is because we received some garbage (and didn't handle it gracefully).

I pushed two fixes to the tree. If you want to continue using pip, you can pull/install with:

pip install -U http://github.com/kk7ds/pynx584

(that command is from memory, correct with google)

nauticus25 commented 8 years ago

Ugh. Every time I've tried to upgrade, it doesn't seem to grab the newer version from github. I just learned about -U --no-cache-dir, but that didn't seem to do the trick either. The file date of controller.py remained April something, so I changed the permissions of it, opened it in Editra and copy/pasted the new code from github. Now it runs without kicking out an exception! (small victory!) Here's the output with --debug:

$ nx584_server --debug --serial /dev/tty.usbserial-A900KMXY
2016-05-09 20:10:30,848 main INFO Ready
2016-05-09 20:10:30,903 controller INFO Loaded extensions []
2016-05-09 20:10:32,423 _internal INFO  * Running on http://127.0.0.1:5007/ (Press CTRL+C to quit)
2016-05-09 20:10:33,668 controller DEBUG Sending queued [59, 16, 5, 9, 20, 10, 2]
2016-05-09 20:10:34,937 controller DEBUG Sending queued [35, 0]
2016-05-09 20:10:36,198 controller DEBUG Sending queued [35, 1]
2016-05-09 20:10:37,465 controller DEBUG Sending queued [35, 2]
2016-05-09 20:10:38,733 controller DEBUG Sending queued [35, 3]
2016-05-09 20:10:39,996 controller DEBUG Sending queued [35, 4]
2016-05-09 20:10:41,264 controller DEBUG Sending queued [35, 5]
2016-05-09 20:10:42,531 controller DEBUG Sending queued [35, 6]
2016-05-09 20:10:43,794 controller DEBUG Sending queued [35, 7]

It stops there and waits. Running

nx584_client summary

in a second terminal results in the same

$ nx584_client summary
+------+------+--------+--------+
| Zone | Name | Bypass | Status |
+------+------+--------+--------+
+------+------+--------+--------+

as before. Looks like the nx584 isn't responding?

kk7ds commented 8 years ago

Yeah, kinda seems like not based on the fact that it didn't respond to the time set command. But, it's also not getting anything from it either, and it definitely was last time, since it was choking. Since you made the edits manually, that kinda seems problematic.

Maybe forget pip for the moment? Something like this should work:

pip uninstall nx584
git clone http://github.com/kk7ds/pynx584
cd pynx584
./nx584_server ...

For reference, this is what my successful startup looks like:

2016-05-09 16:15:40,768 main INFO Ready
2016-05-09 16:15:40,773 controller INFO Loaded extensions []
2016-05-09 16:15:40,779 controller INFO Connected
2016-05-09 16:15:40,779 controller INFO Connected
2016-05-09 16:15:40,785 _internal INFO  * Running on http://192.168.201.1:5007/
2016-05-09 16:15:43,282 controller DEBUG Sending queued [59, 16, 5, 9, 16, 15, 2]
2016-05-09 16:15:43,396 controller DEBUG Parsing raw ASCII line '011D1E1F'
2016-05-09 16:15:43,397 controller DEBUG Received: 29 Positive Acknowledge (data [])
2016-05-09 16:15:43,397 controller DEBUG Parsing raw ASCII line '0C8804000000000200000A01963CF1'
2016-05-09 16:15:43,397 controller DEBUG Received: 8 System Status (data [4, 0, 0, 0, 0, 2, 0, 0, 10, 1, 150])
2016-05-09 16:15:43,397 controller DEBUG System status received (panel id 0x04)
2016-05-09 16:15:43,397 controller INFO System asserts Voltage present interrupt active
2016-05-09 16:15:43,397 controller INFO System asserts Phone line monitor enabled
2016-05-09 16:15:43,397 controller INFO System asserts Valid partition 1
2016-05-09 16:15:43,398 controller INFO System asserts AC power on
2016-05-09 16:15:43,398 controller DEBUG Requesting partition status for 1
2016-05-09 16:15:43,498 controller DEBUG Parsing raw ASCII line '118A96B9F700000509100F01060A01525886546B'
2016-05-09 16:15:43,498 controller DEBUG Received: 10 Log Event (data [150, 185, 247, 0, 0, 5, 9, 16, 15, 1, 6, 10, 1, 82, 88, 134])
2016-05-09 16:15:43,498 controller INFO Log event: Time set at 2016-05-09 16:15:00

You show locations 1-3 above, but those aren't really related to this. What is in locations 210 and 211? Even if commands aren't enabled, it should be sending NAKs I think.

nauticus25 commented 8 years ago

I'm beginning to suspect gremlins. I ran SerialTools to see what it could see and it returned gobblygook. I unplugged/replugged the USB cable, connected again, and got 0C880400000000000000000028C057 printed every 3 seconds. Closed the connection, ran nx584_server again, and am now getting this:

$ nx584_server --debug --serial /dev/tty.usbserial-A900KMXY
2016-05-09 20:22:57,647 main INFO Ready
2016-05-09 20:22:57,704 controller INFO Loaded extensions []
2016-05-09 20:22:59,224 _internal INFO  * Running on http://127.0.0.1:5007/ (Press CTRL+C to quit)
2016-05-09 20:23:00,471 controller DEBUG Sending queued [59, 16, 5, 9, 20, 22, 2]
2016-05-09 20:23:01,092 controller DEBUG Parsing raw ASCII line b'\x80x\x00\x00\x80\xf8\x00x\x00\x80\x00\x80\x00\x80\x00\xf8\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\xf8\x00x\x00\x80x>\xff\xc0\xf8\xf8\x80x\xfc\x00'
2016-05-09 20:23:01,093 controller ERROR Failed to parse raw ASCII line b'\x80x\x00\x00\x80\xf8\x00x\x00\x80\x00\x80\x00\x80\x00\xf8\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\xf8\x00x\x00\x80x>\xff\xc0\xf8\xf8\x80x\xfc\x00'
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 229, in process_next
    line = parse_ascii(data)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 24, in parse_ascii
    data_bytes.append(int(data[i:i + 2], 16))
ValueError: invalid literal for int() with base 16: b'\x80x'
2016-05-09 20:23:01,851 controller DEBUG Sending queued [35, 0]
2016-05-09 20:23:03,111 controller DEBUG Sending queued [35, 1]
2016-05-09 20:23:03,587 controller DEBUG Parsing raw ASCII line b'\x80x\x00\x00\x80\xf8\x00x\x00\x80\x00\x80\x00\x80\x00\xf8\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\xf8\x00x\x00\x80x<\xff\x80\xf8\xf8\x80x\xfc\x00'
2016-05-09 20:23:03,588 controller ERROR Failed to parse raw ASCII line b'\x80x\x00\x00\x80\xf8\x00x\x00\x80\x00\x80\x00\x80\x00\xf8\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\xf8\x00x\x00\x80x<\xff\x80\xf8\xf8\x80x\xfc\x00'
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 229, in process_next
    line = parse_ascii(data)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 24, in parse_ascii
    data_bytes.append(int(data[i:i + 2], 16))
ValueError: invalid literal for int() with base 16: b'\x80x'
2016-05-09 20:23:04,599 controller DEBUG Sending queued [35, 2]
2016-05-09 20:23:06,081 controller DEBUG Parsing raw ASCII line b'\x80x\x00\x00\x80\xf8\x00x\x00\x80\x00\x80\x00\x80\x00\xf8\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\xf8\x00x\x00\x80x>\xff\xc0\xf8\xf8\x80x\xfe\x00'
2016-05-09 20:23:06,081 controller ERROR Failed to parse raw ASCII line b'\x80x\x00\x00\x80\xf8\x00x\x00\x80\x00\x80\x00\x80\x00\xf8\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\xf8\x00x\x00\x80x>\xff\xc0\xf8\xf8\x80x\xfe\x00'
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 229, in process_next
    line = parse_ascii(data)
  File "/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/site-packages/nx584/controller.py", line 24, in parse_ascii
    data_bytes.append(int(data[i:i + 2], 16))
ValueError: invalid literal for int() with base 16: b'\x80x'
2016-05-09 20:23:06,081 controller DEBUG Sending queued [35, 3]
2016-05-09 20:23:07,345 controller DEBUG Sending queued [35, 4]
2016-05-09 20:23:08,580 controller DEBUG Parsing raw ASCII line b'\x80x\x00\x00\x80\xf8\x00x\x00\x80\x00\x80\x00\x80\x00\xf8\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\xf8\x00x\x00\x80x\x1e\xff\xc0\xf8\xf8\x80x\xfe\x00'
2016-05-09 20:23:08,580 controller ERROR Failed to parse raw ASCII line b'\x80x\x00\x00\x80\xf8\x00x\x00\x80\x00\x80\x00\x80\x00\xf8\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x00\x80\x80\x80\x80\x00\x80\xf8\x00x\x00\x80x\x1e\xff\xc0\xf8\xf8\x80x\xfe\x00'

It keeps going, but I figure that's enough to see what's going on. I figured I'd send this update before I uninstalled via pip and do a git clone.

kk7ds commented 8 years ago

Ah, yeah, that's what I was trying to get that debug for.. You're getting binary garbage instead of clean ASCII strings.

What baud rate do you have the panel set for? You need to match that with --baud if it's not 38400. So if it's 9600 you need --baud 9600.

nauticus25 commented 8 years ago

Ha, that was it!!! nx584_client now reports zone status, though it didn't seem to pick up the names of all the zones. Somewhere in the middle of the nx584_server output I'm getting ERROR Unable to write config.ini: [Errno 13] Permission denied: 'config.ini' messages.

kk7ds commented 8 years ago

Nice.

The first time, it writes the config into the current directory by default. So, wherever you are must not be writable by your user?

Try --config ~/config.ini or something

nauticus25 commented 8 years ago

Ok, that nixed the error messages. Config.ini had max zones at 8, but I have a bit more so I upped it to the number of zones I have. The first run showed actual true/false status for each zone. Now it's just showing False for every zone. I deleted config.ini so it'd make a new one, but am getting the same result.

However, I know to quit when I'm ahead, so I'll take this as a win and will continue futzing with it later.

Thank you so much for your patience and assistance!

kk7ds commented 8 years ago

The True/False of each zone in the table is the state of the zone. Any chance when you first ran summary you had someone else in the house faulting the zone (i.e. triggering a motion detector or opening a door)? False means "not faulted" or "closed" or "no motion". So, when everything is quiet, you should have a table of all False rows.

nauticus25 commented 8 years ago

You know, I can't guarantee that my wife wasn't out of the room at that moment, so perhaps that was it.

Thanks again for your help. Next step will be to try it again on the RPi.

kk7ds commented 8 years ago

No problem, let me know if you hit anything else. I want to hear positive acknowledgement that you get this working with HA, or a(nother) reason why not yet! :)