Bug : reuse same inode

Hi all,

I use nilfs2 on a lvm partition for recording dvb streams : it creates big files and I often deleted them quickly so there only a few files on the partition.

Today I notice a problem : where a new file were created, it takes the same inode that a file already have. So the previous file were lost, like if an hard link was made.

philippe@micro11:~$ ls -li $v
total 30051016
14 -rw-r--r-- 1 philippe users    93849600  6 févr. 14:51 f2_20110130_174456.ts
16 -rw-r--r-- 1 philippe users  8606489600  9 janv. 15:42 f3_20110107_205154.ts
14 -rw-r--r-- 1 philippe users    93849600  6 févr. 14:51 f3_20110206_144851.ts
19 -rw-r--r-- 1 philippe users 10623052800  6 févr. 19:55 f3_20110206_145141.ts
15 -rw-r--r-- 1 philippe users  4688870400 19 janv. 23:14 f4_20110119_204007.ts

The file created today is f3_20110206_144851.ts : it reuse inode 14
that the file f2_20110130_174456.ts already had. On the third column, you can see there is only one link (and not 2 as if ln was used).

Of course, I can use a snapshot to recover the old file (f2_20110130_174456.ts).

philippe@micro11:~$ ls mnt/snap2/capture -li
total 32584848
20 -rw-r--r-- 1 philippe users     4812800  5 févr. 17:43 canal_20110205_172318.ts
14 -rw-r--r-- 0 philippe users 13390412800 31 janv. 01:00 f2_20110130_174456.ts 
16 -rw-r--r-- 1 philippe users  8606489600  9 janv. 15:42 f3_20110107_205154.ts 
15 -rw-r--r-- 1 philippe users  4688870400 19 janv. 23:14 f4_20110119_204007.ts

I run Archlinux x86_64 on 2.6.37. It's my first bug report. Ask me for additionnal information if I could help.

Regards,

PhC
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi,

This directory list is already broken because the link count of "f2_20110130_174456.ts" is zero.

Can you track the past state of this file from earlier checkpoints ?

Thanks,
Ryusuke Konishi

--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Just before recording :

philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=16940 /dev/mapper/vg11a-video mnt/snap5
philippe@micro11:~$ ls -li mnt/snap5/**
18 -rw-r--r-- 1 philippe users 4434  9 janv. 15:45 mnt/snap5/channels.conf

mnt/snap5/capture:
total 19452056
16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 f3_20110107_205154.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 f4_20110119_204007.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 tf1hd_20101219_203305_schrek2.ts

mnt/snap5/cut:
total 4
19 -rw-r--r-- 1 philippe 1000 156 29 janv. 21:16 canal_20110129_181951.ts(0).Xcl
14 -rw-r--r-- 0 philippe users 4838067200 30 janv. 00:58 f5_20110125_202053.ts(0).Xcl

Start of recording :

philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=16941 /dev/mapper/vg11a-video mnt/snap6
philippe@micro11:~$ ls -li mnt/snap6/**                                                  
18 -rw-r--r-- 1 philippe users 4434  9 janv. 15:45 mnt/snap6/channels.conf

mnt/snap6/capture:
total 19454420
14 -rw-r--r-- 1 philippe users 2406400 30 janv. 17:45 f2_20110130_174456.ts
16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 f3_20110107_205154.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 f4_20110119_204007.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 tf1hd_20101219_203305_schrek2.ts

mnt/snap6/cut:
total 2368
19 -rw-r--r-- 1 philippe 1000 156 29 janv. 21:16 canal_20110129_181951.ts(0).Xcl
14 -rw-r--r-- 1 philippe users 2406400 30 janv. 17:45 f5_20110125_202053.ts(0).Xcl

That's the problem : inode 14 is reused because there was a file with 0 link (f5_20110125_202053.ts(0).Xcl) in another directory. So I tracked earlier and found that :

cp15730
-------

philippe@micro11:~$ ls -li mnt/snap5/**
18 -rw-r--r-- 1 philippe users 4434  9 janv. 15:45 mnt/snap5/channels.conf

mnt/snap5/capture:
total 19452056
16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 f3_20110107_205154.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 f4_20110119_204007.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 tf1hd_20101219_203305_schrek2.ts

mnt/snap5/cut:
total 4
14 -rw-r--r-- 1 philippe 1000 47 25 janv. 22:33 f5_20110125_202053.ts(0).Xcl

All is OK

cp15731
-------

philippe@micro11:~$ ls -li mnt/snap7/**
18 -rw-r--r-- 1 philippe users 4434  9 janv. 15:45 mnt/snap7/channels.conf

mnt/snap7/capture:
total 19452056
16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 f3_20110107_205154.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 f4_20110119_204007.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 tf1hd_20101219_203305_schrek2.ts

mnt/snap7/cut:
total 9223372036848683032
14 -rw-r--r-- 0 philippe users 6214528000 24 janv. 01:30 f5_20110125_202053.ts(0).Xcl

Size of file f5_20110125_202053.ts(0).Xcl is incorrect and it appears with 0 link.

cp15732
-------

philippe@micro11:~$ ls -li mnt/snap2/**
18 -rw-r--r-- 1 philippe users 4434  9 janv. 15:45 mnt/snap2/channels.conf

mnt/snap2/capture:
total 19452056
14 -rw-r--r-- 1 philippe users 0 29 janv. 18:19 canal_20110129_181951.ts
16 -rw-r--r-- 1 philippe users 8606489600 9 janv. 15:42 f3_20110107_205154.ts 15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 f4_20110119_204007.ts 17 -rw-r--r-- 1 philippe users 6545408000 9 janv. 15:45 tf1hd_20101219_203305_schrek2.ts

mnt/snap2/cut:
total 0
14 -rw-r--r-- 1 philippe users 0 29 janv. 18:19 f5_20110125_202053.ts(0).Xcl

Inode 14 is used by 2 files. When I deleted the file canal_20110129_181951.ts, we have the situation of the cp 16940 (the first of this mail) and a file with 0 link.

Problem is in cp15731, just before the creation of file canal_20110129_181951.ts.

PhC
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi,

Thank you for the detail report! It's really helpful.

I understood the zero link count inode was causing a chain reaction.

And the inode in question at cp15731 also seems to be overridden because gid, size, and timestamp all differs from that file at cp15730.

Can't you find another file with the inode number 14 in the snapshot cp15731 or cp15730 ?

I reviewed back unlink() implementation, but haven't found any issues so far. The problem may be rooted much deeper.

'stat' command may give us much information than 'ls -l' in this case.

Thanks,
Ryusuke Konishi

--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi,
in my previous mail, ls -li ** give all the files in the filesystem (directory capture has inode 12 and cut 13). In cp15730 and cp15731, there's only one file with inode 14.

Heres's the 3 stat outputs :

philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=15730 /dev/mapper/vg11a-video mnt/snap5
philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=15731 /dev/mapper/vg11a-video mnt/snap6
philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=15732 /dev/mapper/vg11a-video mnt/snap7

philippe@micro11:~$ stat mnt/snap5/cut/f5_20110125_202053.ts\(0\).Xcl 
  File: « mnt/snap5/cut/f5_20110125_202053.ts(0).Xcl »
  Size: 47        	Blocks: 8          IO Block: 4096   fichier
Device: fe00h/65024d	Inode: 14          Links: 1
Access: (0644/-rw-r--r--)  Uid: ( 1000/philippe)   Gid: ( 1000/ UNKNOWN)
Access: 2011-01-25 22:33:34.914556435 +0100
Modify: 2011-01-25 22:33:34.914556435 +0100
Change: 2011-01-25 22:33:34.914556435 +0100
 Birth: -

philippe@micro11:~$ stat mnt/snap6/cut/f5_20110125_202053.ts\(0\).Xcl
  File: « mnt/snap6/cut/f5_20110125_202053.ts(0).Xcl »
  Size: 6214528000	Blocks: 18446744073697366064 IO Block: 4096   fichier
Device: fe00h/65024d	Inode: 14          Links: 0
Access: (0644/-rw-r--r--)  Uid: ( 1000/philippe)   Gid: (  100/   users)
Access: 2011-01-24 01:30:02.260271565 +0100
Modify: 2011-01-24 01:30:02.260271565 +0100
Change: 2011-01-25 20:28:48.894851740 +0100
 Birth: -

File: « mnt/snap7/cut/f5_20110125_202053.ts(0).Xcl »
Size: 0 Blocks: 0 IO Block: 4096 fichier vide
Device: fe00h/65024d Inode: 14 Links: 1
Access: (0644/-rw-r--r--) Uid: ( 1000/philippe) Gid: ( 100/ users)
Access: 2011-01-29 18:19:51.719138031 +0100
Modify: 2011-01-29 18:19:51.719138031 +0100
Change: 2011-01-29 18:19:51.719138031 +0100
Birth: -

PhC
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

O.K. so, it seems like something happened at the checkpoint 15731 according to your information.

One thing wired is that the timestamp (mtime) looks to be rewinded at cp15731.

Do you have any ideas on this timestamp ?

Then, let's look back in a different perspective.

As you know, the lscp command displays the total number of inodes (ICNT). Does it match the actual number of files and directories ?

Thanks,
Ryusuke Konishi

--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi,
I pastebin all the lscp (25600 lines) at : http://dpaste.org/U6w6

As you can see, there is an activity at 2011-01-24 01:30:02.

14442  2011-01-24 01:29:56   cp    -        101         11
14443  2011-01-24 01:30:00   cp    -        925         11
14444  2011-01-24 01:30:07   cp    -        625         11
14445  2011-01-25 20:20:58   cp    -        320         12
14446  2011-01-25 20:21:05   cp    -        544         12

philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14443 /dev/mapper/vg11a-video mnt/snap4                                     
philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14444 /dev/mapper/vg11a-video mnt/snap5
philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14445 /dev/mapper/vg11a-video mnt/snap6
philippe@micro11:~$ ls -lid mnt/snap4/**/**                                                                                        
12 drwxr-xr-x 2 philippe users       4096 23 janv. 22:34 mnt/snap4/capture/
19 -rw-r--r-- 1 philippe users 4957184000 24 janv. 01:29 mnt/snap4/capture/f2_20110123_223415.ts
16 -rw-r--r-- 1 philippe users 8606489600  9 janv. 15:42 mnt/snap4/capture/f3_20110107_205154.ts
14 -rw-r--r-- 1 philippe users 6213324800 24 janv. 01:30 mnt/snap4/capture/f3_20110123_223247.ts
15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap4/capture/f4_20110119_204007.ts
17 -rw-r--r-- 1 philippe users 6545408000  9 janv. 15:45 mnt/snap4/capture/tf1hd_20101219_203305_schrek2.ts
18 -rw-r--r-- 1 philippe users       4434  9 janv. 15:45 mnt/snap4/channels.conf
13 drwxr-xr-x 2 philippe users       4096 23 janv. 22:31 mnt/snap4/cut/
philippe@micro11:~$ ls -lid mnt/snap5/**/**
12 drwxr-xr-x 2 philippe users       4096 23 janv. 22:34 mnt/snap5/capture/
19 -rw-r--r-- 1 philippe users 4958387200 24 janv. 01:30 mnt/snap5/capture/f2_20110123_223415.ts
16 -rw-r--r-- 1 philippe users 8606489600  9 janv. 15:42 mnt/snap5/capture/f3_20110107_205154.ts
14 -rw-r--r-- 1 philippe users 6214528000 24 janv. 01:30 mnt/snap5/capture/f3_20110123_223247.ts
15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap5/capture/f4_20110119_204007.ts
17 -rw-r--r-- 1 philippe users 6545408000  9 janv. 15:45 mnt/snap5/capture/tf1hd_20101219_203305_schrek2.ts
18 -rw-r--r-- 1 philippe users       4434  9 janv. 15:45 mnt/snap5/channels.conf
13 drwxr-xr-x 2 philippe users       4096 23 janv. 22:31 mnt/snap5/cut/
philippe@micro11:~$ ls -lid mnt/snap6/**/**
12 drwxr-xr-x 2 philippe users       4096 25 janv. 20:20 mnt/snap6/capture/
19 -rw-r--r-- 1 philippe users 4958387200 24 janv. 01:30 mnt/snap6/capture/f2_20110123_223415.ts
16 -rw-r--r-- 1 philippe users 8606489600  9 janv. 15:42 mnt/snap6/capture/f3_20110107_205154.ts
14 -rw-r--r-- 1 philippe users 6214528000 24 janv. 01:30 mnt/snap6/capture/f3_20110123_223247.ts
15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap6/capture/f4_20110119_204007.ts
20 -rw-r--r-- 1 philippe users    1203200 25 janv. 20:20 mnt/snap6/capture/f5_20110125_202053.ts
17 -rw-r--r-- 1 philippe users 6545408000  9 janv. 15:45 mnt/snap6/capture/tf1hd_20101219_203305_schrek2.ts
18 -rw-r--r-- 1 philippe users       4434  9 janv. 15:45 mnt/snap6/channels.conf
13 drwxr-xr-x 2 philippe users       4096 23 janv. 22:31 mnt/snap6/cut/

Interesting file is :
14 -rw-r--r-- 1 philippe users 6214528000 24 janv. 01:30 mnt/snap5/capture/f3_20110123_223247.ts

It's the timestamp, the size (6214528000) and the inode (14) of the file of the cp15731.

For your information, at 1:30 the computer shuts down with 'at' command. Another remark : 2 files were recorded simultaneously (the other one is f2_20110123_223415.ts at inode 19).

This file is delete in cp 14522. I don't see any trouble after deletion :

philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14521 /dev/mapper/vg11a-video mnt/snap1
philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14522 /dev/mapper/vg11a-video mnt/snap2
philippe@micro11:~$ sudo mount -t nilfs2 -r -o cp=14523 /dev/mapper/vg11a-video mnt/snap3
philippe@micro11:~$ ls -lid mnt/snap1/**/**                                              
12 drwxr-xr-x 2 philippe users       4096 25 janv. 20:26 mnt/snap1/capture/
16 -rw-r--r-- 1 philippe users 8606489600  9 janv. 15:42 mnt/snap1/capture/f3_20110107_205154.ts
14 -rw-r--r-- 1 philippe users 6214528000 24 janv. 01:30 mnt/snap1/capture/f3_20110123_223247.ts
15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap1/capture/f4_20110119_204007.ts
20 -rw-r--r-- 1 philippe users  192512000 25 janv. 20:28 mnt/snap1/capture/f5_20110125_202053.ts
17 -rw-r--r-- 1 philippe users 6545408000  9 janv. 15:45 mnt/snap1/capture/tf1hd_20101219_203305_schrek2.ts
18 -rw-r--r-- 1 philippe users       4434  9 janv. 15:45 mnt/snap1/channels.conf
13 drwxr-xr-x 2 philippe users       4096 25 janv. 20:27 mnt/snap1/cut/
21 -rw-r--r-- 1 philippe  1000         48 25 janv. 20:23 mnt/snap1/cut/f2_20110123_223415.ts(0).Xcl
19 -rw-r--r-- 1 philippe  1000         47 25 janv. 20:27 mnt/snap1/cut/f3_20110123_223247.ts
philippe@micro11:~$ ls -lid mnt/snap2/**/**
12 drwxr-xr-x 2 philippe users       4096 25 janv. 20:28 mnt/snap2/capture/
16 -rw-r--r-- 1 philippe users 8606489600  9 janv. 15:42 mnt/snap2/capture/f3_20110107_205154.ts
15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap2/capture/f4_20110119_204007.ts
20 -rw-r--r-- 1 philippe users  196121600 25 janv. 20:28 mnt/snap2/capture/f5_20110125_202053.ts
17 -rw-r--r-- 1 philippe users 6545408000  9 janv. 15:45 mnt/snap2/capture/tf1hd_20101219_203305_schrek2.ts
18 -rw-r--r-- 1 philippe users       4434  9 janv. 15:45 mnt/snap2/channels.conf
13 drwxr-xr-x 2 philippe users       4096 25 janv. 20:27 mnt/snap2/cut/
21 -rw-r--r-- 1 philippe  1000         48 25 janv. 20:23 mnt/snap2/cut/f2_20110123_223415.ts(0).Xcl
19 -rw-r--r-- 1 philippe  1000         47 25 janv. 20:27 mnt/snap2/cut/f3_20110123_223247.ts
philippe@micro11:~$ ls -lid mnt/snap3/**/**
12 drwxr-xr-x 2 philippe users       4096 25 janv. 20:28 mnt/snap3/capture/
16 -rw-r--r-- 1 philippe users 8606489600  9 janv. 15:42 mnt/snap3/capture/f3_20110107_205154.ts
15 -rw-r--r-- 1 philippe users 4688870400 19 janv. 23:14 mnt/snap3/capture/f4_20110119_204007.ts
20 -rw-r--r-- 1 philippe users  199731200 25 janv. 20:29 mnt/snap3/capture/f5_20110125_202053.ts
17 -rw-r--r-- 1 philippe users 6545408000  9 janv. 15:45 mnt/snap3/capture/tf1hd_20101219_203305_schrek2.ts
18 -rw-r--r-- 1 philippe users       4434  9 janv. 15:45 mnt/snap3/channels.conf
13 drwxr-xr-x 2 philippe users       4096 25 janv. 20:27 mnt/snap3/cut/
21 -rw-r--r-- 1 philippe  1000         48 25 janv. 20:23 mnt/snap3/cut/f2_20110123_223415.ts(0).Xcl
19 -rw-r--r-- 1 philippe  1000         47 25 janv. 20:27 mnt/snap3/cut/f3_20110123_223247.ts

Remark :
cp 14522 is at 2011-01-25 20:29:09
like the Change timestamp: 2011-01-25 20:28:48.894851740 +0100 that appears in the cp15731.

Last line :
5631 2011-02-07 20:27:54 cp - 21 10

And

philippe@micro11:~$ find /mnt/tmp1                   
/mnt/tmp1
/mnt/tmp1/.nilfs
/mnt/tmp1/capture
/mnt/tmp1/capture/f3_20110107_205154.ts
/mnt/tmp1/capture/tf1hd_20101219_203305_schrek2.ts
/mnt/tmp1/capture/f2_20110130_174456.ts
/mnt/tmp1/capture/f4_20110119_204007.ts
/mnt/tmp1/capture/f3_20110206_144851.ts
/mnt/tmp1/channels.conf
/mnt/tmp1/cut
/mnt/tmp1/cut/f3_20110206_145141.ts(0).Xcl

gives 10 files for me. That seems OK.

Recently I noticed this message in dmesg :

Feb  8 21:34:29 localhost kernel: nilfs_palloc_commit_free_entry: entry number 14 already freed
and
Feb  6 20:53:30 localhost kernel: nilfs_palloc_commit_free_entry: entry number 19 already freed

(remember inode 19 was the second file's one)

and the system hangs on umount the nilfs (slow task I presume) :

Feb  7 22:21:50 localhost nilfs_cleanerd[1819]: shutdown
Feb  7 22:21:50 localhost kernel: nilfs_palloc_commit_free_entry: entry number 14 already freed
Feb  7 22:22:10 localhost kernel: nilfs_palloc_commit_free_entry: entry number 14 already freed
Feb  7 22:25:12 localhost -- MARK --
Feb  7 22:27:02 localhost kernel: umount.nilfs2 D ffff88003f861bc0     0  2499   2498 0x00000000
Feb  7 22:27:02 localhost kernel: ffff88002c2cbc28 0000000000000086 ffff88002c2cbfd8 ffff88002c2cbfd8
Feb  7 22:27:02 localhost kernel: ffff88002c2cbfd8 ffff88003f861bc0 ffff88002c2cbfd8 ffff88002c2cbfd8
Feb  7 22:27:02 localhost kernel: ffff88002c2cbfd8 ffff88003f861ea0 ffff88002c2cbfd8 ffff88002c2ca000
Feb  7 22:27:02 localhost kernel: Call Trace:
Feb  7 22:27:02 localhost kernel: [<ffffffff810480bc>] ? finish_task_switch+0x3c/0xd0
Feb  7 22:27:02 localhost kernel: [<ffffffff813a3ca1>] ? schedule+0x381/0xaa0
Feb  7 22:27:02 localhost kernel: [<ffffffff810e62f0>] ? find_get_pages_tag+0x100/0x130
Feb  7 22:27:02 localhost kernel: [<ffffffff813a49bd>] schedule_timeout+0x2bd/0x340
Feb  7 22:27:02 localhost kernel: [<ffffffff810eea44>] ? write_cache_pages+0x114/0x4e0
Feb  7 22:27:02 localhost kernel: [<ffffffff8104ee9b>] ? check_preempt_wakeup+0x18b/0x240
Feb  7 22:27:02 localhost kernel: [<ffffffff810ee3f0>] ? __writepage+0x0/0x40
Feb  7 22:27:02 localhost kernel: [<ffffffff813a37d0>] wait_for_common+0xc0/0x160
Feb  7 22:27:02 localhost kernel: [<ffffffff8104fe00>] ? default_wake_function+0x0/0x10
Feb  7 22:27:02 localhost kernel: [<ffffffff813a3918>] wait_for_completion+0x18/0x20
Feb  7 22:27:02 localhost kernel: [<ffffffff81159333>] sync_inodes_sb+0x83/0x180
Feb  7 22:27:02 localhost kernel: [<ffffffff8115de00>] __sync_filesystem+0x80/0x90
Feb  7 22:27:02 localhost kernel: [<ffffffff8115de73>] sync_filesystem+0x43/0x60
Feb  7 22:27:02 localhost kernel: [<ffffffff811373df>] generic_shutdown_super+0x2f/0x100
Feb  7 22:27:02 localhost kernel: [<ffffffff811374dc>] kill_block_super+0x2c/0x50
Feb  7 22:27:02 localhost kernel: [<ffffffff81137825>] deactivate_locked_super+0x45/0x60
Feb  7 22:27:02 localhost kernel: [<ffffffff811386b5>] deactivate_super+0x45/0x60
Feb  7 22:27:02 localhost kernel: [<ffffffff81151436>] mntput_no_expire+0x86/0xf0
Feb  7 22:27:02 localhost kernel: [<ffffffff81151f37>] sys_umount+0x67/0x370
Feb  7 22:27:02 localhost kernel: [<ffffffff8100bf12>] system_call_fastpath+0x16/0x1b
Feb  7 22:29:02 localhost kernel: umount.nilfs2 D ffff88003f861bc0     0  2499   2498 0x00000000

Now I don't use this filesystem. I just keep it for debug and umount if OK.

Regards,

PhC
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi,

Thank you for the cooperation.

Yeah, this file is exactly the file that overrode
"f5_20110125_202053.ts(0).Xcl" at cp15731.

I don't know why the past inode overrode the latest inode. One possible explanation is that garbage collection caused this interference, and another is interference by a snapshot mount for the checkpoint 14444.

Were you mounting the snapshot cp14444 when "f5_20110125_202053.ts(0).Xcl" was destroyed at cp15731 ?

If not, dummy on-memory inodes used for the garbage collection seem suspicious to me.

Regards,
Ryusuke Konishi
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi,
the first time I used snapshot on this fs is when I lost a file because of inode's reuse (my first mail). When file f5_...Xcl was deleted at cp15731, cp14444 was not a ss and wasn't mounted. And there were no ss on this fs (only cp).

Tell me if you need additional information. This partition's size is 200G and I'll need that space in a few days.

Regards,

PhC
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi,

I found GC never causes such interference. So, the inode corruption was not caused neither by the snapshot mount nor GC.

Now, I'm suspecting a race condition between the removal of "f3_20110123_223247.ts" and creation of "f5_20110125_202053.ts(0).Xcl".

Even though "f3_20110123_223247.ts" was removed at cp14522 (2011-01-25 20:29:09) from the "capture" directory, it seems like actual removal of the inode happened a bit later than that since the file size was pretty big.

OK, but, please resend me the checkpoint list you pasted last week before reusing the disk. The list looks like expired on the web (sorry, it's missing on my PC).

Thanks,
Ryusuke Konishi
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

On my computer, deletion of a .ts file takes ~ 4-6 seconds (~1s/1G). It may happend that a *.Xcl file is created during this time.

I make a little test with that fs. During the deletion of the file f3_20110107_205154.ts (inode 16), in a another console, I touch a file about every second :

The result :

19 -rw-r--r-- 1 philippe users    0 19 févr. 14:54 test1
20 -rw-r--r-- 1 philippe users    0 19 févr. 14:54 test2
22 -rw-r--r-- 1 philippe users    0 19 févr. 14:55 test3
23 -rw-r--r-- 1 philippe users    0 19 févr. 14:55 test4
16 -rw-r--r-- 1 philippe users    0 19 févr. 14:55 test5

test1, 2, 3, 4 were created instantaneously while the ts file was deleting. But not test5 : touch command waits ~ 2-3 seconds until the rm was finished on the other console. It has the same inode that the deleted file. At final, filesystem seems OK but this time zone where the created file reuse the old inode during a file deletion seems a good candidate for race condition.

I ask myself : is it mandatory to reuse inode number in nilfs design ?

Here is the same checkpoint list that I pasted last week (not the actual) with no expiration time : http://dpaste.org/UmEb/

In fact, I will keep this partition and continue to use it. So I delete the 2 files that share the same inode (cf. my first mail). For the 2nd rm, I have the message :
NILFS warning (device dm-0): nilfs_do_unlink: deleting nonexistent file (14), 0

I touch some files after that :

14 -rw-r--r-- 1 philippe users    0 19 févr. 14:58 test6
24 -rw-r--r-- 1 philippe users    0 19 févr. 14:58 test7
25 -rw-r--r-- 1 philippe users    0 19 févr. 14:59 test8

Filesystem seems OK and I will send a new mail if new trouble appears. Thanks for your help,

Regards,

PhC
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html