Bug : reuse same inode

Bug : reuse same inode

[Philippe CHATAIGNON]

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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Bug : reuse same inode

[Ryusuke Konishi]

Hi,
On Sun, 6 Feb 2011 20:09:28 +0100, Philippe CHATAIGNON wrote:
> 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 

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

> 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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Bug : reuse same inode

[Philippe CHATAIGNON]

Le Mon, 07 Feb 2011 13:02:14 +0900 (JST),
Ryusuke Konishi <ryusuke-sG5X7nlA6pw@public.gmane.org> a écrit :

> Can you track the past state of this file from earlier checkpoints ?
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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Bug : reuse same inode

[Ryusuke Konishi]

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.

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

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

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


On Mon, 7 Feb 2011 20:42:32 +0100, Philippe CHATAIGNON wrote:
> Le Mon, 07 Feb 2011 13:02:14 +0900 (JST),
> Ryusuke Konishi <ryusuke-sG5X7nlA6pw@public.gmane.org> a écrit :
> 
> > Can you track the past state of this file from earlier checkpoints ?
> 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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Bug : reuse same inode

[Philippe CHATAIGNON]

Le Tue, 08 Feb 2011 20:42:30 +0900 (JST),
Ryusuke Konishi <ryusuke-sG5X7nlA6pw@public.gmane.org> a écrit :

> 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.
> 
> > cp15730
> > -------
> > mnt/snap5/cut:
> > total 4
> > 14 -rw-r--r-- 1 philippe 1000 47 25 janv. 22:33
> > f5_20110125_202053.ts(0).Xcl
> 
> > cp15731
> > -------
> > mnt/snap7/cut:
> > total 9223372036848683032
> > 14 -rw-r--r-- 0 philippe users 6214528000 24 janv. 01:30
> > f5_20110125_202053.ts(0).Xcl
> 
> 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.

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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Bug : reuse same inode

[Ryusuke Konishi]

On Tue, 8 Feb 2011 21:32:37 +0100, Philippe CHATAIGNON wrote:
> Le Tue, 08 Feb 2011 20:42:30 +0900 (JST),
> Ryusuke Konishi <ryusuke-sG5X7nlA6pw@public.gmane.org> a écrit :
> 
> > 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.
> > 
> > > cp15730
> > > -------
> > > mnt/snap5/cut:
> > > total 4
> > > 14 -rw-r--r-- 1 philippe 1000 47 25 janv. 22:33
> > > f5_20110125_202053.ts(0).Xcl
> > 
> > > cp15731
> > > -------
> > > mnt/snap7/cut:
> > > total 9223372036848683032
> > > 14 -rw-r--r-- 0 philippe users 6214528000 24 janv. 01:30
> > > f5_20110125_202053.ts(0).Xcl
> > 
> > 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.
> 
> 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.

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.

>   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

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

> 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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Bug : reuse same inode

[Philippe CHATAIGNON]

Le Thu, 10 Feb 2011 14:01:05 +0900 (JST),
Ryusuke Konishi <ryusuke-sG5X7nlA6pw@public.gmane.org> a écrit :
> 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.
> 
> >   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
> 
> Do you have any ideas on this timestamp ?

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. 

> 
> 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 ?

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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Bug : reuse same inode

[Ryusuke Konishi]

Hi,
On Thu, 10 Feb 2011 23:32:01 +0100, Philippe CHATAIGNON wrote:
> Le Thu, 10 Feb 2011 14:01:05 +0900 (JST),
> Ryusuke Konishi <ryusuke-sG5X7nlA6pw@public.gmane.org> a écrit :
> > 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.
> > 
> > >   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
> > 
> > Do you have any ideas on this timestamp ?
> 
> 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).

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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Bug : reuse same inode

[Philippe CHATAIGNON]

Le Fri, 18 Feb 2011 16:21:45 +0900 (JST),
Ryusuke Konishi <ryusuke-sG5X7nlA6pw@public.gmane.org> a écrit :
> 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.

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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Bug : reuse same inode

[Ryusuke Konishi]

Hi,
On Fri, 18 Feb 2011 20:57:39 +0100, Philippe CHATAIGNON wrote:
> Le Fri, 18 Feb 2011 16:21:45 +0900 (JST),
> Ryusuke Konishi <ryusuke-sG5X7nlA6pw@public.gmane.org> a écrit :
> > 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.
> 
> 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).

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.

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

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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Bug : reuse same inode

[Philippe CHATAIGNON]

> 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.

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 ? 

> 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).

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 majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html