GUI doesn't inform about errors in callback-script

[buhtz]

I was wondering why the bit-gui told me there is no need for a new snapshot when I tried to start one manually. So restarted bit on the bash and found out that my callback-script had a simple import error (because my Debian GNU/Linux updated the python environment).

There should be a way that a GUI-only user is informed about things like that. Maybe this is related to the IPC planed redesign?

Back In Time
Version: 1.2.0~alpha0

Back In Time comes with ABSOLUTELY NO WARRANTY.
This is free software, and you are welcome to redistribute it
under certain conditions; type `backintime --license' for details.

INFO: Lock
ERROR: user-callback returned 'Traceback (most recent call last):
  File "/home/user/.config/backintime/user-callback", line 17, in <module>
    from plyer import tts
ModuleNotFoundError: No module named 'plyer''
WARNING: user-callback returncode: 1
ERROR: Plugin usercallbackplugin mount failed: 
INFO: Mountpoint /home/user/.local/share/backintime/mnt/9AB43DFF/mountpoint is already mounted
ERROR: user-callback returned 'Traceback (most recent call last):
  File "/home/user/.config/backintime/user-callback", line 17, in <module>
    from plyer import tts
ModuleNotFoundError: No module named 'plyer''
WARNING: user-callback returncode: 1
INFO: A plugin prevented the backup
ERROR: user-callback returned 'Traceback (most recent call last):
  File "/home/user/.config/backintime/user-callback", line 17, in <module>
    from plyer import tts
ModuleNotFoundError: No module named 'plyer''
WARNING: user-callback returncode: 1
ERROR: Plugin usercallbackplugin unmount failed: 
INFO: Mountpoint /home/user/.local/share/backintime/mnt/9AB43DFF/mountpoint still in use. Keep mounted
INFO: Unlock

[Germar]

The current way of handling status messages in GUI is more like an educated guess. Can't fix this without the new IPC

[aryoda]

found out that my callback-script had a simple import error (because my Debian GNU/Linux updated the python environment).

@buhtzz I am surprised that you are using python in the user-callback script. Do you still have a minimal user-callback script for me for reproducing this error?

Generally I think the existing error handling of user-callback calls in BiT looks very good and it would perhaps be a better solution to add set -o pipefail -e to the user-callback to fail on every error (non-zero exit code) so that the error immediately comes back to BiT and can be recognized (otherwise only the exit code of the last command is returned AFIR and this "shadows" the earlier error).

Edit: On the error discovery side only little improvements are possible (and are completely out of control of BiT), eg. by extending the user-callback scripts with this command:

#!/bin/bash

# When an error happens in a bash script by default it throws an error message to "stderr"
# but continues its execution with the rest of the script. 
#
# Use this command to enable "exit-on-error" to exit immediately if
# - a command has a non-zero exit code
# - an error occurs inside a pipeline of command (otherwise only the last command is considered)
# - a syntax error occurs (or a command is not found)
set -o pipefail -e

[aryoda]

Indicative analysis

I have analyzed the the issue a little bit to understand how user-callback script errors are recognized and (re)thrown as exceptions at the moment but it will be not easy to find a simple way to inform the user about the exceptions.

The basic problem is not that user-callback script (runtime) errors are not recognized but that they are not directly and visible fed back to the user via GUI.

Example with a synchronous call from GUI

If the last command of the script fails by returning a non-zero return code this is recognized by the plugin
and logged as warning and additionally an exception is thrown:

backintime/common/plugins/usercallbackplugin.py

Lines 95 to 97 in 4940192

	if callback.returncode != 0:
	logger.warning('user-callback returncode: %s' %callback.returncode, self)
	raise StopException()

The exception is then handled by the pluginmanager and only logged but not fed back to the GUI:

backintime/common/pluginmanager.py

Lines 330 to 340 in 4940192

	try:
	plugin.unmount(profileID)
	except BaseException as e:
	self.logError(plugin, e)
	def logError(self, plugin, e):
	logger.error('Plugin %s %s failed: %s'
	%(plugin.__module__, #plugin name
	sys._getframe(1).f_code.co_name, #method name
	str(e)), #exception
	self, 1)

The logger just writes to the console and the syslog:

backintime/common/logger.py

Lines 44 to 46 in 4940192

	print('%sERROR%s: %s' %(bcolors.FAIL, bcolors.ENDC, msg), file=sys.stderr)
	for line in tools.wrapLine(msg):
	syslog.syslog(syslog.LOG_ERR, 'ERROR: ' + line)

WARNING: user-callback returncode: 33
ERROR: Plugin usercallbackplugin unmount failed: 

The call stack up to the GUI comprises eg. for an "unmount":

backintime/common/mount.py

Line 157 in 4940192

self.config.PLUGIN_MANAGER.unmount(self.profile_id)

backintime/common/mount.py

Line 261 in 4940192

self.umount(hash_id = hash_id)

backintime/qt/app.py

Line 642 in 4940192

hash_id = mnt.remount(new_profile_id)

backintime/qt/app.py

Line 617 in 4940192

self.remount(profile_id, old_profile_id)

backintime/qt/app.py

Line 1617 in 4940192

qapp.exec_()

Here the exception handling could be changed to bubble-up to the GUI.

Example of an async call ("take snapshot" button)

Clicking the "take snapshot" button calls

backintime/qt/app.py

Lines 873 to 875 in 4940192

	def btnTakeSnapshotClicked(self):
	backintime.takeSnapshotAsync(self.config)
	self.updateTakeSnapshot(True)

which then spaws a new process in takeSnapshotAsync with backintime --profile-id 1 backup as command in

backintime/common/backintime.py

Line 81 in 4940192

subprocess.Popen(cmd, env = env)

Here exception handling is not possible due to the async out-of-process call.

Summary

Some user-callback script calls are sync, some async (out-of-process).

For a decent feed-back of (runtime) errors in the user-callback script

• a separate communication channel would be required (as @Germar indicated it above: Eg. via IPC)
• a general concept is required how to present messages to the user (eg. pop-up windows for fatal errors, a summary window after finishing long-running tasks and eg. a permanently visible "live" log output textbox)

Regarding IPC I see these options:

1. via defined text files (eg. implemented in logger.py)
2. monitoring and showing the relvant syslog (into which is written by the logger functions)
3. DBus communication
4. Check how backup progress bar updates are propagated from the job to the GUI...
5. ... your proposal goes here ;-)

Text-based IPC would also require defined unique keywords and arguments to re-translate the output into feed-back that the user can interpret in the context of GUI...

Next steps

Implementing this task is too much work for me ATM so I put it back into the box.
When a GUI-redesign is due this would be the right time to implement this task too...