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

[stable9.1] [debug] Debug fclose wrapper #26735

Closed
wants to merge 3 commits into from

Conversation

PVince81
Copy link
Contributor

This will likely fill your logs so use with caution.

For every fopen and fclose it will log the stack trace.
Needs "loglevel => 0" in config.php.

Goal is to find out why adding fclose in readfile doesn't work.

Steps:

  1. Share a big file (ex: video) with link
  2. Open link
  3. Click "Download" button multiple times until the "normalizedPath" errors appears
  4. Check logs to find the error's request id, then paste all log entries that have the same request id.

@Webbeh

@mention-bot
Copy link

@PVince81, thanks for your PR! By analyzing the history of the files in this pull request, we identified @DeepDiver1975, @tanghus and @lenz1111 to be potential reviewers.

@PVince81
Copy link
Contributor Author

Weird, I wanted to paste my results but debug_backtrace() doesn't seem to work inside the callback

@PVince81 PVince81 force-pushed the stable9.1-fclose-wrapper-debug branch from 7dbb01e to b9782eb Compare November 28, 2016 09:47
@PVince81
Copy link
Contributor Author

Ok, I've adjuted the PR to limit the trace length. Apparently this makes it log something.

In my local env where the issue did not appear, here is how the trace looks like when downloading a public link file:

before callback:
[
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/Files/View.php",
    "line": 963,
    "function": "basicOperation",
    "class": "OC\\Files\\View",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/Files/View.php",
    "line": 425,
    "function": "fopen",
    "class": "OC\\Files\\View",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/legacy/files.php",
    "line": 303,
    "function": "readfile",
    "class": "OC\\Files\\View",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/legacy/files.php",
    "line": 119,
    "function": "getSingleFile",
    "class": "OC_Files",
    "type": "::"
  },
  {
    "file": "/srv/www/htdocs/owncloud/apps/files_sharing/lib/Controllers/ShareController.php",
    "line": 508,
    "function": "get",
    "class": "OC_Files",
    "type": "::"
  },
  {
    "function": "downloadShare",
    "class": "OCA\\Files_Sharing\\Controllers\\ShareController",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php",
    "line": 159,
    "function": "call_user_func_array"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php",
    "line": 89,
    "function": "executeController",
    "class": "OC\\AppFramework\\Http\\Dispatcher",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/AppFramework/App.php",
    "line": 99,
    "function": "dispatch",
    "class": "OC\\AppFramework\\Http\\Dispatcher",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/public/AppFramework/App.php",
    "line": 135,
    "function": "main",
    "class": "OC\\AppFramework\\App",
    "type": "::"
  },
  {
    "file": "/srv/www/htdocs/owncloud/core/routes.php",
    "line": 140,
    "function": "dispatch",
    "class": "OCP\\AppFramework\\App",
    "type": "->"
  },
  {
    "function": "{closure}",
    "class": "OC\\Route\\Router",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/Route/Router.php",
    "line": 280,
    "function": "call_user_func"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/base.php",
    "line": 891,
    "function": "match",
    "class": "OC\\Route\\Router",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/index.php",
    "line": 54,
    "function": "handleRequest",
    "class": "OC",
    "type": "::"
  }
]

in callback:
[
  {
    "function": "OC\\Files\\{closure}",
    "class": "OC\\Files\\View",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php",
    "line": 109,
    "function": "call_user_func"
  },
  {
    "function": "stream_close",
    "class": "Icewind\\Streams\\CallbackWrapper",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/Files/View.php",
    "line": 432,
    "function": "fclose"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/legacy/files.php",
    "line": 303,
    "function": "readfile",
    "class": "OC\\Files\\View",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/legacy/files.php",
    "line": 119,
    "function": "getSingleFile",
    "class": "OC_Files",
    "type": "::"
  },
  {
    "file": "/srv/www/htdocs/owncloud/apps/files_sharing/lib/Controllers/ShareController.php",
    "line": 508,
    "function": "get",
    "class": "OC_Files",
    "type": "::"
  },
  {
    "function": "downloadShare",
    "class": "OCA\\Files_Sharing\\Controllers\\ShareController",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php",
    "line": 159,
    "function": "call_user_func_array"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php",
    "line": 89,
    "function": "executeController",
    "class": "OC\\AppFramework\\Http\\Dispatcher",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/AppFramework/App.php",
    "line": 99,
    "function": "dispatch",
    "class": "OC\\AppFramework\\Http\\Dispatcher",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/public/AppFramework/App.php",
    "line": 135,
    "function": "main",
    "class": "OC\\AppFramework\\App",
    "type": "::"
  },
  {
    "file": "/srv/www/htdocs/owncloud/core/routes.php",
    "line": 140,
    "function": "dispatch",
    "class": "OCP\\AppFramework\\App",
    "type": "->"
  },
  {
    "function": "{closure}",
    "class": "OC\\Route\\Router",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/private/Route/Router.php",
    "line": 280,
    "function": "call_user_func"
  },
  {
    "file": "/srv/www/htdocs/owncloud/lib/base.php",
    "line": 891,
    "function": "match",
    "class": "OC\\Route\\Router",
    "type": "->"
  },
  {
    "file": "/srv/www/htdocs/owncloud/index.php",
    "line": 54,
    "function": "handleRequest",
    "class": "OC",
    "type": "::"
  }
]

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

Nevermind my last comment, it was a typo.

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

{
"reqId":"wEuf1IfcoLNRS7K1Mp1F",
"remoteAddr":"153.109.1.95",
"app":"DEBUG",
"message":"before registering callback : [{"file":"/usr/share/webapps/owncloud/lib/private/Files/View.php",
"line":964,
"function":"basicOperation",
"class":"OC\\Files\\View",
"type":"->"},
{"file":"/usr/share/webapps/owncloud/lib/private/Files/View.php",
"line":450,
"function":"fopen",
"class":"OC\\Files\\View",
"type":"->"},
{"file":"/usr/share/webapps/owncloud/lib/private/legacy/files.php",
"line":276,
"function":"readfilePart",
"class":"OC\\Files\\View",
"type":"->"},
{"file":"/usr/share/webapps/owncloud/lib/private/legacy/files.php",
"line":119,
"function":"getSingleFile",
"class":"OC_Files",
"type":"::"},
{"file":"/usr/share/webapps/owncloud/apps/files_sharing/lib/Controllers/ShareController.php",
"line":508,
"function":"get",
"class":"OC_Files",
"type":"::"},
{"function":"downloadShare",
"class":"OCA\\Files_Sharing\\Controllers\\ShareController",
"type":"->"},
{"file":"/usr/share/webapps/owncloud/lib/private/AppFramework/Http/Dispatcher.php",
"line":159,
"function":"call_user_func_array"},
{"file":"/usr/share/webapps/owncloud/lib/private/AppFramework/Http/Dispatcher.php",
"line":89,
"function":"executeController",
"class":"OC\\AppFramework\\Http\\Dispatcher",
"type":"->"},
{"file":"/usr/share/webapps/owncloud/lib/private/AppFramework/App.php",
"line":99,
"function":"dispatch",
"class":"OC\\AppFramework\\Http\\Dispatcher",
"type":"->"},
{"file":"/usr/share/webapps/owncloud/lib/public/AppFramework/App.php",
"line":135,
"function":"main",
"class":"OC\\AppFramework\\App",
"type":"::"},
{"file":"/usr/share/webapps/owncloud/core/routes.php",
"line":140,
"function":"dispatch",
"class":"OCP\\AppFramework\\App",
"type":"->"},
{"function":"{closure}",
"class":"OC\\Route\\Router",
"type":"->"},
{"file":"/usr/share/webapps/owncloud/lib/private/Route/Router.php",
"line":280,
"function":"call_user_func"},
{"file":"/usr/share/webapps/owncloud/lib/base.php",
"line":891,
"function":"match",
"class":"OC\\Route\\Router",
"type":"->"},
{"file":"/usr/share/webapps/owncloud/index.php",
"line":54,
"function":"handleRequest",
"class":"OC",
"type":"::"}]",
"level":0,
"time":"2016-11-28T09:56:10+00:00",
"method":"GET",
"url":"/index.php/s/oRyje4oAFgIj2el/download",
"user":"--"}

@PVince81
Copy link
Contributor Author

@Webbeh was there no matching "in callback" entry ? Is this from a case where the normalizedPathCache entry was logged ?

@PVince81
Copy link
Contributor Author

Oh readfilePart not readfile ?

@Webbeh last time when you added fclose everywhere, did you also add one in readfilePart ? Are you using the video player ? AFAIK this method is used with range requests when streaming.

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

Yes I added fclose() everywhere it was missing inside /lib, therefore inside readfilePart too.

It was only using the "download" button, no video player.

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

In callback coming

@PVince81
Copy link
Contributor Author

@Webbeh which browser ? I was testing with Chromium 54 with the Download button.

and now... WTF ?!

{"reqId":"zyDiqn2PymJy2PhnXNk9","remoteAddr":"127.0.0.1","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC::$server in \/srv\/www\/htdocs\/owncloud\/lib\/public\/Util.php:157\nStack trace:\n#0 \/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/View.php(1152): OCP\\Util::writeLog('DEBUG', 'in callback: [{...', 0)\n#1 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#2 \/srv\/www\/htdocs\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#3 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#4 {main}\n  thrown at \/srv\/www\/htdocs\/owncloud\/lib\/public\/Util.php#157","level":3,"time":"2016-11-28T10:06:06+00:00","method":"POST","url":"\/owncloud\/index.php\/heartbeat","user":"admin"}

Looks like PHP is GC'ing resources from previous calls even in unrelated calls... the heartbeat doesn't do anything!

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

Firefox developer (aurora) 51.0a2

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

Apparently...
{"reqId":"22o91ElqsCWGxWKsJRj0","remoteAddr":"5.57.108.64","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC::$server in /usr/share/webapps/owncloud/lib/public/Util.php:157\nStack trace:\n#0 /usr/share/webapps/owncloud/lib/private/Files/View.php(1159): OCP\Util::writeLog('DEBUG', 'in callback: [{...', 0)\n#1 [internal function]: OC\Files\View->OC\Files\{closure}()\n#2 /usr/share/webapps/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#3 [internal function]: Icewind\Streams\CallbackWrapper->stream_close()\n#4 {main}\n thrown at /usr/share/webapps/owncloud/lib/public/Util.php#157","level":3,"time":"2016-11-28T10:14:58+00:00","method":"GET","url":"/index.php/s/4tZatiMP55WhAc9/download","user":"--"}

Can't access \OCP\Util:writeLog from inside the callback... weird.

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

I mailed myself the backtrace instead :

[{"function":"OC\\Files\\{closure}","class":"OC\\Files\\View","type":"->"},{"file":"/usr/share/webapps/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php","line":109,"function":"call_user_func"},{"function":"stream_close","class":"Icewind\\Streams\\CallbackWrapper","type":"->"}]

Received a few of them, they're all the same, even for different files.

@PVince81
Copy link
Contributor Author

Yes, that's another static method. I think it's a variant of the original bug but specific to this PR/patch.

Looks like the failing trace in your case starts directly in the View method in the callback.

I'm more and more suspecting a PHP 7 GC bug and will do more research in that direction.

@Webbeh which PHP version do you have ? I have 7.0.7.

In my test case it always uses readfile and never readfilePart, so it must run the fclose that was added in the patch.

Now I also wonder: if the download is finished early, usually the browser might decide to close the network connection early. In some cases this could lead to the PHP process to get killed, so maybe here it wouldn't reach fclose at all.

I'll add more logging inside readfile and readfilePart so we can see if it even reached fclose.

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

PHP 7.0.13.

Should I remove all the fclose() I added ?

I also have readfile and not only readfilePart.

`
{
"reqId": "yuD4Lc8ta5nlVvSjXwIn",
"remoteAddr": "59.102.97.182",
"app": "DEBUG",
"message": "before registering callback : [{"
file ":" / usr / share / webapps / owncloud / lib / private / Files / View.php ","
line ":964,"

function ":"
basicOperation ","
class ":"
OC\\ Files\\ View ","
type ":" - > "},{"
file ":" / usr / share / webapps / owncloud / lib / private / Files / View.php ","
line ":425,"

function ":"
fopen ","
class ":"
OC\\ Files\\ View ","
type ":" - > "},{"
file ":" / usr / share / webapps / owncloud / lib / private / legacy / files.php ","
line ":303,"

function ":"
readfile ","
class ":"
OC\\ Files\\ View ","
type ":" - > "},{"
file ":" / usr / share / webapps / owncloud / lib / private / legacy / files.php ","
line ":119,"

function ":"
getSingleFile ","
class ":"
OC_Files ","
type ":"::"},{"
file ":" / usr / share / webapps / owncloud / apps / files_sharing / lib / Controllers / ShareController.php ","
line ":508,"

function ":"
get ","
class ":"
OC_Files ","
type ":"::"},{"

function ":"
downloadShare ","
class ":"
OCA\\ Files_Sharing\\ Controllers\\ ShareController ","
type ":" - > "},{"
file ":" / usr / share / webapps / owncloud / lib / private / AppFramework / Http / Dispatcher.php ","
line ":159,"

function ":"
call_user_func_array "},{"
file ":" / usr / share / webapps / owncloud / lib / private / AppFramework / Http / Dispatcher.php ","
line ":89,"

function ":"
executeController ","
class ":"
OC\\ AppFramework\\ Http\\ Dispatcher ","
type ":" - > "},{"
file ":" / usr / share / webapps / owncloud / lib / private / AppFramework / App.php ","
line ":99,"

function ":"
dispatch ","
class ":"
OC\\ AppFramework\\ Http\\ Dispatcher ","
type ":" - > "},{"
file ":" / usr / share / webapps / owncloud / lib / public / AppFramework / App.php ","
line ":135,"

function ":"
main ","
class ":"
OC\\ AppFramework\\ App ","
type ":"::"},{"
file ":" / usr / share / webapps / owncloud / core / routes.php ","
line ":140,"

function ":"
dispatch ","
class ":"
OCP\\ AppFramework\\ App ","
type ":" - > "},{"

function ":" {
	closure
}
","
class ":"
OC\\ Route\\ Router ","
type ":" - > "},{"
file ":" / usr / share / webapps / owncloud / lib / private / Route / Router.php ","
line ":280,"

function ":"
call_user_func "},{"
file ":" / usr / share / webapps / owncloud / lib / base.php ","
line ":891,"

function ":"
match ","
class ":"
OC\\ Route\\ Router ","
type ":" - > "},{"
file ":" / usr / share / webapps / owncloud / index.php ","
line ":54,"

function ":"
handleRequest ","
class ":"
OC ","
type ":"::"}]",
"level": 0,
"time": "2016-11-28T10:26:40+00:00",
"method": "GET",
"url": "\/index.php\/s\/4tZatiMP55WhAc9\/download",
"user": "--"

`

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

I should maybe mention that I'm using REDIS as memcache.locking and memcache.local, not sure if it changes anything.

@PVince81 PVince81 force-pushed the stable9.1-fclose-wrapper-debug branch from b9782eb to 9af2e7d Compare November 28, 2016 10:45
@PVince81
Copy link
Contributor Author

Ok, first things first, let's find out why fclose seems to not work in the first place.

I've updated this PR to now log something before and after fclose. We'll see whether fclose is omitted when the error occurs. So far I have not been able to make the original issue appear on my env.

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

Do you have a good online JSON formatter ?

EDIT : separated requests. Still not received any "in callback" yet.

{"reqId":"AUeojYi7qmkY7nm6ogeJ","remoteAddr":"202.80.212.46","app":"DEBUG","message":"readfilePart: fopen","level":0,"time":"2016-11-28T10:55:27+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}
{"reqId":"AUeojYi7qmkY7nm6ogeJ","remoteAddr":"202.80.212.46","app":"DEBUG","message":"before registering callback : [{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":975,\"function\":\"basicOperation\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":456,\"function\":\"fopen\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":276,\"function\":\"readfilePart\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":119,\"function\":\"getSingleFile\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/apps\/files_sharing\/lib\/Controllers\/ShareController.php\",\"line\":508,\"function\":\"get\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"function\":\"downloadShare\",\"class\":\"OCA\\\\Files_Sharing\\\\Controllers\\\\ShareController\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":159,\"function\":\"call_user_func_array\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":89,\"function\":\"executeController\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/App.php\",\"line\":99,\"function\":\"dispatch\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/public\/AppFramework\/App.php\",\"line\":135,\"function\":\"main\",\"class\":\"OC\\\\AppFramework\\\\App\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/core\/routes.php\",\"line\":140,\"function\":\"dispatch\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\"},{\"function\":\"{closure}\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Route\/Router.php\",\"line\":280,\"function\":\"call_user_func\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/base.php\",\"line\":891,\"function\":\"match\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/index.php\",\"line\":54,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\"}]","level":0,"time":"2016-11-28T10:55:27+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}
{"reqId":"AUeojYi7qmkY7nm6ogeJ","remoteAddr":"202.80.212.46","app":"DEBUG","message":"readfilePart: fseek","level":0,"time":"2016-11-28T10:55:27+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}
{"reqId":"AUeojYi7qmkY7nm6ogeJ","remoteAddr":"202.80.212.46","app":"DEBUG","message":"readfilePart: before loop","level":0,"time":"2016-11-28T10:55:27+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}

{"reqId":"zWc6BvUNk7zEhNorcSqG","remoteAddr":"202.80.212.46","app":"DEBUG","message":"readfilePart: fopen","level":0,"time":"2016-11-28T10:55:31+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}
{"reqId":"zWc6BvUNk7zEhNorcSqG","remoteAddr":"202.80.212.46","app":"DEBUG","message":"before registering callback : [{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":975,\"function\":\"basicOperation\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":456,\"function\":\"fopen\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":276,\"function\":\"readfilePart\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":119,\"function\":\"getSingleFile\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/apps\/files_sharing\/lib\/Controllers\/ShareController.php\",\"line\":508,\"function\":\"get\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"function\":\"downloadShare\",\"class\":\"OCA\\\\Files_Sharing\\\\Controllers\\\\ShareController\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":159,\"function\":\"call_user_func_array\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":89,\"function\":\"executeController\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/App.php\",\"line\":99,\"function\":\"dispatch\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/public\/AppFramework\/App.php\",\"line\":135,\"function\":\"main\",\"class\":\"OC\\\\AppFramework\\\\App\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/core\/routes.php\",\"line\":140,\"function\":\"dispatch\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\"},{\"function\":\"{closure}\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Route\/Router.php\",\"line\":280,\"function\":\"call_user_func\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/base.php\",\"line\":891,\"function\":\"match\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/index.php\",\"line\":54,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\"}]","level":0,"time":"2016-11-28T10:55:31+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}
{"reqId":"zWc6BvUNk7zEhNorcSqG","remoteAddr":"202.80.212.46","app":"DEBUG","message":"readfilePart: fseek","level":0,"time":"2016-11-28T10:55:31+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}
{"reqId":"zWc6BvUNk7zEhNorcSqG","remoteAddr":"202.80.212.46","app":"DEBUG","message":"readfilePart: before loop","level":0,"time":"2016-11-28T10:55:31+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}

{"reqId":"b2p9enZOKK6cEOEZG2XK","remoteAddr":"202.80.212.46","app":"DEBUG","message":"readfilePart: fopen","level":0,"time":"2016-11-28T10:55:32+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}
{"reqId":"b2p9enZOKK6cEOEZG2XK","remoteAddr":"202.80.212.46","app":"DEBUG","message":"before registering callback : [{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":975,\"function\":\"basicOperation\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":456,\"function\":\"fopen\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":276,\"function\":\"readfilePart\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":119,\"function\":\"getSingleFile\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/apps\/files_sharing\/lib\/Controllers\/ShareController.php\",\"line\":508,\"function\":\"get\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"function\":\"downloadShare\",\"class\":\"OCA\\\\Files_Sharing\\\\Controllers\\\\ShareController\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":159,\"function\":\"call_user_func_array\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":89,\"function\":\"executeController\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/App.php\",\"line\":99,\"function\":\"dispatch\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/public\/AppFramework\/App.php\",\"line\":135,\"function\":\"main\",\"class\":\"OC\\\\AppFramework\\\\App\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/core\/routes.php\",\"line\":140,\"function\":\"dispatch\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\"},{\"function\":\"{closure}\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Route\/Router.php\",\"line\":280,\"function\":\"call_user_func\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/base.php\",\"line\":891,\"function\":\"match\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/index.php\",\"line\":54,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\"}]","level":0,"time":"2016-11-28T10:55:32+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}
{"reqId":"b2p9enZOKK6cEOEZG2XK","remoteAddr":"202.80.212.46","app":"DEBUG","message":"readfilePart: fseek","level":0,"time":"2016-11-28T10:55:32+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}
{"reqId":"b2p9enZOKK6cEOEZG2XK","remoteAddr":"202.80.212.46","app":"DEBUG","message":"readfilePart: before loop","level":0,"time":"2016-11-28T10:55:32+00:00","method":"GET","url":"\/index.php\/s\/DXOD0Ht5oAxqmib\/download","user":"--"}

{"reqId":"6LOCWMvkUm9VDTLnziOJ","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: fopen","level":0,"time":"2016-11-28T10:55:36+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"6LOCWMvkUm9VDTLnziOJ","remoteAddr":"41.218.182.211","app":"DEBUG","message":"before registering callback : [{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":975,\"function\":\"basicOperation\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":456,\"function\":\"fopen\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":276,\"function\":\"readfilePart\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":119,\"function\":\"getSingleFile\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/apps\/files_sharing\/lib\/Controllers\/ShareController.php\",\"line\":508,\"function\":\"get\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"function\":\"downloadShare\",\"class\":\"OCA\\\\Files_Sharing\\\\Controllers\\\\ShareController\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":159,\"function\":\"call_user_func_array\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":89,\"function\":\"executeController\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/App.php\",\"line\":99,\"function\":\"dispatch\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/public\/AppFramework\/App.php\",\"line\":135,\"function\":\"main\",\"class\":\"OC\\\\AppFramework\\\\App\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/core\/routes.php\",\"line\":140,\"function\":\"dispatch\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\"},{\"function\":\"{closure}\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Route\/Router.php\",\"line\":280,\"function\":\"call_user_func\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/base.php\",\"line\":891,\"function\":\"match\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/index.php\",\"line\":54,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\"}]","level":0,"time":"2016-11-28T10:55:36+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"6LOCWMvkUm9VDTLnziOJ","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: fseek","level":0,"time":"2016-11-28T10:55:36+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"6LOCWMvkUm9VDTLnziOJ","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: before loop","level":0,"time":"2016-11-28T10:55:36+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}

{"reqId":"CBzAqTxglkoCL4K+GFxA","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: fopen","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"CBzAqTxglkoCL4K+GFxA","remoteAddr":"41.218.182.211","app":"DEBUG","message":"before registering callback : [{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":975,\"function\":\"basicOperation\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":456,\"function\":\"fopen\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":276,\"function\":\"readfilePart\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":119,\"function\":\"getSingleFile\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/apps\/files_sharing\/lib\/Controllers\/ShareController.php\",\"line\":508,\"function\":\"get\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"function\":\"downloadShare\",\"class\":\"OCA\\\\Files_Sharing\\\\Controllers\\\\ShareController\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":159,\"function\":\"call_user_func_array\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":89,\"function\":\"executeController\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/App.php\",\"line\":99,\"function\":\"dispatch\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/public\/AppFramework\/App.php\",\"line\":135,\"function\":\"main\",\"class\":\"OC\\\\AppFramework\\\\App\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/core\/routes.php\",\"line\":140,\"function\":\"dispatch\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\"},{\"function\":\"{closure}\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Route\/Router.php\",\"line\":280,\"function\":\"call_user_func\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/base.php\",\"line\":891,\"function\":\"match\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/index.php\",\"line\":54,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\"}]","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"CBzAqTxglkoCL4K+GFxA","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: fseek","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"CBzAqTxglkoCL4K+GFxA","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: before loop","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}

{"reqId":"1aGRKlKwMNnwWFdZxmrm","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: fopen","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"1aGRKlKwMNnwWFdZxmrm","remoteAddr":"41.218.182.211","app":"DEBUG","message":"before registering callback : [{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":975,\"function\":\"basicOperation\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":456,\"function\":\"fopen\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":276,\"function\":\"readfilePart\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":119,\"function\":\"getSingleFile\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/apps\/files_sharing\/lib\/Controllers\/ShareController.php\",\"line\":508,\"function\":\"get\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"function\":\"downloadShare\",\"class\":\"OCA\\\\Files_Sharing\\\\Controllers\\\\ShareController\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":159,\"function\":\"call_user_func_array\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":89,\"function\":\"executeController\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/App.php\",\"line\":99,\"function\":\"dispatch\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/public\/AppFramework\/App.php\",\"line\":135,\"function\":\"main\",\"class\":\"OC\\\\AppFramework\\\\App\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/core\/routes.php\",\"line\":140,\"function\":\"dispatch\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\"},{\"function\":\"{closure}\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Route\/Router.php\",\"line\":280,\"function\":\"call_user_func\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/base.php\",\"line\":891,\"function\":\"match\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/index.php\",\"line\":54,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\"}]","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"1aGRKlKwMNnwWFdZxmrm","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: fseek","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"1aGRKlKwMNnwWFdZxmrm","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: before loop","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}

{"reqId":"gtN+BzGFGv8ziAcwJxrT","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: fopen","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"gtN+BzGFGv8ziAcwJxrT","remoteAddr":"41.218.182.211","app":"DEBUG","message":"before registering callback : [{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":975,\"function\":\"basicOperation\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":456,\"function\":\"fopen\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":276,\"function\":\"readfilePart\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":119,\"function\":\"getSingleFile\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/apps\/files_sharing\/lib\/Controllers\/ShareController.php\",\"line\":508,\"function\":\"get\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"function\":\"downloadShare\",\"class\":\"OCA\\\\Files_Sharing\\\\Controllers\\\\ShareController\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":159,\"function\":\"call_user_func_array\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":89,\"function\":\"executeController\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/App.php\",\"line\":99,\"function\":\"dispatch\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/public\/AppFramework\/App.php\",\"line\":135,\"function\":\"main\",\"class\":\"OC\\\\AppFramework\\\\App\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/core\/routes.php\",\"line\":140,\"function\":\"dispatch\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\"},{\"function\":\"{closure}\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Route\/Router.php\",\"line\":280,\"function\":\"call_user_func\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/base.php\",\"line\":891,\"function\":\"match\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/index.php\",\"line\":54,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\"}]","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"gtN+BzGFGv8ziAcwJxrT","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: fseek","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"gtN+BzGFGv8ziAcwJxrT","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: before loop","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}

{"reqId":"zPU1c417M+o6dFniEUYp","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: fopen","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"zPU1c417M+o6dFniEUYp","remoteAddr":"41.218.182.211","app":"DEBUG","message":"before registering callback : [{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":975,\"function\":\"basicOperation\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Files\/View.php\",\"line\":456,\"function\":\"fopen\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":276,\"function\":\"readfilePart\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":119,\"function\":\"getSingleFile\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/apps\/files_sharing\/lib\/Controllers\/ShareController.php\",\"line\":508,\"function\":\"get\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"function\":\"downloadShare\",\"class\":\"OCA\\\\Files_Sharing\\\\Controllers\\\\ShareController\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":159,\"function\":\"call_user_func_array\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":89,\"function\":\"executeController\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/AppFramework\/App.php\",\"line\":99,\"function\":\"dispatch\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/public\/AppFramework\/App.php\",\"line\":135,\"function\":\"main\",\"class\":\"OC\\\\AppFramework\\\\App\",\"type\":\"::\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/core\/routes.php\",\"line\":140,\"function\":\"dispatch\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\"},{\"function\":\"{closure}\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/private\/Route\/Router.php\",\"line\":280,\"function\":\"call_user_func\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/lib\/base.php\",\"line\":891,\"function\":\"match\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/usr\/share\/webapps\/owncloud\/index.php\",\"line\":54,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\"}]","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"zPU1c417M+o6dFniEUYp","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: fseek","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}
{"reqId":"zPU1c417M+o6dFniEUYp","remoteAddr":"41.218.182.211","app":"DEBUG","message":"readfilePart: before loop","level":0,"time":"2016-11-28T10:55:37+00:00","method":"GET","url":"\/index.php\/s\/ZG1E9MZi4HsJWdu\/download","user":"--"}


@Webbeh
Copy link

Webbeh commented Nov 28, 2016

[{"function":"OC\\Files\\{closure}","class":"OC\\Files\\View","type":"->"},{"file":"/usr/share/webapps/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php","line":109,"function":"call_user_func"},{"function":"stream_close","class":"Icewind\\Streams\\CallbackWrapper","type":"->"}]

-> Still the same.

@PVince81
Copy link
Contributor Author

@Webbeh I usually use CLI jsonlint -p but needs some manual search and replace with vim to discard all these evil extra backslashes.

It seems your log didn't contain any message about "preparing to fclose" or "fclose called".

I got lucky again locally, this is what I got:

{"reqId":"B6VaFKpQ2089z3zyYbve","remoteAddr":"127.0.0.1","app":"DEBUG","message":"readfile: after loop, preparing to fclose","level":0,"time":"2016-11-28T11:03:15+00:00","method":"GET","url":"\/owncloud\/index.php\/s\/MVDIETKPJRiiDUN\/download","user":"--"}
{"reqId":"B6VaFKpQ2089z3zyYbve","remoteAddr":"127.0.0.1","app":"DEBUG","message":"in callback: [{\"function\":\"OC\\\\Files\\\\{closure}\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php\",\"line\":109,\"function\":\"call_user_func\"},{\"function\":\"stream_close\",\"class\":\"Icewind\\\\Streams\\\\CallbackWrapper\",\"type\":\"->\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/View.php\",\"line\":435,\"function\":\"fclose\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":303,\"function\":\"readfile\",\"class\":\"OC\\\\Files\\\\View\",\"type\":\"->\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/lib\/private\/legacy\/files.php\",\"line\":119,\"function\":\"getSingleFile\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/apps\/files_sharing\/lib\/Controllers\/ShareController.php\",\"line\":508,\"function\":\"get\",\"class\":\"OC_Files\",\"type\":\"::\"},{\"function\":\"downloadShare\",\"class\":\"OCA\\\\Files_Sharing\\\\Controllers\\\\ShareController\",\"type\":\"->\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":159,\"function\":\"call_user_func_array\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php\",\"line\":89,\"function\":\"executeController\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/lib\/private\/AppFramework\/App.php\",\"line\":99,\"function\":\"dispatch\",\"class\":\"OC\\\\AppFramework\\\\Http\\\\Dispatcher\",\"type\":\"->\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/lib\/public\/AppFramework\/App.php\",\"line\":135,\"function\":\"main\",\"class\":\"OC\\\\AppFramework\\\\App\",\"type\":\"::\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/core\/routes.php\",\"line\":140,\"function\":\"dispatch\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\"},{\"function\":\"{closure}\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/lib\/private\/Route\/Router.php\",\"line\":280,\"function\":\"call_user_func\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/lib\/base.php\",\"line\":891,\"function\":\"match\",\"class\":\"OC\\\\Route\\\\Router\",\"type\":\"->\"},{\"file\":\"\/srv\/www\/htdocs\/owncloud\/index.php\",\"line\":54,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\"}]","level":0,"time":"2016-11-28T11:03:15+00:00","method":"GET","url":"\/owncloud\/index.php\/s\/MVDIETKPJRiiDUN\/download","user":"--"}
{"reqId":"B6VaFKpQ2089z3zyYbve","remoteAddr":"127.0.0.1","app":"DEBUG","message":"readfile: fclose called","level":0,"time":"2016-11-28T11:03:15+00:00","method":"GET","url":"\/owncloud\/index.php\/s\/MVDIETKPJRiiDUN\/download","user":"--"}
{"reqId":"B6VaFKpQ2089z3zyYbve","remoteAddr":"127.0.0.1","app":"DEBUG","message":"readfile: got filesize: 60996827","level":0,"time":"2016-11-28T11:03:15+00:00","method":"GET","url":"\/owncloud\/index.php\/s\/MVDIETKPJRiiDUN\/download","user":"--"}
{"reqId":"B6VaFKpQ2089z3zyYbve","remoteAddr":"127.0.0.1","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC::$server in \/srv\/www\/htdocs\/owncloud\/lib\/public\/Util.php:157\nStack trace:\n#0 \/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/View.php(1164): OCP\\Util::writeLog('DEBUG', 'in callback: [{...', 0)\n#1 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#2 \/srv\/www\/htdocs\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#3 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#4 {main}\n  thrown at \/srv\/www\/htdocs\/owncloud\/lib\/public\/Util.php#157","level":3,"time":"2016-11-28T11:03:15+00:00","method":"GET","url":"\/owncloud\/index.php\/s\/MVDIETKPJRiiDUN\/download","user":"--"}

In short, they're all from the same request here:

  • readfile: after loop, preparing to fclose
  • in callback: ...
  • readfile: fclose called
  • readfile: got filesize: 60996827
  • Uncaught Error: Access to undeclared static property: OC::$server ...

This seems to tell us that fclose was called properly and also the callback did run.

Then why is it calling the callback a second time ? Maybe PHP is calling fclose twice on the same resource or something...

I'll do more testing. If that's the case, we might be able to check for duplicate fclose runs inside the stream wrapper and prevent this madness.

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

I have no occurence of close yet...

@PVince81
Copy link
Contributor Author

@Webbeh so you're only getting "before loop" but never after loop.
This might confirm my theory that as soon as the browser finished the download, it closes the network connection and this kills the PHP process for this request.

I'm using mod_php btw. Are you using php-fpm ? (I seem to remember that the latter was more brutal regarding to killing)

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

I actually have no idea, but I think it's mod_php7.

phpinfo() doesn't give any sign of having FPM but lists mod_php7.

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

Confirmed mod_php.

@PVince81
Copy link
Contributor Author

From http://php.net/manual/en/features.connection-handling.php

You can decide whether or not you want a client disconnect to cause your script to be aborted. Sometimes it is handy to always have your scripts run to completion even if there is no remote browser receiving the output. The default behaviour is however for your script to be aborted when the remote client disconnects. This behaviour can be set via the ignore_user_abort php.ini directive as well as through the corresponding php_value ignore_user_abort Apache httpd.conf directive or with the ignore_user_abort() function. If you do not tell PHP to ignore a user abort and the user aborts, your script will terminate.

I've updated the patch to call ignore_user_abort() in both readfile functions. Let's see if now your env can reach fclose properly: c075d3d

@PVince81
Copy link
Contributor Author

Hah, I think I got an idea for a trick: basically don't send the last block to the client yet and keep it until after fclose.

I'll first wait for your results to see if the theory matches and then can try it out.

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

Nope, no fclose even after ignore_user_abort() for big files.

They do appear for files that can be downloaded before the "undeclared static property" error appears.

@PVince81
Copy link
Contributor Author

@Webbeh can you precise whether it's going to readfile or readfilePart when you do see fclose ?

Are you using any download manager in Firefox ? I'm still surprised that it does range requests at all. Or maybe the default download manager downloads multiple pieces at once ? (like download managers often do to speed up download)

@Webbeh
Copy link

Webbeh commented Nov 28, 2016

No download manager.

Comes with readfile.

@PVince81
Copy link
Contributor Author

@Webbeh ok, another try: 4a8ba08

This should withhold the last packet and only send it after fclose of the source. Goal here is to prevent the browser to receive the last packet until we explicitly ran the source's resource. This would prevent the browser to kill the connection too early.

@PVince81
Copy link
Contributor Author

PVince81 commented Dec 1, 2016

@Webbeh are you able to try again with the last commit ?

@PVince81
Copy link
Contributor Author

PVince81 commented Dec 1, 2016

@@ -420,16 +420,27 @@ public function filesize($path) {
* @throws \OCP\Files\InvalidPathException
*/
public function readfile($path) {
ignore_user_abort();
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I forgot to set this to true... let's try it in the next-next run

@PVince81
Copy link
Contributor Author

PVince81 commented Dec 1, 2016

  • try with ignore_user_abort(true) (I missed the param previously)

@PVince81
Copy link
Contributor Author

PVince81 commented Dec 2, 2016

@davitol and I managed to recreate this issue on two separate envs where fclose is not called and does not appear in the logs. FINALLY some consistency!

On my side I used a script to close the connection too early during a download: #22370 (comment)

So far adding ignore_user_abort(true) seems to prevent the killing to happen and fclose is now reached.

@davitol
Copy link
Contributor

davitol commented Dec 2, 2016

Steps How I reproduced the issue.

Testing enviroment: owncloud-enterprise-complete-9.1.3RC1.tar.bz2 ubuntu_lamp_1604:latest PHP 7.0.8-0ubuntu0.16.04.2

  1. Share a big file (ex: video) with link
  2. Open link
  3. Using Mozilla Firefox 50.0.1 for OSX as browser, click "Download" button and cancel the dialog about saving the file.
  4. Check logs to find the log
{"reqId":"aPrTNZffEuaH4lCrPy3k","remoteAddr":"82.159.139.58","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache in \/opt\/owncloud\/lib\/private\/Files\/Filesystem.php:793\nStack trace:\n#0 \/opt\/owncloud\/lib\/private\/Files\/View.php(2039):

@PVince81
Copy link
Contributor Author

Closing as we have a solution

@PVince81 PVince81 closed this Dec 12, 2016
@PVince81 PVince81 deleted the stable9.1-fclose-wrapper-debug branch December 12, 2016 14:14
@lock
Copy link

lock bot commented Aug 4, 2019

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@lock lock bot locked as resolved and limited conversation to collaborators Aug 4, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants