Error assembling chunks - chunks deleted too soon?

Here is the behavior, I'll comment it afterwards:

[00:27:32] "MKCOL /remote.php/dav/uploads/user/3697777450"                201
[00:27:34] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000000" 201
[00:27:53] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000001" 201
[00:28:12] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000002" 201
[00:28:31] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000003" 201
[00:28:51] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000004" 201
[00:29:10] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000005" 201
[00:29:28] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000006" 201
[00:29:47] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000007" 201
[00:30:03] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000008" 201
[00:30:21] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000009" 201
[00:30:36] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000010" 201
[00:30:50] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000011" 201
[00:31:08] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000012" 201 
[00:31:24] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000013" 201
[00:31:38] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000014" 201
[00:31:53] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000015" 201
[00:32:08] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000016" 201
[00:32:27] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000017" 201
[00:32:41] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000018" 201
[00:32:55] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000019" 201
[00:33:10] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000020" 201
[00:33:24] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000021" 201
[00:33:40] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000022" 201
[00:33:54] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000023" 201
[00:34:07] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000024" 201
[00:34:25] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000025" 201
[00:34:41] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000026" 201
[00:34:57] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000027" 201
[00:35:11] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000028" 201
[00:35:24] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000029" 201
[00:35:39] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000030" 201
[00:35:55] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000031" 201
[00:36:14] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000032" 201
[00:36:32] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000033" 201
[00:36:50] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000034" 201
[00:37:04] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000035" 201
[00:37:22] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000036" 201
[00:37:36] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000037" 201
[00:37:55] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000038" 201
[00:38:14] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000039" 201
[00:38:33] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000040" 201
[00:38:53] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000041" 201
[00:39:11] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000042" 201
[00:39:27] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000043" 201
[00:39:47] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000044" 201
[00:40:05] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000045" 201
[00:40:22] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000046" 201
[00:40:40] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000047" 201
[00:40:59] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000048" 201
[00:41:17] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000049" 201
[00:41:34] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000050" 201
[00:41:47] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000051" 201
[00:42:01] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000052" 201
[00:42:16] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000053" 201
[00:42:30] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000054" 201
[00:42:46] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000055" 201
[00:43:00] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000056" 201
[00:43:18] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000057" 201
[00:43:36] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000058" 201
[00:43:50] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000059" 201
[00:44:07] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000060" 201
[00:44:20] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000061" 201
[00:44:37] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000062" 201
[00:44:55] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000063" 201
[00:45:10] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000064" 201
[00:45:28] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000065" 201
[00:45:45] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000066" 201
[00:46:05] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000067" 201
[00:46:23] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000068" 201
[00:46:38] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000069" 201
[00:46:53] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000070" 201
[00:47:10] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000071" 201
[00:47:27] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000072" 201
[00:47:46] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000073" 201
[00:47:51] "PUT /remote.php/dav/uploads/user/3697777450/0000000000000074" 201
[02:40:58] "PROPFIND /remote.php/dav/uploads/user/3697777450"   207
[02:40:58] "MOVE /remote.php/dav/uploads/user/3697777450/.file" 423
[04:04:16] "MOVE /remote.php/dav/uploads/user/3697777450/.file" 503
[04:18:55] "PROPFIND /remote.php/dav/uploads/user/3697777450"   207
[04:35:58] "MOVE /remote.php/dav/uploads/user/3697777450/.file" 503
[12:54:46] "PROPFIND /remote.php/dav/uploads/user/3697777450"   207
[12:54:46] "MOVE /remote.php/dav/uploads/user/3697777450/.file" 503
[14:32:36] "PROPFIND /remote.php/dav/uploads/user/3697777450"   207
[14:32:37] "MOVE /remote.php/dav/uploads/user/3697777450/.file" 503
[14:53:29] "PROPFIND /remote.php/dav/uploads/user/3697777450"   207
[14:53:31] "MOVE /remote.php/dav/uploads/user/3697777450/.file" 503
[15:18:46] "PROPFIND /remote.php/dav/uploads/user/3697777450"   207
[15:18:46] "MOVE /remote.php/dav/uploads/user/3697777450/.file" 503
[15:45:57] "PROPFIND /remote.php/dav/uploads/user/3697777450"   207
[15:45:57] "MOVE /remote.php/dav/uploads/user/3697777450/.file" 503
[16:11:11] "PROPFIND /remote.php/dav/uploads/user/3697777450"   207
[16:11:11] "MOVE /remote.php/dav/uploads/user/3697777450/.file" 503
[19:47:51] "PROPFIND /remote.php/dav/uploads/user/3697777450"   207
[19:47:54] "MOVE /remote.php/dav/uploads/user/3697777450/.file" 503

