Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[2.0.1] Not possible to upload files: Connection Closed #3816

Closed
Ninos opened this issue Sep 11, 2015 · 87 comments
Closed

[2.0.1] Not possible to upload files: Connection Closed #3816

Ninos opened this issue Sep 11, 2015 · 87 comments
Assignees
Milestone

Comments

@Ninos
Copy link

Ninos commented Sep 11, 2015

Hey there,
since v2.0.1 I cannot upload large files anymore (updated yesterday). Before I had v1.8.4, I'm not sure, sry.

Here's my error log:

Exception: {"Message":"HTTP\/1.1 400 expected filesize 5242880 got 245760","Code":0,"Trace":"#0 \/htdocs\/lib\/private\/connector\/sabre\/file.php(100): OC\\Connector\\Sabre\\File->createFileChunked(Resource id #29)\n#1 \/htdocs\/lib\/private\/connector\/sabre\/directory.php(113): OC\\Connector\\Sabre\\File->put(Resource id #29)\n#2 \/htdocs\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(1053): OC\\Connector\\Sabre\\Directory->createFile('bigdata-2751...', Resource id #29)\n#3 \/htdocs\/3rdparty\/sabre\/dav\/lib\/DAV\/CorePlugin.php(513): Sabre\\DAV\\Server->createFile('Documents/Fol...', Resource id #29, NULL)\n#4 [internal function]: Sabre\\DAV\\CorePlugin->httpPut(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#5 \/htdocs\/3rdparty\/sabre\/event\/lib\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#6 \/htdocs\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(469): Sabre\\Event\\EventEmitter->emit('method:PUT', Array)\n#7 \/htdocs\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#8 \/htdocs\/apps\/files\/appinfo\/remote.php(83): Sabre\\DAV\\Server->exec()\n#9 \/htdocs\/remote.php(132): require_once('\/var\/www\/virtua...')\n#10 {main}","File":"\/htdocs\/lib\/private\/connector\/sabre\/file.php","Line":347}

ownCloud: v8.1.1
PHP: v5.6
OS: Debian Jessie
DB: MariaDB
Client OS: Windows 8.1 x64

@guruz
Copy link
Contributor

guruz commented Sep 11, 2015

Could you run the client with OWNCLOUD_MAX_PARALLEL=1 owncloud --logfile - and check what happens client side when uploading? (and possible paste here..)
Do you really get this HTTP/1.1 400?

@guruz guruz added this to the 2.0.2-next milestone Sep 11, 2015
@Ninos
Copy link
Author

Ninos commented Sep 11, 2015

How is it possible to run the client with OWNCLOUD_MAX_PARALLEL=1 owncloud --logfile -?

Edit: Yes I really get HTTP/1.1 400
Edit2: I also got following error, but I'm not sure, if relevant to that bug:
Array to string conversion at /htdocs/lib/private/template/functions.php#36

@guruz
Copy link
Contributor

guruz commented Sep 11, 2015

@Ninos Did you also update the server?

@Ninos Sorry, thought you were on Linux on the client.. on windows you could start the client as owncloud.exe --logwindow.

@icewind1991 @PVince81 Is that any known server bug?

@Ninos
Copy link
Author

Ninos commented Sep 11, 2015

Yes server is up2date. Not the last few days I just updated gitlab, no other packages were updated. And I need to correct my issue report. Also other files cannot be uploaded anymore. I think it's because of the connection. Here's my log (hope I found the important part):

09-11 21:43:52:892 0x6a2bbe8 OCC::DiscoveryJob::remote_vio_opendir_hook: static csync_vio_handle_t* OCC::DiscoveryJob::remote_vio_opendir_hook(const char*, void*) OCC::DiscoveryJob(0x77cbd98)  Calling into main thread...
09-11 21:43:55:017 0x44877b0 OCC::AbstractNetworkJob::start: !!! OCC::LsColJob created for "https://example.tld" + "Folder"
09-11 21:43:54:330 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_error(QAbstractSocket::SocketError) QAbstractSocket::RemoteHostClosedError QSslSocket(0x6ab2910) QObject(0x0)  0 false 3 0 QAbstractSocket::ConnectedState
09-11 21:43:54:330 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_disconnected() 0 QSslSocket(0x6ab2910) QObject(0x0)  0 false 3 0
09-11 21:43:56:277 0x44877b0 OCC::DiscoveryMainThread::singleDirectoryJobFirstDirectoryPermissionsSlot: Permissions for root dir: "RDNVCK"
09-11 21:43:56:277 0x44877b0 OCC::SyncEngine::slotRootEtagReceived: void OCC::SyncEngine::slotRootEtagReceived(QString) ""55ef76664a686""55db27e5ad91a""55ab8d5dd7376""55ab8d5eab6a1""55ab8d607cc0f""55ab8d619a4f4""55ea18294ed84""55b1ff94ec886""55ef766656cb0""55e719ae27852""55ac64a8d506a""
09-11 21:43:56:277 0x44877b0 OCC::Folder::etagRetreivedFromSyncEngine: Root etag from during sync: ""55ef76664a686""55db27e5ad91a""55ab8d5dd7376""55ab8d5eab6a1""55ab8d607cc0f""55ab8d619a4f4""55ea18294ed84""55b1ff94ec886""55ef766656cb0""55e719ae27852""55ac64a8d506a""
09-11 21:43:56:277 0x44877b0 OCC::DiscoveryMainThread::singleDirectoryJobResultSlot: void OCC::DiscoveryMainThread::singleDirectoryJobResultSlot(const QList<OCC::FileStatPointer>&) Have 10 results for  "Folder"
09-11 21:43:56:277 0x6a2bbe8 OCC::DiscoveryJob::remote_vio_opendir_hook: static csync_vio_handle_t* OCC::DiscoveryJob::remote_vio_opendir_hook(const char*, void*) OCC::DiscoveryJob(0x77cbd98)  ...Returned from main thread
09-11 21:43:57:214 0x6a2bbe8 csync_walker: directory: ownclouds://example.tld/remote.php/webdav/Folder/subfolder6 [file_id=00003386oc68s9z6nqfw]
09-11 21:43:57:214 0x6a2bbe8 _csync_detect_update: Database entry found, compare: 1437361320 <-> 1437361320, etag: 55ac64a8d506a <-> 55ac64a8d506a, inode: 0 <-> 474291, size: 0 <-> 0, perms: RDNVCK <-> RDNVCK, ignore: 0
09-11 21:43:57:214 0x6a2bbe8 _csync_detect_update: Reading from database: Verträge
09-11 21:43:57:214 0x6a2bbe8 _csync_detect_update: file: Verträge, instruction: INSTRUCTION_NONE <<=
09-11 21:43:57:230 0x6a2bbe8 csync_statedb_get_below_path: 8 entries read below path Verträge from db.
09-11 21:43:57:230 0x6a2bbe8 OCC::DiscoveryJob::remote_vio_closedir_hook: static void OCC::DiscoveryJob::remote_vio_closedir_hook(csync_vio_handle_t*, void*) OCC::DiscoveryJob(0x77cbd98) "Folder"
09-11 21:43:57:230 0x6a2bbe8 csync_ftw:  <= Closing walk for ownclouds://example.tld/remote.php/webdav/Folder with read_from_db 0
09-11 21:43:57:230 0x6a2bbe8 csync_update: Update detection for remote replica took 4.34 seconds walking 2375 files.
09-11 21:43:57:230 0x6a2bbe8 csync_statedb_close: sqlite3_close=0
09-11 21:43:57:230 0x44877b0 OCC::SyncEngine::slotDiscoveryJobFinished: <<#### Discovery end ####################################################  5850
09-11 21:43:57:230 0x44877b0 csync_statedb_load: sqlite3 version "3.8.8.1"
09-11 21:43:57:230 0x44877b0 csync_statedb_load: Success
09-11 21:43:57:230 0x44877b0 _csync_merge_algorithm_visitor: INSTRUCTION_NONE     client dir:  Packages/subfolder5
09-11 21:43:58:892 0x44877b0 csync_reconcile: Reconciliation for remote replica took 0.88 seconds visiting 2375 files.
09-11 21:43:58:892 0x44877b0 csync_statedb_close: sqlite3_close=0
09-11 21:43:58:892 0x44877b0 OCC::SyncEngine::slotDiscoveryJobFinished: <<#### Reconcile end ####################################################  7520
09-11 21:43:58:892 0x44877b0 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:SYNC:C:\Users\User\Documents\Folder\subfolder3\~file.tmp"
09-11 21:43:58:907 0x44877b0 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:SYNC:C:\Users\User\Documents\Folder\subfolder4\~file.tmp"
09-11 21:43:58:923 0x44877b0 OCC::SyncEngine::slotDiscoveryJobFinished: Permissions of the root folder:  "RDNVCK"
09-11 21:43:58:923 0x44877b0 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "post treewalk" and starting new transaction
09-11 21:43:58:923 0x44877b0 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "post stale entry removal" and starting new transaction
09-11 21:43:58:923 0x44877b0 OCC::OwncloudPropagator::start: Using QNAM/HTTP parallel code path
09-11 21:43:58:923 0x44877b0 OCC::SyncEngine::slotDiscoveryJobFinished: <<#### Post-Reconcile end ####################################################  7553
09-11 21:43:58:986 0x44877b0 OCC::Folder::slotSyncStarted: #### Propagation start #################################################### >>
09-11 21:43:58:986 0x44877b0 OCC::SocketApi::slotUpdateFolderView: Not sending UPDATE_VIEW for "Folder" because status() is 3
09-11 21:43:58:986 0x44877b0 OCC::ownCloudGui::slotSyncStateChange: Sync state changed for folder  "Folder" :  "Sync Running"
09-11 21:43:59:052 0x44877b0 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "subfolder2/.svn" INSTRUCTION_IGNORE 6 "File is ignored because it's hidden."
09-11 21:43:59:052 0x44877b0 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:ERROR:C:\Users\User\Documents\Folder\subfolder2\.svn"
09-11 21:43:59:053 0x44877b0 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "subfolder2/.svn" INSTRUCTION_IGNORE 6 "File is ignored because it's hidden."
09-11 21:43:59:054 0x44877b0 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:ERROR:C:\Users\User\Documents\Folder\subfolder2\.svn"
09-11 21:43:59:057 0x44877b0 OCC::PropagateUploadFileQNAM::startNextChunk: Upload chunk 0 of 41 transferid(remote)= 4076157294
09-11 21:43:59:065 0x44877b0 OCC::AbstractNetworkJob::start: !!! OCC::PUTFileJob created for "https://example.tld" + "Folder/file.zip-chunking-4076157294-41-0"
09-11 21:43:59:065 0x44877b0 OCC::PropagateUploadFileQNAM::startNextChunk: Upload chunk 1 of 41 transferid(remote)= 4076157294
09-11 21:43:59:074 0x44877b0 OCC::AbstractNetworkJob::start: !!! OCC::PUTFileJob created for "https://example.tld" + "Folder/file.zip-chunking-4076157294-41-1"
09-11 21:43:59:075 0x44877b0 OCC::PropagateUploadFileQNAM::startNextChunk: Upload chunk 2 of 41 transferid(remote)= 4076157294
09-11 21:43:59:084 0x44877b0 OCC::AbstractNetworkJob::start: !!! OCC::PUTFileJob created for "https://example.tld" + "Folder/file.zip-chunking-4076157294-41-2"
09-11 21:43:59:713 0x44877b0 unknown: Failed to resolve EGL function eglGetPlatformDisplayEXT (Die angegebene Prozedur wurde nicht gefunden.)
09-11 21:43:59:713 0x44877b0 unknown: static QWindowsEGLStaticContext* QWindowsEGLStaticContext::create(): Could not initialize EGL display: error 0x3001

09-11 21:43:59:713 0x44877b0 unknown: static QWindowsEGLStaticContext* QWindowsEGLStaticContext::create(): When using ANGLE, check if d3dcompiler_4x.dll is available
09-11 21:43:59:767 0x44877b0 unknown: Failed to resolve EGL function eglGetPlatformDisplayEXT (Die angegebene Prozedur wurde nicht gefunden.)
09-11 21:43:59:767 0x44877b0 unknown: static QWindowsEGLStaticContext* QWindowsEGLStaticContext::create(): Could not initialize EGL display: error 0x3001

09-11 21:43:59:767 0x44877b0 unknown: static QWindowsEGLStaticContext* QWindowsEGLStaticContext::create(): When using ANGLE, check if d3dcompiler_4x.dll is available
09-11 21:44:04:166 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_error(QAbstractSocket::SocketError) QAbstractSocket::RemoteHostClosedError QSslSocket(0x9a13010) QHttpNetworkReply(0x77c5290) 1465 false 3 2 QAbstractSocket::ConnectedState
09-11 21:44:04:166 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_disconnected() 0 QSslSocket(0x9a13010) QHttpNetworkReply(0x77c5290) 1465 true 2 2
09-11 21:44:04:335 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_error(QAbstractSocket::SocketError) QAbstractSocket::RemoteHostClosedError QSslSocket(0x9a12cf0) QHttpNetworkReply(0x77c57a0) 1465 false 3 2 QAbstractSocket::ConnectedState
09-11 21:44:04:335 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_disconnected() 0 QSslSocket(0x9a12cf0) QHttpNetworkReply(0x77c57a0) 1465 true 2 2
09-11 21:44:08:818 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_error(QAbstractSocket::SocketError) QAbstractSocket::RemoteHostClosedError QSslSocket(0x9a12cf0) QHttpNetworkReply(0x77c57a0) 1465 false 2 2 QAbstractSocket::ConnectedState
09-11 21:44:08:819 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_disconnected() 0 QSslSocket(0x9a12cf0) QHttpNetworkReply(0x77c57a0) 1465 true 1 2
09-11 21:44:08:898 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_error(QAbstractSocket::SocketError) QAbstractSocket::RemoteHostClosedError QSslSocket(0x9a13010) QHttpNetworkReply(0x77c5290) 1465 false 2 2 QAbstractSocket::ConnectedState
09-11 21:44:08:898 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_disconnected() 0 QSslSocket(0x9a13010) QHttpNetworkReply(0x77c5290) 1465 true 1 2
09-11 21:44:11:863 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_error(QAbstractSocket::SocketError) QAbstractSocket::RemoteHostClosedError QSslSocket(0x9a13010) QHttpNetworkReply(0x77c5290) 1465 false 1 2 QAbstractSocket::ConnectedState
09-11 21:44:11:863 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_disconnected() 0 QSslSocket(0x9a13010) QHttpNetworkReply(0x77c5290) 1465 true 0 2
09-11 21:44:12:363 0x44877b0 OCC::ConnectionValidator::checkAuthentication: # Check whether authenticated propfind works.
09-11 21:44:12:363 0x44877b0 OCC::AbstractNetworkJob::start: !!! OCC::PropfindJob created for "https://example.tld" + "/"
09-11 21:44:13:490 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_error(QAbstractSocket::SocketError) QAbstractSocket::RemoteHostClosedError QSslSocket(0x9a12cf0) QHttpNetworkReply(0x77c57a0) 1465 false 1 2 QAbstractSocket::ConnectedState
09-11 21:44:13:490 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_disconnected() 0 QSslSocket(0x9a12cf0) QHttpNetworkReply(0x77c57a0) 1465 true 0 2
09-11 21:44:14:629 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_error(QAbstractSocket::SocketError) QAbstractSocket::RemoteHostClosedError QSslSocket(0x9a13010) QHttpNetworkReply(0x77c5290) 1465 false 0 2 QAbstractSocket::ConnectedState
09-11 21:44:14:629 0x776e150 unknown: ERRORING CURRENT QHttpNetworkReply(0x77c5290)  QUrl( "https://example.tld/remote.php/webdav/Folder/file.zip-chunking-4076157294-41-1" ) 
09-11 21:44:14:629 0x44877b0 OCC::AbstractNetworkJob::slotFinished: void OCC::AbstractNetworkJob::slotFinished() 2 "Verbindung beendet" QVariant(Invalid)
09-11 21:44:14:629 0x44877b0 OCC::PropagateUploadFileQNAM::slotPutFinished: void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://example.tld/remote.php/webdav/Folder/file.zip-chunking-4076157294-41-1" )  FINISHED WITH STATUS 2 "Verbindung beendet" QVariant(Invalid) QVariant(Invalid)
09-11 21:44:14:645 0x44877b0 OCC::PropagateUploadFileQNAM::slotPutFinished: ""
09-11 21:44:14:645 0x44877b0 OCC::PropagateUploadFileQNAM::abort: virtual void OCC::PropagateUploadFileQNAM::abort() OCC::PUTFileJob(0x9aa0a68) "file.zip"
09-11 21:44:14:645 0x44877b0 OCC::AbstractNetworkJob::slotFinished: void OCC::AbstractNetworkJob::slotFinished() 5 "Operation abgebrochen" QVariant(Invalid)
09-11 21:44:14:645 0x44877b0 OCC::PropagateUploadFileQNAM::slotPutFinished: void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://example.tld/remote.php/webdav/Folder/file.zip-chunking-4076157294-41-0" )  FINISHED WITH STATUS 5 "Operation abgebrochen" QVariant(Invalid) QVariant(Invalid)
09-11 21:44:14:645 0x44877b0 OCC::PropagateUploadFileQNAM::abort: virtual void OCC::PropagateUploadFileQNAM::abort() OCC::PUTFileJob(0x9aa0630) "file.zip"
09-11 21:44:14:645 0x44877b0 OCC::AbstractNetworkJob::slotFinished: void OCC::AbstractNetworkJob::slotFinished() 5 "Operation abgebrochen" QVariant(Invalid)
09-11 21:44:14:645 0x44877b0 OCC::PropagateUploadFileQNAM::slotPutFinished: void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://example.tld/remote.php/webdav/Folder/file.zip-chunking-4076157294-41-2" )  FINISHED WITH STATUS 5 "Operation abgebrochen" QVariant(Invalid) QVariant(Invalid)
09-11 21:44:14:645 0x44877b0 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "file.zip" INSTRUCTION_SYNC 1 "Verbindung beendet"
09-11 21:44:14:645 0x44877b0 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:ERROR:C:\Users\User\Documents\Folder\subfolder\file.zip"
09-11 21:44:14:629 0x776e150 unknown: ERRORING OTHER QHttpNetworkReply(0xa43da80)  QUrl( "https://example.tld/remote.php/webdav/" ) 
09-11 21:44:14:645 0x44877b0 OCC::AbstractNetworkJob::slotFinished: void OCC::AbstractNetworkJob::slotFinished() 2 "Verbindung beendet" QVariant(Invalid)
09-11 21:44:14:645 0x44877b0 OCC::AccountState::slotConnectionValidatorResult: AccountState connection status change:  "Connected" -> "Timeout"
09-11 21:44:14:645 0x44877b0 OCC::AccountState::setState: AccountState state change:  "Verbunden" -> "Netzwerkfehler"
09-11 21:44:14:645 0x44877b0 OCC::AccountSettings::showConnectionLabel: "No connection to ownCloud at <a href="https://example.tld">https://example.tld</a>.
Verbindung beendet"
09-11 21:44:14:645 0x44877b0 OCC::FolderMan::slotAccountStateChanged: Account "[email protected]" disconnected, terminating or descheduling sync folders
09-11 21:44:14:645 0x44877b0 OCC::Folder::slotTerminateSync: folder  "Folder"  Terminating!
09-11 21:44:14:645 0x44877b0 OCC::SyncEngine::abort: void OCC::SyncEngine::abort() OCC::DiscoveryMainThread(0x78815b0)
09-11 21:44:14:645 0x44877b0 OCC::PropfindJob::finished: PROPFIND request *not* successful, http result code is 0 ""
09-11 21:44:14:629 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_disconnected() 0 QSslSocket(0x9a13010) QObject(0x0)  1465 false -1 16
09-11 21:44:14:645 0x776e150 unknown: void QHttpNetworkConnectionChannel::close() QSslSocket(0x6ab2910) 2 QObject(0x0) 
09-11 21:44:14:645 0x776e150 unknown: QIODevice::write: device not open
09-11 21:44:14:645 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_error(QAbstractSocket::SocketError) QAbstractSocket::RemoteHostClosedError QSslSocket(0x6ab2910) QObject(0x0)  0 false 3 16 QAbstractSocket::ClosingState
09-11 21:44:14:645 0x776e150 unknown: void QHttpNetworkConnectionChannel::close() QSslSocket(0x9a12cf0) 2 QObject(0x0) 
09-11 21:44:14:645 0x776e150 unknown: QIODevice::write: device not open
09-11 21:44:14:645 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_error(QAbstractSocket::SocketError) QAbstractSocket::RemoteHostClosedError QSslSocket(0x9a12cf0) QObject(0x0)  0 false 0 16 QAbstractSocket::ClosingState
09-11 21:44:14:661 0x44877b0 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "subfolder" INSTRUCTION_SYNC 0 ""
09-11 21:44:14:661 0x44877b0 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:OK:C:\Users\User\Documents\Folder\subfolder"
09-11 21:44:14:661 0x44877b0 OCC::SyncJournalDb::walCheckpoint: void OCC::SyncJournalDb::walCheckpoint() took 0 msec
09-11 21:44:14:676 0x44877b0 OCC::SyncJournalDb::commitInternal: void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "All Finished." 
09-11 21:44:14:676 0x44877b0 OCC::SyncEngine::finalize: CSync run took  23295
09-11 21:44:14:676 0x44877b0 OCC::BandwidthManager::~BandwidthManager: virtual OCC::BandwidthManager::~BandwidthManager()
09-11 21:44:14:676 0x44877b0 OCC::Folder::slotSyncFinished:  - client version 2.0.1 (build 5446)  Qt 5.4.0  SSL  OpenSSL 1.0.2d 9 Jul 2015
09-11 21:44:14:676 0x44877b0 OCC::Folder::slotSyncFinished: -> SyncEngine finished with ERROR, warn count is 20
09-11 21:44:14:676 0x44877b0 OCC::Folder::bubbleUpSyncResult: Processing result list and logging took  5  Milliseconds.
09-11 21:44:14:692 0x44877b0 OCC::Folder::bubbleUpSyncResult: OO folder slotSyncFinished: result:  4
09-11 21:44:14:692 0x44877b0 OCC::Folder::slotSyncFinished:   ** error Strings:  ("Verbindung beendet", "file.zip: Verbindung beendet")
09-11 21:44:14:692 0x44877b0 OCC::Folder::slotSyncFinished:     * owncloud csync thread finished with error
09-11 21:44:14:692 0x44877b0 OCC::Folder::slotSyncFinished: the last 1 syncs failed
09-11 21:44:14:692 0x44877b0 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:ERROR:C:\Users\User\Documents\Folder\"
09-11 21:44:14:692 0x44877b0 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "UPDATE_VIEW:C:\Users\User\Documents\Folder\"
09-11 21:44:14:692 0x44877b0 OCC::ownCloudGui::slotSyncStateChange: Sync state changed for folder  "Folder" :  "Error"
09-11 21:44:14:703 0x44877b0 OCC::FolderWatcher::pathIsIgnored: * Discarded as is hidden! "C:/Users/User/Documents/Folder/.owncloudsync.log"
09-11 21:44:14:726 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_disconnected() 0 QSslSocket(0x6ab2910) QObject(0x0)  0 false 2 16
09-11 21:44:14:892 0x44877b0 OCC::FolderMan::slotFolderSyncFinished: <===================================== sync finished for  "Folder"
09-11 21:44:18:043 0x776e150 unknown: void QHttpNetworkConnectionChannel::_q_disconnected() 0 QSslSocket(0x9a12cf0) QObject(0x0)  0 false -1 16
09-11 21:44:30:396 0x44877b0 unknown: Failed to resolve EGL function eglGetPlatformDisplayEXT (Die angegebene Prozedur wurde nicht gefunden.)
09-11 21:44:30:398 0x44877b0 unknown: static QWindowsEGLStaticContext* QWindowsEGLStaticContext::create(): Could not initialize EGL display: error 0x3001

09-11 21:44:30:399 0x44877b0 unknown: static QWindowsEGLStaticContext* QWindowsEGLStaticContext::create(): When using ANGLE, check if d3dcompiler_4x.dll is available

@rmoesbergen
Copy link

Adding a 'me too'. I get the same 'connection closed' errors and then the client crashes with:

09-12 10:50:12:531 0x1051970 ASSERT: "!_runningNow" in file /usr/src/packages/BUILD/src/libsync/owncloudpropagator.cpp, line 633

If I run it with OWNCLOUD_MAX_PARALLEL=1 it works again and file are uploaded as usual.

Client version 2.0.0 worked fine, broke after upgrading to 2.0.1

@Ninos Ninos changed the title Not possible to upload large files (v2.0.1) Not possible to upload files (v2.0.1) Sep 12, 2015
@Ninos
Copy link
Author

Ninos commented Sep 12, 2015

Small update: v2.0.0 is also not working. v1.8.4 is working fine.

@guruz
Copy link
Contributor

guruz commented Sep 13, 2015

@moesbergen which client OS?

Did you compile the ownCloud client yourself?

If you enable HTTP keep alive in your server (EnableKeepAlive true, KeepAliveTimeout and KeepAliveRequests high values) does that change anything?

@rmoesbergen
Copy link

I run Linux Mint 17.2. I did not compile the client myself, I added the owncloud ubuntu repo to apt-get and installed it.

The server already has keepalive enabled:
KeepAlive On
MaxKeepAliveRequests 100
KeepAliveTimeout 5

@guruz
Copy link
Contributor

guruz commented Sep 15, 2015

@rmoesbergen Can you also check the owncloud.log? (set to debug mode)

@guruz guruz changed the title Not possible to upload files (v2.0.1) [2.0.1] Not possible to upload files: Connection Closed Sep 15, 2015
@guruz guruz added the type:bug label Sep 15, 2015
@guruz
Copy link
Contributor

guruz commented Sep 15, 2015

@rmoesbergen You also see it only for uploads, not downloads?

@rmoesbergen
Copy link

Yes, it happens only with uploads, and only with large uploads that need to be 'chunked'. Small files upload just fine.

The owncloud log on the server side gives this error when uploads fail:

Exception: {"Message":"HTTP/1.1 400 expected filesize 5242880 got 2195456","Code":0,"Trace":"#0 /var/www/owncloud/lib/private/connector/sabre/file.php(100): OC\Connector\Sabre\File->createFileChunked(Resource id #26)\n#1 /var/www/owncloud/lib/private/connector/sabre/directory.php(113): OC\Connector\Sabre\File->put(Resource id #26)\n#2 /var/www/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php(1053): OC\Connector\Sabre\Directory->createFile('Sent-1-chunking...', Resource id #26)\n#3 /var/www/owncloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php(513): Sabre\DAV\Server->createFile('Documents/Mail/...', Resource id #26, NULL)\n#4 [internal function]: Sabre\DAV\CorePlugin->httpPut(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))\n#5 /var/www/owncloud/3rdparty/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#6 /var/www/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php(469): Sabre\Event\EventEmitter->emit('method:PUT', Array)\n#7 /var/www/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php(254): Sabre\DAV\Server->invokeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))\n#8 /var/www/owncloud/apps/files/appinfo/remote.php(83): Sabre\DAV\Server->exec()\n#9 /var/www/owncloud/remote.php(132): require_once('/var/www/ownclo...')\n#10 {main}","File":"/var/www/owncloud/lib/private/connector/sabre/file.php","Line":347}

Server version 8.1.1

@guruz
Copy link
Contributor

guruz commented Sep 16, 2015

Could you guys check the settings mentioned here: https://doc.owncloud.org/server/8.0/admin_manual/configuration_files/big_file_upload_configuration.html#apache

Does changing SSLRenegBufferSize and the other ones (and restarting Apache) change anything?

@Ninos
Copy link
Author

Ninos commented Sep 16, 2015

For me it's not possible to add the Option SSLRenegBufferSize. I'm using Debian Jessie with apache2.4 and mostly the default settings. I do not only have problems with uploading large files, I generally have problems with uploading files, also files which have a size of some kilobytes.

@guruz
Copy link
Contributor

guruz commented Sep 16, 2015

@Ninos It could still be related to SSLRenegBufferSize since multiple files are sent sequentially down one connection..
Do you have anything in Apache's error.log?
Or something else in owncloud.log

@guruz
Copy link
Contributor

guruz commented Sep 16, 2015

@RealRancor @icewind1991 @PVince81 We need some help here with regards to HTTP\/1.1 400 expected filesize 5242880 got 245760.. thanks

@ckamm ckamm modified the milestones: 2.1-next, 2.0.2-current Sep 17, 2015
@PVince81
Copy link
Contributor

@guruz this usually means that the bytes read from the request body are less than the size specified in the Content-Length header. Something (proxy or web server module ?) might be messing with the content before it reaches the ownCloud server code.

@stonerl
Copy link

stonerl commented Sep 18, 2015

I do have the same issue. In my case it was a 27MB file (the owncloud client for OSX).

Error downloading https://server.org/remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-1634413200-6-0 - server replied: Bad Request (expected filesize 5242880 got 0)

and this:

screen shot 2015-09-18 at 14 56 30

I have this error in the owncloud logs when an upload does not succeed:

{"reqId":"gwbYDZ8rnSJwGKhFAqLp","remoteAddr":"95.208.175.100","app":"webdav","message":"Exception: {\"Message\":\"HTTP\\\/1.1 400 expected filesize 5242880 got 0\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php(100): OC\\\\Connector\\\\Sabre\\\\File->createFileChunked(Resource id #34)\\n#1 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/directory.php(113): OC\\\\Connector\\\\Sabre\\\\File->put(Resource id #34)\\n#2 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1053): OC\\\\Connector\\\\Sabre\\\\Directory->createFile('ownCloud-2.0.1....', Resource id #34)\\n#3 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(513): Sabre\\\\DAV\\\\Server->createFile('Documents\\\/ownCl...', Resource id #34, NULL)\\n#4 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#5 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#6 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(469): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#7 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#8 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files\\\/appinfo\\\/remote.php(83): Sabre\\\\DAV\\\\Server->exec()\\n#9 \\\/var\\\/www\\\/owncloud\\\/remote.php(132): require_once('\\\/var\\\/www\\\/ownclo...')\\n#10 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php\",\"Line\":346}","level":4,"time":"2015-09-18T14:55:59+02:00"}

Problem though I cannot reproduce this reliable. I just restarted my Server and now the files upload.

@stonerl
Copy link

stonerl commented Sep 18, 2015

Here are the logs from apache regarding this file:

[18/Sep/2015:14:54:45 +0200] "PUT /remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-1634413200-6-0 HTTP/1.1" 400 1128 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:14:54:45 +0200] "PUT /remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-1634413200-6-1 HTTP/1.1" 400 1128 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:14:54:46 +0200] "PUT /remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-1634413200-6-2 HTTP/1.1" 400 1128 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:14:59:38 +0200] "PUT /remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-462914568-6-2 HTTP/1.1" 400 986 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:14:59:38 +0200] "PUT /remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-462914568-6-0 HTTP/1.1" 400 1128 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:14:59:38 +0200] "PUT /remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-462914568-6-1 HTTP/1.1" 400 1128 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:01:38 +0200] "PUT /remote.php/webdav/Videos/ownCloud-2.0.1.2694.pkg-chunking-2036920002-6-0 HTTP/1.1" 201 756 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:02:10 +0200] "PUT /remote.php/webdav/Videos/ownCloud-2.0.1.2694.pkg-chunking-2036920002-6-3 HTTP/1.1" 201 756 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:02:42 +0200] "PUT /remote.php/webdav/Videos/ownCloud-2.0.1.2694.pkg-chunking-2036920002-6-4 HTTP/1.1" 201 756 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:01:39 +0200] "PUT /remote.php/webdav/Videos/ownCloud-2.0.1.2694.pkg-chunking-2036920002-6-2 HTTP/1.1" 201 899 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:01:39 +0200] "PUT /remote.php/webdav/Videos/ownCloud-2.0.1.2694.pkg-chunking-2036920002-6-1 HTTP/1.1" 201 899 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:03:21 +0200] "PUT /remote.php/webdav/Videos/ownCloud-2.0.1.2694.pkg-chunking-2036920002-6-5 HTTP/1.1" 201 895 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:04:11 +0200] "PUT /remote.php/webdav/Music/ownCloud-2.0.1.2694.pkg-chunking-498813522-6-0 HTTP/1.1" 201 756 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:04:41 +0200] "PUT /remote.php/webdav/Music/ownCloud-2.0.1.2694.pkg-chunking-498813522-6-3 HTTP/1.1" 201 756 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:05:12 +0200] "PUT /remote.php/webdav/Music/ownCloud-2.0.1.2694.pkg-chunking-498813522-6-4 HTTP/1.1" 201 756 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:04:11 +0200] "PUT /remote.php/webdav/Music/ownCloud-2.0.1.2694.pkg-chunking-498813522-6-1 HTTP/1.1" 201 899 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:04:12 +0200] "PUT /remote.php/webdav/Music/ownCloud-2.0.1.2694.pkg-chunking-498813522-6-2 HTTP/1.1" 201 899 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:05:52 +0200] "PUT /remote.php/webdav/Music/ownCloud-2.0.1.2694.pkg-chunking-498813522-6-5 HTTP/1.1" 201 895 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:06:28 +0200] "PUT /remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-1654354355-6-2 HTTP/1.1" 201 899 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:06:28 +0200] "PUT /remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-1654354355-6-1 HTTP/1.1" 201 899 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:06:28 +0200] "PUT /remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-1654354355-6-0 HTTP/1.1" 201 899 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"
[18/Sep/2015:15:07:28 +0200] "PUT /remote.php/webdav/Documents/ownCloud-2.0.1.2694.pkg-chunking-1654354355-6-3 HTTP/1.1" 201 756 "-" "Mozilla/5.0 (Macintosh) mirall/2.0.1"

This is the owncloud.log for another file that could not get uploaded:

09-18 15:54:47:070 0x7fa850d21f60 OCC::SocketApi::command_RETRIEVE_FILE_STATUS: void OCC::SocketApi::command_RETRIEVE_FILE_STATUS(const QString &, QIODevice *) "/Users/toni/Documents/production.sqlite3"
09-18 15:54:47:070 0x7fa850d21f60 OCC::SocketApi::fileStatus: OCC::SyncFileStatus OCC::SocketApi::fileStatus(OCC::Folder *, const QString &, c_strlist_t *) Could not determine state for file "production.sqlite3" will set STATUS_NEW
09-18 15:54:47:071 0x7fa850d21f60 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:NEW:/Users/toni/Documents/production.sqlite3"
09-18 15:54:57:259 0x7fa852081380 csync_walker: file: /Users/toni/Documents/production.sqlite3 [inode=29394046 size=129106944]
09-18 15:54:57:260 0x7fa852081380 _csync_detect_update: file: production.sqlite3, instruction: INSTRUCTION_NEW <<=
09-18 15:55:01:353 0x7fa850d21f60 _csync_merge_algorithm_visitor: INSTRUCTION_NEW      client file: production.sqlite3
09-18 15:55:02:490 0x7fa850d21f60 OCC::SyncEngine::checkErrorBlacklisting: blacklist entry for  "production.sqlite3"  has expired!
09-18 15:55:02:490 0x7fa850d21f60 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:SYNC:/Users/toni/Documents/production.sqlite3"
09-18 15:55:02:490 0x7fa850d21f60 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:SYNC:/Users/toni/Documents/production.sqlite3"
09-18 15:55:02:491 0x7fa850d21f60 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:SYNC:/Users/toni/Documents/production.sqlite3"
09-18 15:55:02:492 0x7fa850d21f60 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:SYNC:/Users/toni/Documents/production.sqlite3"
09-18 15:55:02:682 0x7fa850d21f60 OCC::PropagateUploadFileQNAM::slotStartUpload: void OCC::PropagateUploadFileQNAM::slotStartUpload(const QByteArray &) "production.sqlite3" : Resuming from chunk  10
09-18 15:55:02:690 0x7fa850d21f60 OCC::AbstractNetworkJob::start: !!! OCC::PUTFileJob created for "https://myserver.org" + "/Documents/production.sqlite3-chunking-304999483-25-10"
09-18 15:55:02:697 0x7fa850d21f60 OCC::AbstractNetworkJob::start: !!! OCC::PUTFileJob created for "https://myserver.org" + "/Documents/production.sqlite3-chunking-304999483-25-11"
09-18 15:55:02:704 0x7fa850d21f60 OCC::AbstractNetworkJob::start: !!! OCC::PUTFileJob created for "https://myserver.org" + "/Documents/production.sqlite3-chunking-304999483-25-12"
09-18 15:56:00:233 0x7fa850d21f60 OCC::PropagateUploadFileQNAM::slotPutFinished: void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-10" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created")
09-18 15:56:00:233 0x7fa850d21f60 OCC::SyncJournalDb::setUploadInfo: "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ?1 , ?2, ?3 , ?4 ,  ?5, ?6 )" "production.sqlite3" 11 310242363 0
09-18 15:56:00:262 0x7fa850d21f60 OCC::AbstractNetworkJob::start: !!! OCC::PUTFileJob created for "https://myserver.org" + "/Documents/production.sqlite3-chunking-304999483-25-13"
09-18 15:57:01:018 0x7fa850d21f60 OCC::PropagateUploadFileQNAM::slotPutFinished: void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-11" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created")
09-18 15:57:01:018 0x7fa850d21f60 OCC::SyncJournalDb::setUploadInfo: "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ?1 , ?2, ?3 , ?4 ,  ?5, ?6 )" "production.sqlite3" 12 310242363 0
09-18 15:57:01:043 0x7fa850d21f60 OCC::AbstractNetworkJob::start: !!! OCC::PUTFileJob created for "https://myserver.org" + "/Documents/production.sqlite3-chunking-304999483-25-14"
09-18 15:57:07:626 0x7fa850d21f60 OCC::PropagateUploadFileQNAM::slotPutFinished: void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-13" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created")
09-18 15:57:07:626 0x7fa850d21f60 OCC::SyncJournalDb::setUploadInfo: "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ?1 , ?2, ?3 , ?4 ,  ?5, ?6 )" "production.sqlite3" 12 310242363 0
09-18 15:57:07:643 0x7fa850d21f60 OCC::AbstractNetworkJob::start: !!! OCC::PUTFileJob created for "https://myserver.org" + "/Documents/production.sqlite3-chunking-304999483-25-15"
09-18 15:57:09:881 0x7fa850d21f60 OCC::PropagateUploadFileQNAM::slotPutFinished: void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-12" )  FINISHED WITH STATUS 0 "" QVariant(int, 201) QVariant(QString, "Created")
09-18 15:57:09:881 0x7fa850d21f60 OCC::SyncJournalDb::setUploadInfo: "INSERT OR REPLACE INTO uploadinfo (path, chunk, transferid, errorcount, size, modtime) VALUES ( ?1 , ?2, ?3 , ?4 ,  ?5, ?6 )" "production.sqlite3" 13 310242363 0
09-18 15:57:09:909 0x7fa850d21f60 OCC::AbstractNetworkJob::start: !!! OCC::PUTFileJob created for "https://myserver.org" + "/Documents/production.sqlite3-chunking-304999483-25-16"
09-18 15:58:07:904 0x7fa850d21f60 OCC::AbstractNetworkJob::slotFinished: void OCC::AbstractNetworkJob::slotFinished() 302 "Error downloading https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-14 - server replied: Bad Request" QVariant(int, 400)
09-18 15:58:07:904 0x7fa850d21f60 OCC::PropagateUploadFileQNAM::slotPutFinished: void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-14" )  FINISHED WITH STATUS 302 "Error downloading https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-14 - server replied: Bad Request" QVariant(int, 400) QVariant(QString, "Bad Request")
09-18 15:58:07:904 0x7fa850d21f60 OCC::PropagateUploadFileQNAM::abort: virtual void OCC::PropagateUploadFileQNAM::abort() OCC::PUTFileJob(0x7fa854334770) "production.sqlite3"
09-18 15:58:07:904 0x7fa850d21f60 OCC::PropagateUploadFileQNAM::slotPutFinished: void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-15" )  FINISHED WITH STATUS 5 "Operation canceled" QVariant(Invalid) QVariant(Invalid)
09-18 15:58:07:904 0x7fa850d21f60 OCC::PropagateUploadFileQNAM::abort: virtual void OCC::PropagateUploadFileQNAM::abort() OCC::PUTFileJob(0x7fa8533def10) "production.sqlite3"
09-18 15:58:07:905 0x7fa850d21f60 OCC::PropagateUploadFileQNAM::slotPutFinished: void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-16" )  FINISHED WITH STATUS 5 "Operation canceled" QVariant(Invalid) QVariant(Invalid)
09-18 15:58:07:905 0x7fa850d21f60 OCC::SyncJournalErrorBlacklistRecord::update: blacklisting  "production.sqlite3"  for  625 , retry count  3
09-18 15:58:07:905 0x7fa850d21f60 OCC::SyncJournalDb::updateErrorBlacklistEntry: set blacklist entry for  "production.sqlite3" 3 "Error downloading https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-14 - server replied: Bad Request (expected filesize 5242880 got 0)" 1442584687 625 1436607695 ""
09-18 15:58:07:905 0x7fa850d21f60 OCC::SyncEngine::slotItemCompleted: void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem &, const OCC::PropagatorJob &) "production.sqlite3" INSTRUCTION_NEW 6 "Continue blacklisting: Error downloading https://myserver.org/remote.php/webdav/Documents/production.sqlite3-chunking-304999483-25-14 - server replied: Bad Request (expected filesize 5242880 got 0)"
09-18 15:58:07:905 0x7fa850d21f60 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:ERROR:/Users/toni/Documents/production.sqlite3"
09-18 15:58:07:906 0x7fa850d21f60 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:ERROR:/Users/toni/Documents/production.sqlite3"
09-18 15:58:07:907 0x7fa850d21f60 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:ERROR:/Users/toni/Documents/production.sqlite3"
09-18 15:58:07:908 0x7fa850d21f60 OCC::SocketApi::sendMessage: SocketApi:  Sending message:  "STATUS:ERROR:/Users/toni/Documents/production.sqlite3

@Ninos
Copy link
Author

Ninos commented Sep 18, 2015

@guruz I've updated my owncloud.log in one of my older posts.

Here's also my apache2 error.log:

[Fri Sep 11 20:19:43.536658 2015] [proxy_fcgi:error] [pid 24303:tid 139732222584576] (32)Broken pipe: [client 1.2.3.4:3297] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:19:43.705897 2015] [proxy_fcgi:error] [pid 24303:tid 139732432402176] (32)Broken pipe: [client 1.2.3.4:3296] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:19:45.500608 2015] [proxy_fcgi:error] [pid 24303:tid 139732348475136] (32)Broken pipe: [client 1.2.3.4:3298] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:19:45.685618 2015] [proxy_fcgi:error] [pid 24303:tid 139732105086720] (32)Broken pipe: [client 1.2.3.4:3299] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:19:47.549956 2015] [proxy_fcgi:error] [pid 24303:tid 139732272940800] (32)Broken pipe: [client 1.2.3.4:3300] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:19:47.863166 2015] [proxy_fcgi:error] [pid 24303:tid 139732465972992] (32)Broken pipe: [client 1.2.3.4:3301] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:19:49.447956 2015] [proxy_fcgi:error] [pid 24303:tid 139732415616768] (32)Broken pipe: [client 1.2.3.4:3302] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:19:49.860746 2015] [proxy_fcgi:error] [pid 24303:tid 139732163835648] (32)Broken pipe: [client 1.2.3.4:3303] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:19:52.575143 2015] [proxy_fcgi:error] [pid 24303:tid 139732323297024] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:3295] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 20:20:52.440862 2015] [proxy_fcgi:error] [pid 24303:tid 139732130264832] (32)Broken pipe: [client 1.2.3.4:3310] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:20:52.619593 2015] [proxy_fcgi:error] [pid 24303:tid 139732398831360] (32)Broken pipe: [client 1.2.3.4:3309] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:20:55.027832 2015] [proxy_fcgi:error] [pid 24303:tid 139732507936512] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:3308] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 20:21:52.466108 2015] [proxy_fcgi:error] [pid 24303:tid 139732432402176] (32)Broken pipe: [client 1.2.3.4:3324] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:21:55.283848 2015] [proxy_fcgi:error] [pid 24303:tid 139732222584576] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:3323] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 20:26:52.798039 2015] [proxy_fcgi:error] [pid 24303:tid 139732348475136] (70007)The timeout specified has expired: [client 1.2.3.4:3325] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 20:29:48.362836 2015] [proxy_fcgi:error] [pid 24303:tid 139732256155392] (32)Broken pipe: [client 1.2.3.4:3515] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:29:50.328190 2015] [proxy_fcgi:error] [pid 24303:tid 139732096694016] (32)Broken pipe: [client 1.2.3.4:3523] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:29:50.408747 2015] [proxy_fcgi:error] [pid 24303:tid 139732516329216] (32)Broken pipe: [client 1.2.3.4:3514] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:29:52.847415 2015] [proxy_fcgi:error] [pid 24303:tid 139732348475136] (32)Broken pipe: [client 1.2.3.4:3525] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:29:54.947935 2015] [proxy_fcgi:error] [pid 24303:tid 139732637693696] (32)Broken pipe: [client 1.2.3.4:3526] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:29:57.791179 2015] [proxy_fcgi:error] [pid 24303:tid 139732247762688] (32)Broken pipe: [client 1.2.3.4:3529] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:30:01.465992 2015] [proxy_fcgi:error] [pid 24303:tid 139732088301312] (32)Broken pipe: [client 1.2.3.4:3527] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:30:03.104082 2015] [proxy_fcgi:error] [pid 24303:tid 139732499543808] (32)Broken pipe: [client 1.2.3.4:3530] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:30:05.160598 2015] [proxy_fcgi:error] [pid 24303:tid 139732121872128] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:3508] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 20:30:37.836773 2015] [proxy_fcgi:error] [pid 24302:tid 139732197406464] (32)Broken pipe: [client 1.2.3.4:3538] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:30:40.784258 2015] [proxy_fcgi:error] [pid 24302:tid 139732289726208] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:3537] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 20:31:45.796356 2015] [proxy_fcgi:error] [pid 24303:tid 139732239369984] (32)Broken pipe: [client 1.2.3.4:3572] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:31:46.507487 2015] [proxy_fcgi:error] [pid 24303:tid 139732629300992] (32)Broken pipe: [client 1.2.3.4:3573] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 20:31:50.462031 2015] [proxy_fcgi:error] [pid 24303:tid 139732289726208] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:3565] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 20:34:19.618282 2015] [authz_core:error] [pid 24303:tid 139732499543808] [client 2a01:4f8:141:3c3::2:46086] AH01630: client denied by server configuration: /var/www/virtual/example.tld/htdocs/data/htaccesstest.txt
[Fri Sep 11 20:34:58.051875 2015] [authz_core:error] [pid 24303:tid 139732071515904] [client 2a01:4f8:141:3c3::2:41674] AH01630: client denied by server configuration: /var/www/virtual/example.tld/htdocs/data/htaccesstest.txt
[Fri Sep 11 20:35:07.828982 2015] [authz_core:error] [pid 24303:tid 139732524721920] [client 2a01:4f8:141:3c3::2:41679] AH01630: client denied by server configuration: /var/www/virtual/example.tld/htdocs/data/htaccesstest.txt
[Fri Sep 11 20:35:38.715200 2015] [proxy_fcgi:error] [pid 24302:tid 139732620908288] (70007)The timeout specified has expired: [client 1.2.3.4:3539] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 20:44:43.714867 2015] [authz_core:error] [pid 24302:tid 139732465972992] [client 2a01:4f8:141:3c3::2:41848] AH01630: client denied by server configuration: /var/www/virtual/example.tld/htdocs/data/htaccesstest.txt
[Fri Sep 11 21:16:00.929569 2015] [authz_core:error] [pid 24303:tid 139732113479424] [client 2a01:4f8:141:3c3::2:44562] AH01630: client denied by server configuration: /var/www/virtual/example.tld/htdocs/data/htaccesstest.txt
[Fri Sep 11 21:16:02.586660 2015] [proxy_fcgi:error] [pid 24303:tid 139732637693696] (32)Broken pipe: [client 1.2.3.4:4262] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:16:06.807355 2015] [proxy_fcgi:error] [pid 24303:tid 139732620908288] (32)Broken pipe: [client 1.2.3.4:4263] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:16:09.182845 2015] [proxy_fcgi:error] [pid 24303:tid 139732499543808] (32)Broken pipe: [client 1.2.3.4:4265] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:16:11.719686 2015] [proxy_fcgi:error] [pid 24303:tid 139732365260544] (32)Broken pipe: [client 1.2.3.4:4264] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:16:13.761879 2015] [proxy_fcgi:error] [pid 24303:tid 139732474365696] (32)Broken pipe: [client 1.2.3.4:4267] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:16:15.946305 2015] [proxy_fcgi:error] [pid 24303:tid 139732457580288] (32)Broken pipe: [client 1.2.3.4:4268] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:16:17.083796 2015] [proxy_fcgi:error] [pid 24303:tid 139732415616768] (32)Broken pipe: [client 1.2.3.4:4266] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:16:18.879030 2015] [proxy_fcgi:error] [pid 24303:tid 139732163835648] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:4260] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:16:22.774326 2015] [authz_core:error] [pid 24303:tid 139732272940800] [client 2a01:4f8:141:3c3::2:44569] AH01630: client denied by server configuration: /var/www/virtual/example.tld/htdocs/data/htaccesstest.txt
[Fri Sep 11 21:16:37.746301 2015] [authz_core:error] [pid 24303:tid 139732222584576] [client 2a01:4f8:141:3c3::2:44574] AH01630: client denied by server configuration: /var/www/virtual/example.tld/htdocs/data/htaccesstest.txt
[Fri Sep 11 21:17:01.085571 2015] [proxy_fcgi:error] [pid 24303:tid 139732340082432] (32)Broken pipe: [client 1.2.3.4:4285] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:17:03.901792 2015] [proxy_fcgi:error] [pid 24303:tid 139732533114624] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:4283] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:17:31.912922 2015] [authz_core:error] [pid 24303:tid 139732390438656] [client 2a01:4f8:141:3c3::2:44581] AH01630: client denied by server configuration: /var/www/virtual/example.tld/htdocs/data/htaccesstest.txt
[Fri Sep 11 21:18:03.806066 2015] [proxy_fcgi:error] [pid 24303:tid 139732637693696] (32)Broken pipe: [client 1.2.3.4:4298] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:18:04.057900 2015] [proxy_fcgi:error] [pid 24303:tid 139732205799168] (32)Broken pipe: [client 1.2.3.4:4297] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:18:06.850117 2015] [proxy_fcgi:error] [pid 24303:tid 139732264548096] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:4296] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:18:10.826338 2015] [authz_core:error] [pid 24303:tid 139732323297024] [client 2a01:4f8:141:3c3::2:44587] AH01630: client denied by server configuration: /var/www/virtual/example.tld/htdocs/data/htaccesstest.txt
[Fri Sep 11 21:18:18.223707 2015] [authz_core:error] [pid 24303:tid 139732071515904] [client 2a01:4f8:141:3c3::2:44591] AH01630: client denied by server configuration: /var/www/virtual/example.tld/htdocs/data/htaccesstest.txt
[Fri Sep 11 21:22:02.112150 2015] [proxy_fcgi:error] [pid 24303:tid 139732482758400] (70007)The timeout specified has expired: [client 1.2.3.4:4284] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:44:04.624407 2015] [proxy_fcgi:error] [pid 24303:tid 139732465972992] (32)Broken pipe: [client 1.2.3.4:4976] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:44:04.774134 2015] [proxy_fcgi:error] [pid 24303:tid 139732272940800] (32)Broken pipe: [client 1.2.3.4:4975] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:44:09.266562 2015] [proxy_fcgi:error] [pid 24303:tid 139732298118912] (32)Broken pipe: [client 1.2.3.4:4980] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:44:09.351176 2015] [proxy_fcgi:error] [pid 24303:tid 139732356867840] (32)Broken pipe: [client 1.2.3.4:4979] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:44:12.319466 2015] [proxy_fcgi:error] [pid 24303:tid 139732440794880] (32)Broken pipe: [client 1.2.3.4:4982] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:44:13.945546 2015] [proxy_fcgi:error] [pid 24303:tid 139732155442944] (32)Broken pipe: [client 1.2.3.4:4981] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:44:15.087758 2015] [proxy_fcgi:error] [pid 24303:tid 139732189013760] (32)Broken pipe: [client 1.2.3.4:4983] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:44:18.890844 2015] [proxy_fcgi:error] [pid 24303:tid 139732046337792] (32)Broken pipe: [client 1.2.3.4:4984] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:44:20.281612 2015] [proxy_fcgi:error] [pid 24303:tid 139732457580288] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:4974] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:44:58.885689 2015] [proxy_fcgi:error] [pid 24303:tid 139732516329216] (32)Broken pipe: [client 1.2.3.4:4994] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:44:59.059684 2015] [proxy_fcgi:error] [pid 24303:tid 139732612515584] (32)Broken pipe: [client 1.2.3.4:4995] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:45:01.065799 2015] [proxy_fcgi:error] [pid 24303:tid 139732105086720] (32)Broken pipe: [client 1.2.3.4:4996] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:45:01.598137 2015] [proxy_fcgi:error] [pid 24303:tid 139732533114624] (32)Broken pipe: [client 1.2.3.4:4997] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:45:04.051759 2015] [proxy_fcgi:error] [pid 24303:tid 139732130264832] (32)Broken pipe: [client 1.2.3.4:5001] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:45:06.328306 2015] [proxy_fcgi:error] [pid 24303:tid 139732348475136] (32)Broken pipe: [client 1.2.3.4:5002] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:45:06.500705 2015] [proxy_fcgi:error] [pid 24303:tid 139732147050240] (32)Broken pipe: [client 1.2.3.4:4998] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:45:13.358812 2015] [proxy_fcgi:error] [pid 24303:tid 139732230977280] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:4987] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:48:21.622668 2015] [proxy_fcgi:error] [pid 24302:tid 139732054730496] (32)Broken pipe: [client 1.2.3.4:5018] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:48:23.249952 2015] [proxy_fcgi:error] [pid 24302:tid 139732113479424] (32)Broken pipe: [client 1.2.3.4:5019] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:48:25.793846 2015] [proxy_fcgi:error] [pid 24302:tid 139732365260544] (32)Broken pipe: [client 1.2.3.4:5022] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:48:31.425561 2015] [proxy_fcgi:error] [pid 24302:tid 139732629300992] (32)Broken pipe: [client 1.2.3.4:5023] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:48:34.568809 2015] [proxy_fcgi:error] [pid 24302:tid 139732197406464] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5015] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:48:37.038629 2015] [proxy_fcgi:error] [pid 24302:tid 139732407224064] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5017] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:49:00.665058 2015] [proxy_fcgi:error] [pid 24302:tid 139732499543808] (32)Broken pipe: [client 1.2.3.4:5030] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:49:03.863055 2015] [proxy_fcgi:error] [pid 24303:tid 139732499543808] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5029] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:49:05.920226 2015] [proxy_fcgi:error] [pid 24302:tid 139732079908608] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5028] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:49:42.237938 2015] [proxy_fcgi:error] [pid 24303:tid 139732373653248] (32)Broken pipe: [client 1.2.3.4:5035] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:49:45.877213 2015] [proxy_fcgi:error] [pid 24303:tid 139732424009472] (32)Broken pipe: [client 1.2.3.4:5034] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:49:51.804892 2015] [proxy_fcgi:error] [pid 24303:tid 139732289726208] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5032] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:50:04.441860 2015] [proxy_fcgi:error] [pid 24303:tid 139732079908608] (32)Broken pipe: [client 1.2.3.4:5039] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:50:09.483965 2015] [proxy_fcgi:error] [pid 24303:tid 139732197406464] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5038] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:50:39.359781 2015] [proxy_fcgi:error] [pid 24303:tid 139732524721920] (9)Bad file descriptor: [client 1.2.3.4:5040] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:50:39.598122 2015] [proxy_fcgi:error] [pid 24303:tid 139732306511616] (9)Bad file descriptor: [client 1.2.3.4:5041] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:51:46.944113 2015] [proxy_fcgi:error] [pid 12783:tid 140434609133312] (32)Broken pipe: [client 1.2.3.4:5092] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:51:47.210034 2015] [proxy_fcgi:error] [pid 12783:tid 140434600740608] (32)Broken pipe: [client 1.2.3.4:5093] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:51:50.162499 2015] [proxy_fcgi:error] [pid 12783:tid 140434541991680] (32)Broken pipe: [client 1.2.3.4:5095] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:51:52.966703 2015] [proxy_fcgi:error] [pid 12783:tid 140434558777088] (32)Broken pipe: [client 1.2.3.4:5094] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:51:55.194950 2015] [proxy_fcgi:error] [pid 12783:tid 140434525206272] (32)Broken pipe: [client 1.2.3.4:5097] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:51:55.440056 2015] [proxy_fcgi:error] [pid 12783:tid 140434516813568] (32)Broken pipe: [client 1.2.3.4:5096] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:52:00.030729 2015] [proxy_fcgi:error] [pid 12783:tid 140434500028160] (32)Broken pipe: [client 1.2.3.4:5098] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:52:00.371445 2015] [proxy_fcgi:error] [pid 12783:tid 140434491635456] (32)Broken pipe: [client 1.2.3.4:5099] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:52:02.910589 2015] [proxy_fcgi:error] [pid 12783:tid 140434634311424] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5089] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:52:45.949776 2015] [proxy_fcgi:error] [pid 12783:tid 140434802165504] (32)Broken pipe: [client 1.2.3.4:5128] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:52:47.850295 2015] [proxy_fcgi:error] [pid 12783:tid 140434743416576] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5112] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:52:49.844743 2015] [proxy_fcgi:error] [pid 12783:tid 140434894485248] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5103] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:53:46.832676 2015] [proxy_fcgi:error] [pid 12784:tid 140434735023872] (32)Broken pipe: [client 1.2.3.4:5138] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:53:49.695132 2015] [proxy_fcgi:error] [pid 12784:tid 140434760201984] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5136] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:53:50.297439 2015] [proxy_fcgi:error] [pid 12784:tid 140434743416576] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5137] AH01075: Error dispatching request to : (reading input brigade)
[Fri Sep 11 21:54:25.186440 2015] [proxy_fcgi:error] [pid 12784:tid 140434625918720] (32)Broken pipe: [client 1.2.3.4:5144] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:54:26.434475 2015] [proxy_fcgi:error] [pid 12784:tid 140434634311424] (32)Broken pipe: [client 1.2.3.4:5143] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:54:26.580255 2015] [proxy_fcgi:error] [pid 12784:tid 140434609133312] (32)Broken pipe: [client 1.2.3.4:5145] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:54:28.422516 2015] [proxy_fcgi:error] [pid 12784:tid 140434592347904] (32)Broken pipe: [client 1.2.3.4:5146] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:54:28.615132 2015] [proxy_fcgi:error] [pid 12784:tid 140434583955200] (32)Broken pipe: [client 1.2.3.4:5147] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:54:30.645488 2015] [proxy_fcgi:error] [pid 12784:tid 140434575562496] (32)Broken pipe: [client 1.2.3.4:5148] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:54:31.179375 2015] [proxy_fcgi:error] [pid 12784:tid 140434567169792] (32)Broken pipe: [client 1.2.3.4:5149] AH01075: Error dispatching request to : (sending stdin)
[Fri Sep 11 21:54:34.186194 2015] [proxy_fcgi:error] [pid 12784:tid 140434651096832] (70008)Partial results are valid but processing is incomplete: [client 1.2.3.4:5142] AH01075: Error dispatching request to : (reading input brigade)

