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

Closed
LukasReschke opened this Issue Feb 13, 2016 · 130 comments
@LukasReschke
Member

Seems to be caused by https://github.com/owncloud/core/blob/296519f44a3c0f1d34f6a67a7de33965d0edb9ef/lib/private/files/view.php#L1084-L1094

{"reqId":"YZdjFpzB5CoaRlMO0bak","remoteAddr":"xxxx","app":"PHP","message":"Uncaught Error: Access to undeclared static property: OC\Files\Filesystem::$normalizedPathCache in lib/private/files/filesystem.php:799
Stack trace:
#0 lib/private/files/view.php(1919): OC\Files\Filesystem::normalizePath('/USER/files/shared...')
#1 lib/private/files/view.php(1055): OC\Files\View->unlockFile('/Shared/ownclou...', 1)
#2 [internal function]: OC\Files\View->OC\Files\{closure}()
#3 apps/files_external/3rdparty/icewind/streams/src/CallbackWrapper.php(106): call_user_func(Object(Closure))
#4 [internal function]: Icewind\Streams\CallbackWrapper->stream_close()
#5 {main}
  thrown at lib/private/files/filesystem.php#799","level":3,"time":"2016-02-12T14:02:57+00:00","method":"PROPFIND","url":"/owncloud/remote.php/webdav/"}

cc @icewind1991

@LukasReschke LukasReschke added this to the 9.0-current milestone Feb 13, 2016
@PVince81 PVince81 added the sev2-high label Feb 15, 2016
@icewind1991
Member

Any steps to reproduce?

Looks like the close callback is called during process teardown

@PVince81 PVince81 added the needs info label Feb 23, 2016
@PVince81
Collaborator

@LukasReschke any info ?

@LukasReschke
Member

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

@LukasReschke LukasReschke removed this from the 9.0-current milestone Feb 23, 2016
@LukasReschke LukasReschke removed their assignment Feb 23, 2016
@PVince81
Collaborator
PVince81 commented Mar 1, 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)

@LukasReschke LukasReschke added this to the backlog milestone Mar 1, 2016
@PVince81
Collaborator
PVince81 commented Mar 1, 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
Collaborator
PVince81 commented Mar 1, 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
Collaborator
PVince81 commented Mar 9, 2016

@LukasReschke is this still happening in the S3 logs ?

@PVince81
Collaborator
PVince81 commented Mar 9, 2016

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

@icewind1991 icewind1991 was assigned by PVince81 Mar 9, 2016
@LukasReschke
Member

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

@PVince81
Collaborator

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
Collaborator

Also, this is PHP 7, right ?

@Aidenir
Aidenir commented Apr 4, 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

@cmonteroluque cmonteroluque modified the milestone: 9.1-current, 9.0.1 Apr 11, 2016
@ToeiRei
ToeiRei commented Apr 18, 2016 edited

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.

@PVince81
Collaborator

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

@ToeiRei
ToeiRei commented Apr 18, 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.

@PVince81
Collaborator

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.

@ToeiRei
ToeiRei commented Apr 18, 2016 edited

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
ToeiRei commented Apr 18, 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.

@enoch85
Member
enoch85 commented Apr 26, 2016 edited

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
Member
enoch85 commented May 13, 2016 edited
@enoch85
Member
enoch85 commented May 13, 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
Member
enoch85 commented May 13, 2016

Still happens on 9.0.2 btw.

@enoch85
Member
enoch85 commented May 13, 2016

Steps to reproduce

  1. Create a public link with a random file
  2. Download that public link
  3. Wait for ~10 seconds
  4. 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"}
@PVince81
Collaborator

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

@enoch85
Member
enoch85 commented May 22, 2016 edited

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

@Buzut
Buzut commented May 23, 2016 edited

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

@PVince81
Collaborator

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

@PVince81
Collaborator

@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...

@Happyfeet01

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"}

@PVince81
Collaborator

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

@kvoit
kvoit commented Jun 15, 2016 edited

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.

@ET-Bent
ET-Bent commented Jun 17, 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.

@ghost
ghost commented Jun 17, 2016

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

@ET-Bent
ET-Bent commented Jun 17, 2016

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

@enoch85
Member
enoch85 commented Jul 12, 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.

@PVince81
Collaborator

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

@Rello
Rello commented Aug 26, 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"}

@PVince81
Collaborator

@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
Collaborator

@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
Collaborator

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
Collaborator

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
Collaborator

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
Collaborator

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
Collaborator

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
Collaborator

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
Collaborator

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

@PVince81 PVince81 removed the needs info label Aug 29, 2016
@karyon
karyon commented Sep 5, 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
@PVince81
Collaborator
PVince81 commented Sep 6, 2016

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

@PVince81 PVince81 modified the milestone: 9.1.2, 9.1.1 Sep 21, 2016
@d3xt3r01

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...

@PVince81
Collaborator

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.

@ghost
ghost commented Sep 22, 2016

In nextcloud/server#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

@PVince81
Collaborator

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.

@karyon
karyon commented Sep 23, 2016

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

@enoch85
Member
enoch85 commented Sep 23, 2016 edited

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

ownCloud Server 9.1.1

@d3xt3r01

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

@ghost
ghost commented Sep 25, 2016

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

@d3xt3r01
d3xt3r01 commented Sep 25, 2016 edited

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

@plabong
plabong commented Sep 25, 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
plabong commented Sep 25, 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"

@enoch85
Member
enoch85 commented Oct 8, 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.

