Description: FS-Cache: Duplicate cookie detected after updating Arch Linux yesterday. (This was the first update in a couple weeks.) Additional info: * package version(s) 4.17.2-1-ARCH #1 SMP PREEMPT Sat Jun 16 11:08:59 UTC 2018 x86_64 GNU/Linux * config and/or log files etc. kernel: FS-Cache: Duplicate cookie detected kernel: FS-Cache: O-cookie c=000000001e72b895 [p=0000000089da8da7 fl=222 nc=0 na=1] kernel: FS-Cache: O-cookie d=00000000c3a2cbed n=00000000f757123a kernel: FS-Cache: O-key=[10] '040002000801c0a805c3' kernel: FS-Cache: N-cookie c=00000000ea48db1d [p=0000000089da8da7 fl=2 nc=0 na=1] kernel: FS-Cache: N-cookie d=00000000c3a2cbed n=000000000f72327e kernel: FS-Cache: N-key=[10] '040002000801c0a805c3' The machine is an Intel Core i7 and Asus Z170WS motherboard. Steps to reproduce: Boot system and check `journalctl -b -p err` (I'm sorry about the formatting. I'm not able to find formatting help.)
We are seeing this on each system (i.e., NFS client) as we update the kernels. Linux 4.17.2-1-ARCH #1 SMP PREEMPT Sat Jun 16 11:08:59 UTC 2018 x86_64 GNU/Linux All clients are Arch Linux and the NFS server is Arch Linux
Same problem here:- Fedora 28 x86_64 # uname -r # 4.17.2-200.fc28.x86_64 Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000db12e0e0 [p=000000009b121f93 fl=212 nc=0 na=0] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=00000000c9409ef1 [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=00000000e8f1ac26 Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000db12e0e0 [p=000000009b121f93 fl=212 nc=0 na=0] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=00000000964082ff [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=000000001f536e83 Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000db12e0e0 [p=000000009b121f93 fl=212 nc=0 na=0] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=00000000bc41f6a5 [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=000000003128b81a Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000db12e0e0 [p=000000009b121f93 fl=212 nc=0 na=0] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=0000000053708379 [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=0000000039f900f6 Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000db12e0e0 [p=000000009b121f93 fl=212 nc=0 na=0] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=000000002a007dbf [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=000000007c108fe3 Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=000000002ab03e84 [p=000000009b121f93 fl=222 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d=00000000d7b9b75b n=00000000b853a8ee Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=00000000e7e093b9 [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=00000000945ea721 Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000c9409ef1 [p=000000009b121f93 fl=222 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d=00000000d7b9b75b n=000000001457c555 Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=000000002a007dbf [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=0000000058e97a5a Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000c9409ef1 [p=000000009b121f93 fl=222 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=000000004268bcbb [p=000000009b121f93 fl=212 nc=0 na=0] Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '04 Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] ' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=000000000b84e785 [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=000000008bb85de9 Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000843e3416 [p=000000009b121f93 fl=212 nc=0 na=0] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '04000200 Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=00000000964082ff [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=0000000082425ed3 Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] ' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=00000000dbf8ebfe [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=00000000a1e88c70 Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000c9409ef1 [p=000000009b121f93 fl=212 nc=0 na=0] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=000000000b84e785 [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=000000002de42a5c Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000c9409ef1 [p=000000009b121f93 fl=212 nc=0 na=0] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=000000002a007dbf [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=0000000071ab2f2d Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: Duplicate cookie detected Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie c=00000000964082ff [p=000000009b121f93 fl=212 nc=0 na=0] Jun 25 13:13:37 musi kernel: FS-Cache: O-cookie d= (null) n= (null) Jun 25 13:13:37 musi kernel: FS-Cache: O-key=[10] '040002000801c0a8000a' Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie c=000000002a007dbf [p=000000009b121f93 fl=2 nc=0 na=1] Jun 25 13:13:37 musi kernel: FS-Cache: N-cookie d=00000000d7b9b75b n=000000003f381e0c Jun 25 13:13:37 musi kernel: FS-Cache: N-key=[10] '040002000801c0a8000a'
Still persists for 4.17.3-200.fc28.x86_64
Same problem since today on Archlinux client: Linux 4.17.4-1-ARCH #1 SMP PREEMPT Tue Jul 3 15:45:09 UTC 2018 x86_64 GNU/Linux NFS does not mount anymore, it gives an access denied error.
Still persists in 4.17.6-1-ARCH #1 SMP PREEMPT Wed Jul 11 19:14:29 UTC 2018 x86_64 GNU/Linux On at least one system we are seeing problems with NFS shares not mounting at boot, but they can be mounted manually. Not sure if it is related, but the mounting issue is new and configuration has not changed.
Still occurs regularly in 4.18.6. On one system (PRODUCTION); [ 5.597516] FS-Cache: Duplicate cookie detected [ 5.597545] FS-Cache: O-cookie c=(____ptrval____) [p=(____ptrval____) fl=222 nc=0 na=1] [ 5.597568] FS-Cache: O-cookie d=(____ptrval____) n=(____ptrval____) [ 5.597589] FS-Cache: O-key=[10] '040002000801c0a8802f' [ 5.597610] FS-Cache: N-cookie c=(____ptrval____) [p=(____ptrval____) fl=2 nc=0 na=1] [ 5.597633] FS-Cache: N-cookie d=(____ptrval____) n=(____ptrval____) [ 5.597652] FS-Cache: N-key=[10] '040002000801c0a8802f' ----------------CUT---------------- [243468.028611] FS-Cache: Duplicate cookie detected [243468.028649] FS-Cache: O-cookie c=000000005298fa9f [p=00000000fadc4f4f fl=222 nc=0 na=1] [243468.028673] FS-Cache: O-cookie d=00000000ed593886 n=000000001d7d5f26 [243468.028693] FS-Cache: O-key=[10] '040002000801c0a8802f' [243468.028713] FS-Cache: N-cookie c=00000000d54ce6b9 [p=00000000fadc4f4f fl=2 nc=0 na=1] [243468.028737] FS-Cache: N-cookie d=00000000ed593886 n=00000000eff1b7bc [243468.028756] FS-Cache: N-key=[10] '040002000801c0a8802f' On another (OFFICE): [ 3.572751] FS-Cache: Duplicate cookie detected [ 3.572779] FS-Cache: O-cookie c=(____ptrval____) [p=(____ptrval____) fl=222 nc=0 na=1] [ 3.572803] FS-Cache: O-cookie d=(____ptrval____) n=(____ptrval____) [ 3.572823] FS-Cache: O-key=[10] '040002000801c0a8802f' [ 3.572844] FS-Cache: N-cookie c=(____ptrval____) [p=(____ptrval____) fl=2 nc=0 na=1] [ 3.572867] FS-Cache: N-cookie d=(____ptrval____) n=(____ptrval____) [ 3.572886] FS-Cache: N-key=[10] '040002000801c0a8802f' [ 3.713774] FS-Cache: Duplicate cookie detected [ 3.713801] FS-Cache: O-cookie c=(____ptrval____) [p=(____ptrval____) fl=222 nc=0 na=1] [ 3.713830] FS-Cache: O-cookie d=(____ptrval____) n=(____ptrval____) [ 3.713849] FS-Cache: O-key=[10] '040002000801c0a8802f' [ 3.713871] FS-Cache: N-cookie c=(____ptrval____) [p=(____ptrval____) fl=2 nc=0 na=1] [ 3.713893] FS-Cache: N-cookie d=(____ptrval____) n=(____ptrval____) [ 3.713913] FS-Cache: N-key=[10] '040002000801c0a8802f' [ 3.714992] FS-Cache: Duplicate cookie detected [ 3.715019] FS-Cache: O-cookie c=(____ptrval____) [p=(____ptrval____) fl=222 nc=0 na=1] [ 3.715043] FS-Cache: O-cookie d=(____ptrval____) n=(____ptrval____) [ 3.715073] FS-Cache: O-key=[10] '040002000801c0a88031' [ 3.715094] FS-Cache: N-cookie c=(____ptrval____) [p=(____ptrval____) fl=2 nc=0 na=1] [ 3.715117] FS-Cache: N-cookie d=(____ptrval____) n=(____ptrval____) [ 3.715136] FS-Cache: N-key=[10] '040002000801c0a88031' [ 3.750580] FS-Cache: Duplicate cookie detected [ 3.750607] FS-Cache: O-cookie c=(____ptrval____) [p=(____ptrval____) fl=222 nc=4 na=1] [ 3.750631] FS-Cache: O-cookie d=(____ptrval____) n=(____ptrval____) [ 3.750651] FS-Cache: O-key=[10] '040002000801c0a8802f' [ 3.750672] FS-Cache: N-cookie c=(____ptrval____) [p=(____ptrval____) fl=2 nc=0 na=1] [ 3.750695] FS-Cache: N-cookie d=(____ptrval____) n=(____ptrval____) [ 3.750714] FS-Cache: N-key=[10] '040002000801c0a8802f' [ 3.905088] CacheFiles: Loaded [ 3.914303] FS-Cache: Cache "mycache" added (type cachefiles) [ 3.914305] CacheFiles: File cache on sdb1 registered [ 3.981049] FS-Cache: Duplicate cookie detected [ 3.981075] FS-Cache: O-cookie c=(____ptrval____) [p=(____ptrval____) fl=222 nc=0 na=1] [ 3.981101] FS-Cache: O-cookie d=(____ptrval____) n=(____ptrval____) [ 3.981131] FS-Cache: O-key=[10] '040002000801c0a8802f' [ 3.981152] FS-Cache: N-cookie c=(____ptrval____) [p=(____ptrval____) fl=2 nc=0 na=1] [ 3.981211] FS-Cache: N-cookie d=(____ptrval____) n=(____ptrval____) [ 3.981227] FS-Cache: N-key=[10] '040002000801c0a8802f' [ 4.020095] FS-Cache: Duplicate cookie detected [ 4.020122] FS-Cache: O-cookie c=(____ptrval____) [p=(____ptrval____) fl=222 nc=5 na=1] [ 4.020147] FS-Cache: O-cookie d=(____ptrval____) n=(____ptrval____) [ 4.020166] FS-Cache: O-key=[10] '040002000801c0a8802f' [ 4.020187] FS-Cache: N-cookie c=(____ptrval____) [p=(____ptrval____) fl=2 nc=0 na=1] [ 4.020210] FS-Cache: N-cookie d=(____ptrval____) n=(____ptrval____) [ 4.020230] FS-Cache: N-key=[10] '040002000801c0a8802f' [17638.919246] FS-Cache: Duplicate cookie detected [17638.919274] FS-Cache: O-cookie c=00000000147e71bd [p=00000000ac34690f fl=222 nc=0 na=1] [17638.919296] FS-Cache: O-cookie d=00000000ba3acacd n=00000000f633f60c [17638.919315] FS-Cache: O-key=[10] '040002000801c0a8802f' [17638.919336] FS-Cache: N-cookie c=000000002c444bb0 [p=00000000ac34690f fl=2 nc=0 na=1] [17638.919358] FS-Cache: N-cookie d=00000000ba3acacd n=000000007162a1bd [17638.919378] FS-Cache: N-key=[10] '040002000801c0a8802f' [17638.921062] FS-Cache: Duplicate cookie detected [17638.921086] FS-Cache: O-cookie c=00000000147e71bd [p=00000000ac34690f fl=222 nc=0 na=1] [17638.921106] FS-Cache: O-cookie d=00000000ba3acacd n=00000000f633f60c [17638.921122] FS-Cache: O-key=[10] '040002000801c0a8802f' [17638.921141] FS-Cache: N-cookie c=000000003e824b22 [p=00000000ac34690f fl=2 nc=0 na=1] [17638.922101] FS-Cache: N-cookie d=00000000ba3acacd n=00000000991d0273 [17638.922569] FS-Cache: N-key=[10] '040002000801c0a8802f' [17638.973773] FS-Cache: Duplicate cookie detected [17638.974432] FS-Cache: O-cookie c=00000000b0f6ec39 [p=00000000ac34690f fl=220 nc=1 na=1] [17638.974971] FS-Cache: O-cookie d=00000000ba3acacd n=00000000fc3612f3 [17638.975490] FS-Cache: O-cookie o=0000000077bdc71b [17638.976000] FS-Cache: O-key=[10] '040002000801c0a8802f' [17638.976545] FS-Cache: N-cookie c=00000000147e71bd [p=00000000ac34690f fl=2 nc=0 na=1] [17638.977010] FS-Cache: N-cookie d=00000000ba3acacd n=000000007162a1bd [17638.977566] FS-Cache: N-key=[10] '040002000801c0a8802f' [19593.186254] FS-Cache: Duplicate cookie detected [19593.187265] FS-Cache: O-cookie c=00000000b0f6ec39 [p=00000000ac34690f fl=220 nc=1 na=1] [19593.187840] FS-Cache: O-cookie d=00000000ba3acacd n=00000000fc3612f3 [19593.188302] FS-Cache: O-cookie o=0000000077bdc71b [19593.188762] FS-Cache: O-key=[10] '040002000801c0a8802f' [19593.189253] FS-Cache: N-cookie c=000000000001de54 [p=00000000ac34690f fl=2 nc=0 na=1] [19593.189853] FS-Cache: N-cookie d=00000000ba3acacd n=000000001f2473c6 [19593.190398] FS-Cache: N-key=[10] '040002000801c0a8802f' Two relevant mounts on both with the same settings. One is NFS the other NFS4. I have seen the same issue doing something similar with a SMB mount however. 192.168.128.49:<path> on /srv/shared/<path> type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=10,sec=sys,mountaddr=192.168.128.49,mountvers=3,mountport=46999,mountproto=udp,fsc,local_lock=none,addr=192.168.128.49) 192.168.128.47:<path> on <path> type nfs4 (rw,relatime,vers=4.0,rsize=131072,wsize=131072,namlen=255,hard,proto=tcp,timeo=600,retrans=10,sec=sys,clientaddr=192.168.128.45,fsc,local_lock=none,addr=192.168.128.47) This will occur even with a fresh cache after a period of time/heavy access.
Also seeing this on 4.18.6. [1480847.164687] FS-Cache: Duplicate cookie detected [1480847.164692] FS-Cache: O-cookie c=0000000087de3563 [p=00000000b77cf9f7 fl=222 nc=0 na=1] [1480847.164694] FS-Cache: O-cookie d=00000000e895c803 n=00000000544279fb [1480847.164695] FS-Cache: O-key=[10] '0400020008010a1029a4' [1480847.164701] FS-Cache: N-cookie c=00000000f1035c51 [p=00000000b77cf9f7 fl=2 nc=0 na=1] [1480847.164702] FS-Cache: N-cookie d=00000000e895c803 n=000000002e4ef63d [1480847.164703] FS-Cache: N-key=[10] '0400020008010a1029a4'
This is still happening, seeing it here with an Ubuntu 4.19 ([201810221809](http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.19/)) kernel.
Still seeing this on 4.19.1 [35616.806254] FS-Cache: Duplicate cookie detected [35616.806256] FS-Cache: O-cookie c=0000000054686264 [p=000000001571c359 fl=222 nc=1 na=1] [35616.806257] FS-Cache: O-cookie d=00000000f208744e n=000000009669a7f3 [35616.806258] FS-Cache: O-key=[8] '020001bdac10001f' [35616.806261] FS-Cache: N-cookie c=000000004b9df41f [p=000000001571c359 fl=2 nc=0 na=1] [35616.806261] FS-Cache: N-cookie d=00000000f208744e n=00000000f7992f3b [35616.806262] FS-Cache: N-key=[8] '020001bdac10001f'
Started seeing this problem on Debian since months ago. Happens on 4.17.2 onwards, 4.18.x, 4.19.x: ``` # dmesg | egrep -i "(fs-cache|Linux version)" [ 0.000000] Linux version 4.18.0-0.bpo.1-amd64 (debian-kernel@lists.debian.org) (gcc version 6.3.0 20170516 (Debian 6.3.0-18+deb9u1)) #1 SMP Debian 4.18.6-1~bpo9+1 (2018-09-13) [ 29.192280] FS-Cache: Loaded [ 29.409773] FS-Cache: Netfs 'cifs' registered for caching [ 29.496826] FS-Cache: Duplicate cookie detected [ 29.496867] FS-Cache: O-cookie c=0000000041e46806 [p=0000000031cb431b fl=222 nc=0 na=1] [ 29.496914] FS-Cache: O-cookie d=00000000b223d91c n=00000000b2b12755 [ 29.496951] FS-Cache: O-key=[8] '020001bdaad26009' [ 29.497004] FS-Cache: N-cookie c=00000000b46cd7af [p=0000000031cb431b fl=2 nc=0 na=1] [ 29.497052] FS-Cache: N-cookie d=00000000b223d91c n=000000008c79361f [ 29.497092] FS-Cache: N-key=[8] '020001bdaad26009' [ 29.497131] FS-Cache: Duplicate cookie detected [ 29.497173] FS-Cache: O-cookie c=0000000041e46806 [p=0000000031cb431b fl=222 nc=0 na=1] [ 29.497223] FS-Cache: O-cookie d=00000000b223d91c n=00000000b2b12755 [ 29.497263] FS-Cache: O-key=[8] '020001bdaad26009' [ 29.497303] FS-Cache: N-cookie c=00000000e0cd3dc2 [p=0000000031cb431b fl=2 nc=0 na=1] [ 29.497351] FS-Cache: N-cookie d=00000000b223d91c n=00000000979642dd [ 29.497391] FS-Cache: N-key=[8] '020001bdaad26009' ``` ``` # dmesg | egrep -i "(fs-cache|Linux version)" [ 0.000000] Linux version 4.19.7 (maurom.com) (gcc version 6.3.0 20170516 (Debian 6.3.0-18+deb9u1)) #1 SMP Thu Dec 6 08:57:06 -03 2018 [ 28.172523] FS-Cache: Loaded [ 28.367743] FS-Cache: Netfs 'cifs' registered for caching [ 28.405810] FS-Cache: Duplicate cookie detected [ 28.405829] FS-Cache: O-cookie c=00000000622c2cfb [p=0000000020f157cf fl=222 nc=0 na=1] [ 28.405847] FS-Cache: O-cookie d=00000000a64ed22d n=00000000c762d573 [ 28.405863] FS-Cache: O-key=[8] '020001bdaad26009' [ 28.405879] FS-Cache: N-cookie c=00000000b9d71f03 [p=0000000020f157cf fl=2 nc=0 na=1] [ 28.405897] FS-Cache: N-cookie d=00000000a64ed22d n=0000000020b8ad4c [ 28.405912] FS-Cache: N-key=[8] '020001bdaad26009' [ 28.406274] FS-Cache: Duplicate cookie detected [ 28.406290] FS-Cache: O-cookie c=00000000622c2cfb [p=0000000020f157cf fl=222 nc=0 na=1] [ 28.406309] FS-Cache: O-cookie d=00000000a64ed22d n=00000000c762d573 [ 28.406324] FS-Cache: O-key=[8] '020001bdaad26009' [ 28.406339] FS-Cache: N-cookie c=00000000abc65d43 [p=0000000020f157cf fl=2 nc=0 na=1] [ 28.406357] FS-Cache: N-cookie d=00000000a64ed22d n=00000000c5a79a4d [ 28.406372] FS-Cache: N-key=[8] '020001bdaad26009' ``` However, there are no such messages when running kernel version 4.9.0 ``` # dmesg | egrep -i "(fs-cache|Linux version)" [ 0.000000] Linux version 4.9.0-8-amd64 (debian-kernel@lists.debian.org) (gcc version 6.3.0 20170516 (Debian 6.3.0-18+deb9u1) ) #1 SMP Debian 4.9.130-2 (2018-10-27) [ 32.030230] FS-Cache: Loaded [ 32.507149] FS-Cache: Netfs 'cifs' registered for caching ``` At least in my case, seems related to mounting remote SMB filesystems on boot. My fstab has (partially): ``` //fs1/afolder /media/afolder cifs credentials=/opt/cifs.credentials,vers=3.0,uid=username,iocharset=utf8,cache=none 0 0 //fs1/bfolder /media/bfolder cifs credentials=/opt/cifs.credentials,vers=3.0,uid=username,iocharset=utf8,cache=none 0 0 //fs1/cfolder /media/cfolder cifs credentials=/opt/cifs.credentials,vers=3.0,uid=username,iocharset=utf8,cache=none 0 0 ``` If I disable mounting those filesystems on boot (by commenting their entries), no "Duplicate cookie" message appears, not even after mounting them the manual way via the command line. ``` # dmesg | egrep -i "(fs-cache|Linux version)" [ 0.000000] Linux version 4.19.7 (maurom.com) (gcc version 6.3.0 20170516 (Debian 6.3.0-18+deb9u1)) #1 SMP Thu Dec 6 08:57:06 -03 2018 [ 120.605690] FS-Cache: Loaded [ 120.687546] FS-Cache: Netfs 'cifs' registered for caching ``` Ideas are welcome
I'm seeing this on 4.18.19 with SMBv3 mounts that are managed by autofs. This seems to happen randomly after some time. After rebooting the system the mounts ususally work again. If someone knows an alternative to rebooting of the system I'm glad to hear. # cat /etc/auto.home * -fstype=cifs,sec=krb5i,cache=strict,rw,user=&,cruid=&,cifsacl,nounix,multiuser ://example.com/home\$/& Dec 20 12:16:43 myserver.com kernel: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3), from CIFS (SMB1). To use the less secure SMB1 dialect to access old server Dec 20 12:16:43 myserver.com kernel: FS-Cache: Duplicate cookie detected Dec 20 12:16:43 myserver.com kernel: FS-Cache: O-cookie c=00000000e1b5032a [p=00000000adab294a fl=222 nc=0 na=1] Dec 20 12:16:43 myserver.com kernel: FS-Cache: O-cookie d=00000000fc0edf47 n=00000000b64ec22f Dec 20 12:16:43 myserver.com kernel: FS-Cache: O-key=[5] '686f6d6524' Dec 20 12:16:43 myserver.com kernel: FS-Cache: N-cookie c=000000001497883d [p=00000000adab294a fl=2 nc=0 na=1] Dec 20 12:16:43 myserver.com kernel: FS-Cache: N-cookie d=00000000fc0edf47 n=00000000e91fcf0f Dec 20 12:16:43 myserver.com kernel: FS-Cache: N-key=[5] '686f6d6524'
This patch [1] introduced a catalouge of maintained cookies to handle cookie collisions. However the handling of cookie collisions seems not to be implemented yet. [1] https://github.com/torvalds/linux/commit/ec0328e46d6e5d0f17372eb90ab8e333c2ac7ca9
FWIW I just started seeing this on my Fedora Rawhide desktop - I did an update, reboot, and found an SMB mount won't mount, and the logs show these "Duplicate cookie detected" errors...
Still seeing this with 5.0.0-0.rc4.git3.1.fc30.x86_64 and it still appears to 100% reliably break a SMB mount, I just cannot mount it at all. This isn't as bad for others? Seems like a critical bug to me...
Can somebody confirm if this is dangerous and can potentially lead to data corruption, or it is just a harmless warning? I looked at the changes noted in comment 12, but I'm not familiar enough with the fs-cache. I started seeing the same ``` FS-Cache: N-key=[10] '040002000801c0a80a0a' FS-Cache: N-cookie d=000000000cb4ac9d n=000000002165d4be FS-Cache: N-cookie c=000000000e05d983 [p=000000000ed8ad13 fl=2 nc=0 na=1] FS-Cache: O-key=[10] '040002000801c0a80a0a' FS-Cache: O-cookie d=000000000cb4ac9d n=00000000657f42b1 FS-Cache: O-cookie c=00000000fd6e1f0c [p=000000000ed8ad13 fl=222 nc=0 na=1] FS-Cache: Duplicate cookie detected ``` warnings after switching to NFS4 from v3. Here are the fstab entries and /proc/mounts after they are being mounted ``` url:/export1 /path1 nfs nodev,nosuid,noauto,x-systemd.automount,x-systemd.requires=network-online.target,x-systemd.idle-timeout=5min,hard,vers=4,minorversion=1,ro 0 0 url:/export2 /path2 nfs nodev,nosuid,noauto,x-systemd.automount,x-systemd.requires=network-online.target,x-systemd.idle-timeout=5min,hard,vers=4,minorversion=1,rw 0 0 url:/export1 /path1 nfs4 ro,nosuid,nodev,relatime,vers=4.1,rsize=131072,wsize=131072,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=192.168.10.100,local_lock=none,addr=192.168.10.10 0 0 url:/export2 /path2 nfs4 rw,nosuid,nodev,relatime,vers=4.1,rsize=131072,wsize=131072,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=192.168.10.100,local_lock=none,addr=192.168.10.10 0 0 ``` The server is freeBSD(freeNAS 11.2-U1) so that's the reason for the lower wsize/rsize. I use more shares but I have some mounted as RO and some as RW. Just in case it matters - when I was running vers3 the server export was RO, but during the switch to vers4 I started to only mount as RO. This is on archlinux. 4.19.x and 4.20.x kernels. Started using NFSv3 only 1-2 months ago, but never saw the warnings. I know that vers4.1 supports way more state information, so more things can potentially be cached. I even found information about write caching that let me to wondering if this can be harmful in the first place. For about a week of using NFSv4.1 I've seen the warnings only twice. It doesn't appear to happen during heavy usage. I'm not sure but looking at the timings in my case it might have something to do with the auto unmounting. I changed the idle timeouts to 30 minutes and everything is quiet for now. Also at first glance all the mounts continue to work just fine for me even after the warnings and nothing looks broken.
Oh, I should note for the record that this turned out not to actually be the problem with my CIFS mount. For some reason, it works with an explicit 'vers=3.0' but not if I let the kernel set the version. But even with the explict 'vers=3.0', the 'duplicate cookie' message shows up, so it's clearly not really *breaking* anything. Still dunno what the problem actually is, but the mount works so I'm happy. :P
Same issue on opensuse tumbleweed with kernel 5 Linux mudkip.farm 5.0.2-7-default #1 SMP Thu Mar 14 08:29:17 UTC 2019 (d1f1d19) [ 10.993318] FS-Cache: Duplicate cookie detected [ 10.993324] FS-Cache: O-cookie c=0000000001b97f10 [p=00000000896942dd fl=222 nc=0 na=1] [ 10.993325] FS-Cache: O-cookie d=00000000722c3c7e n=0000000017d4ebeb [ 10.993327] FS-Cache: O-key=[10] '040002000801c0a80032' [ 10.993331] FS-Cache: N-cookie c=000000006683aeea [p=00000000896942dd fl=2 nc=0 na=1] [ 10.993332] FS-Cache: N-cookie d=00000000722c3c7e n=000000008389ecd4 [ 10.993333] FS-Cache: N-key=[10] '040002000801c0a80032' NFS at boot fails to mount. `mount -a` as root works fine.
Dmesg on a nfs-server side is pristine (4.14.107-1-ARCH, core/nfs-utils 2.3.3-1), but a client (4.19.27-gentoo-r1, net-fs/nfs-utils 2.3.3) has got the same red lines at the end of dmesg.To be honest, nfs works just fine except that annoying log.
Same here under: 5.0.5-200.fc29.x86_64 autofs is no longer mounting. ipa.myh.com systemd[1]: Starting Performance Metrics Collector Daemon... ipa.myh.com systemd[1]: Starting NFS Mount Daemon... ipa.myh.com systemd[1]: Starting Cockpit motd updater service... ipa.myh.com systemd[1]: Starting NFS status monitor for NFSv2/3 locking.... ipa.myh.com systemd[1]: dirsrv@IPA-MYH-COM.service: Failed to load environment files: No such file or directory ipa.myh.com systemd[1]: dirsrv@IPA-MYH-COM.service: Failed to run 'start-pre' task: No such file or directory ipa.myh.com systemd[1]: dirsrv@IPA-MYH-COM.service: Failed with result 'resources'. ipa.myh.com systemd[1]: Failed to start 389 Directory Server IPA-MYH-COM.. ipa.myh.com kernel: FS-Cache: Loaded ipa.myh.com kernel: FS-Cache: Netfs 'nfs' registered for caching ipa.myh.com kernel: Key type dns_resolver registered ipa.myh.com kernel: NFS: Registering the id_resolver key type ipa.myh.com kernel: Key type id_resolver registered ipa.myh.com kernel: Key type id_legacy registered ipa.myh.com kernel: FS-Cache: Duplicate cookie detected ipa.myh.com kernel: FS-Cache: O-cookie c=000000007011665d [p=00000000389e076f fl=222 nc=0 na=1] ipa.myh.com kernel: FS-Cache: O-cookie d= (null) n= (null) ipa.myh.com kernel: FS-Cache: O-key=[10] '0400020008010a000107' ipa.myh.com kernel: FS-Cache: N-cookie c=0000000005ddac96 [p=00000000389e076f fl=2 nc=0 na=1] ipa.myh.com kernel: FS-Cache: N-cookie d=0000000008036284 n=000000003f1eb257 ipa.myh.com kernel: FS-Cache: N-key=[10] '0400020008010a000107' ipa.myh.com kernel: FS-Cache: Duplicate cookie detected ipa.myh.com kernel: FS-Cache: O-cookie c=000000007011665d [p=00000000389e076f fl=212 nc=0 na=0] ipa.myh.com kernel: FS-Cache: O-cookie d= (null) n= (null) ipa.myh.com kernel: FS-Cache: O-key=[10] '0400020008010a000107' ipa.myh.com kernel: FS-Cache: N-cookie c=00000000487556ff [p=00000000389e076f fl=2 nc=0 na=1] ipa.myh.com kernel: FS-Cache: N-cookie d=0000000008036284 n=00000000edea5f8d ipa.myh.com kernel: FS-Cache: N-key=[10] '0400020008010a000107' ipa.myh.com rpc.gssd[1003]: ERROR: can't openat nfs/clnt0: No such file or directory ipa.myh.com kernel: FS-Cache: Duplicate cookie detected ipa.myh.com kernel: FS-Cache: O-cookie c=0000000005ddac96 [p=00000000389e076f fl=222 nc=0 na=1] ipa.myh.com kernel: FS-Cache: O-cookie d=0000000008036284 n=000000003aa5c01a ipa.myh.com kernel: FS-Cache: O-key=[10] '0400020008010a000107' ipa.myh.com kernel: FS-Cache: N-cookie c=0000000076bcd936 [p=00000000389e076f fl=2 nc=0 na=1] ipa.myh.com kernel: FS-Cache: N-cookie d=0000000008036284 n=00000000d054e55b ipa.myh.com kernel: FS-Cache: N-key=[10] '0400020008010a000107' ipa.myh.com kernel: FS-Cache: Duplicate cookie detected ipa.myh.com kernel: FS-Cache: O-cookie c=0000000005ddac96 [p=00000000389e076f fl=222 nc=0 na=1] ipa.myh.com kernel: FS-Cache: O-cookie d=0000000008036284 n=000000003aa5c01a ipa.myh.com kernel: FS-Cache: O-key=[10] '0400020008010a000107' ipa.myh.com kernel: FS-Cache: N-cookie c=00000000b3ba1b92 [p=00000000389e076f fl=2 nc=0 na=1] ipa.myh.com kernel: FS-Cache: N-cookie d=0000000008036284 n=000000000e95fa2f ipa.myh.com kernel: FS-Cache: N-key=[10] '0400020008010a000107' ipa.myh.com rpc.gssd[1003]: ERROR: can't openat nfs/clnt6: No such file or directory ipa.myh.com systemd[1]: pmlogger.service: Supervising process 6965 which is not our child. We'll most likely not notice when it exits. ipa.myh.com systemd[1]: Started Performance Metrics Archive Logger. ipa.myh.com audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=pmlogger comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' ipa.myh.com kernel: FS-Cache: Duplicate cookie detected ipa.myh.com kernel: FS-Cache: O-cookie c=000000004384258c [p=00000000389e076f fl=212 nc=0 na=0] ipa.myh.com kernel: FS-Cache: O-cookie d= (null) n= (null) ipa.myh.com kernel: FS-Cache: O-key=[10] '0400020008010a000107' ipa.myh.com kernel: FS-Cache: N-cookie c=00000000a878dc03 [p=00000000389e076f fl=2 nc=0 na=1] ipa.myh.com kernel: FS-Cache: N-cookie d=0000000008036284 n=0000000005148c6c ipa.myh.com kernel: FS-Cache: N-key=[10] '0400020008010a000107'
For the record, Linux version 4.19.19 also shows this behavior. ``` 2019-02-13T14:46:33.272449+01:00 holidayincambodia kernel: [ 0.000000] Linux version 4.19.19.mx64.244 (root@theinternet.molgen.mpg.de) (gcc version 7.3.0 (GCC)) #1 SMP Tue Feb 5 13:01:13 CET 2019 […] 2019-03-14T12:40:18.869889+01:00 holidayincambodia kernel: [2498037.374943] FS-Cache: Duplicate cookie detected 2019-03-14T12:40:18.869912+01:00 holidayincambodia kernel: [2498037.374951] FS-Cache: O-cookie c=00000000aa8ea040 [p=00000000c8387bd7 fl=222 nc=0 na=1] 2019-03-14T12:40:18.869913+01:00 holidayincambodia kernel: [2498037.374951] FS-Cache: O-cookie d=00000000e3baf094 n=00000000abceffd4 2019-03-14T12:40:18.869914+01:00 holidayincambodia kernel: [2498037.374952] FS-Cache: O-key=[10] '0400020008018d0e1013' 2019-03-14T12:40:18.869916+01:00 holidayincambodia kernel: [2498037.374957] FS-Cache: N-cookie c=00000000fb4274f3 [p=00000000c8387bd7 fl=2 nc=0 na=1] 2019-03-14T12:40:18.869917+01:00 holidayincambodia kernel: [2498037.374958] FS-Cache: N-cookie d=00000000e3baf094 n=00000000ea1a1342 2019-03-14T12:40:18.869918+01:00 holidayincambodia kernel: [2498037.374958] FS-Cache: N-key=[10] '0400020008018d0e1013' ``` This is on the NFS client. We moved some servers to NFS 4.1/4.2. Maybe it is related.
Created attachment 283271 [details] I have the same problem: journalctl -b -p err Ubuntu 5.0.0-16.17-generic 5.0.8 my system crashes sometimes is there any patch available? Lutz
Still present in 5.2.1 Jul 15 13:43:06 mudkip kernel: FS-Cache: Duplicate cookie detected Jul 15 13:43:06 mudkip kernel: FS-Cache: O-cookie c=00000000a6f9cb93 [p=00000000bc03f84c fl=212 nc=0 na=0] Jul 15 13:43:06 mudkip kernel: FS-Cache: O-cookie d=0000000010676a16 n=0000000010676a16 Jul 15 13:43:06 mudkip kernel: FS-Cache: O-key=[10] '040002000801c0a80032' Jul 15 13:43:06 mudkip kernel: FS-Cache: N-cookie c=000000004ee451df [p=00000000bc03f84c fl=2 nc=0 na=1] Jul 15 13:43:06 mudkip kernel: FS-Cache: N-cookie d=00000000bf5ab627 n=0000000061623ac9 Jul 15 13:43:06 mudkip kernel: FS-Cache: N-key=[10] '040002000801c0a80032'
I can reproduce this fairly easily by running xfstests on kcephfs with fscache enabled. FWIW, I'm mounting two different directories in the same ceph filesystem and am passing a uniquifier to the fsc= option for both. [ 966.523423] libceph: client5259 fsid 9704d8a8-de76-4b99-a78d-9108304b7a52 [ 966.527437] FS-Cache: Duplicate cookie detected [ 966.528599] FS-Cache: O-cookie c=0000000041d90beb [p=ffff8883c2a62000 fl=218 nc=0 na=0, cnt=1] [ 966.530638] FS-Cache: O-cookie d=0000000000000000 n=0000000000000000 [ 966.532094] FS-Cache: O-cookie o=ffff888429d61000 [ 966.533140] FS-Cache: O-key=[20] '9704d8a8de764b99a78d9108304b7a5274657374' [ 966.534463] FS-Cache: N-cookie c=000000006826d9cf [p=ffff8883c2a62000 fl=2 nc=0 na=1, cnt=1] [ 966.536141] FS-Cache: N-cookie d=ffffffffa04a2320 n=ffff8883af454600 [ 966.537371] FS-Cache: N-key=[20] '9704d8a8de764b99a78d9108304b7a5274657374' [ 966.538700] unable to register fscache cookie for fsid 9704d8a8-de76-4b99-a78d-9108304b7a52 This is mostly happening at mount time, afaict. xfstests does a lot of mount/unmount activity and it registers and unregisters a cookie on each one.
I've been playing with a patch to try and work around this: -------------------------8<---------------------------- diff --git a/fs/fscache/cookie.c b/fs/fscache/cookie.c index b6b7aa220e6f..df731617438d 100644 --- a/fs/fscache/cookie.c +++ b/fs/fscache/cookie.c @@ -201,11 +201,22 @@ struct fscache_cookie *fscache_hash_cookie(struct fscache_cookie *candidate) bucket = candidate->key_hash & (ARRAY_SIZE(fscache_cookie_hash) - 1); h = &fscache_cookie_hash[bucket]; - +retry: hlist_bl_lock(h); hlist_bl_for_each_entry(cursor, p, h, hash_link) { - if (fscache_compare_cookie(candidate, cursor) == 0) - goto collision; + if (fscache_compare_cookie(candidate, cursor) == 0) { + if (test_bit(FSCACHE_COOKIE_ENABLED, &cursor->flags)) + goto collision; + + if (atomic_inc_not_zero(&cursor->usage)) { + hlist_bl_unlock(h); + wait_on_bit_lock(&cursor->flags, FSCACHE_COOKIE_ENABLEMENT_LOCK, TASK_UNINTERRUPTIBLE); + clear_bit_unlock(FSCACHE_COOKIE_ENABLEMENT_LOCK, &cursor->flags); + wake_up_bit(&cursor->flags, FSCACHE_COOKIE_ENABLEMENT_LOCK); + fscache_cookie_put(cursor, fscache_cookie_put_dup_netfs); + goto retry; + } + } } __set_bit(FSCACHE_COOKIE_ACQUIRED, &candidate->flags); -------------------------8<---------------------------- This seems to mostly fix the issue for me, but occasionally I'm seeing this go into an infinite loop because the usage count on the cookie never goes to zero. I suspect this is probably due to an existing refcounting bug, but I haven't been able to find it so far. Here are some tracepoints before just before it starts looping: -------------------------8<---------------------------- kworker/u16:6-3636 [002] ...1 470.692923: fscache_cookie: PUT rlq c=000000005ccd9b43 u=0 p=0000000052e4f404 Nc=0 Na=1 f=12 kworker/u16:6-3636 [002] ...1 470.692924: fscache_cookie: PUT prn c=0000000052e4f404 u=9 p=00000000fbb5c648 Nc=7 Na=1 f=20 kworker/u16:6-3636 [002] ...1 470.692965: fscache_cookie: PUT rlq c=00000000e1093eeb u=0 p=0000000052e4f404 Nc=0 Na=1 f=12 kworker/u16:6-3636 [002] ...1 470.692966: fscache_cookie: PUT prn c=0000000052e4f404 u=8 p=00000000fbb5c648 Nc=6 Na=1 f=20 kworker/u16:3-517 [005] ...1 470.693005: fscache_cookie: PUT rlq c=0000000065143ec9 u=0 p=0000000052e4f404 Nc=0 Na=1 f=12 kworker/u16:3-517 [005] ...1 470.693007: fscache_cookie: PUT prn c=0000000052e4f404 u=7 p=00000000fbb5c648 Nc=5 Na=1 f=20 kworker/u16:6-3636 [002] ...1 470.693042: fscache_cookie: PUT rlq c=000000008acf447f u=0 p=0000000052e4f404 Nc=0 Na=1 f=12 kworker/u16:6-3636 [002] ...1 470.693044: fscache_cookie: PUT prn c=0000000052e4f404 u=6 p=00000000fbb5c648 Nc=4 Na=1 f=20 kworker/u16:6-3636 [002] ...1 470.695587: fscache_cookie: PUT rlq c=000000000eb22115 u=0 p=0000000052e4f404 Nc=0 Na=1 f=12 kworker/u16:6-3636 [002] ...1 470.695589: fscache_cookie: PUT prn c=0000000052e4f404 u=5 p=00000000fbb5c648 Nc=3 Na=1 f=20 kworker/u16:6-3636 [002] ...1 470.700372: fscache_cookie: PUT rlq c=0000000058f6b4c7 u=0 p=0000000052e4f404 Nc=0 Na=1 f=12 kworker/u16:6-3636 [002] ...1 470.700376: fscache_cookie: PUT prn c=0000000052e4f404 u=4 p=00000000fbb5c648 Nc=2 Na=1 f=20 kworker/u16:6-3636 [002] ...1 470.700425: fscache_cookie: PUT rlq c=000000008d0c7880 u=0 p=0000000052e4f404 Nc=0 Na=1 f=12 kworker/u16:6-3636 [002] ...1 470.700427: fscache_cookie: PUT prn c=0000000052e4f404 u=3 p=00000000fbb5c648 Nc=1 Na=1 f=20 kworker/u16:2-146 [005] ...1 470.700847: fscache_cookie: PUT rlq c=00000000dd21d5bd u=0 p=0000000052e4f404 Nc=0 Na=1 f=12 kworker/u16:2-146 [005] ...1 470.700851: fscache_cookie: PUT prn c=0000000052e4f404 u=2 p=00000000fbb5c648 Nc=0 Na=1 f=20 umount-6891 [001] ...1 470.737960: fscache_cookie: PUT rlq c=0000000052e4f404 u=1 p=00000000fbb5c648 Nc=0 Na=0 f=18 mount.ceph-6899 [000] ...1 470.804369: fscache_cookie: PUT dnt c=0000000052e4f404 u=1 p=00000000fbb5c648 Nc=0 Na=0 f=18 mount.ceph-6899 [000] ...1 470.813654: fscache_cookie: PUT dnt c=0000000052e4f404 u=1 p=00000000fbb5c648 Nc=0 Na=0 f=18 mount.ceph-6899 [000] ...1 470.822925: fscache_cookie: PUT dnt c=0000000052e4f404 u=1 p=00000000fbb5c648 Nc=0 Na=0 f=18 mount.ceph-6899 [000] ...1 470.834443: fscache_cookie: PUT dnt c=0000000052e4f404 u=1 p=00000000fbb5c648 Nc=0 Na=0 f=18 -------------------------8<---------------------------- The u= count never seems to go to 1, so I think there's a reference leaking somewhere.
Erm... "The u= count never seems to go _below_ 1..."
A bit more debugging. I had the kernel limit the number of retries to 100, and got this to pop: [ 570.004348] FS-Cache: Duplicate cookie detected [ 570.005397] FS-Cache: O-cookie c=000000006df0abdd [i=(null) p=ffff8883f92dc000 fl=a18 nc=0 na=0, cnt=2] [ 570.009759] FS-Cache: O-cookie d=0000000000000000 n=0000000000000000 [ 570.011147] FS-Cache: O-cookie o=ffff8883f95a3400 [ 570.012169] FS-Cache: O-key=[20] '74ab262f4bde400da8e9fb3248a12a3a74657374' [ 570.013544] FS-Cache: N-cookie c=000000008763dd60 [i=CEPH.fsid p=ffff8883f92dc000 fl=2 nc=0 na=1, cnt=1] [ 570.015484] FS-Cache: N-cookie d=ffffffffa049a280 n=ffff88842b4649c0 [ 570.016763] FS-Cache: N-key=[20] '74ab262f4bde400da8e9fb3248a12a3a74657374' [ 570.018167] unable to register fscache cookie for fsid 74ab262f-4bde-400d-a8e9-fb3248a12a3a # cat /proc/fs/fscache/objects OBJECT PARENT STAT CHLDN OPS OOP IPR EX READS EM EV FL S | NETFS_COOKIE_DEF TY FL NETFS_DATA OBJECT_KEY, AUX_DATA ======== ======== ==== ===== === === === == ===== == == == = | ================ == == ================ ================ 3 0 ?CMD 1 0 0 0 0 0 6d 10 38 0 | FSDEF.netfs IX 220 7e1ffb20 63657068, 00000000 41a 3 ?CLR 0 3 3 0 0 0 10 0 30 0 | (null) IX a18 d03c946b 74ab262f4bde400da8e9fb3248a12a3a74657374 419 ffffffff DEAD 0 0 0 0 0 0 0 0 0 0 | (null) DT a12 d03c946b b6a3030000010000feffffffffffffff, b6a3030000010000feffffffffffffff00000000ad4eadde 0 ffffffff ?INI 1 0 0 0 0 0 6f 10 28 0 | .FS-Cache IX 20 d03c946b Also attaching associated trace file.
Created attachment 285615 [details] tracepoint output from the run
Same problem here. 5.3.12-1-MANJARO #1 SMP PREEMPT Thu Nov 21 10:55:53 UTC 2019 x86_64 GNU/Linux
BTW - does it make any sense to use FS-Cache for NFS clients? NFS have several techniques to speed up things like WCC, delegations and similar. I guess FS-cache makes the filesystem even less consistent, right?
(In reply to Ondrej from comment #29) > BTW - does it make any sense to use FS-Cache for NFS clients? > NFS have several techniques to speed up things like WCC, delegations and > similar. > I guess FS-cache makes the filesystem even less consistent, right? These messages show up even without 'fsc' on the mount due to how fscache is initialized during a mount. My latest tests on 5.6-rc2 even with a simple mount of two different NFS mount points from the same NFS server but different NFS versions it will show the log spam. One might argue "why would someone mount two different exports with different NFS versions from the same server?" and I think that is an open question. I'm not sure if there's other examples where the log spam shows up even when fscache is not in use due to how fscache is initialized. I confess at this point I don't know the internals too well but as I understand this, fscache is always partially initialized regardless of mount flags (possibly due to handling 'remount'?), but then only enabled at the superblock level if the flags are set.
Actually the engineer that reported this originally has figured out this also occurs if an NFS server has higher versions of NFSv4.x disabled, i.e.: # cat /proc/fs/nfsd/versions -2 +3 +4 -4.1 -4.2 and then an NFS client tries to mount 'exportA' and 'exportB' from that server without any 'vers=' lines, you get the log messages about duplicate cookies. Somehow this happens due to trying multiple NFS4 versions and failing. The per-client index cookie is allocated very early on before we know the server does not support the NFS version, though I don't fully understand yet whether this is a bug in maybe teardown when that fails or if this is inevitable due to the early partial initialization of fscache and trying different NFS4 versions.
(In reply to Dave Wysochanski from comment #31) > Actually the engineer that reported this originally has figured out this > also occurs if an NFS server has higher versions of NFSv4.x disabled, i.e.: > # cat /proc/fs/nfsd/versions > -2 +3 +4 -4.1 -4.2 > > and then an NFS client tries to mount 'exportA' and 'exportB' from that > server without any 'vers=' lines, you get the log messages about duplicate > cookies. Somehow this happens due to trying multiple NFS4 versions and > failing. The per-client index cookie is allocated very early on before we > know the server does not support the NFS version, though I don't fully > understand yet whether this is a bug in maybe teardown when that fails or if > this is inevitable due to the early partial initialization of fscache and > trying different NFS4 versions. Does this mean the message would be gone if I explicitly tell the mount options the version to use?
(In reply to Kai Krakow from comment #32) > (In reply to Dave Wysochanski from comment #31) > > Actually the engineer that reported this originally has figured out this > > also occurs if an NFS server has higher versions of NFSv4.x disabled, i.e.: > > # cat /proc/fs/nfsd/versions > > -2 +3 +4 -4.1 -4.2 > > > > and then an NFS client tries to mount 'exportA' and 'exportB' from that > > server without any 'vers=' lines, you get the log messages about duplicate > > cookies. Somehow this happens due to trying multiple NFS4 versions and > > failing. The per-client index cookie is allocated very early on before we > > know the server does not support the NFS version, though I don't fully > > understand yet whether this is a bug in maybe teardown when that fails or > if > > this is inevitable due to the early partial initialization of fscache and > > trying different NFS4 versions. > > Does this mean the message would be gone if I explicitly tell the mount > options the version to use? Yes if you force 'vers=N' for all mounts from one NFS server you won't get the messages. However, you should not need to do that so it's only a workaround.
Ok so this is "working as designed" currently, I see no teardown bug. If you force 'vers=4.0' for example with the two mounts, the second mount will find an existing 'nfs_client' via: nfs_get_client -> nfs_match_client So we won't get as far as if we had to use autonegotiation (from userspace we try 4.2, 4.1, 4.0 ... - see with "mount -vvv") where we would see a call into nfs_fscache_get_client_cookie which is called when we allocate a new nfs_client (see below backtrace). But if there is already an NFS client with a different minor version, nfs_match_client fails, we create a new client then proceed to call nfs_fscache_get_client_cookie with a key that matches the existing one, and we get a hash collision inside fscache_hash_cookie due to the key being the same. I wonder since there is a new client for each NFS minor version, as Scott Mayhew pointed out on an earlier bug, should we consider adding the minor version into the nfs_server_key as in his patch: https://marc.info/?l=linux-nfs&m=153131174316189&w=2 Or do we need further rework of this area because the fscache index for all v4.x nfs_clients should be the same? If it is correct to make a new index cookie for v3 vs v4 (i.e. the nfsversion is part of the key), then this looks like it needs the same for 4.1 and above due to the differences from 4.0. FWIW, some systemtap traces Pass 5: starting run. Mon Feb 24 12:53:01 2020 EST: nfs4_try_mount version=4 minorversion=2 Mon Feb 24 12:53:01 2020 EST: nfs_fscache_get_client_cookie 0xffffffffc0838f50 : nfs_fscache_get_client_cookie+0x0/0x120 [nfs] 0xffffffffc081cf2a : nfs_alloc_client+0xfa/0x130 [nfs] 0xffffffffc08950d3 : nfs4_alloc_client+0x13/0x1d0 [nfsv4] 0xffffffffc081d96c : nfs_get_client+0x14c/0x360 [nfs] 0xffffffffc0894af2 : nfs4_set_client+0xb2/0x100 [nfsv4] 0xffffffffc0895d3f : nfs4_create_server+0xff/0x290 [nfsv4] 0xffffffffc088e298 : nfs4_remote_mount+0x28/0x50 [nfsv4] 0xffffffffaa2ca4eb : mount_fs+0x3b/0x167 [kernel] 0xffffffffaa2e8dc4 : vfs_kern_mount.part.35+0x54/0x120 [kernel] 0xffffffffc088e1bf : nfs_do_root_mount+0x7f/0xc0 [nfsv4] 0xffffffffc088e5b3 : nfs4_try_mount+0x43/0x70 [nfsv4] 0xffffffffc082aca9 : nfs_fs_mount+0x899/0xc30 [nfs] 0xffffffffaa2ca4eb : mount_fs+0x3b/0x167 [kernel] 0xffffffffaa2e8dc4 : vfs_kern_mount.part.35+0x54/0x120 [kernel] 0xffffffffaa2eb4cc : do_mount+0x1fc/0xc80 [kernel] 0xffffffffaa2ec2d6 : ksys_mount+0xb6/0xd0 [kernel] 0xffffffffaa2ec311 : __x64_sys_mount+0x21/0x30 [kernel] 0xffffffffaa00419b : do_syscall_64+0x5b/0x1a0 [kernel] 0xffffffffaaa000ad : entry_SYSCALL_64_after_hwframe+0x65/0xca [kernel] 0xffffffffaaa000ad : entry_SYSCALL_64_after_hwframe+0x65/0xca [kernel] (inexact) Mon Feb 24 12:53:01 2020 EST: nfs4_try_mount version=4 minorversion=1 Mon Feb 24 12:53:01 2020 EST: nfs_fscache_get_client_cookie 0xffffffffc0838f50 : nfs_fscache_get_client_cookie+0x0/0x120 [nfs] 0xffffffffc081cf2a : nfs_alloc_client+0xfa/0x130 [nfs] 0xffffffffc08950d3 : nfs4_alloc_client+0x13/0x1d0 [nfsv4] 0xffffffffc081d96c : nfs_get_client+0x14c/0x360 [nfs] 0xffffffffc0894af2 : nfs4_set_client+0xb2/0x100 [nfsv4] 0xffffffffc0895d3f : nfs4_create_server+0xff/0x290 [nfsv4] 0xffffffffc088e298 : nfs4_remote_mount+0x28/0x50 [nfsv4] 0xffffffffaa2ca4eb : mount_fs+0x3b/0x167 [kernel] 0xffffffffaa2e8dc4 : vfs_kern_mount.part.35+0x54/0x120 [kernel] 0xffffffffc088e1bf : nfs_do_root_mount+0x7f/0xc0 [nfsv4] 0xffffffffc088e5b3 : nfs4_try_mount+0x43/0x70 [nfsv4] 0xffffffffc082aca9 : nfs_fs_mount+0x899/0xc30 [nfs] 0xffffffffaa2ca4eb : mount_fs+0x3b/0x167 [kernel] 0xffffffffaa2e8dc4 : vfs_kern_mount.part.35+0x54/0x120 [kernel] 0xffffffffaa2eb4cc : do_mount+0x1fc/0xc80 [kernel] 0xffffffffaa2ec2d6 : ksys_mount+0xb6/0xd0 [kernel] 0xffffffffaa2ec311 : __x64_sys_mount+0x21/0x30 [kernel] 0xffffffffaa00419b : do_syscall_64+0x5b/0x1a0 [kernel] 0xffffffffaaa000ad : entry_SYSCALL_64_after_hwframe+0x65/0xca [kernel] 0xffffffffaaa000ad : entry_SYSCALL_64_after_hwframe+0x65/0xca [kernel] (inexact) Mon Feb 24 12:53:01 2020 EST: nfs4_try_mount version=4 minorversion=0 Mon Feb 24 12:53:01 2020 EST: nfs_fscache_get_client_cookie 0xffffffffc0838f50 : nfs_fscache_get_client_cookie+0x0/0x120 [nfs] 0xffffffffc081cf2a : nfs_alloc_client+0xfa/0x130 [nfs] 0xffffffffc08950d3 : nfs4_alloc_client+0x13/0x1d0 [nfsv4] 0xffffffffc081d96c : nfs_get_client+0x14c/0x360 [nfs] 0xffffffffc0894af2 : nfs4_set_client+0xb2/0x100 [nfsv4] 0xffffffffc0895d3f : nfs4_create_server+0xff/0x290 [nfsv4] 0xffffffffc088e298 : nfs4_remote_mount+0x28/0x50 [nfsv4] 0xffffffffaa2ca4eb : mount_fs+0x3b/0x167 [kernel] 0xffffffffaa2e8dc4 : vfs_kern_mount.part.35+0x54/0x120 [kernel] 0xffffffffc088e1bf : nfs_do_root_mount+0x7f/0xc0 [nfsv4] 0xffffffffc088e5b3 : nfs4_try_mount+0x43/0x70 [nfsv4] 0xffffffffc082aca9 : nfs_fs_mount+0x899/0xc30 [nfs] 0xffffffffaa2ca4eb : mount_fs+0x3b/0x167 [kernel] 0xffffffffaa2e8dc4 : vfs_kern_mount.part.35+0x54/0x120 [kernel] 0xffffffffaa2eb4cc : do_mount+0x1fc/0xc80 [kernel] 0xffffffffaa2ec2d6 : ksys_mount+0xb6/0xd0 [kernel] 0xffffffffaa2ec311 : __x64_sys_mount+0x21/0x30 [kernel]
Created attachment 287589 [details] testcase for this bug that assumes the client and server are on the same machine # ./bug200145.sh Mon 24 Feb 2020 03:46:48 PM EST: Found 'FS-Cache: Duplicate cookie' in journal TEST FAIL on NFS client kernel 5.6.0-rc2+
FWIW, a while back David posted patches to [lkml](https://lore.kernel.org/lkml/2827.1552315718@warthog.procyon.org.uk/ "FS-Cache: Duplicate cookie detected") but I don't see them in mainline, so I guess they have not been applied, yet.
(In reply to Christian Kujau from comment #36) > FWIW, a while back David posted patches to > [lkml](https://lore.kernel.org/lkml/2827.1552315718@warthog.procyon.org.uk/ > "FS-Cache: Duplicate cookie detected") but I don't see them in mainline, so > I guess they have not been applied, yet. I posted a patch to fix the issue with multiple NFSv4 minor versions to linux-nfs https://marc.info/?l=linux-nfs&m=158257983714330&w=2 Can you see if that fixes your issue?