relan / exfat

Free exFAT file system implementation
GNU General Public License v2.0
779 stars 176 forks source link

exfat 1.3 Transport endpoint is not connected #167

Closed nlienard closed 3 years ago

nlienard commented 3 years ago

Hi I got a usb drive of 4TB. When i mount it on a windows, it works fine. When i mount it on Linux, it works but after a while (idling or with activity) , i got an issue, the drive is not accessible anymore.

root@NAS:~# mount /dev/sde2 /usb
FUSE exfat 1.3.0
WARN: volume was not unmounted cleanly.
root@NAS:~# ls -la /usb
-bash: cd: /usb: Transport endpoint is not connected

fdisk is still seeing it

root@NAS:~# fdisk -l /dev/sde
Disk /dev/sde: 3.7 TiB, 4000787029504 bytes, 7814037167 sectors
Disk model: M3 Portable
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 4096 bytes
I/O size (minimum/optimal): 4096 bytes / 4096 bytes
Disklabel type: gpt
Disk identifier: EBA66CBE-A843-4C6D-B3BF-7DD3D927F735

Device      Start        End    Sectors  Size Type
/dev/sde1      34     262177     262144  128M Microsoft reserved
/dev/sde2  264192 7814035455 7813771264  3.7T Microsoft basic data

Partition 1 does not start on physical sector boundary.

The only solution is to unplugg the disk, plug it to a windows, make a "repair", and unplug, then plug it to the linux back.

A workardound was to umount it during the night with a crontab and to mount it the morning. (still showing the WARN, but the disk was reachable).

in the log

Feb 28 07:39:12 localhost kernel: mount.exfat: page allocation failure: order:0, mode:0x1080120(GFP_ATOMIC|__GFP_COLD), nodemask=(null)
Feb 28 07:39:12 localhost kernel: mount.exfat cpuset=/ mems_allowed=0
Feb 28 07:39:12 localhost kernel: CPU: 0 PID: 12192 Comm: mount.exfat Not tainted 4.14.4 #19
Feb 28 07:39:12 localhost kernel: Hardware name: Marvell Armada 380/385 (Device Tree)
Feb 28 07:39:12 localhost kernel: [<c0111058>] (unwind_backtrace) from [<c010bcbc>] (show_stack+0x10/0x14)
Feb 28 07:39:12 localhost kernel: [<c010bcbc>] (show_stack) from [<c07c5630>] (dump_stack+0x84/0x98)
Feb 28 07:39:12 localhost kernel: [<c07c5630>] (dump_stack) from [<c01b986c>] (warn_alloc+0xc0/0x174)
Feb 28 07:39:12 localhost kernel: [<c01b986c>] (warn_alloc) from [<c01ba764>] (__alloc_pages_nodemask+0xda4/0xdfc)
Feb 28 07:39:12 localhost kernel: [<c01ba764>] (__alloc_pages_nodemask) from [<c01ba958>] (page_frag_alloc+0x13c/0x150)
Feb 28 07:39:12 localhost kernel: [<c01ba958>] (page_frag_alloc) from [<c0638f98>] (netdev_alloc_frag+0x30/0x38)
Feb 28 07:39:12 localhost kernel: [<c0638f98>] (netdev_alloc_frag) from [<c06746c4>] (hwbm_pool_refill+0x18/0x88)
Feb 28 07:39:12 localhost kernel: [<c06746c4>] (hwbm_pool_refill) from [<c0536e90>] (mvneta_poll+0x3bc/0xb2c)
Feb 28 07:39:12 localhost kernel: [<c0536e90>] (mvneta_poll) from [<c0651410>] (net_rx_action+0x290/0x398)
Feb 28 07:39:12 localhost kernel: [<c0651410>] (net_rx_action) from [<c0101664>] (__do_softirq+0xfc/0x224)
Feb 28 07:39:12 localhost kernel: [<c0101664>] (__do_softirq) from [<c0129dcc>] (irq_exit+0xa8/0xdc)
Feb 28 07:39:12 localhost kernel: [<c0129dcc>] (irq_exit) from [<c0171450>] (__handle_domain_irq+0x60/0xb4)
Feb 28 07:39:12 localhost kernel: [<c0171450>] (__handle_domain_irq) from [<c0101480>] (gic_handle_irq+0x4c/0x90)
Feb 28 07:39:12 localhost kernel: [<c0101480>] (gic_handle_irq) from [<c010c90c>] (__irq_svc+0x6c/0x90)
Feb 28 07:39:12 localhost kernel: Exception stack(0xda04fb80 to 0xda04fbc8)
Feb 28 07:39:12 localhost kernel: fb80: 00000001 00000003 00000000 e6baa200 c0b141b0 e5601000 00000003 da04fcb0
Feb 28 07:39:12 localhost kernel: fba0: e6baa200 da04fd40 00000002 00000000 00000000 da04fbd4 00000000 c01c3d40
Feb 28 07:39:12 localhost kernel: fbc0: 200f0013 ffffffff
Feb 28 07:39:12 localhost kernel: [<c010c90c>] (__irq_svc) from [<c01c3d40>] (lruvec_lru_size+0x3c/0xb0)
Feb 28 07:39:12 localhost kernel: [<c01c3d40>] (lruvec_lru_size) from [<c01c3e20>] (inactive_list_is_low+0x6c/0x174)
Feb 28 07:39:12 localhost kernel: [<c01c3e20>] (inactive_list_is_low) from [<c01c6850>] (shrink_node_memcg+0x460/0x68c)
Feb 28 07:39:12 localhost kernel: [<c01c6850>] (shrink_node_memcg) from [<c01c6b44>] (shrink_node+0xc8/0x214)
Feb 28 07:39:12 localhost kernel: [<c01c6b44>] (shrink_node) from [<c01c6d74>] (do_try_to_free_pages+0xe4/0x314)
Feb 28 07:39:12 localhost kernel: [<c01c6d74>] (do_try_to_free_pages) from [<c01c70f8>] (try_to_free_pages+0x154/0x340)
Feb 28 07:39:12 localhost kernel: [<c01c70f8>] (try_to_free_pages) from [<c01b9eac>] (__alloc_pages_nodemask+0x4ec/0xdfc)
Feb 28 07:39:12 localhost kernel: [<c01b9eac>] (__alloc_pages_nodemask) from [<c01bf7e8>] (__do_page_cache_readahead+0xe8/0x260)
Feb 28 07:39:12 localhost kernel: [<c01bf7e8>] (__do_page_cache_readahead) from [<c01b3cd0>] (generic_file_read_iter+0x634/0x940)
Feb 28 07:39:12 localhost kernel: [<c01b3cd0>] (generic_file_read_iter) from [<c0202ca4>] (__vfs_read+0xd0/0x120)
Feb 28 07:39:12 localhost kernel: [<c0202ca4>] (__vfs_read) from [<c0202d80>] (vfs_read+0x8c/0x118)
Feb 28 07:39:12 localhost kernel: [<c0202d80>] (vfs_read) from [<c020336c>] (SyS_pread64+0x78/0x90)
Feb 28 07:39:12 localhost kernel: [<c020336c>] (SyS_pread64) from [<c0107900>] (ret_fast_syscall+0x0/0x48)
Feb 28 07:39:12 localhost kernel: Mem-Info:
Feb 28 07:39:12 localhost kernel: active_anon:8682 inactive_anon:11924 isolated_anon:0
Feb 28 07:39:12 localhost kernel: active_file:41737 inactive_file:158333 isolated_file:0
Feb 28 07:39:12 localhost kernel: unevictable:1 dirty:5205 writeback:0 unstable:0
Feb 28 07:39:12 localhost kernel: slab_reclaimable:11704 slab_unreclaimable:14612
Feb 28 07:39:12 localhost kernel: mapped:9271 shmem:2397 pagetables:1157 bounce:0
Feb 28 07:39:12 localhost kernel: free:1677 free_pcp:152 free_cma:0
Feb 28 07:39:12 localhost kernel: Node 0 active_anon:34728kB inactive_anon:47696kB active_file:166948kB inactive_file:633332kB unevictable:4kB isolated(anon):0kB isolated(file):0kB mapped:37084kB dirty:20820kB writeback:0kB shmem:9588kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Feb 28 07:39:12 localhost kernel: Normal free:4328kB min:3492kB low:4364kB high:5236kB active_anon:14044kB inactive_anon:25028kB active_file:138316kB inactive_file:455392kB unevictable:4kB writepending:20872kB present:786432kB managed:766444kB mlocked:0kB kernel_stack:1736kB pagetables:4628kB bounce:0kB free_pcp:348kB local_pcp:28kB free_cma:0kB
Feb 28 07:39:12 localhost kernel: lowmem_reserve[]: 0 2048 2048
Feb 28 07:39:12 localhost kernel: HighMem free:2380kB min:256kB low:556kB high:856kB active_anon:20692kB inactive_anon:22600kB active_file:28856kB inactive_file:177632kB unevictable:0kB writepending:36kB present:262144kB managed:262144kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:260kB local_pcp:208kB free_cma:0kB
Feb 28 07:39:12 localhost kernel: lowmem_reserve[]: 0 0 0
Feb 28 07:39:12 localhost kernel: Normal: 1*4kB (H) 1*8kB (H) 1*16kB (H) 1*32kB (H) 1*64kB (H) 1*128kB (H) 1*256kB (H) 1*512kB (H) 1*1024kB (H) 1*2048kB (H) 0*4096kB = 4092kB
Feb 28 07:39:12 localhost kernel: HighMem: 396*4kB (UM) 80*8kB (UM) 4*16kB (U) 1*32kB (U) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2320kB
Feb 28 07:39:12 localhost kernel: 204793 total pagecache pages
Feb 28 07:39:12 localhost kernel: 2272 pages in swap cache
relan commented 3 years ago

Looks like the kernel runs out of memory and starts killing user-space programs.

fuse-exfat can consume quite a lot of memory depending on the number of files. What happens if you mount your exFAT partition and run find /usb?

What does exfatfsck /dev/sde2 say after the crash?

nlienard commented 3 years ago

it didn't end good

root@NAS:~# exfatfsck /dev/sde2
exfatfsck 1.3.0
Checking file system on /dev/sde2.
WARN: volume was not unmounted cleanly.
File system version           1.0
Sector size                 512 bytes
Cluster size                  1 MB
Volume size                3726 GB
Used space                 3040 GB
Available space             686 GB
Killed
root@NAS:~#

LOG:

Mar  1 13:21:56 localhost kernel: oom_reaper: reaped process 28054 (exfatfsck), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

it is a NAS with 1GB of memory. This is the issue ?

root@NAS:~# free -m
              total        used        free      shared  buff/cache   available
Mem:           1004         158         245          11         600         810
Swap:           486         153         333

I'm going to add 2GB of swap to see if it changes anything....

nlienard commented 3 years ago

done.

root@NAS:/# swapon /data/stuff/swapfile
root@NAS:/# swapon /data/stuff/swapfile2
root@NAS:/# free -m
              total        used        free      shared  buff/cache   available
Mem:           1004         163         238          11         602         805
Swap:          2486         153        2333
root@NAS:/#

Running exfatfsck finished this time:

root@NAS:/# exfatfsck /dev/sde2
exfatfsck 1.3.0
Checking file system on /dev/sde2.
WARN: volume was not unmounted cleanly.
File system version           1.0
Sector size                 512 bytes
Cluster size                  1 MB
Volume size                3726 GB
Used space                 3040 GB
Available space             686 GB
Totally 36495 directories and 130311 files.
File system checking finished. No errors found.
root@NAS:/#

and mount works:

root@NAS:/# mount /dev/sde2 /usb
FUSE exfat 1.3.0
root@NAS:/#

but still error:

root@NAS:/# ls -la /usb
ls: cannot access '/usb': Transport endpoint is not connected
root@NAS:/#
relan commented 3 years ago

Looks like fuse-exfat uses too much memory.

How many files are there on this volume?

nlienard commented 3 years ago

Around 130 000

relan commented 3 years ago

Created a 4 TB volume with 130 000 files, fuse-exfat's RSS grew up to 102 MB. That's x86_64, armv7 binary should consume even less...

nlienard commented 3 years ago

sorry, i provided a bad value based on exfatfsck output posted previously.

Checking inode number with df -i gave 3 millions files:

root@NAS:~# df -i /usb
Filesystem      Inodes   IUsed  IFree IUse% Mounted on
/dev/sdc2      3815302 3112993 702309   82% /usb

memory consumation is low (around 99MB) for now:

root@NAS:~# ps auxww |grep [e]xfa
root     20730  2.0  9.5  99416 98276 ?        Ss   Mar02  31:09 /sbin/mount.exfat /dev/sdc2 /usb -o rw
relan commented 3 years ago

sorry, i provided a bad value based on exfatfsck output posted previously.

That was the correct value.

Checking inode number with df -i gave 3 millions files

df -i shows meaningless numbers, see fuse_exfat_statfs() in the code:

    /*
       Below are fake values because in exFAT there is
       a) no simple way to count files;
       b) no such thing as inode;
       So here we assume that inode = cluster.
    */
    sfs->f_files = le32_to_cpu(ef.sb->cluster_count);
    sfs->f_favail = sfs->f_bfree >> ef.sb->spc_bits;
    sfs->f_ffree = sfs->f_bavail;

memory consumation is low (around 99MB) for now

I wouldn't say 99 MB is low when there's only 1 GB of system memory in total :)

There are at least two optimizations that can be done in fuse-exfat:

1) Allocate file name strings dynamically. Now they're the part of struct exfat_node and use 512 bytes each. 2) Discard unused subtrees of struct exfat_node.

None of those is easy.

nlienard commented 3 years ago

Ok, For "df -i" good to know, thanks.

Since i added swap files, i didn't experience the OOM on exfat process.

I also added a protection against OOM killer on exfat process:

root@NAS:~# ps auxw |grep [e]xf
root     20730  1.0  8.4 100504 87124 ?        Ss   Mar02  31:42 /sbin/mount.exfat /dev/sdc2 /usb -o rw
root@NAS:~# echo -1000 >  /proc/20730/oom_score_adj
root@NAS:~#

Hope it is solved !

For the optimizations, will make a try if i got the OOM coming back.

Thanks again

nlienard commented 3 years ago

Still good today, 2 full days without issue. looks like it is good. I close the issue for now. thanks for your support.