OpenStack Backup/Restore and DR (Freezer)

failed to backup data to ssh storage

Bug #1638816 reported by Shangzhong Zhu on 2016-11-03

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Backup/Restore and DR (Freezer)	Fix Released	High	Shangzhong Zhu	OpenStack Backup/Restore and DR (Freezer) ocata-rc1 "ocata-rc1"

Bug Description

start the backup action:
zhusz@ubuntu:~/freezer$ freezer-agent --path-to-backup /home/zhusz/freezer --container /home/backup --backup-name my-backup-name --storage ssh --ssh-username root --ssh-key ~/.ssh/id_rsa --ssh-host 192.168.56.252 --debug

error info:
Critical Error: [Errno 2] No such file

log:
2016-11-03 15:05:58.996 24109 INFO freezer.main [-] Begin freezer agent process with args: ['/usr/local/bin/freezer-agent', '--path-to-backup', '/home/zhusz/freezer', '--container', '/home/backup', '--backup-name', 'my-backup-name', '--storage', 'ssh', '--ssh-username', 'root', '--ssh-key', '/home/zhusz/.ssh/id_rsa', '--ssh-host', '192.168.56.252', '--debug']
2016-11-03 15:05:58.996 24109 INFO freezer.main [-] log file at /home/zhusz/.freezer/freezer.log
2016-11-03 15:05:58.997 24109 DEBUG paramiko.transport [-] starting thread (client mode): 0xcb463e10L _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:58.997 24109 DEBUG paramiko.transport [-] Local version/idstring: SSH-2.0-paramiko_2.0.2 _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.002 24109 DEBUG paramiko.transport [-] Remote version/idstring: SSH-2.0-OpenSSH_5.1 _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.002 24109 INFO paramiko.transport [-] Connected (version 2.0, client OpenSSH_5.1)
2016-11-03 15:05:59.003 24109 DEBUG paramiko.transport [-] kex algos:[u'diffie-hellman-group-exchange-sha256', u'diffie-hellman-group-exchange-sha1', u'diffie-hellman-group14-sha1', u'diffie-hellman-group1-sha1'] server key:[u'ssh-rsa', u'ssh-dss'] client encrypt:[u'aes128-cbc', u'3des-cbc', u'blowfish-cbc', u'cast128-cbc', u'arcfour128', u'arcfour256', u'arcfour', u'aes192-cbc', u'aes256-cbc', <email address hidden>', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr'] server encrypt:[u'aes128-cbc', u'3des-cbc', u'blowfish-cbc', u'cast128-cbc', u'arcfour128', u'arcfour256', u'arcfour', u'aes192-cbc', u'aes256-cbc', <email address hidden>', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr'] client mac:[u'hmac-md5', u'hmac-sha1', <email address hidden>', u'hmac-ripemd160', <email address hidden>', u'hmac-sha1-96', u'hmac-md5-96'] server mac:[u'hmac-md5', u'hmac-sha1', <email address hidden>', u'hmac-ripemd160', <email address hidden>', u'hmac-sha1-96', u'hmac-md5-96'] client compress:[u'none', <email address hidden>'] server compress:[u'none', <email address hidden>'] client lang:[u''] server lang:[u''] kex follows?False _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.003 24109 DEBUG paramiko.transport [-] Kex agreed: diffie-hellman-group1-sha1 _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.003 24109 DEBUG paramiko.transport [-] Cipher agreed: aes128-ctr _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.004 24109 DEBUG paramiko.transport [-] MAC agreed: hmac-md5 _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.004 24109 DEBUG paramiko.transport [-] Compression agreed: none _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.378 24109 DEBUG paramiko.transport [-] kex engine KexGroup1 specified hash_algo <built-in function openssl_sha1> _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.378 24109 DEBUG paramiko.transport [-] Switch to new keys ... _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.384 24109 DEBUG paramiko.transport [-] Adding ssh-rsa host key for 192.168.56.252: 2cef005d30119ed082c96bebf0e2a978 _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.384 24109 DEBUG paramiko.transport [-] Trying key 2e9e66c40139397032a6b16a27ecbbae from /home/zhusz/.ssh/id_rsa _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.417 24109 DEBUG paramiko.transport [-] userauth is OK _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.697 24109 INFO paramiko.transport [-] Authentication (publickey) successful!
2016-11-03 15:05:59.701 24109 DEBUG paramiko.transport [-] [chan 0] Max packet in: 32768 bytes _log /usr/local/lib/python2.7/dist-packages/paramiko/channel.py:1095
2016-11-03 15:05:59.702 24109 DEBUG paramiko.transport [-] [chan 0] Max packet out: 32768 bytes _log /usr/local/lib/python2.7/dist-packages/paramiko/channel.py:1095
2016-11-03 15:05:59.702 24109 DEBUG paramiko.transport [-] Secsh channel 0 opened. _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563
2016-11-03 15:05:59.703 24109 DEBUG paramiko.transport [-] [chan 0] Sesch channel 0 request ok _log /usr/local/lib/python2.7/dist-packages/paramiko/channel.py:1095
2016-11-03 15:05:59.742 24109 INFO paramiko.transport.sftp [-] [chan 0] Opened sftp connection (server version 3)
2016-11-03 15:05:59.743 24109 DEBUG paramiko.transport.sftp [-] [chan 0] stat('/home/backup') _log /usr/local/lib/python2.7/dist-packages/paramiko/sftp.py:129
2016-11-03 15:05:59.744 24109 DEBUG paramiko.transport.sftp [-] [chan 0] normalize('/home/backup') _log /usr/local/lib/python2.7/dist-packages/paramiko/sftp.py:129
2016-11-03 15:05:59.749 24109 INFO freezer.job [-] Validating args for the backup job.
2016-11-03 15:05:59.750 24109 INFO freezer.main [-] Job execution Started at: 2016-11-03 15:05:59
2016-11-03 15:05:59.750 24109 INFO freezer.job [-] Backup job started. backup_name: my-backup-name, container: /home/backup, hostname: ubuntu, mode: fs, Storage: ssh, compression: gzip
2016-11-03 15:05:59.750 24109 INFO freezer.job [-] Executing sync to flush the file system buffer.
2016-11-03 15:05:59.892 24109 INFO freezer.job [-] Path to backup: /home/zhusz/freezer
2016-11-03 15:05:59.892 24109 DEBUG paramiko.transport.sftp [-] [chan 0] listdir('/home/backup/metadata/tar/ubuntu_my-backup-name') _log /usr/local/lib/python2.7/dist-packages/paramiko/sftp.py:129
2016-11-03 15:05:59.894 24109 ERROR freezer.main [-] [Errno 2] No such file
2016-11-03 15:05:59.894 24109 ERROR freezer.main Traceback (most recent call last):
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/freezer/main.py", line 226, in main
2016-11-03 15:05:59.894 24109 ERROR freezer.main freezer_main(backup_args)
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/freezer/main.py", line 111, in freezer_main
2016-11-03 15:05:59.894 24109 ERROR freezer.main return run_job(backup_args, storage)
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/freezer/main.py", line 124, in run_job
2016-11-03 15:05:59.894 24109 ERROR freezer.main response = freezer_job.execute()
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/freezer/job.py", line 124, in execute
2016-11-03 15:05:59.894 24109 ERROR freezer.main backup_level = self.backup(app_mode)
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/freezer/job.py", line 211, in backup
2016-11-03 15:05:59.894 24109 ERROR freezer.main restart_always_level=self.conf.restart_always_level)
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/freezer/engine/engine.py", line 114, in backup
2016-11-03 15:05:59.894 24109 ERROR freezer.main restart_always_level=restart_always_level
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/freezer/storage/base.py", line 141, in previous_backup
2016-11-03 15:05:59.894 24109 ERROR freezer.main hostname_backup_name=hostname_backup_name)
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/freezer/storage/base.py", line 91, in get_latest_level_zero_increments
2016-11-03 15:05:59.894 24109 ERROR freezer.main recent_to_date=recent_to_date)
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/freezer/storage/physical.py", line 70, in get_level_zero
2016-11-03 15:05:59.894 24109 ERROR freezer.main level=0) for t in self.listdir(path)]
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/freezer/storage/ssh.py", line 101, in listdir
2016-11-03 15:05:59.894 24109 ERROR freezer.main return self.ftp.listdir(directory)
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/paramiko/sftp_client.py", line 172, in listdir
2016-11-03 15:05:59.894 24109 ERROR freezer.main return [f.filename for f in self.listdir_attr(path)]
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/paramiko/sftp_client.py", line 193, in listdir_attr
2016-11-03 15:05:59.894 24109 ERROR freezer.main t, msg = self._request(CMD_OPENDIR, path)
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/paramiko/sftp_client.py", line 730, in _request
2016-11-03 15:05:59.894 24109 ERROR freezer.main return self._read_response(num)
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/paramiko/sftp_client.py", line 781, in _read_response
2016-11-03 15:05:59.894 24109 ERROR freezer.main self._convert_status(msg)
2016-11-03 15:05:59.894 24109 ERROR freezer.main File "/usr/local/lib/python2.7/dist-packages/paramiko/sftp_client.py", line 807, in _convert_status
2016-11-03 15:05:59.894 24109 ERROR freezer.main raise IOError(errno.ENOENT, text)
2016-11-03 15:05:59.894 24109 ERROR freezer.main IOError: [Errno 2] No such file
2016-11-03 15:05:59.894 24109 ERROR freezer.main
2016-11-03 15:05:59.895 24109 CRITICAL freezer.main [-] End freezer agent process unsuccessfully
2016-11-03 15:05:59.895 24109 CRITICAL freezer.main [-] Critical Error: [Errno 2] No such file

2016-11-03 15:05:59.994 24109 DEBUG paramiko.transport [-] EOF in transport thread _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1563

Shangzhong Zhu (zhusz) on 2016-11-04

Changed in freezer:
assignee:	nobody → Shangzhong Zhu (zhusz)
status:	New → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-11-07: Fix proposed to freezer (master)

Fix proposed to branch: master
Review: https://review.openstack.org/394455

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-11-14: Fix merged to freezer (master)

Reviewed: https://review.openstack.org/394455
Committed: https://git.openstack.org/cgit/openstack/freezer/commit/?id=7cf079940854f91be76be438007915b74ba21436
Submitter: Jenkins
Branch: master

commit 7cf079940854f91be76be438007915b74ba21436
Author: Shangzhong Zhu <email address hidden>
Date: Mon Nov 7 22:26:37 2016 +0800

failed to backup data to ssh storage

    When backup data to ssh storage for the first time, because the sub
    directory "metadata" isn't exist in the ssh storage directory, the
    exception IOError will be raised.

    The exception IOError should be caught in the funtion listdir() of the
    SshStorage class, and the empty list should be returned when the errno
    is ENOENT which indicates "No such file or directory". The other
    exceptions, e.g. "Permission denied", should be raised.

Change-Id: Icddca7078a47fb82c12d4232065d51e2baa0ab60
Closes-Bug: #1638816