WebDAV spamming lock errors after remote davfs2 upload complete

Server
, ,
1

Steps to reproduce

  1. Create Dropbox external storage
  2. Share #1 with User
  3. Mount remote davfs2 folder with credentials to sync with #1
  4. Use Redis cache with file locking
  5. move 3GB file into remote davfs mount, where it then moves/copies the file to the davfs2_cache
  6. Small enough files will finish uploading to Dropbox without error or messages related to locked file
  7. (EDITED) Large files (over 2GB) being uploaded produce locked file error in owncloud.log.

Expected behaviour

No error message, and successful sync.

Actual behaviour

NGINX server log shows 423 response to remote davfs2 mount while other devices are getting 207 replies for calendar, etc.

Server configuration

Operating system: Ubuntu 18.04

Web server: NGINX

Database: MariaDB

PHP version: 7.2-fpm

ownCloud version: 10.3.2

Updated from an older ownCloud or fresh install: Updated from earlier 10.3 but not recently

Where did you install ownCloud from: Production tarball at https://owncloud.org/download/

Signing status (ownCloud 9.0 and above): no errors have been found

The content of config/config.php:

{
    "system": {
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "localhost",
            "owncloud.gbtechlab.com"
        ],
        "datadirectory": "\/usr\/share\/nginx\/html\/owncloud\/data",
        "dbtype": "mysql",
        "version": "10.3.0.4",
        "dbname": "owncloud",
        "dbhost": "localhost",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "dbtableprefix": "oc_",
        "logtimezone": "UTC",
        "installed": true,
        "instanceid": "oceec16j9824",
        "loglevel": 2,
        "maintenance": false,
        "memcache.local": "\\OC\\Memcache\\APCu",
        "filelocking.enabled": true,
        "filelocking.ttl": 3600,
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "\/var\/run\/redis\/redis-server.sock",
            "port": 0,
            "password": "***REMOVED SENSITIVE VALUE***",
            "timeout": 1.5
        },
        "debug": false,
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "smtp",
        "mail_smtpsecure": "tls",
        "mail_smtpauthtype": "LOGIN",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "587",
        "mail_smtpauth": 1,
        "mail_smtptimeout": 10
    },
    "apps": {
        "backgroundjob": {
            "lastjob": "37"
        },
        "calendar": {
            "enabled": "yes",
            "installed_version": "1.6.3",
            "signed": "true",
            "types": ""
        },
        "comments": {
            "enabled": "yes",
            "installed_version": "0.3.0",
            "types": "logging,dav"
        },
        "configreport": {
            "enabled": "yes",
            "installed_version": "0.2.0",
            "types": "filesystem"
        },
        "contacts": {
            "enabled": "yes",
            "installed_version": "1.5.5",
            "signed": "true",
            "types": ""
        },
        "core": {
            "allow_user_mount_sharing": "yes",
            "backgroundjobs_mode": "cron",
            "enable_external_storage": "yes",
            "installedat": "1535817092.8919",
            "lastcron": "1577811122",
            "lastupdateResult": "{\"version\":\"10.3.2\",\"versionstring\":\"ownCloud 10.3.2\",\"url\":\"https:\\\/\\\/download.owncloud.org\\\/community\\\/owncloud-10.3.2.zip\",\"web\":\"https:\\\/\\\/doc.owncloud.org\\\/server\\\/10.3\\\/admin_manual\\\/maintenance\\\/upgrade.html\"}",
            "lastupdatedat": "1577809426",
            "oc.integritycheck.checker": "[]",
            "public_files": "files_sharing\/public.php",
            "public_webdav": "dav\/appinfo\/v1\/publicwebdav.php",
            "shareapi_allow_links": "no",
            "shareapi_allow_public_upload": "no",
            "shareapi_allow_resharing": "no",
            "shareapi_allow_social_share": "no",
            "shareapi_enabled": "yes",
            "umgmt_show_email": "true",
            "updater.secret.created": "1562715072",
            "vendor": "owncloud"
        },
        "dav": {
            "enabled": "yes",
            "installed_version": "0.5.0",
            "types": "filesystem"
        },
        "federatedfilesharing": {
            "enabled": "yes",
            "installed_version": "0.5.0",
            "types": "filesystem"
        },
        "federation": {
            "enabled": "yes",
            "installed_version": "0.1.0",
            "types": "authentication"
        },
        "files": {
            "cronjob_scan_files": "500",
            "enabled": "yes",
            "installed_version": "1.5.2",
            "types": "filesystem"
        },
        "files_external": {
            "allow_user_mounting": "yes",
            "enabled": "yes",
            "installed_version": "0.7.1",
            "ocsid": "166048",
            "types": "filesystem",
            "user_mounting_backends": "owncloud"
        },
        "files_external_dropbox": {
            "enabled": "yes",
            "installed_version": "1.2.0",
            "signed": "true",
            "types": "filesystem"
        },
        "files_external_ftp": {
            "enabled": "yes",
            "installed_version": "0.2.1",
            "signed": "true",
            "types": "filesystem"
        },
        "files_mediaviewer": {
            "enabled": "yes",
            "installed_version": "1.0.1",
            "signed": "true",
            "types": ""
        },
        "files_sharing": {
            "enabled": "yes",
            "incoming_server2server_share_enabled": "no",
            "installed_version": "0.12.0",
            "outgoing_server2server_share_enabled": "no",
            "types": "filesystem"
        },
        "files_trashbin": {
            "enabled": "yes",
            "installed_version": "0.9.1",
            "types": "filesystem"
        },
        "files_versions": {
            "enabled": "yes",
            "installed_version": "1.3.0",
            "types": "filesystem"
        },
        "files_videoplayer": {
            "enabled": "no",
            "installed_version": "0.10.1",
            "types": ""
        },
        "firstrunwizard": {
            "enabled": "yes",
            "installed_version": "1.2.0",
            "ocsid": "166055",
            "types": ""
        },
        "market": {
            "calendar": "1.6.3",
            "enabled": "yes",
            "files_external_dropbox": "1.2.0",
            "files_external_ftp": "0.2.1",
            "files_mediaviewer": "1.0.1",
            "installed_version": "0.5.0",
            "key": null,
            "market": "0.4.0",
            "signed": "true",
            "twofactor_totp": "0.6.1",
            "types": ""
        },
        "notifications": {
            "enabled": "yes",
            "installed_version": "0.5.0",
            "types": "logging"
        },
        "provisioning_api": {
            "enabled": "yes",
            "installed_version": "0.5.0",
            "types": "prevent_group_restriction"
        },
        "systemtags": {
            "enabled": "yes",
            "installed_version": "0.3.0",
            "types": "logging"
        },
        "tasks": {
            "enabled": "yes",
            "installed_version": "0.9.7",
            "signed": "true",
            "types": ""
        },
        "twofactor_totp": {
            "enabled": "yes",
            "installed_version": "0.6.1",
            "signed": "true",
            "types": ""
        },
        "updatenotification": {
            "core": "10.3.2",
            "enabled": "yes",
            "installed_version": "0.2.1",
            "types": ""
        }
    }
}

List of activated apps:

Enabled:
  - calendar: 1.6.3
  - comments: 0.3.0
  - configreport: 0.2.0
  - contacts: 1.5.5
  - dav: 0.5.0
  - federatedfilesharing: 0.5.0
  - federation: 0.1.0
  - files: 1.5.2
  - files_external: 0.7.1
  - files_external_dropbox: 1.2.0
  - files_external_ftp: 0.2.1
  - files_mediaviewer: 1.0.1
  - files_sharing: 0.12.0
  - files_trashbin: 0.9.1
  - files_versions: 1.3.0
  - firstrunwizard: 1.2.0
  - market: 0.5.0
  - notifications: 0.5.0
  - provisioning_api: 0.5.0
  - systemtags: 0.3.0
  - tasks: 0.9.7
  - twofactor_totp: 0.6.1
  - updatenotification: 0.2.1
Disabled:
  - encryption
  - external
  - user_external

Are you using external storage, if yes which one: Dropbox

Are you using encryption: no

Are you using an external user-backend, if yes which one: no

Client configuration

Browser: NA

Operating system: Ubuntu 18.04

Logs

Web server error log

192.168.x.x - xxuserxx [31/Dec/2019:11:26:17 -0500] "PROPFIND /remote.php/dav/files/path/to/share/ HTTP/1.1" 207 3355 "-" "davfs2/1.5.5 neon/0.30.2"
192.168.x.x - xxuserxx [31/Dec/2019:11:35:08 -0500] "PUT /remote.php/dav/files/path/to/share/vzdump-qemu-xxxx.vma.lzo.gpg HTTP/1.1" 499 0 "-" "davfs2/1.5.5 neon/0.30.2"
192.168.x.x - xxuserxx [31/Dec/2019:11:38:35 -0500] "PUT /remote.php/dav/files/path/to/share/vzdump-qemu-xxxx.vma.lzo.gpg HTTP/1.1" 423 303 "-" "davfs2/1.5.5 neon/0.30.2

ownCloud log (data/owncloud.log)

{"reqId":"1N02jI7lhemOY6Yrvmdw","level":4,"time":"2019-12-31T16:39:37+00:00","remoteAddr":"192.168.x.x","user":"xxuserxx","app":"webdav","method":"PUT","url":"\/remote.php\/dav\/files\/path\/to\/share\/vzdump-qemu-xxxx.vma.lzo.gpg","message":"Exception: HTTP\/1.1 423 \"to\/share\/vzdump-qemu-xxxx.vma.lzo.gpg\" is locked: {\"Exception\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Exception\\\\FileLocked\",\"Message\":\"\\\"to\\\/share\\\/vzdump-qemu-xxxx2.vma.lzo.gpg\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1094): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('vzdump-xxxx...', Resource id #13)\\n#1 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(527): Sabre\\\\DAV\\\\Server->createFile('files\\\/path...', Resource id #13, NULL)\\n#2 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/event\\\/lib\\\/WildcardEmitterTrait.php(96): Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#3 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(464): Sabre\\\\DAV\\\\Server->emit('method:PUT', Array)\\n#4 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(241): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#5 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Server.php(326): Sabre\\\\DAV\\\\Server->start()\\n#6 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(31): OCA\\\\DAV\\\\Server->exec()\\n#7 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/remote.php(165): require_once('\\\/usr\\\/share\\\/ngin...')\\n#8 {main}\",\"File\":\"\\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php\",\"Line\":184}"}
{"reqId":"1N02jI7lhemOY6Yrvmdw","level":3,"time":"2019-12-31T16:39:37+00:00","remoteAddr":"192.168.1.42","user":"xxuserxx","app":"webdav","method":"PUT","url":"\/remote.php\/dav\/files\/path\/to\/share\/vzdump-qemu-xxxx.vma.lzo.gpg","message":"Caused by: {\"Exception\":\"OCP\\\\Lock\\\\LockedException\",\"Message\":\"\\\"to\\\/share\\\/vzdump-qemu-xxxx.vma.lzo.gpg\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/View.php(2100): OC\\\\Files\\\\View->lockPath('\\\/to\\\/share...', 1, false)\\n#1 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Node.php(364): OC\\\\Files\\\\View->lockFile('\\\/to\\\/share...', 1)\\n#2 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(171): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Node->acquireLock(1)\\n#3 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1094): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('vzdump-qemu-xxxx...', Resource id #13)\\n#4 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(527): Sabre\\\\DAV\\\\Server->createFile('files\\\/path...', Resource id #13, NULL)\\n#5 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/event\\\/lib\\\/WildcardEmitterTrait.php(96): Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#6 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(464): Sabre\\\\DAV\\\\Server->emit('method:PUT', Array)\\n#7 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(241): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#8 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Server.php(326): Sabre\\\\DAV\\\\Server->start()\\n#9 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(31): OCA\\\\DAV\\\\Server->exec()\\n#10 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/remote.php(165): require_once('\\\/usr\\\/share\\\/ngin...')\\n#11 {main}\",\"File\":\"\\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/View.php\",\"Line\":2002}"}
{"reqId":"1N02jI7lhemOY6Yrvmdw","level":3,"time":"2019-12-31T16:39:37+00:00","remoteAddr":"192.168.x.x","user":"xxuserxx","app":"webdav","method":"PUT","url":"\/remote.php\/dav\/files\/path\/to\/share\/vzdump-qemu-xxxx.vma.lzo.gpg","message":"Caused by: {\"Exception\":\"OCP\\\\Lock\\\\LockedException\",\"Message\":\"\\\"files\\\/3167ba79ca460d4ee1e7e06351af457f\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Common.php(658): OC\\\\Lock\\\\MemcacheLockingProvider->acquireLock('files\\\/3167ba79c...', 1)\\n#1 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(592): OC\\\\Files\\\\Storage\\\\Common->acquireLock('share\\\/vzdu...', 1, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#2 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(592): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->acquireLock('PveBackups\\\/vzdu...', 1, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#3 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(592): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->acquireLock('PveBackups\\\/vzdu...', 1, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#4 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(592): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->acquireLock('PveBackups\\\/vzdu...', 1, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#5 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/View.php(1997): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->acquireLock('PveBackups\\\/vzdu...', 1, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#6 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/View.php(2100): OC\\\\Files\\\\View->lockPath('\\\/db_gbtechlab\\\/P...', 1, false)\\n#7 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Node.php(364): OC\\\\Files\\\\View->lockFile('\\\/db_gbtechlab\\\/P...', 1)\\n#8 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(171): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Node->acquireLock(1)\\n#9 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1094): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('vzdump-qemu-xxxx...', Resource id #13)\\n#10 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(527): Sabre\\\\DAV\\\\Server->createFile('files\\\/path...', Resource id #13, NULL)\\n#11 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/event\\\/lib\\\/WildcardEmitterTrait.php(96): Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#12 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(464): Sabre\\\\DAV\\\\Server->emit('method:PUT', Array)\\n#13 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(241): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#14 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Server.php(326): Sabre\\\\DAV\\\\Server->start()\\n#15 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(31): OCA\\\\DAV\\\\Server->exec()\\n#16 \\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/remote.php(165): require_once('\\\/usr\\\/share\\\/ngin...')\\n#17 {main}\",\"File\":\"\\\/usr\\\/share\\\/nginx\\\/html\\\/owncloud\\\/lib\\\/private\\\/Lock\\\/MemcacheLockingProvider.php\",\"Line\":80}"}

Also,
system:cron is running on every minute.
No other web log errors.
No Php errors.
No Admin page errors.
The file hash referenced in the owncloud.log error is confirmed to be the key from the redis-server.

I can unmount remote davfs2, restart nginx server on owncloud, clear redis keys, and remount remote davfs2 mount and the process repeats exactly. The client server davfs2 cache continues to maintain large files and hangs as if there is never a proper notice the file is done uploading (but it is because the size matches).

Any help is appreciated, thanks.

2

From watching the TCP connections between the remote mount and the owncloud server, it reveals that the remote mount transfers a portion of the large file, then the connection between owncloud and Dropbox kicks in, which is locking the file. The error posts every few minutes as the remote mount attempts again. Then it gives up.

Is there a way to prevent the connection to Dropbox until the transfer of the complete file is done? Hard for me to see whether itā€™s davfs2 remotely that is pausing or owncloud.

EDIT: the following is seen in the /tmp folder. Is the duplication normal?

-rw-------  1 www-data www-data 3223039344 Jan  2 22:24 oc_tmp_jx531Q
-rw-------  1 www-data www-data    8000000 Jan  2 22:26 phpXIEbDX
-rw-------  1 www-data www-data 3223039344 Jan  2 22:24 phpzNZwuV

It seems strange that there is a PHP temp file in addition to an owncloud temp file. This is after the upload has completed. The file with size 8000000 changes names indicating that it is chunking the upload to Dropbox?

Is this duplication possibly the source of locking?

3

Have you noticed a certain time after which this happens? Sounds like there is some timeout kicking in, the length might indicate which one it is.

4

Iā€™ve edited post title and initial post to clarify is not a timeout but actually a completion of the uploadā€¦ but without proper release of the file, causing an error.

  1. The upload appears complete, so there should no longer be a need to use the file.
  2. Owncloud shows duplicate uploads in /tmp that are identical in size while uploading and complete simultaneously
  3. A third /tmp file appears with sync to Dropbox initiating
  4. Though upload is complete, file locked errors spam owncloud.log and my assumption is the upload process on the owncloud side is not allowing a verification of the upload and locking the (wrong?) file early.

I would think if there were duplicate /tmp files then the sync to Dropbox could begin immediately but this does not happen until uploaded file size equals full original file size (5.5Gb for example) .

I have changed davfs2 config settings on remote server to use/not use locks and there is no difference.

5

Hey,

i have searched a little bit around at the ownCloud bugtracker to see if a similar behavior was already reported to the ownCloud development team and had luck with the keywork oc_tmp and found the following issue by @cortho. Maybe this is related?

1 Like
6

Thanks for passing that along. I read through it, but it seems different than my situation.

I used the iotop command mentioned in the link and I can see that writing to the file ends after the remote davfs finishes transferring to the OC server. I also see that in the OC userā€™s web interface, there is a lock icon, but the file is displaying as being there (seems correct).
image

An error keeps getting logged, which I would think is not actually an error, but maybe should be a notice or something. The remote davfs is trying to access the file, but itā€™s locked because itā€™s being uploaded into Dropbox. And that seems perfectly acceptable, and not an error: the remote davfs can handle something being locked just fine.

I would also think that OC shouldnā€™t log that the remote davfs is attempting to use the file while itā€™s locked.

Log Error

{ā€œreqIdā€:ā€œRZWvT50saVGhk39B8TGEā€,ā€œlevelā€:4,ā€œtimeā€:ā€œ2020-01-20T16:05:04+00:00ā€,ā€œremoteAddrā€:ā€œ192.168.1.42ā€,ā€œuserā€:ā€œgbtechlabā€,ā€œappā€:ā€œwebdavā€,ā€œmethodā€:ā€œPUTā€,ā€œurlā€:"/remote.php/dav/files/gbtechlab/db_gbtechlab/PveBackups/vzdump-qemu-610-2019_12_28-00_15_02.vma.lzo.gpg",ā€œmessageā€:ā€œException: HTTP/1.1 423 ā€œdb_gbtechlab/PveBackups/vzdump-qemu-610-2019_12_28-00_15_02.vma.lzo.gpgā€ is locked: {ā€œExceptionā€:ā€œOCA\\DAV\\Connector\\Sabre\\Exception\\FileLockedā€,ā€œMessageā€:ā€\ā€œdb_gbtechlab\/PveBackups\/vzdump-qemu-610-2019_12_28-00_15_02.vma.lzo.gpg\ā€ is locked",ā€œCodeā€:0,ā€œTraceā€:"#0 \/usr\/share\/nginx\/html\/owncloud\/lib\/composer\/sabre\/event\/lib\/WildcardEmitterTrait.php(96): OCA\\DAV\\Connector\\Sabre\\LockPlugin->getLock(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#1 \/usr\/share\/nginx\/html\/owncloud\/lib\/composer\/sabre\/dav\/lib\/DAV\/Server.php(448): Sabre\\DAV\\Server->emit(ā€˜beforeMethod:PUā€¦ā€™, Array)\n#2 \/usr\/share\/nginx\/html\/owncloud\/lib\/composer\/sabre\/dav\/lib\/DAV\/Server.php(241): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#3 \/usr\/share\/nginx\/html\/owncloud\/apps\/dav\/lib\/Server.php(326): Sabre\\DAV\\Server->start()\n#4 \/usr\/share\/nginx\/html\/owncloud\/apps\/dav\/appinfo\/v2\/remote.php(31): OCA\\DAV\\Server->exec()\n#5 \/usr\/share\/nginx\/html\/owncloud\/remote.php(165): require_once(ā€™\/usr\/share\/nginā€¦ā€™)\n#6 {main}",ā€œFileā€:"\/usr\/share\/nginx\/html\/owncloud\/apps\/dav\/lib\/Connector\/Sabre\/LockPlugin.php",ā€œLineā€:71}"}

However! ā€¦
I do see that the rate of upload is projecting the completion of the upload to Dropbox to be very near the one hour markā€¦and this is possibly why the errors compound later.

So this could mean that the deletion of the temporary file actually botches the upload to Dropboxā€¦which makes that process stuck and unusable going forward. Permanently locked to the remote davfs, in theory. Yes?

1 Like
7

Yes, I think we have discovered two problems.

Problem 1: the remote davfs is attempting to ā€œPUTā€ the file after itā€™s finishedā€¦which is causing the FATAL error I posted above, caused by the file being locked too soon due to Dropbox upload (possibly similar logic to how Problem 2 occurs).

Problem 2: the oc_tmp_ cleanup removes the temporary file which has not finished uploading to Dropbox.

The web interface looks like this now, with the top file a size of 0, but showing as done:
image

The errors in the log change from a FATAL lock message (Connector/Sabre/LockPlugin.php, line 71) to a FATAL lock message with (Connector/Sabre/File.php, line 207).

Problem 2 is known, but what about Problem 1?

8

Okay, I figured it out after searching into the Sabre/Connector/File.php error and finding this: https://github.com/nextcloud/server/issues/9001

https://doc.owncloud.com/server/10.3/admin_manual/configuration/files/big_file_upload_configuration.html#long-running-uploads
I added this to config.php:

'filelocking.ttl' => 36000,

It solves a 3600 second timeout that occurs regarding locking.

1 Like