When PD continuously sends libosdp events w/o interruption, reader will get bus fault

[kkeevin123456]

Describe the bug
I would like to inquire about an issue where when my PD (Peripheral Device) continuously sends commands without interruption, the PD encounters this error and reboot. However, if the PD sends commands with a 1-second interval, there are no problems. I would like to ask how to resolve this issue or how can I debug with this error.

Log

[INFO] (pd_build_reply:895) SC Active
[ERROR] (pd_translate_event:171) Unknown event type 0
E: ***** BUS FAULT *****
E: Precise data bus error
E: BFAR Address: 0x32000a3
E: r0/a1: 0x20009df0 r1/a2: 0x20020150 r2/a3: 0x00000001
E: r3/a4: 0x032000a3 r12/ip: 0x20013d70 r14/lr: 0x0003d5dd
E: xpsr: 0x81000000
E: Faulting instruction address (r15/pc): 0x00066b9a
E: >>> ZEPHYR FATAL ERROR 25: Unknown error on CPU 0
E: Current thread: 0x2000ac20 (osdp_thread)
E: Halting system
*** Booting nRF Connect SDK v2.9.0-7787b2649840 ***
*** Using Zephyr OS v3.7.99-1f8f3dc29142 ***

[Elfving]

Hi,

And the log for when you do this with a one second interval doesn't include this "Unknown event type 0" log message either? Does increasing buffer sizes help?

You can also use addr2line on the 'Faulting instruction address' to determine the corresponding code line. You can do this by running the following line in an nRF Connect terminal in the project directory: 

arm-zephyr-eabi-addr2line -e build/zephyr/zephyr.elf 0x32000a3

Regards,

Elfving

[kkeevin123456]

HI~

1. My current reproduction method is to split a very long string into three smaller strings that comply with the osdp message maximum length limit, and send them to the CP through the osdp_pd_notify_event function in libosdp. When adjusted to one second, there are no errors at all.

[INFO] (command_callback:182) Receive a OSDP command: 7

[INFO] (handle_command:354) OSDP_CMD_MFG, vendor_code=13633936, command=9, length=4

Data [4] =>

    0000  9f 01 f5 ff                                       |....            |

[INFO] (handle_set_debug_mode:280) Received MFG command: set_debug_mode, processing...

[INFO] (handle_set_debug_mode:299) Decoded set_debug_mode_v1 version: 1, enabled: ON

[INFO] (set_debug_mode:88) Setting debug mode to: enabled

[INFO] (set_debug_mode_enabled:756) Setting Debug mode to enabled

[INFO] (send_debug_log:38) Sending debug log: Long test message: AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA

[INFO] (send_debug_log:83) Debug log sent successfully

[DEBUG] (pd_decode_command:661) CMD: MFG(80) REPLY: ACK(40)

[INFO] (leaky_bucket_work_handler:97) [leaky_bucket] Processing task type: 0, priority: 0, queue_size 3 -> 2

[INFO] (leaky_bucket_work_handler:105) [leaky_bucket] Sending event notification

[INFO] (leaky_bucket_work_handler:134) [leaky_bucket] Event notification completed

[INFO] (leaky_bucket_work_handler:97) [leaky_bucket] Processing task type: 0, priority: 0, queue_size 2 -> 1

[INFO] (leaky_bucket_work_handler:105) [leaky_bucket] Sending event notification

[INFO] (leaky_bucket_work_handler:134) [leaky_bucket] Event notification completed

[INFO] (leaky_bucket_work_handler:97) [leaky_bucket] Processing task type: 0, priority: 0, queue_size 1 -> 0

[INFO] (leaky_bucket_work_handler:105) [leaky_bucket] Sending event notification

[INFO] (leaky_bucket_work_handler:134) [leaky_bucket] Event notification completed


2. I followed the steps below to run arm-zephyr-eabi-addr2line, but I got ??:0 as the result. I tried to run this command when a bus fault occurred.

Step1: nrfutil toolchain-manager launch --shell
Step2: arm-zephyr-eabi-addr2line -e build/reader/zephyr/zephyr.elf 0x32000a3
Step3: I got this ??:0


3. Now I check other address, here is the all logs

[INFO] (command_callback:175) Receive a OSDP command: 7

[INFO] (handle_command:354) OSDP_CMD_MFG, vendor_code=13633936, command=9, length=4
Data [4] =>
0000 9f 01 f5 ff |.... |
[INFO] (handle_set_debug_mode:280) Received MFG command: set_debug_mode, processing...
[INFO] (handle_set_debug_mode:299) Decoded set_debug_mode_v1 version: 1, enabled: ON
[INFO] (set_debug_mode:93) Setting debug mode to: enabled
E: file open error (-2)
[ERROR] (get_config_value:269) Failed to open file /config/DEBUG_MODE_ENABLED: error -2
[INFO] (set_debug_mode_enabled:756) Setting Debug mode to enabled
[INFO] (send_debug_log:39) Sending debug log: Long test message: AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
[INFO] (send_debug_log:88) Debug log sent successfully
[DEBUG] (pd_decode_command:661) CMD: MFG(80) REPLY: ACK(40)
[INFO] (leaky_bucket_work_handler:97) [leaky_bucket] Processing task type: 0, priority: 0, queue_size 5 -> 4
[INFO] (leaky_bucket_work_handler:105) [leaky_bucket] Sending event notification
[INFO] (leaky_bucket_work_handler:129) [leaky_bucket] Event notification completed
[INFO] (leaky_bucket_work_handler:97) [leaky_bucket] Processing task type: 0, priority: 0, queue_size 4 -> 3
[INFO] (leaky_bucket_work_handler:105) [leaky_bucket] Sending event notification
[INFO] (leaky_bucket_work_handler:129) [leaky_bucket] Event notification completed
[INFO] (leaky_bucket_work_handler:97) [leaky_bucket] Processing task type: 0, priority: 0, queue_size 3 -> 2
[INFO] (leaky_bucket_work_handler:105) [leaky_bucket] Sending event notification
[INFO] (leaky_bucket_work_handler:129) [leaky_bucket] Event notification completed
[INFO] (leaky_bucket_work_handler:97) [leaky_bucket] Processing task type: 0, priority: 0, queue_size 2 -> 1
[INFO] (leaky_bucket_work_handler:105) [leaky_bucket] Sending event notification
E: ***** BUS FAULT *****
E: Precise data bus error
E: BFAR Address: 0xa2982e
E: r0/a1: 0x2000a15c r1/a2: 0x00000000 r2/a3: 0x00000c35
E: r3/a4: 0x00000000 r12/ip: 0x2001ba2c r14/lr: 0x0003dd3d
E: xpsr: 0x210000f4
E: Faulting instruction address (r15/pc): 0x000397f6
E: >>> ZEPHYR FATAL ERROR 25: Unknown error on CPU 0
E: Fault during interrupt handling

and here is all the address

(v2.9.0) sast@sast-Standard-PC-i440FX-PIIX-1996:~/synosrc/reader$ arm-zephyr-eabi-addr2line -e build/reader/zephyr/zephyr.elf 0xa2982e
??:0
(v2.9.0) sast@sast-Standard-PC-i440FX-PIIX-1996:~/synosrc/reader$ arm-zephyr-eabi-addr2line -e build/reader/zephyr/zephyr.elf 0x2000a15c
??:?
(v2.9.0) sast@sast-Standard-PC-i440FX-PIIX-1996:~/synosrc/reader$ arm-zephyr-eabi-addr2line -e build/reader/zephyr/zephyr.elf 0x00000000
??:0
(v2.9.0) sast@sast-Standard-PC-i440FX-PIIX-1996:~/synosrc/reader$ arm-zephyr-eabi-addr2line -e build/reader/zephyr/zephyr.elf 0x00000c35
??:0
(v2.9.0) sast@sast-Standard-PC-i440FX-PIIX-1996:~/synosrc/reader$ arm-zephyr-eabi-addr2line -e build/reader/zephyr/zephyr.elf 0x2001ba2c
??:0
(v2.9.0) sast@sast-Standard-PC-i440FX-PIIX-1996:~/synosrc/reader$ arm-zephyr-eabi-addr2line -e build/reader/zephyr/zephyr.elf 0x0003dd3d
/home/gitlab-runner/builds/kB7UTpSp/0/synology/reader/doorreader_mfg/libosdp/src/osdp_pd.c:91
(v2.9.0) sast@sast-Standard-PC-i440FX-PIIX-1996:~/synosrc/reader$ arm-zephyr-eabi-addr2line -e build/reader/zephyr/zephyr.elf 0x210000f4
??:0
(v2.9.0) sast@sast-Standard-PC-i440FX-PIIX-1996:~/synosrc/reader$ arm-zephyr-eabi-addr2line -e build/reader/zephyr/zephyr.elf 0x000397f6
/home/sast/ncs/v2.9.0/zephyr/kernel/mem_slab.c:229
(v2.9.0) sast@sast-Standard-PC-i440FX-PIIX-1996:~/synosrc/reader$ arm-zephyr-eabi-addr2line -e build/reader/zephyr/zephyr.elf 0x20009a78
/home/gitlab-runner/builds/kB7UTpSp/0/synology/reader/doorreader_mfg/bsp/src/bsp.c:48

E: Current thread: 0x20009a78 (usage_thread)
E: Halting system
*** Booting nRF Connect SDK v2.9.0-7787b2649840 ***
*** Using Zephyr OS v3.7.99-1f8f3dc29142 ***

[Elfving]

Compiler optimization must have optimized this out. Could you try optimizing for debug first? The simplest way to do this might be to check the corresponding box in VSC when editing the build configuration.

[kkeevin123456]

Sure, I can try to change my build config.

I also wrote the minimum reproducible code for this issue.
You need to run CP to send CMP_POLL, if you don't run cp, this bug will not happen.

namespace debug {
osdp_t *ctx = nullptr;
}

int OsdpSetup(const struct shell *shell)
{
int flags = 0;
uint8_t scbk[16] = {0};
uint8_t *p_scbk = nullptr;
int baud = 9600;
int address = 1;

shell_print(shell, "OSDP setup with baud=%d, address=%d\n", baud, address);

if (syno_config::get_scbk(scbk))
{
shell_print(shell, "Using SCBK: %s\n", syno_utility::to_hex_string(scbk, 16).c_str());
flags |= OSDP_FLAG_ENFORCE_SECURE; // Enable secure channel if SCBK is provided
p_scbk = scbk;
}
else
{
shell_print(shell, "No SCBK found in config");
flags |= OSDP_FLAG_INSTALL_MODE; // Install mode if no SCBK
p_scbk = nullptr;
}

char sn[128] = {0};
if (!anmw_get_serial_number(sn, sizeof(sn)))
{
anmw_log_error("Failed to get serial number\n");
return -1;
}

osdp_pd_cap cap[] = {
{OSDP_PD_CAP_CARD_DATA_FORMAT, 0x03, 0},
{OSDP_PD_CAP_READER_LED_CONTROL, 0x05, 1},
{OSDP_PD_CAP_READER_AUDIBLE_OUTPUT, 0x02, 1},
{(uint8_t)-1, 0, 0},
};

osdp_pd_info_t info_pd = {
.baud_rate = baud,
.address = address,
.flags = flags,
.id = {
.version = CONFIG_SYNO_READER_MODEL_VERSION,
.model = CONFIG_SYNO_READER_MODEL_NUMBER,
.vendor_code = 0xD00990,
.serial_number = syno_utility::get_serial_number(),
.firmware_version = syno_firmware::get_version_number_without_build(),
},
.cap = cap,
.scbk = p_scbk,
};

debug::ctx = osdp_pd_setup(&info_pd);

if (debug::ctx == nullptr)
{
anmw_log_error("osdp_pd_setup failed\n");
return -1;
}

shell_print(shell, "pd setup completed\n");

return 0;
}

static int cmd_send_osdp_event(const struct shell *shell, size_t argc, char **argv)
{
if (debug::ctx != nullptr) osdp_pd_teardown(debug::ctx);

int err = OsdpSetup(shell);
if (err < 0) {
shell_error(shell, "OSDP setup failed with error: %d\n", err);
return -1;
}

//std::unique_ptr<osdp_event> event = std::make_unique<osdp_event>();
osdp_event *event = (osdp_event *)k_malloc(sizeof(osdp_event));

uint8_t payload_data[OSDP_EVENT_MFGREP_MAX_DATALEN];
int data_len = 100;
memset(payload_data, 'A', data_len);

event->type = OSDP_EVENT_MFGREP;
event->mfgrep.vendor_code = 0xD00990;
event->mfgrep.command = 32;
event->mfgrep.length = data_len;
memcpy(event->mfgrep.data, payload_data, data_len);

err = osdp_pd_notify_event(debug::ctx, event);
err = osdp_pd_notify_event(debug::ctx, event);
err = osdp_pd_notify_event(debug::ctx, event);

shell_print(shell, "OSDP event sent with result: %d\n", err);

k_free(event);

return 0;
}

[Elfving]

Hi again, and sorry about the wait,

I realize that it might be best if you ask the zephyr community about this, as the OSDP subsystem is not really really made by Nordic. I see that we've also gotten other questions about OSDP on DevZone which have essentially just been forwarded to the zephyr discord.

You can ask about it here.

Regards,

Elfving

[kkeevin123456]

Sure,

I finally find the root cause today....

## enable C++ support

#CONFIG_CPP=y

## expect to be C++23

#CONFIG_STD_CPP2B=y

## standard C++ library

#CONFIG_GLIBCXX_LIBCPP=y

The root cause is I enable the cpp config in my project.

After I change my programming language from cpp to c, this bus fault will not happend again.

Do you have any idea of this root cause?

Regards,

Kevin