ownCloud client 1.7.1 won't sync files on exfat drive

[andrewbridge]

Expected behaviour

ownCloud client successfully syncs data from second internal drive to server.

Actual behaviour

ownCloud client attempts to sync data from second internal drive but fails with one of two messages
"Unable to initialise journal"
"CSync failed to load or create the journal file. Make sure you have read and write permissions in the local sync directory."

Steps to reproduce

1. Install ownCloud client 1.7.1 to drive C: (primary internal drive, NTFS)
2. Configure client to sync files on drive D: (secondary internal drive, exFAT)
3. Wait for client to begin synchronisation attemps

Server configuration

Operating system: Ubuntu 14.10

Web server: Apache 2.4.7

Database: PostgreSQL

PHP version: 5.5.9

ownCloud version: 6.0.2

Storage backend: Local

Client configuration

Client version: 1.7.1

Operating system: Windows 8.1

OS language: English

Installation path of client: C:\Program Files (x86)\ownCloud

Logs

1. Output of owncloud --logwindow or owncloud --logfile log.txt
   The log is empty
2. Web server error log:
   Nothing related to ownCloud
3. ownCloud log (data/owncloud.log):
   Large numbers of errors/logs regarding address books and contacts, I'd imagine this if from using the online interface.

Further notes

• I don't believe this is a server issue as I have two other machines which are still syncing correctly
• There are 3 issues which seem to be experiencing the same errors messages to me, but not for the same reasons
  • [1.5.0beta1] Client (Mac) reports 'Unable to initialize a sync journal' #1228 - an issue that occurred after the updater started the client as a different user
  • CSync failed to load or create the journal file - SQlite error? #2673 - an issue where the database is corrupt
  • wrong error mesage and client stuck on corrupted .csync_journal.db #2547 - an issue suggesting to change the message that is shown when the database is corrupted
• I have tried starting the client as an administrator, and as myself, I've partially and fully reinstalled the client as well as manually deleting the database files to ensure they definitely aren't corrupted.
• To reiterate, I have added a test sync on the primary drive and that is successful and syncs to the server without issue.
• This issue only occurred with the update to 1.7.1, prior to this, I was running 1.7 and previous versions before with this same set up and did not experience the issue.

[ckamm]

@andrewbridge we've been tracking and trying to reproduce this issue in #2701, but without success so far.

To get more info, could you try running owncloud with --logfile log.txt again? It's surprising that it should be empty. I'm particularly interested in the lines in the log file around the error message "ERR: Failed to sqlite3 open statedb - bail out:". That could help with figuring out what's going on.

[andrewbridge]

Hi @ckamm, thanks for taking a look at my issue! I ran owncloud with the --logfile flag as suggested, but nothing seemed to occur. I used the log file panel in the client (F12), and left it for a while, and some output did appear. I've put it in a pastebin, let me know if you'd prefer me to put it elsewhere.

Unfortunately, the line you're looking for doesn't appear to be there. Have I not set a verbosity level high enough somewhere?

Just to double check, running the client from the command line with the flag should output a file into the same directory, called log.txt? Or have I been looking in the wrong place?

Thanks again for your help.

[ckamm]

@andrewbridge The log window has a maximum number of lines, unfortunately. With "--logfile some/path.txt" a logfile should be written (sometimes only fully filled when you close the client).

[andrewbridge]

Hi @ckamm, thanks for your response and sorry for the delay.

I ran the client with the flag again and waited for all the folders to attempt to sync. I've uploaded this log to pastebin again. Let me know if there's anything more I can do to help!

[ckamm]

@andrewbridge Thank you for the full log!

Relevant excerpt:

01-26 16:05:40:572 0x52a9ef8 ownsql.cpp:209 Sqlite prepare statement error: "" in "PRAGMA quick_check;"
01-26 16:05:40:572 0x52a9ef8 ownsql.cpp:81 quick_check returned failure: ""
01-26 16:05:40:572 0x52a9ef8 ownsql.cpp:120 Consistency check failed in readonly mode, giving up "E:\Andrew\Documents/.csync_journal.db"
01-26 16:05:40:572 0x52a9ef8 socketapi.cpp:444 Unable to open db "E:\Andrew\Documents/.csync_journal.db"
01-26 16:05:40:573 0x52a9ef8 syncengine.cpp:548 =====sync with existing DB
01-26 16:05:40:574 0x52a9ef8 ownsql.cpp:209 Sqlite prepare statement error: "" in "SELECT COUNT(*) FROM metadata"
01-26 16:05:40:575 0x9d6ef74 csync_update: Journal: E:\Andrew\Pictures/.csync_journal.db
01-26 16:05:40:575 0x9d6ef74 csync_statedb_query: sqlite3_compile error: disk I/O error - on query PRAGMA quick_check;
01-26 16:05:40:575 0x9d6ef74 csync_statedb_load: ERR: sqlite3 integrity check failed - bail out: disk I/O error.

It looks like we get a "disk I/O error" when running quick_check on the database.

[ckamm]

@andrewbridge If the DB isn't too private and you still have it: could you mail E:\Andrew\Documents/.csync_journal.db* to me (kamm at incasoftware.de)? I want to check whether the DB really is corrupt and whether I can reproduce the problem by opening it on an exfat drive.

[ckamm]

Related to #2697

[andrewbridge]

@ckamm I've sent that to the e-mail you listed.

As previously noted, I have deleted the db files previously and reinstalled the application in case something (probably me) had corrupted them, and this never seems to help the issue. I'm hoping it's not something that I'm doing wrong!

[ckamm]

@andrewbridge Thank you for the DB files. It looks like a valid empty database to me, I can open it just fine. I currently don't know what's going on. Here's another interesting excerpt from your log file: the db setup:

01-26 16:04:39:050 0x52a9ef8 ownsql.cpp:99 Consistency check failed, removing broken db "E:\Andrew\Documents/.csync_journal.db"
01-26 16:04:39:051 0x52a9ef8 syncjournaldb.cpp:140 sqlite3 version "3.8.6"
01-26 16:04:39:052 0x52a9ef8 syncjournaldb.cpp:148 sqlite3 journal_mode= "wal"
01-26 16:04:39:175 0x52a9ef8 syncjournaldb.cpp:90 ERROR committing to the database:  "cannot commit - no transaction is active"
01-26 16:04:39:175 0x52a9ef8 syncjournaldb.cpp:103 SQL Error "Create table metadata" ""
01-26 16:04:39:176 0x52a9ef8 ownsql.cpp:209 Sqlite prepare statement error: "" in "PRAGMA quick_check;"

We create a new database and run all the PRAGMA statements. Then CREATE TABLE fails to exec() and we fail to report the SQL error for that (will fix). The error about committing (triggered by sqlFail()) is also odd, because it looks like there was no error when startTransaction() ran earlier.

I'll try to find if similar issues have been reported elsewhere. I'll also fix the error reporting and will ask you to try again once the new builds are done. But probably that error is just a generic "disk i/o error" too.

[ckamm]

@andrewbridge Could I ask you to test this some more?

• Get and install a bleeding edge owncloud client from http://download.owncloud.com/desktop/daily/ (>= owncloud-1.8.0.4657-nightly20150129-setup.exe)
• Run it and paste the log again (better error reporting might show something)
• The same while setting the environment variable OWNCLOUD_SQLITE_JOURNAL_MODE=DELETE
• The same while setting the environment variable OWNCLOUD_SQLITE_TEMP_STORE=MEMORY

Please use a new sync dir for each test (or delete the .csync_journal.db* files) to ensure we're getting a fresh journal each time.

If you need any help, like more detailed instructions on one of the steps, let me know! I think it's likely that the changed settings will make it work - and if you verify that they do, we'll be able to fix this for good.

[andrewbridge]

@ckamm Sure!

I've done as you instructed, using the build "owncloud-1.8.0.4665-nightly20150131-setup.exe"

I've removed some details from the logs, as varying levels of success resulted in the log retaining filenames that I'd rather keep private. Don't think that should affect their usefulness, as the beginning of the path should always be included.

• Without environment changes
• Journal Mode = Delete (This one appears to work, but that caused the log to be almost 200000 lines long, I've abridged it where I could see duplication in the logs as it crawled around the directories)
• Temp Store = Memory

As noted the journal mode change appears to work. How does this affect the running of the client? Would it be safe to run the client in this way as a workaround in the meantime? If so, I'll use it to resume synching as normal.

Many thanks, I hope these logs are of some help!

[ckamm]

@andrewbridge Thank you for the efforts!

This indicates that @guruz intuition was correct and disabling WAL on FAT, like suggested in #2701 is a good idea.

I think we switched to the WAL mode for performance reasons - as far as I know running with journal mode = delete should be fine.

[ckamm]

@andrewbridge It looks to me like temp store = memory also lead to successful sync?

Both journal mode=delete and temp store=memory still have a couple of disk I/O errors when running quick check on a readonly database, but the default setting has way more errors. Did you delete the sync journals between tests? (these journal mode flags are sticky, so maybe the temp store memory test did use the DELETE journal mode?)

[andrewbridge]

@ckamm I closed the command prompt between attempts and as far as I'm aware, I deleted the journals both times.

I'm pretty sure the client reported an error with the temp store=memory setting. I don't completely understand the logs, but it appeared not to crawl as deeply with the temp store=memory too. I took those two assumptions and concluded that that method hadn't worked.

I noticed the recent commits as well! A final thank you to you and every one else that's been looking and persisting with my issue! I really do appreciate the work and help!

[ckamm]

@andrewbridge You're welcome, it wouldn't have been possible without all the data you provided. Thank you!

[bugsyb]

Hi All,

Just to report and for records, same issue happens on OS X (Mac), synchronizing folder with compression enabled on NTFS mounted via Tuxera.
This is most probably issue on Tuxera side and has been reported accordingly.

Using Tuxera NTFS on Mac I've run across problem with compressed folders/drive.
The problem persists every time the folder in which the file is to be created is compressed.
The filesystem has been tested (fsck multiple times, including test from native Windows).

Once the problem happens (coupe of times) I/O subsystem is locked and there is no possibility to unmount the volume. The only option is to hard power off system.
I've tested this problem extensively and turning off/on cache doesn't help.

Would be great if this could get fixed as I'd need to use compression on the given folder.

Attached are full logs with excerpt below.

1. http://pastebin.com/HTDycbhu - the attached with error is named.
2. http://pastebin.com/3NWAYtH3 - the second run on the same compressed folder (seems to work fine as files are created already).
3. http://pastebin.com/NqP82TFT - same as http://pastebin.com/HTDycbhu but run on uncompressed folder - same volume - no errors.

Problem reproduction steps.
System: MacBookPro11,5 (retina),
El Capitan 10.11.6
Memory: 16 GB
Boot ROM Version: MBP114.0172.B09
SMC Version (system): 2.30f2

Tuxera: 2015.3

Volume: NTFS created natively with Windows tools.

1. Create volume and enable compression either at disk level or at test folder level.
2. create couple of subfolders with non-zero files. This should go fine.
3. use ownCloud client to synchronize test folder to remote server.
4. First synchronization run will fail at level:
   08-07 14:26:20:900 0x7fbbb3426dd0 OCC::SyncEngine::startSync: void OCC::SyncEngine::startSync() "/remove-me-compress-test" QUrl( "https://myhost.domain/owncloud/remote.php/webdav/remove-me-compress-test" )
   08-07 14:26:20:900 0x7fbbb5d232b0 csync_update: Journal: /Volumes/bugs/Exchange/test-compressed-folder-sync/.csync_journal.db

complaining about problem with saving database (see logs). At the same time error in System logs is presented:
==> /var/log/system.log <==
Aug 7 14:26:20 apple tuxera_ntfs[2062]: Failed to read an uncompressed cluster, inode 1129 offs 0x10000

1. The file gets created anyway as per ownCloud logs and ls

==> /tmp/owncloud-ntfs-tuxera-compress-error <==
08-07 14:26:20:916 0x7fbbb5d232b0 csync_statedb_load: sqlite3 version "3.13.0"
08-07 14:26:20:916 0x7fbbb5d232b0 csync_statedb_load: Success
08-07 14:26:20:918 0x7fbbb5d232b0 csync_walker: directory: /Volumes/bugs/Exchange/test-compressed-folder-sync/synctest [inode=1394]
08-07 14:26:20:918 0x7fbbb5d232b0 _csync_detect_update: Checking for rename based on inode # 1394
08-07 14:26:20:918 0x7fbbb5d232b0 _csync_detect_update: file: synctest, instruction: INSTRUCTION_NEW <<=
08-07 14:26:20:922 0x7fbbb5d232b0 csync_walker: file: /Volumes/bugs/Exchange/test-compressed-folder-sync/synctest/file.one [inode=1402 size=0]
08-07 14:26:20:922 0x7fbbb5d232b0 _csync_detect_update: Checking for rename based on inode # 1402
08-07 14:26:20:922 0x7fbbb5d232b0 _csync_detect_update: file: synctest/file.one, instruction: INSTRUCTION_NEW <<=

1. ownCloud tries to write file (update earlier created):
   08-07 14:26:21:673 0x7fbbb3426dd0 OCC::SocketApi::sendMessage: SocketApi: Sending message: "STATUS:SYNC:/Volumes/bugs/Exchange/test-compressed-folder-sync/synctest"
   08-07 14:26:21:675 0x7fbbb3426dd0 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString &, bool) Transaction commit "post treewalk" and starting new transaction
2. Tuxera raises Input/Output error.

==> /var/log/system.log <==
Aug 7 14:26:21 --- last message repeated 5 times ---
Aug 7 14:26:21 apple tuxera_ntfs[2062]: ntfs_attr_pwrite: Failed to find VCN #3: Input/output error

1. ownCloud gets error:

==> /tmp/owncloud-ntfs-tuxera-compress-error <==
08-07 14:26:21:695 0x7fbbb3426dd0 OCC::SyncJournalDb::commitTransaction: ERROR committing to the database: "disk I/O error"
08-07 14:26:21:696 0x7fbbb3426dd0 OCC::SyncJournalDb::startTransaction: Database Transaction is running, not starting another one!
08-07 14:26:21:696 0x7fbbb3426dd0 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString &, bool) Transaction commit "post stale entry removal" and starting new transaction
08-07 14:26:21:696 0x7fbbb3426dd0 OCC::SyncJournalDb::commitTransaction: ERROR committing to the database: "cannot commit - no transaction is active"
08-07 14:26:21:696 0x7fbbb3426dd0 OCC::SyncJournalDb::startTransaction: Database Transaction is running, not starting another one!

1. Due to errors finishes the sync transactions:
   08-07 14:26:28:475 0x7fbbb3426dd0 OCC::SyncJournalDb::commitTransaction: ERROR committing to the database: "cannot commit - no transaction is active"
   08-07 14:26:28:475 0x7fbbb3426dd0 OCC::SyncEngine::abort: void OCC::SyncEngine::abort() QObject(0x0)
   08-07 14:26:28:494 0x7fbbb3426dd0 OCC::OwncloudWizard::slotCurrentPageChanged: Current Wizard page changed to 0
   08-07 14:26:28:513 0x7fbbb3426dd0 OCC::SocketApi::~SocketApi: SocketApi: dtor
2. Tuxera raises same error again:
   ==> /var/log/system.log <==
   Aug 7 14:26:29 --- last message repeated 1 time ---