Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Failure displaining errors that contains UTF8 characters. #194

Closed
mnencia opened this issue Feb 2, 2019 · 0 comments

Comments

Projects
None yet
1 participant
@mnencia
Copy link
Member

commented Feb 2, 2019

During a backup, if rsync dies printing some UTF8 character (È in this case), barman fails to correctly handle the error.

$ barman backup all
Starting backup using rsync-exclusive method for server test-11 in /Users/mnencia/tmp/barman/test-11/base/20190202T210524
Backup start at LSN: 0/2D000028 (00000001000000000000002D, 00000028)
Starting backup copy via rsync/SSH for 20190202T210524 (4 jobs)
ERROR: The backup has failed copying files
Asking PostgreSQL server to finalize the backup.
EXCEPTION: 'ascii' codec can't encode character u'\xc8' in position 35: ordinal not in range(128)
See log file for more details.

Debug log and Traceback:

2019-02-02 21:05:23,286 [99534] barman.cli DEBUG: Initialised Barman version 2.6 (config: /Users/mnencia/.barman.conf, args: {'reuse_backup': None, 'jobs': None, 'server_name': ['all'], 'format': 'console', 'color': 'auto', 'quiet': False, 'retry_times': None, 'command': 'backup', 'retry_sleep': None, 'debug': False})
2019-02-02 21:05:23,341 [99534] barman.backup_executor DEBUG: The default backup strategy for any ssh based backup_method is: exclusive_backup
2019-02-02 21:05:23,341 [99534] barman.server DEBUG: Retention policy for server test-11: REDUNDANCY 1
2019-02-02 21:05:23,342 [99534] barman.server DEBUG: WAL retention policy for server test-11: MAIN
2019-02-02 21:05:23,342 [99534] barman.server DEBUG: Starting check: WAL archive
2019-02-02 21:05:23,342 [99534] barman.server DEBUG: Starting check: empty incoming directory
2019-02-02 21:05:23,342 [99534] barman.server DEBUG: Starting check: empty streaming directory
2019-02-02 21:05:23,342 [99534] barman.server DEBUG: Starting check: PostgreSQL
2019-02-02 21:05:23,387 [99534] barman.command_wrappers DEBUG: Command: ['/Users/mnencia/.pgenv/versions/REL_11_STABLE/bin/pg_receivewal', '--version']
2019-02-02 21:05:23,398 [99534] barman.command_wrappers DEBUG: Command return code: 0
2019-02-02 21:05:23,399 [99534] barman.command_wrappers DEBUG: Command stdout: pg_receivewal (PostgreSQL) 11.1
2019-02-02 21:05:23,399 [99534] barman.command_wrappers DEBUG: Command stderr: 
2019-02-02 21:05:23,400 [99534] barman.wal_archiver DEBUG: Look for 'barman_receive_wal' in 'synchronous_standby_names': ['']
2019-02-02 21:05:23,400 [99534] barman.wal_archiver DEBUG: Synchronous WAL streaming for barman_receive_wal: False
2019-02-02 21:05:23,401 [99534] barman.server DEBUG: Check 'PostgreSQL' succeeded for server 'test-11'
2019-02-02 21:05:23,401 [99534] barman.server DEBUG: Starting check: is_superuser
2019-02-02 21:05:23,401 [99534] barman.server DEBUG: Check 'is_superuser' succeeded for server 'test-11'
2019-02-02 21:05:23,401 [99534] barman.server DEBUG: Starting check: PostgreSQL streaming
2019-02-02 21:05:23,401 [99534] barman.server DEBUG: Check 'PostgreSQL streaming' succeeded for server 'test-11'
2019-02-02 21:05:23,401 [99534] barman.server DEBUG: Starting check: wal_level
2019-02-02 21:05:23,401 [99534] barman.server DEBUG: Check 'wal_level' succeeded for server 'test-11'
2019-02-02 21:05:23,401 [99534] barman.server DEBUG: Starting check: replication slot
2019-02-02 21:05:23,401 [99534] barman.server DEBUG: Check 'replication slot' succeeded for server 'test-11'
2019-02-02 21:05:23,401 [99534] barman.server DEBUG: Starting check: directories
2019-02-02 21:05:23,402 [99534] barman.server DEBUG: Check 'directories' succeeded for server 'test-11'
2019-02-02 21:05:23,402 [99534] barman.server DEBUG: Starting check: retention policy settings
2019-02-02 21:05:23,402 [99534] barman.server DEBUG: Check 'retention policy settings' succeeded for server 'test-11'
2019-02-02 21:05:23,402 [99534] barman.server DEBUG: Starting check: backup maximum age
2019-02-02 21:05:23,402 [99534] barman.server DEBUG: Check 'backup maximum age' succeeded for server 'test-11'
2019-02-02 21:05:23,402 [99534] barman.server DEBUG: Starting check: compression settings
2019-02-02 21:05:23,402 [99534] barman.server DEBUG: Check 'compression settings' succeeded for server 'test-11'
2019-02-02 21:05:23,402 [99534] barman.server DEBUG: Starting check: failed backups
2019-02-02 21:05:23,407 [99534] barman.server DEBUG: Check 'failed backups' succeeded for server 'test-11'
2019-02-02 21:05:23,407 [99534] barman.server DEBUG: Starting check: minimum redundancy requirements
2019-02-02 21:05:23,407 [99534] barman.server DEBUG: Check 'minimum redundancy requirements' succeeded for server 'test-11'
2019-02-02 21:05:23,407 [99534] barman.server DEBUG: Starting check: ssh
2019-02-02 21:05:23,407 [99534] barman.command_wrappers DEBUG: Command: "ssh 'localhost' '-o' 'BatchMode=yes' '-o' 'StrictHostKeyChecking=no' 'true'"
2019-02-02 21:05:24,059 [99534] barman.command_wrappers DEBUG: Command return code: 0
2019-02-02 21:05:24,059 [99534] barman.command_wrappers DEBUG: Command stdout: 
2019-02-02 21:05:24,059 [99534] barman.command_wrappers DEBUG: Command stderr: 
2019-02-02 21:05:24,060 [99534] barman.server DEBUG: Check 'ssh' succeeded for server 'test-11'
2019-02-02 21:05:24,060 [99534] barman.server DEBUG: Starting check: not in recovery
2019-02-02 21:05:24,061 [99534] barman.server DEBUG: Check 'not in recovery' succeeded for server 'test-11'
2019-02-02 21:05:24,061 [99534] barman.server DEBUG: Starting check: configuration
2019-02-02 21:05:24,061 [99534] barman.server DEBUG: Starting check: archive_mode
2019-02-02 21:05:24,061 [99534] barman.server DEBUG: Check 'archive_mode' succeeded for server 'test-11'
2019-02-02 21:05:24,061 [99534] barman.server DEBUG: Starting check: archive_command
2019-02-02 21:05:24,062 [99534] barman.server DEBUG: Check 'archive_command' succeeded for server 'test-11'
2019-02-02 21:05:24,062 [99534] barman.server DEBUG: Check 'continuous archiving' succeeded for server 'test-11'
2019-02-02 21:05:24,062 [99534] barman.server DEBUG: Starting check: pg_receivexlog
2019-02-02 21:05:24,062 [99534] barman.server DEBUG: Check 'pg_receivexlog' succeeded for server 'test-11'
2019-02-02 21:05:24,062 [99534] barman.server DEBUG: Starting check: pg_receivexlog compatible
2019-02-02 21:05:24,062 [99534] barman.server DEBUG: Check 'pg_receivexlog compatible' succeeded for server 'test-11'
2019-02-02 21:05:24,062 [99534] barman.server DEBUG: Starting check: receive-wal running
2019-02-02 21:05:24,062 [99534] barman.server DEBUG: Check 'receive-wal running' succeeded for server 'test-11'
2019-02-02 21:05:24,062 [99534] barman.server DEBUG: Starting check: archiver errors
2019-02-02 21:05:24,062 [99534] barman.server DEBUG: Check 'archiver errors' succeeded for server 'test-11'
2019-02-02 21:05:24,063 [99534] barman.backup DEBUG: initialising backup information
2019-02-02 21:05:24,067 [99534] barman.backup INFO: Starting backup using rsync-exclusive method for server test-11 in /Users/mnencia/tmp/barman/test-11/base/20190202T210524
2019-02-02 21:05:24,070 [99534] barman.backup_executor DEBUG: detecting data directory
2019-02-02 21:05:24,077 [99534] barman.backup_executor DEBUG: detecting tablespaces
2019-02-02 21:05:24,079 [99534] barman.backup_executor DEBUG: issuing start backup command
2019-02-02 21:05:24,079 [99534] barman.backup_executor DEBUG: Start of exclusive backup
2019-02-02 21:05:24,320 [99534] barman.backup_executor INFO: Backup start at LSN: 0/2D000028 (00000001000000000000002D, 00000028)
2019-02-02 21:05:24,322 [99534] barman.backup_executor INFO: Starting backup copy via rsync/SSH for 20190202T210524 (4 jobs)
2019-02-02 21:05:24,323 [99534] barman.infofile DEBUG: Config file 'postgresql.conf' already in PGDATA
2019-02-02 21:05:24,324 [99534] barman.infofile DEBUG: Config file 'pg_hba.conf' already in PGDATA
2019-02-02 21:05:24,324 [99534] barman.infofile DEBUG: Config file 'pg_ident.conf' already in PGDATA
2019-02-02 21:05:24,326 [99534] barman.copy_controller INFO: Copy started (safe before datetime.datetime(2019, 2, 2, 21, 4, 59, 589278, tzinfo=tzoffset(None, 3600)))
2019-02-02 21:05:24,326 [99534] barman.copy_controller INFO: Copy step 1 of 5: [global] analyze remote PGDATA directory: /Users/mnencia/.pgenv/data/REL_11_STABLE/main/
2019-02-02 21:05:24,326 [99534] barman.copy_controller DEBUG: list_files: '/Users/mnencia/tmp/barman/test-11/base/20190202T210524/data/'
2019-02-02 21:05:24,327 [99534] barman.command_wrappers DEBUG: Command: ['/Users/mnencia/bin/rsync', '-e', "ssh 'localhost' '-o' 'BatchMode=yes' '-o' 'StrictHostKeyChecking=no'", '--exclude=/pg_log/*', '--exclude=/pg_xlog/*', '--exclude=/pg_wal/*', '--exclude=/global/pg_control', '--exclude=pgsql_tmp*', '--exclude=postgresql.auto.conf.tmp', '--exclude=postmaster.pid', '--exclude=postmaster.opts', '--exclude=recovery.conf', '--exclude=pg_dynshmem/*', '--exclude=pg_notify/*', '--exclude=pg_replslot/*', '--exclude=pg_serial/*', '--exclude=pg_stat_tmp/*', '--exclude=pg_snapshots/*', '--exclude=pg_subtrans/*', '-rLKpts', '--delete-excluded', '--inplace', '--itemize-changes', '--itemize-changes', '--no-human-readable', '--list-only', '-r', '/Users/mnencia/tmp/barman/test-11/base/20190202T210524/data/']
2019-02-02 21:05:24,386 [99534] barman.command_wrappers DEBUG: Command return code: 1
2019-02-02 21:05:24,386 [99534] barman.command_wrappers DEBUG: Command stdout: È un errore
2019-02-02 21:05:24,387 [99534] barman.command_wrappers DEBUG: Command stderr: Simulating failure(1, È un errore)! Failure remaining 9
2019-02-02 21:05:24,387 [99534] barman.copy_controller ERROR: Unable to retrieve reference directory file list. Using only source file information to decide which files need to be copied with checksums enabled: {'err': u'Simulating failure(1, \xc8 un errore)! Failure remaining 9\n', 'ret': 1, 'out': u'\xc8 un errore\n'}
2019-02-02 21:05:24,387 [99534] barman.copy_controller DEBUG: list_files: ':/Users/mnencia/.pgenv/data/REL_11_STABLE/main/'
2019-02-02 21:05:24,387 [99534] barman.command_wrappers DEBUG: Command: ['/Users/mnencia/bin/rsync', '-e', "ssh 'localhost' '-o' 'BatchMode=yes' '-o' 'StrictHostKeyChecking=no'", '--exclude=/pg_log/*', '--exclude=/pg_xlog/*', '--exclude=/pg_wal/*', '--exclude=/global/pg_control', '--exclude=pgsql_tmp*', '--exclude=postgresql.auto.conf.tmp', '--exclude=postmaster.pid', '--exclude=postmaster.opts', '--exclude=recovery.conf', '--exclude=pg_dynshmem/*', '--exclude=pg_notify/*', '--exclude=pg_replslot/*', '--exclude=pg_serial/*', '--exclude=pg_stat_tmp/*', '--exclude=pg_snapshots/*', '--exclude=pg_subtrans/*', '-rLKpts', '--delete-excluded', '--inplace', '--itemize-changes', '--itemize-changes', '--no-human-readable', '--list-only', '-r', ' :/Users/mnencia/.pgenv/data/REL_11_STABLE/main/']
2019-02-02 21:05:24,440 [99534] barman.command_wrappers DEBUG: Command return code: 1
2019-02-02 21:05:24,441 [99534] barman.command_wrappers DEBUG: Command stdout: È un errore
2019-02-02 21:05:24,441 [99534] barman.command_wrappers DEBUG: Command stderr: Simulating failure(1, È un errore)! Failure remaining 8
2019-02-02 21:05:24,441 [99534] barman.copy_controller INFO: Copy failed (safe before 2019-02-02 21:04:59.589278+01:00)
2019-02-02 21:05:24,445 [99534] barman.backup_executor ERROR: The backup has failed copying files
2019-02-02 21:05:24,447 [99534] barman.backup_executor INFO: Asking PostgreSQL server to finalize the backup.
2019-02-02 21:05:24,447 [99534] barman.backup_executor DEBUG: Stop of exclusive backup
2019-02-02 21:05:25,607 [99534] barman.cli ERROR: 'ascii' codec can't encode character u'\xc8' in position 35: ordinal not in range(128)
See log file for more details.
Traceback (most recent call last):
  File "/Users/mnencia/prj/barman/internal/barman/cli.py", line 1320, in main
    p.dispatch(pre_call=global_config)
  File "/Users/mnencia/.pyenv/versions/barman27/lib/python2.7/site-packages/argh/helpers.py", line 55, in dispatch
    return dispatch(self, *args, **kwargs)
  File "/Users/mnencia/.pyenv/versions/barman27/lib/python2.7/site-packages/argh/dispatching.py", line 174, in dispatch
    for line in lines:
  File "/Users/mnencia/.pyenv/versions/barman27/lib/python2.7/site-packages/argh/dispatching.py", line 277, in _execute_command
    for line in result:
  File "/Users/mnencia/.pyenv/versions/barman27/lib/python2.7/site-packages/argh/dispatching.py", line 231, in _call
    result = function(namespace_obj)
  File "/Users/mnencia/prj/barman/internal/barman/cli.py", line 236, in backup
    server.backup()
  File "/Users/mnencia/prj/barman/internal/barman/server.py", line 1062, in backup
    backup_info = self.backup_manager.backup()
  File "/Users/mnencia/prj/barman/internal/barman/backup.py", line 421, in backup
    msg_lines = str(e).strip().splitlines()
UnicodeEncodeError: 'ascii' codec can't encode character u'\xc8' in position 35: ordinal not in range(128)

@mnencia mnencia self-assigned this Feb 2, 2019

@mnencia mnencia added the bug label Feb 2, 2019

@mnencia mnencia added this to the 2.7 milestone Feb 2, 2019

@mnencia mnencia added the encoding label Feb 5, 2019

@mnencia mnencia closed this in 8b8d466 Mar 19, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.