[1.8.0] Window, Mac and Linux sync client: synchronisation error

[cdamken]

when I start the sync client (1.7.1 and 1.8.0) for the first time on a Linux machine, I always get: "connection closed" and "operation canceled".

After some seconds it starts again, but fails two or three times before it synchronize everything.

It suppose to be solved in https://github.com/owncloud/client/issues/2155 and https://github.com/owncloud/core/pull/11153

Tested with RHEL 6, oC 6.0.6 and Client 1.7.1

@MorrisJobke @dragotin @DeepDiver1975

Logs

S3-ownCloud\Shared\owncloud\support\github-issues\mirall\2689

00001912

[dragotin]

The client tries to download .zip or .ipa files (no idea what that is) and the connection is immediately closed. This is done by the server, so please investigate the server and proxy setup. We saw cases of nginx proxies that show this behaviour.

[danimo]

@dragotin .ipa files are iOS files, stored in zip containers (renamed extension), so it's the same problem.

[cdamken]

@danimo @dragotin Any news?

[cdamken]

@MorrisJobke Server involved, can you help me?

[MorrisJobke]

@cdamken I just have the client log.

01-07 08:19:11:400 0x16a6820   ** error Strings:  ("Connection closed", "Operation canceled", "Operation canceled", "163 error/gca4ea-polybox-sync-error.log: Operation canceled", "CentOS-6.5-x86_64-minimal - Copy.iso: Operation canceled", "CentOS-6.5-x86_64-minimal.iso: Connection closed") 
01-07 08:19:11:401 0x16a6820     * owncloud csync thread finished with error 
01-07 08:19:11:401 0x16a6820 the last 1 syncs failed 

Server owncloud.log, apache log (error and access) would be nice. Also maybe the sever architecture is of interest.

[cdamken]

@MorrisJobke I will ask for the logs

[dragotin]

Looks like this problem is not longer hot. Closing here, please either reopen here or in the server repo (if turns out that its a server problem). Thanks.

[cdamken]

OS: Red Hat Enterprise Linux Server release 6.6 (Santiago) PHP: PHP 5.3.3 HTTP: Apache/2.2.15 (Unix) MySQL: 5.1.73 Source distribution

LOG:

S3-ownCloud\Shared\owncloud\support\github-issues\mirall\2689\New Log File.txt

[MorrisJobke]

There are plenty of the following:

count	exception
1069	Sabre_DAV_Exception_NotFound
447	Sabre_DAV_Exception_Conflict
241	Sabre_DAV_Exception_Forbidden
144	Bind failed: 49: Invalid credentials
109	Sabre_DAV_Exception_UnsupportedMediaType
54	Sabre_DAV_Exception_InsufficientStorage
31	Sabre_DAV_Exception_PreconditionFailed
5	Sabre_DAV_Exception_BadRequest

Then just 6 lines left with some rename and access issues (nothing we should focus now)

@icewind1991 @DeepDiver1975 @PVince81 Which of the above are worth to look into?

[PVince81]

Possibly all of them... some might be related to cancelled uploads though.

[cdamken]

@DeepDiver1975 @icewind1991 @PVince81 @MorrisJobke could be a problem with the Storage?

I see in other logs a lot of errors like:

[Sun Mar 29 17:10:35 2015] [error] [client X.X.X.X] File does not exist: /var/www/html/owncloud/img, referer: https://XXXX(Server)/index.php/settings/personal

[PVince81]

@cdamken this errors seems to come from the "personal" page which is the settings page, so unlikely to be related. Maybe some app is trying to display an icon/image that is missing.

[cdamken]

@PVince81 Ok, thanks

BTW the problem still happens with 1.8.0 Any clue?

[caratsch]

@cdamken @PVince81 The new sync client fails more often with this error. I tried now a completely different instance with oC 7 and normal storage (not an NFS share like our productive system). The sync client fails with "connection closed" and "operation canceled" and doesn't automatically start again on OS X and Linux. On Windows 7 it fails, but it automatically continues after some seconds.

[cdamken]

I tested with Ubuntu and after it crash sometimes does continue and sometimes stops until you press pause and resume.

Log files from Ubuntu: S3-ownCloud\Shared\owncloud\support\github-issues\mirall\2689\download.zip

[moscicki]

@cdamken: I also see this against our server (which is a completely difference implementation). Is this a problem of the server closing connections or is this induced by the client? On the other hand, in all cases I witnessed, the client resumes after this error.

[cdamken]

@moscicki Which version of server and clients do you have?

I saw the problem with 6.0.6 and 7.0.5

With Windows Clients it resumes and continue until sometime it finish, but OsX and Linux, as @caratsch described above it stops syncing.

[dragotin]

@moscicki can you try to catch a wireshark protocol when that happens? Or mitmproxy? It would be great to see what actually happens on the wire.

[cdamken]

@dragotin I added in: S3-ownCloud\Shared\owncloud\support\github-issues\mirall\2689\

The following files: sync_client_180_connection_closed.log sync_client_180_connection_closed.tcpdump

that @caratsch provided me.

[danimo]

@cdamken If possible, make sure to ask for tcpdump output as pcap files. the tcpdump file does not provide the information we are looking for.

The syntax is tcpdump -w out.pcap. This would give us all the traffic for a given tcpdump run in out.pcap.

[cdamken]

@danimo wireshark_sync_client_180_error.log and wireshark_sync_client_180_error.pcapng on S3-ownCloud\Shared\owncloud\support\github-issues\mirall\2689\

[cdamken]

@danimo Are those files right? do you need something more?

[dragotin]

@DeepDiver1975 this is exactly the same effect we saw on the test system yesterday:

04-17 13:49:31:420 0x1fb6470 !!! OCC::GETFileJob created for  QUrl( "https://polybox.ethz.ch" )  querying "/163 error/gca4ea-polybox-sync-error.log" 
04-17 13:49:31:510 0x1fb6470 void OCC::AbstractNetworkJob::slotFinished() 2 "Connection closed" 
04-17 13:49:31:513 0x1fb6470 void OCC::PropagateDownloadFileQNAM::slotGetFinished()  QUrl( "https://polybox.ethz.ch/remote.php/webdav/1.7.1-sync-error-fedora20.txt" )  FINISHED WITH STATUS 2 "Connection closed" 
04-17 13:49:31:514 0x1fb6470 void OCC::SyncEngine::slotJobCompleted(const OCC::SyncFileItem&) "1.7.1-sync-error-fedora20.txt" INSTRUCTION_NEW 1 "Connection closed" 
04-17 13:49:31:519 0x1fb6470 void OCC::AbstractNetworkJob::slotFinished() 5 "Operation canceled" 

do you have any idea meantime?

[moscicki]

@dragotin, @DeepDiver1975 : I still owe you the wireshark analysis. But... I also see it on our server. So it may be a problem in the client networking stack and not necessarily a server problem?

I also have a hard time to reproduce it on linux wheras on Windows it is much more frequent. This is just my impression.

[dragotin]

@jnfrmarks This problem is still fishy. Please, if you do smashbox tests, keep the eyes open for this problem, thanks.

[craigpg]

@DeepDiver1975, @dragotin - Trying to see if we have next steps on this one. Are we waiting for additional log files or to somehow reproduce this in our test environment? Some logs have been posted above (e.g. wireshark) but it's not clear we've gone through them. Please clarify if you can. Thx.

[cdamken]

@craigpg I can reproduce it in S3 today:

Client 1.8.0 (Build 4893) Windows

[dragotin]

Can somebody please check the logs on s3: Check if there is an entry in owncloud.log at the time where this connection close happens in access_log. @danimo

[cdamken]

@dragotin @danimo testing 1.8.1 in mac happens the same error, now doesn't hang out anymore, it restarts after 30 seconds.

New Log

S3-ownCloud\Shared\owncloud\support\github-issues\mirall\2689\sync_client_181_connection_closed.log

[dragotin]

Please check apache access_log and owncloud.log from server for file

test-cyberduck/A.C.N. Vs Double Amp ft. Veela - Im A Liar (Nick Bounce Remix).mp3

at time 10:20:05:701

[cdamken]

@dragotin

The server log has another time 8:20, but that is the correct time for 10:20

Logs:

S3-ownCloud\Shared\owncloud\support\github-issues\mirall\2689\connection_error_181_logs.zip

[dragotin]

The server log shows tons of entries like

{"app":"PHP","message":"Undefined property: OCA\\user_ldap\\USER_LDAP::$connection at \/var\/www\/html\/owncloud\/apps\/user_ldap\/user_ldap.php#173","level":3,"time":"2015-05-11T08:20:04+00:00"}

at the time in question. Can it be that LDAP was not available and the server can not validate the user or such? @blizzz your input welcome!

[blizzz]

What ownCloud version is it? I guessed 6.0.6, but at the line mentioned there is no $connection used at all. Also connection is never a property of USER_LDAP, but the Access class.

[dragotin]

@cdamken your turn again.

[caratsch]

@dragotin @blizzz yes, it's version 6.0.6. If I'm not wrong, this error messages are created by the "second user display name field"-patch provided by you.

[cdamken]

@dragotin how about S3? there is no LDAP there.

@danimo Did you see anything in the logs?

[blizzz]

@caratsch ok, i see it. Bummer, but this will not lead to sync errors or lead to unavailability of LDAP server or service.

[dragotin]

Ok, I do understand that the LDAP logs are about some unrelated problem and do not cause the connection close problems in the logfile.

To be honest, I can't find any more hints what happens. Connection close is something the server is doing to an existing connection, there is no reason reported. I saw that happening for the following reasons

• the server tried to send a file with size X but the actual file was smaller, because of an inconsistency of between real and cached size.
• database lockups

Both could be the reason, but this is just speculation. Maybe its worth to check again if the server log is at the highest level, so that we do not miss server log entries?

[PVince81]

I think in general the server never explicitly closes the connection without giving a response or error response. So it is likely to be a timeout of some sorts where the PHP code didn't get a chance to return anything.

[dragotin]

@PVince81 right. Hard to debug now...

[cdamken]

@dragotin with 1.8.1 happens too, the only advantage is that it restart the search again and again.

[dragotin]

Yes, please ask the user to collect server logs with having logging switched on. The best would be a wireshark recording of one of these failing requests. Maybe that is possible?

[cdamken]

I will ask again,

but you can see some prevous wireshark recordings here: https://github.com/owncloud/client/issues/2689#issuecomment-93965636

[dragotin]

@cdamken the link to the wiresharks on s3 is dead.

[ckamm]

@cdamken I have been using your test account to try to reproduce the problem, but haven't encountered it yet. Can I provoke the error somehow? Does it usually happen at specific times?

You said it happened when you start the client for the first time on a Linux machine" - does that mean quitting and restarting the client will not produce the problem again?

[caratsch]

@ckamm You can try to reset the sync client and start a clean sync. The error normally shows up when you download from the server.

[guruz]

(Please ignore previous comment, my patch only makes it less likely by ~50%.)

[zambaraa]

I have the exact same issue on multiple machines. The server is installed on CentOS 6.6 (openvz vps) Server 8.0.3 (stable) (mysql+apache) - I have problems even with a newaccount uploads.

[cdamken]

@dragotin

@cdamken the link to the wiresharks on s3 is dead.

S3-ownCloud\Shared\owncloud\support\github-issues\mirall\2689

MIRALL folder not Client

[cdamken]

@dragotin @guruz The new log files are here:

S3-ownCloud\Shared\owncloud\support\github-issues\mirall\2689\New