search

goToMain / libosdp

Implementation of IEC 60839-11-5 OSDP (Open Supervised Device Protocol); provides a C library with support for C++, Rust and Python3
https://libosdp.sidcha.dev
Apache License 2.0
140 stars 73 forks source link

FileTransfer not starting / ignoring FTSTATs FtDelay #192

Closed xsrf closed 3 months ago

xsrf commented 3 months ago

I made a python script to perform a firmware update based on the code from the screenshot in https://github.com/goToMain/libosdp/issues/185#issuecomment-2195026272 and you can see my script in #191

I noticed that the file transfer would just hang after the 2nd packed being sent to the PD. Analyzing the raw data, I noticed that my PD responded to the first FILETRANSFER with an FTSTAT containing a value for ftDelay. But since the CP sent the 2nd FILETRANSFER packet immediately after the FTSTAT, the PD kinda locked up and so did my script.

After adding a delay to the first FILETRANSFER packets (I did this by adding time.sleep(sender_delay) to sender_read()), the transfer works fine.

OSDP: CP: PD-1: [2024-08-14T12:15:14Z] [INFO ] vendor\src/osdp_file.c:307: TX_init: Starting file transfer of size: 283472
FW Upgrade started... Reader will reboot when done!
OSDP: CP: PD-1: [2024-08-14T12:15:15Z] [DEBUG] vendor\src/osdp_cp.c:686: CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
 *** it just hangs here forever ***

Wireshark Capture

No.     Time           Source                Destination           Protocol Length Info
    573 44.862479      192.168.3.211         192.168.3.145         OSDP     190    Plaintext Message (FILETRANSFER)

Transmission Control Protocol, Src Port: 62990, Dst Port: 4196, Seq: 98, Ack: 151, Len: 136
OSDP Packet
    Header: ff5301870005
    Payload: 7c015053040000000000740000d0…
        Command/Reply ID: 0x7c
        Command/Reply Data: 015053040000000000740000d09e…
    CheckSum: 475b

No.     Time           Source                Destination           Protocol Length Info
    575 45.028675      192.168.3.145         192.168.3.211         OSDP     70     Plaintext Message (FTSTAT)

Transmission Control Protocol, Src Port: 4196, Dst Port: 62990, Seq: 151, Ack: 234, Len: 16
OSDP Packet
    Header: ff53810f0005
    Payload: 7a00701700000000
        Command/Reply ID: 0x7a
        Command/Reply Data: 00701700000000
    CheckSum: 4b9f

No.     Time           Source                Destination           Protocol Length Info
    576 45.071972      192.168.3.211         192.168.3.145         OSDP     190    Plaintext Message (FILETRANSFER)

Transmission Control Protocol, Src Port: 62990, Dst Port: 4196, Seq: 234, Ack: 167, Len: 136
OSDP Packet
    Header: ff5301870006
    Payload: 7c0150530400740000007400589d…
        Command/Reply ID: 0x7c
        Command/Reply Data: 0150530400740000007400589d38…
    CheckSum: 4de2

I guess ftDelay should be obeyed?

Forgot to mention, I'm using the latest release LibOSDP-3.0.6 master (cf675a0)

sidcha commented 3 months ago

@xsrf Please check if this works for you.

xsrf commented 3 months ago

Thx for the fast reply, but nope, now it's completely broken. Now the CP sends a POLL right after the PD replies with the first FTSTAT. My PD doesn't handle the POLL (since it did not obey FtDelay) and everything locks up. Since I can't delay the POLL the same way I delayed the FILETRANSFER, I can't get the transfer to start.

My script is just sitting at OSDP: CP: PD-1: 2024-08-15T09:21:58Z src/osdp_cp.c:686 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a) and I have to kill it via task manager. There is no timeout even after many minutes. Shouldn't there be a mechanism that will retry a command, re-init the connection or mark the PD as offline?

Edit: cp.get_file_tx_status() is the call that freezes

Edit2: and with the call to cp.get_file_tx_status() removed, my loop loops but there is still no additional communication happening (cp.get_event() just times out every 2s) and no retry or timeout triggered even after minutes.

LibOSDP-3.0.6 master (e8205a0)

sidcha commented 3 months ago

Hm, I assumed the PD will still be able to respond to POLL even when file transfer is in delay-wait mode. So what the CP is doing now is to send POLL commands as usual when file transfer is waiting.

Will have to check about the timeouts in cp.get_file_tx_status().

xsrf commented 3 months ago

I guess the PD just can't handle anything when switching to firmware update. However, the FTSTAT also contains FtAction = 0 which means interleaving is not allowed, so in my understanding, sending POLL after that may violate the spec.

sidcha commented 3 months ago

FTActions in entirely ignored ATM. A bit more work needs to be done to support this in its full glory.

sidcha commented 3 months ago

@xsrf I have added some support for this now.

Fair warning: I don't have any device to test this and the integration test suite does not check for these cases; IOW, it's all just eye balling from my side, so please expect rough edges :)

xsrf commented 3 months ago

Hmm, I don't see a difference with LibOSDP-3.0.6 master (4225650). Still getting the POLL right after FTSTAT and then everything hangs. Also cp.get_file_tx_status() - if added back to the loop - still blocks forever. Any ideas how I can help debug?

sidcha commented 3 months ago

The packet trace file (flags=[LibFlag.CapturePackets] in PDInfo), along with a debug level log file (log_level=LogLevel.Debug in ControlPanel) should be very helpful.

Also, would prefer to take this discussion to a mail thread (sidcha.dev@gmail.com) and then post the final outcome here.

xsrf commented 3 months ago

I'm not sure how to set the flag, but I can still give you the OSDP ethernet capture and full debug log. But there is not really something to see that I haven't already posted. It just stops.

Looking at your commit - is it possible you just inverted the OSDP_FILE_TX_FLAG_EXCLUSIVE Flag? Because Bit 0 of FtAction set/1 means not exclusive (interleave) and not set/0 means file transfer only/exclusive. In https://github.com/goToMain/libosdp/blob/4225650a4327b22ef3e5841b68a84207987346e2/src/osdp_file.c#L357 you return -1 (don't send any command, wait for me) if the flag is set. But it should be the other way round, shouldn't it?

Regardless, here is the rest Code: ```python #!/usr/bin/env python3 import argparse import socket import time import os from osdp import * class TCPChannel: def __init__(self, host: str, port: int): self.sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) self.sock.connect((host, port)) def read(self, max_read: int): return self.sock.recv(max_read) def write(self, data: bytes): return self.sock.send(data) def flush(self): self.sock.setsockopt(socket.SOL_SOCKET, socket.SO_SNDBUF, 1) def __del__(self): self.sock.close() parser = argparse.ArgumentParser(prog = 'osdp_fw_update.py', description = "LibOSDP CP APP") parser.add_argument("device", type = str, metavar = "IPADDR", help = "IP-Address or hostname of Reader/RS485 Converter Port 4196") parser.add_argument("reader", type = int, metavar = "READER", help = "Reader-ID on Bus (default: 1)") parser.add_argument("filename", type = str, metavar = "FILENAME", help = "Filename *.osdp") parser.add_argument("--port", type = int, metavar = "PORT", default = 4196, help = "Reader/RS485 Converter Port (default: 4196)") parser.add_argument("--loglevel", type = int, metavar = "LEVEL", default = 6, help = "LibOSDP log level; can be 0-7 (default: 6)") args = parser.parse_args() sender_data = None sender_delay = 0 def file_read(filename): global sender_data with open(filename,"rb") as file: sender_data = file.read() print(f"File read {filename}") def sender_open(file_id: int, file_size: int) -> int: global sender_data return len(sender_data) def sender_read(size: int, offset: int) -> bytes: if sender_delay > 0: time.sleep(sender_delay) global sender_data sender_data_length = len(sender_data) if offset + size > sender_data_length: size = sender_data_length - offset return bytes(sender_data[offset:offset+size]) def sender_write(data: bytes, offset: int) -> int: return False def sender_close(file_id: int): return True sender_fops = { 'open': sender_open, 'read': sender_read, 'write': sender_write, 'close': sender_close } def send_file_cmd(cp: ControlPanel, pd_info_address: int, file_id: int): file_read(args.filename) result = cp.register_file_ops(pd_info_address,sender_fops) print(f"Register file ops {result} {pd_info_address} {file_id}") file_tx_cmd = { 'command': Command.FileTransfer, 'id': file_id, 'flags': 0 } result = cp.send_command(pd_info_address, file_tx_cmd) if result: print("FW Upgrade started... Reader will reboot when done!") else: print("FW Upgrade ERROR") try: ## Describe the PD (setting scbk=None puts the PD in install mode) channel = TCPChannel(args.device, args.port) pd_info = [ PDInfo(args.reader, channel, scbk=0), ] ## Create a CP device and kick-off the handler thread cp = ControlPanel(pd_info, log_level=args.loglevel) print('cp.start()') cp.start() cp.online_wait_all() beep_cmd = { 'command': Command.Buzzer, 'reader': 0, 'control_code': 2, 'on_count': 1, 'off_count': 1, 'rep_count': 1 } print('Loop') cp.send_command(pd_info[0].address, beep_cmd) time.sleep(0.5) print(f"send_file_cmd", end="\r", flush=True) send_file_cmd(cp, pd_info[0].address, 1) time.sleep(2) sender_delay = 0 while True: #print(f"cp.get_event", end="\r", flush=True) print("cp.get_event") event = cp.get_event(pd_info[0].address, timeout=2) #print(f"cp.get_file_tx_status", end="\r", flush=True) #status = cp.get_file_tx_status(pd_info[0].address) #pct = round((status['offset']/status['size'])*100 , 1) #print(f"Upload: {status['offset']} / {status['size']} ({pct}%)", end="\r", flush=True) except KeyboardInterrupt: print("Quit") os._exit(0) except: print("Quit") os._exit(0) ``` Log: ``` >python osdp_fw_update.py 192.168.3.145 1 sq80_redblink.osdp --loglevel 7 pyosdp: 2024-08-16T13:56:38Z src/osdp_cp.c:1462 [INFO ] CP Setup complete; LibOSDP-3.0.6 master (4225650) NumPDs:1 Channels:1 cp.start() OSDP: CP: PD-1: 2024-08-16T13:56:38Z src/osdp_cp.c:682 [DEBUG] CMD: ID(61) REPLY: PDID(45) OSDP: CP: PD-1: 2024-08-16T13:56:38Z src/osdp_cp.c:1229 [DEBUG] StateChange: [ID-Request] -> [Cap-Detect] (SC-Inactive) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'ContactStatusMonitoring' (1/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'OutputControl' (1/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'CardDataFormat' (3/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'LEDControl' (4/2) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'AudibleControl' (2/1) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'TextOutput' (0/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'TimeKeeping' (0/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'CheckCharacter' (1/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'CommunicationSecurity' (0/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'ReceiveBufferSize' (149/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'CombinedMessageSize' (149/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'SmartCard' (0/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'Reader' (0/1) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:459 [DEBUG] Reports capability 'Biometric' (0/0) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:682 [DEBUG] CMD: CAP(62) REPLY: PDCAP(46) OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:1205 [INFO ] Online; Without SC OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:1229 [DEBUG] StateChange: [Cap-Detect] -> [Online] (SC-Inactive) Loop OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_cp.c:682 [DEBUG] CMD: BUZ(6a) REPLY: ACK(40) File read sq80_redblink.osdp Register file ops True 1 1 OSDP: CP: PD-1: 2024-08-16T13:56:39Z src/osdp_file.c:408 [INFO ] TX_init: Starting file transfer of size: 283472 FW Upgrade started... Reader will reboot when done! OSDP: CP: PD-1: 2024-08-16T13:56:40Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a) cp.get_event cp.get_event cp.get_event cp.get_event cp.get_event cp.get_event cp.get_event cp.get_event Quit (me pressing CTRL+C because it stopped doing anything) ``` OSDP Capture: ``` No. Time Source Destination Protocol Length Info 1102 78.471803 192.168.3.211 192.168.3.145 OSDP 63 Plaintext Message (POLL) Transmission Control Protocol, Src Port: 55204, Dst Port: 4196, Seq: 80, Ack: 133, Len: 9 OSDP Packet Header: ff5301080006 Payload: 60 Command/Reply ID: 0x60 Command/Reply Data: CheckSum: d866 No. Time Source Destination Protocol Length Info 1103 78.497137 192.168.3.145 192.168.3.211 OSDP 63 Plaintext Message (ACK) Transmission Control Protocol, Src Port: 4196, Dst Port: 55204, Seq: 133, Ack: 89, Len: 9 OSDP Packet Header: ff5381080006 Payload: 40 Command/Reply ID: 0x40 Command/Reply Data: CheckSum: 6a60 No. Time Source Destination Protocol Length Info 1105 78.581405 192.168.3.211 192.168.3.145 OSDP 63 Plaintext Message (POLL) Transmission Control Protocol, Src Port: 55204, Dst Port: 4196, Seq: 89, Ack: 142, Len: 9 OSDP Packet Header: ff5301080007 Payload: 60 Command/Reply ID: 0x60 Command/Reply Data: CheckSum: e955 No. Time Source Destination Protocol Length Info 1106 78.606719 192.168.3.145 192.168.3.211 OSDP 63 Plaintext Message (ACK) Transmission Control Protocol, Src Port: 4196, Dst Port: 55204, Seq: 142, Ack: 98, Len: 9 OSDP Packet Header: ff5381080007 Payload: 40 Command/Reply ID: 0x40 Command/Reply Data: CheckSum: 5b53 No. Time Source Destination Protocol Length Info 1109 78.649295 192.168.3.211 192.168.3.145 OSDP 190 Plaintext Message (FILETRANSFER) Transmission Control Protocol, Src Port: 55204, Dst Port: 4196, Seq: 98, Ack: 151, Len: 136 OSDP Packet Header: ff5301870005 Payload: 7c015053040000000000740000d0… Command/Reply ID: 0x7c Command/Reply Data: 015053040000000000740000d0… CheckSum: 475b No. Time Source Destination Protocol Length Info 1113 78.815930 192.168.3.145 192.168.3.211 OSDP 70 Plaintext Message (FTSTAT) Transmission Control Protocol, Src Port: 4196, Dst Port: 55204, Seq: 151, Ack: 234, Len: 16 OSDP Packet Header: ff53810f0005 Payload: 7a00701700000000 Command/Reply ID: 0x7a Command/Reply Data: 00701700000000 CheckSum: 4b9f No. Time Source Destination Protocol Length Info 1115 78.899208 192.168.3.211 192.168.3.145 OSDP 63 Plaintext Message (POLL) Transmission Control Protocol, Src Port: 55204, Dst Port: 4196, Seq: 234, Ack: 167, Len: 9 OSDP Packet Header: ff5301080006 Payload: 60 Command/Reply ID: 0x60 Command/Reply Data: CheckSum: d866 ```
sidcha commented 3 months ago

I'm not sure how to set the flag, [...]

In your script, please apply the following change and invoke it with the option --log-level=7.

--- /tmp/mod.py      2024-08-16 17:28:56.325901045 +0200
+++ /tmp/orig.py        2024-08-16 17:24:51.437900559 +0200
@@ -86,7 +86,7 @@
     ## Describe the PD (setting scbk=None puts the PD in install mode)
     channel = TCPChannel(args.device, args.port)
     pd_info = [
-        PDInfo(args.reader, channel, scbk=0),
+        PDInfo(args.reader, channel, scbk=0, flags=[LibFlag.CapturePackets]),
     ]

     ## Create a CP device and kick-off the handler thread

You would also need to call cp.teardown() before exiting the script to finalize the capture file. But feel free to not produce this if you think your capture is sufficiently describing your issue.

Looking at your commit - is it possible you just inverted the OSDP_FILE_TX_FLAG_EXCLUSIVE Flag?

Good catch; indeed, the flag was inverted. Fixed now.

xsrf commented 3 months ago

Nice, that fixed it. The CP now waits 6s as demanded by the PD before sending the next FILETRANSFER and the upload starts properly. I guess I'd consider this fixed. Thx!

>python osdp_fw_update.py 192.168.3.145 1 sq80.osdp --loglevel=7
pyosdp: 2024-08-16T17:01:21Z src/osdp_cp.c:1462 [INFO ] CP Setup complete; LibOSDP-3.0.6 master (99ab23f) NumPDs:1 Channels:1
cp.start()
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:682  [DEBUG] CMD: ID(61) REPLY: PDID(45)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:1229 [DEBUG] StateChange: [ID-Request] -> [Cap-Detect] (SC-Inactive)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'ContactStatusMonitoring' (1/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'OutputControl' (1/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'CardDataFormat' (3/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'LEDControl' (4/2)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'AudibleControl' (2/1)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'TextOutput' (0/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'TimeKeeping' (0/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'CheckCharacter' (1/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'CommunicationSecurity' (0/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'ReceiveBufferSize' (149/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'CombinedMessageSize' (149/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'SmartCard' (0/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'Reader' (0/1)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:459  [DEBUG] Reports capability 'Biometric' (0/0)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:682  [DEBUG] CMD: CAP(62) REPLY: PDCAP(46)
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:1205 [INFO ] Online; Without SC
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:1229 [DEBUG] StateChange: [Cap-Detect] -> [Online] (SC-Inactive)
Loop
OSDP: CP: PD-1: 2024-08-16T17:01:21Z src/osdp_cp.c:682  [DEBUG] CMD: BUZ(6a) REPLY: ACK(40)
File read sq80.osdp
Register file ops True 1 1
OSDP: CP: PD-1: 2024-08-16T17:01:22Z src/osdp_file.c:408  [INFO ] TX_init: Starting file transfer of size: 283464
FW Upgrade started... Reader will reboot when done!
OSDP: CP: PD-1: 2024-08-16T17:01:22Z src/osdp_cp.c:682  [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:01:28Z src/osdp_cp.c:682  [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:01:29Z src/osdp_cp.c:682  [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:01:29Z src/osdp_cp.c:682  [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:01:29Z src/osdp_cp.c:682  [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:01:29Z src/osdp_cp.c:682  [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:01:29Z src/osdp_cp.c:682  [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:01:30Z src/osdp_cp.c:682  [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:01:30Z src/osdp_cp.c:682  [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
...
sidcha commented 3 months ago

Glad things work now. And thanks for putting in the last nail :)