rsync - Jul 2011 - [Bug 8308] New: rsync: exclude.c:532: change_local_filter_dir: Assertion `dir_depth < 4096/2+1' failed

https://bugzilla.samba.org/show_bug.cgi?id=8308

           Summary: rsync: exclude.c:532: change_local_filter_dir:
                    Assertion `dir_depth < 4096/2+1' failed
           Product: rsync
           Version: 3.0.8
          Platform: x86
        OS/Version: Linux
            Status: NEW
          Severity: major
          Priority: P5
         Component: core
        AssignedTo: wayned at samba.org
        ReportedBy: dave-samba-bugzilla at centerclick.org
         QAContact: rsync-qa at samba.org


I'm seeing the following assert:

rsync --archive --devices --specials --sparse --one-file-system --verbose
--whole-file --numeric-ids --delete-before --hard-links --delete-excluded
--exclude-from=/share/alliance-bind-local2/rsync.exclude.all
--include-from=/share/alliance-bind-local2/rsync.include.all
--include-from=/share/alliance-bind-local2/rsync.include.drive_a
'--include=*/'
'--exclude=*' --prune-empty-dirs /share/alliance-bind-local2/
/media/backup1/alliance-bind-local2/
building file list ... done
rsync: exclude.c:532: change_local_filter_dir: Assertion `dir_depth <
4096/2+1'
failed.
rsync: connection unexpectedly closed (9 bytes received so far) [sender]
rsync error: error in rsync protocol data stream (code 12) at io.c(601)
[sender=3.0.8]



The include/exclude rules I am using are trying to accomplish the
following:
 * exclude everything listed in rsync.exclude.all
 * include everything listed in either rsync.include.all or include.drive_a
 * exclude everything else

The 3 files contain:

$ cat /share/alliance-bind-local2/rsync.exclude.all
/backup/snapshots/**
$ cat /share/alliance-bind-local2/rsync.include.all
/rsync.**
$ cat /share/alliance-bind-local2/rsync.include.drive_a
/videos/dvd/**


Note that the paths of any file in the source and dest (both included or
excluded) are nowhere near 2K in length.  the longest path is probably
about 300 characters.

running in gdb seems to indicate the file in question is in the root directory
and matches the 1st include rule (/rsync.**)


Any thoughts?



$ rsync --version
rsync  version 3.0.8  protocol version 30
Copyright (C) 1996-2011 by Andrew Tridgell, Wayne Davison, and others.
Web site: http://rsync.samba.org/
Capabilities:
    64-bit files, 64-bit inums, 32-bit timestamps, 64-bit long ints,
    socketpairs, hardlinks, symlinks, IPv6, batchfiles, inplace,
    append, no ACLs, xattrs, iconv, symtimes

rsync comes with ABSOLUTELY NO WARRANTY.  This is free software, and you
are welcome to redistribute it under certain conditions.  See the GNU
General Public Licence for details.


(gdb) c
Continuing.

Breakpoint 6, change_local_filter_dir (
    dname=0xfffd3c5c "rsync.include.drive_b", dlen=21, dir_depth=3695)
    at exclude.c:532
532             assert(dir_depth < MAXPATHLEN/2+1);
(gdb) bt
#0  change_local_filter_dir (dname=0xfffd3c5c "rsync.include.drive_b",
    dlen=21, dir_depth=3695) at exclude.c:532
#1  0x080544c3 in do_delete_pass () at generator.c:548
#2  0x08059ac0 in generate_files (f_out=1, local_name=0x0) at generator.c:2251
#3  0x08064c9e in do_recv (f_in=0, f_out=1, local_name=0x0) at main.c:843
#4  0x080656a4 in start_server (f_in=0, f_out=1, argc=1, argv=0xfffd6e30)
    at main.c:953
#5  0x08066738 in child_main (argc=2, argv=0xfffd6e30) at main.c:960
#6  0x0807c92e in local_child (argc=2, argv=0xfffd6e30, f_in=0xfffd8ed0, 
    f_out=0xfffd8ecc, child_main=0x8066710 <child_main>) at pipe.c:156
#7  0x080633e9 in do_cmd (cmd=0x0, machine=0x0, user=0x0, 
    remote_argv=0x80b39b4, remote_argc=0, f_in_p=0xfffd8ed0, 
    f_out_p=0xfffd8ecc) at main.c:469
#8  0x08065f4b in main (argc=Cannot access memory at address 0x0
) at main.c:1275
(gdb) p dir_depth
$5 = 3695
(gdb) up
#1  0x080544c3 in do_delete_pass () at generator.c:548
548                             change_local_filter_dir(fbuf, strlen(fbuf),
F_DEPTH(file));
(gdb) info local
file = (struct file_struct *) 0xf73f738c
fbuf = "rsync.include.drive_b\000b"
st = {st_dev = 65024, __pad1 = 0, __st_ino = 323281, st_mode = 16877, 
  st_nlink = 3, st_uid = 0, st_gid = 0, st_rdev = 0, __pad2 = 0, 
  st_size = 4096, st_blksize = 4096, st_blocks = 8, st_atim = {
    tv_sec = 1310865354, tv_nsec = 0}, st_mtim = {tv_sec = 1305164231, 
    tv_nsec = 0}, st_ctim = {tv_sec = 1305556305, tv_nsec = 0}, 
  st_ino = 323281}
j = 1295
(gdb) p *file
$6 = {dirname = 0x0, modtime = 0, len32 = 1290, mode = 0, flags = 0, 
  basename = ""}
(gdb) p *((union file_extras*)(file) - (1))
$7 = {num = 3695, unum = 3695}
(gdb)

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

--- Comment #1 from jss at mensa.org.au 2014-04-09 01:31:48 UTC ---
I also see this bug with the latest sources for: 3.1.1pre1 and i have a
directory tree i can reproduce this bug with easily, on a local machine. No
remote transfer required.

It is related to the --prune-empty-dirs option. Removing this from my command
line makes the error go away.

http://sourceforge.net/p/luckybackup/discussion/873564/thread/864b0b61/
"Indeed, rsync seems to bring this error up when specific filter rules
(include/exclude patterns) are used and then it tries to delete files at the
destination."

here is what gdb gives me (note, i have added some debug to the source and
recompiled, so line 623 in exclude.c was the assert statement at around line
613 in the original source:

Program received signal SIGABRT, Aborted.
0x0000003e66032925 in raise (sig=6) at
../nptl/sysdeps/unix/sysv/linux/raise.c:64
64        return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb) bt
#0  0x0000003e66032925 in raise (sig=6) at
../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x0000003e66034105 in abort () at abort.c:92
#2  0x0000003e6602ba4e in __assert_fail_base (fmt=<value optimized out>,
assertion=0x45073c "dir_depth < 4096/2+1", file=0x4505c1
"exclude.c",
    line=<value optimized out>, function=<value optimized out>) at
assert.c:96
#3  0x0000003e6602bb10 in __assert_fail (assertion=0x45073c "dir_depth <
4096/2+1", file=0x4505c1 "exclude.c", line=623, function=0x450ca0
"change_local_filter_dir")
    at assert.c:105
#4  0x00000000004183d0 in change_local_filter_dir (dname=0x7fffffff8bb0
"contourd.ss/.Rational/Version_History/rivers/process_connection_utils.h,v",
dlen=73,
    dir_depth=3005) at exclude.c:623
#5  0x000000000040cd1b in do_delete_pass () at generator.c:362
#6  0x0000000000411fa3 in generate_files (f_out=1, local_name=<value
optimized
out>) at generator.c:2180
#7  0x000000000041d161 in do_recv (f_in=<value optimized out>, f_out=1,
local_name=0x0) at main.c:945
#8  0x000000000041d7f5 in do_server_recv (f_in=0, f_out=1, argc=<value
optimized out>, argv=<value optimized out>) at main.c:1057
#9  start_server (f_in=0, f_out=1, argc=<value optimized out>,
argv=<value
optimized out>) at main.c:1091
#10 0x000000000041d935 in child_main (argc=<value optimized out>,
argv=<value
optimized out>) at main.c:1064
#11 0x00000000004380b8 in local_child (argc=2, argv=0x7fffffffae10,
f_in=0x7fffffffde7c, f_out=0x7fffffffde78, child_main=0x41d920
<child_main>) at
pipe.c:167
#12 0x000000000041bafa in do_cmd (cmd=<value optimized out>, machine=0x0,
user=<value optimized out>, remote_argv=<value optimized out>,
    remote_argc=<value optimized out>, f_in_p=0x7fffffffde7c,
f_out_p=0x7fffffffde78) at main.c:535
#13 0x000000000041e758 in start_client (argc=3, argv=0x680230) at main.c:1393
#14 main (argc=3, argv=0x680230) at main.c:1633

Note also, that in the source code, I've added this code directly above the
assert that triggers this failure:

    if ( dir_depth >= MAXPATHLEN/2+1 ) {
      rprintf(FINFO, "dname=[%s] dlen=[%d] dir_depth=[%d] cur_depth=[%d]
MAXPATHLEN/2+1=[%d] \n", dname, dlen, dir_depth, cur_depth,
MAXPATHLEN/2+1);
    }

And this is never triggered. I have  therefore removed the if, and printed this
info unconditionally, and i find that the immediately before the assert fails,
dir_depth still only has a value of 1.

I have also noticed that sometimes the rsync aborts without actually triggering
the assert. And likewise, if the assert is removed, rsync still aborts at much
the same place in the code.

This all seems very odd to me. It's as if something is modifying the value
of
dir_depth underneath this code... 


I am very rusty with my gdb usage - will try to get a breakpoint in and catch
it before it aborts and get some better info out of it.

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

--- Comment #2 from John <jss at mensa.org.au> 2014-04-09 01:38:35 UTC ---

Should've actually added a comment on this bit:

http://sourceforge.net/p/luckybackup/discussion/873564/thread/864b0b61/
"Indeed, rsync seems to bring this error up when specific filter rules
(include/exclude patterns) are used and then it tries to delete files at the
destination."


I included mention of that, to show that those people are also seeing this bug.

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

--- Comment #3 from John <jss at mensa.org.au> 2014-04-09 02:04:50 UTC ---
Some slightly better info from gdb, caught program with bad value of dir_depth,
before crash. There is no way this dir suddenly out of the blue has a depth of
1622.

Looks like i need to recompile my rsync with debug info etc thoughm to get
better info:

(gdb) break exclude.c:615 if dir_depth >= 1000
Breakpoint 2 at 0x4182f9: file exclude.c, line 615.
(gdb) c
Continuing.

Breakpoint 2, change_local_filter_dir (dname=0x7fffffff8bb0
"RPMs/rpm_lib.ss/.Rational/Version_History/ran-lads2/specs/LADS-rl2gs-lib-1-mbt_ws.spec,v",
dlen=88,
    dir_depth=1622) at exclude.c:615
615             if ( dir_depth >= MAXPATHLEN/2+1 ) {
(gdb) p dir_depth
$2 = 1622
(gdb) bt
#0  change_local_filter_dir (dname=0x7fffffff8bb0
"RPMs/rpm_lib.ss/.Rational/Version_History/ran-lads2/specs/LADS-rl2gs-lib-1-mbt_ws.spec,v",
dlen=88, dir_depth=1622)
    at exclude.c:615
#1  0x000000000040cd1b in do_delete_pass () at generator.c:362
#2  0x0000000000411fa3 in generate_files (f_out=1, local_name=<value
optimized
out>) at generator.c:2180
#3  0x000000000041d161 in do_recv (f_in=<value optimized out>, f_out=1,
local_name=0x0) at main.c:945
#4  0x000000000041d7f5 in do_server_recv (f_in=0, f_out=1, argc=<value
optimized out>, argv=<value optimized out>) at main.c:1057
#5  start_server (f_in=0, f_out=1, argc=<value optimized out>,
argv=<value
optimized out>) at main.c:1091
#6  0x000000000041d935 in child_main (argc=<value optimized out>,
argv=<value
optimized out>) at main.c:1064
#7  0x00000000004380b8 in local_child (argc=2, argv=0x7fffffffae10,
f_in=0x7fffffffde7c, f_out=0x7fffffffde78, child_main=0x41d920
<child_main>) at
pipe.c:167
#8  0x000000000041bafa in do_cmd (cmd=<value optimized out>, machine=0x0,
user=<value optimized out>, remote_argv=<value optimized out>,
    remote_argc=<value optimized out>, f_in_p=0x7fffffffde7c,
f_out_p=0x7fffffffde78) at main.c:535
#9  0x000000000041e758 in start_client (argc=3, argv=0x680230) at main.c:1393
#10 main (argc=3, argv=0x680230) at main.c:1633
(gdb) local
Undefined command: "local".  Try "help".
(gdb) info local
cur_depth = 1
filt_array = {0x0 <repeats 2049 times>}
__PRETTY_FUNCTION__ = "change_local_filter_dir"
(gdb) up
#1  0x000000000040cd1b in do_delete_pass () at generator.c:362
362                             change_local_filter_dir(fbuf, strlen(fbuf),
F_DEPTH(file));
(gdb) info local
file = 0x7ffff0694380
fbuf
"RPMs/rpm_lib.ss/.Rational/Version_History/ran-lads2/specs/LADS-rl2gs-lib-1-mbt_ws.spec,v\000tes\000l\000es\000l\000\000l\000\000s\000l\000es\000l\000\000l\000tes\000l\000\000v\000tes\000l\000s\000l",
'\000' <repeats 858 times>"\220,
\226\377\377\377\177\000\000\200\226\377\377\377\177\000\000\377\377\377\377\000\000\000\000\360\253\377\377\377\177\000\000\312\352D\000\000\000\000\000gD\004f>\000\000\000\024",
'\000' <repeats 383 times>"\336, \352D", '\000'
<repeats 25 times>, "\002",
'\000' <repeats 539 times>...
st = {st_dev = 2059, st_ino = 39845946, st_nlink = 2, st_mode = 17917, st_uid
1070, st_gid = 1062, __pad0 = 0, st_rdev = 0, st_size = 4096, st_blksize 4096,
  st_blocks = 8, st_atim = {tv_sec = 1396936899, tv_nsec = 233215828}, st_mtim
= {tv_sec = 1396936901, tv_nsec = 344215827}, st_ctim = {tv_sec = 1396936901,
    tv_nsec = 344215827}, __unused = {0, 0, 0}}
j = <value optimized out>
(gdb) p file
$3 = (struct file_struct *) 0x7ffff0694380
(gdb) p F_DEPTH(file)
No symbol "F_DEPTH" in current context.

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

--- Comment #4 from John <jss at mensa.org.au> 2014-04-09 03:05:08 UTC ---

from rsync.h:
    union file_extras {
        int32 num;
        uint32 unum;
    };
    #define REQ_EXTRA(f,ndx) ((union file_extras*)(f) - (ndx))
    #define F_DEPTH(f) REQ_EXTRA(f, 1)->num


from generator.c:
    struct file_struct *file = cur_flist->sorted[j];
    rprintf(FINFO, "Sizeof pointer to file struct = [%d]\n", sizeof
(file) );
    f_name(file, fbuf);
    if (!(file->flags & FLAG_CONTENT_DIR)) {
    change_local_filter_dir(fbuf, strlen(fbuf), F_DEPTH(file));

When the program runs we see this from the code i added to generator.c:
    Sizeof pointer to file struct =[8]

So... my C is pretty rusty... and it is difficult to make any sense of this
code, but this looks like madness to me... you're using crazy macros to do
32bit pointer arithmetic on a 64-bit pointer.

ie when you run F_DEPTH(file), you're subtracting ndx, in this case 1, from
the
file pointer, but you're doing so with a macro that casts the the pointer to
union file_extras* which is a 32bit pointer, not a 64bit one. so you're
going
to end up subtracting 4 bytes from the pointer where you needed to subtract 8.

Madness!

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

--- Comment #5 from John <jss at mensa.org.au> 2014-04-09 04:03:11 UTC ---

woops, it's not just a 64bit pointer being treated as 32.

When you run macro F_DEPTH(file) you're actually subtracting the size of a
32bit integer, ie 4 bytes, but file is a pointer to structures like this:

struct file_struct {
    const char *dirname;    /* The dir info inside the transfer */
    time_t modtime;        /* When the item was last modified */
    uint32 len32;        /* Lowest 32 bits of the file's length */
    uint16 mode;        /* The item's type and permissions */
    uint16 flags;        /* The FLAG_* bits for this item */
    const char basename[1];    /* The basename (AKA filename) follows */
};

The size of file_struct is 32 bytes

So when you use the F_DEPTH macro you're subtracting 4 bytes from a pointer
that should be decremented 32 bytes at a time.... 

Still crazy.

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

--- Comment #6 from John <jss at mensa.org.au> 2014-04-09 04:38:00 UTC ---
Oh god this is awful. But it is making more sense now - these macros are
supposed to be accessing various members internal to the file_struct structure.

This is hideous though. I cannot believe what a mess this is.

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

--- Comment #7 from Wayne Davison <wayned at samba.org> 2014-04-20
21:10:54 UTC ---
Created attachment 9862
  --> https://bugzilla.samba.org/attachment.cgi?id=9862
Don't pass an inactive dir to change_local_filter_dir()

See if this patch fixes the issue you're seeing.

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

Wayne Davison <wayned at samba.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |ASSIGNED

--- Comment #8 from Wayne Davison <wayned at samba.org> 2014-04-20
21:17:58 UTC ---
The per-file data structure is a combination of a C struct and an array of
extra (32-bit) values that are stored right before the struct.  The array of
values allows the size to vary based on the options, which saves memory for a
really large file list.

I added a patch to the bug with a guess at what might be wrong.  See if that
makes any difference.  If it does not, I'm going to attach a debugging patch
that will allow us to see if the depth values are getting corrupted by the
pruning code (since it abuses the DEPTH value when figuring out if a directory
chain should be removed or not).  Note that it uses fprintf(stderr, ...) calls
instead of rprintf(), which helps them to get output even if rsync dies (your
early debugging that uses rprintf() probably left the overflow output into the
protocol buffers when the assert caused rsync to die).

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

--- Comment #9 from Wayne Davison <wayned at samba.org> 2014-04-20
21:20:02 UTC ---
Created attachment 9863
  --> https://bugzilla.samba.org/attachment.cgi?id=9863
Add some debugging if the prior patch didn't fix anything

If there is still a bug, use this patch to add some debugging info and we will
see if the F_DEPTH() values are OK prior to the pruning code, and corrupt
afterwards.

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

Wayne Davison <wayned at samba.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Attachment #9862|0                           |1
        is obsolete|                            |

--- Comment #10 from Wayne Davison <wayned at samba.org> 2014-04-20
21:41:53 UTC ---
Created attachment 9864
  --> https://bugzilla.samba.org/attachment.cgi?id=9864
More inactive-flist entry ignoring

This patch adds a few more calls to F_IS_ACTIVE() than by first one did.

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=8308

Wayne Davison <wayned at samba.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|ASSIGNED                    |RESOLVED
         Resolution|                            |FIXED

-- 
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.