Raw card data not accepted after a few minutes in secure mode

[z8a]

My peripheral device emulates a card reader and is connected to an access control system. If I connect them using the secure channel it works and the access control read the 'cards'. After some minutes while the communication is still working the access control doesn't read the 'cards'. I'm sure the PD is sending the 'card'. This problem doesn't happen with not encrypted mode. It could be a problem of the access control but what do you think about it? In the standard documentation they tell that if there is an error the keys are destroyed but how the secure channel is restored?

[sidcha]

@z8a, can you provide the logs that the PD emmits with log level set to LOG_DEBUG and packet trace turned on (cmake -DCONFIG_OSDP_PACKET_TRACE=on). This would help narrowing down the issue.

On secure channel, If there is an error (timeout, MAC errors, other any other errors), the PD would discard the current session keys and expects the CP to restart the secure channel handshake process to establish new session keys. This new session is as good as any and there is not state retention between them (with the exception of SCBK, ofcourse).

[z8a]

My PD is a an embedded device so I've to dump the log to a free UART. May be is possible.

[sidcha]

My PD is a an embedded device so I've to dump the log to a free UART. May be is possible.

This can be done easily with LibOSDP. You can pass a logging function to to osdp_logger_init() that writes to your UART device.

See: https://github.com/goToMain/libosdp/blob/master/include/osdp.h#L710.

[sidcha]

Is this issue possibly a duplicate of #31 or is this a separate issue?

[z8a]

I'll verify if it's possible.

[z8a]

This is the log of the problem. What do you think?

OSDP: DEBUG;PD: CMD: 76 REPLY: 76 OSDP: DEBUG;PD: CMD: 77 REPLY: 78 OSDP: WARN ;PD: SC Active with SCBK-D OSDP: DEBUG;PD: CMD: 75 REPLY: 40 OSDP: DEBUG;PD: CMD: 76 REPLY: 76 OSDP: DEBUG;PD: CMD: 77 REPLY: 78 OSDP: INFO ;PD: SC Active OSDP: DEBUG;PHY: cmd for PD[0] discarded OSDP: DEBUG;PHY: cmd for PD[2] discarded OSDP: DEBUG;PHY: cmd for PD[3] discarded OSDP: DEBUG;PHY: cmd for PD[4] discarded OSDP: DEBUG;PHY: cmd for PD[5] discarded OSDP: DEBUG;PHY: cmd for PD[6] discarded OSDP: DEBUG;PHY: cmd for PD[7] discarded OSDP: DEBUG;PHY: cmd for PD[8] discarded OSDP: DEBUG;PHY: cmd for PD[9] discarded OSDP: DEBUG;PHY: cmd for PD[10] discarded OSDP: DEBUG;PHY: cmd for PD[11] discarded OSDP: DEBUG;PHY: cmd for PD[12] discarded OSDP: DEBUG;PHY: cmd for PD[13] discarded OSDP: DEBUG;PHY: cmd for PD[14] discarded OSDP: DEBUG;PHY: cmd for PD[15] discarded OSDP: DEBUG;PHY: cmd for PD[16] discarded OSDP: DEBUG;PHY: cmd for PD[17] discarded OSDP: ERROR;PHY: invalid MAC OSDP: ERROR;PHY: Received plain-text message in SC OSDP: DEBUG;PHY: cmd for PD[18] discarded OSDP: ERROR;PHY: Received plain-text message in SC OSDP: ERROR;PHY: Received plain-text message in SC OSDP: ERROR;PHY: Received plain-text message in SC OSDP: ERROR;PHY: Received plain-text message in SC

[sidcha]

This seems to be the issue:

OSDP: ERROR;PHY: invalid MAC
OSDP: ERROR;PHY: Received plain-text message in SC

The PD found the MAC to be invalid. At this point, the CP thinks it has lost secure channel but the PD doesn't think so. Due to this all further commands from the CP are in plain text while PD discards them as the security constraint is not met.

It is unclear why the MAC validation failed as a secure channel was established successfully just a little earlier. I do see one point of problem in LibOSDP: PD should probably discard it's secure channel on MAC failures. But this is only a side effect and unrelated to the the actual problem (MAC verification failure).

General questions:

• Does it happen repeatedly after a new SC is setup?
• Can you isolate this PD to that CP and check if this is still reproducible?
• Have you considered the possibility of a CP side bug?
• Can you debug on CP side too? If so, logs on CP side may point to some something.

[z8a]

• Does it happen repeatedly after a new SC is setup? It happens every time but after a variable time. I'm not sure but may be after a osdp_RAW answer with data.
  • Can you isolate this PD to that CP and check if this is still reproducible? I've tried with one library in Python but it seems that it has other problems.
  • Have you considered the possibility of a CP side bug? Yes, I've asked to my colleagues that are validating the firmware and I'm waiting for an answer. Now I'll send the error log.
  • Can you debug on CP side too? If so, logs on CP side may point to some something. No. I'll ask if is possible the enable a logger on the CP.

If I disconnect/reconnect the serial port the secure connection will be established again.

[sidcha]

It happens every time but after a variable time. I'm not sure but may be after a osdp_RAW answer with data.

You can turn on packet trace macro, LibOSDP will print the exact bytes it received on wire so you know exactly when it fails.

If I disconnect/reconnect the serial port the secure connection will be established again.

This is expected. When you disconnect the serial line, the PD experiences a timeout and the SC session is discarded so a new one can be established when you reconnect.

On a side note, if you are developing the CP internally, you can force the sequence number to 0 in a message that tries to restart communication to force the PD to discard the current SC session. LibOSDP's CP implementation does this and it has worked very well for me.

[sidcha]

@z8a, Any updates on this?

[z8a]

Today I've received a firmware update of the access control system but the problem is still there. Could you help me to find a way to understand if the 'Wrong MAC' is caused the CP of by the PD?

[sidcha]

When a SC is initialized, both CP and PD would have the same session keys (as both CP and PD were able to verify each others session key during SCRYPT and CCRYPT commands). After this if MAC validation fails, this can only mean that the S_MAC1 and S_MAC2 are not setup correctly. Take a look at osdp_compute_session_keys() and see if your CP firmware is doing the same thing.

Along with packet trace, printing pd->sc.scbk, pd->sc.s_enc, pd->sc.s_mac1, pd->sc.s_mac2 in CP and PD before every transaction and manually auditing the logs to check if they are equal can help narrow down the issue.

[z8a]

In your project is possible to build a CP to run it on a Linux PC?

[sidcha]

In your project is possible to build a CP to run it on a Linux PC?

Of course. Check out the python wrapper for LibOSDP (samples/python/cp_app.py). You have to do a make python_install before you can import osdp.

[z8a]

Is possible to send a osdp_POLL command with cp_app.py?

[sidcha]

cp.refresh() would internally send osodp_POLL command. There is no way in LibOSDP to send a poll command from application layer as there is no need to do so. If the PD reports a card read, you will get a callback event that will call this function.

[z8a]

Now I've 'PD' (my hardware) and 'CP' (your python example) working together. Please could you explain me how works cp_app.py? What about secure channel? Before start it have I to put the 'PD' in setup/install mode? After a 'OSDP: ERROR: PD[0]: CMD: 60 - response timeout' it stop to communicate. I've to solve this problem but in real world it could happen so there should be a system to restore automatically the communication. At the moment I haven't seen any 'invalid MAC' error.

[sidcha]

Now I've 'PD' (my hardware) and 'CP' (your python example) working together. Please could you explain me how works cp_app.py?

You cannot directly use that example as it is meant for API demonstration purpose only. You should modify the pd_info dict to describe the connected PDs and then modify the key variable to your master key. You can set the loglevel to 7 to see more verbose logginig.

What about secure channel? Before start it have I to put the 'PD' in setup/install mode?

The CP will automatically try to setup a secure channel if the PD is capable of doing so. You do not need to do anything about this. If the secure channel fails, the CP will also try to re-establish the SC after a defined timeout (see src/osdp_config.h.in).

For the first time the CP is going to communicate to the PD, the PD has to be put to install mode. This SHOULD NOT be done in each boot.

After a 'OSDP: ERROR: PD[0]: CMD: 60 - response timeout' it stop to communicate. I've to solve this problem but in real world it could happen so there should be a system to restore automatically the communication.

The CP will retry communication after a prefefined timeout in case of a command timeout. See src/osdp_config.h.in.

[z8a]

I've solved a timeout problem caused by interrupt latency and I hope it'll solve also the original problem. I'd like to change the retry time in your CP panel implementation but I'm not able to change it. I've changed OSDP_PD_RETRY_MS and OSDP_CMD_RETRY_MS in src/osdp_config.h.in, then cmake .., make, sudo make install, sudo make python_install but I don't see any modification.

[z8a]

I've not understood how your CP is able to setup a secure channel after first time and with PD not in install mode. Does it save the key in some place?

[sidcha]

I've not understood how your CP is able to setup a secure channel after first time and with PD not in install mode. Does it save the key in some place?

The master key is in the source file cp_app.py. This key is used to generate the SCBK and the session keys. On the PD side, the SCBK is stored on the device and passed at osdp_setup_pd().

I've changed OSDP_PD_RETRY_MS and OSDP_CMD_RETRY_MS in src/osdp_config.h.in, then cmake .., make, sudo make install, sudo make python_install but I don't see any modification.

That's strange. In the directory from where you invoked cmake, check if there is a file src/osdp_config.h and see if it has the values that you modified. If not, remove this file and run make again. Also run sudo make python_uninstall and then sudo make python_install to reinstall python.

[z8a]

Retry timeouts are OK. I've rebuilt all and now it's OK. I've already done but something was wrong. I've seen that the python example can recover from timeout errors so I think the original problem is caused by Access Control system that cannot recover from the timeout of a single communication while if I disconnect and reconnect the RS485 cable it is able to recover. About secure channel I'm still not able to understand while only for the first connection is necessary to put the PD in install mode. I think you save the master key on disk. Is it true?

[sidcha]

I've not understood how your CP is able to setup a secure channel after first time and with PD not in install mode. Does it save the key in some place?

The master key is in the source file cp_app.py. This key is used to generate the SCBK and the session keys. On the PD side, the SCBK is stored on the device and passed at osdp_setup_pd().

Have you seen this?

[z8a]

Yes. I thought that both CP and PD have to store the SCBK.

[sidcha]

The CP has to Store the Master Key. The PD must Store the SCBK. In your setup, the PD hardware is storing the SCBK in some non-volatile memory and the CP has the master key in the python source file so the secure channel is re-established without the need to put the PD in install mode after the first time.

[sidcha]

@z8a, you can reopen this issue if you need more information.