secStoreServer.c SetCurrSystem() 348 | Could not get the current system's hash. LE_NOT_FOUND

Legato Application Framework
1

Dear Legato ：
In the legato framework logs I see an EMR error on the securestorage that could be the root cause of the defect, can you please help check ?

log 1：

[0 syslog failed]<8>Aug 31 14:16:50 Legato: EMR | secStore[2019]/secStoreDaemon T=main | secStoreServer.c SetCurrSystem() 348 | Could not get the current system’s hash. LE_NOT_FOUND.

…

575050 2022/08/31 14:16:50.181977 53.4373 185 NAD SYS SYSL 0 log info verbose 1 [0 syslog failed]<14>Aug 31 12:16:50 Legato: INFO | supervisor[1737]/supervisor T=main | proc.c proc_SigChildHandler() 2077 | Process ‘secStore’ (PID: 2019) has exited with exit code 1.

log2：

20749 2022/05/31 16:23:57.844821 54.3338 167 NAD SYS SYSL 0 log info verbose 1 [0 syslog failed]<8>May 30 11:12:19 Legato: EMR | secStore[2042]/secStoreDaemon T=main | secStoreServer.c SetCurrSystem() 348 | Could not get the current system’s hash. LE_NOT_FOUND.

…

20758 2022/05/31 16:23:57.844821 54.3472 171 NAD SYS SYSL 0 log info verbose 1 [0 syslog failed]<14>May 30 11:12:19 Legato: INFO | supervisor[1773]/supervisor T=main | proc.c proc_SigChildHandler() 2077 | Process ‘secStore’ (PID: 2042) has exited with exit code 1.

I analyzed the Legato source code and seems that the issue is due to the initialization phase of secstore when an app is removed/installed.
In detail the false return of function system_Exists(int systemIndex) in the file system.c trigger the EMR error and the exit 1 of secstore.

le_result_t system_GetSystemHash(
…
if (system_Exists(systemIndex) == false)
{
return LE_NOT_FOUND;
}
…

Have you noticed any of these problems before? Please help analyze the logs/source code ， It would be better if you had a fix for this issue, and we look forward to your response, thank you very much！

2

what is the exact problem you encountered?
How to reproduce the issue?

3

the defect is secStore crash on boot and system will reboot.

16:23:57.844821 54.3338 167 NAD SYS SYSL 0 log info verbose 1 [0 syslog failed]<8>May 30 11:12:19 Legato: EMR | secStore[2042]/secStoreDaemon T=main | secStoreServer.c SetCurrSystem() 348 | Could not get the current system’s hash. LE_NOT_FOUND.
16:23:57.844821 54.3472 171 NAD SYS SYSL 0 log info verbose 1 [0 syslog failed]<14>May 30 11:12:19 Legato: INFO | supervisor[1773]/supervisor T=main | proc.c proc_SigChildHandler() 2077 | Process ‘secStore’ (PID: 2042) has exited with exit code 1.
16:23:57 54.4789 ERR [0 syslog failed]<10>May 30 11:12:20 Legato: CRT | supervisor[1773]/supervisor T=main | app.c app_SigChildHandler() 4061 | Process ‘secStore’ in app ‘secStore’ faulted: Restarting app.
16:23:57 54.4977 ERR [FappManager] [ HandleMiddlewareAppFault ] Middleware app secStore exited following to exit 1
16:23:57 54.4712 ERR [FappManager] [ secStore ] Faulted!
16:23:57 54.4789 ERR [0 syslog failed]<10>May 30 11:12:20 Legato: CRT | supervisor[1773]/supervisor T=main | app.c app_SigChildHandler() 4061 | Process ‘secStore’ in app ‘secStore’ faulted: Restarting app.
16:23:57 54.4977 ERR [FappManager] [ HandleMiddlewareAppFault ] Middleware app secStore exited following to exit 1
16:23:57 54.4977 ERR [FappManager] System will reboot

legato/framework/daemons/linux/updateDaemon/system.c updateDaemon.c
legato/platformAdaptor/qmi/src/ag35x/components/le_pa_secStore/pa_secStore.c
The two generated system_index are inconsistent,and the code flow diagram is as follows:

绘图6
绘图66702×5450 876 KB

I guess how the issue happened: legato (as a system) will increase the value of legato/systems/current/index by 1 and re-write to the index when there is app installing or removing. The code gets this index value twice: BEFORE and AFTER adding 1 to the value (x and x+1). Getting a different index in this action is the cause why this issue happened. we have to put it under high stress testing that can reproduce it.

4

did you try to “update --mark-good” after installing the application?

5

no, I didn’t do that

6

you can try that and see if it helps

7

hello jyijyi
“update --mark-good”
what is this statement for?

8

you can see here:

9

Hi jyijyi,

The following behaviour was observed from our testing that the first read in the lifecycle from securestorage takes around 10s

4828 2023/05/03 08:59:33.402780 37.2802 88 NAD SYS SYSL 0 log info verbose 1 [0 syslog failed]<14>May 3 08:59:31 Legato: INFO | secStore[2102]/le_pa_secStore T=main | pa_secStore.c pa_secStore_Read() 246 | secstore read, pathPtr is /secmwd/IDENTITY_CERT
14675 2023/05/03 08:59:43.995381 47.3453 5 NAD SECS APP 0 log info verbose 10 < 2222 : 0x7f6489b4 > Loaded 1606 byte(s) from secStore entry ' IDENTITY_CERT '

while next one take around 1s
14675 2023/05/03 08:59:43.995381 47.3453 5 NAD SECS APP 0 log info verbose 10 < 2222 : 0x7f6489b4 > Loaded 1606 byte(s) from secStore entry ' IDENTITY_CERT '
15817 2023/05/03 08:59:45.134724 48.9595 93 NAD SYS SYSL 0 log info verbose 1 [0 syslog failed]<14>May 3 08:59:43 Legato: INFO | secStore[2102]/le_pa_secStore T=main | pa_secStore.c pa_secStore_Read() 246 | secstore read, pathPtr is /secmwd/IDENTITY_CERT

Could you please help to explain in detail why first read takes 10s?

Thanks a lot!

BR,
Louis

10

does this application work for you?

11

Hi,

We don’t have issue with applications, just wanted to understand the process of pa_secStore_Read(), why would it take much longer to execute the first Read?

Could you kindly help to check?

BR,
Louis

12

with the hello5.rar sample app, do you see such issue?
which module are you using?
what FW are you using?
Do you see such problem only in new FW but not in old FW?
Is it systematically happening?

BTW, i don’t have source code of pa_secStore.c, you might need to contact distributor on this