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

[Richard Sharpe]

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.

Has anyone seen this?

-- 
Regards,
Richard Sharpe
(何以解憂？唯有杜康。--曹操)