Ubuntu
backintime package

How to make BIT wait until the end of a user-callback script before starting

Asked by jean-christophe manciot

I need to unmount, check some drives, remount them and fsarchive a large drive (inside "Backup-SAMSUNG-Ubuntu" script) before BIT can begin its work on the current main profile; how should I modify the user-callback to achieve that goal?

Here is my current script:
#!/bin/bash
profile_id="$1"
profile_name="$2"
backintime_status="$3"
backintime_snapshotid="$4"
PATH=/usr/local/ssl/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:

case $backintime_status in
    1) #Backup process begins
 case $profile_name in
             "Main profile")
   gnome-terminal --window-with-profile=Backup-SAMSUNG-Ubuntu
                 ;;
             *) #do this for all other profiles
                        ;;
        esac
         ;;
    2) #Backup process ends
         ;;
    3) #A new snapshot was taken
         ;;
    4) #There was an error
         case $backintime_snapshotid in
            1) #The application is not configured
                  ;;
            2) #A "take snapshot" process is already running
                  ;;
            3) #Can't find snapshots folder (is it on a removable drive ?)
                  ;;
            4) #A snapshot for "now" already exist
                  ;;
        esac
        ;;
    5) ## backintime-qt4 (GUI) started ##
        # Here you can put things that need to be done when launching the GUI
 ;;
    6) ## backintime-qt4 (GUI) closed ##
        # Here you can put things that need to be done when closing the GUI
 ;;
    7) ## Mount drives ##
       # Here you should place custom mount commands which will be called everytime
       # the GUI or command line tool is started or the profile is switched in GUI
 ;;
    8) ## Unmount the drives ##
       # Here you should place unmount scripts for the drive you mounted in 7)
 ;;
esac

Question information

Language:
English Edit question
Status:
Expired
For:
Ubuntu backintime Edit question
Assignee:
No assignee Edit question
Last query:
Last reply:
Revision history for this message
Germar (germar) said : 		#1

BackInTime's main process wait for user-callback to finish. So you can just do what ever you like in either '7) ## Mount drives ##' if this needs to be done every time you start a new snapshot, open GUI or what ever. Or if you only need this before start of a new snapshot put it into '1) #Backup process begins'

I'm not sure what you try to accomplish with 'gnome-terminal' but just in case: gnome-terminal is non-blocking. Which means the rest of the user-callback will run and finish while 'gnome-terminal' is still running and so BIT will continue.

Revision history for this message
jean-christophe manciot (manciot-jeanchristophe) said : 		#2

Thanks.
gnome-terminal launches the previous commands in a terminal, so I can actually see what is happening and take action when something goes wrong. If it'rs non-blocking, then the umount will disrupt BIT.
Is there a blocking way to see what's happening without using gnome-terminal?

Revision history for this message
Germar (germar) said : 		#3

You can run the user-callback manually from terminal to see what is happening.

~/.config/backintime/user-callback "1" "Main profile" "1"

Also current BIT version will print all output of user-callback if running with 'backintime --debug'.

BTW you should rather use 'case $profile_id in 1)' instead of $profile_name. Because profile name may change (for example on different locale)

Revision history for this message
jean-christophe manciot (manciot-jeanchristophe) said : 		#4

I'm launching "backintime-qt4 --debug" as root,with "gnome-terminal" call replaced by the script call, but no output from the script appears inside BIT:

~/.config/user-callback:
...
# gnome-terminal --window-with-profile=Backup-MSI-GE60-Ubuntu -->
/home/actionmystique/Program-Files/Ubuntu/Manual-Backup/Backup-MSI-GE60-Ubuntu.sh
...

All I see are the disks LEDs & "Working" at the bottom which suggest that something is happening, but that's not enough....
How about displaying all the script output messages in the log? Or maybe they'll appear there once everything is complete.

Revision history for this message
jean-christophe manciot (manciot-jeanchristophe) said : 		#5

Something has gone wrong: BIT has been displaying for a long time it's working when in fact, there's no disk I/O anymore.

There are some zombie BIT processes: https://drive.google.com/file/d/0B6XxNd5c3zV_VGxaWlZDOG1wV1U/view?usp=sharing

It seems that it is waiting for the script to finish, but it's already done.

Revision history for this message
jean-christophe manciot (manciot-jeanchristophe) said : 		#6

I've solved that issue by adding "exit 0" at the end of the script "Backup-MSI-GE60-Ubuntu.sh".
Now everything works fine, except that I need to see some real time messages from that script somewhere, such as in the log.

Revision history for this message
Germar (germar) said : 		#7

BIT logs all output from user-callback. Log is printed in terminal and send to syslog (/var/log/syslog). stdout will be logged as INFO and stderr as ERROR.

If you don't want BIT to catch the output from user-callback but let it print directly to terminal you can manually add 'profile<N>.user_callback.no_logging=true' to your config.

Revision history for this message
jean-christophe manciot (manciot-jeanchristophe) said : 		#8

Thanks.

However, I'm experiencing a few issues:
1) there's no user-callback log printed in terminal, unless it is replaced by BIT's log in "view last log" (I'm not there when the backup starts)
2) there's no "view user-callback log" which could allow us to review both logs
3) BTW, the regular log (not the one from user-callback) from BIT cuts the paths; isn't it possible to log the full paths?
4) the user-callback log is in /var/log/syslog indeed, but:
- some end of lines are missing, making the log very difficult to read, such as:
INFO: [plugins/usercallbackplugin.py:55 UserCallbackPlugin.notify_callback] user-callback returned 'fsck.fat 3.0.28 (2015-05-16)#012Checking we can access the last sector of the filesystem#012Boot sector contents:#012System ID "mkfs.fat"#012Media byte 0xf8 (hard disk)#012 512 bytes per logical sector#012 4096 bytes per cluster#012 32 reserved sectors#012First FAT starts at byte 16384 (sector 32)#012 2 FATs, 32 bit entries#012 500224 bytes per FAT (= 977 sectors)#012Root directory start at cluster 2 (arbitrary size)#012Data area starts at byte 1016832 (sector 1986)#012 124935 data clusters (511733760 bytes)#01263 sectors/track, 255 heads#012 2048 hidden sectors#012 1001472 sectors total#012Reclaiming unconnected clusters.#012Checking free cluster summary.#012/dev/sdb1: 7 files, 864/124935 clusters#012[ Rootkit Hunter version 1.4.2 ]#012#012#033[0;35mChecking system commands...#033[0;39m#012#012 Performing 'strings' command checks#012 Checking 'strings' command#033[31C[
- the commands in my script are not called in the correct order; as you can see from previous log line, fsck.fat call is followed by rkhunter; in my script, I have the following calls in that order (and they are not repeated):
   1. fsck.fat
   2. dd
   3. fsarchiver
   4. rkhunter
That means that BIT does not wait for each call to end before starting the next one
That's a significant issue, especially when I put some calls back into the script involving a few umount/mount...
- the fsarchiver & dd are called twice, instead of just once as in my script:
The beginning of first call:
--------------------------------------
..
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: One or more warnings have been found while checking the system.
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: Please check the log file (/var/log/rkhunter.log)'ERROR: [plugins/usercallbackplugin.py:57
UserCallbackPlugin.notify_callback] user-callback returned '125184+0 records in
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: 125184+0 records out
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: 512753664 bytes (513 MB) copied, 16.0534 s, 31.9 MB/s
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: Compression levels >= 8 may require a huge amount of memory
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: Please read the man page or "http://www.fsarchiver.org/Compression" for more details.
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: Analysing filesystem on /dev/sdb2...
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: ============= archiving filesystem /dev/sdb2 =============
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: -[00][ 0%][DIR ] /
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: -[00][ 0%][DIR ] /lost+found
Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: -[00][ 0%][SYMLINK ] /initrd.img.old

We can see we have: end of rkhunter, then dd, then fsarchiver which is an incorrect order.

the end of first call:
-----------------------------
Jan 31 09:29:47 samsung-ubuntu gnome-session[4558]: -[00][100%][SYMLINK ] /lib64/ld-linux-x86-64.so.2
Jan 31 09:29:47 samsung-ubuntu gnome-session[4558]: Statistics for filesystem 0
Jan 31 09:29:47 samsung-ubuntu gnome-session[4558]: * files successfully processed:....regfiles=156924, directories=25344, symlinks=64666, hardlinks=5, specials=84

The beginning of the second fsarchiver call, near the end of the first call (the lines with 99%):
--------------------------------------------------------------------------------------------------------------------------------------------
Jan 31 09:29:47 samsung-ubuntu gnome-session[4558]: -[00][ 99%][REGFILEM] /etc/brltty/Text/eo.ttb
Jan 31 09:29:47 samsung-ubuntu gnome-session[4558]: -[00][ 99%][REGFILEM] /etc/brltty/Text/ctl-latin.tti
Jan 31 09:29:47 samsung-ubuntu backintime (root/1): ERROR: [plugins/usercallbackplugin.py:57 UserCallbackPlugin.notify_callback] user-callback returned '125184+0 records in#012125184+0 records out#012512753664 bytes (513 MB) copied, 16.0534 s, 31.9 MB/s#012Compression levels >= 8 may require a huge amount of memory#012Please read the man page or "http://www.fsarchiver.org/Compression" for more details.#012Analysing filesystem on /dev/sdb2...#012============= archiving filesystem /dev/sdb2 =============#012-[00][ 0%][DIR ] /#012-[00][ 0%][DIR ] /lost+found#012-[00][ 0%][SYMLINK ] /initrd.img.old#012-[00][ 0%][DIR ] /var#012-[00][ 0%][DIR ] /var/log#012-[00][ 0%][REGFILEM] /var/log/apport.log.2.gz#012-[00][ 0%][DIR ] /var/log/samba#012-[00][ 0%][REGFILEM] /var/log/rkhunter.log#012-[00][ 0%][DIR ] /var/log/upstart#012-[00][ 0%][REGFILE ] /var/log/auth.log.1#012-[00][ 0%][REGFILEM] /var/log/btmp#012-[00][ 0%][REGFILEM] /var/log/gpu-manager.log#012-[00][ 0%][DIR ] /var/log/installer#012-[00][ 0%][REGFILEM]
Jan 31 09:29:47 samsung-ubuntu gnome-session[4558]: -[00][ 99%][REGFILEM] /etc/brltty/Text/bn.ttb
Jan 31 09:29:47 samsung-ubuntu gnome-session[4558]: -[00][ 99%][REGFILEM] /etc/brltty/Text/sat.ttb
...
Jan 31 09:31:55 samsung-ubuntu backintime (root/1): ERROR: CONTINUE: /etc/rc5.d/S01lvm2-lvmetad#012-[00][ 99%][SYMLINK ] /etc/rc5.d/S01cgmanager#012-[00][ 99%][SYMLINK ] /etc/rc5.d/S03lightdm#012-[00][ 99%][SYMLINK ] /etc/rc5.d/S03avahi-daemon#012-[00][ 99%][SYMLINK ] /etc/rc5.d/S02irqbalance#012-[00][ 99%][REGFILEM] /etc/drirc#012-[00][ 99%][DIR ] /media#012-[00][ 99%][DIR ] /media/actionmystique#012-[00][ 99%][DIR ] /media/actionmystique/SAMSUNG-Ext4#012-[00][ 99%][DIR ] /media/actionmystique/SAMSUNG-EFI1#012-[00][ 99%][DIR ] /media/actionmystique/SAMSUNG-EFI#012-[00][ 99%][DIR ] /media/actionmystique/WD-Ext4#012-[00][ 99%][DIR ] /media/actionmystique/SAMSUNG-Ext4-1#012-[00][ 99%][DIR ] /media/actionmystique/MSI-GE60-Windows#012-[00][ 99%][SYMLINK ] /vmlinuz#012-[00][ 99%][DIR ] /lib64#012-[00][100%][SYMLINK ] /lib64/ld-linux-x86-64.so.2#012Statistics for filesystem 0#012* files successfully processed:....regfiles=156924, directories=25344, symlinks=64666, hardlinks=5, specials=84#012* files with
Jan 31 09:31:55 samsung-ubuntu backintime (root/1): ERROR: CONTINUE: errors:...............regfiles=0, directories=0, symlinks=0, hardlinks=0, specials=0'

You may have noticed another dd call (whereas there is only one in the script), and then the second fsarchiver call which starts with: "Compression levels >= 8 ...".

Then, the regular BIT process starts:
Jan 31 09:31:56 samsung-ubuntu backintime (root/1): INFO: [common/snapshots.py:1018 Snapshots.take_snapshot] Take a new snapshot. Profile: 1 Main profile
Jan 31 09:31:56 samsung-ubuntu backintime (root/1): INFO: [common/snapshots.py:1333 Snapshots._take_snapshot] Call rsync to take the snapshot
...

There's a lot in your plate now.

Revision history for this message
Germar (germar) said : 		#9

1) there is no such thing as a user-callback log. Everything BIT does is to read stdout/stderr from your script and write it back to backintime's stdout/stderr AND through syslog-daemon into /var/log/syslog. As already said if you don't want this add 'profile1.user_callback.no_logging=true' to your config.
2) -> 1)
3) BIT doesn't cut any path but syslog-daemon does not accept unlimit chars in one line. So BIT will split loglines longer than syslog-daemons limit into multiple chunks and send them serialized to syslog -> "Jan 31 09:31:55 samsung-ubuntu backintime (root/1): ERROR: CONTINUE: " this is a second chunk indicated with CONTINUE
4) - not missing, just splited into chunks -> 3)
- BIT just executes your script and continue after the script finished with returncode 0. Please post your script so I could help troubleshoot
- looks like you're also logging backintime's stderr a second time -> "Jan 31 09:29:43 samsung-ubuntu gnome-session[4558]: Please check the log file (/var/log/rkhunter.log)'ERROR: [plugins/usercallbackplugin.py:57
UserCallbackPlugin.notify_callback] user-callback returned '125184+0 records in". The "ERROR: [...] user-callback returned ..." part is from BIT but not send to syslog by BIT

Revision history for this message
jean-christophe manciot (manciot-jeanchristophe) said : 		#10

My script works perfectly fine when called from outside of BIT,. There's no need to troubleshoot it.

Revision history for this message
Launchpad Janitor (janitor) said : 		#11

This question was expired because it remained in the 'Open' state without activity for the last 15 days.