So the Client (desktop, v3.3.0) started the upload of a pretty big file (7,4Gb) at 00:27
At 00:47 (20mn) the whole file has been uploaded (last chunk)
First strange behaviour is here; almost 2 hours later (why so late?) a first PROPFIND is issued on the chunked uploaded folder
It then tries to assemble the chunks (MOVE), but it get a LOCKED status (423), why?
1h35mn later, it gets a 503 (maybe related to the next log entry below)
It retries 20mn later, same result
Next retry is...8 hours later (?)
and it retries in a loop...at random times.

Problem is that, after step 5, it logs the following at nextcloud.log:

{
  "reqId": "SQOSQ9cCqCjFZlclWasO",
  "level": 3,
  "user": "user",
  "app": "PHP",
  "method": "MOVE",
  "url": "/remote.php/dav/uploads/user/3697777450/.file",
  "message": {
    "Exception": "Error",
    "Message": "fopen(/uploads/user/uploads/3697777450/0000000000000000): failed to open stream: No such file or directory at /lib/private/Files/Storage/Local.php#363",
    "Code": 0,
    "Trace": [
      {
        "function": "onError",
        "class": "OC\\Log\\ErrorHandler",
        "type": "::",
        "args": [
          2,
          "fopen(/uploads/user/uploads/3697777450/0000000000000000): failed to open stream: No such file or directory",
          "/lib/private/Files/Storage/Local.php",
          363,
          {
            "path": "3697777450/0000000000000000",
            "mode": "r",
            "oldMask": 18
          }
        ]
      },
      {
        "file": "/lib/private/Files/Storage/Local.php",
        "line": 363,
        "function": "fopen",
        "args": [
          "/uploads/user/uploads/3697777450/0000000000000000",
          "r"
        ]
      },
      {
        "file": "/lib/private/Files/View.php",
        "line": 1170,
        "function": "fopen",
        "class": "OC\\Files\\Storage\\Local",
        "type": "->",
        "args": [
          "3697777450/0000000000000000",
          "r"
        ]
      },
      {
        "file": "/lib/private/Files/View.php",
        "line": 1006,
        "function": "basicOperation",
        "class": "OC\\Files\\View",
        "type": "->",
        "args": [
          "fopen",
          "/3697777450/0000000000000000",
          [
            "read"
          ],
          "r"
        ]
      },
      {
        "file": "/apps/dav/lib/Connector/Sabre/File.php",
        "line": 434,
        "function": "fopen",
        "class": "OC\\Files\\View",
        "type": "->",
        "args": [
          "3697777450/0000000000000000",
          "r"
        ]
      },
      {
        "file": "/apps/dav/lib/Upload/AssemblyStream.php",
        "line": 295,
        "function": "get",
        "class": "OCA\\DAV\\Connector\\Sabre\\File",
        "type": "->",
        "args": []
      },
      {
        "file": "/apps/dav/lib/Upload/AssemblyStream.php",
        "line": 145,
        "function": "getStream",
        "class": "OCA\\DAV\\Upload\\AssemblyStream",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\DAV\\Connector\\Sabre\\File"
          }
        ]
      },
      {
        "function": "stream_read",
        "class": "OCA\\DAV\\Upload\\AssemblyStream",
        "type": "->",
        "args": [
          8192
        ]
      },
      {
        "file": "/3rdparty/icewind/streams/src/Wrapper.php",
        "line": 55,
        "function": "fread",
        "args": [
          null,
          8192
        ]
      },
      {
        "file": "/lib/private/Files/Stream/HashWrapper.php",
        "line": 64,
        "function": "stream_read",
        "class": "Icewind\\Streams\\Wrapper",
        "type": "->",
        "args": [
          8192
        ]
      },
      {
        "function": "stream_read",
        "class": "OC\\Files\\Stream\\HashWrapper",
        "type": "->",
        "args": [
          8192
        ]
      },
      {
        "file": "/3rdparty/icewind/streams/src/Wrapper.php",
        "line": 55,
        "function": "fread",
        "args": [
          null,
          8192
        ]
      },
      {
        "file": "/lib/private/Files/Stream/HashWrapper.php",
        "line": 64,
        "function": "stream_read",
        "class": "Icewind\\Streams\\Wrapper",
        "type": "->",
        "args": [
          8192
        ]
      },
      {
        "function": "stream_read",
        "class": "OC\\Files\\Stream\\HashWrapper",
        "type": "->",
        "args": [
          8192
        ]
      },
      {
        "file": "/3rdparty/icewind/streams/src/Wrapper.php",
        "line": 55,
        "function": "fread",
        "args": [
          null,
          8192
        ]
      },
      {
        "file": "/lib/private/Files/Stream/HashWrapper.php",
        "line": 64,
        "function": "stream_read",
        "class": "Icewind\\Streams\\Wrapper",
        "type": "->",
        "args": [
          8192
        ]
      },
      {
        "function": "stream_read",
        "class": "OC\\Files\\Stream\\HashWrapper",
        "type": "->",
        "args": [
          8192
        ]
      },
      {
        "file": "/3rdparty/icewind/streams/src/Wrapper.php",
        "line": 55,
        "function": "fread",
        "args": [
          null,
          8192
        ]
      },
      {
        "file": "/3rdparty/icewind/streams/src/CallbackWrapper.php",
        "line": 96,
        "function": "stream_read",
        "class": "Icewind\\Streams\\Wrapper",
        "type": "->",
        "args": [
          8192
        ]
      },
      {
        "function": "stream_read",
        "class": "Icewind\\Streams\\CallbackWrapper",
        "type": "->",
        "args": [
          8192
        ]
      },
      {
        "file": "/lib/private/Files/Storage/Local.php",
        "line": 282,
        "function": "file_put_contents",
        "args": [
          "/ofs/users/user/data/user/files/sauvok/COMM/Documents/Fichiers Outlook/comm@user.fr.pst",
          null
        ]
      },
      {
        "file": "/lib/private/Files/Storage/Local.php",
        "line": 570,
        "function": "file_put_contents",
        "class": "OC\\Files\\Storage\\Local",
        "type": "->",
        "args": [
          "files/sauvok/COMM/Documents/Fichiers Outlook/comm@user.fr.pst",
          null
        ]
      },
      {
        "file": "/lib/private/Files/Storage/Wrapper/Wrapper.php",
        "line": 629,
        "function": "writeStream",
        "class": "OC\\Files\\Storage\\Local",
        "type": "->",
        "args": [
          "files/sauvok/COMM/Documents/Fichiers Outlook/comm@user.fr.pst",
          null,
          null
        ]
      },
      {
        "file": "/apps/files_accesscontrol/lib/StorageWrapper.php",
        "line": 320,
        "function": "writeStream",
        "class": "OC\\Files\\Storage\\Wrapper\\Wrapper",
        "type": "->",
        "args": [
          "files/sauvok/COMM/Documents/Fichiers Outlook/comm@user.fr.pst",
          null,
          null
        ]
      },
      {
        "file": "/apps/dav/lib/Connector/Sabre/File.php",
        "line": 207,
        "function": "writeStream",
        "class": "OCA\\FilesAccessControl\\StorageWrapper",
        "type": "->",
        "args": [
          "files/sauvok/COMM/Documents/Fichiers Outlook/comm@user.fr.pst",
          null
        ]
      },
      {
        "file": "/apps/dav/lib/Connector/Sabre/Directory.php",
        "line": 156,
        "function": "put",
        "class": "OCA\\DAV\\Connector\\Sabre\\File",
        "type": "->",
        "args": [
          null
        ]
      },
      {
        "file": "/3rdparty/sabre/dav/lib/DAV/Tree.php",
        "line": 305,
        "function": "createFile",
        "class": "OCA\\DAV\\Connector\\Sabre\\Directory",
        "type": "->",
        "args": [
          "comm@user.fr.pst",
          null
        ]
      },
      {
        "file": "/3rdparty/sabre/dav/lib/DAV/Tree.php",
        "line": 133,
        "function": "copyNode",
        "class": "Sabre\\DAV\\Tree",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\DAV\\Upload\\FutureFile"
          },
          {
            "__class__": "OCA\\DAV\\Connector\\Sabre\\Directory"
          },
          "comm@user.fr.pst"
        ]
      },
      {
        "file": "/3rdparty/sabre/dav/lib/DAV/Tree.php",
        "line": 163,
        "function": "copy",
        "class": "Sabre\\DAV\\Tree",
        "type": "->",
        "args": [
          "uploads/user/3697777450/.file",
          "files/user/sauvok/COMM/Documents/Fichiers Outlook/comm@user.fr.pst"
        ]
      },
      {
        "file": "/apps/dav/lib/Upload/ChunkingPlugin.php",
        "line": 95,
        "function": "move",
        "class": "Sabre\\DAV\\Tree",
        "type": "->",
        "args": [
          "uploads/user/3697777450/.file",
          "files/user/sauvok/COMM/Documents/Fichiers Outlook/comm@user.fr.pst"
        ]
      },
      {
        "file": "/apps/dav/lib/Upload/ChunkingPlugin.php",
        "line": 77,
        "function": "performMove",
        "class": "OCA\\DAV\\Upload\\ChunkingPlugin",
        "type": "->",
        "args": [
          "uploads/user/3697777450/.file",
          "files/user/sauvok/COMM/Documents/Fichiers Outlook/comm@user.fr.pst"
        ]
      },
      {
        "file": "/3rdparty/sabre/event/lib/WildcardEmitterTrait.php",
        "line": 89,
        "function": "beforeMove",
        "class": "OCA\\DAV\\Upload\\ChunkingPlugin",
        "type": "->",
        "args": [
          "uploads/user/3697777450/.file",
          "files/user/sauvok/COMM/Documents/Fichiers Outlook/comm@user.fr.pst"
        ]
      },
      {
        "file": "/3rdparty/sabre/dav/lib/DAV/CorePlugin.php",
        "line": 603,
        "function": "emit",
        "class": "Sabre\\DAV\\Server",
        "type": "->",
        "args": [
          "beforeMove",
          [
            "uploads/user/3697777450/.file",
            "files/user/sauvok/COMM/Documents/Fichiers Outlook/comm@user.fr.pst"
          ]
        ]
      },
      {
        "file": "/3rdparty/sabre/event/lib/WildcardEmitterTrait.php",
        "line": 89,
        "function": "httpMove",
        "class": "Sabre\\DAV\\CorePlugin",
        "type": "->",
        "args": [
          {
            "__class__": "Sabre\\HTTP\\Request"
          },
          {
            "__class__": "Sabre\\HTTP\\Response"
          }
        ]
      },
      {
        "file": "/3rdparty/sabre/dav/lib/DAV/Server.php",
        "line": 472,
        "function": "emit",
        "class": "Sabre\\DAV\\Server",
        "type": "->",
        "args": [
          "method:MOVE",
          [
            {
              "__class__": "Sabre\\HTTP\\Request"
            },
            {
              "__class__": "Sabre\\HTTP\\Response"
            }
          ]
        ]
      },
      {
        "file": "/3rdparty/sabre/dav/lib/DAV/Server.php",
        "line": 253,
        "function": "invokeMethod",
        "class": "Sabre\\DAV\\Server",
        "type": "->",
        "args": [
          {
            "__class__": "Sabre\\HTTP\\Request"
          },
          {
            "__class__": "Sabre\\HTTP\\Response"
          }
        ]
      },
      {
        "file": "/3rdparty/sabre/dav/lib/DAV/Server.php",
        "line": 321,
        "function": "start",
        "class": "Sabre\\DAV\\Server",
        "type": "->",
        "args": []
      },
      {
        "file": "/apps/dav/lib/Server.php",
        "line": 332,
        "function": "exec",
        "class": "Sabre\\DAV\\Server",
        "type": "->",
        "args": []
      },
      {
        "file": "/apps/dav/appinfo/v2/remote.php",
        "line": 35,
        "function": "exec",
        "class": "OCA\\DAV\\Server",
        "type": "->",
        "args": []
      },
      {
        "file": "/remote.php",
        "line": 167,
        "args": [
          "/apps/dav/appinfo/v2/remote.php"
        ],
        "function": "require_once"
      }
    ],
    "File": "/lib/private/Log/ErrorHandler.php",
    "Line": 92,
    "CustomMessage": "--"
  },
  "userAgent": "Mozilla/5.0 (Windows) mirall/3.3.0stable-Win64 (build 20210729) (Nextcloud, windows-10.0.14393 ClientArchitecture: x86_64 OsArchitecture: x86_64)",
  "version": "21.0.4.1"
}

After check, /uploads/user/3697777450/ folder no longer exists and retries go on and on...filling the nextcloud logs with errors similar to #22509 after the previous one.

Uploads under 100Mb are uploaded correctly (i've not tested between 100Mb and 7Gb)

Questions

Is this normal behaviour?
Why is the chunked upload folder deleted, and retries going on?
And the hard one...How to correctly debug this? 🤔

Does this still happen after you've updated NC and the desktop client to the latest releases?

NC was already the latest v21, and Client is now v3.3.3 (and problem remains)

Hi, please update to 24.0.9 or better 25.0.3 and report back if it fixes the issue. Thank you!

My goal is to add a label like e.g. 25-feedback to this ticket of an up-to-date major Nextcloud version where the bug could be reproduced. However this is not going to work without your help. So thanks for all your effort!

If you don't manage to reproduce the issue in time and the issue gets closed but you can reproduce the issue afterwards, feel free to create a new bug report with up-to-date information by following this link: https://github.com/nextcloud/server/issues/new?assignees=&labels=bug%2C0.+Needs+triage&template=BUG_REPORT.yml&title=%5BBug%5D%3A+

Navigation Menu

Repository navigation

Error assembling chunks - chunks deleted too soon? #28589

Questions

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Error assembling chunks - chunks deleted too soon? #28589

Description

Questions

Activity

szaimen commented on Sep 15, 2021

solracsf commented on Sep 15, 2021

szaimen commented on Jan 23, 2023

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions