core 🚀 - Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache

Any steps to reproduce?

Looks like the close callback is called during process teardown

icewind1991 on 17 Feb 2016

@LukasReschke any info ?

PVince81 on 23 Feb 2016

No idea. It just regularly appears on the S3 error logs :see_no_evil:

LukasReschke on 23 Feb 2016

@dragotin thought it could be related to timeout issues.

@icewind1991 if there is a timeout, would the PHP tear down still called ? (that was on S3)

PVince81 on 1 Mar 2016

Let's have a look at this as part of 9.0.1.

Would be good to have some logs. Sometimes cross-referencing the request id might help find out what else happened there. Maybe the audit log could help too.

PVince81 on 1 Mar 2016

I also remember that sometimes in the tear down routine, PHP starts unloading static variables so it is not guaranteed that they are still available within the tear down / destructors...

PVince81 on 1 Mar 2016

@LukasReschke is this still happening in the S3 logs ?

PVince81 on 9 Mar 2016

(well, after the update to 9.0.0...)

PVince81 on 9 Mar 2016

Can't quite tell. It's still on 8.2.2, apparently 9.0 is aimed for this weekend

LukasReschke on 9 Mar 2016

Looked at the code in the View: https://github.com/owncloud/core/blob/v8.2.3/lib/private/files/view.php#L1053 which calls unlock which itself uses the normalization function: https://github.com/owncloud/core/blob/v8.2.3/lib/private/files/view.php#L1920

The CallbackWrapper, IIRC, is called when the file gets closed.
There might be code paths and PHP versions in which the fclose is happening very late, at GC time.

If it's at GC time, it is likely that the GC has already destroyed that normalizedPathCache property from the static class. I saw this happen before.

The difficult part here is to find out which fclose call is missing, could be from an app.

PVince81 on 23 Mar 2016

Also, this is PHP 7, right ?

PVince81 on 23 Mar 2016

I've seen the same issue (I'm pretty sure its the same) on my Arch server, which was recently updated to php 7.
Client: 2.1.1
Server: 8.2.1

Aidenir on 4 Apr 2016

Same here with
PHP: 7 (also troubles with the same files with 5.6)
Client 2.1.1
Server 9.0.1

I even kicked out ACPu for testing - same result but still doing some tests to nail it down.

ToeiRei on 18 Apr 2016

Hmm, and maybe PHP 7's GC logic is different so it could confirm that this is PHP 7 specific.

PVince81 on 18 Apr 2016

@PVince81 So far I get a different error message on sync using PHP 5.6 - It's the same files that I cannot sync.

ToeiRei on 18 Apr 2016

cannot sync

The original issue was not about sync issues, just a mysterious warning.
Can you provide more information ? It isn't clear yet whether that message is directly related to sync issues.

PVince81 on 18 Apr 2016

That's what the error_log of apache2 says:

