Client: INSTRUCTION_UPDATE_METADATA does not update mtime (WAS: fileid)

[moscicki]

Hello,

Whenever mtime or fileid changes on the server (but same etag) the client correctly detects this with INSTRUCTION_UPDATE_METADATA however it does not update the sqlite database.

I have the full debug output in case you want to have a look.

kuba

--

[ogoffart]

What's the client's version?

[moscicki]

Version 2.4.1 (build 9367)

[ogoffart]

I guest tested to change all the fileid programatically (by editing propertyMapToFileStat in discoveryphase.cpp) and the new file id are properly saved on the database.

I'd like to see a log output.

[moscicki]

@ogoffart: I sent the log by private mail.

[ogoffart]

The log seems to indicate that the metadata is updated:

07-02 15:04:41:202 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 3 QVariant(QByteArray, "5a12f20cdf66cc8bc7bcf09dfa79a1c2")
[...]
07-02 15:04:41:203 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 11 QVariant(QByteArray, "628960111099904")
[...]
07-02 15:04:41:203 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:        SQL exec "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm, filesize, ignoredChildrenRemote, contentChecksum, contentChecksumTypeId) VALUES (?1 , ?2, ?3 , ?4 , ?5 , ?6 , ?7,  ?8 , ?9 , ?10, ?11, ?12, ?13, ?14, ?15, ?16);"
0

We find a lot of these INSERT OR REPLACE INTO metadata, one for every file, and it stores the file id (the 11th parameter)

Is that not saved on the DB?

[ogoffart]

So the database is still with the old file id for these files, despite the log claim that it did an INSERT with the right file id?

[moscicki]

I am rerunning these tests to give you a complete picture. I need a bit
more time.

On Tue, Jul 3, 2018 at 2:29 PM, Olivier Goffart [e-mail]
wrote:

So the database is still with the old file id for these files, despite the
log claim that it did an INSERT with the right file id?

—
You are receiving this because you authored the thread.
Reply to this email directly, view it on GitHub
https://github.com/owncloud/client/issues/6629#issuecomment-402138717,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAl9jflBzIGSdClm9zp2PZQtWSnR2Nhwks5uC2OtgaJpZM4U_AfP
.

--

Best regards,
Kuba

[moscicki]

The writing to the DB works but the client does not use updated mtime value to save to sqlite.

Please consider the case of file: 648e69540d6e9e0b6f8fb0b108678060

getlastmodified reported by PROPFIND is 1530200199 (Thu, 28 Jun 2018 15:36:39 GMT)

owncloud.log1:

At local discovery the client has an old mtime value of 1530200212 and old fileid value recorded in the db:

07-02 15:04:41:028 [ debug sync.csync.updater ] [ csync_walker ]:       file: 648e69540d6e9e0b6f8fb0b108678060 [inode=39348046 size=69206016]
07-02 15:04:41:028 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 QVariant(qlonglong, -1775092903239200856)
07-02 15:04:41:028 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:        SQL exec "SELECT path, inode, modtime, type, md5, fileid, remotePerm, filesize,  ignoredChildrenRemote, contentchecksumtype.name || ':' || contentChecksum FROM metadata  LEFT JOIN checksumtype as contentchecksumtype ON metadata.contentChecksumTypeId == contentchecksumtype.id WHERE phash=?1"
07-02 15:04:41:028 [ info sync.csync.updater ]: Database entry found, compare: 1530200212 <-> 1530200212, etag:  <-> 461829433456590848:91ee6972, inode: 39348046 <-> 39348046, size: 69206016 <-> 69206016, perms: 0 <-> ff, ignore: 0
07-02 15:04:41:028 [ info sync.csync.updater ]: file: 648e69540d6e9e0b6f8fb0b108678060, instruction: INSTRUCTION_NONE <<=

At remote discovery the client detects new mtime 1530200199 and also the new file_id which is now: 628960647970816

07-02 15:04:41:089 [ debug sync.csync.updater ] [ csync_walker ]:       file: 648e69540d6e9e0b6f8fb0b108678060 [file_id=628960647970816 size=69206016]
07-02 15:04:41:089 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 QVariant(qlonglong, -1775092903239200856)
07-02 15:04:41:089 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:        SQL exec "SELECT path, inode, modtime, type, md5, fileid, remotePerm, filesize,  ignoredChildrenRemote, contentchecksumtype.name || ':' || contentChecksum FROM metadata  LEFT JOIN checksumtype as contentchecksumtype ON metadata.contentChecksumTypeId == contentchecksumtype.id WHERE phash=?1"
07-02 15:04:41:089 [ info sync.csync.updater ]: Database entry found, compare: 1530200199 <-> 1530200212, etag: 461829433456590848:91ee6972 <-> 461829433456590848:91ee6972, inode: 0 <-> 39348046, size: 69206016 <-> 69206016, perms: ff <-> ff, ignore: 0
07-02 15:04:41:089 [ debug sync.csync.updater ] [ _csync_detect_update ]:       Need to update metadata for: 648e69540d6e9e0b6f8fb0b108678060
07-02 15:04:41:089 [ info sync.csync.updater ]: file: 648e69540d6e9e0b6f8fb0b108678060, instruction: INSTRUCTION_UPDATE_METADATA <<=

And it actually writes the new fileid to disk but old mtime:

07-02 15:04:41:200 [ info sync.database ]:      Updating file record for path: "648e69540d6e9e0b6f8fb0b108678060" inode: 39348046 modtime: 1530200212 type: 0 etag: "461829433456590848:91ee6972" fileId: "628960647970816" remotePerm: "WDNVCKR" fileSize: 69206016 checksum: "SHA1:91c6eb9bec9d231d3a158115b0025d83891d8aa3"
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 QVariant(QByteArray, "SHA1")
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:        SQL exec "INSERT OR IGNORE INTO checksumtype (name) VALUES (?1)"
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:        Last exec affected 0 rows.
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 QVariant(QByteArray, "SHA1")
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:        SQL exec "SELECT id FROM checksumtype WHERE name=?1"
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 QVariant(qlonglong, -1775092903239200856)
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 2 QVariant(int, 32)
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 3 QVariant(QByteArray, "648e69540d6e9e0b6f8fb0b108678060")
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 4 QVariant(qulonglong, 39348046)
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 5 QVariant(int, 0)
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 6 QVariant(int, 0)
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 7 QVariant(int, 0)
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 8 QVariant(qlonglong, 1530200212)
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 9 QVariant(int, 0)
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 10 QVariant(QByteArray, "461829433456590848:91ee6972")
07-02 15:04:41:200 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 11 QVariant(QByteArray, "628960647970816")
07-02 15:04:41:201 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 12 QVariant(QByteArray, "WDNVCKR")
07-02 15:04:41:201 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 13 QVariant(qlonglong, 69206016)
07-02 15:04:41:201 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 14 QVariant(int, 0)
07-02 15:04:41:201 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 15 QVariant(QByteArray, "91c6eb9bec9d231d3a158115b0025d83891d8aa3")
07-02 15:04:41:201 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 16 QVariant(int, 1)
07-02 15:04:41:201 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:        SQL exec "INSERT OR REPLACE INTO metadata (phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm, filesize, ignoredChildrenRemote, contentChecksum, contentChecksumTypeId) VALUES (?1 , ?2, ?3 , ?4 , ?5 , ?6 , ?7,  ?8 , ?9 , ?10, ?11, ?12, ?13, ?14, ?15, ?16);"
07-02 15:04:41:201 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:        Last exec affected 1 rows.
07-02 15:04:41:201 [ debug sync.statustracker ] [ OCC::SyncFileStatusTracker::slotItemCompleted ]:      Item completed "648e69540d6e9e0b6f8fb0b108678060" 0 1024

[ogoffart]

Right, we do not synchronize the mtime when only that changes.
This is https://github.com/owncloud/client/issues/4755

We can't just write the mtime to the database, as the mtime in the database must be the LOCAL mtime. We would need to also update the mtime of the file then. (Otherwise, next sync would want to upload the file again) But if only the mtime changes locally, we can't update the mtime on the server as this would change the etag (server bug https://github.com/owncloud/core/issues/20474 ).

So right now we live with the fact that mtimes might differ on the server and on the client.

We could just put the mtime back to the one from the server if we detect the file has not changed, but that's not a better solution IMHO.

But this is quite unrelated from the original issue which was talking about fileid.

[moscicki]

Ok, I changed the subject as it was misleading.

Why don't we at least change the local mtime of the file when we detect it changed on the server? This would at least propagate the mtime change in one direction, awaiting the opposite direction until the server bugs are fixed.

That would also fix the problem I am reporting. The current situation is pretty inconsistent and the mtime is quite useless.

[ogoffart]

Why don't we at least change the local mtime of the file when we detect it changed on the server?

Because then that means that if the user change the mtime locally, the mtime would be reversed back to the server mtime.
If that's the expected behavior, we could implement that.

Note that there is another set of problem when trying to synchronise the mtime.
For example, on timezone change (daylight saving, ....) filesystem which stores the mtime in local time would then cause an update of the mtime of all files.

That would also fix the problem I am reporting. The current situation is pretty inconsistent and the mtime is quite useless.

Can you elaborate what is the problem you have and why you need the mtime to be synchronized.

[moscicki]

The problem is the following: when you rename the file locally the rename is propagated OK. However on the next sync run the renamed file is re-uploaded. This is caused by the mtime mismatch between the server and the one stored in the sqlite db -- precisely as illustrated in this case (mtime is different, etag is the same, fileid is also the same).

[ogoffart]

The rename problem would be another issue. Normaly on rename, the mtime should stay the local mtime. If not, this is a bug.

[ogoffart]

The rename issue is going to be fixed by PR #6632

[moscicki]

Could I test it tomorrow? If yes - how?

[michaelstingl]

@jnweiger Could you build @moscicki the PR #6632 ? @moscicki Win? Mac? Linux?

[moscicki]

Mac please. Thank you!

On Thu, Jul 5, 2018 at 9:07 AM, Michael Stingl [e-mail]
wrote:

@jnweiger https://github.com/jnweiger Could you build @moscicki
https://github.com/moscicki the PR #6632
https://github.com/owncloud/client/pull/6632 ? @moscicki
https://github.com/moscicki Win? Mac? Linux?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/owncloud/client/issues/6629#issuecomment-402626063,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAl9jYbRJ7BMY1-Lxn1IluEcTt6qaT5qks5uDbs8gaJpZM4U_AfP
.

--

Best regards,
Kuba

[moscicki]

Could you do it on top of 2.4.1? So 2.4.1 + this patch only.

Thanks!

On Thu, Jul 5, 2018 at 10:08 AM, JT M [e-mail] wrote:

Mac please. Thank you!

On Thu, Jul 5, 2018 at 9:07 AM, Michael Stingl [e-mail]
wrote:

@jnweiger https://github.com/jnweiger Could you build @moscicki
https://github.com/moscicki the PR #6632
https://github.com/owncloud/client/pull/6632 ? @moscicki
https://github.com/moscicki Win? Mac? Linux?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/owncloud/client/issues/6629#issuecomment-402626063,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAl9jYbRJ7BMY1-Lxn1IluEcTt6qaT5qks5uDbs8gaJpZM4U_AfP
.

--

Best regards,
Kuba

--

Best regards,
Kuba

[michaelstingl]

@moscicki please perform a quick check with the build from the pull request. After validation, we could discuss backporting options.

[moscicki]

where do I find it?

[michaelstingl]

@jnweiger will provide the Mac build from the PR later today

[jnweiger]

@moscicki it will be on top of the top far above 2.4.1 --- no backports yet, sorry.
Hope you are not afraid of seeing a prerelease 2.6.0 version number in there :-)

I'll start with a testpilotcloud client build.

[moscicki]

For testing it is OK but rolling out to prod 2.6.0 I am not ready...

On Thu, Jul 5, 2018 at 12:14 PM, Jürgen Weigert [e-mail]
wrote:

@moscicki https://github.com/moscicki it will be on top of the top far
above 2.4.1 --- no backports yet, sorry.
Hope you are not afraid of seeing a prerelease 2.6.0 version number in
there :-)

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/owncloud/client/issues/6629#issuecomment-402675253,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAl9jW6I9xwqDOqTQLWq0kKN88fdHUduks5uDeb4gaJpZM4U_AfP
.

--

Best regards,
Kuba

[jnweiger]

It's at 2.5.0 actually, (not 2.6.0) but yes: still for testing only.
You can choose two different Qt flavors. There should be no functional difference.

• https://download.owncloud.com/desktop/testing/testpilotcloud-qt5.10.1-2.5.0.10124pr6632.pkg
• https://download.owncloud.com/desktop/testing/testpilotcloud-qt5.6.2-2.5.0.10124pr6632.pkg

same wrapped as a tar:

• https://download.owncloud.com/desktop/testing/testpilotcloud-qt5.10.1-2.5.0.10124pr6632.pkg.tbz
• https://download.owncloud.com/desktop/testing/testpilotcloud-qt5.6.2-2.5.0.10124pr6632.pkg.tbz

[guruz]

@moscicki Thanks for testing. Let us know the result asap so we can still get this in 2.4.2

[jnweiger]

@guruz what is the timeline for 2.4.2 --- I'd love to have that included too!
2.4.2RC1 tonight.

[moscicki]

Hi guys,

Test affirmative - the rename bug is gone.

For your info: I haven't tested extensively if there are any other side effects of this patch. If you are confident, please include this in 2.4.2 -- that would be great.

Thanks for the great job!

[ogoffart]

Closing this. Remaining issue with synchronizing mtime is tracked in #4755 and the original issue about fileid was apparently invalid.

[moscicki]

Thanks a lot!

[jnweiger]

OK
client 2.4.3rc1 and client 2.5.0beta1 sync the same file. touch -m the file in either of the clients folders, correctly updates the modify timestamp in the other.
Works both directions. (Had expected that 2.4.3 would not receive the update, but okay)

date --date=@$(sqlite3 ._sync_f3502dd50375.db "select modtime from metadata where path like '%/Example.odt';")
can be used to check the mtime in the client database.

[guruz]

Cool date+sqlite3 command :)