pca10059 file system issues with CP 5.0-beta.0

[jerryneedell]

Just a heads up that I have run into serious issues with the current master CP build for the pca10059.

Attempting to erase files from the file system or executing storage.erase_filesystem() causes the board to hang and be completely unusable --and caused my linux box to hang!!
I reproduced this on 2 different pca10059's
I had to reflash the bootloader via J-Link to recover the board -- it works fine with CP 4.1.0

I'll do more testing tomorrow, but wanted to put out a warning.

I seemed to work OK at first when just loading the latest build - I was able to execute files already on the board. The problems occurred when I tried to erase old library files to update them.

[jerryneedell]

Test case:
Reflash bootlader using J-Link -- from Adafruit_nRF52_Bootloader
make BOARD = pca10059 erase
make BOARD = pca10059 sd
make BOARD = pca10059 flash

load CP 4.1.0 to board
copy " blinky.py" to board
all OK -- can erase/rcopy blinky.py
leave blinky.py on board

load CP5.0 (current master build)
looks OK -- blinky.py executive OK via REPL
delete blinky. py
rm /media/jerryneedell/CIRCUITPY/blinky.py
PCA10059 hangs -- eventually disconnects from USB

reboot - single reset fails -- can connect to USB but no REPL

double RESET does not work -- does not mount NRFBOOT

attempted to run "df" on linux box -- linux box hung for a few minutes - eventually responded to control C

reloaded booloader and CP4.1.0 -- working normally

here are the dimesg logs with attempt to reconstruct the steps -- tried to correlate activities, but timing may not be completely accurate:
initial connect -- all good

[Sat Nov 30 05:51:34 2019] usb 3-2.2.1: new full-speed USB device number 18 using xhci_hcd
[Sat Nov 30 05:51:34 2019] usb 3-2.2.1: New USB device found, idVendor=239a, idProduct=802a
[Sat Nov 30 05:51:34 2019] usb 3-2.2.1: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[Sat Nov 30 05:51:34 2019] usb 3-2.2.1: Product: PCA10059
[Sat Nov 30 05:51:34 2019] usb 3-2.2.1: Manufacturer: Nordic Semiconductor
[Sat Nov 30 05:51:34 2019] usb 3-2.2.1: SerialNumber: D7B5EC5C3CC583EC
[Sat Nov 30 05:51:34 2019] cdc_acm 3-2.2.1:1.0: ttyACM0: USB ACM device
[Sat Nov 30 05:51:34 2019] usb-storage 3-2.2.1:1.2: USB Mass Storage device detected
[Sat Nov 30 05:51:34 2019] scsi host7: usb-storage 3-2.2.1:1.2
[Sat Nov 30 05:51:34 2019] input: Nordic Semiconductor PCA10059 as /devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2.2/3-2.2.1/3-2.2.1:1.3/0003:239A:802A.000C/input/input22
[Sat Nov 30 05:51:34 2019] hid-generic 0003:239A:802A.000C: input,hidraw1: USB HID v1.11 Keyboard [Nordic Semiconductor PCA10059] on usb-0000:00:14.0-2.2.1/input3
[Sat Nov 30 05:51:35 2019] scsi host7: scsi scan: INQUIRY result too short (5), using 36
[Sat Nov 30 05:51:35 2019] scsi 7:0:0:0: Direct-Access     Nordic S PCA10059         1.0  PQ: 0 ANSI: 2
[Sat Nov 30 05:51:35 2019] sd 7:0:0:0: Attached scsi generic sg2 type 0
[Sat Nov 30 05:51:35 2019] sd 7:0:0:0: [sdc] 513 512-byte logical blocks: (263 kB/257 KiB)
[Sat Nov 30 05:51:35 2019] sd 7:0:0:0: [sdc] Write Protect is off
[Sat Nov 30 05:51:35 2019] sd 7:0:0:0: [sdc] Mode Sense: 03 00 00 00
[Sat Nov 30 05:51:35 2019] sd 7:0:0:0: [sdc] No Caching mode page found
[Sat Nov 30 05:51:35 2019] sd 7:0:0:0: [sdc] Assuming drive cache: write through
[Sat Nov 30 05:51:35 2019]  sdc: sdc1
[Sat Nov 30 05:51:35 2019] sd 7:0:0:0: [sdc] Attached SCSI removable disk
[Sat Nov 30 05:51:35 2019] FAT-fs (sdc1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.

attempted to delete the file

[Sat Nov 30 05:56:16 2019] usb 3-2.2.1: reset full-speed USB device number 18 using xhci_hcd
[Sat Nov 30 05:56:31 2019] usb 3-2.2.1: device descriptor read/64, error -110
[Sat Nov 30 05:56:47 2019] usb 3-2.2.1: device descriptor read/64, error -110
[Sat Nov 30 05:56:47 2019] usb 3-2.2.1: reset full-speed USB device number 18 using xhci_hcd
[Sat Nov 30 05:57:03 2019] usb 3-2.2.1: device descriptor read/64, error -110
[Sat Nov 30 05:57:16 2019] usb 3-2.2.1: USB disconnect, device number 18

reboot

[Sat Nov 30 05:57:25 2019] usb 3-2.2.1: new full-speed USB device number 19 using xhci_hcd
[Sat Nov 30 05:57:25 2019] usb 3-2.2.1: New USB device found, idVendor=239a, idProduct=802a
[Sat Nov 30 05:57:25 2019] usb 3-2.2.1: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[Sat Nov 30 05:57:25 2019] usb 3-2.2.1: Product: PCA10059
[Sat Nov 30 05:57:25 2019] usb 3-2.2.1: Manufacturer: Nordic Semiconductor
[Sat Nov 30 05:57:25 2019] usb 3-2.2.1: SerialNumber: D7B5EC5C3CC583EC
[Sat Nov 30 05:57:25 2019] cdc_acm 3-2.2.1:1.0: ttyACM0: USB ACM device
[Sat Nov 30 05:57:25 2019] usb-storage 3-2.2.1:1.2: USB Mass Storage device detected
[Sat Nov 30 05:57:25 2019] scsi host7: usb-storage 3-2.2.1:1.2
[Sat Nov 30 05:57:25 2019] input: Nordic Semiconductor PCA10059 as /devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2.2/3-2.2.1/3-2.2.1:1.3/0003:239A:802A.000D/input/input23
[Sat Nov 30 05:57:25 2019] hid-generic 0003:239A:802A.000D: input,hidraw1: USB HID v1.11 Keyboard [Nordic Semiconductor PCA10059] on usb-0000:00:14.0-2.2.1/input3
[Sat Nov 30 05:57:26 2019] scsi host7: scsi scan: INQUIRY result too short (5), using 36
[Sat Nov 30 05:57:26 2019] scsi 7:0:0:0: Direct-Access     Nordic S PCA10059         1.0  PQ: 0 ANSI: 2
[Sat Nov 30 05:57:26 2019] sd 7:0:0:0: Attached scsi generic sg2 type 0
[Sat Nov 30 05:57:26 2019] sd 7:0:0:0: [sdc] 513 512-byte logical blocks: (263 kB/257 KiB)
[Sat Nov 30 05:57:26 2019] sd 7:0:0:0: [sdc] Write Protect is off
[Sat Nov 30 05:57:26 2019] sd 7:0:0:0: [sdc] Mode Sense: 03 00 00 00
[Sat Nov 30 05:57:26 2019] sd 7:0:0:0: [sdc] No Caching mode page found
[Sat Nov 30 05:57:26 2019] sd 7:0:0:0: [sdc] Assuming drive cache: write through
[Sat Nov 30 05:57:26 2019]  sdc: sdc1
[Sat Nov 30 05:57:26 2019] sd 7:0:0:0: [sdc] Attached SCSI removable disk

attempted "df"

[Sat Nov 30 05:57:35 2019] cdc_acm 3-2.2.1:1.0: failed to set dtr/rts
[Sat Nov 30 05:57:58 2019] usb 3-2.2.1: reset full-speed USB device number 19 using xhci_hcd
[Sat Nov 30 05:58:14 2019] usb 3-2.2.1: device descriptor read/64, error -110
[Sat Nov 30 05:58:29 2019] usb 3-2.2.1: device descriptor read/64, error -110
[Sat Nov 30 05:58:30 2019] usb 3-2.2.1: reset full-speed USB device number 19 using xhci_hcd
[Sat Nov 30 05:58:45 2019] usb 3-2.2.1: device descriptor read/64, error -110
[Sat Nov 30 05:59:01 2019] usb 3-2.2.1: device descriptor read/64, error -110
[Sat Nov 30 05:59:01 2019] usb 3-2.2.1: reset full-speed USB device number 19 using xhci_hcd
[Sat Nov 30 05:59:06 2019] usb 3-2.2.1: device descriptor read/8, error -110
[Sat Nov 30 05:59:12 2019] usb 3-2.2.1: device descriptor read/8, error -110
[Sat Nov 30 05:59:12 2019] usb 3-2.2.1: reset full-speed USB device number 19 using xhci_hcd
[Sat Nov 30 05:59:17 2019] usb 3-2.2.1: device descriptor read/8, error -110
[Sat Nov 30 05:59:22 2019] usb 3-2.2.1: device descriptor read/8, error -110
[Sat Nov 30 05:59:22 2019] usb 3-2.2.1: USB disconnect, device number 19
[Sat Nov 30 05:59:22 2019] sd 7:0:0:0: [sdc] tag#0 FAILED Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
[Sat Nov 30 05:59:22 2019] sd 7:0:0:0: [sdc] tag#0 CDB: Read(10) 28 00 00 00 00 02 00 00 01 00
[Sat Nov 30 05:59:22 2019] print_req_error: I/O error, dev sdc, sector 2
[Sat Nov 30 05:59:22 2019] FAT-fs (sdc1): FAT read failed (blocknr 1)
[Sat Nov 30 05:59:22 2019] FAT-fs (sdc1): FAT read failed (blocknr 1)
[Sat Nov 30 05:59:22 2019] FAT-fs (sdc1): FAT read failed (blocknr 1)
[Sat Nov 30 05:59:23 2019] usb 3-2.2.1: new full-speed USB device number 20 using xhci_hcd
[Sat Nov 30 05:59:38 2019] usb 3-2.2.1: device descriptor read/64, error -110
[Sat Nov 30 05:59:54 2019] usb 3-2.2.1: device descriptor read/64, error -110
[Sat Nov 30 05:59:54 2019] usb 3-2.2.1: new full-speed USB device number 21 using xhci_hcd
jerryneedell@Ubuntu-Macmini:~$ 

[jerryneedell]

I tried using a Maker Diary nrf52840 USB dongle and am having the same issues....
perhaps it is common to the nRF52840 builds without an SPI flash file system...

Also verified that the same issues are present on the CP 5.0-beta.0 released version

Also verified that this issue does not occur on a feather_nrf5840_express -- whew!

Also verified that the issue does not occur on a Trinket_m0 --
appears to be limited to non-express nRF52840 boards

[dhalbert]

I am revamping the internal flash partitioning and am suspicious that there’s an overlap between nvm and the file system. But it might be different problem too.

[dhalbert]

I revamped the internal flash layout, and I am still seeing some problems. CIRCUITPY will appear but then the board will crash. This does not sounds like your symptoms.

I do NOT see a problem if I compile with DEBUG=1, so it may be some kind of timing problem. Sometimes when I switch back to a non-debug build it will work for one or two times and then fail. There is no difference in the flash layout between the debug and non-debug builds, except that the firmware is bigger because it's not optimized.

[jerryneedell]

ON my PCA10059 -- I can load 5.0 Beta.1 and even execute a program that is stored on it. It is only when I try to delete a file from the board that it crashes -- hangs then disconnects
I can refresh the .uf2 file if I just do a doubletap after trying to delete one file.

I have not repeated the storage.erase_filesystem() test when it requires the J-Link to recover....

[jro22]

Last evening I built and flashed a uf2 bootloader onto an Arduino nano 33 ble board, hoping to try out CP 5.0 Beta.1. Unfortunately I think I am running into this issue as well.

After a double reset press the boot disk (NANO33BOOT) appears and I can successfully drag the CP .uf2 file to it. When the board resets, CIRCUITPY appears to mount. At this point If I'm quick I can open code.py in the mu editor, but any attempts to edit or save it fail with the board hanging and then disconnecting. No luck getting REPL to run either.

Here's a quick dump of what I was able to do from the terminal between when CIRCUITPY mounted and when it disappeared:

bad-sector:~ jolson$ df /Volumes/CIRCUITPY
Filesystem   512-blocks Used Available Capacity iused ifree %iused  Mounted on
/dev/disk2s1        477    4       473     1%     512     0  100%   /Volumes/CIRCUITPY
bad-sector:~ jolson$ ls /Volumes/CIRCUITPY/
boot_out.txt	code.py		lib
bad-sector:~ jolson$ cat /Volumes/CIRCUITPY/boot_out.txt 
Adafruit CircuitPython 5.0.0-beta.1 on 2019-12-10; Arduino Nano 33 BLE with nRF52840
bad-sector:~ jolson$ cat /Volumes/CIRCUITPY/code.py 
cat: /Volumes/CIRCUITPY/code.py: Device not configured