Bug 15042 - Use pathref fd instead of io fd in vfs_default_durable_cookie
Summary: Use pathref fd instead of io fd in vfs_default_durable_cookie
Status: RESOLVED FIXED
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services (show other bugs)
Version: 4.16.0
Hardware: All All
: P5 normal (vote)
Target Milestone: ---
Assignee: Jule Anger
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2022-04-10 15:52 UTC by Thomas Geppert
Modified: 2022-05-09 08:50 UTC (History)
2 users (show)

See Also:


Attachments
git-am fix for 4.16.next, 4.15.next. (5.47 KB, patch)
2022-04-29 17:36 UTC, Jeremy Allison
slow: review+
jra: review? (npower)
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Thomas Geppert 2022-04-10 15:52:02 UTC
Maybe this issue is similar to https://bugzilla.samba.org/show_bug.cgi?id=14685

A standalone Samba 4.16 Fileserver running in an unprivileged LXC container publishing shares on a bind mounted ZFS filesystem is occasionally logging the following error into /usr/local/samba/var/log.smbd:

 ../../source3/smbd/fd_handle.c:118(fsp_get_io_fd)
  fsp_get_io_fd: fsp [directory/file] is a path referencing fsp

The stack trace for this error is:

../../lib/util/fault.c:245(log_stack_trace)
  BACKTRACE:
   #0 log_stack_trace + 0x37 [ip=0x7fd422d0575b] [sp=0x7ffd7b1da470]
   #1 fsp_get_io_fd + 0x9b [ip=0x7fd422fa65fd] [sp=0x7ffd7b1dad80]
   #2 vfs_default_durable_cookie + 0x13e [ip=0x7fd4230c2e49] [sp=0x7ffd7b1dada0]
   #3 vfswrap_durable_cookie + 0x2f [ip=0x7fd422fb4c1c] [sp=0x7ffd7b1daee0]
   #4 smb_vfs_call_durable_cookie + 0x5e [ip=0x7fd42304f04a] [sp=0x7ffd7b1daf10]
   #5 smbd_smb2_create_after_exec + 0x303 [ip=0x7fd423097931] [sp=0x7ffd7b1daf40]
   #6 smbd_smb2_create_send + 0x154c [ip=0x7fd423096348] [sp=0x7ffd7b1db030]
   #7 smbd_smb2_request_process_create + 0x76b [ip=0x7fd423093b1f] [sp=0x7ffd7b1db340]
   #8 smbd_smb2_request_dispatch + 0x157c [ip=0x7fd423085f30] [sp=0x7ffd7b1db450]
   #9 smbd_smb2_io_handler + 0x876 [ip=0x7fd42308ae6b] [sp=0x7ffd7b1db540]
   #10 smbd_smb2_connection_handler + 0x4a [ip=0x7fd42308af9a] [sp=0x7ffd7b1db5f0]
   #11 tevent_common_invoke_fd_handler + 0x121 [ip=0x7fd422d8f39e] [sp=0x7ffd7b1db630]
   #12 epoll_event_loop + 0x3a5 [ip=0x7fd422d9a503] [sp=0x7ffd7b1db670]
   #13 epoll_event_loop_once + 0x138 [ip=0x7fd422d9abe6] [sp=0x7ffd7b1db6d0]
   #14 std_event_loop_once + 0x5c [ip=0x7fd422d97357] [sp=0x7ffd7b1db720]
   #15 _tevent_loop_once + 0x122 [ip=0x7fd422d8e163] [sp=0x7ffd7b1db760]
   #16 tevent_common_loop_wait + 0x25 [ip=0x7fd422d8e4c1] [sp=0x7ffd7b1db7a0]
   #17 std_event_loop_wait + 0x5c [ip=0x7fd422d973f9] [sp=0x7ffd7b1db7d0]
   #18 _tevent_loop_wait + 0x2b [ip=0x7fd422d8e564] [sp=0x7ffd7b1db810]
   #19 smbd_process + 0xca7 [ip=0x7fd42306a139] [sp=0x7ffd7b1db830]
   #20 smbd_accept_connection + 0x3cd [ip=0x564fa8dbf0d0] [sp=0x7ffd7b1db8f0]
   #21 tevent_common_invoke_fd_handler + 0x121 [ip=0x7fd422d8f39e] [sp=0x7ffd7b1db9d0]
   #22 epoll_event_loop + 0x3a5 [ip=0x7fd422d9a503] [sp=0x7ffd7b1dba10]
   #23 epoll_event_loop_once + 0x138 [ip=0x7fd422d9abe6] [sp=0x7ffd7b1dba70]
   #24 std_event_loop_once + 0x5c [ip=0x7fd422d97357] [sp=0x7ffd7b1dbac0]
   #25 _tevent_loop_once + 0x122 [ip=0x7fd422d8e163] [sp=0x7ffd7b1dbb00]
   #26 tevent_common_loop_wait + 0x25 [ip=0x7fd422d8e4c1] [sp=0x7ffd7b1dbb40]
   #27 std_event_loop_wait + 0x5c [ip=0x7fd422d973f9] [sp=0x7ffd7b1dbb70]
   #28 _tevent_loop_wait + 0x2b [ip=0x7fd422d8e564] [sp=0x7ffd7b1dbbb0]
   #29 smbd_parent_loop + 0xa5 [ip=0x564fa8dbfdf7] [sp=0x7ffd7b1dbbd0]
   #30 main + 0x1841 [ip=0x564fa8dc1ef2] [sp=0x7ffd7b1dbc10]
   #31 __libc_start_main + 0xea [ip=0x7fd422960d0a] [sp=0x7ffd7b1dbf50]
   #32 _start + 0x2a [ip=0x564fa8dbbdea] [sp=0x7ffd7b1dc020]

It looks like the error does not cause a real problem apart from cluttering the log.
Comment 1 Jeremy Allison 2022-04-12 01:28:16 UTC
Hmmm. That's a strange one.

That can only happen if we're returning a durable handle from SMB2 create:

        if (!state->replay_operation && state->durable_requested &&
            (fsp_lease_type(state->result) & SMB2_LEASE_HANDLE))
        {
                status = SMB_VFS_DURABLE_COOKIE(
                        state->result,
                        state->op,
                        &state->op->global->backend_cookie);
                if (!NT_STATUS_IS_OK(status)) {
                        state->op->global->backend_cookie = data_blob_null;
                }
        }

but the fsp->fd_handle->fd value is an fd open with O_PATH.

I have a theory... Can you add a debug here please ?

$ git diff
diff --git a/source3/smbd/smb2_create.c b/source3/smbd/smb2_create.c
index 932ec31a18a..5bc82955cf8 100644
--- a/source3/smbd/smb2_create.c
+++ b/source3/smbd/smb2_create.c
@@ -1425,6 +1425,13 @@ static void smbd_smb2_create_after_exec(struct tevent_req *req)
        if (!state->replay_operation && state->durable_requested &&
            (fsp_lease_type(state->result) & SMB2_LEASE_HANDLE))
        {
+               if (state->result->fsp_flags.is_pathref) {
+                       DBG_ERR("Durable handle requested for file %s is a "
+                               "pathref with access mask 0x%x\n",
+                               fsp_str_dbg(state->result),
+                               (unsigned int)state->result->access_mask);
+               }
+
                status = SMB_VFS_DURABLE_COOKIE(
                        state->result,
                        state->op,

That should tell me if my theory is correct.
Comment 2 Thomas Geppert 2022-04-12 11:07:14 UTC
...and at least for my part it's becoming even stranger. ;-)
I hope you can make a meaning out of the following.

This is the condensed output from the debug you asked me to add:


[2022/04/12 11:17:43.268061,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory1/file1 is a pathref with access mask 0x20080

[2022/04/12 11:17:43.310955,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory1/file1 is a pathref with access mask 0x40080

[2022/04/12 11:17:43.349613,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory1/file1 is a pathref with access mask 0x80080




[2022/04/12 11:17:52.380129,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory1/file2 is a pathref with access mask 0x20080

[2022/04/12 11:17:52.419201,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory1/file2 is a pathref with access mask 0x40080

[2022/04/12 11:17:52.457680,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory1/file2 is a pathref with access mask 0x80080




[2022/04/12 11:18:00.586439,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory2/file3 is a pathref with access mask 0x20080

[2022/04/12 11:18:00.625651,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory2/file3 is a pathref with access mask 0x40080

[2022/04/12 11:18:00.665000,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory2/file3 is a pathref with access mask 0x80080

[2022/04/12 11:18:07.272664,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory2/file3 is a pathref with access mask 0x120080




[2022/04/12 11:18:18.459834,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory3/file4 is a pathref with access mask 0x20080

[2022/04/12 11:18:18.498324,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory3/file4 is a pathref with access mask 0x40080

[2022/04/12 11:18:18.537080,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory3/file4 is a pathref with access mask 0x80080




[2022/04/12 11:18:24.620426,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory3/file5 is a pathref with access mask 0x20080

[2022/04/12 11:18:24.659101,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory3/file5 is a pathref with access mask 0x40080

[2022/04/12 11:18:24.697678,  0] ../../source3/smbd/smb2_create.c:1429(smbd_smb2_create_after_exec)
  smbd_smb2_create_after_exec: Durable handle requested for file directory3/file5 is a pathref with access mask 0x80080



For readability I have seperated the output from different files by a few blank lines.
Comment 3 Jeremy Allison 2022-04-12 17:07:02 UTC
No, it makes sense now and is pretty much what I expected to see.

The client is asking for a durable handle on what we used to call a "stat" read. i.e. it wants access to file meta-data:

FILE_READ_ATTRIBUTE  = 0x00000080;
READ_CONTROL     = 0x00020000
WRITE_DAC        = 0x00040000
WRITE_OWNER      = 0x00080000

but *doesn't* want read or write access. On Linux, or systems with O_PATH, we leave the open file descriptor on the file as a pathref fd i.e. an fd opened with O_PATH.

There is code in vfs_default_durable_cookie() to refuse a durable handle open on such an fd, but it's calling the wrong function. It's calling:

 78         if (fsp_get_io_fd(fsp) == -1) {
 79                 return NT_STATUS_NOT_SUPPORTED;
 80         }

which when compiled with #define EVELOPER will cause fsp_get_io_fd() to panic (by design) or emit a debug level 0 message without DEVELOPER. But this isn't a fatal error here, so we should be using:

if (fsp->fsp_flags.is_pathref) {
        return NT_STATUS_NOT_SUPPORTED;
}

instead. Interestingly enough, there's nothing I can see that we do on disconnect/reconnect that requires read or write access to the file, so a fix for another day might be to correctly support pathref durable handles.

But for now, here is the fix:

--------------------------------------------------
diff --git a/source3/smbd/durable.c b/source3/smbd/durable.c
index a49bca6fd61..04eacc232e0 100644
--- a/source3/smbd/durable.c
+++ b/source3/smbd/durable.c
@@ -75,7 +75,7 @@ NTSTATUS vfs_default_durable_cookie(struct files_struct *fsp,
                return NT_STATUS_NOT_SUPPORTED;
        }
 
-       if (fsp_get_io_fd(fsp) == -1) {
+       if (fsp->fsp_flags.is_pathref) {
                return NT_STATUS_NOT_SUPPORTED;
        }
 --------------------------------------------------


If you can confirm it makes the message go away (it will :-) then I'll submit an MR and get this fixed upstream.
Comment 4 Thomas Geppert 2022-04-13 12:45:10 UTC
I can confirm that the error message is gone.

That was a quick fix. Thank you very much!
Comment 5 Jeremy Allison 2022-04-15 03:02:10 UTC
MR: https://gitlab.com/samba-team/samba/-/merge_requests/2492
Comment 6 Samba QA Contact 2022-04-29 15:51:04 UTC
This bug was referenced in samba master:

bb329d4de505d2c01ba45a06311c9dc6d87f8dec
fe7daae8c4692b99ff08d4e3e48034d59ddee245
Comment 7 Jeremy Allison 2022-04-29 17:36:24 UTC
Created attachment 17280 [details]
git-am fix for 4.16.next, 4.15.next.

Back-port. Applies cleanly to 4.16.next, 4.15.next.
Comment 8 Jeremy Allison 2022-05-06 20:01:14 UTC
Ping Ralph... Can we get this in ? :-).
Comment 9 Ralph Böhme 2022-05-07 05:35:27 UTC
Reassigning to Jule for inclusion in 4.15 and 4.16.
Comment 10 Jule Anger 2022-05-09 06:30:27 UTC
Pushed to autobuild-v4-{16,15}-test.
Comment 11 Samba QA Contact 2022-05-09 07:30:06 UTC
This bug was referenced in samba v4-15-test:

a236b193c42225a448e3c9c5f289c2812fecb2e9
e75837c115bc288758baa51001c66102d2fba61c
Comment 12 Samba QA Contact 2022-05-09 08:19:03 UTC
This bug was referenced in samba v4-16-test:

c7e2b4c3e90ca90be265ea6ee518e980ea6a4364
25b7144283f7871ffba3c3adccbaa7313c4753ca
Comment 13 Jule Anger 2022-05-09 08:50:02 UTC
Closing out bug report.

Thanks!