search

SevenW / Plugwise-2-py

A version 2.0 of a plugwise python interface and controller
GNU General Public License v3.0
35 stars 25 forks source link

What's the right way to pair circles #78

Open DarkShadowNight opened 3 years ago

DarkShadowNight commented 3 years ago

Hello All,

What's the right way to pair circle(+)? I have paired existing circles in Plugwise Source software, but can't get it to work (should be enough to build the network?). Serial port okay, addresses okay... I don't know what's wrong. Did the reset method, it sure did the reset but not able to pair them this way. I repaired them in Source software afterwards and it was working again on Windows. Again not working via this code. What can I do more?

PS: Strange the firmware update did a downgrade to version 2009 somewhat unfortunately :-(

Traceback (most recent call last):
  File "Plugwise-2.py", line 1475, in <module>
    main=PWControl()
  File "Plugwise-2.py", line 132, in __init__
    self.device = Stick(port, timeout=1)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 63, in __init__
    self.init()
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 68, in init
    self.status()
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 315, in status
    _, seqnr  = self.send_msg(req.serialize())
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 94, in send_msg
    resp = self.expect_response(PlugwiseAckResponse)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 188, in expect_response
    msg = self._recv_response(retry_timeout)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 143, in _recv_response
    raise TimeoutException("Timeout while waiting for response from device")
plugwise.exceptions.TimeoutException: Timeout while waiting for response from device
SevenW commented 3 years ago

Hi DSN,

Pairing works automatically, when the new circle is added in the configuration files. The only condition is that the circle is reset properly. It pairs within a few minutes of restarting Plugwise-2-py or periodically, I think every our the code requests unknown circles to announce themselves.

In short, I don't think pairing is the problem if circles have been paired before. What can be a problem is the downgrade to 2009 firmware. Please try to fix this in Source.

From the stacktrace I see the Stick is getting initialized. A command is send to the Stick and then no response is received. So there might be something wrong with the Stick or its USB-port configuration. If this Stack trace started occurring after the firmware downgrade, then it might be related to this.

Can you send me a full logfile of a startup and also the comm logfile?

SevenW

DarkShadowNight commented 3 years ago

Hello,

It was before firmware downgrade also, can't upgrade anymore (upgrade server down?), fallback to "offline" firmware from setup? Works in Source software with stick.

Comm log:

2021-03-22 20:19:45,521 - pwcomm - logging started
2021-03-22 20:19:45,648 - pwcomm - SEND   14 ---> 000A                             B43C <---
2021-03-22 20:19:49,697 - pwcomm - TOUT   83 ^E^E^C^C0000000600C19939
^E^E^C^C00110006000D6F000075ACAE01015A0D6F0001A5A3AF605AFFF424
� - <!> Timeout on serial port

pw log:

2021-03-13 16:24:51,851 - pw-logger - INFO - MQTT Subscribed: 1 (0,)
2021-03-22 20:19:45,607 - pw-logger - INFO - logging started
2021-03-22 20:19:45,615 - pw-logger - INFO - MQTT client initializing for 127.0.0.1:1883
2021-03-22 20:19:45,627 - pw-logger - INFO - MQTT connected return code 0
2021-03-22 20:19:45,628 - pw-logger - DEBUG - MQTT init done
2021-03-22 20:19:45,631 - pw-logger - INFO - MQTT subscribed to plugwise2py/cmd/# with qos 0
2021-03-22 20:19:45,636 - pw-logger - INFO - MQTT thread started
2021-03-22 20:19:45,638 - pw-logger - INFO - MQTT connected return code 0
2021-03-22 20:19:45,650 - pw-logger - DEBUG - SEND   14 ^E^E^C^C000AB43C

2021-03-22 20:19:45,742 - pw-logger - INFO - MQTT Subscribed: 1 (0,)

Issue with multiple USB <> RS232 converters (yes I selected the right port)?

SevenW commented 3 years ago

Really strange. The initial communication sequence should look like this:

2021-03-23 22:12:02,417 - pwcomm - logging started
2021-03-23 22:12:02,434 - pwcomm - SEND   14 ---> 000A                             B43C <---
2021-03-23 22:12:02,459 - pwcomm - RECV   22 ---> 0000 3D56 00C1 ................  57EA <---
2021-03-23 22:12:02,461 - pwcomm - RECV   60 ---> 0011 3D56 .... 000D6F00019E0E85 0101EB0D6F0001A59F7DCDEBFF 8BF3 <---
2021-03-23 22:12:02,463 - pwcomm - SEND   30 ---> 0023           000D6F0001A59F7D  460F <---
2021-03-23 22:12:02,495 - pwcomm - RECV   22 -->> 0000 3D57 00C1 ................  FDBB <---

In your case the start of the timeout logging contains the right response, but it is preceded by ^E^E^C^C. The following data is actually the correct response from the Stick:

0000 0006 00C1 9939

meaning Acknowledge the reception of a command (OK).

So now the question is: Where does come from? In the low level communication protocol there is this header defined: PACKET_HEADER = b'\x05\x05\x03\x03' Another representation for 0x05 is Ctrl-E or ^E, and 0x03 is ^C. So Plugwise-2-py is receiving the expected header, but not in the expected form of a single byte 0x05, but in the form of two bytes '^' and 'E'.

I believe that the serial driver already interpreted the control character and converted it to printable characters. This might be due to some configuration setting of the/dev/ttyUSBx stream in Linux, or of the python Serial module.

I do not know the solution right now, but we have pin-pointed the issue at least. Maybe you can google a bit on the translation of control characters to printable characters?

SevenW

P.S. It is still a possibility that the Stick is transmitting '^','E' due to firmware version where '0x05' is expected. PPS. Can it be related to python3 bytes <-> string conversions? Maybe in combination with a charset?

SevenW commented 3 years ago

The above might not be right. The question is why is a timeout reported. The timeout is generated because the last received character of the message is not one of two expected characters.: https://github.com/SevenW/Plugwise-2-py/blob/a25d48dcb5c2cc625b2237bd23f1de2e3a08c960/plugwise/api.py#L136 So maybe adding some additional debug code will help identifying the root cause.

Add below above reference line 136 and lets see what gets logged in pw-logger.log:

                info("Debug Timeout %s" % msg[-2])
                info("Debug Timeout %s" % msg[-1])

SevenW

DarkShadowNight commented 3 years ago 
2021-03-22 20:19:45,742 - pw-logger - INFO - MQTT Subscribed: 1 (0,)
2021-03-24 19:34:00,462 - pw-logger - INFO - logging started
2021-03-24 19:34:00,470 - pw-logger - INFO - MQTT client initializing for 127.0.0.1:1883
2021-03-24 19:34:00,479 - pw-logger - INFO - MQTT connected return code 0
2021-03-24 19:34:00,480 - pw-logger - DEBUG - MQTT init done
2021-03-24 19:34:00,482 - pw-logger - INFO - MQTT subscribed to plugwise2py/cmd/# with qos 0
2021-03-24 19:34:00,485 - pw-logger - INFO - MQTT thread started
2021-03-24 19:34:00,488 - pw-logger - INFO - MQTT connected return code 0
2021-03-24 19:34:00,495 - pw-logger - DEBUG - SEND   14 ^E^E^C^C000AB43C

2021-03-24 19:34:00,524 - pw-logger - INFO - Debug Timeout
2021-03-24 19:34:00,525 - pw-logger - INFO - Debug Timeout

2021-03-24 19:34:00,535 - pw-logger - INFO - Debug Timeout
2021-03-24 19:34:00,536 - pw-logger - INFO - Debug Timeout

2021-03-24 19:34:00,590 - pw-logger - INFO - MQTT Subscribed: 1 (0,)
2021-03-24 19:34:01,538 - pw-logger - INFO - Debug Timeout

2021-03-24 19:34:01,540 - pw-logger - INFO - Debug Timeout �
2021-03-24 19:34:02,543 - pw-logger - INFO - Debug Timeout

2021-03-24 19:34:02,544 - pw-logger - INFO - Debug Timeout �
2021-03-24 19:34:03,547 - pw-logger - INFO - Debug Timeout

2021-03-24 19:34:03,548 - pw-logger - INFO - Debug Timeout �
2021-03-24 19:34:04,550 - pw-logger - INFO - Debug Timeout

2021-03-24 19:34:04,552 - pw-logger - INFO - Debug Timeout �
DarkShadowNight commented 3 years ago

any news?

SevenW commented 3 years ago

Do not have a full understanding yet. I assume you are the latest version of Plugwise-2-py. Correct? What is your version of python and what method did you use to install?

SevenW commented 3 years ago

Could you try the following additional line in stead of the two earlier lines?

                info("{:02x} {:02x}".format(msg[-2],msg[-1]))

Previous attempt was not clear enough.

DarkShadowNight commented 3 years ago

I added because there was an error in your code: info(":".join("{:02x}".format(ord(c)) for c in msg))

Result:

2021-04-05 08:09:53,581 - pw-logger - INFO - logging started
2021-04-05 08:09:53,585 - pw-logger - INFO - MQTT client initializing for 127.0.0.1:1883
2021-04-05 08:09:53,597 - pw-logger - INFO - MQTT connected return code 0
2021-04-05 08:09:53,599 - pw-logger - DEBUG - MQTT init done
2021-04-05 08:09:53,602 - pw-logger - INFO - MQTT subscribed to plugwise2py/cmd/# with qos 0
2021-04-05 08:09:53,606 - pw-logger - INFO - MQTT thread started
2021-04-05 08:09:53,608 - pw-logger - INFO - MQTT connected return code 0
2021-04-05 08:09:53,620 - pw-logger - DEBUG - SEND   14 000AB43C

2021-04-05 08:09:53,652 - pw-logger - INFO - 05:05:03:03:30:30:30:30:30:30:30:43:30:30:43:31:41:37:45:38:0d:0a
2021-04-05 08:09:53,666 - pw-logger - INFO - 05:05:03:03:30:30:30:30:30:30:30:43:30:30:43:31:41:37:45:38:0d:0a:05:05:03:03:30:30:31:31:30:30:30:43:30:30:30:44:36:46:30:30:30:30:37:35:41:43:41:45:30:31:30:31:35:41:30:44:36:46:30:30:30:31:41:35:41:33:41:46:36:30:35:41:46:46:37:44:44:37:0d:0a
2021-04-05 08:09:53,713 - pw-logger - INFO - MQTT Subscribed: 1 (0,)
2021-04-05 08:09:54,671 - pw-logger - INFO - 05:05:03:03:30:30:30:30:30:30:30:43:30:30:43:31:41:37:45:38:0d:0a:05:05:03:03:30:30:31:31:30:30:30:43:30:30:30:44:36:46:30:30:30:30:37:35:41:43:41:45:30:31:30:31:35:41:30:44:36:46:30:30:30:31:41:35:41:33:41:46:36:30:35:41:46:46:37:44:44:37:0d:0a:83
2021-04-05 08:09:55,676 - pw-logger - INFO - 05:05:03:03:30:30:30:30:30:30:30:43:30:30:43:31:41:37:45:38:0d:0a:05:05:03:03:30:30:31:31:30:30:30:43:30:30:30:44:36:46:30:30:30:30:37:35:41:43:41:45:30:31:30:31:35:41:30:44:36:46:30:30:30:31:41:35:41:33:41:46:36:30:35:41:46:46:37:44:44:37:0d:0a:83
2021-04-05 08:09:56,680 - pw-logger - INFO - 05:05:03:03:30:30:30:30:30:30:30:43:30:30:43:31:41:37:45:38:0d:0a:05:05:03:03:30:30:31:31:30:30:30:43:30:30:30:44:36:46:30:30:30:30:37:35:41:43:41:45:30:31:30:31:35:41:30:44:36:46:30:30:30:31:41:35:41:33:41:46:36:30:35:41:46:46:37:44:44:37:0d:0a:83
2021-04-05 08:09:57,685 - pw-logger - INFO - 05:05:03:03:30:30:30:30:30:30:30:43:30:30:43:31:41:37:45:38:0d:0a:05:05:03:03:30:30:31:31:30:30:30:43:30:30:30:44:36:46:30:30:30:30:37:35:41:43:41:45:30:31:30:31:35:41:30:44:36:46:30:30:30:31:41:35:41:33:41:46:36:30:35:41:46:46:37:44:44:37:0d:0a:83

I'm running the latest version, just dit a git clone. Running version 2.7.16

SevenW commented 3 years ago

Nice logging. The message format looks good. No issues here.

You are using python 2.7. The latest version is a port to python 3. It runs on at least 3.8 and 3.9. Could you try installing it using python 3?

When you installed it like you did because the instructions are unclear, please let me know where I can improve.

SevenW

DarkShadowNight commented 3 years ago

python3 Plugwise-2.py (version 3.7.3) Traceback (most recent call last): Python3: 

File "Plugwise-2.py", line 31, in <module>
    from swutil.pwmqtt import *
  File "/home/pi/scripts/Plugwise-2-py/swutil/pwmqtt.py", line 24, in <module>
    import paho.mqtt.client as mosquitto
ModuleNotFoundError: No module named 'paho'

I followed your instructions how to install.

SevenW commented 3 years ago

at the command line enter this: pip install paho-mqtt

This should install the dependendcy.

DarkShadowNight commented 3 years ago

pip3 install paho-mqtt already done. The strange thing is, I get the same response without the Circle(s) plugged in.

Okay, with Python3 plugs in: True rsync -aXuq /home/pi/datalog/2021/pwact/pwact-2021-04-06.log /tmp/2021/pwact/ rsync: link_stat "/home/pi/datalog/2021/pwact/pwact-2021-04-06.log" failed: No such file or directory (2) rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1207) [sender=3.1.3] b'\x05\x05\x03\x030000001100C1BB4D\r\n' b'\x05\x05\x03\x0300110011000D6F000075ACAE01015A0D6F0001A5A3AF605AFFB65F\r\n' Traceback (most recent call last): File "Plugwise-2.py", line 1475, in main=PWControl() File "Plugwise-2.py", line 164, in init sconf = json.load(open(self.staticconfig_fn)) File "/usr/lib/python3.7/json/init.py", line 296, in load parse_constant=parse_constant, object_pairs_hook=object_pairs_hook, **kw) File "/usr/lib/python3.7/json/init.py", line 348, in loads return _default_decoder.decode(s) File "/usr/lib/python3.7/json/decoder.py", line 337, in decode obj, end = self.raw_decode(s, idx=_w(s, 0).end()) File "/usr/lib/python3.7/json/decoder.py", line 355, in raw_decode raise JSONDecodeError("Expecting value", s, err.value) from None json.decoder.JSONDecodeError: Expecting value: line 4 column 1 (char 321)

