turnip

Creating new subordinate repositories fails

Bug #1853174 reported by Colin Watson on 2019-11-19

This bug affects 3 people

Affects		Status	Importance	Assigned to	Milestone
	turnip	Triaged	Critical	Unassigned

Bug Description

Since the migration to the new deployment last night, creation of new subordinate repositories (i.e. ones where there's already a target-default repository for their target) is failing. The traceback from turnip-api looks like this:

Traceback (most recent call last):
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/gunicorn/workers/sync.py", line 130, in handle
    self.handle_request(listener, req, client, addr)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/gunicorn/workers/sync.py", line 171, in handle_request
    respiter = self.wsgi(environ, resp.start_response)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/pyramid/router.py", line 242, in __call__
    response = self.invoke_subrequest(request, use_tweens=True)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/pyramid/router.py", line 217, in invoke_subrequest
    response = handle_request(request)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/pyramid/tweens.py", line 46, in excview_tween
    response = view_callable(exc, request)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/pyramid/config/views.py", line 385, in viewresult_to_response
    result = view(context, request)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/pyramid/tweens.py", line 21, in excview_tween
    response = handler(request)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/pyramid/router.py", line 163, in handle_request
    response = view_callable(context, request)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/pyramid/config/views.py", line 596, in __call__
    return view(context, request)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/pyramid/config/views.py", line 329, in attr_view
    return view(context, request)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/pyt
hon2.7/site-packages/pyramid/config/views.py", line 305, in predicate_wrapper
    return view(context, request)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/python2.7/site-packages/pyramid/config/views.py", line 355, in rendered_view
    result = view(context, request)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/python2.7/site-packages/pyramid/config/views.py", line 501, in _requestonly_view
    response = view(request)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/env/local/lib/python2.7/site-packages/cornice/service.py", line 527, in wrapper
    response = view_()
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/turnip/api/views.py", line 77, in collection_post
    repo, clone_from=repo_clone, clone_refs=clone_refs)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/turnip/api/store.py", line 167, in init_repo
    import_into_subordinate(sub_path, clone_from)
  File "/srv/turnip/turnip-api/payloads/f486417f5fd1674241677fe2f1afb886b3aa3b24/turnip/api/store.py", line 138, in import_into_subordinate
    os.link(from_path, sub_path)
OSError: [Errno 13] Permission denied

But it's not currently clear to me why this is getting EACCES; the permissions look fine on disk. https://pastebin.canonical.com/p/s4SYJR3rgw/ shows lp:ubuntu/+source/germinate (27656) and a failed attempt to create lp:~cjwatson/ubuntu/+source/germinate (43224). Based on the find output (assuming that find iterates over directories in the same order as os.listdir, which the output seems to suggest), the EACCES is probably on objects/pack/pack-ccdf56ab39b00807e62fc0e290def554e6935b05.pack, but there seems no clear reason why that should be the case.

I haven't been able to reproduce this on staging, and manually running ln on the probable file in question succeeded. Stracing all the gunicorn processes slowed things down to the point where repository creation attempts timed out (which is a separate bug). Maybe this is an NFS race involving new directories or something?

Revision history for this message

Rafael David Tinoco (rafaeldtinoco) wrote on 2019-11-20:

Download full text (9.2 KiB)

######### On the NFS client side ###########

# link(): SVr4, 4.3BSD, POSIX.1-2001 (but see NOTES), POSIX.1-2008.

int link(const char *oldpath, const char *newpath);

ERRORS:

EACCES Write access to the directory containing newpath is denied, or search permission is denied for one of the directories in the path prefix of oldpath or newpath.

Notes:

- Hard links, as created by link(), cannot span filesystems. Use symlink(2) if this is required.

Bugs:

On NFS filesystems, the return code may be wrong in case the NFS server performs the link creation and dies before it can say so. Use stat(2) to find out if the link got created.

----

So, unless ganesha deviates from POSIX.1-2008, OR the ganesha nfsd RPC thread crashes, EACCESS should be a result of either NEWPATH having bad permissions for NFS user OR there is an issue with directory (+x) permissions in ONE directory of EITHER oldpath or newpath (/aaa/bbb/cccc <- the full path I mean).

----

######### On the NFS SERVER side ###########

Considering the NFS server is giving us EACCESS, then...

With https://github.com/nfs-ganesha/nfs-ganesha/wiki/NFS-Ganesha-Architecture:

the EACCESS comes from the def_handle_ops abstraction (FSAL/default_methods.c): fsal_test_access() or fsal_obj_ops->test_access(). We also have the MDCACHE in between final fsal_test_access() and the caller.

The stacktrace:

fsal_print_access_by_acl()
  fsacl_check_access_acl()
    fsal_test_access()
      mdcache_test_access() -> comes from mdcache(ops->test_access()) call
        mdcache_handle_ops_init() -> initializes fsal_obj_ops for:
          mdcache_fsal_init() ops->test_access = mdcache_test_access;
            start_fsals()

would tell us the exact error if:

if (!isFullDebug(COMPONENT_NFS_V4_ACL))
return;

debug was enabled.

--------

For the fsal_test_access():

/* test_access
* common (default) access check method for fsal_obj_handle objects.
* NOTE: A fsal can replace this method with their own custom access
* checker. If so and they wish to have an option to switch
* between their custom and this one, it their test_access
* method's responsibility to do that test and select this one.
*/

looks like a filesystem abstraction can replace the check method. fsal_test_access() is the DEFAULT FSAL check access but not the only one.

NOTE: I'm not sure what is the underlying FSAL you're using (ceph ?)

--------

From the FSAL abstraction layer:

/**
* @brief Check access for a given user against a given object
*
* This function checks whether a given user is allowed to perform the
* specified operations against the supplied file. The goal is to
* allow filesystem specific semantics to be applied to cached
* metadata.
*
* This method must read attributes and/or get them from a cache.
*
* @param[in] obj_hdl Handle to check
* @param[in] access_type Access requested
* @param[out] allowed Returned access that could be granted
* @param[out] denied Returned access that would be granted
* @param[in] owner_skip Skip test if op_ctx->creds is owner
*
* @return FSAL status.
*/
fsal_status_t (*test_access)(struct fsal_obj_handle *obj_hdl,
f...

######### On the NFS client side ###########

# link(): SVr4, 4.3BSD, POSIX.1-2001 (but see NOTES), POSIX.1-2008.

int link(const char *oldpath, const char *newpath);

ERRORS:

EACCES Write access to the directory containing newpath is denied, or search permission is denied for one of the directories in the path prefix of oldpath or newpath.

Notes:

- Hard links, as created by link(), cannot span filesystems.  Use symlink(2) if this is required.

Bugs:

On NFS filesystems, the return code may be wrong in case the NFS server performs the link creation and dies before it can say so.  Use stat(2) to find out if the link got created.

----

######### On the NFS SERVER side ###########

Considering the NFS server is giving us EACCESS, then...

With https://github.com/nfs-ganesha/nfs-ganesha/wiki/NFS-Ganesha-Architecture:

The stacktrace:

fsal_print_access_by_acl()
  fsacl_check_access_acl()
    fsal_test_access()
      mdcache_test_access()       -> comes from mdcache(ops->test_access()) call
        mdcache_handle_ops_init() -> initializes fsal_obj_ops for:
          mdcache_fsal_init()        ops->test_access = mdcache_test_access;
            start_fsals()

would tell us the exact error if:

if (!isFullDebug(COMPONENT_NFS_V4_ACL))
		return;

debug was enabled.

--------

For the fsal_test_access():

/* test_access
 * common (default) access check method for fsal_obj_handle objects.
 * NOTE: A fsal can replace this method with their own custom access
 *       checker.  If so and they wish to have an option to switch
 *       between their custom and this one, it their test_access
 *       method's responsibility to do that test and select this one.
 */

looks like a filesystem abstraction can replace the check method. fsal_test_access() is the DEFAULT FSAL check access but not the only one.

NOTE: I'm not sure what is the underlying FSAL you're using (ceph ?)

--------

From the FSAL abstraction layer:

/**
 * @brief Check access for a given user against a given object
 *
 * This function checks whether a given user is allowed to perform the
 * specified operations against the supplied file.  The goal is to
 * allow filesystem specific semantics to be applied to cached
 * metadata.
 *
 * This method must read attributes and/or get them from a cache.
 *
 * @param[in] obj_hdl     Handle to check
 * @param[in] access_type Access requested
 * @param[out] allowed    Returned access that could be granted
 * @param[out] denied     Returned access that would be granted
 * @param[in] owner_skip  Skip test if op_ctx->creds is owner
 *
 * @return FSAL status.
 */
	 fsal_status_t (*test_access)(struct fsal_obj_handle *obj_hdl,
				      fsal_accessflags_t access_type,
				      fsal_accessflags_t *allowed,
				      fsal_accessflags_t *denied,
				      bool owner_skip);

Considering MDCACHE is calling the FSAL (abstraction layer) test_access method, now we have to understand why the underlying FSAL is giving us EACCESS.

--------

In vanilla upstream git tree I could only find 2 places implementing that function:

The (*test_access) API is ONLY implemented by the MDCACHE:

ops->test_access = mdcache_test_access;

or the "default" FSAL function:

.test_access = fsal_test_access,	/* default is use common test */

So independently of a FSAL being used, the error must come either from MDCACHE (*test_access) layer or the FSAL (*test_access) layer.

--------

Since we already checked fsal_test_access, checking the mdcache_test_access:

/**
 * @brief Check access for a given user against a given object
 *
 * Currently, all FSALs use the default method.  We call the default method
 * directly, so that the test uses cached attributes, rather than having the
 * lower level need to query attributes each call.  This works as long as all
 * FSALs call the default method.  This should be revisited if a FSAL wants to
 * override test_access().
 *
 * @note If @a owner_skip is provided, we test against the cached owner.  This
 * is because doing a getattrs() potentially on each read and write (writes
 * invalidate cached attributes) is a huge performance hit.  Eventually, finer
 * grained attribute validity would be a better solution
 *
 * @param[in] obj_hdl     Handle to check
 * @param[in] access_type Access requested
 * @param[out] allowed    Returned access that could be granted
 * @param[out] denied     Returned access that would be granted
 * @param[in] owner_skip  Skip test if op_ctx->creds is owner
 *
 * @return FSAL status.
 */
static fsal_status_t mdcache_test_access(struct fsal_obj_handle *obj_hdl,
					 fsal_accessflags_t access_type,
					 fsal_accessflags_t *allowed,
					 fsal_accessflags_t *denied,
					 bool owner_skip)
{
	mdcache_entry_t *entry =
		container_of(obj_hdl, mdcache_entry_t, obj_handle);

if (owner_skip && entry->attrs.owner == op_ctx->creds->caller_uid)
		return fsalstat(ERR_FSAL_NO_ERROR, 0);

return fsal_test_access(obj_hdl, access_type, allowed, denied,
				owner_skip);
}

So it is very likely that we're getting the access error in the default fsal_test_access() function, not in the mdcache layer.

--------

We're likely getting an error from here (probability based on code):

if (IS_FSAL_ACE4_REQ(access_type) ||
	    (attrs.acl != NULL && IS_FSAL_ACE4_MASK_VALID(access_type))) {
		status = fsal_check_access_acl(op_ctx->creds,
					       FSAL_ACE4_MASK(access_type),
					       allowed, denied, &attrs);

} else {		/* fall back to use mode to check access. */
		status = fsal_check_access_no_acl(op_ctx->creds,
						  FSAL_MODE_MASK(access_type),
						  allowed, denied, &attrs);
	}

Depending whether we're using NFSv4, using v4 ACL list, or other, using mode bits only. AS you already checked regular directory permissions (hopefully from full paths of oldpath and newpath of the link() call with EACCESS error)..

I'll continue with v4 case only:

--------

/**
 * @brief Check access using v4 ACL list
 *
 * @param[in] creds
 * @param[in] v4mask
 * @param[in] allowed
 * @param[in] denied
 * @param[in] p_object_attributes
 *
 * @return ERR_FSAL_NO_ERROR, ERR_FSAL_ACCESS, or ERR_FSAL_NO_ACE
 */

static fsal_status_t fsal_check_access_acl(struct user_cred *creds,
					   fsal_aceperm_t v4mask,
					   fsal_accessflags_t *allowed,
					   fsal_accessflags_t *denied,
					   struct attrlist *p_object_attributes)

There are some cases where ERR_FSAL_ACCESS will be returned here AND posix2fsal_error() function tells us that the ERR_FSAL_ACCESS error code is:

case EACCES:
		return ERR_FSAL_ACCESS;

EACCESS.

LogFullDebug(COMPONENT_NFS_V4_ACL,
		     "file acl=%p, file uid=%u, file gid=%u, ", pacl, uid, gid);

TODO: Enabling Debug will give you the exact acl/uid/gid for the broken access. From the acl you will get a the ACES which is the FSAL ACE giving access type, erm, uid, gid, so you will have the exact EACCESS issue.

--------

- test_access()
 - fsal_access():
  - check_open_permission()
  - file_To_Fattr()
  - fsal_link() - OUR CASE
  - fsal_lookup()
  - fsal_readdir()
  - nfs3_read()
  - nfs4_read()
  - open2_by_name()

(*test_access) is called by:

- allocate_deallocate()

- check_open_permission() - check permissions when opening a file

- fsal_check_setattr_perms()
- fsal_remove_access()
- fsal_rename_access()

- nfs_access_op() - perform version independent ACCESS: checks access_mask to use 
- nfs3_read()     - NFSPROC3_READ function
- nfs3_write()    - NFSPROC3_WRITE function

- nfs4_op_write() - NFS4_OP_WRITE function
- nfs4_read()     - NFS4_OP_READ function
- nfs4_readdir_callback()

--------

/**
 *
 * @brief Links a new name to a file
 *
 * This function hard links a new name to an existing file.
 *
 * @param[in]  obj      The file to which to add the new name.  Must
 *                      not be a directory.
 * @param[in]  dest_dir The directory in which to create the new name
 * @param[in]  name     The new name to add to the file
 *
 * @return FSAL status
 *                                  in destination.
 */
fsal_status_t fsal_link(struct fsal_obj_handle *obj,
			struct fsal_obj_handle *dest_dir,
			const char *name)
{

It does 3 initial checks (can't be dir and must be in same FS).

Then it does:

if (!op_ctx->fsal_export->exp_ops.fs_supports(
			op_ctx->fsal_export,
			fso_link_supports_permission_checks)) {
		status = fsal_access(dest_dir,
			FSAL_MODE_MASK_SET(FSAL_W_OK) |
			FSAL_MODE_MASK_SET(FSAL_X_OK) |
			FSAL_ACE4_MASK_SET(FSAL_ACE_PERM_EXECUTE) |
			FSAL_ACE4_MASK_SET(FSAL_ACE_PERM_ADD_FILE));

if (FSAL_IS_ERROR(status))
			return status;
	}

which is calling fsal_access() for the dest dir.

--------

Our execution path is likely:

nfs3_link() -> fsal_link()

LogFullDebug(COMPONENT_NFSPROTO, "failed link: fsal_status=%s",fsal_err_txt(fsal_status));

nfs4_op_link() -> fsal_link()

will call nfs4_Errno_verbose() with:

case ERR_FSAL_ACCESS:
    nfserror = NFS4ERR_ACCESS;

--------

Revision history for this message

Rafael David Tinoco (rafaeldtinoco) wrote on 2019-11-20:

Sorry for being prolix in last comment, I was reading ganesha code, by my own personal interest, to check what could have happened and the TL;DR I have is this:

TODO: Enabling Debug will give you the exact acl/uid/gid for the broken access, together with the file/directory server was trying to access. From the acl you will get a the ACES which is the FSAL ACE structure giving you the: access type, erm, uid, gid, so you will have the exact EACCESS issue.

This will get you the EACCESS you're having in FSAL layer coming from the link() operation. Independently if you're getting it from NFS3 or NFS4 clients, LogFullDebug() or LogDebug() will get you the exact EACCESS issue you're getting (Also independently of the underlying filesystem you're using).

I hope this helps as I don't know if you can reproduce the issue outside production environment.

----

Exporting:

#export COMPONENT_DISPATCH=NIV_FULL_DEBUG
#export COMPONENT_DISPATCH=NIV_DEBUG

in the systemd .service unit might do the trick

----

#define LogDebug(component, format, args...) \
do { \
  if (unlikely(component_log_level[component] \
      >= NIV_DEBUG)) \
   DisplayLogComponentLevel(component, __FILE__,\
       __LINE__, \
        __func__, \
       NIV_DEBUG, format, ## args); \
} while (0)

----

#define LogFullDebug(component, format, args...) \
do { \
  if (unlikely(component_log_level[component] \
      >= NIV_FULL_DEBUG)) \
   DisplayLogComponentLevel(component, __FILE__,\
       __LINE__, \
        __func__, \
       NIV_FULL_DEBUG, \
       format, ## args); \
} while (0)

Revision history for this message

Rafael David Tinoco (rafaeldtinoco) wrote on 2019-11-20:

Alright, just saw you - IRC - already found the EACCESS root cause... g'luck =)

Revision history for this message

William Grant (wgrant) wrote on 2019-11-20:

The EACCESS/EPERM was an apparmor deny on ganesha's linkat(), with olddirfd being an open_by_handle_at on a cached handle. It's quite possibly an apparmor bug, since with apparmor put into complain mode it works fine.

Everything should be working fine now, but we still need to work out why apparmor breaks things.

Revision history for this message

Seth Arnold (seth-arnold) wrote on 2020-10-06:

Are there any ALLOWED lines in logs after the complain mode change?

Thanks