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

Connection closed when unicode is present in filename #6516

Closed
JetUni opened this issue May 11, 2018 · 18 comments
Closed

Connection closed when unicode is present in filename #6516

JetUni opened this issue May 11, 2018 · 18 comments
Assignees
Labels
ReadyToTest QA, please validate the fix/enhancement Server Involved type:bug
Milestone

Comments

@JetUni
Copy link

JetUni commented May 11, 2018

Expected behaviour

The file should sync with the server, even if there is a Unicode character (specifically an emoji) in the filename

Actual behaviour

There is an error "Connection closed" and the syncing stops entirely. It won't even move on to the next files. At the very least it should move on and try that file again before it finishes syncing, but instead it just stops everything.

Steps to reproduce

  1. Place a bunch of files in a sync directory and make sure that one file has a Unicode character (I haven't tested with anything other than emojis) in the filename
  2. Let the client try to sync the directory
  3. Notice that once the sync gets to the file with a Unicode character, it stops and doesn't sync any other files

Server configuration

Operating system:
Ubuntu 16.04

Web server:
Apache

Database:
MySQL

PHP version:
7.0.28

ownCloud version:
10.0.8.5

Storage backend (external storage):
Stored locally, Cached with Redis

Client configuration

Client version:
2.4.1

Operating system:
Windows 10

OS language:
English

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

Logs

  1. Client logfile:
05-11 11:17:07:531 [ info gui.folder ]:	#### Propagation start ####################################################
05-11 11:17:07:532 [ info gui.application ]:	Sync state changed for folder  "https://my.jarrett.tk/remote.php/dav/files/jarrett/Docs" :  "Sync Running"
05-11 11:17:09:787 [ info sync.propagator ]:	Starting INSTRUCTION_NEW propagation of "Backups/Computers/BEAST-Laptop/Downloads/Video/Relive the best of Team USA at Rio ???? ??.MP4" by OCC::PropagateUploadFileV1(0x136f5f78)
05-11 11:17:09:787 [ info sync.checksums ]:	Computing "SHA1" checksum of "A:/Documents/Backups/Computers/BEAST-Laptop/Downloads/Video/Relive the best of Team USA at Rio ???? ??.MP4" in a thread
05-11 11:17:09:799 [ info sync.propagator.upload ]:	"/Docs/Backups/Computers/BEAST-Laptop/Downloads/Video/Relive the best of Team USA at Rio ???? ??.MP4" "SHA1:0bbde185b00fee7d8cc4b10736d8009a37bc12d4"
05-11 11:17:09:801 [ info sync.accessmanager ]:	3 "" "https://my.jarrett.tk/remote.php/dav/files/jarrett/Docs/Backups/Computers/BEAST-Laptop/Downloads/Video/Relive the best of Team USA at Rio ???? ??.MP4" has X-Request-ID "052a1f9d-2d75-4de7-8561-549be8698051"
05-11 11:17:09:801 [ info sync.networkjob ]:	OCC::PUTFileJob created for "https://my.jarrett.tk" + "/Docs/Backups/Computers/BEAST-Laptop/Downloads/Video/Relive the best of Team USA at Rio ???? ??.MP4" "OCC::PropagateUploadFileV1"
05-11 11:17:09:871 [ warning sync.networkjob ]:	QNetworkReply::NetworkError(RemoteHostClosedError) "Connection closed" QVariant(Invalid)
05-11 11:17:09:871 [ info sync.networkjob.put ]:	PUT of "https://my.jarrett.tk/remote.php/dav/files/jarrett/Docs/Backups/Computers/BEAST-Laptop/Downloads/Video/Relive the best of Team USA at Rio ???? ??.MP4" FINISHED WITH STATUS QNetworkReply::NetworkError(RemoteHostClosedError) "Connection closed" QVariant(Invalid) QVariant(Invalid)
05-11 11:17:09:871 [ warning sync.propagator ]:	Could not complete propagation of "Backups/Computers/BEAST-Laptop/Downloads/Video/Relive the best of Team USA at Rio ???? ??.MP4" by OCC::PropagateUploadFileV1(0x136f5f78) with status 1 and error: "Connection closed"
  1. Web server error log:
    None

  2. Server logfile: ownCloud log (data/owncloud.log):
    None

@ckamm ckamm added this to the 2.4.2-maybe milestone May 14, 2018
@ckamm ckamm added the type:bug label May 14, 2018
@ckamm
Copy link
Contributor

ckamm commented May 14, 2018

The remote closing the connection seems like the server is involved, but the sync should certainly not get stuck!

@JetUni Could you get another, more verbose log? (either with --logdebug or by switching on debug messages in the log window)

@ckamm
Copy link
Contributor

ckamm commented May 14, 2018

@JetUni The sync should abort after seeing this error from the server and that can take up to 5 seconds. You are saying the folder synchronization stays in the locked-up state indefinitely and there are no more log messages?

@ckamm
Copy link
Contributor

ckamm commented May 14, 2018

A hypothesis:

  • The PUTJob in UploadV1 finishes, goes to PropagateItemJob::done, which calls rootJob->abort() with a queued connection.
  • Afterwards the PUTJob calls deleteLater on itself, but the abort() gets invoked first
  • So when UploadV1::abort() gets called the PUTJob is still in the _jobs list and the async abort never finishes because QNetworkReply::finished is never called again

But why doesn't the 5s abort timeout fire, and why does the server close the connection in the first place?

@ogoffart
Copy link
Contributor

ogoffart commented May 14, 2018

I think the sync gets stuck because the client understands the closed connection as if the connection was dropped.
Maybe we should actually do a connectivity test in that case before interrupting the sync instead of just cutting it.

Edit: But this might not be the problem in this issue.
Edit2: I think it does after all.

@SamuAlfageme
Copy link
Contributor

@ckamm @ogoffart shouldn't the filename on the logs from the propagator be already normalized? the multiple "???" strikes me as weird. On macOS I get:

05-14 12:01:23:689 [ info sync.propagator ]:	Completed propagation of "❤️" by OCC::PropagateRemoteMove(0x7fb9ef453850) with status 4

@JetUni are you using some particular storage option as destination of your local sync folder?

@SamuAlfageme
Copy link
Contributor

Also, after #5661 sync should not be affected at all if one of these pops out in the process.

@SamuAlfageme
Copy link
Contributor

@JetUni since:

Database:
MySQL

If you are also unable to create files with 4-byte characters on its name via webUI, check owncloud-docker/base#4 (comment) for some instructions on how to migrate your DB to support these.

@ogoffart
Copy link
Contributor

Right, the fact that it is not proper in the log is indeed quite strange.
On windows, the encoding used for the log is the default one which comes from qt and is QTextCodec::codecForLocale(), which i think might be dependent of the language, but is likely to be latin1.
Perhaps we should force the log file to be written in UTF-8.

ckamm added a commit that referenced this issue May 14, 2018
Previously it tried to abort even jobs that had already finished, which
was not going to work as they wouldn't emit finished() again.

Also, in some cases the abortCount would never go to zero and that case
wasn't well documented.
@ckamm
Copy link
Contributor

ckamm commented May 14, 2018

I've cleaned up the upload abort code, but my guess was wrong: If a job has a fatalError in done() it'll not be in _runningJobs anymore when abort() is called, so that doesn't end up being the issue.

@JetUni
Copy link
Author

JetUni commented May 14, 2018

If you are also unable to create files with 4-byte characters on its name via webUI, check owncloud-docker/base#4 (comment) for some instructions on how to migrate your DB to support these.

Running occ db:convert-mysql-charset fixed it! However, I still think that the client shouldn't hang on one of these files and impede the rest of the files from being uploaded. I have another ownCloud install that I haven't changed the charset on and I'll be happy to test your changes when this is fixed! In my use case, I made a backup of my laptop before sending it for repairs and so there were thousands of files to be uploaded and it's in the same directory as all my school files, so I wasn't able to get to my new school files because the sync kept getting stuck on that one file.

@JetUni
Copy link
Author

JetUni commented May 14, 2018

@JetUni Could you get another, more verbose log? (either with --logdebug or by switching on debug messages in the log window)

I tried to limit the log as much as I could to give you just what you needed, but here is a log from the debug window taken today.

https://gist.github.com/JetUni/4deaf40e1b1c8ca49b2c06b02d03a730

@JetUni The sync should abort after seeing this error from the server and that can take up to 5 seconds. You are saying the folder synchronization stays in the locked-up state indefinitely and there are no more log messages?

See the log in the gist above, but basically there are 166 files trying to be synced in that gist and once it gets to the file with the unicode character, it stops. In this case, the problem file is number 34 or something like that, and so it only syncs 33 files.

@JetUni are you using some particular storage option as destination of your local sync folder?

I'm not sure I know what you mean. Does the log answer your question? If not, could you be more specific?

@SamuAlfageme
Copy link
Contributor

@JetUni glad to hear the DB commands worked out. Agree it should not block the syncing process; we will check for further client issues and track the progress here.

With "particular storage option as destination of your local sync folder" I meant if you e.g. might be using a different file system on the drive you're placing your sync that might have troubles with the filename encoding.

@JetUni
Copy link
Author

JetUni commented May 14, 2018

Both of my drives are formatted as ext4. The first device is the main OS drive and the second is my "Data" drive. I hope this helps you understand what's going on.

image


image


image

$ cat /var/www/owncloud/config/config.php | grep datadirectory
  'datadirectory' => '/media/Data/ocdata',

@michaelstingl
Copy link
Contributor

However, I still think that the client shouldn't hang on one of these files and impede the rest of the files from being uploaded.

Related: #5859 (Never ever abort sync runs) /cc @SamuAlfageme

@ckamm ckamm modified the milestones: 2.4.2-maybe, 2.5.0 May 15, 2018
@ckamm
Copy link
Contributor

ckamm commented May 15, 2018

@JetUni Thanks for the full log!

So the propagator doesn't get stuck, but the sync aborts when a "Connection closed" error is encountered.

Currently all network errors (Proxy, ssl. timeouts etc) are considered fatal. We could make RemoteHostClosedError not fatal. If the server replied with an error instead of closing the connection that also wouldn't abort the sync.

@ogoffart Your thoughts?

ckamm added a commit that referenced this issue May 15, 2018
Previously it tried to abort even jobs that had already finished, which
was not going to work as they wouldn't emit finished() again.

Also, in some cases the abortCount would never go to zero and that case
wasn't well documented.
@ogoffart
Copy link
Contributor

@ogoffart Your thoughts?

See my first comment to this issue. Where I suggested to do a connectivity check before aborting the sync.

But maybe you are right, RemoteHostClosedError probably does not indicate a connectivity error and we probably could classify it as a "NormalError"
If it is caused by a connectivity error, the next error would probably be different anyway.

ckamm added a commit that referenced this issue May 16, 2018
Because it sometimes appears in conjunction with server bugs and we
don't want to halt all syncing for other files in these cases.
@ckamm ckamm self-assigned this May 16, 2018
ckamm added a commit that referenced this issue May 17, 2018
Because it sometimes appears in conjunction with server bugs and we
don't want to halt all syncing for other files in these cases.
@ckamm ckamm added the ReadyToTest QA, please validate the fix/enhancement label May 18, 2018
@ckamm
Copy link
Contributor

ckamm commented May 18, 2018

@SamuAlfageme The specific thing that is done and could be tested is that ConnectionClosed will no longer abort the sync.

@SamuAlfageme
Copy link
Contributor

I'm using a proxy to drop the GET requests to a particular file every time.

Error is displayed prominently (i.e. up 'till the very tray menu) until the file gets to download, sync is never aborted/dropped. I'd say this can be closed 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
ReadyToTest QA, please validate the fix/enhancement Server Involved type:bug
Projects
None yet
Development

No branches or pull requests

5 participants