Without plugs: True rsync -aXuq /home/pi/datalog/2021/pwact/pwact-2021-04-06.log /tmp/2021/pwact/ rsync: link_stat "/home/pi/datalog/2021/pwact/pwact-2021-04-06.log" failed: No such file or directory (2) rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1207) [sender=3.1.3] b'\x05\x05\x03\x030000001200C1559F\r\n' b'\x05\x05\x03\x0300110012000D6F000075ACAE01015A0D6F0001A5A3AF605AFF09C1\r\n' Traceback (most recent call last): File "Plugwise-2.py", line 1475, in main=PWControl() File "Plugwise-2.py", line 164, in init sconf = json.load(open(self.staticconfig_fn)) File "/usr/lib/python3.7/json/init.py", line 296, in load parse_constant=parse_constant, object_pairs_hook=object_pairs_hook, **kw) File "/usr/lib/python3.7/json/init.py", line 348, in loads return _default_decoder.decode(s) File "/usr/lib/python3.7/json/decoder.py", line 337, in decode obj, end = self.raw_decode(s, idx=_w(s, 0).end()) File "/usr/lib/python3.7/json/decoder.py", line 355, in raw_decode raise JSONDecodeError("Expecting value", s, err.value) from None json.decoder.JSONDecodeError: Expecting value: line 4 column 1 (char 321)

SevenW commented 3 years ago

I think we are making progress. The new error is probably a syntax error in one of the configuration json files: pw-conf.json I expect. But check the others as well.

This note is in the instructions. Use the link to check your config file for syntax issues.

Note: Editing JSON files is error-prone. Use a JSON Validator such as http://jsonlint.com/ to check the config files.

SevenW

SevenW commented 3 years ago

BTW thanks for observing the pip3. I was unsure about this. I will adapt the instructions.

DarkShadowNight commented 3 years ago

Yes it was, a semicolon at the end:

python3 Plugwise-2.py
True
rsync -aXuq /home/pi/datalog/2021/pwact/pwact-2021-04-07*.log /tmp/2021/pwact/
rsync: link_stat "/home/pi/datalog/2021/pwact/pwact-2021-04-07*.log" failed: No such file or directory (2)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1207) [sender=3.1.3]
b'\x05\x05\x03\x030000001300C1FFCE\r\n'
b'\x05\x05\x03\x0300110013000D6F000075ACAE01015A0D6F0001A5A3AF605AFF634B\r\n'
b'\x83\x05\x05\x03\x030000001400C1981A\r\n'
b'PutFifoUnicast 40 : Handle 20 : 000D6F0001A5A3AF\r\n'
Traceback (most recent call last):
  File "Plugwise-2.py", line 1475, in <module>
    main=PWControl()
  File "Plugwise-2.py", line 178, in __init__
    self.circles.append(Circle(item['mac'], self.device, item))
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 414, in __init__
    self.reinit()
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 427, in reinit
    info = self.get_info()
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 689, in get_info
    resp = self._expect_response(PlugwiseInfoResponse, seqnr)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 516, in _expect_response
    resp = self._comchan.expect_response(response_class, self._mac(), seqnr, retry_timeout)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 194, in expect_response
    resp.unserialize(msg)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/protocol.py", line 307, in unserialize
    debug("STRU      "+header+" "+logf(self.function_code)+" "+logf(self.command_counter)+" <data> "+logf(crc)+" "+footer)
TypeError: can only concatenate str (not "bytes") to str
python Plugwise-2.py
True
rsync -aXuq /home/pi/datalog/2021/pwact/pwact-2021-04-07*.log /tmp/2021/pwact/
rsync: link_stat "/home/pi/datalog/2021/pwact/pwact-2021-04-07*.log" failed: No such file or directory (2)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1207) [sender=3.1.3]
0000001500C1324B

0000001500C1324B
00110015000D6F000075ACAE01015A0D6F0001A5A3AF605AFF0C56

0000001500C1324B
00110015000D6F000075ACAE01015A0D6F0001A5A3AF605AFF0C56
�
0000001500C1324B
00110015000D6F000075ACAE01015A0D6F0001A5A3AF605AFF0C56
�
0000001500C1324B
00110015000D6F000075ACAE01015A0D6F0001A5A3AF605AFF0C56
�
0000001500C1324B
00110015000D6F000075ACAE01015A0D6F0001A5A3AF605AFF0C56
�
Traceback (most recent call last):
  File "Plugwise-2.py", line 1475, in <module>
    main=PWControl()
  File "Plugwise-2.py", line 132, in __init__
    self.device = Stick(port, timeout=1)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 63, in __init__
    self.init()
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 68, in init
    self.status()
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 320, in status
    _, seqnr  = self.send_msg(req.serialize())
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 94, in send_msg
    resp = self.expect_response(PlugwiseAckResponse)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 193, in expect_response
    msg = self._recv_response(retry_timeout)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 148, in _recv_response
    raise TimeoutException("Timeout while waiting for response from device")
plugwise.exceptions.TimeoutException: Timeout while waiting for response from device
SevenW commented 3 years ago

Is the first dump with python3 and the second with python 2?

DarkShadowNight commented 3 years ago

Yes, see first rule

SevenW commented 3 years ago

Please change line 307 of protocol.py from:

        debug("STRU      "+header+" "+logf(self.function_code)+" "+logf(self.command_counter)+" <data> "+logf(crc)+" "+footer)

into

        debug("STRU      "+logf(header)+" "+logf(self.function_code)+" "+logf(self.command_counter)+" <data> "+logf(crc)+" "+logf(footer))
DarkShadowNight commented 3 years ago

First try python, second try python3:

2021-04-09 16:32:11,338 - pwcomm - logging started
2021-04-09 16:32:11,478 - pwcomm - SEND   14 ---> 000A                             B43C <---
2021-04-09 16:32:15,516 - pwcomm - TOUT   83 ^E^E^C^C0000001700C176C8
^E^E^C^C00110017000D6F000075ACAE01015A0D6F0001A5A3AF605AFFD942
� - <!> Timeout on serial port
2021-04-09 16:34:54,808 - pwcomm - logging started
2021-04-09 16:34:54,901 - pwcomm - SEND   14 ---> 000A                             B43C <---
2021-04-09 16:34:54,919 - pwcomm - RECV   22 ---> 0000 0018 00C1 ................  1331 <---
2021-04-09 16:34:54,937 - pwcomm - RECV   60 ---> 0011 0018 .... 000D6F000075ACAE 01015A0D6F0001A5A3AF605AFF B8E6 <---
2021-04-09 16:34:54,953 - pwcomm - SEND   30 ---> 0023           000D6F0001A5A3AF  30FC <---
2021-04-09 16:34:54,990 - pwcomm - RECV   22 -->> 0000 0019 00C1 ................  B960 <---
2021-04-09 16:34:55,011 - pwcomm - RERR   50 PutFifoUnicast 40 : Handle 25 : 000D6F0001A5A3AF\r\n - <!> protocol error: checksum error!
2021-04-09 16:34:55,284 - pwcomm - RECV   22 -->> 0000 0019 00E1 ................  13C6 <---
2021-04-09 16:34:55,293 - pwcomm - SEND   30 ---> 0023           000D6F000099687C  5A9B <---
2021-04-09 16:34:55,300 - pwcomm - DSHR   21  ClusterId 40  Fail\r\n
2021-04-09 16:34:55,322 - pwcomm - RECV   22 ---> 0000 001A 00C1 ................  A6CB <---
2021-04-09 16:34:55,340 - pwcomm - RERR   50 PutFifoUnicast 40 : Handle 26 : 000D6F000099687C\r\n - <!> protocol error: checksum error!
2021-04-09 16:34:55,438 - pwcomm - RERR   26 \\x83\\x97116 : 000D6F0001A5A3AF\r\n - <!> protocol error: checksum error!
2021-04-09 16:34:56,420 - pwcomm - RERR   61 emberMessageSentHandler()  ** ClusterId 116 **  Status 0 **\r\n - <!> protocol error: checksum error!
2021-04-09 16:34:59,455 - pwcomm - RERR   22 \x05\x05\x03\x030000001900E113C6\r\n - <!> out of sequence: 'expected seqnr 001A, received seqnr 0019 - this may be a duplicate message'
2021-04-09 16:35:00,029 - pwcomm - RECV   22 ---> 0000 001A 00E1 ................  0C6D <---
SevenW commented 3 years ago

Hi DSN,

Forget about python 2.7. It now only runs under python 3.x.

I see no further crash in the python 3 COMM logfile. There is a lot of clutter due to textual debug messages out of the circle-network itself. Those messages I have never encountered before and may be specific for your firmware version.

I mean logging like PutFifoUnicast 40 : Handle 25 : 000D6F0001A5A3AF\r\n

Is it working well? Otherwise send me the pw-logger.log file as well.

SevenW

DarkShadowNight commented 3 years ago

It's working! There was still an JSON error in schedule config file.

Strange is following: Original line 307 you asked to replace me in protocol.py is not working. Need to comment out or use replaced line.

Can't control it however, power and energy also doesn't change. Will try to wait.

Thanks!

python3 Plugwise-2.py
True
rsync -aXuq /home/pi/datalog/2021/pwact/pwact-2021-04-12*.log /tmp/2021/pwact/
rsync: link_stat "/home/pi/datalog/2021/pwact/pwact-2021-04-12*.log" failed: No such file or directory (2)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1207) [sender=3.1.3]
Traceback (most recent call last):
  File "Plugwise-2.py", line 1475, in <module>
    main=PWControl()
  File "Plugwise-2.py", line 178, in __init__
    self.circles.append(Circle(item['mac'], self.device, item))
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 409, in __init__
    self.reinit()
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 422, in reinit
    info = self.get_info()
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 684, in get_info
    resp = self._expect_response(PlugwiseInfoResponse, seqnr)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 511, in _expect_response
    resp = self._comchan.expect_response(response_class, self._mac(), seqnr, retry_timeout)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/api.py", line 189, in expect_response
    resp.unserialize(msg)
  File "/home/pi/scripts/Plugwise-2-py/plugwise/protocol.py", line 307, in unserialize
    debug("STRU      "+header+" "+logf(self.function_code)+" "+logf(self.command_counter)+" <data> "+logf(crc)+" "+footer)
TypeError: can only concatenate str (not "bytes") to str
SevenW commented 3 years ago

On the first real run it starts reading out all the historic data logged in te circles. This can takes hours, depending on the number of circles you have. During this initial logging to disk of the history the system is pretty inresponsive. This will cure and when it only has to follow the newly made readings the responsiveness is much better. However for switching circles on/off it may take 10 seconds. The code is mostly sequential and the polling loop is entered every ten seconds.

Let me know how it works out for you. How are you using it? Controlling lights or logging energy?

DarkShadowNight commented 3 years ago

This repeats in the logfile:

Want to do both once if MQTT is running. If injection in the grid greather then consumption of the plug, then switch on the plug. If injection is 0, then switch of the plug.

2021-04-14 19:27:50,353 - pw-logger - ERROR - protocol error [1]:checksum error!
2021-04-14 19:27:50,354 - pw-logger - ERROR - TEST: ifoU - going to retry receive msg
2021-04-14 19:27:50,404 - pw-logger - ERROR - protocol error [1]:checksum error!
2021-04-14 19:27:50,406 - pw-logger - ERROR - TEST: erMe - going to retry receive msg
2021-04-14 19:27:50,413 - pw-logger - ERROR - protocol error [1]:checksum error!
2021-04-14 19:27:50,415 - pw-logger - ERROR - TEST: : 00 - going to retry receive msg
sjoerdos92 commented 2 years ago

I have some difficulty pairing Circle+'s. Can someone help? I believe one Circle+ was once connected to the stick, the other one I tried to reset. My logs are:

