invalid package start byte (b'')

[kolins-cz]

Hello, I have encountered same problem as someone here but that issue was not really solved. I am in the same situation where different library works and this one does not.

I have tried this C library and it works well (I have modified default example a little). Code based on this library I have used is here (just a default example with correct serial port)

My Xcom-232i is in RS232 mode, not in Xcom-LAN mode. I believe they have slightly different protocol. I do not have Moxa converter, but different arrangement which cannot connect to a listening port, it can only listen on port (be a server). So I can't test TCP mode. I believe I have also tried changing mode to Xcom-LAN and connecting via RS232 but it gave me different error. I have my Studer setup on R688 firmware. Xcom-232i is connected to linux box via old USB converter with FTDI chip inside, no problem there.

I would like to use this python lib rather than the C one.

[zocker-160]

It would be interesting to know what data scomtest is actually sending via the serial port and then compare it to my implementation.

You can enable debug mode by adding logging.basicConfig(level=logging.DEBUG).

I personally am using a cheap USB2Serial adapter with the PL2303 chip and a Xcom-232i. As for firmware version, my RCC shows the following information for the Xcom-232i:

To be sure that I didn't break something in a recent update, I did a clean setup and install using the following code:

#! /usr/bin/env python3

import logging
logging.basicConfig(level=logging.DEBUG)

from xcom_proto import XcomP as param
from xcom_proto import XcomC
from xcom_proto import XcomRS232
from xcom_proto import XcomLANUDP

xcom = XcomRS232(serialDevice="/dev/ttyUSB1", baudrate=115200)

sunhours = xcom.getValue(param.PV_SUN_HOURS_CURR_DAY)
pvpower = xcom.getValue(param.PV_POWER) * 1000

print("pv power:", pvpower)
print("sunhours:", sunhours)

and it does work

$ python3 test3.py 
DEBUG:XcomRS232:requesting value Datapoint(id=11025, name='PV_SUN_HOURS_CURR_DAY', type='FLOAT', unit='h')
DEBUG:XcomRS232: --> aa0001000000640000000a006e6b00010100112b00000d004a5e0d0a
DEBUG:XcomRS232: <-- aaf764000000010000000e00699c02010100112b00000d0000a00d413add0d0a
DEBUG:XcomRS232:Package(header=Header(flags=247, src=100, dst=1, data_length=14), frame_data=Frame(flags=2, id=b'\x01', setr=(obj_type=b'\x01\x00', obj_id=11025, property_id=b'\r\x00', property_data=b'\x00\xa0\rA')))
DEBUG:XcomRS232:requesting value Datapoint(id=11043, name='PV_POWER', type='FLOAT', unit='W')
DEBUG:XcomRS232: --> aa0001000000640000000a006e6b00010100232b00000d005cca0d0a
DEBUG:XcomRS232: <-- aaf764000000010000000e00699c02010100232b00000d000040e23fbf190d0a
DEBUG:XcomRS232:Package(header=Header(flags=247, src=100, dst=1, data_length=14), frame_data=Frame(flags=2, id=b'\x01', setr=(obj_type=b'\x01\x00', obj_id=11043, property_id=b'\r\x00', property_data=b'\x00@\xe2?')))
pv power: 1767.578125
sunhours: 8.8515625

That being said, I will try to do a reset of the Xcom-232i with a new configuration and check if that makes a difference or not.

[zocker-160]

Update: after resetting everything I managed to reproduce this issue.

Looking into it.

[zocker-160]

ok so it turns out, that despite setting the default baudrate of 38400 in the Xcom configurator, the Xcom-232i still used 115200 for whatever reason resulting in the same issue as you described above.

After setting it to 115200 in the code however, it started working again. So I am not sure what is up with that.

[dusanmsk]

I have the same problem using moxa/tcp. I did some investigation and it seems that there is received some chunk of data which is a fragment of (maybe) previous response or whatever.

OK block: 65000000010000000e0059eb02010100c30b00000d000000754396a30d0aaae665000000010000000e0059eb02010100cd0b00000d0000006d4398f70d0aaae665000000010000000e0059eb02010100c40b00000d0000000000df800d0aaae665000000010000000e0059eb02010100ce0b00000d0000001e4047600d0aaae665000000010000000c0057e702010100c20b00000d000400e1ba0d0aaae666000000010000000e005af5020101000c0c00000d0000304842e2bb0d0aaae666000000010000000e005af5020101000d0c00000d0000004842b3350d0aaae666000000010000000e005af502010100410c00000d00000000005d6b0d0aaae66600

BAD block: 0000010000000e005af502010100400c00000d00000000005c610d0aaae666000000010000000e005af502010100c30b00000d000000764397a50d0aaae666000000010000000e005af502010100cd0b00000d0000006f439afb0d0aaae666000000010000000e005af502010100c40b00000d0000000000df800d0aaae666000000010000000e005af502010100ce0b00000d0000000000e9e40d0aaae666000000010000000c0058f102010100c20b00000d000400e1ba0d0aaae62d010000010000000e0022c402010100212b00000d000080c140dd840d0aaae62d010000010000000e0022c402010100232b00000d00000000005e560d0aaae62e010000

So I tried to do a stupid dirty hack - skip data until 0xAA - and it helped and seems that it solves problem. I am not sure if this is the right way how to solve this, nor I did any deep investigation (will do that tomorrow), but "invalid package start byte" is gone.

https://github.com/zocker-160/xcom-protocol/pull/7

[zocker-160]

@dusanmsk first thank you for this info and the PR, I am sadly currently low on time to do testing, but I see the issue now that for some reason there is simply invalid data coming in which has to be discarded.

If data starts with something like 0x00, then the error message will show b"". It however does not explain that there is no data shown when debug logging is enabled.

Could you please do one test with debugging enabled and post the output? I wonder if there is something wrong with the logger here or if your error is a different one from OP.

[kolins-cz]

Hello I have tried @dusanmsk fix and error is still there. I have finally figured out how to add logging and here is the result:

kolin@pv-iot:~$ python zocker-xcom-232.py
DEBUG:XcomRS232:requesting value Datapoint(id=1607, name='SMART_BOOST_LIMIT', type='FLOAT', unit='')
DEBUG:XcomRS232: --> aa0001000000640000000a006e6b00010200470600000d005cf10d0a
DEBUG:XcomRS232: <--
Traceback (most recent call last):
  File "/home/kolin/zocker-xcom-232.py", line 13, in <module>
    boostValue = xcom.getValue(param.SMART_BOOST_LIMIT)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kolin/.local/lib/python3.11/site-packages/xcom_proto/XcomAbs.py", line 43, in getValue
    response: Package = self.sendPackage(request)
                        ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kolin/.local/lib/python3.11/site-packages/xcom_proto/XcomRS232.py", line 33, in sendPackage
    retPackage = Package.parseBytes(response[:-len(SERIAL_TERMINATOR)])
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kolin/.local/lib/python3.11/site-packages/xcom_proto/protocol.py", line 178, in parseBytes
    return Package.parse(BytesIO(buf))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kolin/.local/lib/python3.11/site-packages/xcom_proto/protocol.py", line 164, in parse
    assert sb == Package.start_byte, f"invalid package start byte ({sb})"
           ^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: invalid package start byte (b'')

I am running Xcom-232 mode, not Xcom-LAN one. Maybe that is the problem? I believe that Xcom-LAN have different protocol. Debug shows a sent query but no answer.

I remember that Studer scom.exe utility worked only with Xcom-232 mode.

[dusanmsk]

I'll try 232 mode in a few next days because I didn't tested it yet in my project and will see.

[zocker-160]

@kolins-cz the protocol is different, but that is accounted for in my code. As I have explained above, I myself have used both for quite some time without issues, I don't think the protocol itself it the issue, because you don't seem to receive any data in the first place.

To me this has the exact same symptom as if the baudrate was wrong, is it set to 115200?

[kolins-cz]

I am sure my baudrate is 115200. This is snippet from example using https://github.com/k3a/studer C library:

    // Initialize the serial port
    if (serial_init(port, B115200, PARITY_EVEN, 1) != 0) {
        return 1;
    }

    while (1) {
        // Read parameters for addresses 100 to 104
        for (int addr = 100; addr < 105; addr++) {
            read_param_result_t result = read_param(addr, 3136);
            if (result.error == 0) {
                printf("xtender %d output power = %.3f kW\n", addr, -result.value);
            } else {
                printf("xtender %d output power = read failed\n", addr);
            }
        }

And it works.

[zocker-160]

Then I don't know what the problem is, sadly cannot reproduce it. :(

[kolins-cz]

I have added debug output to example using C library. Now it prints the query sent to serial port:

AA0001000000640000000A006E6B00010100400C000001004EC5
xtender 100 output power = 0.380 kW
AA0001000000650000000A006F7100010100400C000001004EC5
xtender 101 output power = 0.342 kW
AA0001000000660000000A00707700010100400C000001004EC5
xtender 102 output power = -0.000 kW
AA0001000000670000000A00717D00010100400C000001004EC5
xtender 103 output power = 0.457 kW
AA0001000000680000000A00728300010100400C000001004EC5
xtender 104 output power = 0.311 kW

(I have four Xtenders in 3-phase arrangement with L1 in parallel)

I have also modified your example to read the same parameter (3136)

#! /usr/bin/env python3
import logging
logging.basicConfig(level=logging.DEBUG)

from xcom_proto import XcomP as param
from xcom_proto import XcomC
from xcom_proto import XcomRS232
from xcom_proto import XcomLANUDP

xcom = XcomRS232(serialDevice="/dev/serial/by-path/platform-xhci-hcd.1.auto-usb-0:1.1.1:1.0-port0", baudrate=115200)

acpower = xcom.getValue(param.AC_POWER_OUT) * 1000

print("AC power out:", acpower)

and result is:

kolin@pv-iot:~$ python zockertest.py
DEBUG:XcomRS232:requesting value Datapoint(id=3136, name='AC_POWER_OUT', type='FLOAT', unit='kW')
DEBUG:XcomRS232: --> aa0001000000640000000a006e6b00010100400c00000d005add0d0a
DEBUG:XcomRS232: <--
Traceback (most recent call last):
  File "/home/kolin/zockertest.py", line 14, in <module>
    acpower = xcom.getValue(param.AC_POWER_OUT) * 1000
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kolin/.local/lib/python3.11/site-packages/xcom_proto/XcomAbs.py", line 43, in getValue
    response: Package = self.sendPackage(request)
                        ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kolin/.local/lib/python3.11/site-packages/xcom_proto/XcomRS232.py", line 33, in sendPackage
    retPackage = Package.parseBytes(response[:-len(SERIAL_TERMINATOR)])
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kolin/.local/lib/python3.11/site-packages/xcom_proto/protocol.py", line 178, in parseBytes
    return Package.parse(BytesIO(buf))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kolin/.local/lib/python3.11/site-packages/xcom_proto/protocol.py", line 164, in parse
    assert sb == Package.start_byte, f"invalid package start byte ({sb})"
           ^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: invalid package start byte (b'')

[JeffersM1]

Since you have 3 Xtender inverters, do you need to address them individually (101, 102, and 103) instead of using the default multicast address?

[dusanmsk]

Hmm, I am not sure, but maybe you have pointed a right think - broadcast addresses. I am now using my fork of your lib so the problem is gone, but if I remember right, the problem was mostly (or exclusively) only with requests addressed by '100'. Will double check and let you know.

[dusanmsk]

So it seems that it is problem with battery in my case. I use to grab battery parameters on address 100 ( see https://github.com/dusanmsk/studer/blob/aba70dd3cadfc75e8f650607c65064ebfe774ec6/logger/studerlogger/studerlogger.py#L236 ). I tried also 601, but it sometimes fail with that start byte error also on that address.

So I am going back to use my workaround that will discard all bytes from buffer until it reach the right start byte. (after using this workaround for a week it seems that it has no any sideeffects).

[zocker-160]

I will do some testing regarding your workaround and merge if everything works, also I will have to improve the error messages more, because "invalid start byte" should actually be something like "no data received".

[zocker-160]

I tried also 601, but it sometimes fail with that start byte error also on that address.

@dusanmsk try increasing the timeout, I feel like you might have a very high load on the internal bus, which could explain why the default 2 seconds are not enough.

A completely idle bus usually requires 1 - 1.3 seconds to react. Studer recommends 2 seconds, which is why I use that value.

[JeffersM1]

Will the changes made in version 0.3.5 have any effect on Xcom-LAN communication?

[zocker-160]

@JeffersM1 yes they do, because the start byte seek does affect all versions. If there is something that broke in Xcom-LAN with those changes, then I need to know.

[JeffersM1]

I haven't installed the update yet, I just wanted to know if I should. Will let you know the results once I do.

[JeffersM1]

I just installed the 0.3.5 update and keep getting the following error message: Assertion Error at 2024-05-04 13:54:29.745177 invalid header checksum

This is the error handler of my script:

        except AssertionError as e:
            print("Assertion Error at ", datetime.datetime.now(), e)
            scom_error_code = 1

Do you need me to do anything further to give you enough information to understand the problem?

[zocker-160]

Does this happen every single time? I have not changed anything regarding checksum checks.

[JeffersM1]

Yes, I get the error every time the script executes. I also have other print to screens that print the values of the all the parameters once on startup, and each time one changes thereafter. With new code update, the parameters never print out.

[JeffersM1]

After installing the update, the output to the console looks like this: Successfully installed xcom_proto-0.3.5
(xcom) pi@homeassistant:~ $ python3 ha_xcom31.py -1 4
At 2024-05-04 13:53:56.306736 the Current Studer Python Script Loop Delay is: 3.0 s
Assertion Error at 2024-05-04 13:53:59.737192 invalid header checksum
Assertion Error at 2024-05-04 13:54:04.031512 invalid header checksum
Assertion Error at 2024-05-04 13:54:08.325564 invalid header checksum
Assertion Error at 2024-05-04 13:54:12.619912 invalid header checksum
Assertion Error at 2024-05-04 13:54:16.957305 invalid header checksum
Assertion Error at 2024-05-04 13:54:21.198336 invalid header checksum
Assertion Error at 2024-05-04 13:54:25.449179 invalid header checksum
Assertion Error at 2024-05-04 13:54:29.745177 invalid header checksum
^CTraceback (most recent call last):
File "/home/pi/ha_xcom31.py", line 309, in main() File "/home/pi/ha_xcom31.py", line 130, in main time.sleep(float(current_studer_python_script_loop_delay)) # Pause the loop using the latest delay value ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ KeyboardInterrupt

[JeffersM1]

With version 0.3.4 the output to the console is: (xcom) pi@homeassistant:~ $ python3 ha_xcom31.py -1 4 At 2024-05-04 14:38:51.112807 the Current Studer Python Script Loop Delay is: 3.0 s At 2024-05-04 14:38:51.112807 the Current Tariff Price is: 0.0398 �/kWh At 2024-05-04 14:38:51.112807 the Current Studer Smart Boost Limit is: 100.0 % At 2024-05-04 14:38:51.112807 the Current Studer Inverter Charge Current is: 25.0 A At 2024-05-04 14:38:51.112807 the Current Studer Inverter Max Current of AC Source is: 25.0 A At 2024-05-04 14:38:51.112807 the Current Studer Max Grid Feeding Current is: 31.0 A At 2024-05-04 14:38:51.112807 the Current Studer SOC Level for Grid Feeding is: 95.0 % At 2024-05-04 14:38:51.112807 the Current Studer SOC Level for Backup is: 66.0 %

[zocker-160]

could you enable debugging and post the output?

[JeffersM1]

I haven't used the debugger. I normally start my script from a linux terminal command line with the following: pi@homeassistant:~ $ python3 ha_xcom31.py -1 4 What do I need to add?

[zocker-160]

add this to the start of your script:

import logging
logging.basicConfig(level=logging.DEBUG)

[JeffersM1]

I added the lines to the script and now get a lot of output to the screen. How can I redirect the output to a text file?

[JeffersM1]

I had to reinstall the 0.3.5 so now the output isn't so long.

Successfully installed xcom_proto-0.3.5 (xcom) pi@homeassistant:~ $ python3 ha_xcom31DB.py -1 4 DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1:8123 DEBUG:urllib3.connectionpool:http://127.0.0.1:8123 "GET /api/states/sensor.ha_scom_studer_python_script_loop_delay HTTP/1.1" 200 482 At 2024-05-04 16:46:08.645088 the Current Studer Python Script Loop Delay is: 3.0 s INFO:XcomLANTCP:Starting TCP server on port 4001 INFO:XcomLANTCP:Waiting for MOXA to connect... DEBUG:XcomLANTCP:Got connection from ('moxa ip', 10256) DEBUG:XcomLANTCP:requesting value Datapoint(id=15017, name='VS_PV_PROD', type='FLOAT', unit='kWh') DEBUG:XcomLANTCP: --> aa0001000000bd0200000a00c98b00010100a93a00000d00f139 DEBUG:XcomLANTCP: <-- aae6bd020000010000000e00b36d02010100a93a00000d0000801141c5fc Assertion Error at 2024-05-04 16:46:13.738845 invalid header checksum DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1:8123 DEBUG:urllib3.connectionpool:http://127.0.0.1:8123 "GET /api/states/sensor.ha_scom_studer_python_script_loop_delay HTTP/1.1" 200 482 INFO:XcomLANTCP:Starting TCP server on port 4001 INFO:XcomLANTCP:Waiting for MOXA to connect... DEBUG:XcomLANTCP:Got connection from ('moxa ip', 10258) DEBUG:XcomLANTCP:requesting value Datapoint(id=15017, name='VS_PV_PROD', type='FLOAT', unit='kWh') DEBUG:XcomLANTCP: --> aa0001000000bd0200000a00c98b00010100a93a00000d00f139 DEBUG:XcomLANTCP: <-- aae6f501000001000000ba0096ec02010a000000000100016301000013663666b80bfd00d04942080cfe000044c1090cfe0000f8bf0a0cfe00e0e4410b0cfe00003241400cfe0020393f410cfe00e0a3bb581b0000604942591b0000a0d93f5a1b000000be425b1b000020ab425d1b000060ca415f1b0000c0f242601b0000c08e42611b0000801143621b000060f642f82afd0000c07ffc2afe0000c07fff2afe0000c07f032bfe0000c07f983afd00804942a23afe00207f3fa93afe00b09241b33afe00204342ea01 Assertion Error at 2024-05-04 16:46:18.022793 invalid header checksum DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1:8123 DEBUG:urllib3.connectionpool:http://127.0.0.1:8123 "GET /api/states/sensor.ha_scom_studer_python_script_loop_delay HTTP/1.1" 200 482

[JeffersM1]

I replaced the actual ip address in the screen dump with "moxa ip"

[zocker-160]

thank you! This is very useful @JeffersM1, I will investigate this.

How can I redirect the output to a text file?

On linux you can just pipe the output to a file using: python3 "yourfile.py" "your" "parameters" > fileoutput.txt

[JeffersM1]

That piping to a file is the same way it was back in the day with DOS. > or >> . One appends to existing file, and the other starts a new file.

[zocker-160]

I found the issue, thank you for the debug log @JeffersM1, I pushed a new version 0.3.6 which should fix it.

[zocker-160]

I also added your two suggested parameters and updated documentation in readme.

[JeffersM1]

The version 0.3.6 is working without errors.

[JeffersM1]

Thanks.

[JeffersM1]

With the previous versions of the code (I think I had 0.3.4) , I would always get some sporadic assertion error messages like the following: "Assertion Error at 2024-05-08 16:41:54.730276" The error rate was never enough to cause issues. With the newer version of the code, there is more detail in the error message (its still sporadic and not enough to cause issues): Assertion Error at 2024-05-08 16:41:54.730276 invalid data checksum Maybe the transmission is occasionally interrupted. My Moxa is still connected to the Studer, so maybe that could be causing interruptions.

[zocker-160]

Yeah I have changed the error messages a bit, but it is essentially still the same error.

Wrong checksum error is typically caused either by a broken or an unfinished data transmission, which can happen when there is a lot of traffic happening at the same time.