@PVince81
Collaborator

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 PVince81 modified the milestone: 9.1.3, 9.1.2 Oct 20, 2016
@icewind1991 icewind1991 was unassigned by PVince81 Oct 20, 2016
@enoch85
Member
enoch85 commented Oct 20, 2016

go through the whole OC code

Any volunteers? :D

@Webbeh
Webbeh commented Nov 15, 2016 edited

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 ?

@enoch85
Member
enoch85 commented Nov 15, 2016

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

Thank you for attending this!

@Webbeh
Webbeh commented Nov 15, 2016

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

@PVince81
Collaborator

@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).

@Webbeh
Webbeh commented Nov 18, 2016 edited

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.

@PVince81
Collaborator

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
Collaborator
PVince81 commented Nov 25, 2016 edited

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
Collaborator

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

@PVince81
Collaborator

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

@Webbeh
Webbeh commented Nov 25, 2016
@PVince81
Collaborator

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.

@Webbeh
Webbeh commented Nov 25, 2016
@PVince81
Collaborator

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...

@enoch85
Member
enoch85 commented Nov 25, 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 :)

@Webbeh
Webbeh commented Nov 25, 2016
@PVince81
Collaborator

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

Any volunteers ?

@Webbeh
Webbeh commented Nov 28, 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...

@PVince81
Collaborator

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.

@Webbeh
Webbeh commented Nov 28, 2016 edited

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"

@PVince81
Collaborator

@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
Collaborator

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

@Webbeh
Webbeh commented Nov 28, 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).

@PVince81
Collaborator

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

@Webbeh
Webbeh commented Nov 28, 2016 edited

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.

@PVince81
Collaborator

@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: #26735

@PVince81
Collaborator
PVince81 commented Nov 28, 2016 edited

Summary of what was observed so far from this debug PR: #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: #26735 (comment)

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 PVince81 referenced this issue in owncloud/3rdparty Nov 28, 2016
Closed

[debug] Callbackwrapper close once #282

@PVince81
Collaborator

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

@PVince81
Collaborator
  • TODO: call fclose in readfile and readfilePart (might not help alone but hopefully combined with the other fixes)
@cdamken
Contributor
cdamken commented Dec 1, 2016

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

@Kawohl FYI

@Kawohl
Contributor
Kawohl commented Dec 1, 2016

thanks....

@PVince81
Collaborator
PVince81 commented Dec 1, 2016

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

@PVince81
Collaborator
PVince81 commented Dec 1, 2016

Can anyone try with this debugging patch #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 PVince81 self-assigned this Dec 1, 2016
@PVince81 PVince81 modified the milestone: 9.1.4, 9.1.3 Dec 1, 2016
@felixboehm
Contributor
@PVince81
Collaborator
PVince81 commented Dec 2, 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
Collaborator
PVince81 commented Dec 2, 2016 edited

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
Collaborator
PVince81 commented Dec 2, 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
Collaborator
PVince81 commented Dec 2, 2016 edited

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:

  • patch Icewind/Streams to prevent the ghostly garbage reaper to call fclose twice for the same resource => icewind1991/Streams#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 PVince81 referenced this issue in owncloud/smashbox Dec 2, 2016
Merged

Tests for aborted downloads #151

@PVince81
Collaborator
PVince81 commented Dec 2, 2016 edited
@Rello
Rello commented Dec 2, 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 ;-)

@PVince81
Collaborator
PVince81 commented Dec 4, 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 (owncloud/smashbox#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 !

@Webbeh
Webbeh commented Dec 4, 2016

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

@Rello
Rello commented Dec 4, 2016

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

@Webbeh
Webbeh commented Dec 4, 2016

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

@Webbeh
Webbeh commented Dec 6, 2016

Still no error today.

Assuming the bug is now fixed. Good work !

@PVince81
Collaborator
PVince81 commented Dec 6, 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
Collaborator
PVince81 commented Dec 6, 2016

PR for the view part here: #26775.

The other PR that upgrades the Icewind/streams lib is here: #26762

@PVince81
Collaborator
PVince81 commented Dec 7, 2016

Raised #26790 to look into detecting aborted connections and making shortcuts for faster cleanup

@Webbeh
Webbeh commented Dec 7, 2016

Any idea in which versions will those patches be applied ?

@PVince81
Collaborator
PVince81 commented Dec 7, 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 PVince81 added green-ticket and removed green-ticket labels Dec 22, 2016
@jonixmobile
jonixmobile commented Jan 10, 2017 edited

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,

@PVince81
Collaborator

Fixes were merged and backported, closing.

For stable9.1 it was these two PRs:

@PVince81 PVince81 closed this Jan 18, 2017
@PVince81
Collaborator

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

@PVince81 PVince81 reopened this Jan 18, 2017
@PVince81
Collaborator

Also backported to 9.0, will be in 9.0.8.

Closing now.

@PVince81 PVince81 closed this Jan 19, 2017
@PVince81
Collaborator

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: #26974

@PVince81 PVince81 reopened this Jan 19, 2017
@PVince81
Collaborator

All backports done, closing

@PVince81 PVince81 closed this Jan 25, 2017
@hdering
hdering commented Feb 10, 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

@PVince81
Collaborator

@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
Collaborator

@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)

@hdering
hdering commented Feb 10, 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".

@PVince81
Collaborator

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.

@hdering
hdering commented Feb 10, 2017

No the file doesn't open correctly.

image

@PVince81
Collaborator

@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)

@hdering
hdering commented Feb 10, 2017

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

@PVince81
Collaborator

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.

@hdering
hdering commented Feb 10, 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
hdering commented Feb 10, 2017

Do you mean oc_filecache in database?

@hdering
hdering commented Feb 10, 2017 edited

@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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment