xfs_logprint segfault with external log

xfs_logprint segfault with external log

[Alexander Tsvetkov]

Hello,

I've obtained corrupted xfs log after some sanity xfs testing:

"log=logfile
log_size=855

dd if=/dev/zero "of=$log" bs=4096 count=$log_size
loopdev=$(losetup -f)
losetup $loopdev $log

mkfs.xfs -f -m crc=1 -llogdev=$loopdev,size=${log_size}b $SCRATCH_DEV
mount -t xfs -ologdev=$loopdev $SCRATCH_DEV $SCRATCH_MNT
./fdtree.sh  -l 4 -d 4 -C -o $SCRATCH_MNT
sync
umount $SCRATCH_MNT

xfs_logprint -l $loopdev $SCRATCH_DEV"

Test makes crc enabled xfs filesystem with the external log of minimal 
allowed size and then creates on this fs the small directory tree
with sub directories and files of fixed depth and size with help of 
fdtree utility: https://computing.llnl.gov/?set=code&page=sio_downloads

After that xfs_logprint stably reports bad data in log:

"Oper (307): tid: eec9b0c7  len: 16  clientid: TRANS  flags: none
EXTENTS inode data
Oper (308): tid: 41000000  len: 805306368  clientid: ERROR  flags: none
LOCAL attr data

============================================================================
cycle: 1        version: 2              lsn: 1,3138     tail_lsn: 1,2
length of Log Record: 32256     prev offset: 3074               num ops: 375
uuid: 39a962b7-4c0d-4e0e-8bcd-39471f93bc1d   format: little endian linux
h_size: 32768
----------------------------------------------------------------------------
Oper (0): tid: eec9b0c7  len: 48  clientid: TRANS  flags: none
**********************************************************************
* ERROR: data block=3138                                              *
**********************************************************************

xfs_logprint: unknown log operation type (2e00)
Bad data in log"

Subsequent call to "xfs_repair -n -l $loopdev $SCRATCH_DEV" passes and 
filesystem is mounted without errors.
I've supposed the using of inappropriate log size so updated log_size to 
default mkfs.xfs value for this device: "log_size=2560".
After that xfs_logprint core dumped with segfault (race condition):

"Feb 11 13:55:42 fedora.fedora kernel: xfs_logprint[14007]: segfault at 
29f16768 ip 00000000004028ed sp 00007fff61b46850 error 4 in 
xfs_logprint[400000+4e000]"

I have the following configuration on vbox virtual machine with vdi, 
fixed size /dev/sdb:

[root@fedora alex]# cat /etc/issue
Fedora release 20 (Heisenbug)
Kernel \r on an \m (\l)
[root@fedora alex]# uname -ir
3.19.0-rc6 x86_64
[root@fedora alex]# mkfs.xfs -V
mkfs.xfs version 3.2.2
[root@fedora alex]# xfs_logprint -V
xfs_logprint version 3.2.2
[root@fedora alex]# fdisk -l /dev/sdb

Disk /dev/sdb: 8 GiB, 8589934592 bytes, 16777216 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes

abrt data with sosreport are collected and available on request.

Thanks,
Alexander Tsvetkov

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: xfs_logprint segfault with external log

[Eric Sandeen]

On 2/11/15 7:51 AM, Alexander Tsvetkov wrote:
> Hello,
> 
> I've obtained corrupted xfs log after some sanity xfs testing:
> 
> "log=logfile
> log_size=855
> 
> dd if=/dev/zero "of=$log" bs=4096 count=$log_size
> loopdev=$(losetup -f)
> losetup $loopdev $log
> 
> mkfs.xfs -f -m crc=1 -llogdev=$loopdev,size=${log_size}b $SCRATCH_DEV
> mount -t xfs -ologdev=$loopdev $SCRATCH_DEV $SCRATCH_MNT
> ./fdtree.sh  -l 4 -d 4 -C -o $SCRATCH_MNT
> sync
> umount $SCRATCH_MNT
> 
> xfs_logprint -l $loopdev $SCRATCH_DEV"
> 
> Test makes crc enabled xfs filesystem with the external log of minimal allowed size and then creates on this fs the small directory tree
> with sub directories and files of fixed depth and size with help of fdtree utility: https://computing.llnl.gov/?set=code&page=sio_downloads
> 
> After that xfs_logprint stably reports bad data in log:

TBH, xfs_logprint has always been a little buggy in corners.  It's
a diagnostic/developer tool, and as such has not been made as robust
as tools that users need to use every day.  Still, we'd hope for
no segfaults or errors.  ;)

> "Oper (307): tid: eec9b0c7  len: 16  clientid: TRANS  flags: none
> EXTENTS inode data
> Oper (308): tid: 41000000  len: 805306368  clientid: ERROR  flags: none
> LOCAL attr data
> 
> ============================================================================
> cycle: 1        version: 2              lsn: 1,3138     tail_lsn: 1,2
> length of Log Record: 32256     prev offset: 3074               num ops: 375
> uuid: 39a962b7-4c0d-4e0e-8bcd-39471f93bc1d   format: little endian linux
> h_size: 32768
> ----------------------------------------------------------------------------
> Oper (0): tid: eec9b0c7  len: 48  clientid: TRANS  flags: none
> **********************************************************************
> * ERROR: data block=3138                                              *
> **********************************************************************
> 
> xfs_logprint: unknown log operation type (2e00)
> Bad data in log"

It's probably just mis-parsing something.  i.e. more likely a logprint bug
than an xfs bug.

If you could provide an xfs_metadump of the filesystem at this point, that
would probably be the simplest reproducer for us.  Fixing it may not be the
very highest priority, but I have dug into and fixed logprint bugs in the
past.  It's not very fun.  ;)


> Subsequent call to "xfs_repair -n -l $loopdev $SCRATCH_DEV" passes and filesystem is mounted without errors.
> I've supposed the using of inappropriate log size so updated log_size to default mkfs.xfs value for this device: "log_size=2560".
> After that xfs_logprint core dumped with segfault (race condition):
> 
> "Feb 11 13:55:42 fedora.fedora kernel: xfs_logprint[14007]: segfault at 29f16768 ip 00000000004028ed sp 00007fff61b46850 error 4 in xfs_logprint[400000+4e000]"

a metadump of this filesystem would be useful as well, assuming it reproduces the
bug.

Thanks,
-Eric

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: xfs_logprint segfault with external log

[Dave Chinner]

On Wed, Feb 11, 2015 at 04:51:44PM +0300, Alexander Tsvetkov wrote:
> Hello,
> 
> I've obtained corrupted xfs log after some sanity xfs testing:
> 
> "log=logfile
> log_size=855
> 
> dd if=/dev/zero "of=$log" bs=4096 count=$log_size
> loopdev=$(losetup -f)
> losetup $loopdev $log
> 
> mkfs.xfs -f -m crc=1 -llogdev=$loopdev,size=${log_size}b $SCRATCH_DEV
> mount -t xfs -ologdev=$loopdev $SCRATCH_DEV $SCRATCH_MNT
> ./fdtree.sh  -l 4 -d 4 -C -o $SCRATCH_MNT
> sync
> umount $SCRATCH_MNT
> 
> xfs_logprint -l $loopdev $SCRATCH_DEV"
> 
> Test makes crc enabled xfs filesystem with the external log of
> minimal allowed size and then creates on this fs the small directory
> tree
> with sub directories and files of fixed depth and size with help of
> fdtree utility:
> https://computing.llnl.gov/?set=code&page=sio_downloads

Just take metadump image and put it somewhere we can down load it.

> After that xfs_logprint stably reports bad data in log:
> 
> "Oper (307): tid: eec9b0c7  len: 16  clientid: TRANS  flags: none
> EXTENTS inode data
> Oper (308): tid: 41000000  len: 805306368  clientid: ERROR  flags: none
> LOCAL attr data

Clearly that operation is wrong, so everything past it is suspect.
This sort of error usually comes from an error parsing an earlier
ophdr, so even that probably doesn't point directly at the cause.

> ============================================================================
> cycle: 1        version: 2              lsn: 1,3138     tail_lsn: 1,2
> length of Log Record: 32256     prev offset: 3074               num ops: 375
> uuid: 39a962b7-4c0d-4e0e-8bcd-39471f93bc1d   format: little endian linux
> h_size: 32768
> ----------------------------------------------------------------------------
> Oper (0): tid: eec9b0c7  len: 48  clientid: TRANS  flags: none
> **********************************************************************
> * ERROR: data block=3138                                              *
> **********************************************************************
> 
> xfs_logprint: unknown log operation type (2e00)
> Bad data in log"

i.e. this is not the problem that needs to be chased.

> Subsequent call to "xfs_repair -n -l $loopdev $SCRATCH_DEV" passes
> and filesystem is mounted without errors.

xfs_repair -n doesn't look at the log at all.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: xfs_logprint segfault with external log

[Alexander Tsvetkov]

archive with necessary data is available by this reference:

https://drive.google.com/open?id=0B1Cg0_B_ui2gRTQ1Yk9kVUw1Snc&authuser=0

On 02/11/2015 11:54 PM, Dave Chinner wrote:
> On Wed, Feb 11, 2015 at 04:51:44PM +0300, Alexander Tsvetkov wrote:
>> Hello,
>>
>> I've obtained corrupted xfs log after some sanity xfs testing:
>>
>> "log=logfile
>> log_size=855
>>
>> dd if=/dev/zero "of=$log" bs=4096 count=$log_size
>> loopdev=$(losetup -f)
>> losetup $loopdev $log
>>
>> mkfs.xfs -f -m crc=1 -llogdev=$loopdev,size=${log_size}b $SCRATCH_DEV
>> mount -t xfs -ologdev=$loopdev $SCRATCH_DEV $SCRATCH_MNT
>> ./fdtree.sh  -l 4 -d 4 -C -o $SCRATCH_MNT
>> sync
>> umount $SCRATCH_MNT
>>
>> xfs_logprint -l $loopdev $SCRATCH_DEV"
>>
>> Test makes crc enabled xfs filesystem with the external log of
>> minimal allowed size and then creates on this fs the small directory
>> tree
>> with sub directories and files of fixed depth and size with help of
>> fdtree utility:
>> https://computing.llnl.gov/?set=code&page=sio_downloads
> Just take metadump image and put it somewhere we can down load it.
>
>> After that xfs_logprint stably reports bad data in log:
>>
>> "Oper (307): tid: eec9b0c7  len: 16  clientid: TRANS  flags: none
>> EXTENTS inode data
>> Oper (308): tid: 41000000  len: 805306368  clientid: ERROR  flags: none
>> LOCAL attr data
> Clearly that operation is wrong, so everything past it is suspect.
> This sort of error usually comes from an error parsing an earlier
> ophdr, so even that probably doesn't point directly at the cause.
>
>> ============================================================================
>> cycle: 1        version: 2              lsn: 1,3138     tail_lsn: 1,2
>> length of Log Record: 32256     prev offset: 3074               num ops: 375
>> uuid: 39a962b7-4c0d-4e0e-8bcd-39471f93bc1d   format: little endian linux
>> h_size: 32768
>> ----------------------------------------------------------------------------
>> Oper (0): tid: eec9b0c7  len: 48  clientid: TRANS  flags: none
>> **********************************************************************
>> * ERROR: data block=3138                                              *
>> **********************************************************************
>>
>> xfs_logprint: unknown log operation type (2e00)
>> Bad data in log"
> i.e. this is not the problem that needs to be chased.
>
>> Subsequent call to "xfs_repair -n -l $loopdev $SCRATCH_DEV" passes
>> and filesystem is mounted without errors.
> xfs_repair -n doesn't look at the log at all.
>
> Cheers,
>
> Dave.
Thanks,
Alexander Tsvetkov

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: xfs_logprint segfault with external log

