OSDP: ERROR: PD[0]: PHY: Invalid MAC; discarding SC

dman66 commented 3 years ago

Describe the bug Enabled SC with a commercial CP. Negotiates channel properly then fails and loops forever in failure mode.

Expected behavior Not sure what isn't working to be honest.

Observed behavior libosdp-1.5.0 [master (7190302+)] OSDP: WARN : PD[0]: PD: SCBK not provided. PD is in INSTALL_MODE OSDP: PD: Setup complete - libosdp-1.5.0 master (7190302+) OSDP: DEBUG: PD[0]: PD: CMD: ID(61) REPLY: PDID(45) OSDP: DEBUG: PD[0]: PD: CMD: CAP(62) REPLY: PDCAP(46) OSDP: DEBUG: PD[0]: PD: CMD: CHLNG(76) REPLY: CCRYPT(76) OSDP: DEBUG: PD[0]: PD: CMD: CHLNG(76) REPLY: CCRYPT(76) OSDP: DEBUG: PD[0]: PD: CMD: CHLNG(76) REPLY: CCRYPT(76) OSDP: DEBUG: PD[0]: PD: CMD: SCRYPT(77) REPLY: RMAC_I(78) OSDP: WARN : PD[0]: PD: SC Active with SCBK-D CP: CMD_ID: 5 OSDP: DEBUG: PD[0]: PD: CMD: KEYSET(75) REPLY: ACK(40)

OSDP: DEBUG: PD[0]: PD: CMD: ID(61) REPLY: PDID(45) OSDP: DEBUG: PD[0]: PD: CMD: CAP(62) REPLY: PDCAP(46) OSDP: DEBUG: PD[0]: PD: CMD: CHLNG(76) REPLY: CCRYPT(76) OSDP: DEBUG: PD[0]: PD: CMD: SCRYPT(77) REPLY: RMAC_I(78) OSDP: INFO : PD[0]: PD: SC Active OSDP: DEBUG: PD[0]: PD: CMD: LSTAT(64) REPLY: LSTATR(48) OSDP: INFO : PD[0]: PD: PD is not capable of handling CMD: BUZ(6a); Reply with NAK_CMD_UNKNOWN OSDP: DEBUG: PD[0]: PD: CMD: BUZ(6a) REPLY: NAK(41) OSDP: ERROR: PD[0]: PHY: seq-repeat/reply-resend not supported! OSDP: ERROR: PD[0]: PHY: seq-repeat/reply-resend not supported! OSDP: ERROR: PD[0]: PHY: Invalid MAC; discarding SC OSDP: ERROR: PD[0]: PHY: seq-repeat/reply-resend not supported! OSDP: ERROR: PD[0]: PHY: seq-repeat/reply-resend not supported! OSDP: ERROR: PD[0]: PHY: seq-repeat/reply-resend not supported! OSDP: ERROR: PD[0]: PHY: seq-repeat/reply-resend not supported! OSDP: ERROR: PD[0]: PHY: seq-repeat/reply-resend not supported! OSDP: ERROR: PD[0]: PHY: seq-repeat/reply-resend not supported!

pastebin with all debug turned on: https://pastebin.com/cVz5pf4x

Additional context OPENSSL_ROOT_DIR=/usr/local/opt/openssl cmake -DCONFIG_OSDP_PACKET_TRACE=ON -DCONFIG_OSDP_DATA_TRACE=ON .. Definitely building master, only disabled python in CMakeLists.txt

sidcha commented 3 years ago

Breaking it down using https://libosdp.gotomain.io/protocol/packet-structure.html

First the PD got a Buzzer command (6a) with sequence number 2

OSDP: PD[0]: Received [31] =>
    0000  ff 53 00 1e 00 0f 02 17  6a 44 42 91 b7 93 18 72  |.S......jDB....r|
    0016  6a 1a be fd 46 a1 af 04  1c a8 58 5a 21 a2 54     |j...F.....XZ!.T |

For which it replied with a NAK (41) with the same sequence number as the capability was not advertised.

OSDP: PD[0]: Sent [31] =>
    0000  ff 53 80 1e 00 0f 02 18  41 79 69 20 28 9c 79 80  |.S......Ayi (.y.|
    0016  57 24 a7 af f1 19 ad bd  d8 23 46 c9 3b 81 03     |W$.......#F.;.. |

After this transaction, the CP sent the same command with the same sequence number but with a different R-MAC (since the body of the command has changed).

OSDP: PD[0]: Received [31] =>
    0000  ff 53 00 1e 00 0f 02 17  6a 2e a3 32 28 a0 f0 7a  |.S......j..2(..z|
    0016  3f 7a 7f 9e df bb 83 ba  63 0c 2b eb ec ca c6     |?z......c.+.... |

One of two things may be happening:

CP thinks that the PD is currently busy so it is trying to resend the same command with the same sequence number. This is a spec violation since we sent a NAK and not a BUSY.
The CP is sending a different buzzer command but without the sequence number increment since it thinks the last command was unsuccessful so it can re-use the same sequence number (or it is a bug in the CP where the sequence number increment happens in the happy-code-path). Which is clearly wrong, but I'm not 100% sure if the spec explicitly forbids this (I'll have a look at it later tonight).

A bit more context of the CP would also help (such as model, maker, version, etc.,). Also a good time to kick off a communication with the CP developer with this information and your logs.

dman66 commented 3 years ago

I changed my PD to support buzzer and the problem goes away. What's more, they are also sending an LED command which I also do not support but NAK'ing that is handled OK.

It seems the CP really goes off once I NAK the buzzer.

CP is a Tyco iSTAR Edge G2 with firmware 6.8.5.22814.

sidcha commented 3 years ago

I cannot imagine a sane control flow that would lead to this behaviour :) It is still better to report this issue to Tyco and see if they fix it in future.

Since your issue is resolved, closing this one.

goToMain / libosdp

OSDP: ERROR: PD[0]: PHY: Invalid MAC; discarding SC #67