Fix bug: BiT does not start (DBus exception NameHasNoOwner)

[aryoda]

Fix bug: BiT does not start with DBus exception NameHasNoOwner (partial fix for #921). Also fixes Arch Linux build error (#1233).

• Fix the BiT CLI side of the bug BiT does not start: "Could not get owner of name 'net.launchpad.backintime.serviceHelper': no such name", related to pyqt5 and/or dbus packages #921
• serviceHelper system D-Bus daemon issues are still under investigation
• Fix Arch Linux build test and installation failure ([Arch] Build test fails & installation is aborted #1233)
• Add better documentation for installation on Arch using AUR package to README

[aryoda]

Also closes #1333

[buhtz]

Is it the DBus exception that pollutes the JSON output? Something like this (quick & dirty handwritten)?

$ backintime --diagnostics
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/dbus/bus.py", line 175, in activate_name_owner
    return self.get_name_owner(bus_name)
  File "/usr/lib/python3/dist-packages/dbus/bus.py", line 361, in get_name_owner
    's', (bus_name,), **keywords)
  File "/usr/lib/python3/dist-packages/dbus/connection.py", line 651, in call_blocking
    message, timeout)
dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NameHasNoOwner: Could not get owner of name 'net.launchpad.backintime.serviceHelper': no such name

   "backintime": {
        "name": "Back In Time",
        "version": "1.3.2"
    },
    "host-setup": {
        "platform": "Linux-5.10.0-18-amd64-x86_64-with-glibc2.31",
    },
    "python-setup": {
        "python": "3.9.2 default Feb 28 2021 17:03:44 CPython GCC 10.2.1 20210110",
        ],
    },
    "external-programs": {
        "rsync": "3.2.3",
        "ssh": "OpenSSH_8.4p1 Debian-5+deb11u1, OpenSSL 1.1.1n  15 Mar 2022",
        "sshfs": "3.7.1",
        "encfs": "1.9.5",
        "shell": "/bin/bash",
        "shell-version": "GNU bash, Version 5.1.4(1)-release (x86_64-pc-linux-gnu)"
    }
}

I don't understand enough about DBus, the dbus issue and how it is involved with BIT. And I don't need to. 😄 I trust you at this point. From my understanding the DBus problem isn't fixed yet. Am I right?

Am I also right to say when it is fixed that the json output of --diagnostics won't be polluted anymore?

If I'm wrong cut the rest. ;)

IMHO

The "problem" with this PR is that it kind of "deactivates" the integration test test_backintime.py::TestBackInTime::test_diagnostics_arg().

That test is an integration test because it doesn't test one isolated function/method but a whole feature (--diagnostics). Does this feature work means: Does --diagnostics give me JSON output. Technically this means: Does json.loads(output) raise a parsing exception or not? That's it. Nothing more.

On the other hand we test the content of the output. That is a unit test because we can do this quit isolated. We only test the function common/diagnostics.py::collect_diagnostics(). This is done in test_diagnostics.py::Diagnostics::*. Here we check the content of the JSON output. Are the right keys/items in it? etc

Consequence

I understand that the test test_backintime.py::TestBackInTime::test_diagnostics_arg() does make problems because the dbus issue isn't fixed yet. Because of that I would suggest to really deactivate that test in the meaning of out-comment it with # . And add a link to the DBUS issue. We also could open an extra issue about Re-activating the text when dbus is fixed.

[aryoda]

Is it the DBus exception that pollutes the JSON output?

The problem is the added log output of the captured exception (the exception itself is handled and does not bubble up).
The old implementation was totally silent (swallowed the exception) which made it difficult to diagnose.

Am I also right to say when it is fixed that the json output of --diagnostics won't be polluted anymore?

For this unit test I guess yes, but the new unit tests that eg. combine --diagnostics --debug would fail too (reason see below).

The "problem" with this PR is that it kind of "deactivates" the integration test
test_backintime.py::TestBackInTime::test_diagnostics_arg().
That test is an integration test because it doesn't test one isolated function/method but a whole feature (--diagnostics).

I think the integration test is still done in my PR because --diagnostics is still executed (and eg. every RTE makes the test fail).
Only the assertion checks in the expected results are based on text strings now instead of parsed JSON.

I would suggest to really deactivate that test in the meaning of out-comment it with #

I'd prefer to keep it running due to its integrative character.

We also could open an extra issue about Re-activating the text when dbus is fixed.

There will be no better final D-Bus fix on the BiT client-side (a connection error may always happen) and BiT was (theoretically) and is (now with this PR more reliably) able to work without it.

Opening a new issue for the real underlying problem sounds good:

Our logging system pollutes the normal (non-logging) stdout output with logging output, we need a clear separation here
(eg. logging to stderr instead of stdout) otherwise we can never separate normal from (partially random) logging output in unit tests. I think you have mentioned this problem too during the implementation of --diagnostics (when called together with --debug).

In the new issue we could also request new features

• for logging into a file via a new command line argument, env var or config file
• to add a new command line argument(s) for choosing the log level or do this in a conf file (currently we only have --debug and everything above is always logged to stdout)
• using the python standard logger instead of the custom implementation...

[aryoda]

@buhtzz

Our logging system pollutes the normal (non-logging) stdout output with logging output, we need a clear separation here
(eg. logging to stderr instead of stdout) otherwise we can never separate normal from (partially random) logging output in unit tests.

Thanks for tackling me ;-) I think I can change the unit test so that it uses JSON again by calling subprocess.check_output instead of subprocess.getoutput (the former contains only the stdout, the latter also the stderr).

I also just saw that the custom logger function already do use stderr partially and my new warnings are luckily written to stderr.

backintime/common/logger.py

Lines 48 to 53 in b4dd2d1

	def warning(msg , parent = None, traceDepth = 0):
	if DEBUG:
	msg = '%s %s' %(_debugHeader(parent, traceDepth), msg)
	print('%sWARNING%s: %s' %(bcolors.WARNING, bcolors.ENDC, msg), file=sys.stderr)
	for line in tools.wrapLine(msg):
	syslog.syslog(syslog.LOG_WARNING, 'WARNING: ' + line)

Interestingly the info and debug output is written to stdout which should be stderr too IMHO as standard python does:

If you call the functions debug(), info(), warning(), error() and critical(), they will check to see if no destination is set; and if one is not set, they will set a destination of the console (sys.stderr)

https://docs.python.org/3/howto/logging.html

I will update my PR!

[aryoda]

Interestingly the info and debug output is written to stdout which should be stderr too IMHO as standard python doe

As internal PoC I have just redirected our logger class output to stderr for ALL serverity levels and only one (!) unit test fails.

I think this is worth another PR ;-)

[buhtz]

Great to hear.

Btw: The replacement of common/logger.py with pythons own logging package is also on my todo list. Very important and will save a lot of work and will make other solutions incl. unittesting much easier to control.