search

kee-org / KeeFox

Legacy browser and XUL application integration with KeePass Password Safe. See https://github.com/kee-org/browser-addon for the new version for Firefox 57+
https://forum.kee.pm
418 stars 48 forks source link

"Generate new password" hangs system for 25s #391

Closed saladpanda closed 9 years ago

saladpanda commented 9 years ago

When I start Firefox and generate a new password for the first time it makes my whole system hang for ~25s until the popup "A new password has een copied to your clipboard." appears. All subsequent password-generations appear instantly.

It does not matter if KeePass is loaded before or after Firefox was started. The first attempt to generate a password always hangs.

Log-file:

#######################################
# First password-generate after start #
#######################################
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: Sending a JSON-RPC request
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: received message from web socket
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: starting decryption
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage A took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage B took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage C took: 1
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage D took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage E took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decrypt() called: 1428917615131
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):INFO:  Failed to decrypt using NSS. Falling back to much slower JS implementation.
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: starting decryption using JS
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption data length: 48
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 1a took: 2
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 1b took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 1c took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 2 took: 1
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 3 took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 4 took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 5 took: 1
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 6 took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 7 took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 8 took: 1
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 9 took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 10 took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 11 took: 1
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption stage 12 took: 0
Mon Apr 13 2015 11:33:35 GMT+0200 (CEST):DEBUG: decryption finished
###########################
# notice the 25s gap here #
###########################
Mon Apr 13 2015 11:34:00 GMT+0200 (CEST):DEBUG: metrics being sent

########################################
# Second password-generate after start #
########################################
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: Sending a JSON-RPC request
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: received message from web socket
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: starting decryption
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage A took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage B took: 1
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage C took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage D took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage E took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decrypt() called: 1428917758425
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):INFO:  Failed to decrypt using NSS. Falling back to much slower JS implementation.
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: starting decryption using JS
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption data length: 48
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 1a took: 1
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 1b took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 1c took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 2 took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 3 took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 4 took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 5 took: 1
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 6 took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 7 took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 8 took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 9 took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 10 took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 11 took: 1
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption stage 12 took: 0
Mon Apr 13 2015 11:35:58 GMT+0200 (CEST):DEBUG: decryption finished
###############
# no gap here #
###############
Mon Apr 13 2015 11:36:01 GMT+0200 (CEST):DEBUG: metrics being sent```
luckyrat commented 9 years ago

Can you reproduce the problem by generating a password from within KeePass?

For the whole system to hang it sounds like a serious .NET framework or Windows failure. Perhaps even hardware failure (dodgy hard drive?)

Maybe re-installing KeePass or the .NET framework will fix it up (but if it's a dodgy hard drive, you might find the problem reappears later in different applications anyway).

Maybe look at some of the Microsoft performance monitoring solutions to get a better idea of what part of the system is causing the hang?

saladpanda commented 9 years ago

Oh I forgot to mention: I'm running ArchLinux with the following Software:

$ uname -a
Linux arch 3.19.3-3-ARCH #1 SMP PREEMPT Wed Apr 8 14:10:00 CEST 2015 x86_64 GNU/Linux

$ mono --version
Mono JIT compiler version 3.12.1 (tarball Thu Mar 12 06:31:20 UTC 2015)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors. www.mono-project.com
        TLS:           __thread
        SIGSEGV:       altstack
        Notifications: epoll
        Architecture:  amd64
        Disabled:      none
        Misc:          softdebug 
        LLVM:          supported, not enabled.
        GC:            sgen

$ firefox --version

(process:10504): GLib-CRITICAL **: g_slice_set_config: assertion 'sys_page_size == 0' failed
Mozilla Firefox 37.0.1

When generating a password with KeePass directly, I can't reproduce the problem. Are there any other logs that I could provide?

(According to gsmartcontrol my SSD is working fine)

luckyrat commented 9 years ago

It's probably a Mono bug then. Maybe it's quite a new one since your version was only built last month which might explain why you're the first to mention this.

You could try running KeePass in debug mode by passing the "--debug" command line parameter and also generate a KeePassRPC plugin log file like "--KPRPCDebug=/tmp/kprpc-debug.log". That might help narrow down what part of the system is at fault.

saladpanda commented 9 years ago

I tried downgrading to multiple different verions of mono, KeePass and Firefox. Every version has the exact same issue. So I don't think it's a bug in the new mono version.

I used both debug-parameters an the logs didn't show any anomalies for the first generate. Every password-generate generates the same log entries (whether it hangs or not).

luckyrat commented 9 years ago

Do you know if you have any other Mono applications on your system? It would be interesting to know if any of them can elicit the problem.

I'm struggling to imagine what could be affecting this small part of KeePassRPC code but not the main KeePass password generator.

There are a few basic logic paths like any program and then the only relatively unusual thing is the use of a technique called reflection to allow us to generate a password for both recent and old versions of KeePass. There probably aren't any other examples of that within KeePass itself but it's a very common .NET feature (and one that I know has worked fine in Mono for a few years, albeit with quite a few bugs before that but nothing I'm aware of that could cause a system freeze).

The fact that it happens in lots of Mono versions and seemingly only on your system suggests a bug that relates to one of your other system libraries - either a system-wide problem or a fault with the way that Mono calls that library.

Did you ever use KeeFox without this problem? I'm wondering if it is still caused by a recent update but maybe a system library update instead of Mono.

Have you looked in your system logs? Things like /var/log/messages or the equivalent on your distro. That might give a clue but if not, maybe try increasing some system log levels for a while (I'm not sure how to do that I'm afraid).

Failing that, I'm not sure what sort of performance profiling tools are available on Linux or whether you'd be comfortable using them anyway but apart from that the only other thing I can suggest is investigating how to debug Mono itself - maybe by changing environment variables or installing a debug build from Xamarin.

saladpanda commented 9 years ago

I just did some testing with different WindowManagers and found that the problem does not occur when I use plain fluxbox or plain openbox. But then again when I start openbox with a KDE session (exec openbox-kde-session) the hang occurs.

So it's obviously not a problem with window managers but defenitely a problem with the rest of my KDE setup.

I'm using:

plasma-desktop 5.3.1-2
plasma-framework 5.10.0-1
frameworkintegration 5.10.0-1

Maybe a problem with how the "A new password has been copied to your clipboard." message is generated? Or what are other ways in which KeeFox/KeePassRPC could interact with KDE?

saladpanda commented 9 years ago

I just found, that Firefox logs the following to ~/.xsession-errors at the end of the "freeze":

(firefox:1246): libnotify-WARNING **: Failed to connect to proxy

So it really seems to be the notification that causes the freeze

luckyrat commented 9 years ago

This is where the notification is generated:

https://github.com/luckyrat/KeeFox/blob/7bae66e9c4034985649e5535bfd403c75d369d0c/Firefox%20addon/KeeFox/chrome/content/KFUI.js#L387

Maybe that will help work out whether the bug is in Firefox or KDE/Linux. I don't think KeeFox does anything unusual there but if there is a different way of doing it which doesn't trigger this bug and otherwise has the same effect, I'm happy to put in a workaround.

I'm not sure what libnotify is (a system library I guess?) but it might be worth looking for an updated version of that? Maybe KDE links to a different version of libnotify?

saladpanda commented 9 years ago

I have filed a bugreport at Mozillas Bugtracker: https://bugzilla.mozilla.org/show_bug.cgi?id=1170122

luckyrat commented 9 years ago

Doesn't look like this is a KeeFox bug but feel free to update this issue if any new info from Mozilla sheds light on the problem.