It seems the "priv" struct mostly contains NULL pointers at this time:

(gdb) frame 12
#12 _shadow_copy2_strip_snapshot_internal (mem_ctx=0x814f9a080, handle=handle@entry=0x8114040c0, 
    smb_fname=smb_fname@entry=0x7fffffffdf60, ptimestamp=ptimestamp@entry=0x7fffffffde98, 
    pstripped=pstripped@entry=0x7fffffffdea0, psnappath=psnappath@entry=0x0, _already_converted=0x0, 
    function=0x814c3ba10 <__FUNCTION__.24443> "shadow_copy2_stat") at ../../source3/modules/vfs_shadow_copy2.c:656
656	in ../../source3/modules/vfs_shadow_copy2.c

(gdb) print *priv
$17 = {config = 0x8114c11a0, snaps = 0x8114be160, shadow_cwd = 0x0, shadow_connectpath = 0x0, shadow_realpath = 0x0}



Hmm.. some wild idea (possibly not related):

#11 0x0000000813e982d6 in make_relative_path (abs_path=0x814400cf0 "/(null)/iei/kansli/Ekonomi/Avdelningar/14002 jel eu-projekt/STEM", cwd=0x0)
    at ../../source3/modules/vfs_shadow_copy2.c:440

...

#17 0x000000080170a474 in unix_convert (mem_ctx=mem_ctx@entry=0x810deaf90, conn=conn@entry=0x81452d5e0, 
    orig_path=orig_path@entry=0x810deb3a0 "iei/kansli/Ekonomi/Avdelningar/14002 jel eu-projekt/STEM/Uppf�ljningar/Uppf�ljning STEM staff.xlsx", 
    twrp=twrp@entry=132616044000000000, smb_fname_out=smb_fname_out@entry=0x7fffffffe268, ucf_flags=ucf_flags@entry=0) at ../../source3/smbd/filename.c:1120

There is a zfs snapshot directory at the top directory ("iei", in real world /export/liu/iei). The rest of the tree is just normal directories. "STEM" is the last one with just ASCII characters, the next level down ("Uppföljningar") contains UNICODE characters.

The user trying accessing the share at this time seems to have correct access rights to the files so it's not ACL-related (I think).

I've been trying to reproduce using smbclient in a test share but so far no luck.

Yep, make_relative_path() is only called from one place:

        if (pstripped != NULL) {
                stripped = talloc_strdup(mem_ctx, abs_path);
                if (stripped == NULL) {
                        ret = false;
                        goto out;
                }

                if (smb_fname->base_name[0] != '/') {
                        ret = make_relative_path(priv->shadow_cwd, stripped);

so looks like priv->shadow_cwd == NULL here.

What config does shadow_copy2 use for this share in your smb.conf ?

Parts from our smb.conf:

;; VFS objects to enable
vfs objects = shadow_copy2 zfsacl full_audit

;; Snapshots/Previous Versions
shadow:snapdir = .zfs/snapshot
shadow:format = auto-%Y-%m-%d.%H:%M:%S
shadow:sort = desc
shadow:localtime = yes
shadow:snapdirseverywhere = yes

...
[homes]
browseable = false
printable = false
public = false
writeable = true

...

[liu]
copy = homes
comment = LIU Directories
path = /export/liu
create mask = 0700
directory mask = 0700
inherit owner = no


The snapshot directory typically contains 50 snapshots and looks like this:

root@filur06:/export/liu/iei/.zfs/snapshot # ls
auto-2020-04-01.23:00:00	auto-2021-03-14.22:00:00	auto-2021-03-31.11:00:00	auto-2021-04-01.09:00:00
auto-2020-05-01.23:00:00	auto-2021-03-21.22:00:00	auto-2021-03-31.12:00:00	auto-2021-04-01.10:00:00
auto-2020-06-01.23:00:00	auto-2021-03-25.21:00:00	auto-2021-03-31.13:00:00	auto-2021-04-01.11:00:00
auto-2020-07-01.23:00:00	auto-2021-03-26.21:00:00	auto-2021-03-31.14:00:00	auto-2021-04-01.12:00:00
auto-2020-08-01.23:00:00	auto-2021-03-27.21:00:00	auto-2021-03-31.15:00:00	auto-2021-04-01.13:00:00
auto-2020-09-01.23:00:00	auto-2021-03-28.21:00:00	auto-2021-03-31.16:00:00	auto-2021-04-01.14:00:00
auto-2020-10-01.23:00:00	auto-2021-03-28.22:00:00	auto-2021-03-31.17:00:00	auto-2021-04-01.15:00:00
auto-2020-11-01.23:00:00	auto-2021-03-29.21:00:00	auto-2021-03-31.18:00:00	auto-2021-04-01.16:00:00
auto-2020-12-01.23:00:00	auto-2021-03-30.21:00:00	auto-2021-03-31.19:00:00	auto-2021-04-01.17:00:00
auto-2021-01-01.23:00:00	auto-2021-03-31.07:00:00	auto-2021-03-31.20:00:00	auto-2021-04-01.18:00:00
auto-2021-02-01.23:00:00	auto-2021-03-31.08:00:00	auto-2021-03-31.21:00:00	auto-2021-04-01.19:00:00
auto-2021-03-01.23:00:00	auto-2021-03-31.09:00:00	auto-2021-04-01.07:00:00
auto-2021-03-07.22:00:00	auto-2021-03-31.10:00:00	auto-2021-04-01.08:00:00


Btw, Have been thinking about modifying the "snapdirseverywhere" code a bit. We currently have to set it since the snapshot directory isn't directly in the share but one (or a couple of) levels down (ie, liu/iei).

Just got another core-dump. This time at 4.14.4, looks like the same bug:

(gdb) bt
#0  0x0000000804b66c2a in thr_kill () from /lib/libc.so.7
#1  0x0000000804b65084 in raise () from /lib/libc.so.7
#2  0x0000000804adb279 in abort () from /lib/libc.so.7
#3  0x00000008029b32f9 in dump_core () at ../../source3/lib/dumpcore.c:338
#4  0x00000008029c1cba in smb_panic_s3 (why=<optimized out>) at ../../source3/lib/util.c:850
#5  0x00000008012912e9 in smb_panic (
    why=why@entry=0x7fffffffd350 "Signal 11: Segmentation fault") at ../../lib/util/fault.c:197
#6  0x0000000801291365 in fault_report (sig=11) at ../../lib/util/fault.c:81
#7  sig_fault (sig=11) at ../../lib/util/fault.c:92
#8  0x0000000801517b70 in ?? () from /lib/libthr.so.3
#9  0x000000080151713f in ?? () from /lib/libthr.so.3
#10 <signal handler called>
#11 0x0000000813965976 in make_relative_path (
    abs_path=0x819ae2490 "/(null)/marwi56/MigratedFrom/IEI/axel/2021/Q1", cwd=0x0)
    at ../../source3/modules/vfs_shadow_copy2.c:440
#12 _shadow_copy2_strip_snapshot_internal (mem_ctx=0x819ae2080, handle=handle@entry=0x80fd17120, 
    smb_fname=smb_fname@entry=0x7fffffffdf60, ptimestamp=ptimestamp@entry=0x7fffffffde98, 
    pstripped=pstripped@entry=0x7fffffffdea0, psnappath=psnappath@entry=0x0, 
    _already_converted=0x0, function=0x8139700b0 <__FUNCTION__.24443> "shadow_copy2_stat")
    at ../../source3/modules/vfs_shadow_copy2.c:656
#13 0x0000000813965aa5 in _shadow_copy2_strip_snapshot (mem_ctx=<optimized out>, 
    handle=handle@entry=0x80fd17120, orig_name=orig_name@entry=0x7fffffffdf60, 
    ptimestamp=ptimestamp@entry=0x7fffffffde98, pstripped=pstripped@entry=0x7fffffffdea0, 
    function=function@entry=0x8139700b0 <__FUNCTION__.24443> "shadow_copy2_stat")
    at ../../source3/modules/vfs_shadow_copy2.c:689
#14 0x0000000813969b84 in shadow_copy2_stat (handle=0x80fd17120, smb_fname=0x7fffffffdf60)
    at ../../source3/modules/vfs_shadow_copy2.c:1177
#15 0x000000080171ea9a in smb_vfs_call_stat (handle=<optimized out>, 
    smb_fname=smb_fname@entry=0x7fffffffdf60) at ../../source3/smbd/vfs.c:2172
#16 0x00000008017229ef in stat_cache_lookup (conn=0x819aa79e0, posix_paths=<optimized out>, 
    pp_name=0x819f5a7e0, pp_dirpath=pp_dirpath@entry=0x7fffffffe0f8, 
    pp_start=pp_start@entry=0x7fffffffe0e8, twrp=132647544000000000, pst=0x819f5a7f8)
    at ../../source3/smbd/statcache.c:337
#17 0x000000080170a035 in unix_convert (mem_ctx=mem_ctx@entry=0x80fcd5680, 
    conn=conn@entry=0x819aa79e0, 
    orig_path=orig_path@entry=0x80fcd5a90 "marwi56/MigratedFrom/IEI/Axel/2021/Q1/Manuella periodiseringar Q1 2021 r�ttad.xlsx", twrp=twrp@entry=132647544000000000, 
    smb_fname_out=smb_fname_out@entry=0x7fffffffe268, ucf_flags=ucf_flags@entry=0)
    at ../../source3/smbd/filename.c:1120
#18 0x000000080170bba7 in filename_convert_internal (ctx=ctx@entry=0x80fcd5680, 
    conn=0x819aa79e0, smbreq=smbreq@entry=0x0, 
    name_in=0x80fcd5a90 "marwi56/MigratedFrom/IEI/Axel/2021/Q1/Manuella periodiseringar Q1 2021 r�ttad.xlsx", ucf_flags=0, twrp=132647544000000000, _smb_fname=0x7fffffffe340)
    at ../../source3/smbd/filename.c:1936
#19 0x000000080170c175 in filename_convert (ctx=ctx@entry=0x80fcd5680, conn=<optimized out>, 
    name_in=<optimized out>, ucf_flags=<optimized out>, twrp=<optimized out>, 
    pp_smb_fname=pp_smb_fname@entry=0x7fffffffe340) at ../../source3/smbd/filename.c:2029
#20 0x000000080174fe22 in smbd_smb2_create_send (in_context_blobs=..., 
    in_name=0x813defc70 "marwi56\\MigratedFrom\\IEI\\Axel\\2021\\Q1\\Manuella periodiseringar Q1 2021 r�ttad.xlsx", in_create_options=<optimized out>, in_create_disposition=<optimized out>, 
    in_share_access=<optimized out>, in_file_attributes=<optimized out>, 
    in_desired_access=<optimized out>, in_impersonation_level=<optimized out>, 
    in_oplock_level=<optimized out>, smb2req=0x813def7b0, ev=<optimized out>, 
    mem_ctx=0x813def7b0) at ../../source3/smbd/smb2_create.c:946
#21 smbd_smb2_request_process_create (smb2req=smb2req@entry=0x813def7b0)
    at ../../source3/smbd/smb2_create.c:268
#22 0x000000080174600e in smbd_smb2_request_dispatch (req=req@entry=0x813def7b0)
    at ../../source3/smbd/smb2_server.c:3303
#23 0x0000000801746f27 in smbd_smb2_io_handler (fde_flags=<optimized out>, xconn=0x80fcc8fe0)
    at ../../source3/smbd/smb2_server.c:4913
#24 smbd_smb2_connection_handler (ev=<optimized out>, fde=<optimized out>, 
    flags=<optimized out>, private_data=<optimized out>) at ../../source3/smbd/smb2_server.c:4951
#25 0x0000000802142ea9 in tevent_common_invoke_fd_handler (fde=fde@entry=0x80fcb4900, 
    flags=<optimized out>, removed=removed@entry=0x0) at ../../lib/tevent/tevent_fd.c:138
#26 0x0000000802145485 in poll_event_loop_poll (tvalp=0x7fffffffe550, ev=0x80fcb7060)
    at ../../lib/tevent/tevent_poll.c:569
#27 poll_event_loop_once (ev=0x80fcb7060, location=<optimized out>)
    at ../../lib/tevent/tevent_poll.c:626
#28 0x000000080214267f in _tevent_loop_once (ev=ev@entry=0x80fcb7060, 
    location=location@entry=0x801873440 "../../source3/smbd/process.c:4232")
    at ../../lib/tevent/tevent.c:772
#29 0x0000000802142856 in tevent_common_loop_wait (ev=0x80fcb7060, 
    location=0x801873440 "../../source3/smbd/process.c:4232") at ../../lib/tevent/tevent.c:895
#30 0x00000008021428b2 in _tevent_loop_wait (ev=ev@entry=0x80fcb7060, 
    location=location@entry=0x801873440 "../../source3/smbd/process.c:4232")
    at ../../lib/tevent/tevent.c:914
#31 0x0000000801734949 in smbd_process (ev_ctx=ev_ctx@entry=0x80fcb7060, 
    msg_ctx=msg_ctx@entry=0x80fcb0300, dce_ctx=dce_ctx@entry=0x80fca10c0, 
    sock_fd=sock_fd@entry=49, interactive=interactive@entry=false)
    at ../../source3/smbd/process.c:4232
#32 0x000000000102dfbd in smbd_accept_connection (ev=0x80fcb7060, fde=<optimized out>, 
    flags=<optimized out>, private_data=<optimized out>) at ../../source3/smbd/server.c:1020
#33 0x0000000802142ea9 in tevent_common_invoke_fd_handler (fde=fde@entry=0x80fcb04c0, 
    flags=<optimized out>, removed=removed@entry=0x0) at ../../lib/tevent/tevent_fd.c:138
#34 0x0000000802145485 in poll_event_loop_poll (tvalp=0x7fffffffe7b0, ev=0x80fcb7060)
    at ../../lib/tevent/tevent_poll.c:569
#35 poll_event_loop_once (ev=0x80fcb7060, location=<optimized out>)
    at ../../lib/tevent/tevent_poll.c:626
#36 0x000000080214267f in _tevent_loop_once (ev=ev@entry=0x80fcb7060, 
    location=location@entry=0x1036550 "../../source3/smbd/server.c:1367")
    at ../../lib/tevent/tevent.c:772
#37 0x0000000802142856 in tevent_common_loop_wait (ev=0x80fcb7060, 
    location=0x1036550 "../../source3/smbd/server.c:1367") at ../../lib/tevent/tevent.c:895
#38 0x00000008021428b2 in _tevent_loop_wait (ev=ev@entry=0x80fcb7060, 
    location=location@entry=0x1036550 "../../source3/smbd/server.c:1367")
    at ../../lib/tevent/tevent.c:914
#39 0x000000000102fabb in smbd_parent_loop (parent=0x80fcb0760, ev_ctx=0x80fcb7060)
    at ../../source3/smbd/server.c:1367
#40 main (argc=<optimized out>, argv=<optimized out>) at ../../source3/smbd/server.c:2220

Hmm...

(gdb) print priv->config[0]
$6 = {gmt_format = 0x813da2360 "auto-%Y-%m-%d.%H:%M:%S", use_sscanf = false, 
  use_localtime = true, snapdir = 0x80fca63a0 ".zfs/snapshot", delimiter = 0x80fca6cd0 "_GMT", 
  snapdirseverywhere = true, crossmountpoints = false, fixinodes = false, 
  sort_order = 0x80fd39b60 "desc", snapdir_absolute = false, 
  mount_point = 0x80fd37160 "/export/staff", rel_connectpath = 0x0, 
  snapshot_basepath = 0x80fdd61e0 "/export/staff/.zfs/snapshot"}

That is not the right snapshot directory for that user. It should have been

  /export/staff/marwi56/.zfs/snapshot/

But "snapdirseverywhere" is set so it should have found the one in the 'marwi56' subdir.

The user probably connected to this share using \\server\staff and then cd'd down into the home directory (\\server\staff\marwi56). There are .zfs/snapshot directories in /export/staff and /export/staff/marwi56.


Looking at the data in "priv" is seems store_cwd_data() hasn't been called since that is the one setting "priv->shadow_cwd".

The priv->snaps list of snapshots also seems empty:

(gdb) print priv->snaps[0]
$4 = {snaplist = 0x0, regex = 0x0, fetch_time = 0}

If shadow_copy2_chdir() successfully calls SMB_VFS_NEXT_CHDIR(), then store_cwd_data() *must* be called.

Could a chdir() be failing somewhere ?

I wish I knew. I've sent an email to the user that triggered this bug to try and find out what he was attempting to do (so I can try to reproduce it) but so far no response... 

And all my attempts at reproducing (accessing the "previous versions" via smbclient from a Linux client and via Windows 10 it with my own user always fails (or rather succeeds - no core dump :-). Sigh.

Nothing suspicious in the log files either. 

Annoying this.

Yeah there's definitely a bug here, but I don't immediately see it. Thanks for persevering. I'm sure eventually we'll be able to get the info we need. I'm leaving this one "assigned" so as soon as you find more info I'll get email.

Created attachment 16631 [details]
git-am fix for master.

This one looks suspiciously like the bug I just created:

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

I've posted the fix I added there for you to try.

It's not conclusive, but it's a valgrind error in approximately the right area.

I’ll have a look at testing that patch. Seems related to reading/following symbolic links if I’m not mistaken? Hmm.. I don’t think the user that triggered the bug for us have any symbolic links in their directory. I'll have to check that though.

Hm… There might be a case where they access their home via a symbolic link - if they would mount the share directly via \\server.domain\user - then access is via a symlink farm /export/home/user -> ../staff/user). But normally users access it via AD DFS \\domain\home\user which would point them to \\server.domain\staff\user - but you never know if someone has been creative :-)

- Peter

(In reply to Jeremy Allison from comment #6)

Hi Jeremy,

One of our customers got smbd panic with the same call stack, make_relative_path is called with cwd == NULL. And yes, in logs I see that chdir has failed:

[2021/09/30 16:08:35.234592,  0, pid=7171] ../../source3/smbd/service.c:176(chdir_current_service)
  chdir_current_service: vfs_ChDir(/export/Data) failed: Permission denied. Current token: uid=2014242, gid=2000516, 5 groups: 2014242 2000516 1000003 1000004 1000005
[2021/09/30 16:08:35.234968,  0, pid=7171] ../../source3/smbd/service.c:188(chdir_current_service)
  chdir_current_service: vfs_ChDir(/export/Data) failed: Permission denied. Current token: uid=2014242, gid=2000516, 5 groups: 2014242 2000516 1000003 1000004 1000005

[2021/09/30 16:08:35.244638,  1, pid=7171, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)
[2021/09/30 16:08:35.251043,  1, pid=4153, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)
...
[2021/09/30 16:08:35.363153,  1, pid=4153, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)
[2021/09/30 16:08:35.369467,  1, pid=4153, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)

[2021/09/30 16:08:35.377066,  0, pid=4153] ../../source3/lib/util.c:830(smb_panic_s3)
  PANIC (pid 4153): internal error

(gdb) bt
#0  0x00007f751f128f47 in raise () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007f751f12a8b1 in abort () from /lib/x86_64-linux-gnu/libc.so.6
#2  0x00007f7522f29b58 in dump_core () at ../../source3/lib/dumpcore.c:338
#3  0x00007f7522f19449 in smb_panic_s3 (why=0x7f7523a54485 "internal error") at ../../source3/lib/util.c:861
#4  0x00007f7523a0da31 in smb_panic (why=0x7f7523a54485 "internal error") at ../../lib/util/fault.c:174
#5  0x00007f7523a0d6fd in fault_report (sig=11) at ../../lib/util/fault.c:88
#6  0x00007f7523a0d712 in sig_fault (sig=11) at ../../lib/util/fault.c:99
#7  <signal handler called>
#8  0x00007f751f19b6b6 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#9  0x00007f7506a26fa6 in make_relative_path (cwd=0x0, abs_path=0x7f7508189240 "/(null)/gghcapps/users/trading/orderentrysvr.exe") at ../../source3/modules/vfs_shadow_copy2.c:440
#10 0x00007f7506a279fd in shadow_copy2_strip_snapshot_internal (mem_ctx=0x7f7508189080, handle=0x7f7508168f20, orig_name=0x7f750812dfe0 "@GMT-2021.09.20-21.00.18/gghcapps/users/trading/orderentrysvr.exe", ptimestamp=0x7ffeefc04090, pstripped=0x7ffeefc04098, psnappath=0x0, _already_converted=0x0) at ../../source3/modules/vfs_shadow_copy2.c:741
#11 0x00007f7506a27b32 in shadow_copy2_strip_snapshot (mem_ctx=0x7f7508189080, handle=0x7f7508168f20, orig_name=0x7f750812dfe0 "@GMT-2021.09.20-21.00.18/gghcapps/users/trading/orderentrysvr.exe", ptimestamp=0x7ffeefc04090, pstripped=0x7ffeefc04098) at ../../source3/modules/vfs_shadow_copy2.c:767
#12 0x00007f7506a28ff4 in shadow_copy2_stat (handle=0x7f7508168f20, smb_fname=0x7f75080a2820) at ../../source3/modules/vfs_shadow_copy2.c:1295
#13 0x00007f7523523c84 in smb_vfs_call_stat (handle=0x7f7508168f20, smb_fname=0x7f75080a2820) at ../../source3/smbd/vfs.c:2112
#14 0x00007f7523505bd4 in unix_convert (ctx=0x7f7508181b20, conn=0x7f75080dcc60, orig_path=0x7f750812dce0 "@GMT-2021.09.20-21.00.18/gghcapps/users/trading/orderentrysvr.exe", smb_fname_out=0x7ffeefc043f0, ucf_flags=1024) at ../../source3/smbd/filename.c:693
#15 0x00007f75235084a7 in filename_convert_internal (ctx=0x7f7508181b20, conn=0x7f75080dcc60, smbreq=0x0, name_in=0x7f7508181f40 "gghcapps/users/trading/orderentrysvr.exe", ucf_flags=1024, twrp=0x7f7508181df0, ppath_contains_wcard=0x0, pp_smb_fname=0x7ffeefc043f0) at ../../source3/smbd/filename.c:1781
#16 0x00007f7523508715 in filename_convert (ctx=0x7f7508181b20, conn=0x7f75080dcc60, name_in=0x7f7508181f40 "gghcapps/users/trading/orderentrysvr.exe", ucf_flags=1024, twrp=0x7f7508181df0, ppath_contains_wcard=0x0, pp_smb_fname=0x7ffeefc043f0) at ../../source3/smbd/filename.c:1829
#17 0x00007f7523570128 in smbd_smb2_create_send (mem_ctx=0x7f7508180fa0, ev=0x7f75080a1560, smb2req=0x7f7508180fa0, in_oplock_level=0 '\000', in_impersonation_level=2, in_desired_access=128, in_file_attributes=0, in_share_access=7, in_create_disposition=1, in_create_options=2097152, in_name=0x7f7508181410 "gghcapps\\users\\trading\\orderentrysvr.exe", in_context_blobs=...) at ../../source3/smbd/smb2_create.c:937
#18 0x00007f752356ddc0 in smbd_smb2_request_process_create (smb2req=0x7f7508180fa0) at ../../source3/smbd/smb2_create.c:268
#19 0x00007f752355f054 in smbd_smb2_request_dispatch (req=0x7f7508180fa0) at ../../source3/smbd/smb2_server.c:2731
#20 0x00007f752356457f in smbd_smb2_io_handler (xconn=0x7f7508040fe0, fde_flags=1) at ../../source3/smbd/smb2_server.c:4109
#21 0x00007f7523564699 in smbd_smb2_connection_handler (ev=0x7f75080a1560, fde=0x7f75080d9f20, flags=1, private_data=0x7f7508040fe0) at ../../source3/smbd/smb2_server.c:4147
#22 0x00007f7522292085 in tevent_common_invoke_fd_handler (fde=0x7f75080d9f20, flags=1, removed=0x0) at ../../lib/tevent/tevent_fd.c:138
#23 0x00007f752229caec in epoll_event_loop (epoll_ev=0x7f750802c580, tvalp=0x7ffeefc047e0) at ../../lib/tevent/tevent_epoll.c:736
#24 0x00007f752229d1cf in epoll_event_loop_once (ev=0x7f75080a1560, location=0x7f752370bd98 "../../source3/smbd/process.c:4170") at ../../lib/tevent/tevent_epoll.c:937
#25 0x00007f7522299931 in std_event_loop_once (ev=0x7f75080a1560, location=0x7f752370bd98 "../../source3/smbd/process.c:4170") at ../../lib/tevent/tevent_standard.c:110
#26 0x00007f75222912a4 in _tevent_loop_once (ev=0x7f75080a1560, location=0x7f752370bd98 "../../source3/smbd/process.c:4170") at ../../lib/tevent/tevent.c:772
#27 0x00007f75222915f6 in tevent_common_loop_wait (ev=0x7f75080a1560, location=0x7f752370bd98 "../../source3/smbd/process.c:4170") at ../../lib/tevent/tevent.c:895
#28 0x00007f75222999d3 in std_event_loop_wait (ev=0x7f75080a1560, location=0x7f752370bd98 "../../source3/smbd/process.c:4170") at ../../lib/tevent/tevent_standard.c:141
#29 0x00007f7522291699 in _tevent_loop_wait (ev=0x7f75080a1560, location=0x7f752370bd98 "../../source3/smbd/process.c:4170") at ../../lib/tevent/tevent.c:914
#30 0x00007f7523542c5c in smbd_process (ev_ctx=0x7f75080a1560, msg_ctx=0x7f75080d8320, sock_fd=36, interactive=false) at ../../source3/smbd/process.c:4170
#31 0x0000556685b7c39b in smbd_accept_connection (ev=0x7f75080a1560, fde=0x7f75080d9820, flags=1, private_data=0x7f7508167440) at ../../source3/smbd/server.c:1019
#32 0x00007f7522292085 in tevent_common_invoke_fd_handler (fde=0x7f75080d9820, flags=1, removed=0x0) at ../../lib/tevent/tevent_fd.c:138
#33 0x00007f752229caec in epoll_event_loop (epoll_ev=0x7f750802c580, tvalp=0x7ffeefc04b90) at ../../lib/tevent/tevent_epoll.c:736
#34 0x00007f752229d1cf in epoll_event_loop_once (ev=0x7f75080a1560, location=0x556685b84a08 "../../source3/smbd/server.c:1366") at ../../lib/tevent/tevent_epoll.c:937
#35 0x00007f7522299931 in std_event_loop_once (ev=0x7f75080a1560, location=0x556685b84a08 "../../source3/smbd/server.c:1366") at ../../lib/tevent/tevent_standard.c:110
#36 0x00007f75222912a4 in _tevent_loop_once (ev=0x7f75080a1560, location=0x556685b84a08 "../../source3/smbd/server.c:1366") at ../../lib/tevent/tevent.c:772
#37 0x00007f75222915f6 in tevent_common_loop_wait (ev=0x7f75080a1560, location=0x556685b84a08 "../../source3/smbd/server.c:1366") at ../../lib/tevent/tevent.c:895
#38 0x00007f75222999d3 in std_event_loop_wait (ev=0x7f75080a1560, location=0x556685b84a08 "../../source3/smbd/server.c:1366") at ../../lib/tevent/tevent_standard.c:141
#39 0x00007f7522291699 in _tevent_loop_wait (ev=0x7f75080a1560, location=0x556685b84a08 "../../source3/smbd/server.c:1366") at ../../lib/tevent/tevent.c:914
#40 0x0000556685b7d152 in smbd_parent_loop (ev_ctx=0x7f75080a1560, parent=0x7f75080d8940) at ../../source3/smbd/server.c:1366
#41 0x0000556685b7f647 in main (argc=3, argv=0x7ffeefc051b8) at ../../source3/smbd/server.c:2226

-Lev.

(In reply to Lev from comment #12)

Hi Lev,

So I'm confused as to how it's gotten into smbd_smb2_create_send() at all in this case.

Inside: smbd_smb2_request_dispatch() we have:

         if (call->need_tcon) {
                SMB_ASSERT(call->need_session);

                /*
                 * This call needs to be run as user.
                 *
                 * smbd_smb2_request_check_tcon()
                 * calls change_to_user() on success.
                 * Which implies set_current_user_info()
                 * and chdir_current_service().
                 */
                status = smbd_smb2_request_check_tcon(req);
                if (!NT_STATUS_IS_OK(status)) {
                        return smbd_smb2_request_error(req, status);
                }

smbd_smb2_request_check_tcon() looks like:

static NTSTATUS smbd_smb2_request_check_tcon(struct smbd_smb2_request *req)
{
        const uint8_t *inhdr;
        uint32_t in_flags;
        uint32_t in_tid;
        struct smbXsrv_tcon *tcon;
        NTSTATUS status;
        NTTIME now = timeval_to_nttime(&req->request_time);

        req->tcon = NULL;

...

        status = smb2srv_tcon_lookup(req->session,
                                     in_tid, now, &tcon);
        if (!NT_STATUS_IS_OK(status)) {
                return status;
        }

        if (!change_to_user_and_service(
                    tcon->compat,
                    req->session->global->session_wire_id))
        {
                return NT_STATUS_ACCESS_DENIED;
        }

And in change_to_user_and_service()

bool change_to_user_and_service(connection_struct *conn, uint64_t vuid)
{
       if (conn == NULL) {
                DBG_WARNING("Connection not open\n");
                return false;
        }

        status = smbXsrv_session_info_lookup(conn->sconn->client,
                                             vuid,
                                             &si);
        if (!NT_STATUS_IS_OK(status)) {
                DBG_WARNING("Invalid vuid %llu used on share %s.\n",
                            (unsigned long long)vuid,
                            lp_const_servicename(snum));
                return false;
        }

        ok = change_to_user_impersonate(conn, si, vuid);
        if (!ok) {
                return false;
        }

        if (conn->tcon_done) {
                ok = chdir_current_service(conn);
                if (!ok) {
                        return false;
                }
        }

So conn->tcon_done should be true, we call chdir_current_service() and you do see:

chdir_current_service: vfs_ChDir(/export/Data) failed: Permission denied. Current token: uid=2014242, gid=2000516, 5 groups: 2014242 2000516 1000003 1000004 1000005

bool chdir_current_service(connection_struct *conn)
{
        const struct smb_filename connectpath_fname = {
                .base_name = conn->connectpath,
        };
        int saved_errno = 0;
        char *utok_str = NULL;
        int ret;

        conn->lastused_count++;

        ret = vfs_ChDir(conn, &connectpath_fname);
        if (ret == 0) {
                return true;
        }
        saved_errno = errno;

        utok_str = utok_string(talloc_tos(),
                               conn->session_info->unix_token);
        if (utok_str == NULL) {
                errno = saved_errno;
                return false;
        }

        DBG_ERR("vfs_ChDir(%s) failed: %s. Current token: %s\n",
                conn->connectpath,
                strerror(saved_errno),
                utok_str);

        if (saved_errno != 0) {
                errno = saved_errno;
        }
        return false;
}

So chdir_current_service() returns false, change_to_user_and_service() should return false, so smbd_smb2_request_check_tcon() should be returning ACESS_DENIED, and smbd_smb2_request_dispatch() should be erroring out the SMB2 request.

Can you add more debugs, and try and reproduce locally with a permission denied directory to figure out why the SMB2 request is continuing to be processed after this. It makes no sense.

The very first successful call to shadow_copy2_chdir() will call store_cwd_data() which sets priv->shadow_cwd to non NULL, and after that there's no way I can see for priv->shadow_cwd to get back to NULL without store_cwd_data() calling smb_panic(), not from make_relative_path().

Hi Jeremy,

Sorry, the logs I posted above were uncomplete, also they were from 2 different processes (7171 and 4153), the process in interest is 4153, here is its full log:

[2021/09/30 15:58:36.592009,  1, pid=4153] ../../source3/smbd/service.c:938(make_connection_snum)
  ajosew10 (ipv4:192.168.68.79:18801) connect to service Data initially as user ROADRUNNER\ajose (uid=2004548, gid=2000514) (pid 4153)

[2021/09/30 16:08:31.666920,  1, pid=4153] ../../source3/smbd/service.c:938(make_connection_snum)
  ajosew10 (ipv4:192.168.68.79:18801) connect to service Data initially as user ROADRUNNER\ajosew10$ (uid=2014242, gid=2000516) (pid 4153)
[2021/09/30 16:08:31.673476,  1, pid=4153, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)
[2021/09/30 16:08:31.679868,  1, pid=4153, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)

[2021/09/30 16:08:35.251043,  1, pid=4153, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)
[2021/09/30 16:08:35.257916,  1, pid=4153, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)
...  
[2021/09/30 16:08:35.363153,  1, pid=4153, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)
[2021/09/30 16:08:35.369467,  1, pid=4153, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)
[2021/09/30 16:08:35.376086,  0, pid=4153] ../../lib/util/fault.c:79(fault_report)
[2021/09/30 16:08:35.377066,  0, pid=4153] ../../source3/lib/util.c:830(smb_panic_s3)
  PANIC (pid 4153): internal error

As you can see it first connected as a user ROADRUNNER\ajose (uid=2004548, gid=2000514) and then created new connection as ROADRUNNER\ajosew10$ (uid=2014242, gid=2000516). I found out that group 2000514 has an access to the share Data, while users 2004548 and 2014242 and group 2000516 do not:

# getfacl -pn /export/Data/
# file: /export/Data/
# owner: 0
# group: 0
user::rwx
user:0:rwx
user:2000513:rwx
user:2000514:rwx
user:2001311:rwx
user:2013994:rwx
user:2015981:rwx
group::rwx
group:0:rwx
group:1000006:rwx
group:2000513:rwx
group:2000514:rwx
group:2001311:rwx
group:2013994:rwx
group:2015981:rwx
mask::rwx
other::---
default:user::rwx
default:user:0:rwx
default:user:2000513:rwx
default:user:2001311:rwx
default:user:2013994:rwx
default:user:2015981:rwx
default:group::---
default:group:0:---
default:group:1000006:rwx
default:group:2000513:rwx
default:group:2001311:rwx
default:group:2013994:rwx
default:group:2015981:rwx
default:mask::rwx
default:other::---

# sudo -u ROADRUNNER\\ajose ls -l /export/Data > /dev/null
# echo $?
0
# sudo -u ROADRUNNER\\ajosew10$ ls -l /export/Data > /dev/null
ls: cannot open directory '/export/Data': Permission denied
# echo $?
2

So I guess the first connection as ROADRUNNER\\ajose with gid 2000514 did chdir() and set LastDir="/export/Data/". And later the second connection succesfully passed vfs_ChDir(), as strcsequal(LastDir,smb_fname->base_name) returned true. Then vfs_GetWd() failed (now smbd is running with credentials of ROADRUNNER\\ajosew10$ that can't access the share), and eventually smbd paniced.



I did the following test in my lab:

1. Created 2 users: user1(uid=10001) and user2(uid=10002).
2. Changed ownership and mode of the share root folder, so that only user1 can access it, but not user2.

Test-1. Connected as user2, and run mkdir:

# smbclient -Uuser2%user2 \\\\127.0.0.1\\smb1
Try "help" to get a list of possible commands.
smb: \> mkdir dir2
NT_STATUS_ACCESS_DENIED making remote directory \dir2

[2021/10/06 17:05:26.317603,  1, pid=29248] ../../source3/smbd/service.c:938(make_connection_snum)
  vsa-001de06be55 (ipv4:127.0.0.1:43900) connect to service smb1 initially as user user2 (uid=10002, gid=65534) (pid 29248)
[2021/10/06 17:05:33.732940,  0, pid=29248] ../../source3/smbd/service.c:176(chdir_current_service)
  chdir_current_service: vfs_ChDir(/export/smb1) failed: Permission denied. Current token: uid=10002, gid=65534, 1 groups: 65534
[2021/10/06 17:05:33.733038,  0, pid=29248] ../../source3/smbd/service.c:188(chdir_current_service)
  chdir_current_service: vfs_ChDir(/export/smb1) failed: Permission denied. Current token: uid=10002, gid=65534, 1 groups: 65534

Test-2. Connected as user1, then switched to user2, and run mkdir.

# smbclient -Uuser1%user1 \\\\127.0.0.1\\smb1
Try "help" to get a list of possible commands.
smb: \> ls
  .                                   D        0  Wed Oct  6 17:05:01 2021
  ..                                  D        0  Wed Oct  6 16:15:14 2021

                1047552000 blocks of size 1024. 1046440364 blocks available
smb: \> logon user2 user2
Current VUID is 0
smb: \> tcon smb1
tcon to smb1 successful, tid: 3528568315
smb: \> mkdir dir2
NT_STATUS_ACCESS_DENIED making remote directory \dir2

[2021/10/06 17:06:40.892639,  1, pid=30055] ../../source3/smbd/service.c:938(make_connection_snum)
  vsa-001de06be55 (ipv4:127.0.0.1:43926) connect to service smb1 initially as user user1 (uid=10001, gid=65534) (pid 30055)
[2021/10/06 17:06:55.885755,  1, pid=30055] ../../source3/smbd/service.c:938(make_connection_snum)
  vsa-001de06be55 (ipv4:127.0.0.1:43926) connect to service smb1 initially as user user2 (uid=10002, gid=65534) (pid 30055)
[2021/10/06 17:07:01.757635,  1, pid=30055, class=vfs] ../../source3/smbd/vfs.c:1020(vfs_GetWd)
  vfs_GetWd: couldn't stat "." error Permission denied (NFS problem ?)

In both tests mkdir run by user2 failed, however in Test-1 it failed in vfs_ChDir(), while in Test-2 it failed in vfs_GetWd(), i.e. passed the smbd_smb2_request_check_tcon! BTW, isn't it a security breach?

-Lev.

> 2. Changed ownership and mode of the share root folder, so that only user1 can
> access it, but not user2.

Can you share what the permissions are *exactly* on this directory ? Does user2 have 'x access on this folder ?

Secondly, can you try and reproduce against 4.15.0 ? Just want to make sure this isn't something that is still broken in 4.15.0.

Thinking about this, it might be the cwd$ cache that is biting us here. I don't think it's a security issue, as no operations are allowed.

In source3/smbd/vfs.c:vfs_ChDir() we have:


 922         if (smb_fname->base_name[0] == '/' &&
 923             strcsequal(LastDir,smb_fname->base_name))
 924         {
 925                 /*
 926                  * conn->cwd_fsp->fsp_name and the kernel
 927                  * are already correct, but conn->cwd_fsp->fh->fd
 928                  * might still be -1 as initialized in conn_new().
 929                  *
 930                  * This can happen when a client made a 2nd
 931                  * tree connect to a share with the same underlying
 932                  * path (may or may not the same share).
 933                  */
 934                 fsp_set_fd(conn->cwd_fsp, AT_FDCWD);
 935                 return 0;
 936         }

LastDir here is the last successful directory we SMB_VFS_CHDIR()'ed to. This logic might need tweaking a bit.

Yes, been checking on master. Permissions on the containing directory matter here.

I have a share /tmp/btest, owned by user jeremy, group jeremy. Permissions are:

[btest]
    path = /tmp/btest
    read only = no

drwxrwx--- 2 jeremy jeremy 4096 Oct  6 17:52 /tmp/btest

Connecting as smbclient //127.0.0.1/btest -Uuser2%pass succeeds.

But trying to do anything (ls) fails.

(In reply to Jeremy Allison from comment #15)

The permissions for the share are:

# ls -ldn /export/smb1/
drwx------ 2 10001 10001 19 Oct  6 17:23 /export/smb1/

I tried the same test with 4.15.0, Test-2 again passed the smbd_smb2_request_check_tcon. And then it failed in OpenDir -> open_internal_dirfsp -> fd_openat.

[2021/10/07 13:38:40.180557, 10, pid=550, effective(10002, 65534), real(10002, 0)] ../../source3/smbd/open.c:930(fd_openat)
  fd_openat: name ., flags = 0200000 mode = 00, fd = -1. NT_STATUS_ACCESS_DENIED

(In reply to Lev from comment #18)

I think the LastDir cache is causing the tcon check to pass. I think this is also behind the shadow_copy2 crash. I'll look into disabling it and should have a patch for you today.

Alright, I see the problem (and the underlying issue with shadow_copy2).

The LastDir directory cache isn't vuid or current user aware.

In other words, so long as the directory path we are doing the CHDIR into matches the last successful CHDIR request, then it assumes that the new CHDIR will also succeed and just returns 0 (success).

If we have changed vuid or connection in the meantime this isn't the case, and the CHDIR for the new vuid or conn should fail with ACCESS_DENIED.

It isn't a security hole as even if we are left in the connection directory to which we have no access, as soon as any attempt to access anything is made via the VFS it returns ACCESS_DENIED, but it breaks shadow_copy2 as the shadow_copy2 CHDIR hook isn't called in this case, leaving the priv->shadow_cwd variable as zero.

There are two fixes for this. The first is a very simple one - inside set_sec_ctx_internal() call SAFE_FREE(LastDir) to delete the LastDir cache to ensure we always properly call CHDIR after changing users. This is a one-liner.

The second possible fix for this is to remove the LastDir cache, meaning we'll do the CHDIR on every incoming SMB2 packet.

I'm going to ask Ralph for his opinions on this.

Created attachment 16840 [details]
git-am fix for master.

I'm going with the "delete the LastDir on context switch patch". It's safer for now, and we can revisit removing the $cwd cache later. Also adds regression test.

In ci here:

https://gitlab.com/samba-team/devel/samba/-/pipelines/384617081

Lev, the patch I've just uploaded for master should apply cleanly to your version too if you want to test.

Created attachment 16841 [details]
git-am fix for master.

Removed erroneous line left in regression test removing the error_inject file too soon. Didn't break the test but might cause a race on a slow machine.

New ci pipeline running here:

https://gitlab.com/samba-team/devel/samba/-/pipelines/384626410

(In reply to Jeremy Allison from comment #23)

Passes ci. Asking Ralph to review.

This bug was referenced in samba master:

954e637ddc6f0f5291d0a15cdbcbc6a4f7a6cb13
4fe965836243928ac33eb95a67d3e889fdc15861

Created attachment 16844 [details]
git-am fix for 4.15.next, 4.14.next.

Cherry-picked from master.

Reassigning to Jule for inclusion in 4.14 and 4.15.

Pushed to autobuild-v4-{15,14}-test.

This bug was referenced in samba v4-14-test:

de2150dc762bb911e320cd352ab5a41a0f92bc72
edf50886ec524a58a8862c04347bbb29a8a29376

This bug was referenced in samba v4-15-test:

a55d4fe22086ff4a8b66f00e4496d91556210384
f2455a9023ca39e32b38a3f905aaf477bc90463f

Closing out bug report.

Thanks!

This bug was referenced in samba v4-14-stable (Release samba-4.14.9):

de2150dc762bb911e320cd352ab5a41a0f92bc72
edf50886ec524a58a8862c04347bbb29a8a29376

This bug was referenced in samba v4-15-stable (Release samba-4.15.1):

a55d4fe22086ff4a8b66f00e4496d91556210384
f2455a9023ca39e32b38a3f905aaf477bc90463f