Closed xsrf closed 3 months ago
@xsrf Thanks for the details bug report. Please check if this works for you.
Well I don't get the last FILETRANSFER
repeated anymore, but now the CP suddenly wants to init a SC:
OSDP: CP: PD-1: 2024-08-16T17:18:59Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:18:59Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:19:00Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:19:00Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:19:00Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:19:00Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:19:00Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:19:01Z src/osdp_file.c:184 [INFO ] Stat_Decode: File transfer complete
OSDP: CP: PD-1: 2024-08-16T17:19:01Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-16T17:19:01Z src/osdp_cp.c:1229 [DEBUG] StateChange: [Online] -> [SC-Chlng] (SC-Inactive)
OSDP: CP: PD-1: 2024-08-16T17:19:01Z src/osdp_cp.c:419 [WARN ] PD replied with NAK(5) for CMD: CHLNG(76)
OSDP: CP: PD-1: 2024-08-16T17:19:01Z src/osdp_cp.c:682 [DEBUG] CMD: CHLNG(76) REPLY: NAK(41)
OSDP: CP: PD-1: 2024-08-16T17:19:01Z src/osdp_cp.c:1156 [WARN ] SC Failed. Retry with SCBK-D
OSDP: CP: PD-1: 2024-08-16T17:19:01Z src/osdp_cp.c:419 [WARN ] PD replied with NAK(5) for CMD: CHLNG(76)
OSDP: CP: PD-1: 2024-08-16T17:19:01Z src/osdp_cp.c:682 [DEBUG] CMD: CHLNG(76) REPLY: NAK(41)
OSDP: CP: PD-1: 2024-08-16T17:19:01Z src/osdp_cp.c:1205 [INFO ] Online; Without SC
OSDP: CP: PD-1: 2024-08-16T17:19:01Z src/osdp_cp.c:1229 [DEBUG] StateChange: [SC-Chlng] -> [Online] (SC-Inactive)
Quit (me pressing STRG-C because it hang)
(had to kill python via Task-Manager)
The capture flag didn't work (I added cp.teardown()
to my exception handler which caused it to freeze) so here is my ethernet capture again, which should be enough anyways:
No. Time Source Destination Protocol Length Info
17239 621.184695 192.168.3.211 192.168.3.145 OSDP 150 Plaintext Message (FILETRANSFER)
Transmission Control Protocol, Src Port: 51909, Dst Port: 4196, Seq: 332346, Ack: 39239, Len: 96
OSDP Packet
Header: ff53015f0006
Payload: 7c0148530400fc5204004c…
Command/Reply ID: 0x7c
Command/Reply Data: 0148530400fc5204004c…
CheckSum: af4d
No. Time Source Destination Protocol Length Info
17244 621.310571 192.168.3.145 192.168.3.211 OSDP 70 Plaintext Message (FTSTAT)
Transmission Control Protocol, Src Port: 4196, Dst Port: 51909, Seq: 39239, Ack: 332442, Len: 16
OSDP Packet
Header: ff53810f0006
Payload: 7a00000002000000
Command/Reply ID: 0x7a
Command/Reply Data: 00000002000000
CheckSum: 7579
No. Time Source Destination Protocol Length Info
17247 621.352175 192.168.3.211 192.168.3.145 OSDP 74 Seure Message
Transmission Control Protocol, Src Port: 51909, Dst Port: 4196, Seq: 332442, Ack: 39255, Len: 20
OSDP Packet
Header: ff530113000c
Payload: 03110176009031cf957a59e5
Command/Reply ID: 0x76
Secure Channel Block: 031101 (SCS_11)
CheckSum: 9325
No. Time Source Destination Protocol Length Info
17252 621.388600 192.168.3.145 192.168.3.211 OSDP 64 Plaintext Message (NACK)
Transmission Control Protocol, Src Port: 4196, Dst Port: 51909, Seq: 39255, Ack: 332462, Len: 10
OSDP Packet
Header: ff5381090004
Payload: 4105
Command/Reply ID: 0x41
Command/Reply Data: 05
CheckSum: 03a1
No. Time Source Destination Protocol Length Info
17253 621.431416 192.168.3.211 192.168.3.145 OSDP 74 Seure Message
Transmission Control Protocol, Src Port: 51909, Dst Port: 4196, Seq: 332462, Ack: 39265, Len: 20
OSDP Packet
Header: ff530113000d
Payload: 03110076009031cf957a59e5
Command/Reply ID: 0x76
Secure Channel Block: 031100 (SCS_11)
CheckSum: b50f
No. Time Source Destination Protocol Length Info
17258 621.467508 192.168.3.145 192.168.3.211 OSDP 64 Plaintext Message (NACK)
Transmission Control Protocol, Src Port: 4196, Dst Port: 51909, Seq: 39265, Ack: 332482, Len: 10
OSDP Packet
Header: ff5381090005
Payload: 4105
Command/Reply ID: 0x41
Command/Reply Data: 05
CheckSum: 3396
No. Time Source Destination Protocol Length Info
17260 621.550657 192.168.3.211 192.168.3.145 OSDP 63 Plaintext Message (POLL)
Transmission Control Protocol, Src Port: 51909, Dst Port: 4196, Seq: 332482, Ack: 39275, Len: 9
OSDP Packet
Header: ff5301080006
Payload: 60
Command/Reply ID: 0x60
Command/Reply Data: <MISSING>
CheckSum: d866
No. Time Source Destination Protocol Length Info
17261 621.575979 192.168.3.145 192.168.3.211 OSDP 63 Plaintext Message (ACK)
Transmission Control Protocol, Src Port: 4196, Dst Port: 51909, Seq: 39275, Ack: 332491, Len: 9
OSDP Packet
Header: ff5381080006
Payload: 40
Command/Reply ID: 0x40
Command/Reply Data: <MISSING>
CheckSum: 6a60
No. Time Source Destination Protocol Length Info
17263 621.660261 192.168.3.211 192.168.3.145 OSDP 63 Plaintext Message (POLL)
Transmission Control Protocol, Src Port: 51909, Dst Port: 4196, Seq: 332491, Ack: 39284, Len: 9
OSDP Packet
Header: ff5301080007
Payload: 60
Command/Reply ID: 0x60
Command/Reply Data: <MISSING>
CheckSum: e955
No. Time Source Destination Protocol Length Info
17264 621.685646 192.168.3.145 192.168.3.211 OSDP 63 Plaintext Message (ACK)
Transmission Control Protocol, Src Port: 4196, Dst Port: 51909, Seq: 39284, Ack: 332500, Len: 9
OSDP Packet
Header: ff5381080007
Payload: 40
Command/Reply ID: 0x40
Command/Reply Data: <MISSING>
CheckSum: 5b53
No. Time Source Destination Protocol Length Info
17266 621.770040 192.168.3.211 192.168.3.145 OSDP 63 Plaintext Message (POLL)
Transmission Control Protocol, Src Port: 51909, Dst Port: 4196, Seq: 332500, Ack: 39293, Len: 9
OSDP Packet
Header: ff5301080005
Payload: 60
Command/Reply ID: 0x60
Command/Reply Data: <MISSING>
CheckSum: 8b33
No. Time Source Destination Protocol Length Info
17268 621.795510 192.168.3.145 192.168.3.211 OSDP 63 Plaintext Message (ACK)
Transmission Control Protocol, Src Port: 4196, Dst Port: 51909, Seq: 39293, Ack: 332509, Len: 9
OSDP Packet
Header: ff5381080005
Payload: 40
Command/Reply ID: 0x40
Command/Reply Data: <MISSING>
CheckSum: 3935
No. Time Source Destination Protocol Length Info
17270 621.877653 192.168.3.211 192.168.3.145 OSDP 63 Plaintext Message (POLL)
Transmission Control Protocol, Src Port: 51909, Dst Port: 4196, Seq: 332509, Ack: 39302, Len: 9
OSDP Packet
Header: ff5301080006
Payload: 60
Command/Reply ID: 0x60
Command/Reply Data: <MISSING>
CheckSum: d866
*** reader reboot ***
I think(I cannot say for sure because data potion is missing) the PD responded with “File contents processed” instead of “going to reboot”. In this case, CP just goes on about its normal tasks - one if which is to attempt a secure channel if the PD is capable of doing so.
There is this other mode where the PD can ask the file transfer to be in plain text which LibOSDP ignores on purpose because I think it could have security implications.
I think(I cannot say for sure because data potion is missing) the PD responded with “File contents processed” instead of “going to reboot”.
No. Time Source Destination Protocol Length Info
17244 621.310571 192.168.3.145 192.168.3.211 OSDP 70 Plaintext Message (FTSTAT)
Transmission Control Protocol, Src Port: 4196, Dst Port: 51909, Seq: 39239, Ack: 332442, Len: 16
OSDP Packet
Header: ff53810f0006
Payload: 7a00000002000000
Command/Reply ID: 0x7a
Command/Reply Data: 00 00 00 02 00 00 00
CheckSum: 7579
Payload is not missing, it's 0x02 "rebooting now, expect full communications reset."
Also, PD is not capable of "CommunicationSecurity" if I read this correctly
>python osdp_fw_update.py 192.168.3.145 1 sq80.osdp --loglevel=7
pyosdp: 2024-08-16T19:45:18Z 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-16T19:45:18Z src/osdp_cp.c:682 [DEBUG] CMD: ID(61) REPLY: PDID(45)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:1229 [DEBUG] StateChange: [ID-Request] -> [Cap-Detect] (SC-Inactive)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'ContactStatusMonitoring' (1/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'OutputControl' (1/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'CardDataFormat' (3/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'LEDControl' (4/2)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'AudibleControl' (2/1)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'TextOutput' (0/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'TimeKeeping' (0/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'CheckCharacter' (1/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'CommunicationSecurity' (0/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'ReceiveBufferSize' (149/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'CombinedMessageSize' (149/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'SmartCard' (0/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'Reader' (0/1)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:459 [DEBUG] Reports capability 'Biometric' (0/0)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:682 [DEBUG] CMD: CAP(62) REPLY: PDCAP(46)
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:1205 [INFO ] Online; Without SC
OSDP: CP: PD-1: 2024-08-16T19:45:18Z src/osdp_cp.c:1229 [DEBUG] StateChange: [Cap-Detect] -> [Online] (SC-Inactive)
And I initialized scbk with 0 (not sure how to disable SC on CP side properly)
PDInfo(args.reader, channel, scbk=0, flags=[LibFlag.CapturePackets]),
Payload is not missing, it's 0x02 "rebooting now, expect full communications reset."
Right. I was replying from phone with text wraps :) There were some <MISSING>
tags so I assumed the payload part is just missing everywhere. I believe now this issue must be fixed.
And I initialized scbk with 0 (not sure how to disable SC on CP side properly)
Setting scbk to anything other than Bytes
type will cause CP to disable SC for that PD so this is fine (although it would be more idiomatic to set it to None
). As to why CP attempted to start a secure channel in spite this was a regression - more info in commit message of 485870b if you are curious why.
Great, works. It now goes offline immediately after the last FTSTAT
, waits 5min and re-inits correctly again.
Is the 5min configurable?
...
OSDP: CP: PD-1: 2024-08-17T09:26:48Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-17T09:26:48Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-17T09:26:48Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-17T09:26:48Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-17T09:26:48Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-17T09:26:49Z src/osdp_file.c:184 [INFO ] Stat_Decode: File transfer complete
OSDP: CP: PD-1: 2024-08-17T09:26:49Z src/osdp_cp.c:682 [DEBUG] CMD: FILETRANSFER(7c) REPLY: FTSTAT(7a)
OSDP: CP: PD-1: 2024-08-17T09:26:49Z src/osdp_cp.c:1317 [INFO ] Going offline due to request
OSDP: CP: PD-1: 2024-08-17T09:26:49Z src/osdp_cp.c:1214 [ERROR] Going offline for 300 seconds; Was in 'Online' state
OSDP: CP: PD-1: 2024-08-17T09:26:49Z src/osdp_cp.c:1229 [DEBUG] StateChange: [Online] -> [Offline] (SC-Inactive)
OSDP: CP: PD-1: 2024-08-17T09:31:49Z src/osdp_cp.c:1229 [DEBUG] StateChange: [Offline] -> [ID-Request] (SC-Inactive)
OSDP: CP: PD-1: 2024-08-17T09:31:49Z src/osdp_cp.c:682 [DEBUG] CMD: ID(61) REPLY: PDID(45)
OSDP: CP: PD-1: 2024-08-17T09:31:49Z src/osdp_cp.c:1229 [DEBUG] StateChange: [ID-Request] -> [Cap-Detect] (SC-Inactive)
...
LibOSDP-3.0.6 master (485870b)
That value (and other timeouts) comes from src/config.h.in and changes require the library to be rebuilt to take effect.
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
The update works, but I noticed that the library is not ending the transfer correctly.
The PD I have responds to the last packet with
FTSTAT
andFtStatusDetail = 2
(reboot, expect reset). But then the CP sends the last packet again, which the PD responds to with NACK (9) and the CP tears down the connection.I captured the communication using Wireshark, since I do use a Ethernet to RS485 converter:
You can see that the last two
FILETRANSFER
are shorter (as it's the end - I confirmed this looking at the data) and have identical payload. You can also see the lastFTSTAT
with detail2
.I guess this is an issue with the library and nothing I could have messed up?
This is the script I'm using:
Forgot to mention, I'm using the latest release
LibOSDP-3.0.6 master (cf675a0)