286854 2011-11-17 15:35:49 +0000 Dolphin loses metadata when moving files 2012-11-10 16:00:02 +0000 1 1 10 Unmaintained nepomuk filewatch 4.7 openSUSE Linux RESOLVED FIXED NOR major --- 1 alvaro.aguilera sebastian bladud me peter.penz19 trueg http://commits.kde.org/nepomuk-core/3d0705355bf274eee613d9dd78667fcc53ea5809 4.10 1 oldest_to_newest 1186412 0 alvaro.aguilera 2011-11-17 15:35:49 +0000 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 1186454 1 trueg 2011-11-17 18:35:05 +0000 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? 1186689 2 alvaro.aguilera 2011-11-18 08:25:21 +0000 The files were moved locally without delay. Closing and starting Dolphin again, or restarting the computer had no effect. 1186694 3 trueg 2011-11-18 08:31:19 +0000 Can you reproduce this all the time? I am asking because maybe a Nepomuk service went down without you noticing. 1186695 4 alvaro.aguilera 2011-11-18 08:32:47 +0000 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. 1186720 5 trueg 2011-11-18 09:44:07 +0000 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" 1186722 6 alvaro.aguilera 2011-11-18 09:50:05 +0000 $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. 1186727 7 trueg 2011-11-18 09:59:40 +0000 (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" 1186728 8 alvaro.aguilera 2011-11-18 10:01:02 +0000 $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() 1186735 9 alvaro.aguilera 2011-11-18 10:13:13 +0000 Btw. the metadata is also lost when I rename files. 1186772 10 trueg 2011-11-18 12:31:13 +0000 A rename is a move. Are the files in question in your home folder? Which file system type are the files on? 1186778 11 alvaro.aguilera 2011-11-18 12:41:03 +0000 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. 1186784 12 65814 alvaro.aguilera 2011-11-18 12:51:10 +0000 Created attachment 65814 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"» 1186785 13 trueg 2011-11-18 12:55:00 +0000 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 1186787 14 trueg 2011-11-18 13:00:18 +0000 (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... 1186792 15 alvaro.aguilera 2011-11-18 13:05:42 +0000 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. 1186794 16 trueg 2011-11-18 13:12:06 +0000 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? 1186795 17 alvaro.aguilera 2011-11-18 13:18:41 +0000 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. 1186850 18 trueg 2011-11-18 16:28:25 +0000 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. 1186857 19 alvaro.aguilera 2011-11-18 16:48:45 +0000 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. 1186911 20 trueg 2011-11-18 19:20:09 +0000 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. 1186914 21 alvaro.aguilera 2011-11-18 19:28:40 +0000 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. 1186916 22 trueg 2011-11-18 19:34:04 +0000 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 1186917 23 alvaro.aguilera 2011-11-18 19:35:51 +0000 let me know if you need more debugging info. 1198883 24 alvaro.aguilera 2011-12-13 12:40:10 +0000 just to confirm that this still happens with KDE 4.7.4. 1309808 25 bladud 2012-10-27 06:59:58 +0000 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? 1314265 26 bladud 2012-11-10 16:00:02 +0000 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 65814 2011-11-18 12:51:10 +0000 2011-11-18 12:51:10 +0000 Excerpt from .xsession-erros nepomuk-error.txt text/plain 2226 alvaro.aguilera dm9pZCBTb3ByYW5vOjpTZXJ2ZXI6OlNlcnZlckNvcmU6OnNlcnZlckNvbm5lY3Rpb25GaW5pc2hl ZCgpIENvbm5lY3Rpb24gcmVtb3ZlZC4gQ3VycmVudCBjb3VudDogMTAKZG9scGhpbigxNTgzOCkv a2RldWkgKEtJY29uTG9hZGVyKSBLSWNvbkxvYWRlclByaXZhdGU6Om5vcm1hbGl6ZUljb25NZXRh ZGF0YTogSWxsZWdhbCBpY29uIHN0YXRlOiAgMzIgClsvdXNyL2Jpbi9uZXBvbXVrc2VydmljZXN0 dWJdIHZpcnR1YWwgdm9pZCBTb3ByYW5vOjpTZXJ2ZXI6OkxvY2FsU2VydmVyOjppbmNvbWluZ0Nv bm5lY3Rpb24ocXVpbnRwdHIpClsvdXNyL2Jpbi9uZXBvbXVrc2VydmljZXN0dWJdIHZvaWQgU29w cmFubzo6U2VydmVyOjpTZXJ2ZXJDb3JlUHJpdmF0ZTo6YWRkQ29ubmVjdGlvbihTb3ByYW5vOjpT ZXJ2ZXI6OlNlcnZlckNvbm5lY3Rpb24qKSBOZXcgY29ubmVjdGlvbi4gTmV3IGNvdW50OiAxMQpb L3Vzci9iaW4vbmVwb211a3NlcnZpY2VzdHViXSBTb3ByYW5vOjpPREJDOjpDb25uZWN0aW9uOjpD b25uZWN0aW9uKCkgU29wcmFubzo6U2VydmVyOjpTZXJ2ZXJDb25uZWN0aW9uKDB4N2Y5YzVjMDM4 M2EwKQpbL3Vzci9iaW4vbmVwb211a3NlcnZpY2VzdHViXSB2aXJ0dWFsIHZvaWQgU29wcmFubzo6 U2VydmVyOjpTZXJ2ZXJDb25uZWN0aW9uOjpydW4oKSB0aHJlYWQgZG9uZS4KWy91c3IvYmluL25l cG9tdWtzZXJ2aWNlc3R1Yl0gdmlydHVhbCBTb3ByYW5vOjpPREJDOjpDb25uZWN0aW9uOjp+Q29u bmVjdGlvbigpIFNvcHJhbm86OlNlcnZlcjo6U2VydmVyQ29ubmVjdGlvbigweDdmOWM1YzAzODNh MCkKWy91c3IvYmluL25lcG9tdWtzZXJ2aWNlc3R1Yl0gdm9pZCBTb3ByYW5vOjpTZXJ2ZXI6OlNl cnZlckNvcmU6OnNlcnZlckNvbm5lY3Rpb25GaW5pc2hlZCgpIAp2aXJ0dWFsIFNvcHJhbm86OlNl cnZlcjo6U2VydmVyQ29ubmVjdGlvbjo6flNlcnZlckNvbm5lY3Rpb24oKSBSZW1vdmluZyBjb25u ZWN0aW9uIAp2b2lkIFNvcHJhbm86OlNlcnZlcjo6U2VydmVyQ29yZTo6c2VydmVyQ29ubmVjdGlv bkZpbmlzaGVkKCkgQ29ubmVjdGlvbiByZW1vdmVkLiBDdXJyZW50IGNvdW50OiAxMApkb2xwaGlu KDE1ODM4KS9raW8gKEtEaXJXYXRjaCkgS0RpcldhdGNoUHJpdmF0ZTo6cmVtb3ZlRW50cnk6IGRv ZXNuJ3Qga25vdyAiL2hvbWUiIApbL3Vzci9iaW4vbmVwb211a3NlcnZpY2VzdHViXSAiL3Vzci9i aW4vbmVwb211a3NlcnZpY2VzdHViKDI3ODQpIiBTb3ByYW5vOiAiSW52YWxpZCBhcmd1bWVudCAo MSkiOiAic2V0UHJvcGVydHk6IE5vIHR3byByZXNvdXJjZXMgY2FuIGhhdmUgdGhlIHNhbWUgbmll OnVybCBhdCB0aGUgc2FtZSB0aW1lLiIKWy91c3IvYmluL25lcG9tdWtzZXJ2aWNlc3R1Yl0gdmly dHVhbCB2b2lkIFNvcHJhbm86OlNlcnZlcjo6TG9jYWxTZXJ2ZXI6OmluY29taW5nQ29ubmVjdGlv bihxdWludHB0cikgCnZvaWQgU29wcmFubzo6U2VydmVyOjpTZXJ2ZXJDb3JlUHJpdmF0ZTo6YWRk Q29ubmVjdGlvbihTb3ByYW5vOjpTZXJ2ZXI6OlNlcnZlckNvbm5lY3Rpb24qKSBOZXcgY29ubmVj dGlvbi4gTmV3IGNvdW50OiAxMQpbL3Vzci9iaW4vbmVwb211a3NlcnZpY2VzdHViXSBTb3ByYW5v OjpPREJDOjpDb25uZWN0aW9uOjpDb25uZWN0aW9uKCkgU29wcmFubzo6U2VydmVyOjpTZXJ2ZXJD b25uZWN0aW9uKDB4YmZmMDMwKQpbL3Vzci9iaW4vbmVwb211a3NlcnZpY2VzdHViXSB2aXJ0dWFs IHZvaWQgU29wcmFubzo6U2VydmVyOjpTZXJ2ZXJDb25uZWN0aW9uOjpydW4oKSB0aHJlYWQgZG9u ZS4KWy91c3IvYmluL25lcG9tdWtzZXJ2aWNlc3R1Yl0gdmlydHVhbCBTb3ByYW5vOjpPREJDOjpD b25uZWN0aW9uOjp+Q29ubmVjdGlvbigpIFNvcHJhbm86OlNlcnZlcjo6U2VydmVyQ29ubmVjdGlv bigweGJmZjAzMCkKWy91c3IvYmluL25lcG9tdWtzZXJ2aWNlc3R1Yl0gdm9pZCBTb3ByYW5vOjpT ZXJ2ZXI6OlNlcnZlckNvcmU6OnNlcnZlckNvbm5lY3Rpb25GaW5pc2hlZCgpClsvdXNyL2Jpbi9u ZXBvbXVrc2VydmljZXN0dWJdIHZpcnR1YWwgU29wcmFubzo6U2VydmVyOjpTZXJ2ZXJDb25uZWN0 aW9uOjp+U2VydmVyQ29ubmVjdGlvbigpIFJlbW92aW5nIGNvbm5lY3Rpb24KWy91c3IvYmluL25l cG9tdWtzZXJ2aWNlc3R1Yl0gdm9pZCBTb3ByYW5vOjpTZXJ2ZXI6OlNlcnZlckNvcmU6OnNlcnZl ckNvbm5lY3Rpb25GaW5pc2hlZCgpIENvbm5lY3Rpb24gcmVtb3ZlZC4gQ3VycmVudCBjb3VudDog MTAK