We are seeing timed event problems with chdir that suggest event ordering and chdir issues in Samba 3.5.15 and possibly other versions of Samba

[Jeremy Allison]

On Mon, Jun 11, 2012 at 01:28:36PM -0700, Richard Sharpe wrote:
> Hi folks,
> 
> We are seeing issues in one of our VFSes where relative path names are
> causing confusion. We are capturing chdir requests in the VFS and
> saving the path and if we see a relative path name we prepend the
> captured path name.
> 
> However, we also check that the path that has been constructed matches
> the path coming down via the connection pointed to by the handle and
> we are seeing intermittent exceptions.
> 
> The following shows an example. A little while before this snippet
> there was a ChDir to /containers/torture-24 and there has been no
> further ChDir ... (We know this because we are dumping the stack and
> the chdir location on every chdir in the VFS now.)
> 
> [2012/06/11 12:27:19.562395,  3] smbd/fileio.c:379(write_file)
>   WRITECACHE: Flushes SEEK=0, READ=0, WRITE=0, READRAW=0, OPLOCK=0,
> CLOSE=0, SYNC=0
> [2012/06/11 12:27:21.535961, 10] smbd/fileio.c:139(real_write_file)
>   real_write_file (w2k3-801-96m-29061): pos = 97714176, size = 65536,
> returned 65536
> [2012/06/11 12:27:21.536071,  3] smbd/reply.c:4440(reply_write_and_X)
>   writeX fnum=20221 num=65536 wrote=65536
> [2012/06/11 12:27:21.536133, 10] lib/events.c:131(run_events)
>   Running timed event "ocafs_event_cleanup_handler" 0x2ba7052d7760
> [2012/06/11 12:27:21.536217, 10] lib/events.c:131(run_events)
>   Running timed event "update_write_time_handler" 0x2ba7033e0c10
> [2012/06/11 12:27:21.536237,  5] smbd/fileio.c:181(update_write_time_handler)
>   Update write time on w2k3-801-1m-9226
> [2012/06/11 12:27:21.536286, 10] lib/dbwrap_tdb.c:100(db_tdb_fetch_locked)
>   Locking key 0A000100000000006497
> [2012/06/11 12:27:21.536318, 10] lib/dbwrap_tdb.c:129(db_tdb_fetch_locked)
>   Allocated locked data 0x0x2ba7036d76c0
> [2012/06/11 12:27:21.536396, 10] lib/dbwrap_tdb.c:42(db_tdb_record_destr)
>   Unlocking key 0A000100000000006497
> [2012/06/11 12:27:21.540273,  0] lib/util.c:1572(log_stack_trace)
>   BACKTRACE: 18 stack frames:
>    #0 smbd(log_stack_trace+0x1c) [0x2ba6d6cd7fcd]
>    #1 /usr/lib64/samba/vfs/ocafs.so [0x2ba6e1bef160]
>    #2 /usr/lib64/samba/vfs/ocafs.so [0x2ba6e1bf3e60]
>    #3 /usr/lib64/samba/vfs/ocafs.so [0x2ba6e1bfba7f]
>    #4 smbd(smb_vfs_call_stat+0x4a) [0x2ba6d6991405]
>    #5 smbd(notify_fname+0xb0) [0x2ba6d6d44b78]
>    #6 smbd(update_write_time_handler+0x130) [0x2ba6d6903db9]
>    #7 smbd(run_events+0x23d) [0x2ba6d6cf29db]
>    #8 smbd [0x2ba6d69a850d]
>    #9 smbd(smbd_process+0xbf3) [0x2ba6d69ac1b9]
>    #10 smbd [0x2ba6d71d83ac]
>    #11 smbd(run_events+0x443) [0x2ba6d6cf2be1]
>    #12 smbd [0x2ba6d6cf2f29]
>    #13 smbd(_tevent_loop_once+0xdf) [0x2ba6d6cf401b]
>    #14 smbd [0x2ba6d71d90ff]
>    #15 smbd(main+0x116b) [0x2ba6d71daa7b]
>    #16 /lib64/libc.so.6(__libc_start_main+0xf4) [0x2ba6da786994]
>    #17 smbd [0x2ba6d68d8a79]
> [2012/06/11 12:27:21.549414,  0] ofsd_vfs.c:176(cifs_printf)
>   [14714]: ocafs_get_rel_path: fsid 4294967306: Invalid path (.),
> g_ocafs_rpath (/containers/torture-24/.), root
> (/containers/torture-23), Invalid argument
> [2012/06/11 12:27:21.550700,  0] ofsd_vfs.c:176(cifs_printf)
>   [14714]: ocafs_stat: fsid 4294967306: Could not determine relative
> path (.), Invalid argument
> 
> While this case only possibly lost a change_notify event, we are
> seeing the same error messages in our logs at a customer site and they
> seem correlated with application level failures, so we think there are
> some other problems with ChDir not being backed out and resulting in
> access to relative pathnames returning an error.

Ok, I'm confused and I don't understand the problem here.

What exactly isn't working as it should. Can you be a little
clearer Richard ?

Jeremy.