Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Soft SIM LittleFS Backend #30

Open
optical-o opened this issue Feb 6, 2024 · 43 comments · May be fixed by #31
Open

Soft SIM LittleFS Backend #30

optical-o opened this issue Feb 6, 2024 · 43 comments · May be fixed by #31
Assignees

Comments

@optical-o
Copy link

optical-o commented Feb 6, 2024

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
Copy link
Member

Hi there,

#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 peterbornerup self-assigned this Feb 7, 2024
@peterbornerup peterbornerup linked a pull request Feb 7, 2024 that will close this issue
@peterbornerup
Copy link
Member

@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
Copy link
Author

@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
Copy link
Member

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
Copy link
Member

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
Copy link
Author

optical-o commented Feb 9, 2024

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
Copy link
Author

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
Copy link
Author

optical-o commented Feb 9, 2024

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
Copy link
Member

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
Copy link
Member

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
Copy link
Author

optical-o commented Feb 9, 2024

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
Copy link
Member

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
Copy link
Author

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
Copy link
Member

Ah completely missed that!! Nice nice nice.

@optical-o
Copy link
Author

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
Copy link
Author

optical-o commented Feb 9, 2024

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
Copy link
Author

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
Copy link
Author

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
Copy link
Member

peterbornerup commented Feb 10, 2024 via email

@optical-o
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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
Copy link
Author

optical-o commented Feb 14, 2024

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 [email protected] -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-nvs.conf;overlay-profile.conf"
west build -b [email protected] -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-littlefs.conf;overlay-profile.conf"
west build -b [email protected] -- "-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
Copy link
Member

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
Copy link
Member

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
Copy link
Member

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 [email protected] -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-nvs.conf;overlay-profile.conf"
west build -b [email protected] -- "-DOVERLAY_CONFIG=../../overlay-softsim.conf;../../overlay-softsim-littlefs.conf;overlay-profile.conf"
west build -b [email protected] -- "-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:

  • does the key resolve the correct ID as expected? (should always be the KI for authentication)
  • are the crypto operations OK? Don't know if the flash layout conflicts with the TFM partition or so?

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

@peterbornerup
Copy link
Member

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
Copy link
Author

optical-o commented Feb 20, 2024

@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
Copy link
Author

optical-o commented Feb 20, 2024

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
Copy link
Author

optical-o commented Feb 20, 2024

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
Copy link
Member

[00:00:22.961,486] �[0m<inf> softsim_sample: RRC mode: Connected
�[0m
[00:00:23.452,209] �[0m<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..?..         �[0m
+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
Copy link
Author

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
Copy link
Author

optical-o commented Feb 21, 2024

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
Copy link
Author

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

@optical-o
Copy link
Author

@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
Copy link
Author

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
Copy link
Author

@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
Copy link
Member

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
Copy link
Member

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
Copy link
Author

@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
Copy link
Member

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants