search

owncloud / client

🖥️ Desktop Syncing Client for ownCloud
GNU General Public License v2.0
1.4k stars 663 forks source link

Internal Server Error caused by syncing an image #8133

Open KarstenS123 opened 4 years ago

KarstenS123 commented 4 years ago

Expected behaviour

Image file should get synced.

Actual behaviour

Internal server error appears:

03.10.2020 11:41:21, Bilder/HighPowerMode.png, E:\Sync,Server hat "500 Internal Server Error" auf "PUT https:// [removed] /remote.php/dav/files/KarstenS/Bilder/HighPowerMode.png" geantwortet (An exception occurred while executing 'SELECT SUM(size) AS f1, MIN(size) AS f2 FROM oc_filecache WHERE parent = ? AND storage = ?' with params [33, 1]:

SQLSTATE[HY000]: General error: 2006 MySQL server has gone away) (Übersprungen aufgrund des früheren Fehlers, erneuter Versuch in 12 Stunden)

The Image (PNG file generated by the screenshot tool delivered with Windows):

HighPowerMode

Steps to reproduce

  1. Copy the file into the sync folder.
  2. Wait for sync.

Server configuration

Operating system: Ubuntu 18.04.5 LTS

Web server: Apache

Database: MySQL Server-Version: 5.7.31-0ubuntu0.18.04.1-log - (Ubuntu)

PHP version: 7.3.22-1+ubuntu18.04.1+deb.sury.org+1

ownCloud version: 10.5.0.10

Storage backend (external storage): internal harddisk

Client configuration

Client version: 2.6.3 (build 13551)

Operating system: Windows 10 (2004)

OS language: German

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

michaelstingl commented 4 years ago

I wasn't able to reproduce with the image file provided.

Please find the line in the desktop log where the upload of this file fails. The upload request should have a X-REQUEST-ID. Please then grep your owncloud.log for the X-REQUEST-ID to find what's going wrong.

KarstenS123 commented 4 years ago

I don't find a request ID around the timestamp I did copy the file again into the folder.

After "discovery end" there is only this in the desktop log.

10-04 20:27:26:114 [ info sync.engine ]:    #### Discovery end ####################################################  398 ms
10-04 20:27:26:114 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:    SQL exec "SELECT fingerprint FROM datafingerprint"
10-04 20:27:26:114 [ info sync.engine ]:    #### Reconcile (aboutToPropagate) ####################################################  399 ms
10-04 20:27:26:114 [ debug sync.statustracker ] [ OCC::SyncFileStatusTracker::slotAboutToPropagate ]:   Investigating "Bilder/HighPowerMode.png" OCC::SyncFileItem::BlacklistedError CSyncEnums::CSYNC_INSTRUCTION_IGNORE
10-04 20:27:26:114 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:114 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync" to QLocalSocket(0x79350d0)
10-04 20:27:26:114 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 QVariant(qlonglong, -7866600945928434832)
10-04 20:27:26:114 [ 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"
10-04 20:27:26:114 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\Bilder" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:114 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\Bilder" to QLocalSocket(0x79350d0)
10-04 20:27:26:114 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:ERROR:E:\\Sync\\Bilder\\HighPowerMode.png" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:114 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:ERROR:E:\\Sync\\Bilder\\HighPowerMode.png" to QLocalSocket(0x79350d0)
10-04 20:27:26:114 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\._sync_aa3840f26908.db" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:114 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\._sync_aa3840f26908.db" to QLocalSocket(0x79350d0)
10-04 20:27:26:114 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\._sync_aa3840f26908.db-shm" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:114 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\._sync_aa3840f26908.db-shm" to QLocalSocket(0x79350d0)
10-04 20:27:26:115 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\._sync_aa3840f26908.db-wal" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:115 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\._sync_aa3840f26908.db-wal" to QLocalSocket(0x79350d0)
10-04 20:27:26:115 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\.owncloudsync.log" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:115 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\.owncloudsync.log" to QLocalSocket(0x79350d0)
10-04 20:27:26:115 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\.owncloudsync.log.1" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:115 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\.owncloudsync.log.1" to QLocalSocket(0x79350d0)
10-04 20:27:26:115 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\Desktop.ini" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:115 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\Desktop.ini" to QLocalSocket(0x79350d0)
10-04 20:27:26:115 [ info sync.engine ]:    #### Reconcile (aboutToPropagate OK) ####################################################  399 ms
10-04 20:27:26:115 [ debug sync.database ]  [ OCC::SyncJournalDb::commitInternal ]: Transaction commit  "post treewalk" and starting new transaction
10-04 20:27:26:115 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:    SQL exec "SELECT tmpfile, etag, errorcount, path FROM downloadinfo"
10-04 20:27:26:115 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:    SQL exec "SELECT path,transferid FROM uploadinfo"
10-04 20:27:26:115 [ debug sync.database ]  [ OCC::deleteBatch ]:   Removing stale  uploadinfo  entries:  "Bilder/HighPowerMode.png"
10-04 20:27:26:115 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 QVariant(QString, "Bilder/HighPowerMode.png")
10-04 20:27:26:115 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:    SQL exec "DELETE FROM uploadinfo WHERE path=?1"
10-04 20:27:26:115 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:    Last exec affected 1 rows.
10-04 20:27:26:115 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:    SQL exec "SELECT path FROM blacklist"
10-04 20:27:26:115 [ debug sync.database ]  [ OCC::SyncJournalDb::commitInternal ]: Transaction commit  "post stale entry removal" and starting new transaction
10-04 20:27:26:115 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:115 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync" to QLocalSocket(0x79350d0)
10-04 20:27:26:115 [ info sync.engine ]:    #### Post-Reconcile end ####################################################  400 ms
10-04 20:27:26:116 [ info gui.folder ]: #### Propagation start ####################################################
10-04 20:27:26:116 [ debug gui.socketapi ]  [ OCC::SocketApi::slotUpdateFolderView ]:   Not sending UPDATE_VIEW for "1" because status() is 3
10-04 20:27:26:121 [ info gui.application ]:    Sync state changed for folder  "https://[DomainRemoved]/cloudspeicher/remote.php/dav/files/KarstenS/" :  "Sync Running"
10-04 20:27:26:126 [ info sync.propagator ]:    Starting INSTRUCTION_IGNORE propagation of "Bilder/HighPowerMode.png" by OCC::PropagateIgnoreJob(0x6e7f2a8)
10-04 20:27:26:126 [ warning sync.propagator ]: Could not complete propagation of "Bilder/HighPowerMode.png" by OCC::PropagateIgnoreJob(0x6e7f2a8) with status OCC::SyncFileItem::BlacklistedError and error: "Server hat \"500 Internal Server Error\" auf \"PUT https://[DomainRemoved]/cloudspeicher/remote.php/dav/files/KarstenS/Bilder/HighPowerMode.png\" geantwortet (An exception occurred while executing 'SELECT SUM(`size`) AS f1, MIN(`size`) AS f2 FROM `oc_filecache` WHERE `parent` = ? AND `storage` = ?' with params [33, 1]:\n\nSQLSTATE[HY000]: General error: 2006 MySQL server has gone away) (Übersprungen aufgrund des früheren Fehlers, erneuter Versuch in 13 Sekunden)"
10-04 20:27:26:126 [ debug sync.statustracker ] [ OCC::SyncFileStatusTracker::slotItemCompleted ]:  Item completed "Bilder/HighPowerMode.png" OCC::SyncFileItem::BlacklistedError CSyncEnums::CSYNC_INSTRUCTION_IGNORE
10-04 20:27:26:126 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:126 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync" to QLocalSocket(0x79350d0)
10-04 20:27:26:126 [ debug sync.database.sql ]  [ OCC::SqlQuery::bindValue ]:   SQL bind 1 QVariant(qlonglong, -7866600945928434832)
10-04 20:27:26:126 [ 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"
10-04 20:27:26:126 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\Bilder" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:126 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync\\Bilder" to QLocalSocket(0x79350d0)
10-04 20:27:26:126 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:ERROR:E:\\Sync\\Bilder\\HighPowerMode.png" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:126 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:ERROR:E:\\Sync\\Bilder\\HighPowerMode.png" to QLocalSocket(0x79350d0)
10-04 20:27:26:126 [ debug sync.localdiscoverytracker ] [ OCC::LocalDiscoveryTracker::slotItemCompleted ]:  inserted error item "Bilder/HighPowerMode.png"
10-04 20:27:26:127 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:    SQL exec "SELECT path FROM conflicts"
10-04 20:27:26:127 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:    SQL exec "DELETE FROM flags WHERE path != '' AND path NOT IN (SELECT path from metadata);"
10-04 20:27:26:127 [ debug sync.database.sql ]  [ OCC::SqlQuery::exec ]:    Last exec affected 0 rows.
10-04 20:27:26:127 [ debug sync.database ]  [ OCC::SyncJournalDb::commitInternal ]: Transaction commit  "All Finished." 
10-04 20:27:26:128 [ info sync.engine ]:    Sync run took  412 ms
10-04 20:27:26:128 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:128 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync" to QLocalSocket(0x79350d0)
10-04 20:27:26:128 [ debug sync.localdiscoverytracker ] [ OCC::LocalDiscoveryTracker::slotSyncFinished ]:   sync failed, keeping last sync's local discovery path list
10-04 20:27:26:132 [ info gui.folder ]: Client version 2.6.3 (build 13551)  Qt 5.12.7  SSL  OpenSSL 1.1.1g  21 Apr 2020
10-04 20:27:26:132 [ info gui.folder ]: SyncEngine finished without problem.
10-04 20:27:26:133 [ info gui.folder ]: Folder sync result:  3
10-04 20:27:26:133 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:133 [ info gui.socketapi ]:  Sending SocketAPI message --> "STATUS:IGNORE:E:\\Sync" to QLocalSocket(0x79350d0)
10-04 20:27:26:133 [ info gui.socketapi ]:  Sending SocketAPI message --> "UPDATE_VIEW:E:\\Sync" to QLocalSocket(0x5a44fe8)
10-04 20:27:26:133 [ info gui.socketapi ]:  Sending SocketAPI message --> "UPDATE_VIEW:E:\\Sync" to QLocalSocket(0x5fc8710)
10-04 20:27:26:133 [ info gui.socketapi ]:  Sending SocketAPI message --> "UPDATE_VIEW:E:\\Sync" to QLocalSocket(0x79350d0)
10-04 20:27:26:136 [ info gui.application ]:    Sync state changed for folder  "https://[DomainRemoved]/cloudspeicher/remote.php/dav/files/KarstenS/" :  "Success, some files were ignored."
michaelstingl commented 4 years ago

10-04 20:27:26:126 [ warning sync.propagator ]: Could not complete propagation of "Bilder/HighPowerMode.png" by OCC::PropagateIgnoreJob(0x6e7f2a8) with status OCC::SyncFileItem::BlacklistedError and error: "Server hat \"500 Internal Server Error\" auf \"PUT https://[DomainRemoved]/cloudspeicher/remote.php/dav/files/KarstenS/Bilder/HighPowerMode.png\" geantwortet (An exception occurred while executing 'SELECT SUM(size) AS f1, MIN(size) AS f2 FROMoc_filecacheWHEREparent= ? ANDstorage= ?' with params [33, 1]:\n\nSQLSTATE[HY000]: General error: 2006 MySQL server has gone away) (Übersprungen aufgrund des früheren Fehlers, erneuter Versuch in 13 Sekunden)"

The actual PUT did not happen in this log. At 20:27:26 it says it will try again in 13 seconds. Better check the log after ~20:27:39 … You'll need the line that has the actual PUT for the HighPowerMode.png. There you'll also see the X-REQUEST-ID

KarstenS123 commented 4 years ago

This timestamp is in a new log file. I can't find a new try of uploading this file.

20201004_2027_owncloud.log

michaelstingl commented 4 years ago

Nope

% grep HighPowerMode 20201004_2027_owncloud.log | wc -l
       0

Upload again to another folder, and try to capture the initial PUT?

You could also try with the 2.7.0-beta5 client: https://owncloud.com/beta-testing/#desktop-beta

You can enable logs much easier in the settings, und it can capture full HTTP requests and responses:

CleanShot 2020-10-01 at 22 41 06@2x

[ATTENTION] Don't post logs containing such sensitive information in the public!!!

KarstenS123 commented 4 years ago

In another folder it synced the file without issue, but I forgot to log.

I'm currently very busy. Maybe I can do it at the coming weekend.

KarstenS123 commented 4 years ago

ownCloud-logdir.zip (Domain name replaced in the logs)

So I did a fresh try with 2 files.

Cleared up all logs, started OwnCloud desktop client, copied the files into one folder, where it successed and then into the folder where both files failed. After this I did quit the desktop client and prepared the logs for providing here.

I think the network traffic will noch really help. If you need some server logs, just ask. As I have full access to the server (I run my own hardware for it), I can get all informations that could help.