Where does script output go to (difference between BEFORE and AFTER?)

S1dney · April 7, 2020, 7:29am

Hey Guys,

TL;DR
Wondering a few things regarding scripting in duplicati:

Where does the --run-script-[before|after] stdout output go to (is there a difference)?
Why is output written to stderr in the BEFORE event shown after the backup as warning, but errors written during AFTER don’t show up?

Full details
Recently adopted duplicati and very happy with it so far.
I’m still tailoring it to my needs, which the --run-script-before and --run-script-after switches are perfect for.
More specifically I’m working on a script that makes sure that my docker environment is in a consistent state (off, for most containers) before backing up their databases and data. No issues there, it all works well.

Now one thing I don’t really understand, nor was able to found explained somewhere, is where exactly does output go to when echoed to stdout?
Upon creating the initial versions of the script I noticed the echo commands (used to see/log what was going on) seemed to “vanish”, so therefore I’ve created a simple function write_log that checks an environment variable for value TRUE, and if it is, it’ll write debug information into a file in the /tmp dir. When I call the function with “ERROR” behind it, it’ll also write the same line into the stderr stream, so that it shows up in the final log as a warning (which is does, but only while running the BEFORE event, the AFTER errors don’t show up in any log).

I have several steps in my AFTER sequence, that aims to start docker and also checks if the number of docker containers running is the same as before the backup, but I’m wondering how to get the log to show any errors, I know I can just exit with 4 and have an exit thrown, but it doesn’t give me any details on the error I’ve outputted into stderr during the AFTER event which will be confusing if something will fail in the future.

Note that I’m aware I can have duplicati just mail the loglines and have the same information, but I’d like to understand what is going on here
When I’ve sorted this out I’ll expand my work to include mailing.

Running in:

Docker image duplicati/duplicati (DUPLICATI_VERSION=2.0.5.1_beta_2020-01-18)
unRAID (slackware based) host
Docker CE version 19.03.5

I appreciate any efforts taken to read and answer
Cheers!

drwtsn32 · April 16, 2020, 3:25am

Welcome to the forum, @S1dney

stderr is captured in either --run-script-before or --run-script-after but all that it does is include the output in Duplicati’s own logging mechanism.

stdout on the other hand is only captured in --run-script-before. It’s designed to let a backup script adjust parameters before the backup runs. Duplicati will parse stdout looking for strings that start with -- so it can adjust parameters.

You can see an example here:

github.com

duplicati/duplicati/blob/master/Duplicati/Library/Modules/Builtin/run-script-example.sh#L145


	# If the operation is a backup starting, 
	# then we check if the --dblock-size option is unset
	# or 50mb, and change it to 25mb, otherwise we 
	# leave it alone
	
	if [ "$OPERATIONNAME" == "Backup" ]
	then
		if [ "$DUPLICATI__dblock_size" == "" ] || ["$DUPLICATI__dblock_size" == "50mb"]
		then
			# Write the option to stdout to change it
			echo "--dblock-size=25mb"
		else
			# We write this to stderr, and it will show up as a warning in the logfile
			echo "Not setting volumesize, it was already set to $DUPLICATI__dblock_size" >&2
		fi
	else
		# This will be ignored
		echo "Got operation \"OPERATIONNAME\", ignoring"	
	fi


elif [ "$EVENTNAME" == "AFTER" ]

stdout is never written to Duplicati’s logging mechanism that I can see.

drwtsn32 · April 16, 2020, 3:29am

It should… when you exit with 4, the stderr text should be included in the Errors section of the job log.

Relevant code snip:

github.com

duplicati/duplicati/blob/master/Duplicati/Library/Modules/Builtin/RunScript.cs#L275-L280


      
          stdout = cs.StandardOutput;

          if (p.ExitCode != 0)

          {

              if (!requiredScript)

              {

                  // We log a warning or an error depending on the exit code

S1dney · April 16, 2020, 9:52am

This makes a lot of sense.
Thank you very much for taking the effort in elaborating this.

I’m actually learning C#, cause I noticed I run into these kinds or situations more often.
I like the idea to actually be able to browse the source code and find it out myself.

The thing that got me off though if the fact that the else statement in the bash example script echoes out to stdout:

else
# This will be ignored
echo “Got operation "OPERATIONNAME", ignoring”
fi

Since the output isn’t captured, I thought: “why would the example echo the Operation result into thin air” ?

I will modify my runscripts so that they output their log into a common log in /tmp and iterate that log after the last backup job to see if errors occurred in either BEFORE or AFTER phase. This makes sure that I can also catch events that don’t necessarily compromise backup integrity (like docker containers that did not came up).

Thanks again for this push in the right direction.
Cheers!

S1dney · April 16, 2020, 9:56am

I might look into this better. The code does suggest indeed that this should be the case…

However, if I take the approach of iteration the logs this will not technically be necessary, since my log that is mailed to me will contain a hint for the fail .

Cheers!

drwtsn32 · April 16, 2020, 2:52pm

Let me know if it still doesn’t seem to work right for you and I can do some testing. Good luck!

S1dney · June 9, 2020, 6:59pm

So I finally found the time to take a good look at this.
This is still bugging me. It still does not appear to do what I thought it would and (if I’ve read your comments correctly) still not as you thought it would as well.

I’ve setup a very very basic script to illustrate this:

#!/bin/bash

# We read a few variables first.
EVENTNAME=$DUPLICATI__EVENTNAME
OPERATIONNAME=$DUPLICATI__OPERATIONNAME
REMOTEURL=$DUPLICATI__REMOTEURL
LOCALPATH=$DUPLICATI__LOCALPATH

# Basic setup, we use the same file for both before and after,
# so we need to figure out which event has happened
if [ "$EVENTNAME" == "BEFORE" ]
then

    if [ "$OPERATIONNAME" == "Backup" ]
    then
	
        echo "Echoing into stdout, will not show up anywhere cause it's is no option."
    else
	    # This will be ignored
	    echo "Got operation \"OPERATIONNAME\", ignoring"	
    fi

elif [ "$EVENTNAME" == "AFTER" ]
then

    # If this is a finished backup, we send an email
    if [ "$OPERATIONNAME" == "Backup" ]
    then

        echo "This will trigger an error, which will show as warning cause we exit with 0, but this message won't show up in the errorlog." >&2
	    exit 0
    else
	    # This will be ignored
	    echo "Got operation \"OPERATIONNAME\", ignoring"	
    fi
else
    # This should never happen, but there may be new operations
    # in new version of Duplicati
    # We write this to stderr, and it will show up as a warning in the logfile
    echo "Got unknown event \"$EVENTNAME\", ignoring" >&2
fi

exit 0

This script will trigger a warning in the AFTER stage since it writes something the stderr, but exits with 0 (which is considered sucess).
Changing the exit 0 to exit 5 causes the job to throw an error, but only in the console window, I cannot find any details on the error anywhere.

On clicking the “Show” button, I only see those entries.
Note that the warning shown was because I removed too much from the example script causing the BEFORE phase to fail, since the event was unknown.

I have been looking into the source code again, but still cannot find a reason why it behaves like it does.
I’m backing up just one folder (a small one) with my test job, but these principles should apply to any job.

Appreciate the help again!!

EDIT:
It seems like stdout options are ignored also.
I’m trying to exit the script and skip the --run-script-after script by setting these before I exit.
I used echo “–run-script-after=""” first but noticed this did not work, so used a non-existing path instead.

write_log "$DUPLICATI__dblock_size"
echo "--run-script-after=/test/test" # Remove the after script
echo "--dblock-size=25mb"

write_log "$DUPLICATI__run_script_after"
write_log "$DUPLICATI__dblock_size"

I also included the blocksize from the example-script to make sure I was doing the correctly.
Write_log shows these settings not being applied tho

09-06-2020 23:17:29 --> INFO: 50mb
09-06-2020 23:17:29 --> INFO: /scripts/TEST.sh
09-06-2020 23:17:29 --> INFO: 50mb

Things aren’t really working along here hahaha, really sad cause the options to script against this really looked promising and I got pretty enthusiastic about it!