• State Not Answered
  • Replies 42 replies
  • Subscribers 26 subscribers
  • Views 3330 views
  • Users 0 members are here
Attachments (10) Download All
Nordic Case Info
  • Case ID: 267337
Options

MSC exception

user85932

Hi,

Our production uses NRF52840 as the master chip. We encountered a strange problem where two folders have the same name and a file name has illegal characters. 

The probability of this happening is very low, so we can not find the root cause so far. As we know, the file system does not allow a folder with the same name and a file name with illegal characters. What are the possible causes of this problem?

The normal directory structure is shown below.

-----------------------------------------------------------------------------------------

I would like to provide more details for the MSC issue as below.

I attached the nrf_block_dev_qspi.c that I used, you may diff with the original file of the SDK.

There are two major modifications.

1.the issue was reported in this link https://devzone.nordicsemi.com/f/nordic-q-a/36654/usbd_msd-disk-initialization-fails-in-usb-unplug-with-sdk15-0

the difference was I added a timeout for the wait_for_idle()  function because I found it would hang on this function sometimes.

2. add debug message for troubleshooting 

We got the debug log sometimes(please find debug.log), although everything looks good, I thought it was unexpected. 

By the way, there were not any debug logs when the issue "two folders have the same name and a file name has illegal characters"  occurred.

Parents
  • 0

    Hi ,

    Filenames are stored on the QSPI memory just like file contents, so it is possible that there is a remaining bug in block_dev library other than what was fixed in the earlier thread. It is not a known issue though nor can we pinpoint it as this point.

    Can you say more about how early it occurs, and have you found a way to reliably reproduce it?

  • 0 in reply to user7377

    Hi Einar

    I can not find a way to reliably reproduce it so far, and the probability of this happening is very low. It may have happened before this thread, but I'm not 100% sure.
    I believe that there is a bug in block_dev library because I am able to capture the debug logs sometimes.
    By the way, the latest SDK did not fix the issue mentioned in this thread.

  • 0 in reply to user7377
    user7377 said:
    Can you explain the logs, perhaps share the code that writes it? I would guess that the last number is the return value from the function, but about the first? Please explain.

    For example, AE-0.28-1609461906-fit_file.c-FIT_closeDir-68-0x9

    AE: APP error 

    0.28：FW version 

    1609461906:timestamp

    fit_file.c: file name

    FIT_closeDir: function name 

    68: the code line number of source file 

    0x9:the return value from the function.

    By the way, the function FIT_closeDir is the same as f_closedir, I'm simply encapsulating the API of Fatfs.

    fitFileResult_t FIT_openDir(fitDir_t *dp, const char_t *path) {
        fitFileResult_t ret;
        ret = f_opendir(dp, path);
        APP_ERROR_CHECK(ret);
        return ret;
    }
    user7377 said:
    To be frank there is little to go on here, so I think it is important to try to narrow down the issue even though it might seem a bit tedious.

    I see, I will try to reproduce it on nRF52840-DK PCA10056.

    user7377 said:
    It does not seem relevant but as this is not something we have used it would be interesting to know if you can reproduce the issue without as well (so _FS_NORTC and _USE_LFN both set to 0)?

    We had enabled_FS_NORTC and _USE_LFN both set to 1 at the beginning of this project. So I don't know whether this issue can be reproduced if set to 0.

  • 0 in reply to user85932

    Thank you for the explanation. Please let me know if/when you are able to reproduce on a DK, and also if you see a pattern where removing some of your code/modules seems to make the issue less likely to happen.

  • 0 in reply to user7377

    Hi Einar,

    I am able to reproduce on a DK without the patch. That means this issue is caused by the unexpected write operation.

    Below is the repeat method.

    1. Press Button 3 to format the disk 
    2. Press Button 1 to create the folder and file.
    3. connect USB to the PC, then you will see a exception file in the Activ folder 

    ----------------------------------------------------------------------------------------------------------------------------------------------

    ---------------------------------------------------------------------------------------------------------------------------------------------

    After the patch was applied, although this issue couldn't be reproduced, I found some unexpected write operation while connect to the PC.  

    the exception log:

    [00:00:00.011,779] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1

    [00:00:00.022,338] <info> app: #1blk_count:1, erase_unit_dirty_blocks:0, erase_required:0
    [00:00:00.022,338] <info> app: #0:erase_unit_dirty_blocks:0, erase_unit_idx:0xC

    1.connect to the PC, and format the disk via the PC.

    00> [00:00:00.008,850] <info> app: Read req from block 63 size 1(x512) to 20001804
