backintime icon indicating copy to clipboard operation
backintime copied to clipboard

Unhandled exception: NoneType

Open jim-moe opened this issue 7 years ago • 10 comments

opensuse 42.2 linux 4.4.87-18.29-default x86_64 backintime 1.1.20

I occasionally receive the error message below during a backup. Probably not a Good Thing.

Unhandled exception in thread started by <function __log_keyring_warning at 0x7fd39670a400> Traceback (most recent call last): File "/usr/share/backintime/common/tools.py", line 1463, in __log_keyring_warning TypeError: 'NoneType' object is not callable

jim-moe avatar Oct 09 '17 18:10 jim-moe

Can you reproduce this error while running bit with --debug option and post the complete output?

buhtz avatar Oct 12 '17 16:10 buhtz

The fault happens very rarely. How much output does --debug produce?

jim-moe avatar Oct 12 '17 18:10 jim-moe

Not very much. The output appears on the console. So you have to start bit on shell.

@Germar Would the --debug output appear in any logfile if that option would be added to the bit-call in the crontab?

Did you copy and paste the error message? I can not find __log_keyring_warning anywhere in the code.

buhtz avatar Oct 14 '17 06:10 buhtz

Sure. Debugging messages from --debug will appear in the default log.

__log_keyring_warning is in line 1457 in version 1.1.20. But the line 1463 which is reported in the Traceback is not part of that function. Did you modify tools.py by your self? Can you please check with a vanilla BiT install?

Germar avatar Oct 14 '17 23:10 Germar

No, I have made no changes whatsoever to the source. BiT was installed from the opensuse repository, v1.1.20-3.3.1. I presume you submit the application for inclusion.

-rw-r--r-- 1 root root 50750 Apr 21 00:25 tools.py -rw-r--r-- 1 root root 11202 Sep 9 2012 tools.pyc

jim-moe avatar Oct 16 '17 19:10 jim-moe

The error finally recurred. There was nothing in the BiT log file itself that contained "keyring."

The command line: /usr/bin/nice -n19 /usr/bin/ionice -c2 -n7 /usr/bin/backintime --debug --profile-id 2 backup-job >/dev/null

The additional output: Unhandled exception in thread started by <function __log_keyring_warning at 0x7fd698dbf400> Traceback (most recent call last): File "/usr/share/backintime/common/tools.py", line 1463, in __log_keyring_warning File "", line 2237, in _find_and_load File "", line 2222, in _find_and_load_unlocked File "", line 2150, in _find_spec TypeError: 'NoneType' object is not callable

jim-moe avatar Oct 27 '17 18:10 jim-moe

Hello: Yes, I did mention that I had found #820 when I posted #1169 in 07/2021. #1169 being closed for being a duplicate of #820, makes total sense.

But I see that #820 has also been closed but there's no mention of a fix for it. I cannot find a reference to it in the link to Codeberg-AsGithubAlternative-buhtz.

Please advise.

Thanks in advance. Best,

PCL

pclinuxer avatar Aug 30 '22 11:08 pclinuxer

I am confused also. ;)

We are here at Issue 820 which is open. But you say that #820 was closed?

buhtz avatar Aug 30 '22 11:08 buhtz

Hello:

Hmm ... Yes, I did. My mistake.

Too early, not enough coffee. 8^° I saw the Closed with the purple background and ...

Sorry. Thanks for the heads up.

Best,

PCL

pclinuxer avatar Aug 30 '22 11:08 pclinuxer

Related Debian report https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=990343

buhtz avatar Sep 20 '22 20:09 buhtz

@jim-moe There is a new forming maintaining team and we do review all issues. Is this problem still relevant for you or did you find a solution?

buhtz avatar Sep 25 '22 07:09 buhtz

Hello: @buhtzz FWIW, I am still getting the warning from Cron in my mbox. Like I mentioned, it happens every so often but have not been able to figure out under what conditions so cannot reproduce it.

Unhandled exception in thread started by <function __log_keyring_warning at 0x7ff1f8266268>
Traceback (most recent call last):
  File "/usr/share/backintime/common/tools.py", line 1458, in __log_keyring_warning
TypeError: 'NoneType' object is not callable

