Re: A lot of NILFS: bad btree node messages (readonly fs)

[Piotr Szymaniak <szarpaj-TbOm9Ca2r9GrDJvtcaxF/A@public.gmane.org>]

[-- Attachment #1.1: Type: text/plain, Size: 2418 bytes --]

On Tue, Jan 08, 2013 at 03:52:30PM +0300, Vyacheslav Dubeyko wrote:
> Hi guys,
> 
> I am trying to reproduce the issue last three days but without
> success. I tried different workloads and different environments. As I
> know all of you have the issue in reproduced state. So I have
> additional questions.
> 
> 1. All of you have such messages:
> 
> Jan 03 22:36:38 [kernel] [  953.289973] NILFS: bad btree node (blocknr=26229286): level = 67, flags = 0xee, nchildren = 40
> Jan 03 22:36:38 [kernel] [  953.289976] NILFS error (device sda2): nilfs_bmap_lookup_contig: broken bmap (inode number=102230)

I noticed already, that before I had:
Jan 04 19:40:29 [kernel] [  801.937864] NILFS: bad btree node (blocknr=26229286): level = 67, flags = 0xee, nchildren = 40

And now it is:
[34101.963275] NILFS: bad btree node (blocknr=26229286): level = 84, flags = 0x89, nchildren = 13348

So different level, flags and nchildren, but blocknr is the same.


> As I understand, you still have message for concrete block number (for
> example, blocknr=26229286) during remount. But you haven't the message
> for this block number (for example, blocknr=26229286) after umount and
> mount again. But you can get error messages for another block number
> after it. Am I correct?

Looking at my logs I only have an error for the mentioned blocknr.


> Could you share strace output for "cat" command for such corrupted
> file? Maybe syslog can contain some interesting details during
> execution of "cat" command. Could you check syslog for interesting
> error messages during such try?

Attached strace output.


> 3. Could you share configuration file of your kernel (.config)? I
> suspect that you can have some special configuration of your
> environment that I haven't.

Attached.


> 4. Could you share content of nilfs_cleanerd.conf file for NILFS2
> partition that has such issue? Sorry, if I ask about it again.

Attached.



> 5. Did you have any sudden power-off before you encounter the issue
> firstly?

No, I think not.


Piotr Szymaniak.
-- 
 Odpowiedz, nie zastanawiając się: co jest najgroźniejsze dla firmowych
danych? Pomyślałeś o sabotażu, hakerach albo szpiegostwie przemysłowym?
Owszem,  wszystko to prawda,  ale największym zagrożeniem dla firmowych
danych są żółte samoprzylepne karteczki.
  -- Ben Rothke, "Computer security"

[-- Attachment #1.2: config.bz2 --]
[-- Type: application/x-bzip2, Size: 14282 bytes --]

[-- Attachment #1.3: dmesg_cat.log.bz2 --]
[-- Type: application/x-bzip2, Size: 996 bytes --]

[-- Attachment #1.4: nilfs.conf --]
[-- Type: text/plain, Size: 285 bytes --]

protection_period	3600
min_clean_segments	15%
max_clean_segments	25%
clean_check_interval	10
selection_policy	timestamp	# timestamp in ascend order
nsegments_per_clean	2
mc_nsegments_per_clean	4
cleaning_interval	5
mc_cleaning_interval	1
retry_interval		60
use_mmap
log_priority		info

[-- Attachment #1.5: strace_cat.log --]
[-- Type: text/plain, Size: 4245 bytes --]

execve("/bin/cat", ["cat", "/var/tmp/kdecache-malpa/plasma_t"...], [/* 45 vars */]) = 0
brk(0)                                  = 0x8ba0000
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb772a000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=105158, ...}) = 0
mmap2(NULL, 105158, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7710000
close(3)                                = 0
open("/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0\315\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1729888, ...}) = 0
mmap2(NULL, 1743644, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7566000
mprotect(0xb7709000, 4096, PROT_NONE)   = 0
mmap2(0xb770a000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a3) = 0xb770a000
mmap2(0xb770d000, 11036, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb770d000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7565000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb75656c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb770a000, 8192, PROT_READ)   = 0
mprotect(0x8052000, 4096, PROT_READ)    = 0
mprotect(0xb774c000, 4096, PROT_READ)   = 0
munmap(0xb7710000, 105158)              = 0
brk(0)                                  = 0x8ba0000
brk(0x8bc1000)                          = 0x8bc1000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=1716432, ...}) = 0
mmap2(NULL, 1716432, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb73c1000
close(3)                                = 0
fstat64(1, {st_mode=S_IFREG|0664, st_size=1904, ...}) = 0
open("/var/tmp/kdecache-malpa/plasma_theme_Transparent-sima84.kcache", O_RDONLY|O_LARGEFILE) = 3
fstat64(3, {st_mode=S_IFREG|0664, st_size=84213856, ...}) = 0
fadvise64_64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
read(3, 0x8ba1000, 65536)               = -1 EIO (Input/output error)
write(2, "cat: ", 5cat: )                    = 5
write(2, "/var/tmp/kdecache-malpa/plasma_t"..., 62/var/tmp/kdecache-malpa/plasma_theme_Transparent-sima84.kcache) = 62
open("/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 4
fcntl64(4, F_GETFD)                     = 0x1 (flags FD_CLOEXEC)
fstat64(4, {st_mode=S_IFREG|0644, st_size=2502, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7729000
read(4, "# Locale name alias data base.\n#"..., 4096) = 2502
read(4, "", 4096)                       = 0
close(4)                                = 0
munmap(0xb7729000, 4096)                = 0
open("/usr/share/locale/pl_PL.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/pl_PL.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/pl_PL/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/pl.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/pl.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/pl/LC_MESSAGES/libc.mo", O_RDONLY) = 4
fstat64(4, {st_mode=S_IFREG|0644, st_size=143799, ...}) = 0
mmap2(NULL, 143799, PROT_READ, MAP_PRIVATE, 4, 0) = 0xb739d000
close(4)                                = 0
open("/usr/lib/gconv/gconv-modules.cache", O_RDONLY) = 4
fstat64(4, {st_mode=S_IFREG|0644, st_size=26242, ...}) = 0
mmap2(NULL, 26242, PROT_READ, MAP_SHARED, 4, 0) = 0xb7396000
close(4)                                = 0
write(2, ": B\305\202\304\205d wej\305\233cia/wyj\305\233cia", 26: Błąd wejścia/wyjścia) = 26
write(2, "\n", 1
)                       = 1
close(3)                                = 0
close(1)                                = 0
close(2)                                = 0
exit_group(1)                           = ?
+++ exited with 1 +++

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 836 bytes --]