Hook error due to cleanup failure if rsync exits early

[Robert C Jennings]

Start hook failure (with sync-on-start=True in config) when initial rsync operations fail. The metadata directory could not be removed during cleanup, causing a traceback (attached).

juju-log:
Performing initial sync from archive.ubuntu.com
Making dir /srv/ubuntu-repository-cache/apache/data/ubuntu_2015-09-26_09:41:03_u1 www-sync:www-data 555
...
Archive readiness check for 91.189.92.201
...
/usr/bin/rsync --quiet --links --perms --times --dirs --chmod=g+w --delete --compress --link-dest=/srv/ubuntu-repository-cache/apache/data/ubuntu_active/ 91.189.92.201::ubuntu/ /srv/ubuntu-repository-cache/apache/data/ubuntu_2015-09-26_09:41:03_u1
...
rsync: safe_read failed to read 1 bytes [Receiver]: Connection reset by peer (104)
rsync error: error in rsync protocol data stream (code 12) at io.c(251) [Receiver=3.1.0]
rsync failed(12):
...
No retries left. (attempt #5)
Cleaning metadata directory
Removing tree /srv/ubuntu-repository-cache/apache/data/ubuntu_2015-09-26_09:41:03_u1
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-ubuntu-repository-cache-1/charm/hooks/start", line 200, in <module>
    HOOKS.execute(sys.argv)
  File "/var/lib/juju/agents/unit-ubuntu-repository-cache-1/charm/lib/charmhelpers/core/hookenv.py", line 593, in execute
    self._hooks[hook_name]()
   File "/var/lib/juju/agents/unit-ubuntu-repository-cache-1/charm/hooks/start", line 119, in start
    meta_ver = mirror.mirror_archive(sync_host)
  File "/var/lib/juju/agents/unit-ubuntu-repository-cache-1/charm/lib/ubuntu_repository_cache/util.py", line 114, in wrapper
    result = function(*args, **kwargs)
  File "/var/lib/juju/agents/unit-ubuntu-repository-cache-1/charm/lib/ubuntu_repository_cache/mirror.py", line 196, in mirror_archive
     util.clean_metadata_dir(keep=set((current, current_good)))
  File "/var/lib/juju/agents/unit-ubuntu-repository-cache-1/charm/lib/ubuntu_repository_cache/util.py", line 225, in clean_metadata_dir
    shutil.rmtree(entry)
  File "/usr/lib/python2.7/shutil.py", line 247, in rmtree
    rmtree(fullname, ignore_errors, onerror)
  File "/usr/lib/python2.7/shutil.py", line 256, in rmtree
    onerror(os.rmdir, path, sys.exc_info())
  File "/usr/lib/python2.7/shutil.py", line 254, in rmtree
    os.rmdir(path)
OSError: [Errno 13] Permission denied: '/srv/ubuntu-repository-cache/apache/data/ubuntu_2015-09-26_09:41:03_u1/pool'

ERROR juju.worker.uniter.operation runhook.go:86 hook "start" failed: exit status 1

[Robert C Jennings (rcj)]

In the initial failure log we see that the rsync has failed prematurely and repeatedly. As a result, the charm is attempting to clean up the local metadata directory which had been used. When attempting to delete the entire destination metadata tree there is a permission failure which raises an exception. I have not recreated the exact failure as I am not recreating the internal errors that saw rsync exit early, however my tests have created a failure which matches this behavior.

I ran with a locally modified charm that would skip the rsync and fail the mirror_base() function. I that case cleanup failed as we see from the initial environment. Looking at the environment (and code) we see that the destination directory has permissions 0555 when it is create and after a successful rsync they are 0775. I appears that the early exit from rsync leaves the parent directory without write permissions this is causing the clean_metadata_dir function to fail. The fix is to create the directory with user and group write permissions (0o775 rather than 0o555 as we have done).

Summary:
Initial metadata directory permissions blocked clean on failure (LP: #1500442)

  If a unit has an rsync problem, the clean_metadata_dir() call can fail
  with a permission denied error for the metadata directory (or one of its
  entries).

  Successful 'rsync' execution has a side-effect of changing the metadata
  directory permissions from 0555 to 0775. Without rsync success the
  directory can not be removed with shutils.rmtree() due to the missing
  write permissions on the parent. The initial permissions during directory
  creation have been changed to 0775 so that cleanup can proceed even if
  rsync has failed.

[Robert C Jennings (rcj)]

Attaching the initial failure log