source: owncloud.server | message: [:error] [pid 29660] [client 192.168.1.190:35684] PHP Fatal error: Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /home/oc/owncloud/lib/private/files/filesystem.php:804 (...) { application_name: apache2 | gl2_source_node: bdffd45f-a36f-43a2-b4a2-1ce704fb47db | full_message: <187>1 2016-04-18T10:04:51.736384+02:00 stargazer apache2 29660 - - [:error] [pid 29660] [client 194.183.146.190:35684] PHP Fatal error: Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /home/oc/owncloud/lib/private/files/filesystem.php:804\nStack trace:\n#0 /home/oc/owncloud/lib/private/files/view.php(1977): OC\\Files\\Filesystem::normalizePath('/cbauer/files/M...')\n#1 /home/oc/owncloud/lib/private/files/view.php(1095): OC\\Files\\View->unlockFile('/MailStore/Data...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 /home/oc/owncloud/apps/files_external/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n thrown in /home/oc/owncloud/lib/private/files/filesystem.php on line 804 | gl2_remote_port: 44262 | gl2_remote_ip: 10.0.0.3 | timestamp: 2016-04-18T08:04:51.736Z | level: 3 | process_id: 29660 | facility: local7 | _id: 26e160a0-053c-11e6-9c52-000c29fb3aa1 | gl2_source_input: 5702a61c0cf2c929d96b791a | streams: [5702c17b0cf2c929d96b96f3] }

Those messages started to appear as soon as I had issues syncing a couple of files.

Setup: Apache2 using the PHP Module
Error message in the client says 'Server unavailable' - but the box is at a decent connection which shouldn't even drop packages.

Any chance to get the client to spill out debug logs?

ToeiRei on 18 Apr 2016

I guess in my case it was the client acting up. Nuking that one did drastically reduce the number of those messages and resolved the sync issues. Pretty weird if you ask me.

ToeiRei on 18 Apr 2016

I can confirm this on Ubuntu 16.04 with PHP 7 and MySQL 5.7 - ownCloud 9.0.1.

{"reqId":"iTsNNfGl7adS3E2QbmcS","remoteAddr":"99.163.30.109","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php:807\nStack trace:\n#0 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1977): OC\\Files\\Filesystem::normalizePath('\/daniel...')\n#1 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1095): OC\\Files\\View->unlockFile('\/_VMs\/ownCloud ...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 \/var\/www\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n  thrown at \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php#807","level":3,"time":"2016-05-13T04:16:16+02:00","method":"GET","url":"\/core\/js\/oc.js?v=26ed1e1c91e8e0412e1fe375a06eb902","user":"--"}
{"reqId":"WaV6P1ifbhBTRnUf\/CYU","remoteAddr":"99.163.30.109","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php:807\nStack trace:\n#0 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1977): OC\\Files\\Filesystem::normalizePath('\/daniel...')\n#1 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1095): OC\\Files\\View->unlockFile('\/_VMs\/ownCloud ...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 \/var\/www\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n  thrown at \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php#807","level":3,"time":"2016-05-13T04:24:19+02:00","method":"GET","url":"\/core\/js\/oc.js?v=26ed1e1c91e8e0412e1fe375a06eb902","user":"--"}
{"reqId":"8ARO4jLYMrmLl7z8SAs6","remoteAddr":"192.168.1.201","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php:807\nStack trace:\n#0 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1977): OC\\Files\\Filesystem::normalizePath('\/daniel...')\n#1 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1095): OC\\Files\\View->unlockFile('\/_VMs\/ownCloud ...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 \/var\/www\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n  thrown at \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php#807","level":3,"time":"2016-05-13T05:04:42+02:00","method":"GET","url":"\/ocs\/v2.php\/apps\/notifications\/api\/v1\/notifications?format=json","user":"daniel"}
{"reqId":"SkFCdie1WdYVQ2eZA19k","remoteAddr":"192.168.1.201","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php:807\nStack trace:\n#0 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1977): OC\\Files\\Filesystem::normalizePath('\/daniel...')\n#1 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1095): OC\\Files\\View->unlockFile('\/_VMs\/MineCraft...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 \/var\/www\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n  thrown at \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php#807","level":3,"time":"2016-05-13T05:19:11+02:00","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"daniel"}

enoch85 on 26 Apr 2016

Ref #23804 & https://github.com/owncloud/core/issues/23804#issuecomment-218288818

enoch85 on 13 May 2016

Is there a fix for this? It spams my log every time someone downloads from a public link. If there is a fix, please backport to stable 9. Thanks you @icewind1991

enoch85 on 13 May 2016

Still happens on 9.0.2 btw.

enoch85 on 13 May 2016

Steps to reproduce

Create a public link with a random file
Download that public link
Wait for ~10 seconds
Errors appears

These steps produces the error for me, but I'm not sure they work for everyone. What's strange is that it seems like the sync client (on XPS 13) throws and error on one of the attempts (I did 2 attempts).

{"reqId":"GJulUGLEvl+i5JrcrFCD","remoteAddr":"192.168.1.201","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php:807\nStack trace:\n#0 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1977): OC\\Files\\Filesystem::normalizePath('\/daniel...')\n#1 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1095): OC\\Files\\View->unlockFile('\/_VMs\/ownCloud ...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 \/var\/www\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n  thrown at \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php#807","level":3,"time":"2016-05-13T09:23:40+02:00","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"DELL-XPS13"}
{"reqId":"t5Hah4zinZhJTG1LPCZ6","remoteAddr":"192.168.1.201","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php:807\nStack trace:\n#0 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1977): OC\\Files\\Filesystem::normalizePath('\/daniel...')\n#1 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1095): OC\\Files\\View->unlockFile('\/_VMs\/MineCraft...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 \/var\/www\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n  thrown at \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php#807","level":3,"time":"2016-05-13T09:28:12+02:00","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"daniel"}

enoch85 on 13 May 2016

@icewind1991 can you have a look ? Possibly PHP 7 garbage collection race condition / order difference

PVince81 on 13 May 2016

Could this be fixed for 9.0.3? It spams my log. Please.

enoch85 on 22 May 2016

Same error here. My config:

Ubuntu 16.04,
oC 9.0.2.2,
Apache 2.4.18,
PHP 7.0.4,
MariaDB 10.01

When the error occus, the client stops and I'm not able to sync anything.

Error log:
[Mon May 23 00:46:08.321776 2016] [:error] [pid 2633] [client 83.61.36.110:64660] PHP Fatal error: Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /var/www/owncloud/lib/private/files/filesystem.php:807\nStack trace:\n#0 /var/www/owncloud/lib/private/files/view.php(1977): OC\\Files\\Filesystem::normalizePath('/Buzut/files/Bu...')\n#1 /var/www/owncloud/lib/private/files/view.php(1095): OC\\Files\\View->unlockFile('/Buzeo/Com-mark...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 /var/www/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n thrown in /var/www/owncloud/lib/private/files/filesystem.php on line 807

Buzut on 23 May 2016

👍1

@icewind1991 have you been able to reproduce this yet, with PHP 7.0.4 ?

PVince81 on 23 May 2016

@icewind1991 or can we add some safeguards that check whether that propery still exists in the __destruct code that uses it ? If that object has been GC'd already then just bail out.
Might cause stray locks to appear though...

PVince81 on 23 May 2016

i have this Warning

PHP 7.0.4
Owncloud 9.0.1
Apache2
MySQL

Uncaught Error: Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache in /var/www/vhosts/cloud-surfer.eu/httpdocs/owncloud/lib/private/files/filesystem.php:807 Stack trace: #0 /var/www/vhosts/cloud-surfer.eu/httpdocs/owncloud/lib/private/files/view.php(1977): OC\Files\Filesystem::normalizePath('/Lars/files/vid...') #1 /var/www/vhosts/cloud-surfer.eu/httpdocs/owncloud/lib/private/files/view.php(1095): OC\Files\View->unlockFile('/videos/Nusskna...', 1) #2 [internal function]: OC\Files\View->OC\Files\{closure}() #3 /var/www/vhosts/cloud-surfer.eu/httpdocs/owncloud/apps/files_external/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure)) #4 [internal function]: Icewind\Streams\CallbackWrapper->stream_close() #5 {main} thrown at /var/www/vhosts/cloud-surfer.eu/httpdocs/owncloud/lib/private/files/filesystem.php#807

Exception: {"Message":"Bad Signature","Exception":"OC\\HintException","Code":0,"Trace":"#0 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/apps\/encryption\/lib\/crypto\/crypt.php(463): OCA\\Encryption\\Crypto\\Crypt->checkSignature('t161Vr8hSJB5Yk7...', 'M\\xBFK\\x8F\\xF6\\x83\\xC6\\x8C@A\\xDBR\\xBB\\xA7M...', 'ef9c2c997c1052d...')\n#1 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/apps\/encryption\/lib\/crypto\/encryption.php(363): OCA\\Encryption\\Crypto\\Crypt->symmetricDecryptFileContent('t161Vr8hSJB5Yk7...', 'M\\xBFK\\x8F\\xF6\\x83\\xC6\\x8C@A\\xDBR\\xBB\\xA7M...', 'AES-256-CTR', 0, 0)\n#2 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/lib\/private\/files\/stream\/encryption.php(459): OCA\\Encryption\\Crypto\\Encryption->decrypt('t161Vr8hSJB5Yk7...', 0)\n#3 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/lib\/private\/files\/stream\/encryption.php(290): OC\\Files\\Stream\\Encryption->readCache()\n#4 [internal function]: OC\\Files\\Stream\\Encryption->stream_read(8192)\n#5 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/apps\/files_external\/3rdparty\/icewind\/streams\/src\/Wrapper.php(83): fread(Resource id #90, 8192)\n#6 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/apps\/files_external\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(91): Icewind\\Streams\\Wrapper->stream_read(8192)\n#7 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_read(8192)\n#8 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/3rdparty\/sabre\/http\/lib\/Sapi.php(78): stream_copy_to_stream(Resource id #94, Resource id #98, '836339136')\n#9 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(470): Sabre\\HTTP\\Sapi::sendResponse(Object(Sabre\\HTTP\\Response))\n#10 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(248): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#11 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/apps\/dav\/appinfo\/v1\/webdav.php(55): Sabre\\DAV\\Server->exec()\n#12 \/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/remote.php(138): require_once('\/var\/www\/vhosts...')\n#13 {main}","File":"\/var\/www\/vhosts\/cloud-surfer.eu\/httpdocs\/owncloud\/apps\/encryption\/lib\/crypto\/crypt.php","Line":483,"User":"Lars"}

Happyfeet01 on 3 Jun 2016

@icewind1991 have you never seen this on your own instance ? I'm pretty sure you must be running PHP 7 too

PVince81 on 15 Jun 2016

This occured for me when I activated the app Tasks and went away after I deleted /apps/tasks
Some other apps I activated right before where not activated afterwards, but seem to activate fine now.

kvoit on 15 Jun 2016

Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache

Occurs for me when trying to upload large files 5 GB+ using OwnCloud 9.

Chromes console shows:
jquery.min.js?v=c5b8591…:6 POST https://MYCLOUD/index.php/apps/files/ajax/upload.php 413 ()

php.ini and nginx.conf and nginx virtualhost are set to accept up to 32 GB large uploads.

BentHaase on 17 Jun 2016

@ET-Bent Do you have enabled the Tasks App?

ghost on 17 Jun 2016

@RealRancor no it's not enabled. It was about three weeks ago though. But it is completely disabled / removed.

BentHaase on 17 Jun 2016

@PVince81 Shouldn't this be backported as well? This has been known for a while now, and still not fixed. It spams many users logs, mine as well.

enoch85 on 12 Jul 2016

@enoch85 once we are able to fix it, yes, a backport would be good.

PVince81 on 12 Jul 2016

Hello,
I have some observation - not sure if it helps.
Using the audioplayer app I can play a song right from the files-app (one click play).

The following errorlog might be helpfull:
It happened when I was playing one file (tv theme song...) and then clicked the second file (tetris.mp3) to play this.
by this click the first playback gets stopped and the second start.
To me it sounds like there is an issue with "releasing" the file that was previously accessed?

{"reqId":"uLyb1Jag8WOE6npGuZ9+","remoteAddr":"192.168.0.39","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache in ...
n#1 \/var\/www\/owncloud\/lib\/private\/files\/view.php(1129): OC\Files\View->unlockFile('\/tv theme songs...', 1)\
...n#5 {main}\n thrown at \/var\/www\/owncloud\/lib\/private\/files\/filesystem.php#798","level":3,"time":"August 26, 2016 20:32:56","method":"GET","url":"\/owncloud\/index.phpoplayer\/getaudiostream?file=tetris.mp3","user":"Admin"}

Rello on 26 Aug 2016

@Rello does it happen consistently, every time you do these steps ?
If yes, then this info can be useful to debug the issue.

Which audioplayer app ? The music app ? https://github.com/owncloud/music

PVince81 on 29 Aug 2016

@alphamat excellent, thanks.

Okay, interesting: I have setup PHP 7.0.10 with this audio player.
Now I don't see any warning in the logs for some reason.
However if I put a breakpoint in the closure and debug up to the erroring point, the debugger crashes when I try to evaluate the value. This happened for one of two connections.

This is likely because the garbage collector already discarded that static variable but we're still trying to access it here.

PVince81 on 29 Aug 2016

Now weird, even when closed manually from the audio player itself, the problem occurs here:

0  OC\Files\Filesystem::normalizePath() /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php:772
1  OC\Files\View->unlockFile() /srv/www/htdocs/owncloud/lib/private/Files/View.php:2032
2  OC\Files\View->OC\Files\{closure}() /srv/www/htdocs/owncloud/lib/private/Files/View.php:1150
3  call_user_func:{/srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php:109}() /srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php:109
4  Icewind\Streams\CallbackWrapper->stream_close() /srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php:109
5  OCA\audioplayer\AudioStream->stream() /srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php:0
6  OCA\audioplayer\AudioStream->start() /srv/www/htdocs/owncloud/apps/audioplayer/lib/audiostream.php:166
7  OCA\audioplayer\Controller\MusicController->getAudioStream() /srv/www/htdocs/owncloud/apps/audioplayer/controller/musiccontroller.php:134
8  call_user_func_array:{/srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:159}() /srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:159
9  OC\AppFramework\Http\Dispatcher->executeController() /srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:159
10 OC\AppFramework\Http\Dispatcher->dispatch() /srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:89
11 OC\AppFramework\App::main() /srv/www/htdocs/owncloud/lib/private/AppFramework/App.php:110
12 OC\AppFramework\Routing\RouteActionHandler->__invoke() /srv/www/htdocs/owncloud/lib/private/AppFramework/Routing/RouteActionHandler.php:46
13 call_user_func:{/srv/www/htdocs/owncloud/lib/private/Route/Router.php:280}() /srv/www/htdocs/owncloud/lib/private/Route/Router.php:280
14 OC\Route\Router->match() /srv/www/htdocs/owncloud/lib/private/Route/Router.php:280
15 OC::handleRequest() /srv/www/htdocs/owncloud/lib/base.php:891
16 {main}          /srv/www/htdocs/owncloud/index.php:39

And AH! The error appears actually in PHP's error_log, not at all in owncloud.log

PVince81 on 29 Aug 2016

Fuller stack:

[Mon Aug 29 18:18:21.057700 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP Fatal error:  Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php:772\nStack trace:\n#0 /srv/www/htdocs/owncloud/lib/private/Files/View.php(2032): OC\\Files\\Filesystem::normalizePath('/admin/files/te...')\n#1 /srv/www/htdocs/owncloud/lib/private/Files/View.php(1150): OC\\Files\\View->unlockFile('/test/4mat - Su...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 /srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n  thrown in /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php on line 772
[Mon Aug 29 18:18:21.057729 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP Stack trace:
[Mon Aug 29 18:18:21.057740 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP   1. {main}() /srv/www/htdocs/owncloud/index.php:0
[Mon Aug 29 18:18:21.057746 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP   2. OC::handleRequest() /srv/www/htdocs/owncloud/index.php:39
[Mon Aug 29 18:18:21.057751 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP   3. OC\\Route\\Router->match($url = *uninitialized*) /srv/www/htdocs/owncloud/lib/base.php:891
[Mon Aug 29 18:18:21.057757 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP   4. call_user_func:{/srv/www/htdocs/owncloud/lib/private/Route/Router.php:280}(*uninitialized*, *uninitialized*) /srv/www/htdocs/owncloud/lib/private/Route/Router.php:280
[Mon Aug 29 18:18:21.057762 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP   5. OC\\AppFramework\\Routing\\RouteActionHandler->__invoke($params = *uninitialized*) /srv/www/htdocs/owncloud/lib/private/Route/Router.php:280
[Mon Aug 29 18:18:21.057768 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP   6. OC\\AppFramework\\App::main($controllerName = *uninitialized*, $methodName = *uninitialized*, $container = *uninitialized*, $urlParams = *uninitialized*) /srv/www/htdocs/owncloud/lib/private/AppFramework/Routing/RouteActionHandler.php:46
[Mon Aug 29 18:18:21.057774 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP   7. OC\\AppFramework\\Http\\Dispatcher->dispatch($controller = *uninitialized*, $methodName = *uninitialized*) /srv/www/htdocs/owncloud/lib/private/AppFramework/App.php:110
[Mon Aug 29 18:18:21.057780 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP   8. OC\\AppFramework\\Http\\Dispatcher->executeController($controller = *uninitialized*, $methodName = *uninitialized*) /srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:89
[Mon Aug 29 18:18:21.057785 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP   9. call_user_func_array:{/srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:159}(*uninitialized*, *uninitialized*) /srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:159
[Mon Aug 29 18:18:21.057790 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP  10. OCA\\audioplayer\\Controller\\MusicController->getAudioStream() /srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:159
[Mon Aug 29 18:18:21.057795 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP  11. OCA\\audioplayer\\AudioStream->start() /srv/www/htdocs/owncloud/apps/audioplayer/controller/musiccontroller.php:134
[Mon Aug 29 18:18:21.057800 2016] [:error] [pid 409] [client 127.0.0.1:58224] PHP  12. OCA\\audioplayer\\AudioStream->stream() /srv/www/htdocs/owncloud/apps/audioplayer/lib/audiostream.php:166

Now I find it weird that even in this legitimate non-garbage-collection-y situation the problem occurs.

PVince81 on 29 Aug 2016

I added more log statements in the audio app and it looks like in the error case the loop never reaches the end, and something seems to trigger an implicit fclose() in the middle of the loop, which also triggers the callback. And at that point it seems the GC already did its job.
Ah, and I also added a public static var \OC\Files\Filesystem::$hey which I set in various places to test whether the object still exists or crash.

{"reqId":"Yh2bFkEgKhgQnSHTOBSy","remoteAddr":"127.0.0.1","app":"audioplayer","message":"stream $curPos=1957888 of 2035066","level":0,"time":"2016-08-29T16:37:42+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2015%20Soft%20Touch.ogg","user":"admin"}
{"reqId":"Yh2bFkEgKhgQnSHTOBSy","remoteAddr":"127.0.0.1","app":"audioplayer","message":"stream $curPos=1966080 of 2035066","level":0,"time":"2016-08-29T16:37:42+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2015%20Soft%20Touch.ogg","user":"admin"}
{"reqId":"Yh2bFkEgKhgQnSHTOBSy","remoteAddr":"127.0.0.1","app":"audioplayer","message":"stream $curPos=1974272 of 2035066","level":0,"time":"2016-08-29T16:37:42+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2015%20Soft%20Touch.ogg","user":"admin"}
{"reqId":"Yh2bFkEgKhgQnSHTOBSy","remoteAddr":"127.0.0.1","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$hey in \/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/View.php:1147\nStack trace:\n#0 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#1 \/srv\/www\/htdocs\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#2 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#3 {main}\n  thrown at \/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/View.php#1147","level":3,"time":"2016-08-29T16:37:42+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2015%20Soft%20Touch.ogg","user":"admin"}

PVince81 on 29 Aug 2016

Getting closer, it seems that the echo $data operation is making PHP jump and decide to KILL ALL THE THINGS.

{"reqId":"s0JbptlH\/77ngBJbufIq","remoteAddr":"127.0.0.1","app":"audioplayer","message":"stream $curPos=2957312 of 3027184","level":0,"time":"2016-08-29T16:42:00+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2009%20Pretty%20Prairie.ogg","user":"admin"}
{"reqId":"s0JbptlH\/77ngBJbufIq","remoteAddr":"127.0.0.1","app":"audioplayer","message":"fread of 8192 bytes","level":0,"time":"2016-08-29T16:42:00+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2009%20Pretty%20Prairie.ogg","user":"admin"}
{"reqId":"s0JbptlH\/77ngBJbufIq","remoteAddr":"127.0.0.1","app":"audioplayer","message":"output the data","level":0,"time":"2016-08-29T16:42:00+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2009%20Pretty%20Prairie.ogg","user":"admin"}
{"reqId":"s0JbptlH\/77ngBJbufIq","remoteAddr":"127.0.0.1","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$hey in \/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/View.php:1147\nStack trace:\n#0 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#1 \/srv\/www\/htdocs\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#2 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#3 {main}\n  thrown at \/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/View.php#1147","level":3,"time":"2016-08-29T16:42:00+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2009%20Pretty%20Prairie.ogg","user":"admin"}

One theory here is that maybe the client closed the connection on the other end, so writing in the buffer maybe fails. But there is no error logged about it.

PVince81 on 29 Aug 2016

This one https://github.com/Rello/audioplayer/blob/master/lib/audiostream.php#L148
big bada :boom:

PVince81 on 29 Aug 2016

If I comment out the callback wrapper which detects file closing here https://github.com/owncloud/core/blob/v9.1.0/lib/private/Files/View.php#L1146, the error disappears!

So there is something in PHP7 about writing into wrapped streams and sudden death of the stream when writing into it.

Another issue also sometimes appears:

{"reqId":"805ZhxMJBiFsNkX4zFbc","remoteAddr":"127.0.0.1","app":"PHP","message":"rewinddir(): 513 is not a valid Directory resource at \/srv\/www\/htdocs\/owncloud\/3rdparty\/icewind\/streams\/src\/Wrapper.php#31","level":0,"time":"2016-08-29T16:57:12+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2008%20Moonrock.ogg","user":"admin"}

PVince81 on 29 Aug 2016

Hmmm, now that I'm trying to debug it further it seems that it does reach the closing of the stream, or I'm just very unlucky...

It seems that there are two situations observed so far: one in which the last exit() call is triggering an implicit fclose of the stream, in which the callback wrapper is being called. In that situation it is understandable that PHP 7 might be overeager and has freed the memory of static classes already.

The second situation however is one where the closing seems to happen earlier. Maybe an error of some sorts happens.

On the other hand, I see a small detail in my last debug log:

{"reqId":"BToxoHKyS4z6\/IODP2iU","remoteAddr":"127.0.0.1","app":"audioplayer","message":"end stream","level":0,"time":"2016-08-29T17:07:18+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2008%20Moonrock.ogg","user":"admin"}
{"reqId":"BToxoHKyS4z6\/IODP2iU","remoteAddr":"127.0.0.1","app":"audioplayer","message":"before fclose","level":0,"time":"2016-08-29T17:07:18+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2008%20Moonrock.ogg","user":"admin"}
{"reqId":"BToxoHKyS4z6\/IODP2iU","remoteAddr":"127.0.0.1","app":"audioplayer","message":"after fclose, calling exit","level":0,"time":"2016-08-29T17:07:18+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2008%20Moonrock.ogg","user":"admin"}
{"reqId":"BToxoHKyS4z6\/IODP2iU","remoteAddr":"127.0.0.1","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in \/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/Filesystem.php:772\nStack trace:\n#0 \/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/View.php(2032): OC\\Files\\Filesystem::normalizePath('\/admin\/files\/te...')\n#1 \/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/View.php(1150): OC\\Files\\View->unlockFile('\/test\/4mat - Su...', 1)\n#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()\n#3 \/srv\/www\/htdocs\/owncloud\/3rdparty\/icewind\/streams\/src\/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()\n#5 {main}\n  thrown at \/srv\/www\/htdocs\/owncloud\/lib\/private\/Files\/Filesystem.php#772","level":3,"time":"2016-08-29T17:07:18+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/audioplayer\/getaudiostream?file=%2Ftest%2F4mat%20-%20Surrender%20-%2008%20Moonrock.ogg","user":"admin"}

So apparently the audio player does call an explicit fclose before calling exit, but for some reason that explicit fclose wasn't acted upon by the callback wrapper.

PVince81 on 29 Aug 2016

@icewind1991 would be good if you could have a look as well now that it is reproducible.

PVince81 on 29 Aug 2016

i get this exact error when doing occ music:scan

full output:

Start scan for jaykay
Scanning /jaykay/files//johannes/Music/<snip>.flac
PHP Fatal error:  Cannot 'break' 2 levels in /var/www/owncloud/apps/music/3rdparty/getID3/getid3/module.audio.ogg.php on line 511
PHP Fatal error:  Uncaught Error: Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache in /var/www/owncloud/lib/private/Files/Filesystem.php:772
Stack trace:
#0 /var/www/owncloud/lib/private/Files/View.php(2032): OC\Files\Filesystem::normalizePath('/jaykay/files/j...')
#1 /var/www/owncloud/lib/private/Files/View.php(1150): OC\Files\View->unlockFile('/jaykay/files/j...', 1)
#2 [internal function]: OC\Files\View->OC\Files\{closure}()
#3 /var/www/owncloud/apps/files_external/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))
#4 [internal function]: Icewind\Streams\CallbackWrapper->stream_close()
#5 /var/www/owncloud/lib/private/Files/Stream/OC.php(122): fclose(Resource id #824)
#6 [internal function]: OC\Files\Stream\OC->stream_close()
#7 {main}
  thrown in /var/www/owncloud/lib/private/Files/Filesystem.php on line 772

karyon on 5 Sep 2016

Okay, so it looks like it happens for any PHP request that works with streams

PVince81 on 6 Sep 2016

Is there anything I can help test faster ? This bug is open since Feb and has been dragged since then to each release .. I really thought it'd get fixed in 9.1.1 with no luck...

d3xt3r01 on 21 Sep 2016

Is this bug causing real issues apart from just logging ?
When I tested the music player the streaming worked properly even when those were logged.

It's likely either a bug in @icewind1991's library Icewind/Streams where file closing isn't detected properly or a bug in PHP 7 where PHP prevents overriding/detecting file closing.

PVince81 on 22 Sep 2016

In https://github.com/nextcloud/server/issues/1166 some additional notes where posted:

Afaik this is a race condition in php's garbage collection on scrim exit, if we have a CallbackWrapper stream that is garbage collected after Filesystem::$normalizedPathCache has been gc'd

The solution to this is making sure we close streams before exiting the script, this used to be fairly consistent with webdav but was fixed by closing the output stream in sabre/dav

ghost on 22 Sep 2016

In the audio player case above the stream is not opened through Webdav but by the audio player directly.
And from what I saw it also calls fclose() explicitly.

PVince81 on 22 Sep 2016

@PVince81 for me, occ music:scan seems to crash with this error. output see above.

karyon on 23 Sep 2016

FYI, I don't have the Music app installed, and it happens for me as described above.

ownCloud Server 9.1.1

enoch85 on 23 Sep 2016

@PVince81 in my case, videos don't play on users that watch them on iphones for example. ( That's why I opened #23804 )

d3xt3r01 on 25 Sep 2016

@d3xt3r01 Video playing is most likely unrelated. This was fixed for PHP7 installations with oC 9.0.5 and 9.1.1

ghost on 25 Sep 2016

@RealRancor I can confirm, haven't tried since @MorrisJobke closed #23804 as duplicate to this one ( mine was related to video ). Thanks.

d3xt3r01 on 25 Sep 2016

ownCloud 9.1.1.3:
Exactly same behaviour as described by OP of #23804 (but line number changes from 804 to 772)

triggered by event:
Click on MP4-File in ownCloud web interface to play the movie
The fatal PHP error is randomly thrown once, twice, ... up to 5 times

Selecting a MP4 file and downloading it DOES NOT triggers the error

plabong on 25 Sep 2016

In my MP4 collection I found one movie, which allways throws 5 PHP fatal errors on start and one fatal error when movie is stopped by click on close-"X"

plabong on 25 Sep 2016

In my MP4 collection

Click on MP4-File in ownCloud web interface

mine was related to video

Mine is _not_ related to MP4 so that isn't the sole cause here. See above for steps to reproduce. Just wanted to confirm this so that you don't lock yourself down to just haunting this bug releated to MP4 or video.

enoch85 on 8 Oct 2016

I guess the solution then is to go through the whole OC code and find places where the files aren't closed explicitly/properly. As for third party apps, these would have to do so as well as core cannot enforce closing.

PVince81 on 20 Oct 2016

go through the whole OC code

Any volunteers? :D

enoch85 on 21 Oct 2016

Just want to add that I get this error spammed ~1000x per second in my logs with NO plugin installed, just shared files.

ArchLinux, PHP 7. Seems to happen with big shares only (512M and more), and only with direct download links (you know, /download).

[Tue Nov 15 20:43:26.528991 2016] [:error] [pid 16404] [client 121.54.44.88:17657] 
PHP Fatal error:  Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /usr/share/webapps/owncloud/lib/private/Files/Filesystem.php:790
Stack trace:
#0 /usr/share/webapps/owncloud/lib/private/Files/View.php(2039): OC\\Files\\Filesystem::normalizePath('/Asia81/files/C...')
#1 /usr/share/webapps/owncloud/lib/private/Files/View.php(1151): OC\\Files\\View->unlockFile('/Conversions Pe...', 1)
#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()
#3 /usr/share/webapps/owncloud/apps/files_external/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))
#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()
#5 {main}
  thrown in /usr/share/webapps/owncloud/lib/private/Files/Filesystem.php on line 790, referer: http://www.******.com/******.html

I'm willing to do the job myself, for core at least. How to proceed ?

Webbeh on 15 Nov 2016

@Webbeh Pleaee read this and make your first PR in core :)

Thank you for attending this!

enoch85 on 15 Nov 2016

When I said "How to proceed ?", I actually meant "what to look for in detail ?".

Webbeh on 15 Nov 2016

@Webbeh thanks, the fact that you saw it happening for "/download" is already useful info!

The code path goes to "apps/files/download.php" and then to "private/files/View.php" in the method readfile.

Oh booooo, there's a missing fclose there.
Try adding one and see if the problem disappears !

I suspect that other code paths might be using this method as well so it could fix those as well.
If it works, please make a PR (or let me know and I'll make it).

PVince81 on 18 Nov 2016

Adding the missing fcloses to all the methods missing them inside View.php didn't fix the issue.

I'm currently looking in lib/ for instances of fopen() that aren't closed, and I'm finding an awful lot of them. If it changes anything I'll do a PR.

EDIT: after closing all the unclosed instances of fopen() inside the lib/ folder, there is no change in the frequency or contents of the error messages.

Webbeh on 18 Nov 2016

So, I've updated my personal server to PHP7 and could see very few of these statements. I've now enabled more advanced logging so I can try and find out what kind of requests (and from which clients) this is happening.

PVince81 on 25 Nov 2016

Here are the past entries:

{
  "reqId": "v/a/LoG7k6cTqRdaKhfQ",
  "remoteAddr": "xxx.xxx.xxx.xxx",
  "app": "PHP",
  "message": "Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php:790
Stack trace:
#0 /srv/www/htdocs/owncloud/lib/private/Files/View.php(2039): OC\\Files\\Filesystem::normalizePath('/tingting/files...')
#1 /srv/www/htdocs/owncloud/lib/private/Files/View.php(1151): OC\\Files\\View->unlockFile('/petry/pics/Fam...', 1)
#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()
#3 /srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))
#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()
#5 {main}
  thrown at /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php#790",
  "level": 3,
  "time": "2016-11-22T12:32:17+00:00",
  "method": "GET",
  "url": "/remote.php/webdav/petry/pics/Family/P1110512.JPG",
  "user": "tingting"
}
{
  "reqId": "MiSDajYVPnlMOEoYwDhh",
  "remoteAddr": "xxx.xxx.xxx.xxx",
  "app": "PHP",
  "message": "Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php:790
Stack trace:
#0 /srv/www/htdocs/owncloud/lib/private/Files/View.php(2039): OC\\Files\\Filesystem::normalizePath('/tingting/files...')
#1 /srv/www/htdocs/owncloud/lib/private/Files/View.php(1151): OC\\Files\\View->unlockFile('/petry/pics/Fam...', 1)
#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()
#3 /srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))
#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()
#5 {main}
  thrown at /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php#790",
  "level": 3,
  "time": "2016-11-22T12:35:28+00:00",
  "method": "PROPFIND",
  "url": "/remote.php/webdav/clientsync",
  "user": "vincent"
}
{
  "reqId": "M5UP6blRow6qhG3yzsjS",
  "remoteAddr": "yyy.yyy.yyy.yyy",
  "app": "PHP",
  "message": "Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php:790
Stack trace:
#0 /srv/www/htdocs/owncloud/lib/private/Files/View.php(2039): OC\\Files\\Filesystem::normalizePath('/vincent/files/...')
#1 /srv/www/htdocs/owncloud/lib/private/Files/View.php(1151): OC\\Files\\View->unlockFile('/clientsync/pic...', 1)
#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()
#3 /srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))
#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()
#5 {main}
  thrown at /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php#790",
  "level": 3,
  "time": "2016-11-22T21:35:40+00:00",
  "method": "PROPFIND",
  "url": "/remote.php/webdav/clientsync",
  "user": "vincent"
}
{
  "reqId": "/6K33mJ95fR+wYIJVbgQ",
  "remoteAddr": "yyy.yyy.yyy.yyy",
  "app": "PHP",
  "message": "Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php:790
Stack trace:
#0 /srv/www/htdocs/owncloud/lib/private/Files/View.php(2039): OC\\Files\\Filesystem::normalizePath('/vincent/files/...')
#1 /srv/www/htdocs/owncloud/lib/private/Files/View.php(1151): OC\\Files\\View->unlockFile('/clientsync/pic...', 1)
#2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()
#3 /srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))
#4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()
#5 {main}
  thrown at /srv/www/htdocs/owncloud/lib/private/Files/Filesystem.php#790",
  "level": 3,
  "time": "2016-11-22T21:36:40+00:00",
  "method": "PROPFIND",
  "url": "/remote.php/webdav/clientsync",
  "user": "vincent"
}

While I can understand that a GET will do a fopen() and might have unclosed streams, I don't get how a simple PROPFIND on the sync folder would even trigger such a situation ??

I don't have any external storage so there is no file that would be opened within a PROPFIND.

PVince81 on 25 Nov 2016

This in on v9.1.2 on openSUSE Leap 42.2 with PHP 7.0.7

PVince81 on 25 Nov 2016

also I have encryption enabled. Hmmm I wonder if the encryption code is trying to fopen the file only to compute the size when not known, or even for trying to find out whether the file is encrypted... at PROPFIND time... bääääh

PVince81 on 25 Nov 2016

                                                                                  I personally dont have encryption enabled, just my two cents.                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        From: Vincent PetrySent: Friday, 25 November 2016 15:48To: owncloud/coreReply To: owncloud/coreCc: Nicolas Glassey; MentionSubject: Re: [owncloud/core] Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache (#22370)also I have encryption enabled. Hmmm I wonder if the encryption code is trying to fopen the file only to compute the size when not known, or even for trying to find out whether the file is encrypted... at PROPFIND time... bääääh

—You are receiving this because you were mentioned.Reply to this email directly, view it on GitHub, or mute the thread.

{"api_version":"1.0","publisher":{"api_key":"05dde50f1d1a384dd78767c55493e4bb","name":"GitHub"},"entity":{"external_key":"github/owncloud/core","title":"owncloud/core","subtitle":"GitHub repository","main_image_url":"https://cloud.githubusercontent.com/assets/143418/17495839/a5054eac-5d88-11e6-95fc-7290892c7bb5.png","avatar_image_url":"https://cloud.githubusercontent.com/assets/143418/15842166/7c72db34-2c0b-11e6-9aed-b52498112777.png","action":{"name":"Open in GitHub","url":"https://github.com/owncloud/core"}},"updates":{"snippets":[{"icon":"PERSON","message":"@PVince81 in #22370: also I have encryption enabled. Hmmm I wonder if the encryption code is trying to fopen the file only to compute the size when not known, or even for trying to find out whether the file is encrypted... at PROPFIND time... bääääh"}],"action":{"name":"View Issue","url":"https://github.com/owncloud/core/issues/22370#issuecomment-262970913"}}}

Webbeh on 25 Nov 2016

Yeah, this seems to be a general issue. As soon as a file is opened with fopen and some magic unknown crazy stuff happens, the garbage collector of PHP 7 runs too late and triggers this issue.

If we can't fix it at the lower level then let's at least look for a way to mitigate it, which might involve some trickery to avoid logging this message.

PVince81 on 25 Nov 2016

                                                                                  How about a simple try catch only on PHP7.                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        From: Vincent PetrySent: Friday, 25 November 2016 16:03To: owncloud/coreReply To: owncloud/coreCc: Nicolas Glassey; MentionSubject: Re: [owncloud/core] Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache (#22370)Yeah, this seems to be a general issue. As soon as a file is opened with  fopen and some magic unknown crazy stuff happens, the garbage collector of PHP 7 runs too late and triggers this issue.

If we can't fix it at the lower level then let's at least look for a way to mitigate it, which might involve some trickery to avoid logging this message.

—You are receiving this because you were mentioned.Reply to this email directly, view it on GitHub, or mute the thread.

{"api_version":"1.0","publisher":{"api_key":"05dde50f1d1a384dd78767c55493e4bb","name":"GitHub"},"entity":{"external_key":"github/owncloud/core","title":"owncloud/core","subtitle":"GitHub repository","main_image_url":"https://cloud.githubusercontent.com/assets/143418/17495839/a5054eac-5d88-11e6-95fc-7290892c7bb5.png","avatar_image_url":"https://cloud.githubusercontent.com/assets/143418/15842166/7c72db34-2c0b-11e6-9aed-b52498112777.png","action":{"name":"Open in GitHub","url":"https://github.com/owncloud/core"}},"updates":{"snippets":[{"icon":"PERSON","message":"@PVince81 in #22370: Yeah, this seems to be a general issue. As soon as a file is opened with fopen and some magic unknown crazy stuff happens, the garbage collector of PHP 7 runs too late and triggers this issue.\r\n\r\nIf we can't fix it at the lower level then let's at least look for a way to mitigate it, which might involve some trickery to avoid logging this message."}],"action":{"name":"View Issue","url":"https://github.com/owncloud/core/issues/22370#issuecomment-262974190"}}}

Webbeh on 25 Nov 2016

I have setup a local PHP 7 env now.

The log entries appear randomly, sometimes for previews, sometimes for downloads, regardless of size.
Video player doesn't seem to trigger it yet.

@Webbeh try/catch won't work as it's not an exception but some kind of compile-time error, even though the class already exists but somehow the GC killed an existing attribute.

The reason the message is logged is because we have a global error handler. The super-dirty way to do it would be to add code there to detect if the message contains the string "normalizedPathCache" and then discard it... It would make the message disappear but not fix the underlying issue.

I'm now trying to think if there are ways to force PHP 7 to add a reference to the array in the static Filesystem class to prevent the GC to decide to kill it too early...

PVince81 on 25 Nov 2016

The log entries appear randomly, sometimes for previews, sometimes for downloads, regardless of size.
Video player doesn't seem to trigger it yet.

Exactly my point. I get thousands of theese enteries in my logs as I host the VMs in my cloud.

Very nice that you finally installed PHP 7 @PVince81 :)

enoch85 on 25 Nov 2016

                                                                                  It's possible to disable the garbage collection using gc_disable(), it's super dirty but couldn't it do the trick between the fopen and éclose.                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         From: Daniel HanssonSent: Friday, 25 November 2016 16:35To: owncloud/coreReply To: owncloud/coreCc: Nicolas Glassey; MentionSubject: Re: [owncloud/core] Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache (#22370)

The log entries appear randomly, sometimes for previews, sometimes for downloads, regardless of size.
Video player doesn't seem to trigger it yet.

Exactly my point. I get thousands of theese enteries in my logs as I host the VMs in my cloud.
Very nice that you finally installed PHP 7 @PVince81 :)

—You are receiving this because you were mentioned.Reply to this email directly, view it on GitHub, or mute the thread.

{"api_version":"1.0","publisher":{"api_key":"05dde50f1d1a384dd78767c55493e4bb","name":"GitHub"},"entity":{"external_key":"github/owncloud/core","title":"owncloud/core","subtitle":"GitHub repository","main_image_url":"https://cloud.githubusercontent.com/assets/143418/17495839/a5054eac-5d88-11e6-95fc-7290892c7bb5.png","avatar_image_url":"https://cloud.githubusercontent.com/assets/143418/15842166/7c72db34-2c0b-11e6-9aed-b52498112777.png","action":{"name":"Open in GitHub","url":"https://github.com/owncloud/core"}},"updates":{"snippets":[{"icon":"PERSON","message":"@enoch85 in #22370: \u003e The log entries appear randomly, sometimes for previews, sometimes for downloads, regardless of size.\r\nVideo player doesn't seem to trigger it yet.\r\n\r\nExactly my point. I get thousands of theese enteries in my logs as I host the VMs in my cloud. \r\n\r\nVery nice that you finally installed PHP 7 @PVince81 :)"}],"action":{"name":"View Issue","url":"https://github.com/owncloud/core/issues/22370#issuecomment-262980785"}}}

Webbeh on 25 Nov 2016

GC buster attempt 1 https://github.com/owncloud/core/pull/26725 (https://github.com/owncloud/core/pull/26725.patch)

Any volunteers ?

PVince81 on 25 Nov 2016

Attempt 1 #26725 : no result.

Small precision : after trying to reproduce the bug by myself, I saw that it didn't appear instantly, but rather ~10s after the start of the download, _but only if the download was still running_.

If it helps...

Webbeh on 28 Nov 2016

s/no result/failed => bug still happening. Thanks for testing.

Yes, in the rare cases where it happened for me as well on my dev env I noticed that the message appeared later. I think it's probably because while the PHP request has already sent the response, the garbage collector hasn't started freeing memory until many seconds later.

The cleanest solution is probably to move to normalizer to be a real object instead of a static class.
Move it to a utility class instance that can be retrieved as \OC::$server->getUtil()->normalizePath($path) or so and hope that the GC doesn't kill the server container services as early as static classes. If it does, then store the instance as $util in the View class and inside the closure.

PVince81 on 28 Nov 2016

Isn't it weird that PHP garbage collects a static class ?

I know we can't really compare with Java/C# due to the fact that PHP is a scripted language, but neither of those two actually GCs static classes, for the simple fact that they have to be available for the full lifetime of the application...

EDIT:
Related : https://secure.php.net/manual/en/features.gc.refcounting-basics.php -> "Cleanup problems"

Webbeh on 28 Nov 2016

@Webbeh in the case of PHP the static class is not shared with separate requests. Basically every PHP request starts from scratch and then destroys all classes. So it is understandable that PHP needs to destroy static classes at point. It is just not clear to me why it does so while there is still some code that needs to run.

The way this CallbackWrapper works is that it creates a stream wrapper to detect when fclose() is called on the given resource. If fclose is called early enough (which was suggested above), the callback would also run early. However if fclose is not called explicitly, then at some point the garbage collector will destroy the resource by itself and implicitly call fclose on it which would trigger the callback.
I guess this means that the GC destroys resources after having already destroyed all static classes instead of before.

I'm still surprised that the proposed workaround of having explicit fclose did not work.

PVince81 on 28 Nov 2016

("resource" here being the file resource as created by fopen)

PVince81 on 28 Nov 2016

Could it be due to session GC ?
If PHP sees an active download (without new user request) as an inactive session, it could trigger the GC after the session.gc_maxlifetime time.
There may be something to do around that (display a download progress, for example).

Webbeh on 28 Nov 2016

@Webbeh interesting point. What is your value for session.gc_maxlifetime ? Mine is the default which is 1440 seconds which would be 24 minutes.

PVince81 on 28 Nov 2016

2400 minutes.. (144000 seconds), which seems to be the default max lifetime of the ArchLinux PHP7 package.

I'm pretty sure though that this timeout is a "catch-all" that just prevents memory leaks if there are no more requests to PHP. The other settings (session.gc_probability and session.gc_divisor) also alter the session GC and may (or may not) play a role in here.

My config :
session.gc_probability = 1
session.gc_divisor = 1000

...which means that the GC will happen each 1/1000 requests.

Yes, it's a long shot, but I'm not excluding this probability.

Webbeh on 28 Nov 2016

@Webbeh so you said the problem occurs for you when downloading a file shared with public link.
I did so and put a breakpoint in the callback, this is how it looks like:

0  OC\Files\View->OC\Files\{closure}() /srv/www/htdocs/owncloud/lib/private/Files/View.php:1148
1  call_user_func:{/srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php:109}() /srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php:109
2  Icewind\Streams\CallbackWrapper->stream_close() /srv/www/htdocs/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php:109
3  OC\Files\View->readfile() /srv/www/htdocs/owncloud/lib/private/Files/View.php:433
4  OC_Files::getSingleFile() /srv/www/htdocs/owncloud/lib/private/legacy/files.php:303
5  OC_Files::get() /srv/www/htdocs/owncloud/lib/private/legacy/files.php:119
6  OCA\Files_Sharing\Controllers\ShareController->downloadShare() /srv/www/htdocs/owncloud/apps/files_sharing/lib/Controllers/ShareController.php:508
7  call_user_func_array:{/srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:159}() /srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:159
8  OC\AppFramework\Http\Dispatcher->executeController() /srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:159
9  OC\AppFramework\Http\Dispatcher->dispatch() /srv/www/htdocs/owncloud/lib/private/AppFramework/Http/Dispatcher.php:89
10 OC\AppFramework\App::main() /srv/www/htdocs/owncloud/lib/private/AppFramework/App.php:99
11 OCP\AppFramework\App->dispatch() /srv/www/htdocs/owncloud/lib/public/AppFramework/App.php:135
12 OC\Route\Router->{closure:/srv/www/htdocs/owncloud/core/routes.php:138-141}() /srv/www/htdocs/owncloud/core/routes.php:140
13 call_user_func:{/srv/www/htdocs/owncloud/lib/private/Route/Router.php:280}() /srv/www/htdocs/owncloud/lib/private/Route/Router.php:280
14 OC\Route\Router->match() /srv/www/htdocs/owncloud/lib/private/Route/Router.php:280
15 OC::handleRequest() /srv/www/htdocs/owncloud/lib/base.php:891
16 {main}          /srv/www/htdocs/owncloud/index.php:54

Apparently View::readfile() already triggers an implicit fclose() (remember that we found out that fclose was missing there) which itself leads to a call to the callback. So it seems to be working fine right here.

But as observed there seems to be cases where PHP 7 feels lazy and doesn't directly close.
BUT if we add an explicit fclose in readfile it must happen.

@Webbeh let's try the following on your env: https://github.com/owncloud/core/pull/26735

PVince81 on 28 Nov 2016

Summary of what was observed so far from this debug PR: https://github.com/owncloud/core/pull/26735

There are multiple scenarios where this log message would appear even when explicitly having a fclose as advised:

Scenario 1

Observed this on my env with mod_php.
The request calls readfile on download, then fopen, the fread loop, then finishes the loop then calls fclose. Fclose properly calls the callback that releases the locks.
So far so good.
However after this the callback is called again at a time where all objects got GC'd already: https://github.com/owncloud/core/pull/26735#issuecomment-263244444

Potential fix: add a check in the callback wrapper to make sure the callback only runs once

Scenario 2

This is what we observed on @Webbeh's environment.
Call to readfilePart, then fopen then the fread loop runs. However the code never reaches the fclose after the loop. The theory here is that the client closes the connection as soon as it received all bytes, and in some envs closing the connection results in PHP killing the current process. (php-fpm does that AFAIK).
Since no fclose was called at all, the GC will at some point discard the resource which results in calling the callback. But that happens too late when static objects are gone already.

Potential fix: try and not flush the output for the last buffer iteration, then fclose, then flush. (to prevent the client closing the connection)

Scenario 3

This is the weirdest. Observed locally.

Request 1: goes through fopen and delivers the file. (when it happened I didn't have logging so not sure if fclose was called)
Request 2 (ex: heartbeat): the GC runs here and discards the resource that was allocated in request 1. This is even later than before and the required objects from request 1 are already long gone.

Potential fix: with a bit of luck the fixes for scenarios 1 and 2 should make sure that the callback is already called so the GC run in the second request doesn't have to do anything...

Next steps:

investigate a way to prevent the callback to be called twice, this would solve scenario 1
find a way to still have fclose running in scenario 2, maybe some gentle php.ini settings ?
find a PHP 7 GC expert to explain scenario 3

PVince81 on 28 Nov 2016

Potential fix for scenario 2: it's a patch for the "3rdparty" folder: https://github.com/owncloud/3rdparty/pull/283
Basically it should prevent the callback to be called twice in case it was already called before.

PVince81 on 28 Nov 2016

[ ] TODO: call fclose in readfile and readfilePart (might not help alone but hopefully combined with the other fixes)

PVince81 on 28 Nov 2016

@PVince81 could we also be backported to 9.0.X?

@Kawohl FYI

cdamken on 1 Dec 2016

thanks....

JKawohl on 1 Dec 2016

@cdamken if we ever find how to fix this for all scenarios, then yes... hopefully...

PVince81 on 1 Dec 2016

Can anyone try with this debugging patch https://github.com/owncloud/core/pull/26735 and tell me whether the problems continue to happen ? It contains several trials to force fclose to happen and not be bypassed by potential PHP request killings...

PVince81 on 1 Dec 2016

@owncloud/qa

felixboehm on 1 Dec 2016

I rechecked my personal server which now runs PHP 7 but the problem has never reappeared since unfortunately. Ideal would be to be able to setup an env where the issue happens consistently but so far it is not clear at all what kind of setup it is. Since it's about GC the issue is highly random.

PVince81 on 2 Dec 2016

Looks like we got some clues thanks to @davitol, it seems to be related to aborted/cancelled connections. Or at least one scenario is.

I wrote this script to simulate a download and purposefully close the connection at random intervals and it is seems to reproduce one variant of the issue consistently:

<?php
    $tries = 1;

    for ($i = 0; $i < $tries; $i++) {


        // enter URL and known real file size
        $url = 'http://localhost/owncloud/index.php/s/91AFuwOr8UMvGnB/download';
        $realSize = 928670754;

        $handle = fopen($url, 'rb');

        if (!is_resource($handle)) {
            die("Could not open whatever...\n");
        }

        // compute random breaking point
        $breakSize = (int)(rand() * $realSize / getrandmax());

        echo "Iteration number $i, breaking size at $breakSize of $realSize\n";

        $readSize = 0;
        while (!feof($handle) && ($breakSize === null || $readSize <= $breakSize)) {
            $buf = fread($handle, 8192);
            $readSize += strlen($buf);
        }

        fclose($handle);
    }

PVince81 on 2 Dec 2016

Looks like sometimes the script needs to do more than 1 iterations before the issue starts happening, maybe to somehow induce the GC to start working. Once the problem appears, subsequent runs of the script seems to keep reproducing it. So let's stay it's always a "rough start".

This sounds like it would be good candidate for a smashbox test.

Happens with link share downloads and also Webdav endpoint.

Looks like we'll need to apply the solution (possibly ignore_user_abort(true)) to all code paths that involve streaming a file back to the client:

View::readfile
View::readfilePart
Webdav endpoint, possibly Sabre plugin or inside the File sabre node

Also I think a nice addition would be to add a check whether the connection is gone inside the loop like @Rello did in his streaming code. If the connection is gone, simply break the loop and properly call fclose at the end. That's what we need to do.

I'll work on a PR...

PVince81 on 2 Dec 2016

This can get really confusing due to the several scenarios...

I just discovered that even a full Webdav download could sometimes produce a similar message.
It seems that fclose is called twice, once by us explicitly and once by the ghostly resource reaper of PHP 7. It is so ghostly that even the debugger isn't able to detect it.

Looks like patching Icewind/Streams to prevent duplicate calls of fclose will fix this. Will prepare another PR...

Ok, so far here's the plan:

[x] patch Icewind/Streams to prevent the ghostly garbage reaper to call fclose twice for the same resource => https://github.com/icewind1991/Streams/pull/5
~~view::readfile => use ignore_user_abort(true) fix~~ => added directly in View::fopen
~~view::readfilePart => use ignore_user_abort(true) fix~~ => added directly in View::fopen
~~Webdav => use ignore_user_abort(true) fix~~ => added directly in View::fopen
~~... other potential older code paths that stream files back to use it => use ignore_user_abort(true)~~ => added directly in View::fopen
~~tell @Rello to add ignore_user_abort(true) in his audio streaming code~~ => added directly in View::fopen
[ ] optionally: use connection_aborted() || connection_status() !== 0 to detect aborted connections and abort earlier (might be something for a separate PR)

PVince81 on 2 Dec 2016

[x] smashbox test to reproduce the issue: https://github.com/owncloud/smashbox/pull/151

PVince81 on 2 Dec 2016

@PVince81 my respect for your deep analysiis on this.

Let me know when the first code was patched with this ignore...
This will male it easier for me to understand what I have to do ;-)

Rello on 2 Dec 2016

In the end I made a simpler patch that calls ignore_user_abort(true) in ownCloud core's fopen function.

The patch changes two files:
1) icewind/streams fix for duplicate fclose (potential PHP 7 bug): it seems the smashbox tests (https://github.com/owncloud/smashbox/issues/151) cannot reproduce this, so maybe needs futher parameters to reproduce it in an automated manner
2) add ignore_user_abort(true) in View::fopen(): when applying this one the smashbox test does not fail any more, so it's looking good. (@Rello this means that you likely don't need any changes in your app, but would still be good to test)

Here is the patch:
https://gist.github.com/anonymous/ef0325e2c5023f57c211629a2a45164e

@Webbeh @enoch85 and others, can you help testing the patch ?

I've tested with mod_php, if some people have php-fpm and/or nginx it would be good to know if it also works there. (I'm not sure if php-fpm would respect the ignore_user_abort setting).

If you guys can confirm that it all fixes the problem for you, I'll make respective PRs to integrate the fix in the next release. Thanks !

PVince81 on 4 Dec 2016

Applied the patch. For now, no errors. Will confirm in a few hours when I'm sure the error doesn't come back.

Webbeh on 4 Dec 2016

Will apply it to nginx/fpm and give an update...

Rello on 4 Dec 2016

After ~60 huge downloads, aborts, etc, still no error.

Webbeh on 4 Dec 2016

Still no error today.

Assuming the bug is now fixed. Good work !

Webbeh on 6 Dec 2016

Thanks a lot for the feedback !
Would be good to hear about other reporters.

I will now make a PR for the View specific change.

PVince81 on 6 Dec 2016

PR for the view part here: https://github.com/owncloud/core/pull/26775.

The other PR that upgrades the Icewind/streams lib is here: https://github.com/owncloud/core/pull/26762

PVince81 on 6 Dec 2016

Raised https://github.com/owncloud/core/issues/26790 to look into detecting aborted connections and making shortcuts for faster cleanup

PVince81 on 7 Dec 2016

Any idea in which versions will those patches be applied ?

Webbeh on 7 Dec 2016

I'd say at least stable9.1, maybe stable9.
It also depends whether we can safely update icewind/streams in these versions without breaking other things.

PVince81 on 7 Dec 2016

i have a similar error:

PHP Fatal error: Uncaught Error: Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache in /var/www/html/owncloud/lib/private/Files/Filesystem.php:793\nStack trace:\n#0 /var/www/html/owncloud/lib/private/Files/View.php(2039): OC\Files\Filesystem::normalizePath('/0973482A-87DC-...')\n#1 /var/www/html/owncloud/lib/private/Files/View.php(1151): OC\Files\View->unlockFile('/Documents/data...', 1)\n#2 [internal function]: OC\Files\View->OC\Files\{closure}()\n#3 /var/www/html/owncloud/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))\n#4 [internal function]: Icewind\Streams\CallbackWrapper->stream_close()\n#5 {main}\n thrown in /var/www/html/owncloud/lib/private/Files/Filesystem.php on line 793

with LDAP users show this error. the users from owncloud work fine

version owncloud 9.1.3, test with php 7.0.14 and php 5.4.16,

jonixmobile on 10 Jan 2017

Fixes were merged and backported, closing.

For stable9.1 it was these two PRs:

update icewind/streams lib: https://github.com/owncloud/3rdparty/pull/284
prevent fclose to be skipped when PHP connection lost: https://github.com/owncloud/core/pull/26939

PVince81 on 18 Jan 2017

Oh wait, the 3rdparty backport wasn't merged yet.

PVince81 on 18 Jan 2017

Also backported to 9.0, will be in 9.0.8.

Closing now.

PVince81 on 19 Jan 2017

Additional backport required, because it turns out that the icewind/streams library is also bundled by files_external and needs to have the same version to avoid strange side effects...

PR here: https://github.com/owncloud/core/pull/26974

PVince81 on 19 Jan 2017

All backports done, closing

PVince81 on 25 Jan 2017

Should this error be fixed with OC 9.1.4?

Yesterday, I updated my instance to 9.1.4 but I already have the error:

[Fri Feb 10 08:24:39.863243 2017] [:error] [pid 24183] [client 109.75.208.254:20098] FastCGI: server "/var/www/clients/client2/web46/cgi-bin/php5-fcgi-*-443-my.domain" stderr: PHP message: PHP Fatal error:  Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /var/www/clients/client2/web46/web/lib/private/Files/Filesystem.php:793
[Fri Feb 10 08:24:39.863494 2017] [:error] [pid 24183] [client 109.75.208.254:20098] FastCGI: server "/var/www/clients/client2/web46/cgi-bin/php5-fcgi-*-443-my.domain" stderr: Stack trace:
[Fri Feb 10 08:24:39.863546 2017] [:error] [pid 24183] [client 109.75.208.254:20098] FastCGI: server "/var/www/clients/client2/web46/cgi-bin/php5-fcgi-*-443-my.domain" stderr: #0 /var/www/clients/client2/web46/web/lib/private/Files/View.php(2041): OC\\Files\\Filesystem::normalizePath('/EFG-KL/files/L...')
[Fri Feb 10 08:24:39.863818 2017] [:error] [pid 24183] [client 109.75.208.254:20098] FastCGI: server "/var/www/clients/client2/web46/cgi-bin/php5-fcgi-*-443-my.domain" stderr: #1 /var/www/clients/client2/web46/web/lib/private/Files/View.php(1153): OC\\Files\\View->unlockFile('/Lieder PPT/Son...', 1)
[Fri Feb 10 08:24:39.863867 2017] [:error] [pid 24183] [client 109.75.208.254:20098] FastCGI: server "/var/www/clients/client2/web46/cgi-bin/php5-fcgi-*-443-my.domain" stderr: #2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()
[Fri Feb 10 08:24:39.863986 2017] [:error] [pid 24183] [client 109.75.208.254:20098] FastCGI: server "/var/www/clients/client2/web46/cgi-bin/php5-fcgi-*-443-my.domain" stderr: #3 /var/www/clients/client2/web46/web/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))
[Fri Feb 10 08:24:39.864076 2017] [:error] [pid 24183] [client 109.75.208.254:20098] FastCGI: server "/var/www/clients/client2/web46/cgi-bin/php5-fcgi-*-443-my.domain" stderr: #4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()
[Fri Feb 10 08:24:39.864167 2017] [:error] [pid 24183] [client 109.75.208.254:20098] FastCGI: server "/var/www/clients/client2/web46/cgi-bin/php5-fcgi-*-443-my.domain" stderr: #5 {main}
[Fri Feb 10 08:24:39.864310 2017] [:error] [pid 24183] [client 109.75.208.254:20098] FastCGI: server "/var/www/clients/client2/web46/cgi-bin/php5-fcgi-*-443-my.domain" stderr:   thrown in /var/www/clients/client2/web46/web/lib/private/Files/Filesystem.php on line 793

Apache2: 2.4.18
PHP: 7.0.13-0ubuntu0.16.04.1

I already tried to cleanup filecache and so on:
php occ files:cleanup
php occ maintenance:mimetype:update-db

hdering on 10 Feb 2017

@hdering all known code paths that cause such log messages have been fixed in 9.1.4, yes.

Maybe you found yet another code path causing this 😞

PVince81 on 10 Feb 2017

@hdering are you able to find out when this is happening ?

In the known cases it used to happen for aborted uploads or downloads. (download a file with the web browser but cancel it)

PVince81 on 10 Feb 2017

It happens when I try to open it through Browser, a simple click on the file.

And it happens through die Desktop Client. I get the message: "Operation abgebrochen".

hdering on 10 Feb 2017

and does the file open correctly or is it corrupt ?

It could also be a problem in your environment that prevents downloads to work correctly and only shows this message as a side effect.

PVince81 on 10 Feb 2017

No the file doesn't open correctly.

hdering on 10 Feb 2017

@hdering I suggest you investigate your environment. The error you see is just a side effect of something else preventing the download to start/finish.

Maybe try retrieving that URL with curl and see whether you get 0 bytes or more.
If 0 bytes, then something is likely wrong in your environment and something is blocking the download. (could be a php-fpm config issue of some sorts)

PVince81 on 10 Feb 2017

it does not affect all files, only a few files.

hdering on 10 Feb 2017

if you have encryption enabled, check in oc_filecache whether that specific file has the "encrypted" flag set to 1. If not, set it manually and try downloading it twice.

PVince81 on 10 Feb 2017

For test i switched to fastcgi. the same:

[fcgid:warn] [pid 29469] [client 109.75.208.254:24798] mod_fcgid: stderr: PHP Fatal error:  Uncaught Error: Access to undeclared static property: OC\\Files\\Filesystem::$normalizedPathCache in /var/www/clients/client2/web46/web/lib/private/Files/Filesystem.php:793
[Fri Feb 10 09:50:22.244693 2017] [fcgid:warn] [pid 29469] [client 109.75.208.254:24798] mod_fcgid: stderr: Stack trace:
[Fri Feb 10 09:50:22.244702 2017] [fcgid:warn] [pid 29469] [client 109.75.208.254:24798] mod_fcgid: stderr: #0 /var/www/clients/client2/web46/web/lib/private/Files/View.php(2041): OC\\Files\\Filesystem::normalizePath('/EFG-KL/files/L...')
[Fri Feb 10 09:50:22.244707 2017] [fcgid:warn] [pid 29469] [client 109.75.208.254:24798] mod_fcgid: stderr: #1 /var/www/clients/client2/web46/web/lib/private/Files/View.php(1153): OC\\Files\\View->unlockFile('/Lieder PPT/Son...', 1)
[Fri Feb 10 09:50:22.244712 2017] [fcgid:warn] [pid 29469] [client 109.75.208.254:24798] mod_fcgid: stderr: #2 [internal function]: OC\\Files\\View->OC\\Files\\{closure}()
[Fri Feb 10 09:50:22.244736 2017] [fcgid:warn] [pid 29469] [client 109.75.208.254:24798] mod_fcgid: stderr: #3 /var/www/clients/client2/web46/web/3rdparty/icewind/streams/src/CallbackWrapper.php(109): call_user_func(Object(Closure))
[Fri Feb 10 09:50:22.244801 2017] [fcgid:warn] [pid 29469] [client 109.75.208.254:24798] mod_fcgid: stderr: #4 [internal function]: Icewind\\Streams\\CallbackWrapper->stream_close()
[Fri Feb 10 09:50:22.244807 2017] [fcgid:warn] [pid 29469] [client 109.75.208.254:24798] mod_fcgid: stderr: #5 {main}
[Fri Feb 10 09:50:22.244811 2017] [fcgid:warn] [pid 29469] [client 109.75.208.254:24798] mod_fcgid: stderr:   thrown in /var/www/clients/client2/web46/web/lib/private/Files/Filesystem.php on line 793

hdering on 10 Feb 2017

Do you mean oc_filecache in database?

hdering on 10 Feb 2017

@PVince81 Now I checked oc_filecache. For me it is just the other way. The original version has encrypted = 1. The other versions have 0. But it doesn't help to change from 1 to 0 or 0 to 1.

hdering on 10 Feb 2017

@PVince81 Unfortunately, this behavior occurs with another user. Other installation, but same server.

I checked the oc_filecache entry and the encrypted was 0. I changed it to 1 but it does not help.

owncloud Version is 9.1.4.

Do you have any idea?

hdering on 16 May 2017

@hdering without detailed logs it will be impossible to guess and help

PVince81 on 16 May 2017

@PVince81 If I try to download a file from Browser I get the mesage ERR_INVALID_RESPONSE.

If I try to download through the Android App I get a 500 error.

owncloud.log:
{"reqId":"nKtJuZkzNoXtverTkR4T","remoteAddr":"x.x.x.x","app":"webdav","message":"Exception: {\"Message\":\"Bad Signature\",\"Exception\":\"OC\\\\HintException\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/clients\\\/client2\\\/web46\\\/web\\\/apps\\\/encryption\\\/lib\\\/Crypto\\\/Crypt.php(463): OCA\\\\Encryption\\\\Crypto\\\\Crypt->checkSignature('McpPP0a1KClI\\\/WG...', 'y8z\\\\xB8\\\\xB7\\\\xD7\\\\xF1\\\\xE0Sx\\\\xC9L\\\\xEB\\\\x1A\\\\x9F...', '7507f57bb5d918b...')\\n#1 \\\/var\\\/www\\\/clients\\\/client2\\\/web46\\\/web\\\/apps\\\/encryption\\\/lib\\\/Crypto\\\/Encryption.php(363): OCA\\\\Encryption\\\\Crypto\\\\Crypt->symmetricDecryptFileContent('McpPP0a1KClI\\\/WG...', 'y8z\\\\xB8\\\\xB7\\\\xD7\\\\xF1\\\\xE0Sx\\\\xC9L\\\\xEB\\\\x1A\\\\x9F...', 'AES-256-CTR', 1, 0)\\n#2 \\\/var\\\/www\\\/clients\\\/client2\\\/web46\\\/web\\\/lib\\\/private\\\/Files\\\/Stream\\\/Encryption.php(459): OCA\\\\Encryption\\\\Crypto\\\\Encryption->decrypt('McpPP0a1KClI\\\/WG...', 0)\\n#3 \\\/var\\\/www\\\/clients\\\/client2\\\/web46\\\/web\\\/lib\\\/private\\\/Files\\\/Stream\\\/Encryption.php(290): OC\\\\Files\\\\Stream\\\\Encryption->readCache()\\n#4 [internal function]: OC\\\\Files\\\\Stream\\\\Encryption->stream_read(8192)\\n#5 \\\/var\\\/www\\\/clients\\\/client2\\\/web46\\\/web\\\/3rdparty\\\/sabre\\\/http\\\/lib\\\/Sapi.php(78): stream_copy_to_stream(Resource id #84, Resource id #86, '22248')\\n#6 \\\/var\\\/www\\\/clients\\\/client2\\\/web46\\\/web\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(470): Sabre\\\\HTTP\\\\Sapi::sendResponse(Object(Sabre\\\\HTTP\\\\Response))\\n#7 \\\/var\\\/www\\\/clients\\\/client2\\\/web46\\\/web\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(248): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#8 \\\/var\\\/www\\\/clients\\\/client2\\\/web46\\\/web\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(57): Sabre\\\\DAV\\\\Server->exec()\\n#9 \\\/var\\\/www\\\/clients\\\/client2\\\/web46\\\/web\\\/remote.php(164): require_once('\\\/var\\\/www\\\/client...')\\n#10 {main}\",\"File\":\"\\\/var\\\/www\\\/clients\\\/client2\\\/web46\\\/web\\\/apps\\\/encryption\\\/lib\\\/Crypto\\\/Crypt.php\",\"Line\":483,\"User\":\"Ernst\"}","level":4,"time":"2017-05-16T11:29:08+00:00","method":"GET","url":"\/remote.php\/webdav\/Ernst\/HolzinTakt-Cajon\/Fahrtenbuch.xlsx","user":"Ernst"}

hdering on 16 May 2017

@hdering this looks unrelated to "normalizedPathCache" error. Looks more like https://github.com/owncloud/core/issues/27824#issuecomment-301660467

PVince81 on 16 May 2017

@PVince81 this are bad news...

hdering on 16 May 2017

is there no fix? This cant be true

lenusch on 17 Aug 2017

@lenusch the fix was already released and works, please upgrade.

If you still see it, please make a new ticket and use the issue template https://raw.githubusercontent.com/owncloud/core/master/.github/issue_template.md

PVince81 on 17 Aug 2017

👍1

@PVince81 i have latest nextcloud. Still same Errors.

lenusch on 17 Aug 2017

@lenusch Just a note that ownCloud is not Nextcloud, and you're currently in the ownCloud bugtracker. If something like this is happening in Nextcloud it doesn't mean if applies for ownCloud as well.

ghost on 18 Aug 2017

@kdslkdsaldsal yes i have noticed too. Sorry.
Also posted into Nextcloud, can be deleted on owncloud if you want to.
Or can i delete by my self?

lenusch on 18 Aug 2017

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[bot] on 2 Aug 2019

Core: Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache

All 141 comments

Steps to reproduce

Scenario 1

Scenario 2

Scenario 3

Related issues