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
138 stars 71 forks source link

cp: Improved busy reply handling #47

Closed dvucich closed 3 years ago

dvucich commented 3 years ago

This proposed change is to add detection and handling by the CP of a busy reply from a PD where the busy reply was sent with sequence number 0, as per the OSDP specification. Otherwise the busy reply would be rejected as having a "packet seq mismatch".

Also, the building of the osdp_CHLNG(0x76) command is modified to not perform the generation of random numbers each time the message is sent (or re-sent). Instead the random number generation is moved to osdp_sc_init(). Otherwise new random numbers could cause the challenge response to be rejected due to the PD possibly using the random numbers from a previously sent osdp_CHLNG command when it replied busy.

Previously the following timeout was used for both retrying commands and retrying to establish communications:

   #define OSDP_CMD_RETRY_WAIT_MS      (300 * 1000)

Two timeouts are now defined:

   #define OSDP_ONLINE_RETRY_WAIT_MS   (1000)
   #define OSDP_CMD_RETRY_WAIT_MS      (300)

Note that the default online retry timeout is significantly reduced to 1 second. The short timeout allows quickly retrying establishing the connection and often quickly succeeding. It's not known if there may be situations where this shorter timeout may be an issue.

The motivation for these changes came from working with a particular badge reader when it was configured for baud rates of 38400 and higher. At the higher baud rates, the badge reader would often reply with an osdp_BUSY(0x79) to an osdp_CHLNG(0x76). The following log snippet (where the first number on each line is a relative time stamp in seconds) shows the issue for one of the worst cases where it took a long time to recover:

593.139 OSDP: DEBUG: PD[0]: CP : CMD(61) REPLY(45)
593.196 OSDP: DEBUG: PD[0]: CP : CMD(62) REPLY(46)
593.309 OSDP: ERROR: PD[0]: PHY: packet seq mismatch 2/0
593.311 OSDP: INFO : PD[0]: CP : SC Failed. Set PD offline due to ENFORCE_SECURE
594.380 OSDP: ERROR: PD[0]: PHY: packet seq mismatch 0/2
595.447 OSDP: DEBUG: PD[0]: CP : CMD(61) REPLY(45)
595.506 OSDP: DEBUG: PD[0]: CP : CMD(62) REPLY(46)
595.622 OSDP: ERROR: PD[0]: PHY: packet seq mismatch 2/0
595.628 OSDP: INFO : PD[0]: CP : SC Failed. Set PD offline due to ENFORCE_SECURE
596.693 OSDP: ERROR: PD[0]: PHY: packet seq mismatch 0/2
597.753 OSDP: DEBUG: PD[0]: CP : CMD(61) REPLY(45)
597.811 OSDP: DEBUG: PD[0]: CP : CMD(62) REPLY(46)
597.927 OSDP: ERROR: PD[0]: PHY: packet seq mismatch 2/0
597.930 OSDP: INFO : PD[0]: CP : SC Failed. Set PD offline due to ENFORCE_SECURE
   .
   .
   .
682.870 OSDP: DEBUG: PD[0]: CP : CMD(61) REPLY(45)
682.928 OSDP: DEBUG: PD[0]: CP : CMD(62) REPLY(46)
683.039 OSDP: ERROR: PD[0]: PHY: packet seq mismatch 2/0
683.041 OSDP: INFO : PD[0]: CP : SC Failed. Set PD offline due to ENFORCE_SECURE
684.115 OSDP: ERROR: PD[0]: PHY: packet seq mismatch 0/2
685.185 OSDP: DEBUG: PD[0]: CP : CMD(61) REPLY(45)
685.244 OSDP: DEBUG: PD[0]: CP : CMD(62) REPLY(46)
685.368 OSDP: DEBUG: PD[0]: CP : CMD(76) REPLY(76)
685.472 OSDP: DEBUG: PD[0]: CP : CMD(77) REPLY(78)
685.489 OSDP: INFO : PD[0]: CP : SC Active

Following are the send/receive messages for when the first busy reply occurred:

593.243 OsdpUartSnd(1)  19: 530013000E0311017676A876FF5A45A8AA2C44
593.305 OsdpUartRcv(1)   8: 538008000479230B
593.309 OSDP: ERROR: PD[0]: PHY: packet seq mismatch 2/0
593.311 OSDP: INFO : PD[0]: CP : SC Failed. Set PD offline due to ENFORCE_SECURE

The following log snippet shows the behavior with the improved busy reply handling:

1079.080 OSDP: DEBUG: PD[0]: CP : CMD(61) REPLY(45)
1079.139 OSDP: DEBUG: PD[0]: CP : CMD(62) REPLY(46)
1079.252 OSDP: DEBUG: PD[0]: CP : CMD(76) REPLY(79)
1079.262 OSDP: INFO : PD[0]: CP : PD busy; retry last command
1079.609 OSDP: DEBUG: PD[0]: CP : CMD(76) REPLY(76)
1079.711 OSDP: DEBUG: PD[0]: CP : CMD(77) REPLY(79)
1079.714 OSDP: INFO : PD[0]: CP : PD busy; retry last command
1080.056 OSDP: DEBUG: PD[0]: CP : CMD(77) REPLY(78)
1080.074 OSDP: INFO : PD[0]: CP : SC Active

The following is a portion of the preceding log snippet with the send/receive messages included:

1079.186 OsdpUartSnd(1)  19: 530013000E03110176484ED0FF63FF2FB7DDEE
1079.249 OsdpUartRcv(1)   8: 538008000479230B
1079.252 OSDP: DEBUG: PD[0]: CP : CMD(76) REPLY(79)
1079.262 OSDP: INFO : PD[0]: CP : PD busy; retry last command
1079.579 OsdpUartSnd(1)  19: 530013000E03110176484ED0FF63FF2FB7DDEE
1079.603 OsdpUartRcv(1)  43: 53802B000E0312017600068E0000303030E43EFD17C6E5B8B74C497E97507DF87CD35A1405F26703E0C090
1079.609 OSDP: DEBUG: PD[0]: CP : CMD(76) REPLY(76)
1079.642 OsdpUartSnd(1)  27: 53001B000F03130177E761497D9E663F7D74BE19814C51BF00141A
1079.708 OsdpUartRcv(1)   8: 538008000479230B
1079.711 OSDP: DEBUG: PD[0]: CP : CMD(77) REPLY(79)
1079.714 OSDP: INFO : PD[0]: CP : PD busy; retry last command
1080.033 OsdpUartSnd(1)  27: 53001B000F03130177E761497D9E663F7D74BE19814C51BF00141A
1080.053 OsdpUartRcv(1)  27: 53801B000F031401787F4CC3281D3573D6F1F1B9EFB8EBBF8B49D2
1080.056 OSDP: DEBUG: PD[0]: CP : CMD(77) REPLY(78)