[Windows] Client does not sync .mwb MySQL Workbench files since version 2.4.0

[sfadschm]

Expected behaviour

.mwb files should be recognized and synced normally (works fine up to version 2.3.4, even after a rollback from 2.4.x)

Actual behaviour

.mwb files are not recognized at all. When it gets created, it gets labeled with the blue “syncing” symbol, but this disappears within 1-2s. Looking into the client, no activity is reported, neither a syncing process nor an error, nor an ignored file. I anyway checked the ignored files list and none of the entries suits the file. Interestingly, if I change the files extension to “.txt”, it will still not be recognized or handled.
After a rollback to 2.3.4, the file will immediately be recognized and synced. Now with the file being inside the synced folder, after an automatic client update, it will even get deleted from the server (I now disabled automatic updates).

Steps to reproduce

1. Open MySQL Workbench.
   

2. Create new .mwb model file.
   

3. Place file in OwnCloud directory.
   

Server configuration

Operating system: Debian
Web server: Apache
PHP version: 7.1
ownCloud version: latest version (stable channel)
Storage backend (external storage): shared host

Client configuration

Client version: latest
Operating system: Windows 10
OS language: german

[guruz]

Does the behaviour change if you close MySQL Workbench?

Which messages related to this file do you see in the log file / log window?
https://doc.owncloud.org/desktop/2.4/troubleshooting.html#log-files

(CC @ckamm maybe related to locking?)

[sfadschm]

Closing Workbench unfortunately does not change the behaviour.

I just did the following:
1: .mwb file is synced on both server and client (with v2.3.4) and inside the folders.
2: Update client to v2.4.1.
3: Open .mwb file with Workbench, save file and exit Workbench.

Result:
Synchronisation protocol shows: ".mwb file deleted", ".mwb.bak file uploaded". (the .mwb.bak file is a backup of the old .mwb file produced by Workbench). The .mwb file is completely removed from

After that I duplicated the .mwb inside the folder. The sync protocoll does not show any action. The log windows shows the following for the two actions:

06-25 11:43:05:270 [ info gui.folderwatcher ]:	Detected changes in paths: QSet("C:/Xampp/htdocs/warehouse/_mysql/warehouse.mwb")
06-25 11:43:05:270 [ debug sync.database.sql ]	[ OCC::SqlQuery::bindValue ]:	SQL bind 1 QVariant(qlonglong, -7764091623761620616)
06-25 11:43:05:270 [ 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"
06-25 11:43:05:271 [ info gui.socketapi ]:	Sending SocketAPI message --> "STATUS:SYNC:C:\\Xampp\\htdocs\\warehouse\\_mysql\\warehouse.mwb" to QLocalSocket(0x8ae2eb8)
06-25 11:43:05:271 [ info gui.folderwatcher ]:	Detected changes in paths: QSet("C:/Xampp/htdocs/warehouse/_mysql/warehouse.mwb.bak")
06-25 11:43:05:271 [ debug sync.database.sql ]	[ OCC::SqlQuery::bindValue ]:	SQL bind 1 QVariant(qlonglong, 7579874821486694928)
06-25 11:43:05:271 [ 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"
06-25 11:43:05:272 [ info gui.socketapi ]:	Sending SocketAPI message --> "STATUS:SYNC:C:\\Xampp\\htdocs\\warehouse\\_mysql\\warehouse.mwb.bak" to QLocalSocket(0x8ae2eb8)
06-25 11:43:05:274 [ info gui.folderwatcher ]:	Detected changes in paths: QSet("C:/Xampp/htdocs/warehouse/_mysql/warehouse.mwb.0e87aa60")
06-25 11:43:05:274 [ debug sync.database.sql ]	[ OCC::SqlQuery::bindValue ]:	SQL bind 1 QVariant(qlonglong, 5213818495637230143)
06-25 11:43:05:275 [ 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"
06-25 11:43:05:275 [ info gui.socketapi ]:	Sending SocketAPI message --> "STATUS:SYNC:C:\\Xampp\\htdocs\\warehouse\\_mysql\\warehouse.mwb.0e87aa60" to QLocalSocket(0x8ae2eb8)
06-25 11:43:05:282 [ info gui.folderwatcher ]:	Detected changes in paths: QSet("C:/Xampp/htdocs/warehouse/_mysql/warehouse.mwb")
06-25 11:43:05:283 [ debug sync.database.sql ]	[ OCC::SqlQuery::bindValue ]:	SQL bind 1 QVariant(qlonglong, -7764091623761620616)
06-25 11:43:05:283 [ 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"
06-25 11:43:05:283 [ info gui.socketapi ]:	Sending SocketAPI message --> "STATUS:SYNC:C:\\Xampp\\htdocs\\warehouse\\_mysql\\warehouse.mwb" to QLocalSocket(0x8ae2eb8)

06-25 11:43:42:997 [ info gui.folderwatcher ]:	Detected changes in paths: QSet("C:/Xampp/htdocs/warehouse/_mysql/warehouse - Kopie.mwb")
06-25 11:43:42:997 [ debug sync.database.sql ]	[ OCC::SqlQuery::bindValue ]:	SQL bind 1 QVariant(qlonglong, 1773000152588615812)
06-25 11:43:42:998 [ 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"
06-25 11:43:42:998 [ info gui.socketapi ]:	Sending SocketAPI message --> "STATUS:SYNC:C:\\Xampp\\htdocs\\warehouse\\_mysql\\warehouse - Kopie.mwb" to QLocalSocket(0x8ae2eb8)
06-25 11:43:43:077 [ info gui.socketapi ]:	Received SocketAPI message <-- "RETRIEVE_FILE_STATUS:C:\\Xampp\\htdocs\\warehouse\\_mysql\\warehouse - Kopie.mwb" from QLocalSocket(0x8ae2eb8)
06-25 11:43:43:078 [ info gui.socketapi ]:	Sending SocketAPI message --> "STATUS:SYNC:C:\\Xampp\\htdocs\\warehouse\\_mysql\\warehouse - Kopie.mwb" to QLocalSocket(0x8ae2eb8)

Hope this helps tracking the issue.
I guess locking might be an issue here, however, it wasn't in v2.3.4.

[ckamm]

@sfadschm Thanks for the report and the log. This kind of behavior is unacceptable.

Unfortunately the log only shows the file watcher and socket api communication: All it tells us is that it's not related to excludes/ignored files since otherwise warehouse.mwb should have been filtered out before this stage.

Could you send me more of the log file? The full (--logdebug, see https://doc.owncloud.org/desktop/2.4/troubleshooting.html#saving-files-directly) log would be ideal since we need to debug the decision of deleting the file. Feel free to send to mail at ckamm de if you don't want it shared publicly (it has private information!)

Since you say the client actively deletes the file I doubt that locks are involved.

[sfadschm]

@ckamm thanks for the help, thats why I did not paste the whole logfile here.
I will redo all the stuff that went wrong and send the logfile tomorrow.

Just for clarification, the file does not get deleted from the local storage on the system with the 2.4.1 client. However, as the client does not seem to see the local file, but sees the file on the server, it deletes the file on the server upon syncing. Following from this, the client 2.3.4 (which runs nicely) on another system will see the deleted file on the server and thus delete its local copy on the second system, too.

Best and thanks
Alex

[ckamm]

@sfadschm Okay, thanks for the clarification and for helping debug this issue.

[ckamm]

From the logs I got it looks like the file is seen locally and there's no db entry (EDIT: note this is warehouse.sql; warehouse.mwb is not listed amount the local discovery files):

06-25 16:41:45:060 [ info sync.csync.updater ]:	file: _mysql/warehouse.sql, instruction: INSTRUCTION_NONE <<=
06-25 16:41:45:060 [ info sync.csync ]:	## Starting remote discovery ##

and that should make it INSTRUCTION_NEW but it ends up as INSTRUCTION_REMOVE:

06-25 16:41:45:172 [ info sync.csync.reconciler ]:	INSTRUCTION_REMOVE             server file: _mysql/warehouse.mwb

[sfadschm]

The line you cited is warehouse.sql, not warehouse.mwb.
Sorry, I missed deleting the other files in the folder before logging. Will do so with the logdebug option.

[ckamm]

@sfadschm Oops, great point!

My current best guess then is that ctx->statedb->getFileRecordByInode(fs->inode, &base) in the rename detection fails for warehouse.sql and the whole local discovery is somehow silently aborted.

@sfadschm Maybe a --logdebug log would have more information on why that fails, could I ask you to get one?

@ogoffart Have you seen this before? If my guess is true a non fatal abort like this seems very problematic - the whole sync finishes with a success.

EDIT: No, that abort isn't it - it looks like the errors propagate correctly.

[sfadschm]

Will try to do the logdebug this evening, tomorrow morning the latest. You will get it in your mails again.

Did you again mean warehouse.mwb instead of warehouse.sql? :D
However, when updating the client to 2.4.1, there should be no rename detection as the files did not change oder should it?

[ckamm]

@sfadschm This time I meant warehouse.sql because that's a somewhat surprising last line in the local discovery part of your log file.

[ckamm]

@sfadschm Thanks for the extra logs and testing. That makes it clear that there's no error during directory iteration. However, warehouse.mwb just isn't seen by the client - it is as if it didn't exist at all. Does it maybe have some esoteric attributes (particularly FILE_ATTRIBUTE_DEVICE, FILE_ATTRIBUTE_OFFLINE, FILE_ATTRIBUTE_TEMPORARY)?

Could you check with

fsutil usn readdata C:\XAMPP\htdocs\warehouse\_mysql\warehouse.mwb

Also check the detailed permissions of the files: maybe the client can't iterate over it because the client user doesn't have permission to stat the file?

Is there something else special about any of the parent directories?

If you add a file that isn't a copy of warehouse.mwb, would that get seen and uploaded? Try with a file a.txt and z.txt - maybe there's still a file in the directory that stops all files behind it from being visible.

I've looked at differences in the windows file io between 2.3 and 2.4 but didn't see anything suspicious yet.

@ogoffart It looks to me like errors from FindNextFile() in the windows csync_vio_local_readdir() aren't propagated fully - maybe that is to blame?

[ckamm]

The error propagation issue is addressed by #6616. That does not solve the problem here yet though.

[sfadschm]

@ckamm Thank you for the dedication in finding the bug :)

I checked for additional files in the directory, neither hidden nor system files are present. Whatever file I add to the folder, it will get synced. Even if I create a text file and rename it to warehouse.mwb to replace the original file it will get synced right away. I thus think it might really be related to the way Workbench saves the .mwb file.

I noticed, that if I 7zip a not synchronised .mwb file and unzip it later, the file will get synced when put into the directory. I thus created two files warehouse1.mwb, which gets synced in 2.4.1, then opened it in Workbench and saved it as warehouse2.mwb, which consequently does not get synced.
Here is the fsutil output for both files:

warehouse1.mwb
	Hauptversion                 : 0x3
	Nebenversion                 : 0x0
	Dateibezugsnr.               : 0x00000000000000000016000000001852
	Übergeordnete Dateibezugsnr. : 0x000000000000000000150000000064b2
	USN                          : 0x000000011a0b04d0
	Zeitangabe                   : 0x0000000000000000 00:00:00 01.01.1601
	Ursache                      : 0x0
	Quellinformation             : 0x0
	Sicherheitskennung           : 0x0
	Dateiattribute               : 0x20
	Dateinamenlänge              : 0x1c
	Dateinamenoffset             : 0x4c
	Dateiname                    : warehouse1.mwb

warehouse2.mwb
	Hauptversion                 : 0x3
	Nebenversion                 : 0x0
	Dateibezugsnr.               : 0x0000000000000000000d0000000031c5
	Übergeordnete Dateibezugsnr. : 0x000000000000000000150000000064b2
	USN                          : 0x000000011a0b0bd8
	Zeitangabe                   : 0x0000000000000000 00:00:00 01.01.1601
	Ursache                      : 0x0
	Quellinformation             : 0x0
	Sicherheitskennung           : 0x0
	Dateiattribute               : 0x120
	Dateinamenlänge              : 0x1c
	Dateinamenoffset             : 0x4c
	Dateiname                    : warehouse2.mwb

As far as I recall, the file attirbute 0x120 marks warehouse2.mwb as a temporary file, so might this be the core of the problem here?

However, after finding this, I did a rollback to 2.3.4 with both files in the directory. Although the file attribute of warehouse2.mwb stays the same, it again gets sync with the old client. Is there any difference between 2.3.4 and 2.4 in handling (or detecting) temporary files?

[guruz]

    } else if (handle->ffd.dwFileAttributes & FILE_ATTRIBUTE_DEVICE
                || handle->ffd.dwFileAttributes & FILE_ATTRIBUTE_OFFLINE
                || handle->ffd.dwFileAttributes & FILE_ATTRIBUTE_TEMPORARY) {
        file_stat->type = ItemTypeSkip;

:-/

[sfadschm]

Looks reasonable. However, skipping should maybe be reported in the sync protokoll of the client, shouldn't it?
I conclude that this is then rather a bug in Workbench for adding the temporary attribute after saving.

[guruz]

It was changed from CSYNC_VIO_FILE_TYPE_UNKNOWN to CSYNC_FTW_TYPE_SKIP to ItemTypeSkip in e8f7adc#diff-2806ff908889e7dd2cf746917f9ec78fL186
Maybe @jturcotte or @ogoffart remembers. Did we "just sync" CSYNC_VIO_FILE_TYPE_UNKNOWN files before?

I conclude that this is then rather a bug in Workbench for adding the temporary attribute after saving.

It's definitely annoying, but if it worked before it should still work.
Is the 0x120 taken away at some point?

[sfadschm]

As mentioned, it seems to be removed in some cases after zipping and unzipping the file in the 7z format.

[sfadschm]

Just found that this bug has been reported to Workbench already in 2016 (#84028). Will try to put some pressure to it. Thank you guys for tracking down the issue!

[guruz]

Linking for convenience :) https://bugs.mysql.com/bug.php?id=84028

[sfadschm]

Can we maybe implement an exception for .mwb files for as long as the issue at MySQL is open?
I think using FILE_ATTRIBUTE_TEMPORARY to exclude files makes perfect sense so we sould probably keep that. Just maybe add a notice to the not synced files.

[sfadschm]

For now I'm using a workaround by executing a batch file after saving the .mwb file to remove the temporary attribute. Might be helpful until the issue is resolved at MySQL:

powershell -Command "Get-childitem C:\Xampp\htdocs\warehouse\_mysql\warehouse.mwb | ForEach-Object -process {if (($_.attributes -band 0x100) -eq 0x100) {$_.attributes = ($_.attributes -band 0xFEFF)}} "

[sfadschm]

Adding bug report for Workbench 8.0 for convenience: https://bugs.mysql.com/bug.php?id=91510

[ckamm]

I'm glad there's a workaround and hope this'll get fixed upstream!

[guruz]

Happens also for IE11 downloaded files: #6696

[guruz]

@sfadschm Do you want to test with https://download.owncloud.com/desktop/testing/ownCloud-2.4.3.10180rc1-setup.exe ?

[sfadschm]

Happy to do so, yet I still don't think its the best solution to the problem. However, as the other developers (at Workench and IE) do not seem to care about it, we might not have another choice.

Workbench files sync nicely now, freshly saved, copied and newly created too. Thanks for all the help :)

[guruz]

@sfadschm :-)