00> 
00> [00:00:00.010,131] <info> app: Read req from block 63 size 1(x512) to 20001804
00> 
00> [00:00:00.062,561] <info> app: Write req to block 127 size 2(x512) from 20001804
00> 
00> [00:00:00.063,598] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.063,598] <info> app: erase:addr:F000 block:120, id:15
00> 
00> [00:00:00.073,364] <info> app: Write req to block 129 size 2(x512) from 20001C04
00> 
00> [00:00:00.073,547] <info> app: Write req to block 127 size 2(x512) from 20001804
00> 
00> [00:00:00.074,584] <info> app: #1blk_count:1, erase_unit_dirty_blocks:0, erase_required:0
00> 
00> [00:00:00.074,584] <info> app: #0:erase_unit_dirty_blocks:0, erase_unit_idx:0xF
00> 
00> [00:00:00.074,584] <info> app: src:20004804, blk_size:512, dst:13000, block:152
00> 
00> [00:00:00.075,988] <info> app: Write req to block 129 size 2(x512) from 20001C04
00> 
00> [00:00:00.076,232] <info> app: Write req to block 127 size 2(x512) from 20001804
00> 
00> [00:00:00.077,209] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.077,209] <info> app: erase:addr:F000 block:120, id:15
00> 
00> [00:00:00.086,975] <info> app: Write req to block 129 size 2(x512) from 20001C04
00> 
00> [00:00:00.087,768] <info> app: Write req to block 63 size 1(x512) from 20001804
00> 
00> [00:00:00.088,806] <info> app: Read req from block 63 size 1(x512) to 20001804
00> 
00> [00:00:00.089,111] <info> app: Write req to block 16383 size 1(x512) from 20001804
00> 
00> [00:00:00.089,111] <info> app: writeback_mode:idx:0x7,dirty_blocks:255
00> 
00> [00:00:00.089,111] <info> app: erase:addr:7000 block:56, id:7
00> 
00> [00:00:00.098,876] <info> app: Read req from block 16383 size 1(x512) to 20001804
00> 
00> [00:00:00.099,365] <info> app: Write req to block 71 size 2(x512) from 20001804
00> 
00> [00:00:00.100,341] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.100,341] <info> app: erase:addr:8000 block:64, id:8
00> 
00> [00:00:00.110,656] <info> app: Write req to block 73 size 2(x512) from 20001C04
00> 
00> [00:00:00.110,839] <info> app: Write req to block 75 size 2(x512) from 20001804
00> 
00> [00:00:00.111,022] <info> app: Write req to block 77 size 2(x512) from 20001C04
00> 
00> [00:00:00.111,267] <info> app: Write req to block 79 size 2(x512) from 20001804
00> 
00> [00:00:00.111,267] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.111,267] <info> app: erase:addr:9000 block:72, id:9
00> 
00> [00:00:00.121,643] <info> app: Write req to block 81 size 2(x512) from 20001C04
00> 
00> [00:00:00.121,704] <info> app: Read req from block 71 size 2(x512) to 20001804
00> 
00> [00:00:00.121,948] <info> app: Read req from block 73 size 2(x512) to 20001C04
00> 
00> [00:00:00.122,253] <info> app: Read req from block 75 size 2(x512) to 20001804
00> 
00> [00:00:00.122,497] <info> app: Read req from block 77 size 2(x512) to 20001C04
00> 
00> [00:00:00.122,741] <info> app: Read req from block 79 size 2(x512) to 20001804
00> 
00> [00:00:00.123,046] <info> app: Read req from block 81 size 2(x512) to 20001C04
00> 
00> [00:00:00.123,596] <info> app: Write req to block 83 size 2(x512) from 20001804
00> 
00> [00:00:00.123,779] <info> app: Write req to block 85 size 2(x512) from 20001C04
00> 
00> [00:00:00.123,962] <info> app: Write req to block 87 size 2(x512) from 20001804
00> 
00> [00:00:00.123,962] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.123,962] <info> app: erase:addr:A000 block:80, id:10
00> 
00> [00:00:00.009,399] <info> app: Write req to block 89 size 2(x512) from 20001C04
00> 
00> [00:00:00.009,582] <info> app: Write req to block 91 size 2(x512) from 20001804
00> 
00> [00:00:00.009,826] <info> app: Write req to block 93 size 2(x512) from 20001C04
00> 
00> [00:00:00.009,887] <info> app: Read req from block 83 size 2(x512) to 20001804
00> 
00> [00:00:00.010,131] <info> app: Read req from block 85 size 2(x512) to 20001C04
00> 
00> [00:00:00.010,375] <info> app: Read req from block 87 size 2(x512) to 20001804
00> 
00> [00:00:00.010,681] <info> app: Read req from block 89 size 2(x512) to 20001C04
00> 
00> [00:00:00.010,925] <info> app: Read req from block 91 size 2(x512) to 20001804
00> 
00> [00:00:00.011,230] <info> app: Read req from block 93 size 2(x512) to 20001C04
00> 
00> [00:00:00.011,779] <info> app: Write req to block 95 size 2(x512) from 20001804
00> 
00> [00:00:00.011,779] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.011,779] <info> app: erase:addr:B000 block:88, id:11
00> 
00> [00:00:00.021,728] <info> app: Write req to block 97 size 2(x512) from 20001C04
00> 
00> [00:00:00.021,911] <info> app: Write req to block 99 size 2(x512) from 20001804
00> 
00> [00:00:00.022,094] <info> app: Write req to block 101 size 2(x512) from 20001C04
00> 
00> [00:00:00.022,338] <info> app: Write req to block 103 size 2(x512) from 20001804
00> 
00> [00:00:00.022,338] <info> app: #1blk_count:1, erase_unit_dirty_blocks:0, erase_required:0
00> 
00> [00:00:00.022,338] <info> app: #0:erase_unit_dirty_blocks:0, erase_unit_idx:0xC
00> 
00> [00:00:00.022,338] <info> app: src:20004804, blk_size:512, dst:10000, block:128
00> 
00> [00:00:00.023,498] <info> app: Write req to block 105 size 2(x512) from 20001C04
00> 
00> [00:00:00.023,681] <info> app: Write req to block 107 size 2(x512) from 20001804
00> 
00> [00:00:00.023,864] <info> app: Write req to block 109 size 2(x512) from 20001C04
00> 
00> [00:00:00.024,047] <info> app: Write req to block 111 size 2(x512) from 20001804
00> 
00> [00:00:00.024,047] <info> app: #1blk_count:1, erase_unit_dirty_blocks:0, erase_required:0
00> 
00> [00:00:00.024,047] <info> app: #0:erase_unit_dirty_blocks:0, erase_unit_idx:0xD
00> 
00> [00:00:00.024,047] <info> app: src:20004804, blk_size:512, dst:11000, block:136
00> 
00> [00:00:00.025,207] <info> app: Write req to block 113 size 2(x512) from 20001C04
00> 
00> [00:00:00.025,451] <info> app: Write req to block 115 size 2(x512) from 20001804
00> 
00> [00:00:00.025,573] <info> app: Write req to block 117 size 2(x512) from 20001C04
00> 
00> [00:00:00.025,756] <info> app: Write req to block 119 size 2(x512) from 20001804
00> 
00> [00:00:00.025,756] <info> app: #1blk_count:1, erase_unit_dirty_blocks:0, erase_required:0
00> 
00> [00:00:00.025,756] <info> app: #0:erase_unit_dirty_blocks:0, erase_unit_idx:0xE
00> 
00> [00:00:00.025,756] <info> app: src:20004804, blk_size:512, dst:12000, block:144
00> 
00> [00:00:00.027,221] <info> app: Write req to block 121 size 2(x512) from 20001C04
00> 
00> [00:00:00.027,404] <info> app: Write req to block 123 size 2(x512) from 20001804
00> 
00> [00:00:00.027,526] <info> app: Write req to block 125 size 2(x512) from 20001C04
00> 
00> [00:00:00.027,587] <info> app: Read req from block 95 size 2(x512) to 20001804
00> 
00> [00:00:00.027,832] <info> app: Read req from block 97 size 2(x512) to 20001C04
00> 
00> [00:00:00.028,137] <info> app: Read req from block 99 size 2(x512) to 20001804
00> 
00> [00:00:00.028,381] <info> app: Read req from block 101 size 2(x512) to 20001C04
00> 
00> [00:00:00.028,686] <info> app: Read req from block 103 size 2(x512) to 20001804
00> 
00> [00:00:00.028,930] <info> app: Read req from block 105 size 2(x512) to 20001C04
00> 
00> [00:00:00.029,174] <info> app: Read req from block 107 size 2(x512) to 20001804
00> 
00> [00:00:00.029,479] <info> app: Read req from block 109 size 2(x512) to 20001C04
00> 
00> [00:00:00.029,724] <info> app: Read req from block 111 size 2(x512) to 20001804
00> 
00> [00:00:00.030,029] <info> app: Read req from block 113 size 2(x512) to 20001C04
00> 
00> [00:00:00.030,273] <info> app: Read req from block 115 size 2(x512) to 20001804
00> 
00> [00:00:00.030,517] <info> app: Read req from block 117 size 2(x512) to 20001C04
00> 
00> [00:00:00.030,822] <info> app: Read req from block 119 size 2(x512) to 20001804
00> 
00> [00:00:00.031,066] <info> app: Read req from block 121 size 2(x512) to 20001C04
00> 
00> [00:00:00.031,372] <info> app: Read req from block 123 size 2(x512) to 20001804
00> 
00> [00:00:00.031,616] <info> app: Read req from block 125 size 2(x512) to 20001C04
00> 
00> [00:00:00.032,226] <info> app: Write req to block 63 size 2(x512) from 20001804
00> 
00> [00:00:00.033,264] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.033,264] <info> app: erase:addr:7000 block:56, id:7
00> 
00> [00:00:00.042,785] <info> app: Write req to block 65 size 2(x512) from 20001C04
00> 
00> [00:00:00.042,968] <info> app: Write req to block 67 size 2(x512) from 20001804
00> 
00> [00:00:00.043,151] <info> app: Write req to block 69 size 2(x512) from 20001C04
00> 
00> [00:00:00.043,212] <info> app: Read req from block 63 size 2(x512) to 20001804
00> 
00> [00:00:00.043,518] <info> app: Read req from block 65 size 2(x512) to 20001C04
00> 
00> [00:00:00.043,762] <info> app: Read req from block 67 size 2(x512) to 20001804
00> 
00> [00:00:00.044,067] <info> app: Read req from block 69 size 2(x512) to 20001C04
00> 
00> [00:00:00.044,555] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.044,738] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.045,043] <info> app: Write req to block 0 size 1(x512) from 20001804
00> 
00> [00:00:00.046,142] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.046,508] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.046,752] <info> app: Read req from block 63 size 2(x512) to 20001804
00> 
00> [00:00:00.047,058] <info> app: Read req from block 65 size 2(x512) to 20001C04
00> 
00> [00:00:00.047,302] <info> app: Read req from block 67 size 2(x512) to 20001804
00> 
00> [00:00:00.047,546] <info> app: Read req from block 69 size 2(x512) to 20001C04
00> 
00> [00:00:00.047,973] <info> app: Read req from block 71 size 2(x512) to 20001804
00> 
00> [00:00:00.048,278] <info> app: Read req from block 73 size 2(x512) to 20001C04
00> 
00> [00:00:00.048,522] <info> app: Read req from block 75 size 2(x512) to 20001804
00> 
00> [00:00:00.048,828] <info> app: Read req from block 77 size 2(x512) to 20001C04
00> 
00> [00:00:00.049,194] <info> app: Read req from block 79 size 2(x512) to 20001804
00> 
00> [00:00:00.049,499] <info> app: Read req from block 81 size 2(x512) to 20001C04
00> 
00> [00:00:00.049,743] <info> app: Read req from block 83 size 2(x512) to 20001804
00> 
00> [00:00:00.049,987] <info> app: Read req from block 85 size 2(x512) to 20001C04
00> 
00> [00:00:00.050,415] <info> app: Read req from block 95 size 2(x512) to 20001804
00> 
00> [00:00:00.050,659] <info> app: Read req from block 97 size 2(x512) to 20001C04
00> 
00> [00:00:00.050,964] <info> app: Read req from block 99 size 2(x512) to 20001804
00> 
00> [00:00:00.051,208] <info> app: Read req from block 101 size 2(x512) to 20001C04
00> 
00> [00:00:00.051,879] <info> app: Read req from block 2 size 1(x512) to 20001804
00> 
00> [00:00:00.052,429] <info> app: Read req from block 63 size 2(x512) to 20001804
00> 
00> [00:00:00.052,673] <info> app: Read req from block 65 size 2(x512) to 20001C04
00> 
00> [00:00:00.052,978] <info> app: Read req from block 67 size 2(x512) to 20001804
00> 
00> [00:00:00.053,222] <info> app: Read req from block 69 size 2(x512) to 20001C04
00> 
00> [00:00:00.053,527] <info> app: Read req from block 71 size 2(x512) to 20001804
00> 
00> [00:00:00.053,771] <info> app: Read req from block 73 size 2(x512) to 20001C04
00> 
00> [00:00:00.054,016] <info> app: Read req from block 75 size 2(x512) to 20001804
00> 
00> [00:00:00.054,321] <info> app: Read req from block 77 size 2(x512) to 20001C04
00> 
00> [00:00:00.054,748] <info> app: Read req from block 127 size 2(x512) to 20001804
00> 
00> [00:00:00.054,992] <info> app: Read req from block 129 size 2(x512) to 20001C04
00> 
00> [00:00:00.055,603] <info> app: Write req to block 95 size 2(x512) from 20001804
00> 
00> [00:00:00.056,579] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.056,579] <info> app: erase:addr:B000 block:88, id:11
00> 
00> [00:00:00.066,589] <info> app: Write req to block 97 size 2(x512) from 20001C04
00> 
00> [00:00:00.066,772] <info> app: Write req to block 99 size 2(x512) from 20001804
00> 
00> [00:00:00.066,955] <info> app: Write req to block 101 size 2(x512) from 20001C04
00> 
00> [00:00:00.066,955] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.067,260] <info> app: Write req to block 71 size 1(x512) from 20001804
00> 
00> [00:00:00.068,359] <info> app: Write req to block 83 size 1(x512) from 20001804
00> 
00> [00:00:00.068,359] <info> app: writeback_mode:idx:0x8,dirty_blocks:255
00> 
00> [00:00:00.068,359] <info> app: erase:addr:8000 block:64, id:8
00> 
00> [00:00:00.078,735] <info> app: Write req to block 127 size 2(x512) from 20001804
00> 
00> [00:00:00.078,735] <info> app: writeback_mode:idx:0xA,dirty_blocks:255
00> 
00> [00:00:00.078,735] <info> app: erase:addr:A000 block:80, id:10
00> 
00> [00:00:00.088,806] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.088,806] <info> app: erase:addr:F000 block:120, id:15
00> 
00> [00:00:00.098,693] <info> app: Write req to block 129 size 2(x512) from 20001C04
00> 
00> [00:00:00.098,937] <info> app: Write req to block 127 size 2(x512) from 20001804
00> 
00> [00:00:00.099,975] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.099,975] <info> app: erase:addr:F000 block:120, id:15
00> 
00> [00:00:00.109,741] <info> app: Write req to block 129 size 2(x512) from 20001C04
00> 
00> [00:00:00.109,741] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.109,985] <info> app: Read req from block 63 size 2(x512) to 20001804
00> 
00> [00:00:00.110,229] <info> app: Read req from block 65 size 2(x512) to 20001C04
00> 
00> [00:00:00.110,534] <info> app: Read req from block 67 size 2(x512) to 20001804
00> 
00> [00:00:00.110,778] <info> app: Read req from block 69 size 2(x512) to 20001C04
00> 
00> [00:00:00.111,022] <info> app: Read req from block 71 size 2(x512) to 20001804
00> 
00> [00:00:00.111,328] <info> app: Read req from block 73 size 2(x512) to 20001C04
00> 
00> [00:00:00.111,572] <info> app: Read req from block 75 size 2(x512) to 20001804
00> 
00> [00:00:00.111,877] <info> app: Read req from block 77 size 2(x512) to 20001C04
00> 
00> [00:00:00.112,426] <info> app: Write req to block 127 size 2(x512) from 20001804
00> 
00> [00:00:00.113,403] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.113,403] <info> app: erase:addr:F000 block:120, id:15
00> 
00> [00:00:00.123,168] <info> app: Write req to block 129 size 2(x512) from 20001C04
00> 
00> [00:00:00.123,413] <info> app: Write req to block 127 size 2(x512) from 20001804
00> 
00> [00:00:00.124,450] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.124,450] <info> app: erase:addr:F000 block:120, id:15
00> 
00> [00:00:00.009,033] <info> app: Write req to block 129 size 2(x512) from 20001C04
00> 
00> [00:00:00.009,094] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.009,460] <info> app: Write req to block 127 size 2(x512) from 20001804
00> 
00> [00:00:00.010,498] <info> app: #1blk_count:1, erase_unit_dirty_blocks:0, erase_required:0
00> 
00> [00:00:00.010,498] <info> app: #0:erase_unit_dirty_blocks:0, erase_unit_idx:0xF
00> 
00> [00:00:00.010,498] <info> app: src:20004804, blk_size:512, dst:13000, block:152
00> 
00> [00:00:00.011,657] <info> app: Write req to block 129 size 2(x512) from 20001C04
00> 
00> [00:00:00.011,779] <info> app: Write req to block 135 size 1(x512) from 20001804
00> 
00> [00:00:00.011,901] <info> app: Write req to block 131 size 1(x512) from 20001804
00> 
00> [00:00:00.012,023] <info> app: Write req to block 71 size 1(x512) from 20001804
00> 
00> [00:00:00.012,023] <info> app: writeback_mode:idx:0x10,dirty_blocks:255
00> 
00> [00:00:00.012,023] <info> app: erase:addr:10000 block:128, id:16
00> 
00> [00:00:00.021,728] <info> app: Write req to block 83 size 1(x512) from 20001804
00> 
00> [00:00:00.021,728] <info> app: writeback_mode:idx:0x8,dirty_blocks:255
00> 
00> [00:00:00.021,728] <info> app: erase:addr:8000 block:64, id:8
00> 
00> [00:00:00.031,921] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.032,104] <info> app: Read req from block 63 size 2(x512) to 20001804
00> 
00> [00:00:00.032,409] <info> app: Read req from block 65 size 2(x512) to 20001C04
00> 
00> [00:00:00.032,653] <info> app: Read req from block 67 size 2(x512) to 20001804
00> 
00> [00:00:00.032,897] <info> app: Read req from block 69 size 2(x512) to 20001C04
00> 
00> [00:00:00.033,203] <info> app: Read req from block 71 size 2(x512) to 20001804
00> 
00> [00:00:00.033,447] <info> app: Read req from block 73 size 2(x512) to 20001C04
00> 
00> [00:00:00.033,691] <info> app: Read req from block 75 size 2(x512) to 20001804
00> 
00> [00:00:00.033,996] <info> app: Read req from block 77 size 2(x512) to 20001C04
00> 
00> [00:00:00.034,545] <info> app: Read req from block 63 size 1(x512) to 20001804
00>

    2.After formating the disk via the PC,  copy a file to the MSC via the PC 

    00> [00:00:00.052,978] <info> app: Write req to block 1195 size 2(x512) from 20001804
00> 
00> [00:00:00.053,161] <info> app: Write req to block 1197 size 2(x512) from 20001C04
00> 
00> [00:00:00.053,283] <info> app: Write req to block 1199 size 1(x512) from 20001804
00> 
00> [00:00:00.053,466] <info> app: Write req to block 95 size 2(x512) from 20001804
00> 
00> [00:00:00.053,466] <info> app: writeback_mode:idx:0x95,dirty_blocks:255
00> 
00> [00:00:00.053,466] <info> app: erase:addr:95000 block:1192, id:149
00> 
00> [00:00:00.062,622] <info> app: #1blk_count:1, erase_unit_dirty_blocks:255, erase_required:1
00> 
00> [00:00:00.062,622] <info> app: erase:addr:B000 block:88, id:11
00> 
00> [00:00:00.072,570] <info> app: Write req to block 97 size 2(x512) from 20001C04
00> 
00> [00:00:00.072,753] <info> app: Write req to block 99 size 2(x512) from 20001804
00> 
00> [00:00:00.072,937] <info> app: Write req to block 101 size 2(x512) from 20001C04
00> 
00> [00:00:00.073,242] <info> app: Write req to block 95 size 2(x512) from 20001804
00> 
00> [00:00:00.074,279] <info> app: #1blk_count:1, erase_unit_dirty_blocks:0, erase_required:0
00> 
00> [00:00:00.074,279] <info> app: #0:erase_unit_dirty_blocks:0, erase_unit_idx:0xB
00> 
00> [00:00:00.074,279] <info> app: src:20004804, blk_size:512, dst:F000, block:120
00> 
00> [00:00:00.075,439] <info> app: Write req to block 97 size 2(x512) from 20001C04
00> 
00> [00:00:00.075,622] <info> app: Write req to block 99 size 2(x512) from 20001804
00> 
00> [00:00:00.075,805] <info> app: Write req to block 101 size 2(x512) from 20001C04

    3. Press button 3 to format the disk, and then connect to the PC, you can see some write operation from PC, what I understand, it should have read operation only.

    00> [00:00:00.123,291] <info> app: USB power detected
00> 
00> [00:00:00.123,291] <info> app: Un-initializing disk 0 (QSPI)...
00> 
00> [00:00:00.123,291] <info> app: USB ready
00> 
00> [00:00:00.020,629] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.020,996] <info> app: Read req from block 2 size 1(x512) to 20001804
00> 
00> [00:00:00.021,301] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.021,484] <info> app: Read req from block 63 size 1(x512) to 20001804
00> 
00> [00:00:00.021,972] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.022,277] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.022,460] <info> app: Read req from block 63 size 2(x512) to 20001804
00> 
00> [00:00:00.022,766] <info> app: Read req from block 65 size 2(x512) to 20001C04
00> 
00> [00:00:00.023,010] <info> app: Read req from block 67 size 2(x512) to 20001804
00> 
00> [00:00:00.023,315] <info> app: Read req from block 69 size 2(x512) to 20001C04
00> 
00> [00:00:00.023,559] <info> app: Read req from block 71 size 2(x512) to 20001804
00> 
00> [00:00:00.023,803] <info> app: Read req from block 73 size 2(x512) to 20001C04
00> 
00> [00:00:00.024,108] <info> app: Read req from block 75 size 2(x512) to 20001804
00> 
00> [00:00:00.024,353] <info> app: Read req from block 77 size 2(x512) to 20001C04
00> 
00> [00:00:00.024,902] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.025,146] <info> app: Read req from block 63 size 2(x512) to 20001804
00> 
00> [00:00:00.025,451] <info> app: Read req from block 65 size 2(x512) to 20001C04
00> 
00> [00:00:00.025,695] <info> app: Read req from block 67 size 2(x512) to 20001804
00> 
00> [00:00:00.026,000] <info> app: Read req from block 69 size 2(x512) to 20001C04
00> 
00> [00:00:00.026,367] <info> app: Read req from block 71 size 2(x512) to 20001804
00> 
00> [00:00:00.026,672] <info> app: Read req from block 73 size 2(x512) to 20001C04
00> 
00> [00:00:00.026,916] <info> app: Read req from block 75 size 2(x512) to 20001804
00> 
00> [00:00:00.027,160] <info> app: Read req from block 77 size 2(x512) to 20001C04
00> 
00> [00:00:00.027,465] <info> app: Read req from block 79 size 2(x512) to 20001804
00> 
00> [00:00:00.027,709] <info> app: Read req from block 81 size 2(x512) to 20001C04
00> 
00> [00:00:00.028,015] <info> app: Read req from block 83 size 2(x512) to 20001804
00> 
00> [00:00:00.028,259] <info> app: Read req from block 85 size 2(x512) to 20001C04
00> 
00> [00:00:00.028,503] <info> app: Read req from block 87 size 2(x512) to 20001804
00> 
00> [00:00:00.028,808] <info> app: Read req from block 89 size 2(x512) to 20001C04
00> 
00> [00:00:00.029,052] <info> app: Read req from block 91 size 2(x512) to 20001804
00> 
00> [00:00:00.029,357] <info> app: Read req from block 93 size 2(x512) to 20001C04
00> 
00> [00:00:00.029,602] <info> app: Read req from block 95 size 2(x512) to 20001804
00> 
00> [00:00:00.029,846] <info> app: Read req from block 97 size 2(x512) to 20001C04
00> 
00> [00:00:00.030,151] <info> app: Read req from block 99 size 2(x512) to 20001804
00> 
00> [00:00:00.030,395] <info> app: Read req from block 101 size 2(x512) to 20001C04
00> 
00> [00:00:00.030,822] <info> app: Read req from block 96 size 2(x512) to 20001804
00> 
00> [00:00:00.031,066] <info> app: Read req from block 98 size 2(x512) to 20001C04
00> 
00> [00:00:00.031,372] <info> app: Read req from block 100 size 2(x512) to 20001804
00> 
00> [00:00:00.031,616] <info> app: Read req from block 102 size 2(x512) to 20001C04
00> 
00> [00:00:00.032,226] <info> app: Read req from block 2 size 1(x512) to 20001804
00> 
00> [00:00:00.032,836] <info> app: Read req from block 63 size 2(x512) to 20001804
00> 
00> [00:00:00.033,081] <info> app: Read req from block 65 size 2(x512) to 20001C04
00> 
00> [00:00:00.033,325] <info> app: Read req from block 67 size 2(x512) to 20001804
00> 
00> [00:00:00.033,630] <info> app: Read req from block 69 size 2(x512) to 20001C04
00> 
00> [00:00:00.033,874] <info> app: Read req from block 71 size 2(x512) to 20001804
00> 
00> [00:00:00.034,179] <info> app: Read req from block 73 size 2(x512) to 20001C04
00> 
00> [00:00:00.034,423] <info> app: Read req from block 75 size 2(x512) to 20001804
00> 
00> [00:00:00.034,667] <info> app: Read req from block 77 size 2(x512) to 20001C04
00> 
00> [00:00:00.035,217] <info> app: Write req to block 63 size 1(x512) from 20001804
00> 
00> [00:00:00.036,254] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.036,499] <info> app: Read req from block 128 size 2(x512) to 20001804
00> 
00> [00:00:00.037,048] <info> app: Write req to block 96 size 2(x512) from 20001804
00> 
00> [00:00:00.037,048] <info> app: writeback_mode:idx:0x7,dirty_blocks:255
00> 
00> [00:00:00.037,048] <info> app: erase:addr:7000 block:56, id:7
00> 
00> [00:00:00.046,813] <info> app: Write req to block 98 size 2(x512) from 20001C04
00> 
00> [00:00:00.046,997] <info> app: Write req to block 100 size 2(x512) from 20001804
00> 
00> [00:00:00.047,180] <info> app: Write req to block 102 size 2(x512) from 20001C04
00> 
00> [00:00:00.047,302] <info> app: Write req to block 64 size 1(x512) from 20001804
00> 
00> [00:00:00.047,302] <info> app: writeback_mode:idx:0xC,dirty_blocks:255
00> 
00> [00:00:00.047,302] <info> app: erase:addr:C000 block:96, id:12
00> 
00> [00:00:00.057,312] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.057,678] <info> app: Write req to block 128 size 2(x512) from 20001804
00> 
00> [00:00:00.057,678] <info> app: writeback_mode:idx:0x8,dirty_blocks:255
00> 
00> [00:00:00.057,678] <info> app: erase:addr:8000 block:64, id:8
00> 
00> [00:00:00.067,810] <info> app: Write req to block 63 size 1(x512) from 20001804
00> 
00> [00:00:00.067,810] <info> app: writeback_mode:idx:0x10,dirty_blocks:255
00> 
00> [00:00:00.067,810] <info> app: erase:addr:10000 block:128, id:16
00> 
00> [00:00:00.077,392] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.077,697] <info> app: Write req to block 64 size 1(x512) from 20001804
00> 
00> [00:00:00.077,697] <info> app: writeback_mode:idx:0x7,dirty_blocks:255
00> 
00> [00:00:00.077,697] <info> app: erase:addr:7000 block:56, id:7
00> 
00> [00:00:00.087,585] <info> app: Write req to block 128 size 2(x512) from 20001804
00> 
00> [00:00:00.087,585] <info> app: writeback_mode:idx:0x8,dirty_blocks:255
00> 
00> [00:00:00.087,585] <info> app: erase:addr:8000 block:64, id:8
00> 
00> [00:00:00.097,778] <info> app: Read req from block 0 size 1(x512) to 20001804
00> 
00> [00:00:00.098,083] <info> app: Write req to block 63 size 1(x512) from 20001804
00> 
00> [00:00:00.098,083] <info> app: writeback_mode:idx:0x10,dirty_blocks:255
00> 
00> [00:00:00.098,083] <info> app: erase:addr:10000 block:128, id:16
00> 
00> [00:00:00.107,788] <info> app: Write req to block 128 size 2(x512) from 20001804
00> 
00> [00:00:00.107,788] <info> app: writeback_mode:idx:0x7,dirty_blocks:255
00> 
00> [00:00:00.107,788] <info> app: erase:addr:7000 block:56, id:7
00> 
00> [00:00:00.117,675] <info> app: Write req to block 64 size 1(x512) from 20001804
00> 
00> [00:00:00.117,675] <info> app: writeback_mode:idx:0x10,dirty_blocks:255
00> 
00> [00:00:00.117,675] <info> app: erase:addr:10000 block:128, id:16
00> 
00> [00:00:00.002,136] <info> app: Read req from block 63 size 1(x512) to 20001804
00> 
00> [00:00:00.002,502] <info> app: Write req to block 63 size 1(x512) from 20001804
00> 
00> [00:00:00.002,502] <info> app: writeback_mode:idx:0x8,dirty_blocks:255
00> 
00> [00:00:00.002,502] <info> app: erase:addr:8000 block:64, id:8
00> 
00> [00:00:00.012,756] <info> app: Write req to block 64 size 1(x512) from 20001804
00> 
00> [00:00:00.012,756] <info> app: writeback_mode:idx:0x7,dirty_blocks:255
00> 
00> [00:00:00.012,756] <info> app: erase:addr:7000 block:56, id:7
00> 
00> [00:00:00.022,338] <info> app: Read req from block 63 size 2(x512) to 20001804
00> 
00> [00:00:00.022,583] <info> app: Read req from block 65 size 2(x512) to 20001C04
00> 
00> [00:00:00.022,888] <info> app: Read req from block 67 size 2(x512) to 20001804
00> 
00> [00:00:00.023,132] <info> app: Read req from block 69 size 2(x512) to 20001C04
00> 
00> [00:00:00.023,437] <info> app: Read req from block 71 size 2(x512) to 20001804
00> 
00> [00:00:00.023,681] <info> app: Read req from block 73 size 2(x512) to 20001C04
00> 
00> [00:00:00.023,986] <info> app: Read req from block 75 size 2(x512) to 20001804
00> 
00> [00:00:00.024,230] <info> app: Read req from block 77 size 2(x512) to 20001C04
00> 
00> [00:00:00.024,780] <info> app: Write req to block 130 size 1(x512) from 20001804
00> 
00> [00:00:00.024,780] <info> app: writeback_mode:idx:0x8,dirty_blocks:255
00> 
00> [00:00:00.024,780] <info> app: erase:addr:8000 block:64, id:8
00> 
00> [00:00:00.035,095] <info> app: Write req to block 128 size 2(x512) from 20001804
00> 
00> [00:00:00.035,217] <info> app: Write req to block 64 size 1(x512) from 20001804
00> 
00> [00:00:00.035,217] <info> app: writeback_mode:idx:0x10,dirty_blocks:255
00> 
00> [00:00:00.035,217] <info> app: erase:addr:10000 block:128, id:16
00> 
00> [00:00:00.044,921] <info> app: Write req to block 128 size 2(x512) from 20001804
00> 
00> [00:00:00.044,921] <info> app: writeback_mode:idx:0x8,dirty_blocks:255
00> 
00> [00:00:00.044,921] <info> app: erase:addr:8000 block:64, id:8
00> 
00> [00:00:00.055,175] <info> app: Write req to block 63 size 1(x512) from 20001804
00> 
00> [00:00:00.056,335] <info> app: Write req to block 132 size 1(x512) from 20001804
00> 
00> [00:00:00.056,335] <info> app: writeback_mode:idx:0x7,dirty_blocks:255
00> 
00> [00:00:00.056,335] <info> app: erase:addr:7000 block:56, id:7
00> 
00> [00:00:00.066,223] <info> app: Write req to block 128 size 2(x512) from 20001804
00> 
00> [00:00:00.066,467] <info> app: Write req to block 128 size 2(x512) from 20001804
00> 
00> [00:00:00.066,528] <info> app: Write req to block 64 size 1(x512) from 20001804
00> 
00> [00:00:00.066,528] <info> app: writeback_mode:idx:0x10,dirty_blocks:255
00> 
00> [00:00:00.066,528] <info> app: erase:addr:10000 block:128, id:16
00> 
00> [00:00:00.076,416] <info> app: Write req to block 63 size 1(x512) from 20001804
00> 
00> [00:00:00.076,416] <info> app: writeback_mode:idx:0x8,dirty_blocks:255
00> 
00> [00:00:00.076,416] <info> app: erase:addr:8000 block:64, id:8
00> 
00> [00:00:00.086,669] <info> app: Write req to block 64 size 1(x512) from 20001804
00> 
00> [00:00:00.086,669] <info> app: writeback_mode:idx:0x7,dirty_blocks:255
00> 
00> [00:00:00.086,669] <info> app: erase:addr:7000 block:56, id:7
00> 
00> [00:00:00.096,435] <info> app: Read req from block 63 size 2(x512) to 20001804
00> 
00> [00:00:00.096,679] <info> app: Read req from block 65 size 2(x512) to 20001C04
00> 
00> [00:00:00.096,984] <info> app: Read req from block 67 size 2(x512) to 20001804
00> 
00> [00:00:00.097,229] <info> app: Read req from block 69 size 2(x512) to 20001C04
00> 
00> [00:00:00.097,534] <info> app: Read req from block 71 size 2(x512) to 20001804
00> 
00> [00:00:00.097,839] <info> app: Read req from block 73 size 2(x512) to 20001C04
00> 
00> [00:00:00.098,083] <info> app: Read req from block 75 size 2(x512) to 20001804
00> 
00> [00:00:00.098,327] <info> app: Read req from block 77 size 2(x512) to 20001C04
00>

    I attached the project file below .

    Please replace the nrf_block_dev_qspi.c of the SDK, I use RTT for logging output and  test on the nRF5_SDK_17.0.2.

  • 0 in reply to user85932

    Hi,

    I have asked the maintainers to review the logs and provide input. I will let you know when we have something.

    Einar

  • 0 in reply to user7377

    Hi Einar, 

    One more finding.

    1.Plug the USB into the PC and create a new file from the PC

    2. Disconnect the USB, and plug the USB into the PC again, the PC pops up the following message.

    • Reply Children
    • 0 in reply to user85932

      Thanks for the update. I do not have any news from my side atm.

    • 0 in reply to user7377

      Hi,

      Have you had any progress on this issue on your side?

      I had a meeting with the R&D team responsible for this yesterday, and the current state is that after a thorough inspection of the code we cannot see an issue with the blockdevice code that would result in the observed corruption. In other words, we cannot see by analysis, a code path that would result in this. This does not mean that we have ruled out that there is an issue.

      As we are not able to reproduce the corruption itself, we suggest that we provide you with a modified library that has instrumentation to detect some unexpected changes/states/behaviors. Would you be willing to use that in our testing to help narrow down the issue?

      Another hypothesis that came up was that there could be a reentrancy issue where you call from multiple interrupt contexts (into the blockdevice code. Could that be the case?

    • 0 in reply to user7377

      Hi Einar,

      Thanks for the update.

      user7377 said:
      Have you had any progress on this issue on your side?

      No，we haven't made any progress.

      user7377 said:
      I had a meeting with the R&D team responsible for this yesterday, and the current state is that after a thorough inspection of the code we cannot see an issue with the blockdevice code that would result in the observed corruption. In other words, we cannot see by analysis, a code path that would result in this. This does not mean that we have ruled out that there is an issue.

      What I understand so far, this issue likely occurs while connecting to the PC and copying files to the MSC from the PC side. Our products can be upgraded by copying the firmware to MSC. I have asked our test team to check the MSC before and after the upgrade, it's still being tested.

      user85932 said:
      After the patch was applied, although this issue couldn't be reproduced, I found some unexpected write operation while connect to the PC.  
      user85932 said:

      One more finding.

      1.Plug the USB into the PC and create a new file from the PC

      Have you fixed these problems? They can be reproduced on the Nordic DK. I think if these are fixed, this issue will probably be fixed.

      user7377 said:
      As we are not able to reproduce the corruption itself, we suggest that we provide you with a modified library that has instrumentation to detect some unexpected changes/states/behaviors. Would you be willing to use that in our testing to help narrow down the issue?

      Yes, of course. 

      user7377 said:
      Another hypothesis that came up was that there could be a reentrancy issue where you call from multiple interrupt contexts (into the blockdevice code. Could that be the case?

      I don't think so. We do not use any RTOS, nor do we do any file operations in the interrupt service.

    • 0 in reply to user85932

      Hi,

      greyorbit said:
      What I understand so far, this issue likely occurs while connecting to the PC and copying files to the MSC from the PC side. Our products can be upgraded by copying the firmware to MSC. I have asked our test team to check the MSC before and after the upgrade, it's still being tested.

      It will be interesting to learn the result of that test.

      greyorbit said:
      Have you fixed these problems? They can be reproduced on the Nordic DK. I think if these are fixed, this issue will probably be fixed.

      I was not able to reproduce the issue with warnings on Windows on my side, but I managed once to get a corrupt file while coping new files, disconnect, reconnect, copy new file, etc. I agree it seems reasonable that the same root cause can be the cause of all this though we cannot say for sure at this point.

      I will let you know when the team investigating this have any progress, if they have any questions and when they have some code we would like you to test.

    • 0 in reply to user7377

      Hi,

      user7377 said:
      I was not able to reproduce the issue with warnings on Windows on my side

      I test on the Windows 10 Pro. I can also reproduce this problem in another product that is not developed by us, and it also uses NRF52840.

    Related
    Terms of service