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

barman-cloud-restore "seeking backwards is not allowed" #351

Closed
cescobarresi opened this issue Jul 14, 2021 · 5 comments
Closed

barman-cloud-restore "seeking backwards is not allowed" #351

cescobarresi opened this issue Jul 14, 2021 · 5 comments
Assignees
Milestone

Comments

@cescobarresi
Copy link

Hello,
when running barman-cloud-restore I get the following error:

ERROR: Barman cloud restore exception: seeking backwards is not allowed

I researched online this error and found that it is actually a python error in the tarfile module. There is a bug report detailing this error and also a "test.py" to verify the bug.

Using the provided "test.py" I verified that I had a faulty python version. I have upgraded to Ubuntu 20.04 with Python 3.8.10. Now running the "test.py" doesn't get me the error. But barman-cloud-restore keeps returning the same error.

The archive command we are using is archive_command = 'barman-cloud-wal-archive -P barman-cloud -z s3://bucket-name/ server-name %p'

I tried manually running a restore, without the help of barman-cloud-restore, and found that the backups are correct.

Has any one using barman-cloud-restore experienced this same issue?

Thanks
Francesco

@drsm79 drsm79 added this to the 2.13 milestone Jul 15, 2021
@amenonsen
Copy link
Contributor

@cescobarresi could you please provide the complete backtrace?

@cescobarresi
Copy link
Author

cescobarresi commented Jul 19, 2021

@amenonsen here the full Traceback.

If it can be usefull I can paste the full DEBUG log, but it basically does the GET of backup.info, then data.tar.gz:

2021-07-19 10:00:57,819 [541608] DEBUG: CanonicalRequest:
GET
/myserver/base/20210719T040001/data.tar.gz

host:backup-bucket.s3.eu-west-1.amazonaws.com
x-amz-content-sha256:e3b0c44298fc1c14a9fbf4c8996fb98427ae41e4649b934ca495991b7852b855
x-amz-date:20210719T080057Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2021-07-19 10:00:57,819 [541608] DEBUG: StringToSign:
AWS4-HMAC-SHA256
20210719T080057Z
20210719/eu-west-1/s3/aws4_request
236a8d8e8e3848ab11acd7faa71f013595e35ee4a1389c8a3c7e0110b2eea1d0
2021-07-19 10:00:57,820 [541608] DEBUG: Signature: 36f8ffff72072af74bfb4c5...
2021-07-19 10:00:57,820 [541608] DEBUG: Sending http request: <AWSPreparedRequest stream_output=True, method=GET, url=https://backup-bucket.s3.eu-west-1.amazonaws.com/myserver/base/20210719T040001/data.tar.gz, headers={'User-Agent': b'Boto3/1.9.253 Python/3.8.10 Linux/5.4.0-77-generic Botocore/1.16.19 Resource', ...
2021-07-19 10:00:57,951 [541608] DEBUG: https://backup-bucket.s3.eu-west-1.amazonaws.com:443 "GET /myserver/base/20210719T040001/data.tar.gz HTTP/1.1" 200 6564346528
2021-07-19 10:00:57,952 [541608] DEBUG: Response headers: {'x-amz-id-2': 'UNg99H2zw4wkB8XKkUawf1ZbOH1KOmKLAeXU129S7uf/6pCM9vDBHteqQiEcsCfR6EAKuUyD4aQ=', 'x-amz-...
2021-07-19 10:00:57,952 [541608] DEBUG: Response body:<botocore.response.StreamingBody object at 0x7f5bc20>
2021-07-19 10:00:57,952 [541608] DEBUG: Event needs-retry.s3.GetObject: calling handler <botocore.retryhandler.RetryHandler object at 0x7f5bc2359310>
2021-07-19 10:00:57,952 [541608] DEBUG: No retry needed.
2021-07-19 10:00:57,953 [541608] DEBUG: Event needs-retry.s3.GetObject: calling handler <bound method S3RegionRedirector.redirect_from_error of <botocore.utils.S3RegionRedirector object at 0x7f5bc2359370>>
2021-07-19 10:00:57,953 [541608] DEBUG: Response: {'ResponseMetadata': ...

When it has finished the download I get the error in extract_tar:

2021-07-19 10:07:06,368 [541608] ERROR: Barman cloud restore exception: seeking backwards is not allowed
2021-07-19 10:07:06,368 [541608] DEBUG: Exception details:
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/barman/clients/cloud_restore.py", line 70, in main
    downloader.download_backup(config.backup_id, config.recovery_dir)
  File "/usr/lib/python3/dist-packages/barman/clients/cloud_restore.py", line 230, in download_backup
    self.cloud_interface.extract_tar(file_info.path, target_dir)
  File "/usr/lib/python3/dist-packages/barman/cloud.py", line 879, in extract_tar
    tf.extractall(path=dst)
  File "/usr/lib/python3.8/tarfile.py", line 2028, in extractall
    self.extract(tarinfo, path, set_attrs=not tarinfo.isdir(),
  File "/usr/lib/python3.8/tarfile.py", line 2069, in extract
    self._extract_member(tarinfo, os.path.join(path, tarinfo.name),
  File "/usr/lib/python3.8/tarfile.py", line 2141, in _extract_member
    self.makefile(tarinfo, targetpath)
  File "/usr/lib/python3.8/tarfile.py", line 2180, in makefile
    source.seek(tarinfo.offset_data)
  File "/usr/lib/python3.8/tarfile.py", line 515, in seek
    raise StreamError("seeking backwards is not allowed")
tarfile.StreamError: seeking backwards is not allowed

Thanks.

@amenonsen
Copy link
Contributor

amenonsen commented Jul 23, 2021

@cescobarresi thanks for the details. I have not yet fully understood the problem. I tried test.py from the page you linked to, and I actually get the same error even with Python 3.9.0 and 3.8.6:

Traceback (most recent call last):
  File "/home/ams/test.py", line 12, in <module>
    tf.extractall()
  File "/home/ams/.pyenv/versions/3.9.0/lib/python3.9/tarfile.py", line 2034, in extractall
    self.extract(tarinfo, path, set_attrs=not tarinfo.isdir(),
  File "/home/ams/.pyenv/versions/3.9.0/lib/python3.9/tarfile.py", line 2075, in extract
    self._extract_member(tarinfo, os.path.join(path, tarinfo.name),
  File "/home/ams/.pyenv/versions/3.9.0/lib/python3.9/tarfile.py", line 2155, in _extract_member
    self.makelink(tarinfo, targetpath)
  File "/home/ams/.pyenv/versions/3.9.0/lib/python3.9/tarfile.py", line 2247, in makelink
    self._extract_member(self._find_link_target(tarinfo),
  File "/home/ams/.pyenv/versions/3.9.0/lib/python3.9/tarfile.py", line 2147, in _extract_member
    self.makefile(tarinfo, targetpath)
  File "/home/ams/.pyenv/versions/3.9.0/lib/python3.9/tarfile.py", line 2186, in makefile
    source.seek(tarinfo.offset_data)
  File "/home/ams/.pyenv/versions/3.9.0/lib/python3.9/tarfile.py", line 513, in seek
    raise StreamError("seeking backwards is not allowed")

The other thing I'm a bit puzzled about is that the error seems dependent on the tarfile containing symlinks, but the tar files uploaded by barman-cloud-backup should not contain symlinks (neither pg_wal nor the symlinks under pg_tblspc are included in the tar files). Since you tested a restore by hand, perhaps you could shed some light on this? Are there some other symlinks?

(We've tried to reproduce this using barman-cloud-restore directly, but have not been able to do so.)

@cescobarresi
Copy link
Author

I was using a symlik as destination of barman-cloud-restore so now I've tested without using a symlink as destination and the error is the same.

Following your suggestion I manually downloaded the backup a searched for symlinks inside. The only one I could find i the root "." which in the source is a symlink.

barman@srvpsqlutils:/mnt/temp_disk/test_restore$ tar -vtf data.tar.gz | grep lr
lrwxrwxrwx postgres/postgres 0 2019-09-19 11:45 . -> /media/data

"dot" is the root of the tarball, here the first few files of the tar:

barman@srvpsqlutils:/mnt/temp_disk/test_restore$ tar -vtf data.tar.gz | head
lrwxrwxrwx postgres/postgres 0 2019-09-19 11:45 . -> /media/data
-rw------- postgres/postgres 3 2019-09-19 11:29 ./PG_VERSION
-rw------- postgres/postgres 88 2019-09-19 11:29 ./postgresql.auto.conf
-rw-r----- postgres/postgres 30 2021-07-17 00:00 ./current_logfiles
drwx------ postgres/postgres  0 2019-09-19 11:27 lost+found/
drwx------ postgres/postgres  0 2019-09-19 11:29 pg_tblspc/
drwx------ postgres/postgres  0 2021-07-17 03:46 global/
-rw------- postgres/postgres 16384 2021-04-12 02:53 global/2695
-rw------- postgres/postgres 16384 2020-12-14 16:57 global/2397
-rw------- postgres/postgres 24576 2021-04-12 02:51 global/1261_fsm

In the source server, where barman-cloud-backup is run, we have this symlink:

root@srvpsql02:/var/lib/postgresql/11# ls -la
total 8
drwxr-xr-x  2 postgres postgres 4096 Sep 19  2019 .
drwxr-xr-x 10 postgres postgres 4096 Jul  5 10:45 ..
lrwxrwxrwx  1 postgres postgres   11 Sep 19  2019 main -> /media/data

I don't find it wrong to have /var/lib/postgresql/11/main -> /media/data, but maybe is uncommon?

With regard to you having the python bug in you system: at the end of the issue bpo-12800 you can see that the fix has been merged in python master, 3.9 and 3.8. Depending on the release you are running you may have the bug in tarfile library. I haven't tested on 3.9 but I can tell you that in python 3.8.10 the bug is fixed.

The thing that is confusing me is that the python I have installed doesn't have the tarfile bug, but when running barman-cloud-restore the tarfile bug appears.

barman@srvpsqlutils:~$ /usr/bin/python3 --version
Python 3.8.10
barman@srvpsqlutils:~$ /usr/bin/python3 test.py
barman@srvpsqlutils:~$ tar -tvf test.tar
-rw-rw-r-- barman/barman    12 2021-07-23 14:28 message.txt
lrwxrwxrwx barman/barman     0 2021-07-23 14:28 symlink.txt -> message.txt
barman@srvpsqlutils:~$ cat /usr/bin/barman-cloud-restore
#!/usr/bin/python3
# EASY-INSTALL-ENTRY-SCRIPT: 'barman==2.12','console_scripts','barman-cloud-restore'
__requires__ = 'barman==2.12'
import re
import sys
from pkg_resources import load_entry_point

if __name__ == '__main__':
    sys.argv[0] = re.sub(r'(-script\.pyw?|\.exe)?$', '', sys.argv[0])
    sys.exit(
        load_entry_point('barman==2.12', 'console_scripts', 'barman-cloud-restore')()
    )
$ python3 /usr/bin/barman-cloud-restore -P barman-cloud s3://backup-bucket srvpsql02 20210718T040002 /var/lib/postgresql/11/main -v
2021-07-23 14:17:39,666 [986373] INFO: Found credentials in shared credentials file: ~/.aws/credentials
2021-07-23 14:17:40,191 [986373] INFO: Found file from backup '20210718T040002' of server 'srvpsql02': srvpsql02/base/20210718T040002/data.tar.gz
2021-07-23 14:25:47,467 [986373] ERROR: Barman cloud restore exception: seeking backwards is not allowed

amenonsen added a commit that referenced this issue Jul 23, 2021
It's perfectly valid to have PGDATA, say /var/lib/postgresql/13/main, be
a symlink to /mnt/somedir. But there were two significant problems with
how barman-cloud-backup handled this case.

1. If you run `barman-cloud-restore … /some/dir`, you would expect that
   directory to BE your data directory, not a symlink to somewhere else.
   Even if you were OK with the symlink, there would be no way to allow
   you to specify a different directory, the way it is now possible to
   do for tablespaces.

2. As reported in #351, there are Python-version-dependent problems with
   extracting from a tarfile that contains symlinks.

   Using Python 3.8.10 or newer may fix the problem or some part of it,
   but barman-cloud-restore can still trigger the "seeking backwards is
   not allowed" error under 3.8.10 with a backup from a server where
   PGDATA is a symlink.

The existing behaviour being unreasonable and problematic—and clearly
not anticipated by the code—we change _backup_copy to check if PGDATA
is a symlink, and if so, just backup whatever it points to.

Closes #351
@amenonsen
Copy link
Contributor

@cescobarresi Thanks! Your mention of PGDATA itself being a symlink helped me to reproduce the problem. Here's a quick update.

  1. You're right, the problem with test.py happens in 3.8.6 and 3.9.0, but it is fixed in 3.8.10 and 3.9.6 (but it may have been fixed earlier, I didn't try any smaller minor versions).
  2. You're also right that if you run barman-cloud-restore under Python 3.8.10 (to do this I set PYTHONPATH), you do still get the same "seeking backwards is not allowed" error. I have not actually looked in more detail, but one possible explanation is that the upstream fix was about changing what is stored in the tar file, and not about how the tar file is extracted.
  3. The reason I didn't look in more detail is that, after some thought, I decided that the correct way to fix this is to not try to store the top-level symlink in data.tar at all (for reasons as explained in the commit message of 62aecdc, linked above).

By fixing the problem at the source, in barman-cloud-backup, we avoid the tarfile version-dependent behaviour altogether. I have verified this fix, and it works OK. If you have a chance, please try it in your environment. Of course, you will have to take a new backup, you will not be able to restore the old one.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants