search

backup / backup

Easy full stack backup operations on UNIX-like systems.
http://backup.github.io/backup/v4/
MIT License
4.83k stars 676 forks source link

Logger::Logfile::Error: Log File at '/root/Backup/log/backup.log' is not writable #971

Closed gbisheimer closed 2 years ago

gbisheimer commented 2 years ago

What went wrong?

Starting with an existing backup.log file, I get the following error

[2021/09/30 11:30:11][error] CLI::Error
[2021/09/30 11:30:11][error] --- Wrapped Exception ---
[2021/09/30 11:30:11][error] Logger::Logfile::Error: Log File at '/root/Backup/log/backup.log' is not writable
[2021/09/30 11:30:11][error] CLI::Error
[2021/09/30 11:30:11][error] --- Wrapped Exception ---
[2021/09/30 11:30:11][error] Logger::Logfile::Error: Log File at '/root/Backup/log/backup.log' is not writable

If I delete the log file, I get the following error:

~/Backup/log # backup perform -t backup_scada -c /root/Backup/config.rb
[2021/09/30 11:30:29][info] Performing Backup for 'Backup DB SCADA (backup_scada)'!
[2021/09/30 11:30:29][info] [ backup 5.0.0.beta.3 : ruby 2.7.4p191 (2021-07-07 revision a21a3b7d23) [x86_64-linux-musl] ]
[2021/09/30 11:30:29][info] Database::PostgreSQL Started...
[2021/09/30 11:30:29][info] Using Compressor::Gzip for compression.
[2021/09/30 11:30:29][info]   Command: '/bin/gzip'
[2021/09/30 11:30:29][info]   Ext: '.gz'
[2021/09/30 11:30:30][info] Database::PostgreSQL Finished!
[2021/09/30 11:30:30][info] Packaging the backup files...
[2021/09/30 11:30:30][info] Running system utility 'tar'...
[2021/09/30 11:30:30][info] tar:STDOUT: tar (busybox) 1.33.1
[2021/09/30 11:30:30][info] Packaging Complete!
[2021/09/30 11:30:30][info] Cleaning up the temporary files...
[2021/09/30 11:30:30][info] Storage::Local Started...
[2021/09/30 11:30:30][info] Storing '/root/dbbackup/backup_scada/2021.09.30.11.30.29/backup_scada.tar'...
[2021/09/30 11:30:30][info] Cycling Started...
[2021/09/30 11:30:30][info] Storage::Local Finished!
[2021/09/30 11:30:30][info] Cleaning up the package files...
[2021/09/30 11:30:30][info] Backup for 'Backup DB SCADA (backup_scada)' Completed Successfully in 00:00:01
Traceback (most recent call last):
        14: from /usr/local/bundle/bin/backup:23:in `<main>'
        13: from /usr/local/bundle/bin/backup:23:in `load'
        12: from /usr/local/bundle/gems/backup-5.0.0.beta.3/bin/backup:5:in `<top (required)>'
        11: from /usr/local/bundle/gems/thor-0.20.3/lib/thor/base.rb:466:in `start'
        10: from /usr/local/bundle/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
         9: from /usr/local/bundle/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
         8: from /usr/local/bundle/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
         7: from /usr/local/bundle/gems/backup-5.0.0.beta.3/lib/backup/cli.rb:182:in `perform'
         6: from /usr/local/bundle/gems/backup-5.0.0.beta.3/lib/backup/logger.rb:101:in `clear!'
         5: from /usr/local/bundle/gems/backup-5.0.0.beta.3/lib/backup/logger.rb:165:in `start!'
         4: from /usr/local/bundle/gems/backup-5.0.0.beta.3/lib/backup/logger.rb:165:in `each'
         3: from /usr/local/bundle/gems/backup-5.0.0.beta.3/lib/backup/logger.rb:166:in `block in start!'
         2: from /usr/local/bundle/gems/backup-5.0.0.beta.3/lib/backup/logger.rb:166:in `new'
         1: from /usr/local/bundle/gems/backup-5.0.0.beta.3/lib/backup/logger/logfile.rb:80:in `initialize'
/usr/local/bundle/gems/backup-5.0.0.beta.3/lib/backup/logger/logfile.rb:106:in `setup_logfile': Logger::Logfile::Error: Log File at '/root/Backup/log/backup.log' is not writable (Backup::Logger::Logfile::Error)

After this, the logfile is created with only the first part of the last message:

[2021/09/30 11:30:29][info] Performing Backup for 'Backup DB SCADA (backup_scada)'!
[2021/09/30 11:30:29][info] [ backup 5.0.0.beta.3 : ruby 2.7.4p191 (2021-07-07 revision a21a3b7d23) [x86_64-linux-musl] ]
[2021/09/30 11:30:29][info] Database::PostgreSQL Started...
[2021/09/30 11:30:29][info] Using Compressor::Gzip for compression.
[2021/09/30 11:30:29][info]   Command: '/bin/gzip'
[2021/09/30 11:30:29][info]   Ext: '.gz'
[2021/09/30 11:30:30][info] Database::PostgreSQL Finished!
[2021/09/30 11:30:30][info] Packaging the backup files...
[2021/09/30 11:30:30][info] Running system utility 'tar'...
[2021/09/30 11:30:30][info] tar:STDOUT: tar (busybox) 1.33.1
[2021/09/30 11:30:30][info] Packaging Complete!
[2021/09/30 11:30:30][info] Cleaning up the temporary files...
[2021/09/30 11:30:30][info] Storage::Local Started...
[2021/09/30 11:30:30][info] Storing '/root/dbbackup/backup_scada/2021.09.30.11.30.29/backup_scada.tar'...
[2021/09/30 11:30:30][info] Cycling Started...
[2021/09/30 11:30:30][info] Storage::Local Finished!
[2021/09/30 11:30:30][info] Cleaning up the package files...
[2021/09/30 11:30:30][info] Backup for 'Backup DB SCADA (backup_scada)' Completed Successfully in 00:00:01

The log file is indeed writable, so I don't know why I'm getting the error message after the first backup.

What steps did you follow?

  1. gem install backup --version 5.0.0.beta.3
  2. backup check
  3. backup perform -t backup_scada -c /root/Backup/config.rb

How is your copy of backup configured?

I'm using a clean config file with the header for version 5 (# Backup v5.x Configuration)

Tell us about the computer that runs the backup gem

Running inside a docker container.

ID=alpine
VERSION_ID=3.14.2
PRETTY_NAME="Alpine Linux v3.14"
HOME_URL="https://alpinelinux.org/"
BUG_REPORT_URL="https://bugs.alpinelinux.org/"
gbisheimer commented 2 years ago

I've found the problem. Don't know why, but I was creating the docker image with docker 20.10.8 and the system running that image is using docker 19.xx.... I upgraded to docker 20.10.8 and everything works correctly.

I'm closing this issue as is not related to this gem.