Decode Error in password handling

[Benjamin Schmid]

Since I upgraded to the latest BIT version which transitioned the Gnome version to the QT4 version, BIT completely stopped working for me. I'm trying to do backups to an encrypted SSH target as Root user.

BIT displays my old snapshots. On pressing "Take snapshots" it does some things and then simply ends with "Nothing to backup" in the statusbar.

Running "pkexec backintime-qt4" in a console reveals the following error. Not sure if this is the problem:
    UnicodeDecodeError: 'utf-8' codec can't decode byte 0xb5 in position 1: invalid start byte

Full output attached as file.

What can I do to get BIT working again?

[Germar (germar)]

I was able to reproduce it here. I was planing to release a new version today but now I'll shift this until I've fixed this.

[Benjamin Schmid (benbuntu)]

That's great, Germar! Thank you for your quick and positive feedback. Looking forward to your next release.

[Germar (germar)]

Hi Benjamin and Mauro,

could you both please test the dev release from testing ppa (sudo add-apt-repository ppa:bit-team/testing && sudo apt-get update && sudo apt-get upgrade) and report back if this fixed your problems?

Thanks,
Germar

[Mauro (mauromol)]

Hi Germar,
I started my system, installed the new BIT version from the testing repository and waited for the scheduled plan.
However, nothing happend. I see this in my /var/log/syslog:

Mar 18 23:00:02 hppb backintime (mauro): INFO: Lock
Mar 18 23:00:02 hppb backintime (mauro): WARNING: Inhibit Suspend failed.
Mar 18 23:00:02 hppb backintime (mauro): ERROR: Non ho potuto sbloccare la chiave privata ssh. Password errata o non disponibile per cron.
Mar 18 23:00:02 hppb backintime (mauro): INFO: Unlock

The error in English is something like: I couldn't unlock the SSH private key. Wrong password or password not available for cron.

[Mauro (mauromol)]

Please note that meanwhile I uninstalled python3-secretstorage because it seemed to make no difference. Maybe I have to reinstall it and retry? The testing package still doesn't seem to require it as a dependency.

Also note that the fix for bug 1426881 (whose fix version is the same as this) seems not to be in this package, or at least it isn't working (I still get the "can't find UUID" error if I do not connect my USB device, even if I'm trying to change settings for another profile that doesn't use that device).

[Mauro (mauromol)]

I checked that the SSH key password is fine in kwallet. How can I check if it is actually available to cron? Should I see it in cleartext in "crontab -l"? Because, if it should be there, I don't see it at all in my crontab:
0 * * * * /usr/bin/nice -n 19 /usr/bin/ionice -c2 -n7 /usr/bin/backintime --profile-id 3 --backup-job >/dev/null 2>&1

Another weird thing I see is this: I tried to change the settings of my profile, but I was hit by bug 1426881: so, I would have expected no change were made by BIT to my profile configuration, however now my "crontab -l" output is empty (I see just the two BIT commented lines, the line I reported above is now missing). So, it seems like that when the error of bug 1426881 is shown, BIT actually has already done some activity (cleaning up the crontab) so I'm left in an inconsistent state.

[Germar (germar)]

No, your password must not be in crontab!

Please use the attached diff to add some traps in BIT. It will log your password to syslog. So please make sure to use a dummy password. Than run run a new snapshot and post the corresponding lines from /var/log/syslog

To install please run:
cd /usr/share/backintime
sudo patch -p0 < /path/to/pw_debug.diff

BTW python3-secretstorage is now in Recommends for backintime-qt4

[Benjamin Schmid (benbuntu)]

Thanks Germar. This release seems to fix the issue! Currently BIT is effectively running a backup.
Furthermore this version removes a little annoyance for me, by respecting my dark GTK theme again.

[Mauro (mauromol)]

I think that re-saving settings (as I wrote in the other bug report) was the key to fix also this problem, because today the remote SSH profile started to backup without the need to enter the SSH key password.

If I see this issue occur again, I will apply your debug patch and let you know. Thank you very much!!

[Germar (germar)]

Great! Thanks for the feedback!
I'm planing to release next version on Saturday. So please keep on testing ;-) and if you find a show-stopper please don't hesitate to report.

Kind regards,
Germar

[Mauro (mauromol)]

I still have problems here :-(
Today, no snapshot was taken. I open the BIT main window, switch to my remote profile and BIT says it can't unlock my SSH key... again!!
So, I have applied your patch. Now, if I open the BIT main window and switch to may remote profile, the UI freezes.
If I cat /var/log/syslog I see a long series of:

Mar 22 00:23:19 hppb /askpass.py: INFO: recived password from pw_cache:
Mar 22 00:23:19 hppb /askpass.py: INFO: askpass recived password from pw_cache
Mar 22 00:23:19 hppb /askpass.py: INFO: recived password from pw_cache:
Mar 22 00:23:19 hppb /askpass.py: INFO: askpass recived password from pw_cache

It seems like pw_cache returns a "space" or an "empty" password.

[Mauro (mauromol)]

Now I've run backtime --pw-cache stop after killing the UI.
Without doing anything else, I now find my /var/log/syslog flooded with:

Mar 22 00:28:40 hppb /askpass.py: INFO: recived password from pw_cache: myrealpassword
Mar 22 00:28:40 hppb /askpass.py: INFO: askpass recived password myrealpassword from pw_cache

So, this time the password seems to be correct. However, BIT is flooding /var/log/syslog and if I open its main window, as soon as I try to switch to the remote profile the UI freezes.

If I do a ps -ef | grep backintime I see the following:

mauro 3343 1 0 00:27 ? 00:00:00 python3 /usr/share/backintime/common/backintime.py --pw-cache start
root 3406 1 0 mar21 ? 00:00:00 /usr/bin/python3 /usr/share/backintime/qt4/serviceHelper.py
mauro 8869 3355 0 00:30 ? 00:00:00 /bin/sh /usr/bin/backintime-askpass Bad passphrase, try again for /home/mauro/.ssh/id_rsa:
mauro 8870 8869 0 00:30 ? 00:00:00 python3 /usr/share/backintime/common/askpass.py Bad passphrase, try again for /home/mauro/.ssh/id_rsa:
mauro 8874 8598 0 00:30 pts/7 00:00:00 grep --colour=auto backintime

If I repeat the command, I see that the pid for askpass.py changes continuously. I think it's this that is flooding my /var/log/syslog

After killing pid 3343 above it stopped.

[Mauro (mauromol)]

Now whenever I start the BIT and try to switch to that profile, the loop begins and the UI freezes. Now I also killed the --pw-cache start process, but askpass.py keeps on kicking in, I don't know from where it spawns...

If I manually start my remote profile via command-line, it hangs after:

INFO: Lock
INFO: Inhibit Suspend started. Reason: take snapshot

and the /var/log/syslog is flooded. The strange thing is that the password is now correct in /var/log/syslog...

I'm going to restart the system and, if I can't get out of this, I will revert the patch.

[Mauro (mauromol)]

I reverted the patch without rebooting (re-applied the patch with -R) and now the snapshot I started via command line magically started and /var/log/syslog stopped to be flooded. The snapshot started correctly, without asking me for SSH unlock password.

So, two conclusions:
1) the debug patch has some problem that causes the log output to be produced in an infinite loop
2) it seems like in some circumstances BIT is retrieving the password correctly, in some other it is not. Honestly, I can't really understand what's going on. If you have an idea on what I could do to try to isolate a better use case, please let me know.

[Mauro (mauromol)]

Sorry for flooding, I'm writing as soon as I discover something new.
When I said "today, no snapshot was taken" I was not quite right: having BIT back to normal, I now see that today it has taken some snapshots until 7 pm, then stopped. At that time I must have switched off the system and for sure I've turned it on again at around 9 pm or so. From that moment on no new snapshot was taken (it should every hour).
So, for some obscure reason, sometimes unlocking the SSH key works, sometimes it does not...

Please note I still don't have python3-secretstorage installed, because I could not yet understand if it's really needed or not.

[Germar (germar)]

Could have been that the debug marks interrupted the askpass process.

It sometimes happens that pw-cache doesn't collect the passwords on startup and so only return empty strings. I'm neither yet sure why this happens nor can I just say empty string is invalid and do it again because if you have a passphrase-less key the string must be empty.

If this happens again it should help to run 'backintime --pw-cache restart'

Some versions of python3-keyring do have kwallet and Gnome-keyring support integrated. For others we need to install either python3-keyring-kwallet, python3-gnomekeyring or python3-secretstorage. Where python3-secretstorage is a method to access both kwallet and Gnome-keyring. This depends very much on the distribution and release. You are fine without all of them because it is integrated in python3-keyring

[Mauro (mauromol)]

My suspect is that if I open BIT main window, password is retrieved correctly, otherwise, if the first event is the start of the job caused by cron, it won't and it will ask me for SSH key password. But it's just a guess, I don't have exact proofs for this.
Could it be that the process to decode the password is different in those two cases?

[Germar (germar)]

Did you deactivate the autostart 'Backintime Password Cache'? Please run 'gnome-session-properties' and make sure 'Backintime Password Cache' is checked.

Because this is responsible for collecting passwords from keyring. If it doesn't start at user login the first instance of BIT will try to collect passwords from keyring and paste it to pw-cache. But cronjobs can't connect to keyring (because of missing environs) and so it will fail.

[Mauro (mauromol)]

I'm using KDE, not Gnome and I don't have gnome-session-properties.
I don't have changed anything regarding Backintime Password Cache, maybe there's a problem in the BIT installer package that does not register this as autostart in case of KDE?

[Germar (germar)]

BIT installs a systemwide autostart entry in /etc/xdg/autostart/backintime.desktop. It could get overridden by ~/.config/autostart/backintime.desktop. So if the second exist, please delete it.

This should start 'python3 /usr/share/backintime/common/backintime.py --pw-cache start' after login. Please make sure this process is running ('ps ax | grep [b]ackintime.py') directly after a clean restart.

Both /etc/xdg/autostart/ and ~/.config/autostart/ are default autostart folder defined by freedesktop specs. And KDE respects this in here.

[Mauro (mauromol)]

"ps ax | grep backintime" shows only /usr/bin/python3 /usr/share/backintime/qt4/serviceHelper.py
In /etc/xdg/autostart/backintime.desktop I do have "backintime --pw-cache start".
I do not have ~/.config/autostart/backintime.desktop.
So, how is it possible that the password cache does not start? I have to investigate...

[Mauro (mauromol)]

Interesting. First of all I determined the desktop file is honoured and backintime --pw-cache start is run.
However, look at what just happened. The command was run, but here is the output of two pses run quickly one after the other:

mauro@hppb:~ > ps -ef | grep backintime
mauro 3336 1 0 23:10 ? 00:00:00 ssh-agent python3 /usr/share/backintime/common/backintime.py --pw-cache start
root 3421 1 1 23:10 ? 00:00:00 /usr/bin/python3 /usr/share/backintime/qt4/serviceHelper.py
mauro 3680 3642 0 23:11 pts/4 00:00:00 grep --colour=auto backintime
mauro@hppb:~ > ps -ef | grep backintime
root 3421 1 0 23:10 ? 00:00:00 /usr/bin/python3 /usr/share/backintime/qt4/serviceHelper.py
mauro 3732 3642 0 23:11 pts/4 00:00:00 grep --colour=auto backintime

The same happens if I run: "kioclient exec /etc/xdg/autostart/backintime.desktop": ssh-agent starts, then dies after some seconds, while python3 backintime.py --pw-cache start is not run.

If I run backintime --pw-cache start manually, instead, I see two processes:
mauro 4120 1 0 23:15 ? 00:00:00 ssh-agent python3 /usr/share/backintime/common/backintime.py --pw-cache start
mauro 4124 1 2 23:15 ? 00:00:00 python3 /usr/share/backintime/common/backintime.py --pw-cache start

and after some seconds just:
mauro 4124 1 0 23:15 ? 00:00:00 python3 /usr/share/backintime/common/backintime.py --pw-cache start

Any idea on why this different behaviour?

[Mauro (mauromol)]

Funny enough, if I edit /etc/xdg/autostart/backintime.desktop and I change:
Terminal=false
to:
Terminal=true

running the desktop file with kioclient makes the password cache starts correctly!

The side effect is there's an ugly terminal window that opens and closes at session start.

[Germar (germar)]

Looks like your distribution is missing some environ variables while launching the autostart files. Sorry for asking again, I'm sure you already told me that, but which distri and release do you use? I'll setup a VM and try my self.

In your first 'ps' in #23 the pw-cache already died. Only the ssh-agent took some more seconds to terminate it self, too.

[Mauro (mauromol)]

I'm using Linux Mint 17.1 KDE.

[Mauro (mauromol)]

Hi Germar, did you have the chance to test with my distribution? Otherwise, if you prefer, I can try some debugging if you sent me patches...
Thanks in advance!

[Germar (germar)]

Sorry, I totally forgot this. I'll have a look very soon.

[Germar (germar)]

Hey Mauro,

Sorry for the long delay. I finally managed to install Mint 17.1 KDE and I wasn't able to store passwords in keyring at all. I'm not sure if that's the same for you, too. But please let us check this first before I go on with troubleshooting.

The 'Save Password to keyring' checkbox in BackInTime was grayed out and the command "python3 -c 'import keyring; print(keyring.get_keyring())' " returned <keyring.backends.file.EncryptedKeyring object at 0x7f5070b34b00>

I fixed this by installing python3-pykde4 (sudo apt-get install python3-pykde4)

If this works correctly the above command should print <keyring.backends.kwallet.Keyring object at 0x7ff6945e4f98>
Also the 'Save Password to keyring' checkbox should be active.

Please check this and install python3-pykde4 if necessary. If this didn't help I'll look further.

Regards,
Germar

[Mauro (mauromol)]

Hi Germar,
I already had python3-pykde4 (the checkbox in BIT was never greyed out), probably it got installed somehow before I tried this with BIT.
The command you mentioned replies exactly like you said (with kwallet backend), except that the final hexadecimal number is different.

[Germar (germar)]

Looks like KDE in Mint execute the .desktop files without stdout and stderr file-descriptors which seems to disrupt backintime. Please run this command (all one line) and check out if this helps

sudo sed -e 's#^Exec=\(.*\)#Exec=\1 2>\&1 >/dev/null#' -i /etc/xdg/autostart/backintime.desktop

[Mauro (mauromol)]

I applied this but I can't reboot now. I'll let you know.

[Mauro (mauromol)]

Hi Germar, I confirm your fix about >/dev/null works for me! Thank you!

[Germar (germar)]

This fix broke pw-cache on Ubuntu. Next version should work for both ;)