Skip to content

Error assembling chunks - chunks deleted too soon? #28589

Closed
#63122
Closed
Error assembling chunks - chunks deleted too soon?#28589
#63122
Labels
0. Needs triagePending check for reproducibility or if it fits our roadmapbugclient: 💻 desktopneeds info

Description

@solracsf
solracsf
opened on Aug 24, 2021

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

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    0. Needs triagePending check for reproducibility or if it fits our roadmapbugclient: 💻 desktopneeds info

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions