RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1868558 - cannot create a directory in home over SMB2, mkdirat returns EBADF
Summary: cannot create a directory in home over SMB2, mkdirat returns EBADF
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: samba
Version: 8.3
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: 8.0
Assignee: Andreas Schneider
QA Contact: sssd-qe
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-08-13 06:27 UTC by Alexander Bokovoy
Modified: 2022-04-04 23:37 UTC (History)
5 users (show)

Fixed In Version: samba-4.12.3-12
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-11-04 02:00:01 UTC
Type: Bug
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHEA-2020:4543 0 None None None 2020-11-04 02:00:09 UTC
Samba Project 14427 0 None None None 2020-08-13 06:30:27 UTC
Samba Project 14464 0 None None None 2020-08-13 06:27:06 UTC

Description Alexander Bokovoy 2020-08-13 06:27:06 UTC 
FreeIPA 4.8 supports running Samba file server on its domain member. We have an automated test that creates such setup, adds a simple share and attempts to operate on it via cifs.ko mount with kerberos authentication and multiuser.

In general, the setup works. However, there are few use cases which started to fail with Samba 4.12. Unfortunately, I did not record the specific version where the regression started to happen.

In the setup, there are three machines: a DC, a file server, and a client.

The file server setup allows to access home shares.

A share was mounted as root on the client:

kinit user1
mkdir -p /mnt/smb
mount -t cifs //fs.ipa.test/homes  /mnt/smb -o multiuser,sec=krb5i

All commands below were executed as usual user, not root

Step 1.
$ kinit user1

Step 2.
On samba client inside shared dir:
$ mkdir test
mkdir: cannot create directory ‘test’: Bad file descriptor

Step 3.
On samba server inside shared dir:
$ mkdir test_serv

On samba client inside shared dir:
$ mkdir test_serv/test
-> Success

Step4
On samba client inside shared dir:
$ mkdir test
-> Success


Looking into the server logs for the step 2, we can see:

2020/08/10 17:51:06.490508,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/uid.c:298(print_impersonation_info)
  print_impersonation_info: Impersonated user: uid=(1692800004,1692800004), gid=(0,1692800004), cwd=[/home/user1]
[2020/08/10 17:51:06.490627,  3, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2] ../../source3/smbd/smb2_server.c:3266(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[9] status[NT_STATUS_FILE_CLOSED] || at ../../source3/smbd/smb2_server.c:2627
[2020/08/10 17:51:06.490711, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2] ../../source3/smbd/smb2_server.c:3158(smbd_smb2_request_done_ex)
  smbd_smb2_request_done_ex: mid [34] idx[9] status[NT_STATUS_FILE_CLOSED] body[8] dyn[yes:1] at ../../source3/smbd/smb2_server.c:3314
[2020/08/10 17:51:06.490795,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../libcli/smb/smb2_signing.c:174(smb2_signing_sign_pdu)
  signed SMB2 message
[2020/08/10 17:51:06.490848, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2_credits] ../../source3/smbd/smb2_server.c:959(smb2_set_operation_credit)
  smb2_set_operation_credit: smb2_set_operation_credit: requested 10, charge 1, granted 10, current possible/max 7459/8192, total granted/max/low/range 743/8192/35/743
[2020/08/10 17:51:06.490946, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2_credits] ../../source3/smbd/smb2_server.c:959(smb2_set_operation_credit)
  smb2_set_operation_credit: smb2_set_operation_credit: requested 10, charge 1, granted 10, current possible/max 7449/8192, total granted/max/low/range 753/8192/35/753
[2020/08/10 17:51:06.490994, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2_credits] ../../source3/smbd/smb2_server.c:959(smb2_set_operation_credit)
  smb2_set_operation_credit: smb2_set_operation_credit: requested 10, charge 1, granted 10, current possible/max 7439/8192, total granted/max/low/range 763/8192/35/763
[2020/08/10 17:51:06.491039,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../libcli/smb/smb2_signing.c:174(smb2_signing_sign_pdu)
  signed SMB2 message
[2020/08/10 17:51:06.492660, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2] ../../source3/smbd/smb2_server.c:4034(smbd_smb2_io_handler)
  smbd_smb2_request idx[1] of 9 vectors
[2020/08/10 17:51:06.492782, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2_credits] ../../source3/smbd/smb2_server.c:694(smb2_validate_sequence_number)
  smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 35 (position 35) from bitmap
[2020/08/10 17:51:06.492856, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2_credits] ../../source3/smbd/smb2_server.c:694(smb2_validate_sequence_number)
  smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 36 (position 36) from bitmap
[2020/08/10 17:51:06.492972, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2] ../../source3/smbd/smb2_server.c:2351(smbd_smb2_request_dispatch)
  smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 35
[2020/08/10 17:51:06.493049,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/uid.c:326(change_to_user_impersonate)
  change_to_user_impersonate: Skipping user change - already user
[2020/08/10 17:51:06.493125,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/uid.c:298(print_impersonation_info)
  print_impersonation_info: Impersonated user: uid=(1692800004,1692800004), gid=(0,1692800004), cwd=[/home/user1]
[2020/08/10 17:51:06.493197, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2] ../../source3/smbd/smb2_create.c:706(smbd_smb2_create_send)
  smbd_smb2_create_send: name [test_dir]
[2020/08/10 17:51:06.493248, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2] ../../source3/smbd/smb2_create.c:811(smbd_smb2_create_send)
  smbd_smb2_create_send: open execution phase
[2020/08/10 17:51:06.493295,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/filename.c:481(unix_convert)
  unix_convert called on file "test_dir"
[2020/08/10 17:51:06.493346, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/statcache.c:245(stat_cache_lookup)
  stat_cache_lookup: lookup failed for name [TEST_DIR]
[2020/08/10 17:51:06.493393,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/filename.c:682(unix_convert)
  unix_convert begin: name = test_dir, dirpath = ., start = test_dir
[2020/08/10 17:51:06.493491, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/mangle_hash2.c:413(is_mangled)
  is_mangled test_dir ?
[2020/08/10 17:51:06.493550, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/mangle_hash2.c:352(is_mangled_component)
  is_mangled_component test_dir (len 8) ?
[2020/08/10 17:51:06.493597, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/mangle_hash2.c:413(is_mangled)
  is_mangled test_dir ?
[2020/08/10 17:51:06.493674, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/mangle_hash2.c:352(is_mangled_component)
  is_mangled_component test_dir (len 8) ?
[2020/08/10 17:51:06.493738, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=vfs] ../../source3/smbd/vfs.c:1282(check_reduced_name)
  check_reduced_name: check_reduced_name [.] [/home/user1]
[2020/08/10 17:51:06.493795, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=vfs] ../../source3/smbd/vfs.c:1346(check_reduced_name)
  check_reduced_name realpath [.] -> [/home/user1]
[2020/08/10 17:51:06.493839,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=vfs] ../../source3/smbd/vfs.c:1457(check_reduced_name)
  check_reduced_name: . reduced to /home/user1
[2020/08/10 17:51:06.493979, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/mangle_hash2.c:413(is_mangled)
  is_mangled test_dir ?
[2020/08/10 17:51:06.494030, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/mangle_hash2.c:352(is_mangled_component)
  is_mangled_component test_dir (len 8) ?
[2020/08/10 17:51:06.494070,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/filename.c:1123(unix_convert)
  New file test_dir
[2020/08/10 17:51:06.494112, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=vfs] ../../source3/smbd/vfs.c:1282(check_reduced_name)
  check_reduced_name: check_reduced_name [test_dir] [/home/user1]
[2020/08/10 17:51:06.494172, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=vfs] ../../source3/smbd/vfs.c:1346(check_reduced_name)
  check_reduced_name realpath [test_dir] -> [/home/user1/test_dir]
[2020/08/10 17:51:06.494215,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=vfs] ../../source3/smbd/vfs.c:1457(check_reduced_name)
  check_reduced_name: test_dir reduced to /home/user1/test_dir
[2020/08/10 17:51:06.494260, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/open.c:5925(create_file_default)
  create_file_default: create_file: access_mask = 0x100 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x2 create_options = 0x1 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = (nil), sd = (nil), fname = test_dir
[2020/08/10 17:51:06.494314, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/open.c:5372(create_file_unixpath)
  create_file_unixpath: create_file_unixpath: access_mask = 0x100 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x2 create_options = 0x1 oplock_request = 0x0 private_flags = 0x0 ea_list = (nil), sd = (nil), fname = test_dir
[2020/08/10 17:51:06.494364,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/open.c:4255(open_directory)
  open_directory: opening directory test_dir, access_mask = 0x100, share_access = 0x7 create_options = 0x1, create_disposition = 0x2, file_attributes = 0x10
[2020/08/10 17:51:06.494415,  5, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/dosmode.c:208(unix_mode)
  unix_mode: unix_mode(test_dir) returning 0755
[2020/08/10 17:51:06.494518, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=acls] ../../source3/smbd/posix_acls.c:3520(posix_get_nt_acl)
  posix_get_nt_acl: called for file .
[2020/08/10 17:51:06.494652, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/passdb/lookup_sid.c:1174(xid_to_sid)
  xid_to_sid: UID 1692800004 -> S-1-5-21-3722864543-743103260-3007237568-1004 from cache
[2020/08/10 17:51:06.494692, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/passdb/lookup_sid.c:1174(xid_to_sid)
  xid_to_sid: GID 1692800004 -> S-0-0 from cache
[2020/08/10 17:51:06.494742, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/passdb/lookup_sid.c:1229(xid_to_sid)
  xid_to_sid: GID 1692800004 -> S-1-22-2-1692800004 fallback
[2020/08/10 17:51:06.494776, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=acls] ../../source3/smbd/posix_acls.c:2763(canonicalise_acl)
  canonicalise_acl: Access ace entries before arrange :
[2020/08/10 17:51:06.494804, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=acls] ../../source3/smbd/posix_acls.c:2776(canonicalise_acl)
  canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms ---
[2020/08/10 17:51:06.494838, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=acls] ../../source3/smbd/posix_acls.c:2776(canonicalise_acl)
  canon_ace index 1. Type = allow SID = S-1-22-2-1692800004 gid 1692800004 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms ---
[2020/08/10 17:51:06.494869, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=acls] ../../source3/smbd/posix_acls.c:2776(canonicalise_acl)
  canon_ace index 2. Type = allow SID = S-1-5-21-3722864543-743103260-3007237568-1004 uid 1692800004 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx
[2020/08/10 17:51:06.494923, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=acls] ../../source3/smbd/posix_acls.c:848(print_canon_ace_list)
  print_canon_ace_list: canonicalise_acl: ace entries after arrange
  canon_ace index 0. Type = allow SID = S-1-5-21-3722864543-743103260-3007237568-1004 uid 1692800004 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx
  canon_ace index 1. Type = allow SID = S-1-22-2-1692800004 gid 1692800004 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms ---
  canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms ---
[2020/08/10 17:51:06.494982, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=acls] ../../source3/smbd/posix_acls.c:1112(map_canon_ace_perms)
  map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff
[2020/08/10 17:51:06.495012, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=acls] ../../source3/smbd/posix_acls.c:1112(map_canon_ace_perms)
  map_canon_ace_perms: Mapped (UNIX) 0 to (NT) 0
[2020/08/10 17:51:06.495039, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=acls] ../../source3/smbd/posix_acls.c:1112(map_canon_ace_perms)
  map_canon_ace_perms: Mapped (UNIX) 0 to (NT) 0
[2020/08/10 17:51:06.495089,  2, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/open.c:4307(open_directory)
  open_directory: unable to create test_dir. Error was NT_STATUS_INVALID_HANDLE
[2020/08/10 17:51:06.495123, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/open.c:5744(create_file_unixpath)
  create_file_unixpath: NT_STATUS_INVALID_HANDLE
[2020/08/10 17:51:06.495152, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0)] ../../source3/smbd/open.c:6031(create_file_default)
  create_file: NT_STATUS_INVALID_HANDLE
[2020/08/10 17:51:06.495187,  3, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2] ../../source3/smbd/smb2_server.c:3266(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_INVALID_HANDLE] || at ../../source3/smbd/smb2_create.c:334
[2020/08/10 17:51:06.495219, 10, pid=22111, effective(1692800004, 1692800004), real(1692800004, 0), class=smb2] ../../source3/smbd/smb2_server.c:3158(smbd_smb2_request_done_ex)
  smbd_smb2_request_done_ex: mid [35] idx[1] status[NT_STATUS_INVALID_HANDLE] body[8] dyn[yes:1] at ../../source3/smbd/smb2_server.c:3314

It seems the actual failure happened in mkdir_internal() which was called from the open_directory() and called SMB_VFS_MKDIRAT(). Default implementation of mkdirat() VFS wrapper calls mkdirat() and then mkdir_internal() translates returned code to NT status error code. EBADF is translated to NT_STATUS_INVALID_HANDLE and means that a directory file descriptor passed to mkdirat() was invalid.

If the setup in question is left without any additional activity, some time later 'mkdir test_dir' will succeed. Looks like there is either a race for the directory FSP in that path or use of -1 as a FSP fd?
Comment 1 Alexander Bokovoy 2020-08-13 06:28:00 UTC 
This bug is a duplicate of https://bugzilla.samba.org/show_bug.cgi?id=14427 but I am filing it separately to track for RHEL IdM usage.
Comment 9 errata-xmlrpc 2020-11-04 02:00:01 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (samba bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2020:4543
Note You need to log in before you can comment on or make changes to this bug.