In php-fpm I cannot find relevant logs:

[11-Sep-2015 00:24:46] NOTICE: [pool example.tld] child 2307 exited with code 0 after 30770.177897 seconds from start
[11-Sep-2015 00:24:46] NOTICE: [pool example.tld] child 22208 started
[11-Sep-2015 02:15:24] NOTICE: [pool example.tld] child 20577 exited with code 0 after 30735.085565 seconds from start
[11-Sep-2015 02:15:24] NOTICE: [pool example.tld] child 7594 started
[11-Sep-2015 03:41:46] WARNING: [pool example.tld] server reached max_children setting (6), consider raising it
[11-Sep-2015 10:04:18] NOTICE: [pool example.tld] child 30655 exited with code 0 after 22656.030141 seconds from start
[11-Sep-2015 10:04:18] NOTICE: [pool example.tld] child 26786 started
[11-Sep-2015 10:39:08] NOTICE: [pool example.tld] child 3032 exited with code 0 after 23162.717985 seconds from start
[11-Sep-2015 10:39:08] NOTICE: [pool example.tld] child 32293 started
[11-Sep-2015 20:34:19] WARNING: [pool example.tld] server reached max_children setting (6), consider raising it
[11-Sep-2015 21:15:53] WARNING: [pool example.tld] server reached max_children setting (6), consider raising it

@stonerl
Copy link

stonerl commented Sep 30, 2015

I enabled debuging on the Server. Here is one of the famous errors:

Error downloading https://kumori.fosuta.org/remote.php/webdav/Music/Cat Stevens/The Very Best of Cat Stevens/16. Another Saturday Night.m4a-chunking-3152591687-4-2 - server replied: Bad Request (expected filesize 5242880 got 0)

And here is everything from the Server:

{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Write lock requested for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:00+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"PASS: Write lock succeeded on \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:00+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Incrementing lock type 2 count for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:00+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_antivirus","message":"Response :: stream: OK\n","level":0,"time":"2015-09-30T20:58:38+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Read lock requested for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:38+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"PASS: Acquired read lock for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:38+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Incrementing lock type 1 count for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:38+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Write lock requested for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2","level":0,"time":"2015-09-30T20:58:38+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"PASS: Write lock succeeded on \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2","level":0,"time":"2015-09-30T20:58:38+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Incrementing lock type 2 count for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2","level":0,"time":"2015-09-30T20:58:38+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Releasing locks on \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2","level":0,"time":"2015-09-30T20:58:38+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Released lock handle Resource id #52 on \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2","level":0,"time":"2015-09-30T20:58:38+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"FREE: Released locks on \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2","level":0,"time":"2015-09-30T20:58:38+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Read lock requested for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:39+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"PASS: Acquired read lock for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:39+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Incrementing lock type 1 count for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:39+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Incrementing lock type 2 count for \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:39+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Destroying locks on \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:39+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Releasing locks on \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:39+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"INFO: Released lock handle Resource id #48 on \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:39+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"files_locking","message":"FREE: Released locks on \/srv\/owncloud-data\/toni\/cache\/16. Another Saturday Night.m4a-chunking-3152591687-2.YymOFvO9fm4zMWSY.part","level":0,"time":"2015-09-30T20:58:39+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}
{"reqId":"SY9QhHWasR7+9ZiQGD9L","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"webdav","message":"Exception: {\"Message\":\"HTTP\\\/1.1 400 expected filesize 5242880 got 0\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php(100): OC\\\\Connector\\\\Sabre\\\\File->createFileChunked(Resource id #37)\\n#1 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/directory.php(113): OC\\\\Connector\\\\Sabre\\\\File->put(Resource id #37)\\n#2 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1053): OC\\\\Connector\\\\Sabre\\\\Directory->createFile('16. Another Sat...', Resource id #37)\\n#3 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(513): Sabre\\\\DAV\\\\Server->createFile('Music\\\/Cat Steve...', Resource id #37, NULL)\\n#4 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#5 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#6 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(469): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#7 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#8 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files\\\/appinfo\\\/remote.php(83): Sabre\\\\DAV\\\\Server->exec()\\n#9 \\\/var\\\/www\\\/owncloud\\\/remote.php(132): require_once('\\\/var\\\/www\\\/ownclo...')\\n#10 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php\",\"Line\":346}","level":4,"time":"2015-09-30T20:58:39+02:00","method":"PUT","url":"\/remote.php\/webdav\/Music\/Cat%20Stevens\/The%20Very%20Best%20of%20Cat%20Stevens\/16.%20Another%20Saturday%20Night.m4a-chunking-3152591687-4-2"}

What I think, can clearly be seen is that the time between the first filelock 20:58:00 and the fail 20:58:39 is about the time a 5MB files takes with a 2.5Mbit Upstream. I took in consideration that a second file got transferred. So what I stated before seems to hold true, the chunk gets transferred but "vanishes". I think that this is not a client issue, rather a core "bug".

@guruz
Copy link
Contributor

guruz commented Oct 1, 2015

On my second server, with v8.1.3, I don't have these kind of problems, and the configuration is identical as far as I can tell.

...

I tested this on my second server, where I never had problems. root-folder|/first-folder/second-folder/file gave me an error.

I'm confused, so 8.1.3 is broken too or not?

@maxstricker
Copy link

I use ownCloud 8.1.3 (beta) and Client 2.0.2-nightly20150929 (build 2752) and have the problems.

@stonerl
Copy link

stonerl commented Oct 1, 2015

I was always talking about Server Version 8.1.3, the whole time, sorry didn't I mention this?

@guruz
Copy link
Contributor

guruz commented Oct 1, 2015

Sorry, hard to keep an overview here.

owncloud.example.tld
owncloud.example.tld:4433
example.tld/owncloud
In case 1 I always get the errors. In case 2 and 3 not a single one. Also I used the same Apache config
for 1 and 2 and only changed the port. Why do I get an error when I use the standard ssl port but none
when I use a custom one.

@maxstricker Does it work for you too if you configure like in that comment?

I'm tempted to close this bug here since this seems to be a server setup problem, nothing to do with owncloud PHP (-> core bugtracker) or client :-|

@maxstricker
Copy link

I just changed my configuration to owncloud.example.tld:4433, but the problem remains the same.
I see many "400 expected filesize 5242880 got 458752" in the logs ant there are files that do not get synced.
But now the error message in the client becomes a different one. I see a message saying "Broken webserver returning empty content length for non-empty file on resume" but for the same file my Apache combined log tells me that it sends 69899 back.

@guruz
Copy link
Contributor

guruz commented Oct 1, 2015

The only thing I can recommend is that you paste your Apache virtual host configuration, maybe we see something obvious in there..

@maxstricker
Copy link

Below my configuration, adopted the various recommendations on similar issues found in the OC forums (KeepAliveTimeout etc.).

<VirtualHost *:443>
        ServerAdmin [email protected]
        ServerName  owncloud.mydomain.com
        ServerAlias owncloud.seconddomain.com
        DirectoryIndex index.php
        DocumentRoot /var/www/owncloud/owncloud/

        KeepAlive On
        MaxKeepAliveRequests 100
        KeepAliveTimeout 10
        Header always set Strict-Transport-Security "max-age=63072000; includeSubdomains; preload"

        SSLEngine on
        SSLCertificateFile /etc/apache2/ssl/cloud.crt
        SSLCertificateKeyFile /etc/apache2/ssl/cloud.key

        ErrorLog  /var/www/owncloud/logs/error.log
        CustomLog /var/www/owncloud/logs/access.log combined

        <Directory "/var/www/owncloud/owncloud/">
           Options Indexes FollowSymLinks
           AllowOverride All
           Order allow,deny
           allow from all
        </Directory>
        <Directory /var/www/owncloud/owncloud/owncloud>
          <IfModule mod_xsendfile.c>
                SetEnv MOD_X_SENDFILE_ENABLED 1
                XSendFile On
                XSendFilePath /tmp/oc-noclean
            </IfModule>
        </Directory>
</VirtualHost>

@stonerl
Copy link

stonerl commented Oct 1, 2015

This is how mine looks like:

<IfModule mod_ssl.c>
    <VirtualHost *:443>
        ServerAdmin [email protected]
        ServerName kumori.example.tld

        Header always set Strict-Transport-Security: max-age=31536000
        Header always set Public-Key-Pins "pin-sha256=\"TaZp92pTEm0w7+Gm4J3i5rvwlZ8MQ/7khUk64WIL9gQ=\"; max-age=5184000"

        DocumentRoot /var/www/owncloud

        <Directory /var/www/owncloud>
            Options +FollowSymLinks
            AllowOverride all

            SetEnv MOD_X_SENDFILE_ENABLED 1
            XSendFile On
            XSendfilePath /srv/owncloud-data

            <IfModule mod_dav.c>
                Dav off
            </IfModule>

            SetEnv HOME /var/www/owncloud
            SetEnv HTTP_HOME /var/www/owncloud
        </Directory>

        CustomLog ${APACHE_LOG_DIR}/ssl_access.log combined
        ErrorLog ${APACHE_LOG_DIR}/error.log
        LogLevel debug

        SSLEngine on

        SSLOptions +StdEnvVars

        SSLCertificateFile    /etc/ssl/certs/kumori-server.crt
        SSLCertificateKeyFile /etc/ssl/private/server.key
        SSLCertificateChainFile /etc/ssl/certs/sub.class1.server.ca.pem

        SSLUseStapling on
        SSLStaplingResponderTimeout 5
        SSLStaplingReturnResponderErrors off

    </VirtualHost>
    SSLStaplingCache shmcb:/tmp/stapling_cache(128000)
</IfModule>

@stonerl
Copy link

stonerl commented Oct 2, 2015

I did some extensive testing last night. I monitored data/$user/cacheand /tmp. The Antivirus app is enabled, this helped me allot to track this down.
Here is the script i used:

#!/bin/bash

COUNTER=0
while [  $COUNTER -lt 600000 ]; do
   ls -lhA /srv/owncloud-data/toni/cache/ | grep "part" >> /tmp/ocfolder.log
   ls -lhA /tmp/ | grep "clamav" >> /tmp/ocfolder.log
   sleep 1
   let COUNTER=COUNTER+1 
done
-rw-r--r-- 1 www-data www-data 5.0M Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-17.2x9DV1RILLVsgpO6.part
-rw-r--r-- 1 www-data www-data 784K Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-19.r3Get2pBrSsZR0zF.part
-rw-r--r-- 1 www-data www-data 128K Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-20.gHxTBqyhYucJjpSL.part
-rwx------ 1 clamav   clamav   784K Oct  2 09:40 clamav-60e96853a54ef3e818f5ed10c28e7e27.tmp
-rwx------ 1 clamav   clamav   5.0M Oct  2 09:40 clamav-6895d3a134dd853b5c5fd5e343fbe561.tmp
-rwx------ 1 clamav   clamav   128K Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rw-r--r-- 1 www-data www-data 912K Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-19.r3Get2pBrSsZR0zF.part
-rw-r--r-- 1 www-data www-data 256K Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-20.gHxTBqyhYucJjpSL.part
-rw-r--r-- 1 www-data www-data  16K Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-21.L2KJHF1Ws1hsrY1o.part
-rwx------ 1 clamav   clamav   912K Oct  2 09:40 clamav-60e96853a54ef3e818f5ed10c28e7e27.tmp
-rwx------ 1 clamav   clamav    32K Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   256K Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rw-r--r-- 1 www-data www-data 1.0M Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-19.r3Get2pBrSsZR0zF.part
-rw-r--r-- 1 www-data www-data 288K Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-20.gHxTBqyhYucJjpSL.part
-rw-r--r-- 1 www-data www-data 128K Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-21.L2KJHF1Ws1hsrY1o.part
-rwx------ 1 clamav   clamav   1.0M Oct  2 09:40 clamav-60e96853a54ef3e818f5ed10c28e7e27.tmp
-rwx------ 1 clamav   clamav   128K Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   288K Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rw-r--r-- 1 www-data www-data 416K Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-20.gHxTBqyhYucJjpSL.part
-rwx------ 1 clamav   clamav   1.1M Oct  2 09:40 clamav-60e96853a54ef3e818f5ed10c28e7e27.tmp
-rwx------ 1 clamav   clamav   208K Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   416K Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rwx------ 1 clamav   clamav   1.1M Oct  2 09:40 clamav-60e96853a54ef3e818f5ed10c28e7e27.tmp
-rwx------ 1 clamav   clamav   208K Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   416K Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rwx------ 1 clamav   clamav   1.3M Oct  2 09:40 clamav-60e96853a54ef3e818f5ed10c28e7e27.tmp
-rwx------ 1 clamav   clamav   288K Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   512K Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rwx------ 1 clamav   clamav   1.4M Oct  2 09:40 clamav-60e96853a54ef3e818f5ed10c28e7e27.tmp
-rwx------ 1 clamav   clamav   336K Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   624K Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
.
.
.
-rwx------ 1 clamav   clamav   3.3M Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   4.5M Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rwx------ 1 clamav   clamav   5.0M Oct  2 09:40 clamav-60e96853a54ef3e818f5ed10c28e7e27.tmp
-rwx------ 1 clamav   clamav   3.4M Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   4.6M Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rwx------ 1 clamav   clamav   3.5M Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   4.7M Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rw-r--r-- 1 www-data www-data  16K Oct  2 09:40 Turbo Kid.mkv-chunking-2011514449-14.CbbfLIuFHxmBogCS.part
-rw-r--r-- 1 www-data www-data  16K Oct  2 09:40 Turbo Kid.mkv-chunking-2011514449-15.K6TRcq6f4FMxvPpx.part
-rw-r--r-- 1 www-data www-data  32K Oct  2 09:40 Turbo Kid.mkv-chunking-2011514449-16.Cnjz7cblW3Ibd3G5.part
-rwx------ 1 clamav   clamav    16K Oct  2 09:40 clamav-0765092e18458a4207640ac967a17e2c.tmp
-rwx------ 1 clamav   clamav   3.5M Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   4.8M Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rwx------ 1 clamav   clamav    16K Oct  2 09:40 clamav-f5f37953cf62c7d5001fba2e5bf80926.tmp
-rwx------ 1 clamav   clamav    32K Oct  2 09:40 clamav-fa5b0f4f8956eea0966be64193e234a4.tmp
-rw-r--r-- 1 www-data www-data 112K Oct  2 09:40 Turbo Kid.mkv-chunking-2011514449-14.CbbfLIuFHxmBogCS.part
-rw-r--r-- 1 www-data www-data  64K Oct  2 09:40 Turbo Kid.mkv-chunking-2011514449-15.K6TRcq6f4FMxvPpx.part
-rw-r--r-- 1 www-data www-data  80K Oct  2 09:40 Turbo Kid.mkv-chunking-2011514449-16.Cnjz7cblW3Ibd3G5.part
-rwx------ 1 clamav   clamav   112K Oct  2 09:40 clamav-0765092e18458a4207640ac967a17e2c.tmp
-rwx------ 1 clamav   clamav   3.6M Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   4.8M Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rwx------ 1 clamav   clamav    80K Oct  2 09:40 clamav-f5f37953cf62c7d5001fba2e5bf80926.tmp
-rwx------ 1 clamav   clamav    80K Oct  2 09:40 clamav-fa5b0f4f8956eea0966be64193e234a4.tmp
-rw-r--r-- 1 www-data www-data 256K Oct  2 09:40 Turbo Kid.mkv-chunking-2011514449-14.CbbfLIuFHxmBogCS.part
-rw-r--r-- 1 www-data www-data 144K Oct  2 09:40 Turbo Kid.mkv-chunking-2011514449-15.K6TRcq6f4FMxvPpx.part
-rw-r--r-- 1 www-data www-data 160K Oct  2 09:40 Turbo Kid.mkv-chunking-2011514449-16.Cnjz7cblW3Ibd3G5.part
-rwx------ 1 clamav   clamav   256K Oct  2 09:40 clamav-0765092e18458a4207640ac967a17e2c.tmp
-rwx------ 1 clamav   clamav   3.6M Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp
-rwx------ 1 clamav   clamav   4.8M Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp
-rwx------ 1 clamav   clamav   144K Oct  2 09:40 clamav-f5f37953cf62c7d5001fba2e5bf80926.tmp
-rwx------ 1 clamav   clamav   160K Oct  2 09:40 clamav-fa5b0f4f8956eea0966be64193e234a4.tmp
-rw-r--r-- 1 www-data www-data 400K Oct  2 09:41 Turbo Kid.mkv-chunking-2011514449-14.CbbfLIuFHxmBogCS.part
-rw-r--r-- 1 www-data www-data 224K Oct  2 09:41 Turbo Kid.mkv-chunking-2011514449-15.K6TRcq6f4FMxvPpx.part
-rw-r--r-- 1 www-data www-data 240K Oct  2 09:41 Turbo Kid.mkv-chunking-2011514449-16.Cnjz7cblW3Ibd3G5.part
-rwx------ 1 clamav   clamav   400K Oct  2 09:41 clamav-0765092e18458a4207640ac967a17e2c.tmp
-rwx------ 1 clamav   clamav   224K Oct  2 09:41 clamav-f5f37953cf62c7d5001fba2e5bf80926.tmp
-rwx------ 1 clamav   clamav   240K Oct  2 09:41 clamav-fa5b0f4f8956eea0966be64193e234a4.tmp

Here are the matching part files and clamav temp files. You can tell this from the size.

Chunk 19:

-rw-r--r-- 1 www-data www-data 1.0M Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-19.r3Get2pBrSsZR0zF.part
-rwx------ 1 clamav   clamav   1.0M Oct  2 09:40 clamav-60e96853a54ef3e818f5ed10c28e7e27.tmp

Chunk 20:

-rw-r--r-- 1 www-data www-data 288K Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-20.gHxTBqyhYucJjpSL.part
-rwx------ 1 clamav   clamav   288K Oct  2 09:40 clamav-acb912216ef9de22a572fc6c266efa38.tmp

Chunk 21:

-rw-r--r-- 1 www-data www-data 128K Oct  2 09:40 Stollfilm-1080p.mp4-chunking-138980595-21.L2KJHF1Ws1hsrY1o.part
-rwx------ 1 clamav   clamav   128K Oct  2 09:40 clamav-800efbf4d135127c8c6c96438a15c873.tmp

What you can see is that the .part-files for chunk 19 and 21 disappear/get deleted and later also the part file for chunk 20 disappears. But the corresponding ClamAV-files are increasing in size. So the chunks still get transferred but the part file was deleted.

What you can also see from the timestamps is when the client receives a 400 and starts with new files (the Turbo.mkv).

{"reqId":"2qZPWakTIBpD34Ba05tg","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"webdav","message":"Exception: {\"Message\":\"HTTP\\\/1.1 400 expected filesize 5242880 got 0\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php(100): OC\\\\Connector\\\\Sabre\\\\File->createFileChunked(Resource id #34)\\n#1 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/directory.php(113): OC\\\\Connector\\\\Sabre\\\\File->put(Resource id #34)\\n#2 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1053): OC\\\\Connector\\\\Sabre\\\\Directory->createFile('Stollfilm-1080p...', Resource id #34)\\n#3 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(513): Sabre\\\\DAV\\\\Server->createFile('Videos\\\/Stollfil...', Resource id #34, NULL)\\n#4 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#5 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#6 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(469): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#7 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#8 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files\\\/appinfo\\\/remote.php(83): Sabre\\\\DAV\\\\Server->exec()\\n#9 \\\/var\\\/www\\\/owncloud\\\/remote.php(132): require_once('\\\/var\\\/www\\\/ownclo...')\\n#10 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php\",\"Line\":346}","level":4,"time":"2015-10-02T09:40:56+02:00"}
{"reqId":"8SIEukrMqY2TwbBElQkR","remoteAddr":"2a01:1e8:e100:8204:2e41:38ff:fe8c:5542","app":"webdav","message":"Exception: {\"Message\":\"HTTP\\\/1.1 400 expected filesize 5242880 got 0\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php(100): OC\\\\Connector\\\\Sabre\\\\File->createFileChunked(Resource id #34)\\n#1 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/directory.php(113): OC\\\\Connector\\\\Sabre\\\\File->put(Resource id #34)\\n#2 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1053): OC\\\\Connector\\\\Sabre\\\\Directory->createFile('Stollfilm-1080p...', Resource id #34)\\n#3 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(513): Sabre\\\\DAV\\\\Server->createFile('Videos\\\/Stollfil...', Resource id #34, NULL)\\n#4 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#5 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#6 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(469): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#7 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#8 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files\\\/appinfo\\\/remote.php(83): Sabre\\\\DAV\\\\Server->exec()\\n#9 \\\/var\\\/www\\\/owncloud\\\/remote.php(132): require_once('\\\/var\\\/www\\\/ownclo...')\\n#10 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/file.php\",\"Line\":346}","level":4,"time":"2015-10-02T09:40:59+02:00"}

@stonerl
Copy link

stonerl commented Oct 2, 2015

Just on more question I did an lsin the cache folder:

-rw-r--r-- 1 www-data www-data 5.0M Oct  3  2015 Stollfilm-1080p.mp4-chunking-138980595-1
-rw-r--r-- 1 www-data www-data 5.0M Oct  3  2015 Stollfilm-1080p.mp4-chunking-138980595-10

Why is the timestamp for all files October 3 now? Today is the 2nd.

@PVince81
Copy link
Contributor

PVince81 commented Oct 2, 2015

Because that's how the chunk expiration code does it.
It sets the timestamp in the future.

Then during garbage collection, it expires all chunks which mtime is in
the past.

On 10/02/2015 02:53 PM, Toni Förster wrote:

Just on more question I did an lsin the cache folder:

-rw-r--r-- 1 www-data www-data 5.0M Oct  3  2015 Stollfilm-1080p.mp4-chunking-138980595-1
-rw-r--r-- 1 www-data www-data 5.0M Oct  3  2015 Stollfilm-1080p.mp4-chunking-138980595-10

Why is the timestamp for all files October 3 now? Today is the 2nd?


Reply to this email directly or view it on GitHub:
#3816 (comment)

@stonerl
Copy link

stonerl commented Oct 2, 2015

@PVince81 thanks allot

@stonerl
Copy link

stonerl commented Oct 8, 2015

Just an update. As I said before I have a second server. I was working with one of the users who uses this server and this very user also got the (expected filesize 5242880 got 0) error.

Should I open an issue in core? Is there any way I can debug this any further? The closest to figure out what is going on was in my second last post: #3816 (comment)

@PVince81
Copy link
Contributor

PVince81 commented Oct 8, 2015

@guruz: I had a chat with @stonerl on IRC and he told me that he had a resumable situation. Basically chunks fail from times to times but the second time it works. But if within the same transfer several chunks failed, the file still gets blacklisted. @guruz does that match the current implementation of the client ?

If yes I'd say the client should discard the blacklist counter value as soon as there is a successful chunk. Only if the same chunk fails over and over again, then blacklist the file.
Unless you are able to track on a chunk to chunk basis instead of transfer basis, but that might be overkill.

What do you think ?

@PVince81
Copy link
Contributor

PVince81 commented Oct 8, 2015

@guruz raised here #3934

@ljsjl
Copy link

ljsjl commented Oct 15, 2015

Hi,

I think I'm seeing this problem, or at least something that looks a lot like it:

  • OC server 8.1.3 from repos, running on stock up to date Ubuntu 14.04 server
  • Linux client 2.0.1 on a Ubuntu 14.04 desktop crashes almost immediately as it starts to resume uploading chunked files
  • A few chunks in cache/, a bunch of .part files in the appropriate directory tree on the server
  • Client log (owncloud --logfile ) has a few lines about "Forcing job aborts on HTTP connection reset with Qt < 5.4.2", and "FINISHED WITH STATUS 5 "Operation canceled" QVariant(, ) QVariant(, )", but other than that nothing really stands out that might lead to a crash. An assertion is the last line logged "0x135a460 ASSERT: "!_runningNow" in file /usr/src/packages/BUILD/src/libsync/owncloudpropagator.cpp, line 633"
  • Apache log shows some chunks returning a 401 error
  • Owncloud server logs error about filesize mismatch at time of client crash - "{"reqId":"yW5AL4CzzODScYmo7dUX","remoteAddr":"150.xxx.xxx.xxx","app":"webdav","message":"Exception: {"Message":"HTTP\/1.1 400 expected filesize 5242880 got 3702784"..."

This is a test environment so I can happily change clients, add/remove files etc. The files in question are created from scripts triggered by cron, and those scripts have been disabled for the time being.

If it would be useful I'll give more detail on the setup, log excerpts etc., or I can open another issue if that would be easier than adding to an already long thread.

Thanks

@andi-at
Copy link

andi-at commented Oct 19, 2015

Hello,
I have the same issue, and i think i figured out what mabe happens.
The problem occured on a few random files when uploading a big cloud for the first time. The desktop client gives erros "broken webserver returning empty content for non-empty file on resume", "operation cancelled", "connection closed". If i look at the status bar, i see that it stucks on the specific file at lets say 300/500kb.
Looking at the server the file is existing, but with a wrong size than the original! So i think in my case the upload of the original file got broken, but the server didn´t recognized it. It now has the filelenght in the DB, but the file on the disk is too small, and after a timeout occurs it throws the error.
Is that possible? I think the problem is on the server, not client!
Also, if i try to download the corrupted file per web interface the download doesn´t start, or downloads some kb and then fails.
Also the timestamp is incorrect, shows the upload date not the real creation date

@guruz
Copy link
Contributor

guruz commented Oct 19, 2015

@andi-at that sounds not good. would you have some infos about any special ownCloud apps or webserver modules you have installed?

@andi-at
Copy link

andi-at commented Oct 19, 2015

hello,
for shure, i haven´t changed anything. Just apt-get install owncloud on debian, and installed the needed certificates for ssl. The Upload was done by the owncloudcmd v2.0.1 client, but same happened at the desktop client before on another directory. yeah and i have turned on server side encryption, also cron job every 15 minutes (wich is working, i have checked it) I had to delete 3 files wich throw the error, since then it worked

Found out another creepy thing, the broken file on the server is acually BIGGER! than the original?!
And this seems to happen randomly, about 1 of 50 files has a wrong creation date showing up in the server (7 hours instead of 5 years ago...), so something is seriously going wrong here. But i have no idea how to reproduce this bug

@lhartmann
Copy link

I have been having this issue for weeks here. Long time since I last saw a successful sync. The separated behaviour (discover all then sync all) does not help either... The client should smart enough to scan and sync depth-first, so that it could resume faster after a failure...

POSSIBLE CAUSE:
Then I found a couple files with '\r' or '\n' (not sure which) in their names, probably got there by pasting the title of the article... Removed the newline and the issue is now sporadic instead of persistent.

All error messages were completely useless on the client... I expected at least 'Failed while syncing file "sample\nfile.png"', but instead got just connection closed...

EDIT: The connection close remains and the bad character is logged. I must have read a log where the connection was closed before the bad character was found...

@ogoffart
Copy link
Contributor

I tested with the latest version, and i correctly get a "Bad Request" from the server.

Ignoring the character would be the opposite of #3736

@adressler
Copy link

Why is this ticket closed? Is there any solution or fix?
Still getting the "HTTP/1.1 400 expected filesize…" bug from time to time for some big files, that could not be uploaded by the client. Current Windows client 2.1, server 8.1.3. I checked the release notes of server updates, but this issue is not addressed.

@PVince81
Copy link
Contributor

@adressler the important question is whether the sync client properly resumed the upload or is it always failing ? Because the message "400 expected filesize" can happen sometimes due to timeouts and is not a bug. If the upload resumes properly during the next run, there is nothing to worry about.
However if the same file fails uploading after several tries, there might be a bug.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests