onomondo / nrf-softsim

Manifest repo for integrating SoftSIM and nrf-sdk
30 stars 6 forks source link

Soft SIM LittleFS Backend #30

Open optical-o opened 8 months ago

optical-o commented 8 months ago

Hello, i'm reaching out like this because all inquires though onomondo email are met with deaf ear.

We are ready to integrate the Onomondo Softsim and we are willing to make the thing work on our own also to contribute into this repository. All i need is your initial code for LittleFS backend you told you have and also the script that created the provisioning template that so we can retrofit older devices that do not have the provision hex included.

@peterbornerup

peterbornerup commented 8 months ago

Hi there,

https://github.com/onomondo/nrf-softsim/pull/31

I've started a pr to track the work.

First commit contains all the files that is included in softsim by default. I've dug up an old scripts that reads the directory, writes to a littlefs partition and dumps it into a .bin file.

The generated image needs to be adjusted to match your partition size (set the number of blocks accordingly).

peterbornerup commented 8 months ago

@optical-o there are some concerns with some relatively heavy writes.

Internally some data will be dumped to flash byte-by-byte instead of one write. Haven't looked through the littlefs source but I'm assuming that the writes are buffered and not committed to flash until the file is closed.

The original implementation is most like lost. It was made 1 year+ ago and there has been quite a lot of iterations since.

optical-o commented 8 months ago

@peterbornerup Do you have some access example or typical example that the SoftSim is calling the API ? So i know how many files can be opened and etc. Whether the SoftSim is correctly closing all of the files when the modem is shuting down.

peterbornerup commented 8 months ago

filelog.txt Sure thing!

I've made a build that runs locally on my machine. This is basically a full 'replay' of what has happened on a device at some point.

Please note that STORAGE ERROR OPENING FILE: ../../../files/3f00/a003

should be read as STORAGE INFO OPENING FILE: "/3f00/a003"

etc. had to set a hard log level to supress other stuff. Lastly, the actual path "prefix" can be adjusted as well. I'm assuming the "/" is OK for now

peterbornerup commented 8 months ago

As you can see there are a few frequently visited files. In the NVS implementation these are cached to avoid slow flash reads. You could consider caching the 4-5 most frequently visited files (those are pretty much never changing btw)

optical-o commented 7 months ago

I have created first working implementation without any optimization here: https://github.com/dronetag/nrf-softsim

Had to rebase to support NCS 2.5.2. The branch is called the same as here: enable-little-fs-backend

Build step for static profile. Sotred in separate config file: overlay-profile.conf

west build -b nrf9160dk_nrf9160_ns -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-littlefs.conf;overlay-profile.conf" 

What is the usual way how you test the SoftSim functionality as a whole ? To verify that it will not fail in certain situations ?

optical-o commented 7 months ago

I haven't look thoroughly at the NVS storage implementation but it seems that the same way how i initialized the Filesystem for the FS_BACKEND the same thing can be done for the NVS ? Do i overlook something there ?

optical-o commented 7 months ago

Attaching the ROM footprint of the static files:

│   │           │   └── scripts                                                                  4815   3.44%
│   │           │       └── ss_static_files.c                                                    4815   3.44%
│   │           │           ├── _3f00_2f00                                                         76   0.05%
│   │           │           ├── _3f00_2f00_def                                                     28   0.02%
│   │           │           ├── _3f00_2f05                                                         10   0.01%
│   │           │           ├── _3f00_2f05_def                                                     25   0.02%
│   │           │           ├── _3f00_2f06                                                        640   0.46%
│   │           │           ├── _3f00_2f06_def                                                     28   0.02%
│   │           │           ├── _3f00_2f08                                                          5   0.00%
│   │           │           ├── _3f00_2f08_def                                                     25   0.02%
│   │           │           ├── _3f00_2fe2                                                         10   0.01%
│   │           │           ├── _3f00_2fe2_def                                                     25   0.02%
│   │           │           ├── _3f00_5f100001                                                     62   0.04%
│   │           │           ├── _3f00_5f100001_def                                                 18   0.01%
│   │           │           ├── _3f00_7ff0_5f100001                                                62   0.04%
│   │           │           ├── _3f00_7ff0_5f100001_def                                            18   0.01%
│   │           │           ├── _3f00_7ff0_6f05                                                    10   0.01%
│   │           │           ├── _3f00_7ff0_6f05_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6f06                                                   640   0.46%
│   │           │           ├── _3f00_7ff0_6f06_def                                                28   0.02%
│   │           │           ├── _3f00_7ff0_6f07                                                     9   0.01%
│   │           │           ├── _3f00_7ff0_6f07_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6f08                                                    33   0.02%
│   │           │           ├── _3f00_7ff0_6f08_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6f09                                                    33   0.02%
│   │           │           ├── _3f00_7ff0_6f09_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6f31                                                     1   0.00%
│   │           │           ├── _3f00_7ff0_6f31_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6f38                                                    15   0.01%
│   │           │           ├── _3f00_7ff0_6f38_def                                                24   0.02%
│   │           │           ├── _3f00_7ff0_6f42                                                   104   0.07%
│   │           │           ├── _3f00_7ff0_6f42_def                                                27   0.02%
│   │           │           ├── _3f00_7ff0_6f5b                                                     6   0.00%
│   │           │           ├── _3f00_7ff0_6f5b_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6f5c                                                     3   0.00%
│   │           │           ├── _3f00_7ff0_6f5c_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6f73                                                    14   0.01%
│   │           │           ├── _3f00_7ff0_6f73_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6f78                                                     2   0.00%
│   │           │           ├── _3f00_7ff0_6f78_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6f7b                                                    12   0.01%
│   │           │           ├── _3f00_7ff0_6f7b_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6f7e                                                    11   0.01%
│   │           │           ├── _3f00_7ff0_6f7e_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6fad                                                     4   0.00%
│   │           │           ├── _3f00_7ff0_6fad_def                                                24   0.02%
│   │           │           ├── _3f00_7ff0_6fb7                                                    80   0.06%
│   │           │           ├── _3f00_7ff0_6fb7_def                                                28   0.02%
│   │           │           ├── _3f00_7ff0_6fc4                                                    64   0.05%
│   │           │           ├── _3f00_7ff0_6fc4_def                                                24   0.02%
│   │           │           ├── _3f00_7ff0_6fe3                                                    18   0.01%
│   │           │           ├── _3f00_7ff0_6fe3_def                                                25   0.02%
│   │           │           ├── _3f00_7ff0_6fe4                                                    54   0.04%
│   │           │           ├── _3f00_7ff0_6fe4_def                                                28   0.02%
│   │           │           ├── _3f00_7ff0_def                                                     36   0.03%
│   │           │           ├── _3f00_a001                                                         33   0.02%
│   │           │           ├── _3f00_a001_def                                                     24   0.02%
│   │           │           ├── _3f00_a003                                                         66   0.05%
│   │           │           ├── _3f00_a003_def                                                     27   0.02%
│   │           │           ├── _3f00_a004                                                        114   0.08%
│   │           │           ├── _3f00_a004_def                                                     27   0.02%
│   │           │           ├── _3f00_a005                                                         33   0.02%
│   │           │           ├── _3f00_a005_def                                                     27   0.02%
│   │           │           ├── _3f00_a100                                                          8   0.01%
│   │           │           ├── _3f00_a100_def                                                     24   0.02%
│   │           │           ├── _3f00_a101                                                          8   0.01%
│   │           │           ├── _3f00_a102                                                          8   0.01%
│   │           │           ├── _3f00_a103                                                          8   0.01%
│   │           │           ├── _3f00_a104                                                          8   0.01%
│   │           │           ├── _3f00_a105                                                          8   0.01%
│   │           │           ├── _3f00_a106                                                          8   0.01%
│   │           │           ├── _3f00_a107                                                          8   0.01%
│   │           │           ├── _3f00_a108                                                          8   0.01%
│   │           │           ├── _3f00_a109                                                          8   0.01%
│   │           │           ├── _3f00_a10a                                                          8   0.01%
│   │           │           ├── _3f00_a10b                                                          8   0.01%
│   │           │           ├── _3f00_a10c                                                          8   0.01%
│   │           │           ├── _3f00_a10d                                                          8   0.01%
│   │           │           ├── _3f00_a10e                                                          8   0.01%
│   │           │           ├── _3f00_a10f                                                          8   0.01%
│   │           │           ├── _3f00_a110                                                          8   0.01%
│   │           │           ├── _3f00_a111                                                          8   0.01%
│   │           │           ├── _3f00_a112                                                          8   0.01%
│   │           │           ├── _3f00_a113                                                          8   0.01%
│   │           │           ├── _3f00_a114                                                          8   0.01%
│   │           │           ├── _3f00_a115                                                          8   0.01%
│   │           │           ├── _3f00_a116                                                          8   0.01%
│   │           │           ├── _3f00_a117                                                          8   0.01%
│   │           │           ├── _3f00_a118                                                          8   0.01%
│   │           │           ├── _3f00_a119                                                          8   0.01%
│   │           │           ├── _3f00_a11a                                                          8   0.01%
│   │           │           ├── _3f00_a11b                                                          8   0.01%
│   │           │           ├── _3f00_a11c                                                          8   0.01%
│   │           │           ├── _3f00_a11d                                                          8   0.01%
│   │           │           ├── _3f00_a11e                                                          8   0.01%
│   │           │           ├── _3f00_a11f                                                          8   0.01%
│   │           │           ├── _3f00_a120                                                          8   0.01%
│   │           │           ├── _3f00_a1df1d01                                                    288   0.21%
│   │           │           ├── _3f00_a1df1d01_def                                                 19   0.01%
│   │           │           ├── _3f00_def                                                          29   0.02%
│   │           │           └── onomondo_sf_files_arr                                            1176   0.84%
peterbornerup commented 7 months ago

