Logging is somewhat broken

[johny-mnemonic]

I have been using RaspiBackup on Loxberry 1.x for 3 years without an issue, so I was happy to find there is a plugin for it when I finally upgraded to Loxberry 2.x
But when I tried to use it, I have found few blocking issues:-(
The most painful is, that logging is broken.
When the backup finishes successfully, the only thing that you find in the Loxberry log is this:

24.05.2020 22:41:20 TASK FINISHED

Worse is, that when it finishes with error, it is not much better:

ERROR: Backup failed with error code 109
 23.05.2020 03:22:07 TASK FINISHED

This is, quite frankly, totally useless when the backup is failing and you need to find why :-(

Would it be possible to return to default behavior of RaspiBackup and store the log file in the backup folder?
It has several advantages, like:

1. being able to check the logfile without even opening Loxberry WebUI, just using file browser of your PC and opening the backup folder on NAS/fileserver/etc.
2. being able to check the log file after Loxberry restarts (as it seems, all logs are lost during restart)
3. It should also has big benefit of not writing anything to Loxberry SD Card.
4. And last but not least, being able to actually debug what the backup was doing and why it failed.

Just for info, my backups were failing because with new 6.5 version of RaspiBackup you probably need to configure it differently than old versions or it's default behavior changed.
For my case, manually adding the following into "raspiBackup.conf" finally made it working:

DEFAULT_TAR_BACKUP_OPTIONS="-cpi --one-file-system --ignore-failed-read -v"

Without "--ignore-failed-read" it was always failing on any file changed during backup and if I remember it correctly, without "--one-file-system" it was trying to backup everything on the mounted netshare. This could be probably prevented by excluding "/opt/loxberry/system/storage/smb" path, but using that tar parameter seemed as a better solution to me.

[framps]

Error code 109 means there happened some backup tool error. In order to find the root cause of the error tar detected I suggest to use option -v with raspiBackup and check the debug log for error messages from tar. Just paste them here and I will check whether any change in raspiBackup is the root cause for your issue.

You detected '--ignore-failed-read' fixes your issue but I suggest to locate the root cause for the issue with option '-v' first. Just to check there is no major tar failure.

[johny-mnemonic]

Thanks for fast response and for RaspiBackup @framps !

I found the '--ignore-failed-read' tar option only after I have found (using verbose mode) that tar was failing on files changed during read. In case you have better advice how to solve this issue, I am all ears. I don't remember having this issue with old 6.3.x, which I used for really long time, but it could be caused by newer tar version as well...

[framps]

Great. Sou you already did what I suggested to do. Could you please show the list of files which were changed during backup? That way I may be able to check whether some change in raspiBackup 0.6.5 is the root cause.

In any case I strongly recommend not to use --ignore-failed-read because this way you may irgnore file errors for important files. Assuming the number of files is short or just a subdirectory then I recommend to use exclude statements instead.

@christianTF I assume it's OK for you we continue in this issue even it may be a raspiBackup issue?

[johny-mnemonic]

@framps Well, this issue is mostly about LB Plugin not handling RaspiBackup logs correctly and basically preventing the debugging of issues (unless you go and edit RaspiConfig manually).
Even though I have configured RaspiBackup with verbose and LB with debug level, the log is visible only while the backup is running. When it finishes, LB deletes the log and leave only the return code, which is useless for any debugging.

This issue is not about the backup issues itself, which can have plethora of reasons and which can be solved in RaspiBackup repo eventually.
My problem is related to the InfluxDB, which I am running in docker on LoxBerry. I don't want to stop it for the backup, but I don't want to exclude it either as I am pretty sure, it can survive inconsistency of one or two files. It would be best to be able to just ignore changed files, not suppressing read errors in general...

[framps]

I see. But if you just updated to 0.6.5 and then the issue started to show up for me it sounds it's related to raspiBackup update.

I suggest to exclude the files instead of globally ignore all errors.

But I agree the raspiBackup Log should not be deleted. That's @christianTF s domain 😉

[christianTF]

Hi,

some clarification about the logs:

• If LBBackup is set to Debug loglevel, it automatically enables verbose in RaspiBackup.

• The log of the plugin including the log of RaspiBackup is stored in the log folder of the plugin and available via the Logfiles tab or via Log Manager.

• It is correct, that a reboot of LoxBerry will delete the logs, as they are stored in a ramdisk to prevent sd card write-cycles. This is by design of LoxBerry.

• The log of RaspiBackup is not stored at the backup destination for two reasons:
  The plugin does not know the name of the backup folder that RaspiBackup will create, and, as some people have/had issues mounting their backup destination, this would also prevent to write the log.

From my perspective, I can try to archive the following:

• I can try to fetch/grab the backup directory somehow from the log output, and could copy the log into the backup.

• I could add come kind of “Extended options” to the WebIf where experienced user may add additional options to the backup commandline.

[framps]

* I can try to fetch/grab the backup directory somehow from the log output, and could copy the log into the backup.

👍

I don't think you have to do this.

1. raspiBackup writes a file /tmp/raspiBackup.vars which has the backup directory just created in a backup run in a variable and also the image name for a dd backup in another variable.
2. Is there any reason why you store the log at a different location than the backup directory which is the default location in raspiBackup?

* I could add come kind of “Extended options” to the WebIf where experienced user may add additional options to the backup commandline.

👍

Looks like the plugin manages the options. An alternative would be to accept raspiBackup invocation options. No sure what's better from an user point of view. But this may create some headache with spaces and quotes.

* It is correct, that a reboot of LoxBerry will delete the logs, as they are stored in a ramdisk to prevent sd card write-cycles. This is by design of LoxBerry.

Do you think it's worth to store the log in memory? Whenever a system dies by some accident the log is gone. Frankly raspiBackup is not able to kill the system if something goes wrong and thus I think it's OK. But in general I wouldn't store important system logs in memory.

Edit: Forgot to paste the .vars contents:

BACKUP_TARGETDIR="/disks/silver/backup/rsync/asterix/asterix-rsync-backup-20200524-030002"
BACKUP_TARGETFILE="/disks/silver/backup/rsync/asterix/asterix.rsync-backup-20200524-030002/asterix-rsync-backup-20200524-030002"

Looks like this is not documented on the webpage 😢 . I will add this soon.

[christianTF]

LoxBerry has very sophisticated management of system and plugin logfiles and ramdisk usage, including a logfile database and automatic deletion on several criteria. Linux system logs are in ramdisk too, but survive a reboot.

Logfiles neither in the default path nor in the backup destination would be accessible via the WebIf because of permissions, and the plugin uses LoxBerry’s logging SDK.

[johny-mnemonic]

@christianTF So the reason why not to put RaspiBackup log in target backup directory is because of permissions?

Because apart from that it shouldn't be an issue. As @framp noted, you don't need to detect backup path for setting where to log. In case you would start RaspiBackup from the backup folder and let log path unchanged, it would store it in that folder, as that is the default.
Also jumping into backup folder, before starting RaspiBackup, is good way to fail fast when backup folder is inaccessible (i.e. Backup server down).

So from my point of view, it would be best to keep plugin log in plugin folder, but add "cd Backup_Folder" before the execution of RaspiBackup.

Also you are correct with the statement, that the log is accessible in plugin folder. The issue is, that when backup fails, it only contains the log of clean-up stage. Everything else is lost. Not sure, whether this is issue of the plugin or RaspiBackup itself.

[christianTF]

#26
#27
#28
#29

I capture the log of RaspiBackup, I don’t think the plugin is responsible if something is missing in the log output in case of a failure.

Could you please upload the full plugin log of that situation.

[johny-mnemonic]

@christianTF Thanks!
I can now confirm it is the behavior of RaspiBackup.
I tried to run the backup and used command below to redirect it's log file to my own.

tail -f /opt/loxberry/log/plugins/lbbackup/raspiBackup.log | tee /media/smb/mediaserver/Backup/Loxberry/loxberry/raspiBackup.log

My log file contains whole backup stage and is ending with following:

??? RBK0021E: Backupprogram for type tgz failed with RC 1.
--- RBK0033I: Please wait until cleanup has finished.
--- RBK0043I: Removing incomplete backup in /media/smb/mediaserver/Backup/Loxberry/loxberry/loxberry-tgz-backup-20200530-190355. This may take some time. Please be patient.

While the /opt/loxberry/log/plugins/lbbackup/raspiBackup.log contains only the clean-up stage.
This means, the log file was deleted and new one created for the clean-up stage.

@framps Could you confirm, this is expected behavior? Looks like a bug to me.
Also should I add RaspiBackup feature request for being able to not fail on tar RC 1? According to tar documentation, RC 1 doesn't mean anything failed, it just means it encountered file that changed while reading it. Only RC 2 means tar failed.

[framps]

Could you confirm, this is expected behavior?

Yes, that's expected behavior. Any non zero RC from a backup tool is considered as an backup error. If a file was modified during backup and that's an expected behavior this file has to be added to the exclude list to get a successful backup with raspiBackup.

[johny-mnemonic]

Sorry @framps, I probably didn't write it correctly. I was asking whether it is expected, that clean-up stage basically overwrites the backup log, so whole backup log is effectively lost.

[framps]

Which raspiBackup version do you use? Please provide the output of sudo raspiBackup.sh --version.

[johny-mnemonic]

raspiBackup.sh --version
Version: 0.6.5 CommitSHA: f822b75 CommitDate: 2020-05-19 CommitTime: 09:58:55

[framps]

Thank you very much for the version info.

If raspiBackup fails the new backup directory is cleaned up. Because default is to store the backup log in the backup directory this will also delete the log. Therefore the log is saved in the callers home directory before cleaning up the backup directory.

I just forced a tar backup failure and the log in callers home directory is complete.

[johny-mnemonic]

That's weird.
The only thing I can think of is, that LB backup plugin is redirecting the log to the callers home directory, so when the backup fails and RaspiBackup goes into clean-up stage, it somehow overwrites that log file.

[christianTF]

Capturing the RaspiBackup log of the plugin is “special”, as earlier versions of RaspiBackup didn’t output to STDOUT or STDERR, but to TTY. I use a special call to capture the serial console.
The plugin collects the tty output at runtime directly to the plugins log.

The logfile location itself uses
'-L current'

LoxBerry-Plugin-LoxberryBackup/bin/runbackup.pl

Line 177 in eedb980

push @params, "-L", "current";

that seems to be not available anymore (it is now missing in the alphabetical parameters list, but still in the thematic list).

[framps]

as earlier versions of RaspiBackup didn’t output to STDOUT or STDERR, but to TTY.

Didn't I change the logic because you asked for it? Anyhow stderr and stdout should be used instead of direct tty output.

that seems to be not available anymore (option -L)

It's still available but not documented any more. I had a lot of trouble with users using other backup locations and thus decided to change the default to -L Backup.

I try to be backward compatible with a new version of raspiBackup if possible. If options are not documented any more they are still available because of this 😉.

[christianTF]

Yes, you’ve changed this, but I haven’t, because your change was in Dev and later in Beta but not yet in the Release as I had to release 😉

I will do a major code review and update of the plugin somewhere in August or September.
Currently my main focus is a new roof and front of my house 🙂

This is my current outlook from the balcony 😂

[framps]

I see. That's because we don't sync any releases (I don't say we should :-) ).

I wish you success in your much more important house project 😉

[johny-mnemonic]

@christianTF I see you have found some time for this plugin. ;-)
Would you please also try to adapt to the logging changes you mentioned above? Would be great to finally get the log output without manually piping it somewhere else while RaspiBackup is running...