Bug 353036

Very surprising, since
1) kbuildsycoca5 actually creates the ksycoca5 hardlink right after saving to ksycoca5_en_sha1
2) nothing needs the old-named ksycoca5 file anymore (this was for compatibility with running apps using kservice <= 5.14).

Do you have debug output from the kservice framework to attach here?
(e.g. from ~/.xsession-errors-:0)

(In reply to David Faure from comment #1)
> Very surprising, since
> 1) kbuildsycoca5 actually creates the ksycoca5 hardlink right after saving
> to ksycoca5_en_sha1
> 2) nothing needs the old-named ksycoca5 file anymore (this was for
> compatibility with running apps using kservice <= 5.14).
> 
> Do you have debug output from the kservice framework to attach here?
> (e.g. from ~/.xsession-errors-:0)

Mm.. Crazy : I rebuilt plasma and now this problem disappeared completely..

- is ksycoca5 hard link supposed to be created always? because it is not getting created for new users.
- now that you mention is it possible that plasma was built agains 5.13 and then I upgraded frameworks and things messed up?

As of errors

I just see lots of

Reusing existing ksycoca
Recreating ksycoca file ("/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ=", version 302)
Still in the time dict (i.e. deleted files) ("apps")
Menu "applications-kmenuedit.menu" not found.
Saving

Also I see ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ=.lock file present in .cache dir.

This problem is more clearly visible/reproducible in Plasma mobile.

* Hardlink created always: yes (unless the filesystem doesn't support hardlinks).
* Building against 5.13 and running 5.14 should be fine, the behavior change is internal to the kservice library and the kbuildsycoca5 executable.
* Debug output: please use kdebugsettings to ensure kf5.kservice.sycoca is enabled
* Lock file: is it empty? Or does it point to a PID? Is that PID running while the lock file is there?

(In reply to David Faure from comment #5)
> * Debug output: please use kdebugsettings to ensure kf5.kservice.sycoca is
> enabled

This is errors in logs with grep for sycoca

Waiting for already running kbuildsycoca5 to finish.
kf5.kservice.sycoca: Opening ksycoca from "/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ="
kf5.kservice.sycoca: QThread(0x104b60) got a notifyDatabaseChanged signal
kf5.kservice.sycoca: Opening ksycoca from "/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ="
kf5.kservice.sycoca: checking file timestamps
kf5.kservice.sycoca: timestamp changed: "/usr/share/kservicetypes5"
Waiting for already running kbuildsycoca5 to finish.
kf5.kservice.sycoca: Opening ksycoca from "/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ="
kf5.kservice.sycoca: QThread(0x104b60) got a notifyDatabaseChanged signal
kf5.kservice.sycoca: Opening ksycoca from "/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ="
kf5.kservice.sycoca: checking file timestamps
kf5.kservice.sycoca: timestamp changed: "/usr/share/kservicetypes5"
Reusing existing ksycoca
Recreating ksycoca file ("/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ=", version 302)
....
and lots of similar mesages

> * Lock file: is it empty? Or does it point to a PID? Is that PID running
> while the lock file is there?

1936
plasmashell
ubuntu-phablet                            

Lock file contains this and yes that process is running..

*ping* :)

Its quite severe issue..

I woke up this morning with a possible explanation for this.

> timestamp changed: "/usr/share/kservicetypes5"

Bhushan, could it be that this directory has a timestamp in the future?

The logic in the code is: if one of the dirs with desktop files has a modification time which is after the time at which ksycoca was recreated the last time [1], then ksycoca gets recreated.

But that logic assumes mtimes are logical, and not in the future.

In case of a timestamp in the future, I guess I should "touch" the dir to bring back to something more reasonable...

[1] technically that is not exactly the mtime of ksycoca, but something slightly before, a timestamp which then gets written into ksycoca; this is a safety measure in case a file is modified while ksycoca is recreated; shouldn't matter but I'm just mentionning this in case someone debugs by looking at the mtime of ksycoca.

If this isn't the issue, then I'll write a patch with more debug output for you to try.

On Tue, Sep 29, 2015 at 12:32 PM, David Faure <faure@kde.org> wrote:
> Bhushan, could it be that this directory has a timestamp in the future?

Ack.. that might be very well issue.. We don't have proper date
settings for the mobile.

so yeah, you found it.

Editing bug title to mention proper issue.

So your "current date/time" can go back in time? Odd.

Please try the patch at https://git.reviewboard.kde.org/r/125497/
1) do you get the debug output "has a modification time in the future" ?
2) does the patch fix the issue?

(In reply to David Faure from comment #11)
> So your "current date/time" can go back in time? Odd.

Yeah, on every reboot phone's date and time is set back to 1970. Given timedate syncing is not working.

> Please try the patch at https://git.reviewboard.kde.org/r/125497/
> 1) do you get the debug output "has a modification time in the future" ?
> 2) does the patch fix the issue?

I will need bit of help from our packagers to package it.. Once this is packaged I can test it. I tried to manually cross build but I screwed something else.. and I failed to build it.

Sorry for delay.

Okay so I managed to cross-build it but it seems that there is still kbuildsycoca loop.. :\

Recreating ksycoca file ("/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ=", version 302)
kf5.kservice.sycoca: Opening ksycoca from "/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ="
kf5.kservice.sycoca: Opening ksycoca from "/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ="
kf5.kservice.sycoca: checking file timestamps
kf5.kservice.sycoca: "/usr/share/kservicetypes5" has a modification time in the future QDateTime("2015-09-24 08:59:11.000 UTC Qt::LocalTime") - fixing it to avoid constant ksycoca rebuilds
kf5.kservice.sycoca: timestamp changed: "/usr/share/kservicetypes5"
Reusing existing ksycoca
Recreating ksycoca file ("/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ=", version 302)
kf5.kservice.sycoca: Opening ksycoca from "/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ="
kf5.kservice.sycoca: checking file timestamps
kf5.kservice.sycoca: "/usr/share/kservicetypes5" has a modification time in the future QDateTime("2015-09-24 08:59:11.000 UTC Qt::LocalTime") - fixing it to avoid constant ksycoca rebuilds
kf5.kservice.sycoca: timestamp changed: "/usr/share/kservicetypes5"
Reusing existing ksycoca
Recreating ksycoca file ("/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ=", version 302)
kf5.kservice.sycoca: Opening ksycoca from "/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ="

Also this time launcher have no applications it.. Perhaps I should try with removed ksycoca cache?

It's getting recreated, so no point in removing it.

What's the timestamp of /usr/share/kservicetypes5
and what's the timestamp of /home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ=?

(Use `stat` on both of them, and look for the Modify: line)

phablet@ubuntu-phablet:~$ stat /home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ=
  File: ‘/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ=’
  Size: 704425          Blocks: 1376       IO Block: 4096   regular file
Device: b31ch/45852d    Inode: 195678      Links: 1
Access: (0600/-rw-------)  Uid: (32011/ phablet)   Gid: (32011/ phablet)
Access: 1970-10-27 10:07:45.289999997 +0000
Modify: 1970-10-27 10:07:46.919999996 +0000
Change: 1970-10-27 10:07:46.969999995 +0000
 Birth: -
phablet@ubuntu-phablet:~$ stat /usr/share/kservicetypes5
  File: ‘/usr/share/kservicetypes5’
  Size: 4096            Blocks: 8          IO Block: 4096   directory
Device: 700h/1792d      Inode: 58798       Links: 2
Access: (0755/drwxr-xr-x)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 1970-10-27 10:20:53.000000000 +0000
Modify: 2015-09-24 08:59:11.000000000 +0000
Change: 2015-09-24 08:59:11.000000000 +0000
 Birth: -

and date : Tue Oct 27 10:22:09 UTC 1970

Very strange, the utime call should bring that dir back to the past...

Can you apply this patch for more debug output and try again? http://www.davidfaure.fr/2015/ksycoca_future_debug.diff

Mm, crazy..

I don't see this in my log at all, rest same.

Then you didn't apply the patch or you didn't recompile ... 

ah and after that, type
kdeinit5
in a terminal.

Sorry my bad.. I didn't install properly

kf5.kservice.sycoca: Opening ksycoca from "/home/phablet/.cache/ksycoca5_en_oApiElUYNFUoBBsUQi59ER6LrpQ="
kf5.kservice.sycoca: checking file timestamps
kf5.kservice.sycoca: "/usr/share/kservicetypes5" has a modification time in the future QDateTime("2015-09-24 08:59:11.000 UTC Qt::LocalTime") - fixing it to avoid constant ksycoca rebuilds
kf5.kservice.sycoca: utime "/usr/share/kservicetypes5" , 25876975 said -1
kf5.kservice.sycoca: Operation not permitted
kf5.kservice.sycoca: timestamp changed: "/usr/share/kservicetypes5"
Reusing existing ksycoca

Oh! Doh! /usr/share/kservicetypes5 is owned by root, and you're running as user, so changing the mtime of /usr isn't possible.

I need to find another solution.... brainstorming gives

- ignoring timestamps in the future (this could miss updates? but only at the point of going back in time)
- storing the timestamp of every dir and rebuilding on change (not sure how this interacts with the sycoca timestamp)
- doing the other way around and changing the mtime of ksycoca to match the most-in-the-future directory timestamp .... well, on your system this would miss any updates between 1970 and 2015, once the current datetime is back to 1970, probably not good.

... need to think a bit more about this, but ideas welcome.

The second solution seems to be the only one. The sycoca timestamp would just not matter anymore.

New patch is up on reviewboard (same URL). Note that I pushed a small refactoring meanwhile, so you need to first update to git master and then apply the patch from reviewboard.

Git commit 0e4d7247e27f82a9b79b19dbceb35b603baceb76 by David Faure.
Committed on 04/10/2015 at 18:37.
Pushed by dfaure into branch 'master'.

KSycoca: store mtime for every source dir, to detect changes.

The old solution was to compare the mtime of the source dirs with
a stored timestamp of "just before listing them". However this assumes
that time always moves forward, and some people have a phone that also acts
as a time machine (a limited one, with a single possible "destination", 01/01/1970).

Well, this new solution should also avoid problems with DST making time
go back 1h once a year; or problems when changing timezones (although we
could also just use UTC everywhere for these issues).
REVIEW: 125497

M  +50   -1    autotests/ksycocatest.cpp
M  +21   -4    src/sycoca/kbuildsycoca.cpp
M  +1    -1    src/sycoca/kbuildsycoca_p.h
M  +91   -48   src/sycoca/ksycoca.cpp
M  +7    -3    src/sycoca/ksycoca_p.h

http://commits.kde.org/kservice/0e4d7247e27f82a9b79b19dbceb35b603baceb76