The news is that I am now getting this warning, which I did not get before:

WARNING: import keyring failed
WARNING: import keyring failed
WARNING: import keyring failed

In any case, BiT seems to be doing its job and I don't know if it is a keyring issue or not. Wanted to let you know in case it is relevant.

Best,

JHM

pclinuxer avatar Sep 25 '22 10:09 pclinuxer

Maybe it helps when you install one of the python-keyring packages?

buhtz avatar Sep 25 '22 10:09 buhtz

Hello: Thanks for the fast reply.

Here is what I have installed on my Devuan installation:

user@devuan:~$ apt list | grep installed | grep keyring
--- snip ---
debian-archive-keyring/oldstable,oldstable,now 2019.1+deb10u1 all [installed]
devuan-keyring/oldstable,oldstable,now 2022.09.04 all [installed]
gir1.2-gnomekeyring-1.0/now 3.12.0-1+b2 amd64 [installed,local]
gnome-keyring-pkcs11/oldstable,now 3.28.2-5 amd64 [installed,automatic]
gnome-keyring/oldstable,now 3.28.2-5 amd64 [installed,automatic]
libgnome-keyring-common/now 3.12.0-1 all [installed,local]
libgnome-keyring0/now 3.12.0-1+b2 amd64 [installed,local]
libpam-gnome-keyring/oldstable,now 3.28.2-5 amd64 [installed,automatic]  

python-keyring/oldstable,oldstable,now 17.1.1-1 all [installed,automatic]
python-keyrings.alt/oldstable,oldstable,now 3.1.1-1 all [installed,automatic]
python3-keyring/oldstable,oldstable,now 17.1.1-1 all [installed,automatic]
python3-keyrings.alt/oldstable,oldstable,now 3.1.1-1 all [installed,automatic]

user@devuan:~$ 

At least, it is what I have available in the Devuan repository, the installation being up to date:

user@devuan:~$ apt list | grep python | grep keyring
--- snip ---
python-keyring/oldstable,oldstable,now 17.1.1-1 all [installed,automatic]
python-keyrings.alt/oldstable,oldstable,now 3.1.1-1 all [installed,automatic]
python3-keyring/oldstable,oldstable,now 17.1.1-1 all [installed,automatic]
python3-keyrings.alt/oldstable,oldstable,now 3.1.1-1 all [installed,automatic]
user@devuan:~$ 

After having some espresso, I recalled that I originally attempted to find an answer on the Devuan forum last year and what I got answers led me to post the bug report here.

If you do a search with the text WARNING: import keyring failed you get (ggl) 61 results. It seems that BiT is involved in quite a few, some as far back as 2015.

Thanks for your input.

Best,

JHM

pclinuxer avatar Sep 25 '22 11:09 pclinuxer

Hello:

Here is what I have installed on my Devuan installation ...

I have checked and have not been able to find a good reason for having gnome-keyring in my Devuan installation.

[root@devuan ~]# aptitude why gnome-keyring
i   pcmanfm       Recommends gvfs-backends
i A gvfs-backends Recommends gnome-keyring
[root@devuan ~]# 

Or for gvfs-backends for that matter.

They are not dependencies, they are pcmanfm recommends. And we all know that recommends can sometimes be silently problematic.

Just shooting in the dark, but ... I wonder if the problem isn't being caused by having too many ***-keyring instances?

One way to find out: Today at noon (03:00 GMT) my rig was purged of gnome-keyring and gvfs-backends. Now let's wait and see if I get any more mail in my mbox regarding BiT or whatever keyring.

I'll post back if I get another message or in a fortnight, whatever comes first.

Best,

JHM

pclinuxer avatar Sep 25 '22 17:09 pclinuxer

@jim-moe There is a new forming maintaining team and we do review all issues. Is this problem still relevant for you or did you find a solution? I am so glad to hear that BiT is being maintained again!

I have not seen this error, NoneType, in a very long time (years).

jim-moe avatar Sep 25 '22 17:09 jim-moe

Hello:

I'll post back if I get another message or in a fortnight, whatever comes first.

BiT apparently is working properly and cron has not sent me any mails. But to check, I ran it manually and this is what I got:

user@devuan:~$ backintime backup
Gkr-Message: 08:42:53.971: secret service operation failed: The name org.freedesktop.secrets was not provided by any .service files

Back In Time
Version: 1.1.24

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
WARNING: Inhibit Suspend failed.
WARNING: import keyring failed
INFO: Take a new snapshot. Profile: 1 Main profile
INFO: [qt4systrayicon] begin loop
INFO: Call rsync to take the snapshot
INFO: Save config file
INFO: Create info file
INFO: Remove backups older than: 20220117-000000
INFO: Keep min free disk space: 40960 MiB
INFO: Keep min 5% free inodes
INFO: Unlock
user@devuan:~$ INFO: [qt4systrayicon] end loop

It would seem that BiT does not need gnome-keyring to work properly, but from the manual backup terminal's output we can see that the import keyring failed warning is still there. ie: whether gnome-keyring is installed or not, so it does not seem to be the what causes the BiT problem.

Any ideas?

Edit: Reinstalling gnome-keyring got rid of the import keyring failed warning and the manual backup went on as expected. ie: import keyring did not fail.

But a cron job to run BiT was logging the error message related to keyring described previously.

--> Q: What links BiT and gnome-keyring and why does a cron job running BiT want to import it?

I searched yet some more and found a lead of sorts here:

The OP had purged gnome-keyring and was getting errors in his logs.

... realized that the problem was not limited just to Docker, any services using libsecret were broken. As I use KeePassXC with libsecret integration I took a look in the settings and it turns out the integration was disabled. I purged the gnome-keyring package again, killed the gnome-keyring service and enabled the KeePassXC integration and it all worked as usual.

Thought I'd post all this as it may have some bearing ie: the libsecret integration.

Thanks in advance.

Best,

PCL

pclinuxer avatar Sep 26 '22 12:09 pclinuxer

Maybe related to #1321 (fixing there)...

--> Q: What links BiT and gnome-keyring and why does a cron job running BiT want to import it?

You can save your password for your private SSH key and EncFS password (local encryption) in a supported keyring in the BiT GUI:

Settings GUI > General > Mode: SSH > checkbox "Save Password to Keyring"

If the job is scheduled in the settings it is added to cron and it may request this password via the keyring python package that tries to access your installed "password safe".

Note: It is important to configure a supported keyring backend in a config file if ChainedBackend (keyring.backends.chainer.ChainerBackend) is shown in the debug output of BiT. See the linked issue for an example and where to find the config file...

aryoda avatar Oct 07 '22 15:10 aryoda

Hello:

I have not had this issue again since my Sept 25th. post and the usual was once every week or so. Totally random.

FWIW, I had purged and the reinstalled gnome-keyring before posting. Maybe there's a clue there?

Like I mentioned before, BiT was doing its job properly (as far as I can tell) in spite of the error. And I have my settings as > General > Mode: Local as my BiT backups go to a local drive. (yes, I know ... ) It is a repeated schedule which runs once a day because the box run regularly but not always, which then makes it sort of irregular. 8^°

Thanks for your input.

Best,

PCL

pclinuxer avatar Oct 07 '22 17:10 pclinuxer

To everyone involved: Would you say this Issue can be closed?

emtiu avatar Oct 07 '22 20:10 emtiu

Hello:

To everyone involved: Would you say this Issue can be closed? I may be the last one who actually saw this problem in the past couple of years. Problem without apparent consequences but still a problem. ie: when there's an error and it gets logged, it is a problem.

I would suggest leaving it open till the end of this month so I see if it crops up again. If it does not, I think we can call it 'case closed'.

Unless it crops up again. 8^°

I sort of don't like 1. not knowing exactly what caused it, 2. think that it got solved the MS way. ie: by reinstalling something.

Thanks, PCL

pclinuxer avatar Oct 07 '22 22:10 pclinuxer

Agreed, we'll give this Issue a 4-week timeout.

emtiu avatar Oct 07 '22 23:10 emtiu

Hello:

Right, thank you. I've made a note to be back 04/10. That or report before that date if anything crops up.

Best,

PCL

pclinuxer avatar Oct 08 '22 10:10 pclinuxer

Hello:

... or report before that date if anything crops up. I'm sorry to have to report that I have had another notification in my mbox:

From groucho@devuan Wed Oct 12 23:00:01 2022
Received: from groucho (uid 1000)
	(envelope-from groucho@devuan)
	id df3b4
	by devuan (DragonFly Mail Agent v0.11);
	Wed, 12 Oct 2022 23:00:01 -0300
From: root (Cron Daemon)
To: groucho
Subject: Cron <groucho@devuan> /usr/bin/nice -n 19 /usr/bin/ionice -c2 -n7 /usr/bin/backintime backup-job >/dev/null
MIME-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 8bit
X-Cron-Env: <SHELL=/bin/sh>
X-Cron-Env: <PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin>
X-Cron-Env: <HOME=/home/groucho>
X-Cron-Env: <LOGNAME=groucho>
Date: Wed, 12 Oct 2022 23:00:01 -0300
Message-Id: <63477121.df3b4.3077b0cf@devuan>

Unhandled exception in thread started by <function __log_keyring_warning at 0x7f137fbe2488>
Traceback (most recent call last):
File "/usr/share/backintime/common/tools.py", line 1458, in __log_keyring_warning
TypeError: 'NoneType' object is not callable

As you can see, the error is the same. /usr/share/backintime/common/tools.py -> Line 1458

These are the last 10 lines of that particular script:

--- snip ---
1457 def __log_keyring_warning():
1458     from time import sleep
1459     sleep(0.1)
1460     logger.warning('import keyring failed')
1461 
1462 if keyring is None and keyring_warn:
1463     #delay warning to give logger some time to import
1464     import _thread
1465     _thread.start_new_thread(__log_keyring_warning, ())
1466     # logger.warning('import keyring failed')
1467 

So I'd say this issue should remain open.

My box run Linux Devuan Beowulf with a backported kernel:

groucho@devuan:~$ uname -a
Linux devuan 5.10.0-0.deb10.16-amd64 #1 SMP Debian 5.10.127-2~bpo10+1 (2022-07-28) x86_64 GNU/Linux
groucho@devuan:~$ 

BiT 1.1.24.0

groucho@devuan:~$ apt list | grep installed | grep backin
--- snip ---
backintime-common/oldstable,oldstable,now 1.1.24-0.1 all [installed]
backintime-qt4/oldstable,oldstable,now 1.1.24-0.1 all [installed]
groucho@devuan:~$ 

Best,

PCL

pclinuxer avatar Oct 13 '22 03:10 pclinuxer

File "/usr/share/backintime/common/tools.py", line 1458, in __log_keyring_warning TypeError: 'NoneType' object is not callable

1457 def __log_keyring_warning():
1458     from time import sleep
1459     sleep(0.1)
1460     logger.warning('import keyring failed')
1461 
1462 if keyring is None and keyring_warn:
1463     #delay warning to give logger some time to import
1464     import _thread
1465     _thread.start_new_thread(__log_keyring_warning, ())
1466     # logger.warning('import keyring failed')
1467 

May be a multi-threading issue

Could you move the line 1458 after 1464 so that the sleep function is imported before the thread starts?...

Then wait and see ;-)

Edit: If it fails you could try a variant: import time + time.sleep(0.1) in the original code lines and if this does not work as another variation move the import again to after 1464

aryoda avatar Oct 13 '22 08:10 aryoda

Hello:

Thanks for the prompt reply. 8^)

May be a multi-threading issue I see ...

Could you move the line 1458 after 1464 so that the sleep function is imported before the thread starts?... Right, I'll do that and see if the issue crops up again. Like I mentioned, it is totally random and sometimes does no happen for the longest while.

Then wait and see ;-) Edit: If it fails you could try ...

Better if I report back when/if I get another notification and get further instructions. I don't want to muck-up my BiT config. 8^° We'll have to give it a min of 15 days and a max of 30. If in four weeks there is no notification, we could consider that it may have worked.

Just to check, is this it?:

1457 def __log_keyring_warning():
1459     sleep(0.1)
1460     logger.warning('import keyring failed')
1461 
1462 if keyring is None and keyring_warn:
1463     #delay warning to give logger some time to import
1464     import _thread
1458     from time import sleep
1465     _thread.start_new_thread(__log_keyring_warning, ())
1466     # logger.warning('import keyring failed')
1467 

Obviously no renumbering needed as these are generated by jed.

Thanks for your input.

Best,

PCL

pclinuxer avatar Oct 13 '22 12:10 pclinuxer

Just to check, is this it?:

1457 def __log_keyring_warning():
1459     sleep(0.1)
1460     logger.warning('import keyring failed')
1461 
1462 if keyring is None and keyring_warn:
1463     #delay warning to give logger some time to import
1464     import _thread
1458     from time import sleep
1465     _thread.start_new_thread(__log_keyring_warning, ())
1466     # logger.warning('import keyring failed')
1467 

Exactly like I described it! I have just checked it (using Git master branch - but your code looks older, it imports _thread instead of threading, but this shouldn't matter here).

Good luck (we should propose a new Github badge: Heisenberg bug hunter ;-)

To be sure not to break your backups you could also start the BiT GUI since it always executes this code path and should trigger the warning in the console (if you already got it before - otherwise you wouldn't have seen the NoneType error):

WARNING: [common/tools.py:2377 __logKeyringWarning] import keyring failed

aryoda avatar Oct 13 '22 12:10 aryoda

Hello:

Exactly like I described it!

Good.

... checked it (using Git master branch - but your code looks older ...

No idea how that could be. The BiT I have installed proceeds from the Devuan repository which in turn proceeds from the Debian repository.

Back In Time 1.1.24-0.1

If any application from the Debian repository has some systemd nastiness and can work without it, it is then sanitised by the Devuan maintainers and then included in the Devuan repository.

I expect that the version I have installed should be the same one presently available in the Debian Buster (10.4) repository.

Good luck (we should propose a new Github badge: Heisenberg bug hunter ;-)

Heisenbug ... Don't think it is that sort of bug.

To be sure not to break your backups ...

The curious thing is that BiT is (apparently) working properly.

... you could also start the BiT GUI ...

I think it may be best to let it run in the same conditions the error cropped up in. It gets me not to be able to find out what is going on.

And I am not fond of the so called harmless notices. 8^/ It is just crud piling up in some dark corner of the code just wating to reach critical mass and screw up everything.

I'll edit the *.py file now, reboot and report back when/if I get another notification. Lets give it a min of 15 days and a max of 30. If in four weeks there is no notification, I'll report back.

Thanks for your input.

Best,

PCL

pclinuxer avatar Oct 13 '22 13:10 pclinuxer

@pclinuxer

You are using an old but commonly installed BiT version that is probably based on the Debian package (that is OK so far, even Ubuntu 20.04 is using this version).

I think this a new kind of bug (race-alike condition between package loading and usage; it already happened earlier which I could see in git blame (last change of this code tried to fix a similar problem #473 which introduced this problematic sleep(0.5) call).

@emtiu I would like to keep this bug open, since there is no other way of reproducing it but together with the OP. I will try to fix this (not high prio since the bug happens only from time to time). If you assign the issue to me it could help me filtering my issues easier... THX!

Note to self: Add a hint to the warning how to fix this (eg. link to github README)...

aryoda avatar Oct 13 '22 14:10 aryoda

Hello:

@pclinuxer ... using an old but commonly installed BiT version that is probably based on the Debian package ... It should be based on a Debian package, in this/my case a package from the Debian Buster repository.

This what is listed there:

[backintime-common] (https://packages.debian.org/buster/backintime-common) (1.1.24-0.1)
[backintime-gnome] (https://packages.debian.org/buster/backintime-gnome) (1.1.24-0.1)
[backintime-kde] (https://packages.debian.org/buster/backintime-kde) (1.1.24-0.1)
[backintime-qt4] (https://packages.debian.org/buster/backintime-qt4) (1.1.24-0.1)

There is a newer version in the Debian Bullseye repository (1.2.1-3) and this is reflected in the Devuan Chimaera repository.

I think this a new kind of bug ... Not Heisenbug? 8^D

Right. I have made the edition and rebooted the box. Hopefully I'll be back with no news when 30 days have gone by.

Thanks for taking care of this.

Best,

PCL

pclinuxer avatar Oct 13 '22 14:10 pclinuxer