[Dave Chinner]

On Thu, Feb 12, 2015 at 02:52:45PM +0300, Alexander Tsvetkov wrote:
> On 02/11/2015 11:54 PM, Dave Chinner wrote:
> >On Wed, Feb 11, 2015 at 04:51:44PM +0300, Alexander Tsvetkov wrote:
> >>Hello,
> >>
> >>I've obtained corrupted xfs log after some sanity xfs testing:
> >>
> >>"log=logfile
> >>log_size=855
> >>
> >>dd if=/dev/zero "of=$log" bs=4096 count=$log_size
> >>loopdev=$(losetup -f)
> >>losetup $loopdev $log
> >>
> >>mkfs.xfs -f -m crc=1 -llogdev=$loopdev,size=${log_size}b $SCRATCH_DEV
> >>mount -t xfs -ologdev=$loopdev $SCRATCH_DEV $SCRATCH_MNT
> >>./fdtree.sh  -l 4 -d 4 -C -o $SCRATCH_MNT
> >>sync
> >>umount $SCRATCH_MNT
> >>
> >>xfs_logprint -l $loopdev $SCRATCH_DEV"
> >>
> >>Test makes crc enabled xfs filesystem with the external log of
> >>minimal allowed size and then creates on this fs the small directory
> >>tree
> >>with sub directories and files of fixed depth and size with help of
> >>fdtree utility:
> >>https://computing.llnl.gov/?set=code&page=sio_downloads
> >Just take metadump image and put it somewhere we can down load it.
> >
> >>After that xfs_logprint stably reports bad data in log:

Please try the patch below, it fixes the problem on the image you
provided.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

logprint: fix inode fork print record overrun

From: Dave Chinner <dchinner@redhat.com>

logprint checks for whether the inode log item extends across a log
record boundary so that it doesn't try to dereference beyond the ned
of the buffer containing the log items. It doesn' however, take into
account log items with attribute forks in them, and so doesn't catch
the overrun in this case. Fix it.

reported-by: Alexander Tsvetkov <alexander.tsvetkov@oracle.com>
Signed-off-by: Dave Chinner <dchinner@redhat.com>
---
 logprint/log_misc.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/logprint/log_misc.c b/logprint/log_misc.c
index 521ab66..e4f2174 100644
--- a/logprint/log_misc.c
+++ b/logprint/log_misc.c
@@ -698,7 +698,7 @@ xlog_print_trans_inode(
     xlog_print_trans_inode_core(&dino);
     *ptr += xfs_icdinode_size(dino.di_version);
 
-    if (*i == num_ops-1 && f->ilf_size == 3)  {
+    if (*i == num_ops-1 && f->ilf_size >= 3) {
 	return 1;
     }
 

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: xfs_logprint segfault with external log

[Alexander Tsvetkov]

On 02/13/2015 02:09 AM, Dave Chinner wrote:
> On Thu, Feb 12, 2015 at 02:52:45PM +0300, Alexander Tsvetkov wrote:
>> On 02/11/2015 11:54 PM, Dave Chinner wrote:
>>> On Wed, Feb 11, 2015 at 04:51:44PM +0300, Alexander Tsvetkov wrote:
>>>> Hello,
>>>>
>>>> I've obtained corrupted xfs log after some sanity xfs testing:
>>>>
>>>> "log=logfile
>>>> log_size=855
>>>>
>>>> dd if=/dev/zero "of=$log" bs=4096 count=$log_size
>>>> loopdev=$(losetup -f)
>>>> losetup $loopdev $log
>>>>
>>>> mkfs.xfs -f -m crc=1 -llogdev=$loopdev,size=${log_size}b $SCRATCH_DEV
>>>> mount -t xfs -ologdev=$loopdev $SCRATCH_DEV $SCRATCH_MNT
>>>> ./fdtree.sh  -l 4 -d 4 -C -o $SCRATCH_MNT
>>>> sync
>>>> umount $SCRATCH_MNT
>>>>
>>>> xfs_logprint -l $loopdev $SCRATCH_DEV"
>>>>
>>>> Test makes crc enabled xfs filesystem with the external log of
>>>> minimal allowed size and then creates on this fs the small directory
>>>> tree
>>>> with sub directories and files of fixed depth and size with help of
>>>> fdtree utility:
>>>> https://computing.llnl.gov/?set=code&page=sio_downloads
>>> Just take metadump image and put it somewhere we can down load it.
>>>
>>>> After that xfs_logprint stably reports bad data in log:
> Please try the patch below, it fixes the problem on the image you
> provided.

I've restored provided image to filesystem with the same log file, 
applied patch to latest xfsprogs and have stable pass runs
of xfs_logprint on that filesystem and running with xfsprogs without 
this patch results to xfs_logprint segfaults reported that means patch 
is working.
The problem that it is not working for repeated test runs where 
xfs_logprint still continue to report bad log data. It seems it is 
working for some
cases including this image, because sometimes test can be passed but 
most part of test runs have still this xfs_logprint log error. Here is 
another fs image
that is still failed for me with patch applied to xfsprogs: 
https://drive.google.com/file/d/0B1Cg0_B_ui2gM1Bzdkc3TWVqbGM/view?usp=sharing


> Cheers,
>
> Dave.
Thanks,
Alexander Tsvetkov

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: xfs_logprint segfault with external log

[Dave Chinner]

On Mon, Feb 16, 2015 at 04:55:14PM +0300, Alexander Tsvetkov wrote:
> 
> On 02/13/2015 02:09 AM, Dave Chinner wrote:
> >On Thu, Feb 12, 2015 at 02:52:45PM +0300, Alexander Tsvetkov wrote:
> >>On 02/11/2015 11:54 PM, Dave Chinner wrote:
> >>>On Wed, Feb 11, 2015 at 04:51:44PM +0300, Alexander Tsvetkov wrote:
> >>>>Hello,
> >>>>
> >>>>I've obtained corrupted xfs log after some sanity xfs testing:
> >>>>
> >>>>"log=logfile
> >>>>log_size=855
> >>>>
> >>>>dd if=/dev/zero "of=$log" bs=4096 count=$log_size
> >>>>loopdev=$(losetup -f)
> >>>>losetup $loopdev $log
> >>>>
> >>>>mkfs.xfs -f -m crc=1 -llogdev=$loopdev,size=${log_size}b $SCRATCH_DEV
> >>>>mount -t xfs -ologdev=$loopdev $SCRATCH_DEV $SCRATCH_MNT
> >>>>./fdtree.sh  -l 4 -d 4 -C -o $SCRATCH_MNT
> >>>>sync
> >>>>umount $SCRATCH_MNT
> >>>>
> >>>>xfs_logprint -l $loopdev $SCRATCH_DEV"
> >>>>
> >>>>Test makes crc enabled xfs filesystem with the external log of
> >>>>minimal allowed size and then creates on this fs the small directory
> >>>>tree
> >>>>with sub directories and files of fixed depth and size with help of
> >>>>fdtree utility:
> >>>>https://computing.llnl.gov/?set=code&page=sio_downloads
> >>>Just take metadump image and put it somewhere we can down load it.
> >>>
> >>>>After that xfs_logprint stably reports bad data in log:
> >Please try the patch below, it fixes the problem on the image you
> >provided.
> 
> I've restored provided image to filesystem with the same log file,
> applied patch to latest xfsprogs and have stable pass runs
> of xfs_logprint on that filesystem and running with xfsprogs without
> this patch results to xfs_logprint segfaults reported that means
> patch is working.

Good.

> The problem that it is not working for repeated test runs where
> xfs_logprint still continue to report bad log data. It seems it is

xfs_logprint is not a tool that is intended for validation of the
log contents. It's a triage tool that was written in a hurry, and as
such it's neither reliable or maintainable.  Indeed, there's a
comment in the code saying it really needs to be rewritten. ;)

I'll have a look the image, but really spending lots of time on
fixing minor issues with logprint really isn't the best use of my
time right now...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: xfs_logprint segfault with external log

[Alexander Tsvetkov]

On 02/17/2015 04:38 AM, Dave Chinner wrote:
> On Mon, Feb 16, 2015 at 04:55:14PM +0300, Alexander Tsvetkov wrote:
>> On 02/13/2015 02:09 AM, Dave Chinner wrote:
>>> On Thu, Feb 12, 2015 at 02:52:45PM +0300, Alexander Tsvetkov wrote:
>>>> On 02/11/2015 11:54 PM, Dave Chinner wrote:
>>>>> On Wed, Feb 11, 2015 at 04:51:44PM +0300, Alexander Tsvetkov wrote:
>>>>>> Hello,
>>>>>>
>>>>>> I've obtained corrupted xfs log after some sanity xfs testing:
>>>>>>
>>>>>> "log=logfile
>>>>>> log_size=855
>>>>>>
>>>>>> dd if=/dev/zero "of=$log" bs=4096 count=$log_size
>>>>>> loopdev=$(losetup -f)
>>>>>> losetup $loopdev $log
>>>>>>
>>>>>> mkfs.xfs -f -m crc=1 -llogdev=$loopdev,size=${log_size}b $SCRATCH_DEV
>>>>>> mount -t xfs -ologdev=$loopdev $SCRATCH_DEV $SCRATCH_MNT
>>>>>> ./fdtree.sh  -l 4 -d 4 -C -o $SCRATCH_MNT
>>>>>> sync
>>>>>> umount $SCRATCH_MNT
>>>>>>
>>>>>> xfs_logprint -l $loopdev $SCRATCH_DEV"
>>>>>>
>>>>>> Test makes crc enabled xfs filesystem with the external log of
>>>>>> minimal allowed size and then creates on this fs the small directory
>>>>>> tree
>>>>>> with sub directories and files of fixed depth and size with help of
>>>>>> fdtree utility:
>>>>>> https://computing.llnl.gov/?set=code&page=sio_downloads
>>>>> Just take metadump image and put it somewhere we can down load it.
>>>>>
>>>>>> After that xfs_logprint stably reports bad data in log:
>>> Please try the patch below, it fixes the problem on the image you
>>> provided.
>> I've restored provided image to filesystem with the same log file,
>> applied patch to latest xfsprogs and have stable pass runs
>> of xfs_logprint on that filesystem and running with xfsprogs without
>> this patch results to xfs_logprint segfaults reported that means
>> patch is working.
> Good.
>
>> The problem that it is not working for repeated test runs where
>> xfs_logprint still continue to report bad log data. It seems it is
> xfs_logprint is not a tool that is intended for validation of the
> log contents. It's a triage tool that was written in a hurry, and as
> such it's neither reliable or maintainable.  Indeed, there's a
> comment in the code saying it really needs to be rewritten. ;)
>
> I'll have a look the image, but really spending lots of time on
> fixing minor issues with logprint really isn't the best use of my
> time right now...
Thank you, really xfs_logprint was not a subject here. It's used by me
to understand xfs log data format to verify some cases related to xfs
log recovery functionality, just tried to simulate some cases with log 
corruptions
and have no expected specific xfs alert from the kernel source that I 
would like to
see for that test case. xfs journaling para is marked as TODO in 
documentation
currently,  so I thought xfs_logprint would put more clarity how xfs 
journal data
organized.
>
> Cheers,
>
> Dave.
Thanks,
Alexander Tsvetkov

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs