database is locked error prevents Diodon from adding items to or clearing history

[Karl-Philipp Richter]

For an unknown reason `diodon` turns into a state where adding items to the list and cleaning the history constantly results in

    ** (diodon:22537): WARNING **: zeitgeist-clipboard-storage.vala:382: Failed to clear items: GDBus.Error:org.gnome.zeitgeist.EngineError.DatabaseError: engine.vala:392: SQL Error: 5, database is locked

logged to stdout only. Due to the fact that this state blocks the application completely the error and instructions on how to deal with the issue should be displayed in a dialog.

Invoking `sudo apt-get purge diodon` doesn't even fix that error. I'm curious about how it can be overcome, but that's not the only point of this issue.

ProblemType: Bug
DistroRelease: Ubuntu 14.10
Package: diodon 1.2.0-0ubuntu1
Uname: Linux 3.19.0-031900rc1-generic x86_64
ApportVersion: 2.14.7-0ubuntu8
Architecture: amd64
CurrentDesktop: Unity
Date: Thu Dec 25 03:27:29 2014
SourcePackage: diodon
UpgradeStatus: No upgrade log present (probably fresh install)
---
ApportVersion: 2.17.1-0ubuntu2
Architecture: amd64
CurrentDesktop: Unity
DistroRelease: Ubuntu 15.04
EcryptfsInUse: Yes
InstallationDate: Installed on 2015-04-02 (14 days ago)
InstallationMedia: Ubuntu 15.04 "Vivid Vervet" - Beta amd64 (20150326)
Package: diodon 1.2.0-0ubuntu1
PackageArchitecture: amd64
ProcEnviron:
 TERM=xterm
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=de_DE.UTF-8
 SHELL=/bin/bash
Tags: vivid
Uname: Linux 4.0.0-040000-generic x86_64
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups: adm bumblebee cdrom dip lpadmin plugdev sambashare sudo
_MarkForUpload: True
---
ApportVersion: 2.19.1-0ubuntu5
Architecture: amd64
CrashDB: diodon
DistroRelease: Ubuntu 15.10
InstallationDate: Installed on 2015-09-14 (80 days ago)
InstallationMedia: Ubuntu 15.04 "Vivid Vervet" - Release amd64 (20150422)
MarkForUpload: True
Package: diodon 1.4.0~494+131~ubuntu15.10.1 [origin: LP-PPA-diodon-team-daily]
PackageArchitecture: amd64
SystemImageInfo: Error: command ['system-image-cli', '-i'] failed with exit code 2:
Tags: third-party-packages wily
Uname: Linux 4.3.0-040300-generic x86_64
UpgradeStatus: Upgraded to wily on 2015-10-23 (41 days ago)
UserGroups: adm autopilot bumblebee cdrom dip libvirtd lpadmin plugdev sambashare sudo wireshark

[Oliver Sauder (sao)]

This is a zeitgeist issue which is trying to access a locked database. Logging out Unity and logging in usually fixes this issue.

Can you reproduce this issue though in anyway?

[Karl-Philipp Richter (krichter722)]

Is there a way to unlock the zeitgeist database without logging out and in (I won't do that for the next days, maybe weeks, I guess)? I can only guess whether the issue persists accross reboot, maybe it reappears systematically very soon right after logging in.

After reading your reply I feel like I have reported this issue before, but I don't see it in my list of launchpad bugs. Maybe it was an enhancement request for unlimited history for `glipper` in the GNOME bug tracker... anyway, as it turned out there was a big struggle with zeitgeist as well.

[Oliver Sauder (sao)]

As I cannot reproduce the problem I can only guess - most likely are there several zeitgeist-daemon or zeitgeist-fts running which are locking the database.

Can you check the following:
ps -ef | grep zeitgeist

copy the output and then kill all the processes. See whether it works - if it does the output of the command would be helpful.

[Karl-Philipp Richter (krichter722)]

I could finally reproduce the issue and `sudo pkill zeitgeist` _and_ restarting `diodon` did the job.

    $ ps -ef | grep zeitgeist
    richter 8099 6764 0 15:05 ? 00:00:00 /usr/bin/zeitgeist-daemon
    richter 8152 6764 0 15:05 ? 00:00:00 /usr/lib/x86_64-linux-gnu/zeitgeist-fts
    richter 8154 6764 0 15:05 ? 00:00:01 zeitgeist-datahub
    richter 13637 8206 0 21:07 pts/11 00:00:00 grep --color=auto zeitgeist
    root 28105 6764 0 15:57 ? 00:00:00 /usr/bin/zeitgeist-daemon
    root 28112 6764 0 15:57 ? 00:00:00 zeitgeist-datahub
    $ sudo pkill zeitgeist
    $ ps -ef | grep zeitgeist
    richter 13683 8206 0 21:09 pts/11 00:00:00 grep --color=auto zeitgeist

After restarting I can repeatedly clear `diodon` sucessfully and `diodon` logs nothing when started in a terminal.

This was the first time that the issue reappeared - it might take some time to reproduce it again. A humble guess is that the database is filling up.

[Oliver Sauder (sao)]

zeitgeist-daemon shouldn't run twice and especially not as root so maybe this is the problem.

I wonder though how this has happened that zeitgeist-daemon started as root.

Could it be that you at one point opened a desktop session as root or started a desktop application which potentially uses Zeitgeist with sudo?

[Karl-Philipp Richter (krichter722)]

I'll figure that out as soon as possible. If that's potentially a problem, maybe you can add a warning in form of a popup dialog explaining the problem. That would not only help me in further debugging this issue.

[Oliver Sauder (sao)]

That's not something Diodon has under control.

Anyway for now I just want to figure out a way what steps are needed to reproduce this issue. When we found a reliable way it is then easier to think about how to fix it.

[Karl-Philipp Richter (krichter722)]

> That's not something Diodon has under control.
IMO it's sufficient to detect that the external resource is in an illegal or malfunctional state and forward that information to the user. The check needs to be included anyway in order to avoid a non-responsive state of `diodon` regardless of the issue and its fix - after fixing the issue/requesting the fix in `zeitgeist` or the usage of `zeitgeist` within `diodon` it can still occur that it misbehaves at a later point for other reasons.

[Karl-Philipp Richter (krichter722)]

The blockage now no longer survives a reboot. `diodon`'s version is 1.2.0 and `zeitgeist`'s is 0.9.14-2.2ubuntu2.

[Oliver Sauder (sao)]

I have created another bug report for showing critical error messages to user https://bugs.launchpad.net/diodon/+bug/1424236 for better usability when an error happen.

Concerning your response above - are you saying that the error doesn't appear anymore or simply after a reboot error is not there but reoccurs again after a while?

Thanks for clarification.

[Karl-Philipp Richter (krichter722)]

> Concerning your response above - are you saying that the error doesn't appear anymore or simply after a reboot error is not there but reoccurs again after a while?
No, I meant while initially (at the time of reporting the bug) the blockage was permantent and could not be fixed at all, meanwhile any blockage of the described sort is resolved after a reboot, i.e. `diodon` works again after reboot if the issue occured before that, but the issue still occurs.

[Karl-Philipp Richter (krichter722)]

apport information

[Karl-Philipp Richter (krichter722)]

apport information

[Karl-Philipp Richter (krichter722)]

Meanwhile this issue persist even after reboot, either the original cause for the blockage being removed after a reboot was not deterministic, but random or a dependency changed and reintroduced a bug.

> Could it be that you at one point opened a desktop session as root or started a desktop application which potentially uses Zeitgeist with sudo?
I had my eye on it for some time now and I didn't figure out why a `zeitgeist` daemon is started by root. I wouldn't bother with it. If `diodon` relies on certain conditions (be that only one `zeitgeist` daemon process running by a specific user or the `zeitgeist` database being unlocked), then these conditions have to be checked before every action taken.

[Oliver Sauder (sao)]

This is a zeitgeist bug so we have to see whether we get more information from the zeitgeist service itself, could even be an corrupt database.

So when you have this error that the database is locked, keep Diodon running and run the following command:
zeitgeist-daemon --replace --log-file zg.log --log-level=debug

now copy something to the clipboard and see what the output is of zeigeist-daemon is and attach it here.

Thanks.

[Karl-Philipp Richter (krichter722)]

Sure. There's nothing in `zg.log` and

    $ zeitgeist-daemon --replace --log-file zg.log --log-level=debug
    [08:06:54.968164 DEBUG] utils.vala:67: DATA_PATH = /home/richter/.local/share/zeitgeist
    [08:06:54.968283 DEBUG] utils.vala:86: DATABASE_FILE_PATH = /home/richter/.local/share/zeitgeist/activity.sqlite
    [08:06:55.062362 DEBUG] sql-schema.vala:204: schema_version is 10
    [08:06:55.134323 DEBUG] extension.vala:146: Loaded extension: ZeitgeistDataSourceRegistryExtension
    [08:06:55.134508 DEBUG] extension.vala:146: Loaded extension: ZeitgeistBlacklist
    [08:06:55.134607 DEBUG] extension.vala:146: Loaded extension: ZeitgeistHistogram
    [08:06:55.134998 DEBUG] extension.vala:146: Loaded extension: ZeitgeistStorageMonitor
    [08:06:55.135231 DEBUG] notify.vala:290: Installed new monitor for org.gnome.zeitgeist.SimpleIndexer
    [08:06:55.135615 DEBUG] extension.vala:146: Loaded extension: ZeitgeistSearchEngine
    [08:06:55.135710 DEBUG] extension.vala:146: Loaded extension: ZeitgeistBenchmarker
    [08:06:55.135767 DEBUG] utils.vala:127: LOCAL_EXTENSIONS_PATH = /home/richter/.local/share/zeitgeist/extensions
    [08:06:55.142015 DEBUG] ext-storage-monitor.vala:469: Creating NetworkManager network monitor
    [08:06:55.238184 DEBUG] ext-storage-monitor.vala:488: NetworkManager network state: 70
    [08:06:55.238266 DEBUG] ext-storage-monitor.vala:370: VOLUME ADDED: net
    [08:06:55.461395 DEBUG] notify.vala:290: Installed new monitor for :1.221

    ** (zeitgeist-datahub:17838): WARNING **: zeitgeist-datahub.vala:229: Unable to get name "org.gnome.zeitgeist.datahub" on the bus!
    [08:06:56.888484 DEBUG] notify.vala:300: Removing monitor org.gnome.zeitgeist.SimpleIndexer/org/gnome/zeitgeist/monitor/special
    [08:06:56.888595 DEBUG] ext-fts.vala:175: Zeitgeist.SearchEngine.unload, this.ref_count = 3

is printed to stdout.

[Oliver Sauder (sao)]

so after you have run this command - close Diodon and start it again. Is error message with database locked still occurring or does it run now?

[Karl-Philipp Richter (krichter722)]

Always takes some time until the issue occurs...

Quitting and restarting `diodon` after running `zeitgeist-daemon --replace --log-file zg.log --log-level=debug` works :) Still a lot of work even for a workaround.

[Tasos Sahanidis (tatokis)]

I came across this bug while trying to build Diodon from source.
If I understood correctly, running sudo ./waf install, installs Diodon to the specified prefix and also executes a build test.

From the waf install log:
[131/131] utest: _build_/tests/diodon-test

This spawns a new instance of zeitgeist as root (probably due to it being ran with sudo), which then causes the Zeitgeist database to lock.
In order to recover from that state, the root instances of zeitgeist-datahub and zeitgeist-daemon need to be killed and zeitgeist-daemon --replace to be ran as the normal user.

In order for it to be avoided, --skiptests needs to be appended to waf, so that it doesn't attempt to run the test as root (eg. sudo ./waf install --skiptests).
A good solution, as mentioned previously in this report, is to prevent Diodon (and the test) from running as root, or at least disallow attempts to access Zeitgeist as root.

[Oliver Sauder (sao)]

Thanks Tasos for this additional feedback.

It is certainly not a good thing that zeitgeist-daemon needs to be started during build which of course can cause issues as in your case. Something I have noticed in the past as well. I now split integration tests where Zeitgeist is needed and unit tests so this error during build is not happening again see Bug #1471438

What the original cause of this issue is, is still unclear to me. I also had zeitgeist-daemon running as root and my user without any problems.

It is not good that zeitgeist-daemon is started as root in any case - but this is not necessary a cause of Diodon as every other application depending on Zeitgeist can issue starting of this daemon.

All in all is this a Zeitgeist issue. I haven't reported this yet though as unfortunately I have not been able to create an example where it can be reproduced which would be needed for the Zeitgeist team to fix it.

[Karl-Philipp Richter (krichter722)]

apport information

[Karl-Philipp Richter (krichter722)]

apport information

[Karl-Philipp Richter (krichter722)]

apport information

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Oliver Sauder (sao)]

This is a fairly old bug and also seemed to be in relation with Unity.

I am marking this as invalid but if someone can still reproduce this issue on a newer system please comment.