Bug 286854

Summary: Dolphin loses metadata when moving files
Product: nepomuk Reporter: Alvaro Aguilera <alvaro.aguilera>
Component: filewatchAssignee: Sebastian Trueg <sebastian>
Status: RESOLVED FIXED    
Severity: major CC: bladud, me, peter.penz19, trueg
Priority: NOR    
Version: 4.7   
Target Milestone: ---   
Platform: openSUSE RPMs   
OS: Linux   
Latest Commit: Version Fixed In: 4.10
Attachments: Excerpt from .xsession-erros

Description Alvaro Aguilera 2011-11-17 15:35:49 UTC
Version:           1.7 (using KDE 4.7.3) 
OS:                Linux

I'm giving my best to try to convince myself that the metadata framework in KDE4 is actually useful, but I'm having a hard time...

Reproducible: Didn't try

Steps to Reproduce:
1. Split view and browse two different directories
2. add metadata to a file (tag/comment/ranking) using the panel on the right
3. move the file using drag and drop into the other directory



Actual Results:  
metadata is no more

Expected Results:  
no data loss(?)

OS: Linux (x86_64) release 3.0.6-2-desktop
Compiler: gcc
Comment 1 Sebastian Trueg 2011-11-17 18:35:05 UTC
There is some possibilities:
1. The data was in fact not moved
2. There was a delay and the data was updated
3. The data was updated but the GUI did not get notified
So the question is: did you check the metadata with a restarted dolphin?
Comment 2 Alvaro Aguilera 2011-11-18 08:25:21 UTC
The files were moved locally without delay. Closing and starting Dolphin again, or restarting the computer had no effect.
Comment 3 Sebastian Trueg 2011-11-18 08:31:19 UTC
Can you reproduce this all the time?
I am asking because maybe a Nepomuk service went down without you noticing.
Comment 4 Alvaro Aguilera 2011-11-18 08:32:47 UTC
Yes. It happens all the time. Note that when I add metadata to a file, it stays there. The problem occurs only when I move or copy it.
Comment 5 Sebastian Trueg 2011-11-18 09:44:07 UTC
Just to be clear: file copy will never result in metadata to be copied. The reason is that there is no way to track all copy operations yet. Thus, we could only track the ones done by KIO - or maybe a few more through Zeitgeist - something that we should look into soon.
Anyway, for file moves metadata should in fact be updated. And for me it works perfectly. So now I need to continue to go fish:

please check if the correct service is running like so: "ps aux|grep nepomukfilewatch"

then if it is there check it via dbus to see if it is blocked: "qdbus org.kde.nepomukfilewatch-3016 /nepomukfilewatch"
Comment 6 Alvaro Aguilera 2011-11-18 09:50:05 UTC
$ps aux|grep nepomukfilewatch
myuser 2979 0.0 0.6 339868 25872 ? SNl 09:13 0:00 /usr/bin/nepomukservicestub nepomukfilewatch


$qdbus org.kde.nepomukfilewatch-3016 /nepomukfilewatch
Service 'org.kde.nepomukfilewatch' does not exist.
Comment 7 Sebastian Trueg 2011-11-18 09:59:40 UTC
(In reply to comment #6)
> $qdbus org.kde.nepomukfilewatch-3016 /nepomukfilewatch
> Service 'org.kde.nepomukfilewatch' does not exist.

Stupid me: "qdbus org.kde.nepomuk.services.nepomukfilewatch /nepomukfilewatch"
Comment 8 Alvaro Aguilera 2011-11-18 10:01:02 UTC
$qdbus org.kde.nepomuk.services.nepomukfilewatch /nepomukfilewatch
method void org.kde.nepomuk.FileWatch.watchFolder(QString path)
method QDBusVariant org.freedesktop.DBus.Properties.Get(QString interface_name, QString property_name)
method QVariantMap org.freedesktop.DBus.Properties.GetAll(QString interface_name)
method void org.freedesktop.DBus.Properties.Set(QString interface_name, QString property_name, QDBusVariant value)
method QString org.freedesktop.DBus.Introspectable.Introspect()
Comment 9 Alvaro Aguilera 2011-11-18 10:13:13 UTC
Btw. the metadata is also lost when I rename files.
Comment 10 Sebastian Trueg 2011-11-18 12:31:13 UTC
A rename is a move.

Are the files in question in your home folder?
Which file system type are the files on?
Comment 11 Alvaro Aguilera 2011-11-18 12:41:03 UTC
The files are inside my home directory and I moved them within the home directory.

$mount |grep home
/dev/sda3 on /home type ext4 (rw,relatime,user_xattr,acl,barrier=1,data=ordered)

Moreover, the Linux installation is brand new with no pre-existing file system,  .kde4 directory, imported configuration or other things that could mess up with KDE.
Comment 12 Alvaro Aguilera 2011-11-18 12:51:10 UTC
Created attachment 65814 [details]
Excerpt from .xsession-erros

This is written to the .xsession-erros file when I move a tagged  file using Dolphin. Note the «dolphin(15838)/kio (KDirWatch) KDirWatchPrivate::removeEntry: doesn't know "/home"»
Comment 13 Sebastian Trueg 2011-11-18 12:55:00 UTC
Well then, let's debug this a bit.
Could you please do the following:
1. enable nepomuk (filewatch service) debugging output in kdebugdialog
2. then please shut down the file watch service: "qdbus org.kde.NepomukServer /servicemanager org.kde.nepomuk.ServiceManager.stopService nepomukfilewatch"
3. Start it manually in a konsole: "nepomukservicestub nepomukfilewatch"
4. wait a while for the io to settle (inotify watches are being installed)
5. now move a file and watch the output
Comment 14 Sebastian Trueg 2011-11-18 13:00:18 UTC
(In reply to comment #12)
> This is written to the .xsession-erros file when I move a tagged  file using
> Dolphin. Note the «dolphin(15838)/kio (KDirWatch)
> KDirWatchPrivate::removeEntry: doesn't know "/home"»

Actually the interesting part is this: 
[/usr/bin/nepomukservicestub] "/usr/bin/nepomukservicestub(2784)" Soprano: "Invalid argument (1)": "setProperty: No two resources can have the same nie:url at the same time."

Are you overwriting another file?
If not, I have a suspicion...
Comment 15 Alvaro Aguilera 2011-11-18 13:05:42 UTC
No, I'm not overwriting anything. This is the output of the debugdialog:

nepomukfilewatch(16004)/nepomuk (filewatch service) Nepomuk::FileWatch::watchFolder: "/home/user"
nepomukfilewatch(16004)/nepomuk (filewatch service) KInotify::addWatch: "/home/book"
nepomukfilewatch(16004)/nepomuk (filewatch service) KInotify::Private::open:
nepomukfilewatch(16004)/nepomuk (filewatch service) KInotify::Private::open: Successfully opened connection to inotify: 15
nepomukfilewatch(16004)/nepomuk (filewatch service) Nepomuk::InvalidFileResourceCleaner::run: Searching for invalid local file entries
nepomukfilewatch(16004)/nepomuk (filewatch service) Nepomuk::InvalidFileResourceCleaner::run: REMOVING  "/home/user/Documents/Bücher/book.djvu"
nepomukfilewatch(16004)/nepomuk (filewatch service) Nepomuk::InvalidFileResourceCleaner::run: REMOVING  "/home/user/book.djvu"
nepomukfilewatch(16004)/nepomuk (filewatch service) Nepomuk::InvalidFileResourceCleaner::run: Done searching for invalid local file entries
nepomukfilewatch(16004)/nepomuk (filewatch service) Nepomuk::MetadataMover::updateMetadata: KUrl("file:///home/user/Documents/Bücher/book.djvu") -> KUrl("file:///home/user/Documents/book.djvu")
nepomukfilewatch(16004)/nepomuk (filewatch service) Nepomuk::MetadataMover::slotWorkUpdateQueue: All update requests handled. Stopping timer.
Comment 16 Sebastian Trueg 2011-11-18 13:12:06 UTC
Do you again get one of those "setProperty" errors in .xsession-errors?
Also: is there any change if you move a file in your home folder directly, ie. use paths without any umlauts?
Comment 17 Alvaro Aguilera 2011-11-18 13:18:41 UTC
The setProperty error doesn't appear anymore. I tried moving a tagged document from /home to /home/Documents back and fort an couple of times. No umlauts in the path or filename. It preserved the tags for 1 cycle, and then the metadata was gone.
Comment 18 Sebastian Trueg 2011-11-18 16:28:25 UTC
I tried to reproduce the problem again by moving a file back and forth between folders but the meta-data including tags was always updated properly.

Could you please provide the filewatch service output from a whole moving test which includes the successful metadata update and the failures.
Comment 19 Alvaro Aguilera 2011-11-18 16:48:45 UTC
I think we have at least two diffenrent bugs acting here. One dealing with umlauts/utf and the other with cyclic moves. Here is the output of filewatch when I move a document back and fort.

move tagged file form "documents" up one level to "home", metadata preserved. output:

nepomukfilewatch(19357)/nepomuk (filewatch service) Nepomuk::MetadataMover::updateMetadata: KUrl("file:///home/aguilera/Documents/darmstadt.pdf") -> KUrl("file:///home/aguilera/darmstadt.pdf")
nepomukfilewatch(19357)/nepomuk (filewatch service) Nepomuk::MetadataMover::slotWorkUpdateQueue: All update requests handled. Stopping timer.

move tagged file back into "documents", metadata still there:

nepomukfilewatch(19357)/nepomuk (filewatch service) Nepomuk::MetadataMover::updateMetadata: KUrl("file:///home/aguilera/darmstadt.pdf") -> KUrl("file:///home/aguilera/Documents/darmstadt.pdf")
nepomukfilewatch(19357)/nepomuk (filewatch service) Nepomuk::MetadataMover::slotWorkUpdateQueue: All update requests handled. Stopping timer.

move file one level up into "home" again, no metadata and the log is missing the call for updateMetadata():

nepomukfilewatch(19357)/nepomuk (filewatch service) Nepomuk::MetadataMover::slotWorkUpdateQueue: All update requests handled. Stopping timer.
nepomukfilewatch(19357)/nepomuk (filewatch service) Nepomuk::MetadataMover::slotClearRecentlyFinishedRequests: No more old requests. Stopping timer.

once again moving file into "documents", no metadata but at least the log has the call to updateMetadata():

nepomukfilewatch(19357)/nepomuk (filewatch service) Nepomuk::MetadataMover::updateMetadata: KUrl("file:///home/aguilera/darmstadt.pdf") -> KUrl("file:///home/aguilera/Documents/darmstadt.pdf")
nepomukfilewatch(19357)/nepomuk (filewatch service) Nepomuk::MetadataMover::slotWorkUpdateQueue: All update requests handled. Stopping timer.

That was the cyclic moving. Now, if I use umlauts in the path, things don't work at all.

If I move the tagged file into a directory called "fück", then the metadata is lost and filewatch produces no output.

When I move the file from "fück" again into "home", then the metadata is shown again, and the following output is produced by filewatch:

nepomukfilewatch(19357)/nepomuk (filewatch service) KInotify::slotEvent: No cookie for move information of "/home/aguilera/Documents/darmstadt.pdf"

There is no additional information provided by filewatch.
Comment 20 Sebastian Trueg 2011-11-18 19:20:09 UTC
Well, the unicode bug has already been fixed in 4.7.4: http://quickgit.kde.org/?p=kde-runtime.git&a=commit&h=2af5bddc81bbcac0a08528f658430795e575f4c0
I am amazed (in a bad way) that I never caught this bug before. :/

As for the other bug: this is really strange, especially since I cannot reproduce.
Comment 21 Alvaro Aguilera 2011-11-18 19:28:40 UTC
well, it happens to me all the time. I guess I'll wait until 4.7.4 and see whether it still happens or not... Thanks for the effort though.
Comment 22 Sebastian Trueg 2011-11-18 19:34:04 UTC
Thank you for the intense testing and the debug session. I am not finished here though. I really want to solve the issue for you. I simply need to do some soul-searching for more debugging ideas. :P
Comment 23 Alvaro Aguilera 2011-11-18 19:35:51 UTC
let me know if you need more debugging info.
Comment 24 Alvaro Aguilera 2011-12-13 12:40:10 UTC
just to confirm that this still happens with KDE 4.7.4.
Comment 25 Simeon Bird 2012-10-27 06:59:58 UTC
Ok. I can reproduce. You have to sling the file around real fast.

The filewatch service calls moveFileMetadata ( oldPath, newPath). This sticks the metadata move into a queue, like so:
    if ( !m_updateQueue.contains( req ) &&
         !m_recentlyFinishedRequests.contains( req ) )
        m_updateQueue.enqueue( req );

If you move oldPath to newPath twice in fairly quick succession, the first move will still be in the m_recentlyFinishedRequests, and the metadata move will not be queued. 

git blame tells me that trueg added this check with commit 840dbb6005ead in 2009. 
He explained why in this comment:

// we use several systems to watch for file operations.
// Thus, we can get the same request more than once. We then
// need a way to determine if we have already handled it.
// (otherwise we would remove the previously moved data.)
// The only way to do that is to keep a list of all requests
// that have been handled in the last N seconds.

I believe this is no longer true - we only use inotify to watch for file operations, and cannot get the same event twice, so probably we can simply remove this memory of recently run requests. 
Otherwise we can pass the move cookie to moveFileMetadata, and disambiguate that way. 

trueg, vishesh, any thoughts?
Comment 26 Simeon Bird 2012-11-10 16:00:02 UTC
Git commit 3d0705355bf274eee613d9dd78667fcc53ea5809 by Simeon Bird.
Committed on 08/11/2012 at 07:47.
Pushed by sbird into branch 'master'.

Remove m_recentlyFinishedRequests from the metadatamover.
The filewatch service calls moveFileMetadata ( oldPath, newPath).

This sticks the metadata move into a queue, like so:
if ( !m_updateQueue.contains( req ) &&
!m_recentlyFinishedRequests.contains( req ) )
m_updateQueue.enqueue( req );

If you move oldPath to newPath twice in fairly quick succession, the
first move will still be in the m_recentlyFinishedRequests, and the metadata move will
not be queued.

git blame tells me that trueg added this check with commit 840dbb6005ead
in 2009, to prevent events received twice from being acted on twice.
However, it means that if an event is repeated quickly, the repeat
will not be acted on, even if it should.
(eg, move A -> B -> A -> B in quick succession)

Nowadays we just use inotifty, which, so far as I know,
cannot deliver the same event twice. and so
we can just remove the list entirely.

In other words: bug 286854 is due to a rogue, no longer needed, workaround.
FIXED-IN: 4.10
REVIEW: 107260

M  +2    -35   services/filewatch/metadatamover.cpp
M  +0    -10   services/filewatch/metadatamover.h

http://commits.kde.org/nepomuk-core/3d0705355bf274eee613d9dd78667fcc53ea5809