Moving FutureFile after chunk assembly logs warning #31631

PVince81 · 2018-06-04T13:13:41Z

Steps

~~Run acceptance test from Test for chunking upload guests#212 with name features/apiGuests/guests.feature:44~~
~~cd tests/acceptance; ./run.sh features/apiWebdav/webdav-related-new-endpoint.feature:497~~
EDIT vicdeo:
since a55ce77#diff-4ab58a91bb1ef5af35805d89e6475100 it's
cd tests/acceptance; ./run.sh ./run.sh features/apiWebdav/webdav-related-new-endpoint.feature:38
Observe output then search for ".file"

Expected

No warning

Actual

Warning appears:

{"reqId":"nPvqv4sBxY2z8A77udaO","level":2,"time":"2018-06-04T13:04:12+00:00","remoteAddr":"127.0.0.1","user":"[email protected]","app":"dav","method":"MOVE","url":"\/remote.php\/dav\/uploads\/[email protected]\/chunking-42\/.file","message":"Could not get node for path: \"uploads\/[email protected]\/chunking-42\/.file\" : File with name \/\/chunking-42 could not be located"}

Version

With stable10 5114289 and guests PR which adds a new test owncloud/guests#212.

TODO

debug for stack trace

0  OCA\DAV\DAV\MiscCustomPropertiesBackend->delete() /srv/www/htdocs/owncloud/apps/dav/lib/DAV/MiscCustomPropertiesBackend.php:55
1  Sabre\DAV\PropertyStorage\Plugin->afterUnbind() /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/PropertyStorage/Plugin.php:126
2  call_user_func_array:{/srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php:105}() /srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php:105
3  OCA\DAV\Connector\Sabre\Server->emit() /srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php:105
4  Sabre\DAV\CorePlugin->httpMove() /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/CorePlugin.php:649
5  call_user_func_array:{/srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php:105}() /srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php:105
6  OCA\DAV\Connector\Sabre\Server->emit() /srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php:105
7  OCA\DAV\Connector\Sabre\Server->invokeMethod() /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php:479
8  OCA\DAV\Connector\Sabre\Server->exec() /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php:254
9  OCA\DAV\Server->exec() /srv/www/htdocs/owncloud/apps/dav/lib/Server.php:279
10 require_once()  /srv/www/htdocs/owncloud/apps/dav/appinfo/v2/remote.php:31
11 {main}          /srv/www/htdocs/owncloud/remote.php:165

confirm whether this also happens outside of guest app
check if regression
find good solution

@VicDeo I believed you touched this logic recently as part of #31093 and might understand it better.
The code states that this is supposed to be a "rare" situation here: https://github.com/owncloud/core/blob/stable10/apps/dav/lib/DAV/AbstractCustomPropertiesBackend.php#L245
But the reason the node is not found is because it was already moved (actually copied + deleted) after chunk assembly.

Would it be safe to ignore the exception here and prevent the log entry or is there some bigger issue hidden in there ?
Should this code also be covered by some logic grabbing the nodes beforehand like in #31093 ?

The text was updated successfully, but these errors were encountered:

PVince81 · 2018-06-04T13:19:05Z

Edited first post: this also happens in core, not isolated to guest app.

Need to run ./run.sh features/apiWebdav/webdav-related-new-endpoint.feature:497 and this appears:

[Mon Jun  4 15:17:41 2018] 127.0.0.1:39274 [201]: /remote.php/dav/uploads/user0/chunking-42/3
    And user "user0" uploads new chunk file "3" with "CCCCC" to id "chunking-42" using the API       # FeatureContext::userUploadsNewChunkFileOfWithToId()                                                                                                                                          
[Mon Jun  4 15:17:42 2018] Could not get node for path: "uploads/user0/chunking-42/.file" : File with name //chunking-42 could not be located
[Mon Jun  4 15:17:42 2018] 127.0.0.1:39290 [204]: /remote.php/dav/uploads/user0/chunking-42/.file
    And user "user0" moves new chunk file with id "chunking-42" to "/existingFile.txt" using the API # FeatureContext::userMovesNewChunkFileWithIdToMychunkedfile()

PVince81 · 2018-06-04T13:20:30Z

Same when uploading a big file (more than 10 MB) with the web UI on the same stable10 commit:

{"reqId":"rFabuJn3fxIV0pfA4faK","level":2,"time":"2018-06-04T13:19:54+00:00","remoteAddr":"127.0.0.1","user":"admin","app":"dav","method":"MOVE","url":"\/owncloud\/remote.php\/dav\/uploads\/admin\/web-file-upload-ec8866ce63c5779b9e37763591d1fa2b-1528118384658\/.file","message":"Could not get node for path: \"uploads\/admin\/web-file-upload-ec8866ce63c5779b9e37763591d1fa2b-1528118384658\/.file\" : File with name \/\/web-file-upload-ec8866ce63c5779b9e37763591d1fa2b-1528118384658 could not be located"}

PVince81 · 2018-06-04T13:34:54Z

Also happening on v10.0.8.

Bisect leads to 0422d32 from #29273

PVince81 · 2018-06-04T13:35:21Z

Leaving in backlog to be scheduled

ownclouders · 2018-06-04T13:36:07Z

GitMate.io thinks possibly related issues are #25493 (New chunking API assembly very slow), #25682 (New chunking: etags on the final MOVE), #18575 (Warning when moving two files to different storages.), #7887 (Warnings in logs on master), and #10358 (possibility to omit warnings about symbolic links in activity log).

VicDeo · 2018-06-04T13:36:12Z

@PVince81
ouch. too many factors here. chunks, guests, etc...
In general MiscCustomPropertiesBackend is used to store the properties for non-file entities like calendars and contacts.Those entities are referenced by path.

#31093 is irrelevant here as it applies to files only

VicDeo · 2018-06-04T13:38:38Z

@PVince81 probably this filter needs to be adjusted to ignore uploads directory https://github.com/owncloud/core/blob/stable10/apps/dav/lib/Server.php#L226

PVince81 · 2018-06-04T13:57:30Z

I hope this warning will not appear also for regular files in case of a move that requires copy + delete

VicDeo · 2018-06-25T20:50:46Z

@PVince81 #31890 reduces mention of .file
from 20 https://drone.owncloud.com/owncloud/core/8192/295
to 6 https://drone.owncloud.com/owncloud/core/8199/295
Is that enough? :)

PVince81 · 2018-06-26T07:58:08Z

that's a good start.

we should get rid of those completely as they are misleading and admins will think something is wrong: find out how to prevent MiscCustomPropertiesBackend to complain about deleted nodes (or exclude IFutureFile?)

VicDeo · 2018-06-26T08:09:30Z

@PVince81 The rest is not related to MiscCustomPropertiesBackend ;)

{"reqId":"YAd2623fYlxPvJ5eQoTY","level":0,"time":"2018-06-25T20:14:59+00:00","remoteAddr":"172.20.0.5","user":"user0","app":"webdav","method":"MOVE","url":"\/remote.php\/webdav\/uploads\/user0\/chunking-42\/.file","message":"Exception: {\"Message\":\"HTTP\\\/1.1 404 File with name uploads\\\/user0\\\/chunking-42\\\/.file could not be located\",\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\NotFound\",\"Code\":0,\"Trace\":\"#0 \\\/drone\\\/src\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/QuotaPlugin.php(89): 

{"reqId":"bUd2FZaE70g8qmMVthIk","level":4,"time":"2018-06-25T20:15:05+00:00","remoteAddr":"172.20.0.5","user":"user0","app":"webdav","method":"MOVE","url":"\/remote.php\/dav\/uploads\/user0\/chunking-42\/.file","message":"Exception: {\"Message\":\"HTTP\\\/1.1 400 Chunks on server do not sum up to 5 but to 15\",\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\BadRequest\",\"Code\":0,\"Trace\":\"#0 \\\/drone\\\/src\\\/apps\\\/dav\\\/lib\\\/Upload\\\/ChunkingPlugin.php(57): OCA\\\\DAV\\\\Upload\\\\ChunkingPlugin->verifySize()\\n#1 [internal function]: OCA\\\\DAV\\\\Upload\\\\ChunkingPlugin->beforeMove('uploads\\\/user0\\\/c...', 'files\\\/user0\\\/myC...')\\n#2

PVince81 · 2018-06-26T09:13:08Z

Oh... can you still look into the QuotaPlugin then ? Let me know if the fix would be too complex.

VicDeo · 2018-06-26T19:06:57Z

@PVince81 these failures seems to be expected:
New chunked upload PUT using old DAV path should fail
https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdav/webdav-related-new-endpoint.feature#L84

Scenario: New chunked upload MOVE using old DAV path should fail
https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdav/webdav-related-new-endpoint.feature#L95
Upload file via new chunking endpoint with wrong size header
https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdav/webdav-related-new-endpoint.feature#L111

phil-davis · 2018-06-27T01:58:34Z

I agree, there are acceptance tests that verify that if the client sends "wrong stuff" that the upload will fail with a reasonable 4nn code. Internally the code might do whatever while responding to such "naughty" clients.

PVince81 · 2018-06-27T07:43:27Z

failing is ok but does it log additional bogus entries ? if not then the current fix is enough

VicDeo · 2018-06-27T13:51:04Z

it's a pita to play detective trying to relate 800+ log entries to 75 test cases 😢
Given that there is nothing related to custom properties backend any more I'd better give up.

PeterPablo · 2018-07-31T06:52:33Z

From a users perspective I want to note that when uploading from Mac with Client 2.4.2 (rev 10200) to an ownCloud instance 10.0.9 with apache and mysql, I regularly receive the above mentioned error log entry:
{"reqId":"ce8015ee-0220-4df2-9d90-c35fb8e83116","level":2,"time":"2018-07-31T03:23:09+02:00","remoteAddr":"192.168.0.1","user":"peterpablo","app":"dav","method":"MOVE","url":"\/owncloud\/remote.php\/dav\/uploads\/peterpablo\/2579301221\/.file","message":"Could not get node for path: \"uploads\/peterpablo\/2579301221\/.file\" : File with name \/\/2579301221 could not be located"}
I am uploading as a user, so no guest app is involved.

Hopefully the supplied fix will resolve the log spam in 10.9.10. Am I correct in assuming the fix will be included in that upcoming release?

partial config.php

'dbtype' => 'mysql',
  'version' => '10.0.9.5',
  'dbname' => 'owncloud',
  'dbhost' => 'localhost',
  'dbtableprefix' => 'oc_',
  'dbuser' => 'owncloud',
  'dbpassword' => 'xxx',
  'logtimezone' => 'Europe/Berlin',
  'log_rotate_size' => 104857600,
  'installed' => true,
  'filelocking.enabled' => true,
  'memcache.local' => '\\OC\\Memcache\\Redis',
  'redis' => 
  array (
    'host' => 'localhost',
    'port' => 6379,
  ),
  'memcache.locking' => '\\OC\\Memcache\\Redis',
  'maintenance' => false,
  'theme' => '',
  'loglevel' => 2,
  'cron_log' => true,
  'mail_from_address' => 'peter.ploss',
  'mail_smtpmode' => 'php',
  'mail_domain' => 'gmail.com',
  'updatechecker' => false,
  'appstore.experimental.enabled' => true,
  'htaccess.RewriteBase' => '/owncloud',

PVince81 · 2018-07-31T07:05:49Z

the log spamming fix will be in 10.0.10

PVince81 added Type:Bug p3-medium Normal priority labels Jun 4, 2018

PVince81 added this to the backlog milestone Jun 4, 2018

PVince81 mentioned this issue Jun 4, 2018

Test for chunking upload owncloud/guests#212

Merged

PVince81 assigned VicDeo Jun 25, 2018

PVince81 modified the milestones: backlog, development Jun 25, 2018

VicDeo mentioned this issue Jun 25, 2018

Fix warning in logs while moving FutureFile after chunk assembly #31890

Merged

9 tasks

PVince81 closed this as completed in #31890 Jul 26, 2018

VicDeo mentioned this issue Jul 26, 2018

[Stable10] Fix warning in logs while moving FutureFile after chunk assembly #32166

Merged

9 tasks

PVince81 modified the milestones: development, QA Jan 11, 2019

lock bot locked as resolved and limited conversation to collaborators Jan 11, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Moving FutureFile after chunk assembly logs warning #31631

Moving FutureFile after chunk assembly logs warning #31631

PVince81 commented Jun 4, 2018 •

edited by VicDeo

Loading

PVince81 commented Jun 4, 2018

PVince81 commented Jun 4, 2018

PVince81 commented Jun 4, 2018

PVince81 commented Jun 4, 2018

ownclouders commented Jun 4, 2018

VicDeo commented Jun 4, 2018

VicDeo commented Jun 4, 2018

PVince81 commented Jun 4, 2018

VicDeo commented Jun 25, 2018

PVince81 commented Jun 26, 2018

VicDeo commented Jun 26, 2018

PVince81 commented Jun 26, 2018

VicDeo commented Jun 26, 2018

phil-davis commented Jun 27, 2018 •

edited

Loading

PVince81 commented Jun 27, 2018

VicDeo commented Jun 27, 2018 •

edited

Loading

PeterPablo commented Jul 31, 2018 •

edited

Loading

PVince81 commented Jul 31, 2018

Moving FutureFile after chunk assembly logs warning #31631

Moving FutureFile after chunk assembly logs warning #31631

Comments

PVince81 commented Jun 4, 2018 • edited by VicDeo Loading

Steps

Expected

Actual

Version

TODO

PVince81 commented Jun 4, 2018

PVince81 commented Jun 4, 2018

PVince81 commented Jun 4, 2018

PVince81 commented Jun 4, 2018

ownclouders commented Jun 4, 2018

VicDeo commented Jun 4, 2018

VicDeo commented Jun 4, 2018

PVince81 commented Jun 4, 2018

VicDeo commented Jun 25, 2018

PVince81 commented Jun 26, 2018

VicDeo commented Jun 26, 2018

PVince81 commented Jun 26, 2018

VicDeo commented Jun 26, 2018

phil-davis commented Jun 27, 2018 • edited Loading

PVince81 commented Jun 27, 2018

VicDeo commented Jun 27, 2018 • edited Loading

PeterPablo commented Jul 31, 2018 • edited Loading

PVince81 commented Jul 31, 2018

PVince81 commented Jun 4, 2018 •

edited by VicDeo

Loading

phil-davis commented Jun 27, 2018 •

edited

Loading

VicDeo commented Jun 27, 2018 •

edited

Loading

PeterPablo commented Jul 31, 2018 •

edited

Loading