I haven't look thoroughly at the NVS storage implementation but it seems that the same way how i initialized the Filesystem for the FS_BACKEND the same thing can be done for the NVS ? Do i overlook something there ?

Yes - very similar. Some fiddling around with file_name > id mapping. Nothing big - we just haven't gotten around to do it.

peterbornerup commented 7 months ago

https://github.com/dronetag/nrf-softsim/blob/09d294bb7c95fc640120a8199f72a8c1327cd77c/lib/ss_fs.c#L126

should technically return rc/size - otherwise it can fail in some cases

optical-o commented 7 months ago

https://github.com/dronetag/nrf-softsim/blob/09d294bb7c95fc640120a8199f72a8c1327cd77c/lib/ss_fs.c#L126

should technically return rc/size - otherwise it can fail in some cases

So the return is the number of elements ? If i understand correctly ?

Scratch that in the comment above it is clearly witten :)

peterbornerup commented 7 months ago

https://github.com/dronetag/nrf-softsim/blob/09d294bb7c95fc640120a8199f72a8c1327cd77c/lib/ss_fs.c#L130

Had a second look in libstorage - I've previously removed all references to this one - so it can be omitted.

Earlier builds stored everything as hex strings instead of the raw data - good for debugging. At some point we switched to binary format and dropped all references to fgets.

How big is the overhead of adding directories in littleFS? We can technically use a different separator and keep a flat structure. If it doesn't free up space then it better to stick to the current implementation.

optical-o commented 7 months ago

https://github.com/dronetag/nrf-softsim/blob/09d294bb7c95fc640120a8199f72a8c1327cd77c/lib/ss_fs.c#L130