2022-08-18 12:48:58,626 - pw-logger - INFO - logging started
2022-08-18 12:48:58,626 - pw-logger - INFO - MQTT client initializing for 192.168.8.226:1883
2022-08-18 12:48:58,628 - pw-logger - INFO - MQTT connected return code 0
2022-08-18 12:48:58,628 - pw-logger - DEBUG - MQTT init done
2022-08-18 12:48:58,628 - pw-logger - INFO - MQTT subscribed to plugwise2py/cmd/# with qos 0
2022-08-18 12:48:58,628 - pw-logger - INFO - MQTT thread started
2022-08-18 12:48:58,628 - pw-logger - INFO - MQTT connected return code 0
2022-08-18 12:48:58,629 - pw-logger - DEBUG - SEND   14 \x05\x05\x03\x03000AB43C\r\n
2022-08-18 12:48:58,653 - pw-logger - DEBUG - RECV   22 \x05\x05\x03\x030000028700C15EC9\r\n
2022-08-18 12:48:58,653 - pw-logger - DEBUG - STRU      ---> 0000 0287 <data> 5EC9 <---
2022-08-18 12:48:58,653 - pw-logger - DEBUG - DATA    4 00C1
2022-08-18 12:48:58,653 - pw-logger - DEBUG - PARS      00C1
2022-08-18 12:48:58,653 - pw-logger - DEBUG - PARS      00C1 EVAL 193
2022-08-18 12:48:58,653 - pw-logger - DEBUG - RECV   60 \x05\x05\x03\x0300110287000D6F0000598E340101CA0D6F0000598A138DCAFF5E30\r\n
2022-08-18 12:48:58,653 - pw-logger - DEBUG - STRU      ---> 0011 0287 <data> 5E30 <---
2022-08-18 12:48:58,653 - pw-logger - DEBUG - DATA   26 0101CA0D6F0000598A138DCAFF
2022-08-18 12:48:58,653 - pw-logger - DEBUG - PARS      01
2022-08-18 12:48:58,653 - pw-logger - DEBUG - PARS      01 EVAL 1
2022-08-18 12:48:58,653 - pw-logger - DEBUG - PARS      01
2022-08-18 12:48:58,654 - pw-logger - DEBUG - PARS      01 EVAL 1
2022-08-18 12:48:58,654 - pw-logger - DEBUG - PARS      CA0D6F0000598A13
2022-08-18 12:48:58,654 - pw-logger - DEBUG - PARS      CA0D6F0000598A13 EVAL 14559415216155232787
2022-08-18 12:48:58,654 - pw-logger - DEBUG - PARS      8DCA
2022-08-18 12:48:58,654 - pw-logger - DEBUG - PARS      8DCA EVAL 36298
2022-08-18 12:48:58,654 - pw-logger - DEBUG - PARS      FF
2022-08-18 12:48:58,654 - pw-logger - DEBUG - PARS      FF EVAL 255
2022-08-18 12:48:58,654 - pw-logger - DEBUG - <plugwise.protocol.PlugwiseStatusResponse object at 0x7f26541a4f40>
2022-08-18 12:48:58,654 - pw-logger - DEBUG - SEND   30 \x05\x05\x03\x030023000D6F000072991D0F58\r\n
2022-08-18 12:48:58,685 - pw-logger - DEBUG - RECV   23 \\x83\x05\x05\x03\x030000028800C13B30\r\n
2022-08-18 12:48:58,685 - pw-logger - DEBUG - STRU      -->> 0000 0288 <data> 3B30 <---
2022-08-18 12:48:58,685 - pw-logger - DEBUG - DATA    4 00C1
2022-08-18 12:48:58,685 - pw-logger - DEBUG - PARS      00C1
2022-08-18 12:48:58,685 - pw-logger - DEBUG - PARS      00C1 EVAL 193
2022-08-18 12:48:58,729 - pw-logger - INFO - MQTT Subscribed: 1 (0,)
2022-08-18 12:49:00,252 - pw-logger - DEBUG - RECV   22 \x05\x05\x03\x030000028800E19196\r\n
2022-08-18 12:49:00,252 - pw-logger - DEBUG - STRU      ---> 0000 0288 <data> 9196 <---
2022-08-18 12:49:00,252 - pw-logger - DEBUG - DATA    4 00E1
2022-08-18 12:49:00,253 - pw-logger - ERROR - unexpected response [1]:'expected response code 0024, received code 0000'
2022-08-18 12:49:00,253 - pw-logger - DEBUG - STRU      ---> 0000 0288 <data> 9196 <---
2022-08-18 12:49:00,253 - pw-logger - DEBUG - DATA    4 00E1
2022-08-18 12:49:00,253 - pw-logger - DEBUG - PARS      00E1
2022-08-18 12:49:00,253 - pw-logger - DEBUG - PARS      00E1 EVAL 225
2022-08-18 12:49:00,253 - pw-logger - DEBUG - Received an error status '00E1' from circle 'circle+1' - Network slow or circle offline - Retry receive ...
2022-08-18 12:49:00,253 - pw-logger - ERROR - OFFLINE Circle 'circle+1' during initialization Error: Timeout while waiting for response from circle 'circle+1'
2022-08-18 12:49:00,254 - pw-logger - INFO - adding circle: circle+1
2022-08-18 12:49:00,254 - pw-logger - DEBUG - SEND   30 \x05\x05\x03\x030023000D6F00005988BE6448\r\n
2022-08-18 12:49:00,284 - pw-logger - DEBUG - RECV   22 \x05\x05\x03\x030000028900C19161\r\n
2022-08-18 12:49:00,285 - pw-logger - DEBUG - STRU      ---> 0000 0289 <data> 9161 <---
2022-08-18 12:49:00,285 - pw-logger - DEBUG - DATA    4 00C1
2022-08-18 12:49:00,285 - pw-logger - DEBUG - PARS      00C1
2022-08-18 12:49:00,285 - pw-logger - DEBUG - PARS      00C1 EVAL 193
2022-08-18 12:49:01,852 - pw-logger - DEBUG - RECV   22 \x05\x05\x03\x030000028900E13BC7\r\n
2022-08-18 12:49:01,852 - pw-logger - DEBUG - STRU      ---> 0000 0289 <data> 3BC7 <---
2022-08-18 12:49:01,852 - pw-logger - DEBUG - DATA    4 00E1
2022-08-18 12:49:01,852 - pw-logger - ERROR - unexpected response [1]:'expected response code 0024, received code 0000'
2022-08-18 12:49:01,852 - pw-logger - DEBUG - STRU      ---> 0000 0289 <data> 3BC7 <---
2022-08-18 12:49:01,853 - pw-logger - DEBUG - DATA    4 00E1
2022-08-18 12:49:01,853 - pw-logger - DEBUG - PARS      00E1
2022-08-18 12:49:01,853 - pw-logger - DEBUG - PARS      00E1 EVAL 225
2022-08-18 12:49:01,853 - pw-logger - DEBUG - Received an error status '00E1' from circle 'circle+2' - Network slow or circle offline - Retry receive ...
2022-08-18 12:49:01,853 - pw-logger - ERROR - OFFLINE Circle 'circle+2' during initialization Error: Timeout while waiting for response from circle 'circle+2'
2022-08-18 12:49:01,853 - pw-logger - INFO - adding circle: circle+2
2022-08-18 12:49:01,854 - pw-logger - DEBUG - read_schedules
2022-08-18 12:49:01,854 - pw-logger - INFO - generate schedule: __PW2PY__test-alternate
2022-08-18 12:49:01,854 - pw-logger - INFO - generate schedule: __PW2PY__test-10
2022-08-18 12:49:01,854 - pw-logger - INFO - import   schedule: carcharging.json
2022-08-18 12:49:01,854 - pw-logger - INFO - import   schedule: testsched2.json
2022-08-18 12:49:01,854 - pw-logger - INFO - import   schedule: winter.json
2022-08-18 12:49:01,855 - pw-logger - INFO - import   schedule: testsched1.json
2022-08-18 12:49:01,855 - pw-logger - DEBUG - poll_configuration()
2022-08-18 12:49:01,855 - pw-logger - DEBUG - read_apply_controls
2022-08-18 12:49:03,453 - pw-logger - ERROR - unexpected response [1]:'expected response code 0024, received code 0000'
2022-08-18 12:49:05,052 - pw-logger - ERROR - unexpected response [1]:'expected response code 0024, received code 0000'
2022-08-18 12:49:12,076 - pw-logger - ERROR - PWControl.run(): Communication error in enable_joining
2022-08-18 12:48:58,624 - pwcomm - logging started
2022-08-18 12:48:58,629 - pwcomm - SEND   14 ---> 000A                             B43C <---
2022-08-18 12:48:58,653 - pwcomm - RECV   22 ---> 0000 0287 00C1 ................  5EC9 <---
2022-08-18 12:48:58,653 - pwcomm - RECV   60 ---> 0011 0287 .... 000D6F0000598E34 0101CA0D6F0000598A138DCAFF 5E30 <---
2022-08-18 12:48:58,654 - pwcomm - SEND   30 ---> 0023           000D6F000072991D  0F58 <---
2022-08-18 12:48:58,685 - pwcomm - RECV   22 -->> 0000 0288 00C1 ................  3B30 <---
2022-08-18 12:48:58,686 - pwcomm - DTRC   91 # APSRequestNodeInfo: Source MAC: 000D6F0000598E34# APSRequestNodeInfo: Destination MAC: \r\n
2022-08-18 12:48:58,686 - pwcomm - DSHR   18 000D6F000072991D\r\n
2022-08-18 12:48:59,687 - pwcomm - DSHR    1 \\x83
2022-08-18 12:49:00,253 - pwcomm - RECV   22 ---> 0000 0288 00E1 ................  9196 <---
2022-08-18 12:49:00,254 - pwcomm - SEND   30 ---> 0023           000D6F00005988BE  6448 <---
2022-08-18 12:49:00,285 - pwcomm - RECV   22 ---> 0000 0289 00C1 ................  9161 <---
2022-08-18 12:49:00,286 - pwcomm - DTRC   91 # APSRequestNodeInfo: Source MAC: 000D6F0000598E34# APSRequestNodeInfo: Destination MAC: \r\n
2022-08-18 12:49:00,286 - pwcomm - DSHR   18 000D6F00005988BE\r\n
2022-08-18 12:49:01,287 - pwcomm - DSHR    1 \\x83
2022-08-18 12:49:01,853 - pwcomm - RECV   22 ---> 0000 0289 00E1 ................  3BC7 <---
2022-08-18 12:49:01,855 - pwcomm - SEND   30 ---> 0023           000D6F000072991D  0F58 <---
2022-08-18 12:49:01,886 - pwcomm - RECV   22 ---> 0000 028A 00C1 ................  8ECA <---
2022-08-18 12:49:01,887 - pwcomm - DTRC   91 # APSRequestNodeInfo: Source MAC: 000D6F0000598E34# APSRequestNodeInfo: Destination MAC: \r\n
2022-08-18 12:49:01,887 - pwcomm - DSHR   18 000D6F000072991D\r\n
2022-08-18 12:49:02,888 - pwcomm - DSHR    1 \\x83
2022-08-18 12:49:03,454 - pwcomm - RECV   22 ---> 0000 028A 00E1 ................  246C <---
2022-08-18 12:49:03,454 - pwcomm - SEND   30 ---> 0023           000D6F00005988BE  6448 <---
2022-08-18 12:49:03,484 - pwcomm - RECV   22 ---> 0000 028B 00C1 ................  6018 <---
2022-08-18 12:49:03,485 - pwcomm - DTRC   91 # APSRequestNodeInfo: Source MAC: 000D6F0000598E34# APSRequestNodeInfo: Destination MAC: \r\n
2022-08-18 12:49:03,485 - pwcomm - DSHR   18 000D6F00005988BE\r\n
2022-08-18 12:49:04,485 - pwcomm - DSHR    1 \\x83
2022-08-18 12:49:05,052 - pwcomm - RECV   22 ---> 0000 028B 00E1 ................  CABE <---
2022-08-18 12:49:05,052 - pwcomm - SEND   16 ---> 0008                            01 4068 <---
2022-08-18 12:49:05,068 - pwcomm - RECV   22 ---> 0000 028C 00C1 ................  CA49 <---
2022-08-18 12:49:06,069 - pwcomm - DSHR    1 \\x83
2022-08-18 12:49:12,076 - pwcomm - TOUT      '' - <!> Timeout on serial port
2022-08-18 12:49:12,076 - pwcomm - SEND   30 ---> 000D           000D6F000072991D  D7B2 <---
2022-08-18 12:49:12,102 - pwcomm - DTRC   49 # SENDING PING UNICAST: Macid: F902C2378D027A6E\r\n
2022-08-18 12:49:12,102 - pwcomm - DTRC   16 # HANDLE: 0x8D\r\n
2022-08-18 12:49:12,103 - pwcomm - RECV   22 ---> 0000 028D 00C1 ................  AD9D <---
2022-08-18 12:49:12,103 - pwcomm - SEND   30 ---> 000D           000D6F00005988BE  BCA2 <---
2022-08-18 12:49:12,128 - pwcomm - DTRC   50 \\x83# SENDING PING UNICAST: Macid: F902C2378E027A6E\r\n
2022-08-18 12:49:12,128 - pwcomm - DTRC   16 # HANDLE: 0x8E\r\n
2022-08-18 12:49:12,128 - pwcomm - RECV   22 ---> 0000 028E 00C1 ................  07CC <---