Had a second look in libstorage - I've previously removed all references to this one - so it can be omitted.

Earlier builds stored everything as hex strings instead of the raw data - good for debugging. At some point we switched to binary format and dropped all references to fgets.

How big is the overhead of adding directories in littleFS? We can technically use a different separator and keep a flat structure. If it doesn't free up space then it better to stick to the current implementation.

Not sure how much space can be saved by this, however i think it should not be necessary. It will be just few metablocks so the effect will be minimal.

This implementation should be also compatible with ANY filesystem that is supported by the zephyr. So it is not a littlefs specific thing.

peterbornerup commented 7 months ago

Ah completely missed that!! Nice nice nice.

optical-o commented 7 months ago

Is there a possibility that slow reaction of the external flash might interfere with the ability of the modem to connect into the network ?

I manage to connect to the network using the nrf9160 with internal flash used as LITTLEFS the external flash is significantly slower due to the 8Mhz limit on the SPI. However the modem is not establishing a connection when used with the external flash.

optical-o commented 7 months ago

I have noticed that i received the XSIM notification after a CEREG notification which should signal that the modem tried to access the SIM Card after connection to the network. Which is rather odd. image

optical-o commented 7 months ago

I have look at the accesses to the flash and indeed the SoftSim is accessing a lot of files and it takes 15s to initialize i will try to look at it whether a caching will help in this case.

optical-o commented 7 months ago

From the log i see that the nRF91 was in the RESET LOOP. https://infocenter.nordicsemi.com/index.jsp?topic=%2Fnwp_042%2FWP%2Fnwp_042%2Factivation.html Which prevent device from attaching to the network.

I have added the Template generation code to the NVS storage to verify its speed against the Little FS. The NVS with external flash is thanks to the cache fast enough loading bellow 2s. It si currently functional.

I also added option to specify the NVS partition using device tree and added the sector size detection from the flash_map.

peterbornerup commented 7 months ago

Hi there,

I'm out of office until next Monday.

Glad you got it working - we are currently working on a more generic caching layer - that should be something we can add later though.

/Peter S. Bornerup


From: Tomáš Beneš @.> Sent: Saturday, February 10, 2024 4:27:04 PM To: onomondo/nrf-softsim @.> Cc: Peter S. Bornerup @.>; Mention @.> Subject: Re: [onomondo/nrf-softsim] Soft SIM LittleFS Backend (Issue #30)

From the log i see that the nRF91 was in the RESET LOOP. https://infocenter.nordicsemi.com/index.jsp?topic=%2Fnwp_042%2FWP%2Fnwp_042%2Factivation.html Which prevent device from attaching to the network.

I have added the Template generation code to the NVS storage to verify its speed against the Little FS. The NVS with external flash is thanks to the cache fast enough loading bellow 2s. It si currently functional.

I also added option to specify the NVS partition using device tree and added the sector size detection from the flash_map.

— Reply to this email directly, view it on GitHubhttps://github.com/onomondo/nrf-softsim/issues/30#issuecomment-1937043689, or unsubscribehttps://github.com/notifications/unsubscribe-auth/ALCWC4IGEGF26FEM2BOBXLTYS6GURAVCNFSM6AAAAABC3OELN2VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSMZXGA2DGNRYHE. You are receiving this because you were mentioned.Message ID: @.***>

optical-o commented 7 months ago

FIY the NVS Storage in zephyr already has built in caching functionality.

The LittleFS the same. I will try to use the FS cache capability if it can handle the repeated access to the few files.

optical-o commented 7 months ago

I have added a FS Layer that can keep the files open i 'r' mode to seek to beginning them instead closing them. This way the LittleFS caching can be applied. It dramatically reduces the RAM usage of the SoftSIM.

Hardware SIM -> XSIM: 1 - 1.4s SoftSIM NVS -> XSIM: 1 - 2.5s SoftSIM LittleFS External Flash Cache -> XSIM: 1 - 4s SoftSIM LittleFS External Flash -> XSIM: 1 - 15s

I have verified that the LittleFS implementation is working on the nrf9160dk with internal flash. However the implementation using the External Flash is not connecting to the network resulting in XSIM: 0,9 and CEREG: 90.

I will attach the log of the AT notifications later.

optical-o commented 7 months ago

Just for completeness so we don't forget the python script creating the NVS keys does not have any logic it should be replicated from your python that was used to generate the template.

Keys currently does not honor your intended flags when generated from code. entry->_flags = (id & 0xFF00) >> 8;

optical-o commented 7 months ago

I have extracted the caching logic from the nvs backend. The use still remains there due to the functionality of mapping paths to nvs keys.

I cleaned up and extended the functionality of the cache and added a layer between the port_fs and the actual storage backend (nvs, fs). It is usable only for the fs but it can be compiled with both.

On the nrf9160dk the combination of the caching and the filesystem is working correctly i will proceed with testing it with the external flash.

I would suggest tu arrange a call next week so we an properly test the implementation and discuss possibility of mergin the code or what can you actually use.

optical-o commented 7 months ago

I have added a FS Layer that can keep the files open i 'r' mode to seek to beginning them instead closing them. This way the LittleFS caching can be applied. It dramatically reduces the RAM usage of the SoftSIM.

Hardware SIM -> XSIM: 1 - 1.4s SoftSIM NVS -> XSIM: 1 - 2.5s SoftSIM LittleFS External Flash Cache -> XSIM: 1 - 4s SoftSIM LittleFS External Flash -> XSIM: 1 - 15s

I have verified that the LittleFS implementation is working on the nrf9160dk with internal flash. However the implementation using the External Flash is not connecting to the network resulting in XSIM: 0,9 and CEREG: 90.

I will attach the log of the AT notifications later.

Just keeping the issue up to date with the state of the implementation. The problem still remains even with the caching layer.

[00:01:08.752,000] <inf> dt_modem: Notif: +CEREG: 2,"C15D","000BF821",9,0,13
[00:01:08.786,000] <inf> dt_modem: Notif: +CSCON: 0
[00:01:09.011,000] <inf> dt_modem: Notif: %CESQ: 255,0,255,0
[00:01:09.011,000] <inf> dt_modem: Notif: %XSNRSQ: 127,0,32767,255
[00:01:09.111,000] <inf> dt_modem: Notif: +CEREG: 2
[00:01:12.428,000] <inf> dt_modem: Notif: %CESQ: 57,2,15,2
[00:01:12.429,000] <inf> dt_modem: Notif: %XSNRSQ: 23,1,184,0
[00:01:12.429,000] <inf> dt_modem: Notif: +CEREG: 2,"2B88","09482D56",9
[00:01:12.752,000] <inf> dt_modem: Notif: %CESQ: 57,2,21,3
[00:01:13.078,000] <inf> dt_modem: Notif: %XSNRSQ: 26,2,184,0
[00:01:13.238,000] <inf> dt_modem: Notif: +CSCON: 1
[00:01:13.352,000] <inf> dt_modem: Notif: +CEREG: 2,"2B88","09482D56",9,0,15
[00:01:13.451,000] <inf> dt_modem: Notif: +CSCON: 0
[00:01:13.801,000] <inf> dt_modem: Notif: %CESQ: 255,0,255,0
[00:01:13.801,000] <inf> dt_modem: Notif: %XSNRSQ: 127,0,32767,255
[00:01:13.801,000] <inf> dt_modem: Notif: +CEREG: 2
[00:01:20.695,000] <inf> dt_mgmt: System heap Alloc: 9680, Free: 19544
[00:01:23.899,000] <inf> dt_modem: Notif: %CESQ: 50,2,15,2
[00:01:23.999,000] <inf> dt_modem: Notif: %XSNRSQ: 27,2,161,0
[00:01:23.999,000] <inf> dt_modem: Notif: +CEREG: 2,"0478","09482D51",7
[00:01:24.530,000] <inf> dt_modem: Notif: +CSCON: 1
[00:01:24.535,000] <inf> dt_modem: Notif: %CESQ: 44,2,11,1
[00:01:29.598,000] <inf> dt_modem: Notif: +CEREG: 0
[00:01:29.598,000] <inf> dt_modem: Notif: %MDMEV: SEARCH STATUS 2
[00:01:29.741,000] <inf> dt_modem: Notif: %XSNRSQ: 24,2,159,0
[00:01:29.753,000] <inf> dt_modem: Notif: +CEREG: 90
[00:01:29.754,000] <inf> dt_modem: Notif: %XSIM: 0,9
optical-o commented 7 months ago

I have prepared three configurations on the nrf9160dk revision > 0.1.4. So they can be easily tested.

Refactored NVS configuration - Working LittleFS + Cache - Working LittleFS External + Cache - Not working ending with +CEREG: 90

west build -b nrf9160dk_nrf9160_ns@1.0.0 -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-nvs.conf;overlay-profile.conf"
west build -b nrf9160dk_nrf9160_ns@1.0.0 -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-littlefs.conf;overlay-profile.conf"
west build -b nrf9160dk_nrf9160_ns@1.0.0 -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-littlefs.conf;overlay-profile.conf;prj-littlefs-external.conf"

Additionally i have tested: Refactored NVS External configuration - Working (Tested not prepared for compilation)

peterbornerup commented 7 months ago

FIY the NVS Storage in zephyr already has built in caching functionality.

The LittleFS the same. I will try to use the FS cache capability if it can handle the repeated access to the few files.

Yeah I looked into that as well. The main difference is that we can cache non essential writes. For networks where PSM and/or eDRX is fully supported the device could technically stay on for long periods without the need to commit anything to flash but rather keep file updates in RAM.

The flags were introduced to make sure sequence numbers were correctly updated as these are more critical. If the power is lost the device could be susceptible to replay attacks where a 'fake' base station could send the same authentication challenge to the device and have it register on that one.

Other updates (such as writes to the EF_LOCI file) are nice to have but not super critical. The EF_LOCI help speed up the next attach - but the device/"sim" won't break if it isn't commited

peterbornerup commented 7 months ago

I have verified that the LittleFS implementation is working on the nrf9160dk with internal flash. However the implementation using the External Flash is not connecting to the network resulting in XSIM: 0,9 and CEREG: 90.

I don't have a device with external flash unfortunately so I won't be able to test locally.

It could be beneficial to enable the softsim apdu dump (enabled with the loglevel set to debug). This makes the execution slightly slower I think - but usually it doesn't interfere too much. At least we'll be able to verify that the commands are executed correctly.

peterbornerup commented 7 months ago

I have prepared three configurations on the nrf9160dk revision > 0.1.4. So they can be easily tested.

Refactored NVS configuration - Working LittleFS + Cache - Working LittleFS External + Cache - Not working ending with +CEREG: 90

west build -b nrf9160dk_nrf9160_ns@1.0.0 -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-nvs.conf;overlay-profile.conf"
west build -b nrf9160dk_nrf9160_ns@1.0.0 -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-littlefs.conf;overlay-profile.conf"
west build -b nrf9160dk_nrf9160_ns@1.0.0 -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-littlefs.conf;overlay-profile.conf;prj-littlefs-external.conf"

Additionally i have tested: Refactored NVS External configuration - Working (Tested not prepared for compilation)

Can you note down the time + ICCID next time you test with external flash?

I'll check the signalling on our platform for that timeframe.

I've noticed that the SIM is rejected if the authentication goes wrong. So - if you can read the ICCID with AT commands I think we can conclude that the SIM initialized correctly. But if the authentication goes haywire it is flagged as malfunctioning. That is probably why you get the ERR after device is communicating with the network.

Stuff to consider:

Again, if we dump some APDUs we'll probably be able to infer a lot of this as well

peterbornerup commented 7 months ago

Just for completeness so we don't forget the python script creating the NVS keys does not have any logic it should be replicated from your python that was used to generate the template.

Keys currently does not honor your intended flags when generated from code. entry->_flags = (id & 0xFF00) >> 8;

I'll see if I can find the original scripts. The keys/files are ordered after cache hit rate. In that way we could optimize the access as there would be a cache hit within 3-4 lookup :)

optical-o commented 7 months ago

@peterbornerup Here is tjhe APDU log the test was performed around 15:40 20.02 CET.

I hope sharing log with a test sim is OK and nothing is important is exposed.

ICCID is at the bottom of the log. Read out using the AT%XICCID

softsim.log

optical-o commented 7 months ago

Note that the LittleFS configuration is working using the internal flash. The only difference is that the LittleFS partition is moved to an external flash.

So i presume that all of the keys should be working internally the same. Tomorrow i can investigate if this does not indeed interfere with the TFM in some way. However i would presume that the psa_crypto would report some kind of error that would result in fail in SoftSim initialization.

optical-o commented 7 months ago

Just to have complete record also test 15:56 20.02 CET. LittleFS using internal flash.

softsim-internal.log

The same ICCID as the other log using external flash. So you can compare the APDU frames and the difference between them.

peterbornerup commented 7 months ago
[00:00:22.961,486] <inf> softsim_sample: RRC mode: Connected

[00:00:23.452,209] <dbg> softsim: softsim_req_task: SoftSIM APDU request
                                  00 88 00 81 22 10 59 1c  58 51 25 9f 7d 95 15 8e |....".Y. XQ%.}...
                                  cb ef 64 69 37 ab 10 51  40 f7 b2 82 80 90 01 37 |..di7..Q @......7
                                  5d 0a 70 1a 15 3f 2e 00                          |].p..?..         
+CEREG: 0

So the 00 88 00 81 LEN DATA[LEN] is the authenticate command - essentially authenticating the network and authenticating towards the network.

It looks like something goes wrong in that process. This command eventually invokes the aes_encrypt operations down the line to generate a response to the network.

optical-o commented 7 months ago

I have added a logging capability to the fs_port to be able log only certain files. I have also added logging to the provisioning part to see whether the dava from the FS are still valid.

Here is a log from that attempt. softsim-fs-check.log

Interesting thing about that is the data is correctly read from the FS. The AES operations are logged way after the +CEREG: 90, which is really weird. I'm gonna check the internal if it behaves the same.

+CSCON: 0
[00:01:36.324,005] <inf> softsim_sample: RRC mode: Idle

+CEREG: 90
[00:01:46.059,173] <dbg> softsim_crypto: ss_utils_aes_encrypt: AES encrypt to key id: 10
[00:01:46.060,302] <dbg> softsim_crypto: ss_utils_aes_encrypt: AES encrypt to key id: 10
[00:01:46.061,462] <dbg> softsim_crypto: ss_utils_aes_encrypt: AES encrypt to key id: 10
[00:01:46.062,591] <dbg> softsim_crypto: ss_utils_aes_encrypt: AES encrypt to key id: 10
[00:01:46.063,751] <dbg> softsim_crypto: ss_utils_aes_encrypt: AES encrypt to key id: 10
[00:01:46.064,880] <dbg> softsim_crypto: ss_utils_aes_encrypt: AES encrypt to key id: 10
[00:01:46.066,040] <dbg> softsim_crypto: ss_utils_aes_encrypt: AES encrypt to key id: 10
[00:01:46.067,169] <dbg> softsim_crypto: ss_utils_aes_encrypt: AES encrypt to key id: 10
[00:01:46.068,328] <dbg> softsim_crypto: ss_utils_aes_encrypt: AES encrypt to key id: 10
[00:01:46.069,458] <dbg> softsim_crypto: ss_utils_aes_encrypt: AES encrypt to key id: 10
optical-o commented 7 months ago

Yes exactly the AES Operations are performed before the CEREG. This looks like some kind priority issue or the softsim is getting stuck by the low priority spi_nor.c driver. I will check priorities of the soc_flash_nrf.c driver against the spi_nor.c priority.

softsim-fs-check.log

optical-o commented 7 months ago

It still could be a timing issue in the end but i will see.

optical-o commented 7 months ago

@peterbornerup So the issue is indeed in the LittleFS being for some unknown reason dreadfully slow. I have verified it by pre-caching the files required for the authenticating towards network then it worked fine.

It takes about 200ms to get the size of a file and then another 200ms to read it... I will try to tune the LittleFS or found the root cause of this.

optical-o commented 7 months ago

I resolved the issue with the LittleFS the whole problem comes from the configuration of block_size, which should be configured from SFDP of the external flash, which for some reason returns a block size of 64K. This causes the LittleFS to create a dir_entry with this size and each file open operation then searches this 64K region for the file.

This will increase the time to open the file to significant number. For me this was to 200ms. I have also added a shortcut that reduced the required number of opening files for loading into the cache which in total reduced the access time from ~500ms per file to ~3ms. I will commit the correct configuration of the littlefs. I will retest whether now the cache is even needed for the LittleFS variant. But it can be trivialy enabled or disabled. You can even specify how many files you want to have loaded into it and others will not be cached.

optical-o commented 7 months ago

@peterbornerup I have a question about the SoftSim stack size and heap usage.

Do you have some worst case measurements ? How much of it is actually needed ? I have spin up the SoftSim on our Dronetag Mini and i can see from thread analyzer that only about 1/3 is used. What are the margins there ? 0x2001bc08 : STACK: unused 6660 usage 3340 / 10000 (33 %); CPU: 3 % : Total CPU cycles used: 64111

I will also name the thread so it is correctly displayed in zephyr.

It would be nice to also know how much of the heap can the SoftSim use i want fix the size of the cache for files so i can better stabilize and optimize the memory in the firmware. This way the total cost of the SoftSim is more than 40K of RAM i would like to reduce that to necessary minimum.

Is there a way how we can test the worst case the provisioning of the SIM ?

peterbornerup commented 7 months ago

Stack should be safe to decrease based on the number you got - probably. I have an idea for testing - I'll provide some background below.

The main concern with softsim is that we wan't to be able to fire remote requests. These are typically executed via SMS(s). The SMS contains a series of commands and the whole content is encrypted and signed with some of the keys on the softsim.

Anyway, in order to not interfere with the main softsim context - the remote sms command will eventually spawn a new softsim context internally so the apdu commands in the envelope SMS doesn't affect the main ctx. Granted - the second context is slimmed down as the parent (main ctx) has some additional data associated.

We can with a test profile generated the expected apdu commands related to the remote sim operations - or alternatively we can perform actual OTA updates of your softsim file-system while you are tracing some stuff?

peterbornerup commented 7 months ago

Oh forgot to mention - the heap set currently is just enough to complete the OTA. However, with a more efficient impl of the file system you could get away with less memory reserved for SoftSIM.

optical-o commented 7 months ago

@peterbornerup Got little bit caught up with some other development stuff. I will allow to use a separate heap implementation for the Cache system so we have better understanding of the heap usage. Maybe i will also allow adding a heap for the SoftSim it self so we can see the usages in more detail.

Hopefully i will clean it up during next two weeks. I would appreciate that we test the OTA and some SMS in the future.

peterbornerup commented 7 months ago

Absolutely - I'll look into what is needed to fire a OTA update from our core. I'll have to bring in some different guys but shouldn't be too bad though.