-
-
Notifications
You must be signed in to change notification settings - Fork 4.1k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
[21.0.1] "Error: Trying to access array offset on value of type bool" at lib/private/Files/Storage/Wrapper/Encryption.php#441 #26473
Comments
Same issue appears right after upgrade from NC 20.0.8 to 20.0.9 (message never seen on 20.0.8). Log from NC 20.0.9{
"reqId": "tJTPnzsZTjlh60DEcxmd",
"level": 4,
"time": "2021-04-13T10:28:17+00:00",
"remoteAddr": "<removed>",
"user": "<removed>",
"app": "webdav",
"method": "DELETE",
"url": "/remote.php/dav/files/<removed>/Joplin/locks/sync_desktop_a535d7e027ae44a7b0b7bdc72b971073.json",
"message": {
"Exception": "Error",
"Message": "Call to a member function getId() on array",
"Code": 0,
"Trace": [
{
"file": "/var/www/html/lib/private/Files/Cache/Updater.php",
"line": 160,
"function": "remove",
"class": "OC\\Files\\Cache\\Cache",
"type": "->",
"args": [
"files/Joplin/locks/sync_desktop_a535d7e027ae44a7b0b7bdc72b971073.json"
]
},
{
"file": "/var/www/html/lib/private/Files/View.php",
"line": 329,
"function": "remove",
"class": "OC\\Files\\Cache\\Updater",
"type": "->",
"args": [
"files/Joplin/locks/sync_desktop_a535d7e027ae44a7b0b7bdc72b971073.json"
]
},
{
"file": "/var/www/html/lib/private/Files/View.php",
"line": 1179,
"function": "removeUpdate",
"class": "OC\\Files\\View",
"type": "->",
"args": [
{
"cache": null,
"scanner": {
"__class__": "OC\\Files\\Cache\\Scanner"
},
"watcher": null,
"propagator": null,
"updater": {
"__class__": "OC\\Files\\Cache\\Updater"
},
"__class__": "OCA\\Files_Trashbin\\Storage"
},
"files/Joplin/locks/sync_desktop_a535d7e027ae44a7b0b7bdc72b971073.json"
]
},
{
"file": "/var/www/html/lib/private/Files/View.php",
"line": 724,
"function": "basicOperation",
"class": "OC\\Files\\View",
"type": "->",
"args": [
"unlink",
"/Joplin/locks/sync_desktop_a535d7e027ae44a7b0b7bdc72b971073.json",
[
"delete"
]
]
},
{
"file": "/var/www/html/apps/dav/lib/Connector/Sabre/File.php",
"line": 466,
"function": "unlink",
"class": "OC\\Files\\View",
"type": "->",
"args": [
"/Joplin/locks/sync_desktop_a535d7e027ae44a7b0b7bdc72b971073.json"
]
},
{
"file": "/var/www/html/3rdparty/sabre/dav/lib/DAV/Tree.php",
"line": 183,
"function": "delete",
"class": "OCA\\DAV\\Connector\\Sabre\\File",
"type": "->",
"args": []
},
{
"file": "/var/www/html/3rdparty/sabre/dav/lib/DAV/CorePlugin.php",
"line": 295,
"function": "delete",
"class": "Sabre\\DAV\\Tree",
"type": "->",
"args": [
"files/<removed>/Joplin/locks/sync_desktop_a535d7e027ae44a7b0b7bdc72b971073.json"
]
},
{
"file": "/var/www/html/3rdparty/sabre/event/lib/WildcardEmitterTrait.php",
"line": 89,
"function": "httpDelete",
"class": "Sabre\\DAV\\CorePlugin",
"type": "->",
"args": [
{
"__class__": "Sabre\\HTTP\\Request"
},
{
"__class__": "Sabre\\HTTP\\Response"
}
]
},
{
"file": "/var/www/html/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 474,
"function": "emit",
"class": "Sabre\\DAV\\Server",
"type": "->",
"args": [
"method:DELETE",
[
{
"__class__": "Sabre\\HTTP\\Request"
},
{
"__class__": "Sabre\\HTTP\\Response"
}
]
]
},
{
"file": "/var/www/html/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 251,
"function": "invokeMethod",
"class": "Sabre\\DAV\\Server",
"type": "->",
"args": [
{
"__class__": "Sabre\\HTTP\\Request"
},
{
"__class__": "Sabre\\HTTP\\Response"
}
]
},
{
"file": "/var/www/html/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 319,
"function": "start",
"class": "Sabre\\DAV\\Server",
"type": "->",
"args": []
},
{
"file": "/var/www/html/apps/dav/lib/Server.php",
"line": 332,
"function": "exec",
"class": "Sabre\\DAV\\Server",
"type": "->",
"args": []
},
{
"file": "/var/www/html/apps/dav/appinfo/v2/remote.php",
"line": 35,
"function": "exec",
"class": "OCA\\DAV\\Server",
"type": "->",
"args": []
},
{
"file": "/var/www/html/remote.php",
"line": 167,
"args": [
"/var/www/html/apps/dav/appinfo/v2/remote.php"
],
"function": "require_once"
}
],
"File": "/var/www/html/lib/private/Files/Cache/Cache.php",
"Line": 528,
"CustomMessage": "--"
},
"userAgent": "Joplin/1.0",
"version": "20.0.9.1"
}
|
This issue (as reported by @caugner) seems to be caused by a change in the filesystem cache code that was introduced in 20.0.9 and 21.0.1. It crashes here:
but $info is actually assigned here:
So something in the cache code causes $info to be different than it was in previous versions of Nextcloud. One commit that caught my attention is b844293#diff-2b1f228ea5cf1c94347251d18c7a94f86bfb229573277dd160cb57cd7b16c864 by @icewind1991 (and committed by @rullzer). It documents the possibility of a null return for metadata requests, so that's in line with the issue we're seeing here. But I am not sure how that commit (which addresses an issue with SMB) relates to the context we have here (no SMB).Anyone a suggestion? @nextcloud/encryption Of course we'll likely have to catch the changed output of $this->getCache()->get($path) in https://github.com/nextcloud/server/blob/23b8e4a1d4e3d3f54d18f6c7f1be57baf8f75795/lib/private/Files/Storage/Wrapper/Encryption.php but I would prefer to first understand what causes empty an empty/null cache result. One can only end up in the code where the issue happens in case of reading an existing file. That should not be consistent with absent metadata.
|
@jknockaert my apologies, it appears that I took the wrong log. Here is the log I have a lot on 20.0.9{
"reqId": "goJnpbOy1wgPKnL9UHfF",
"level": 3,
"time": "2021-04-13T18:28:15+00:00",
"remoteAddr": "<removed>",
"user": "<removed>",
"app": "PHP",
"method": "PUT",
"url": "/remote.php/webdav/Nextcloud/Photos/2021/04/IMG_9453.JPG",
"message": {
"Exception": "Error",
"Message": "Trying to access array offset on value of type bool at /var/www/html/lib/private/Files/Storage/Wrapper/Encryption.php#439",
"Code": 0,
"Trace": [
{
"file": "/var/www/html/lib/private/Files/Storage/Wrapper/Encryption.php",
"line": 439,
"function": "onError",
"class": "OC\\Log\\ErrorHandler",
"type": "::",
"args": [
8,
"Trying to access array offset on value of type bool",
"/var/www/html/lib/private/Files/Storage/Wrapper/Encryption.php",
439,
{
"path": "files/Nextcloud/Photos/2021/04/IMG_9453.JPG.ocTransferId1287283558.part",
"mode": "r",
"encryptionEnabled": true,
"shouldEncrypt": false,
"encryptionModule": null,
"0": "And 10 more entries, set log level to debug to see all entries"
}
]
},
{
"file": "/var/www/html/lib/private/Files/Storage/Wrapper/Wrapper.php",
"line": 300,
"function": "fopen",
"class": "OC\\Files\\Storage\\Wrapper\\Encryption",
"type": "->",
"args": [
"files/Nextcloud/Photos/2021/04/IMG_9453.JPG.ocTransferId1287283558.part",
"r"
]
},
{
"file": "/var/www/html/lib/private/Files/Storage/Wrapper/Encryption.php",
"line": 751,
"function": "fopen",
"class": "OC\\Files\\Storage\\Wrapper\\Wrapper",
"type": "->",
"args": [
"files/Nextcloud/Photos/2021/04/IMG_9453.JPG.ocTransferId1287283558.part",
"r"
]
},
{
"file": "/var/www/html/lib/private/Files/Storage/Wrapper/Encryption.php",
"line": 621,
"function": "copyBetweenStorage",
"class": "OC\\Files\\Storage\\Wrapper\\Encryption",
"type": "->",
"args": [
{
"cache": null,
"scanner": {
"__class__": "OC\\Files\\Cache\\Scanner"
},
"watcher": null,
"propagator": null,
"updater": null,
"__class__": "OCA\\Files_Trashbin\\Storage"
},
"files/Nextcloud/Photos/2021/04/IMG_9453.JPG.ocTransferId1287283558.part",
"files/Nextcloud/Photos/2021/04/IMG_9453.JPG",
true,
true
]
},
{
"file": "/var/www/html/apps/files_trashbin/lib/Storage.php",
"line": 240,
"function": "moveFromStorage",
"class": "OC\\Files\\Storage\\Wrapper\\Encryption",
"type": "->",
"args": [
{
"cache": null,
"scanner": {
"__class__": "OC\\Files\\Cache\\Scanner"
},
"watcher": null,
"propagator": null,
"updater": null,
"__class__": "OCA\\Files_Trashbin\\Storage"
},
"files/Nextcloud/Photos/2021/04/IMG_9453.JPG.ocTransferId1287283558.part",
"files/Nextcloud/Photos/2021/04/IMG_9453.JPG"
]
},
{
"file": "/var/www/html/apps/dav/lib/Connector/Sabre/File.php",
"line": 292,
"function": "moveFromStorage",
"class": "OCA\\Files_Trashbin\\Storage",
"type": "->",
"args": [
{
"cache": null,
"scanner": {
"__class__": "OC\\Files\\Cache\\Scanner"
},
"watcher": null,
"propagator": null,
"updater": null,
"__class__": "OCA\\Files_Trashbin\\Storage"
},
"files/Nextcloud/Photos/2021/04/IMG_9453.JPG.ocTransferId1287283558.part",
"files/Nextcloud/Photos/2021/04/IMG_9453.JPG"
]
},
{
"file": "/var/www/html/apps/dav/lib/Connector/Sabre/Directory.php",
"line": 156,
"function": "put",
"class": "OCA\\DAV\\Connector\\Sabre\\File",
"type": "->",
"args": [
null
]
},
{
"file": "/var/www/html/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 1104,
"function": "createFile",
"class": "OCA\\DAV\\Connector\\Sabre\\Directory",
"type": "->",
"args": [
"IMG_9453.JPG",
null
]
},
{
"file": "/var/www/html/3rdparty/sabre/dav/lib/DAV/CorePlugin.php",
"line": 527,
"function": "createFile",
"class": "Sabre\\DAV\\Server",
"type": "->",
"args": [
"Nextcloud/Photos/2021/04/IMG_9453.JPG",
null,
null
]
},
{
"file": "/var/www/html/3rdparty/sabre/event/lib/WildcardEmitterTrait.php",
"line": 89,
"function": "httpPut",
"class": "Sabre\\DAV\\CorePlugin",
"type": "->",
"args": [
{
"__class__": "Sabre\\HTTP\\Request"
},
{
"__class__": "Sabre\\HTTP\\Response"
}
]
},
{
"file": "/var/www/html/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 474,
"function": "emit",
"class": "Sabre\\DAV\\Server",
"type": "->",
"args": [
"method:PUT",
[
{
"__class__": "Sabre\\HTTP\\Request"
},
{
"__class__": "Sabre\\HTTP\\Response"
}
]
]
},
{
"file": "/var/www/html/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 251,
"function": "invokeMethod",
"class": "Sabre\\DAV\\Server",
"type": "->",
"args": [
{
"__class__": "Sabre\\HTTP\\Request"
},
{
"__class__": "Sabre\\HTTP\\Response"
}
]
},
{
"file": "/var/www/html/3rdparty/sabre/dav/lib/DAV/Server.php",
"line": 319,
"function": "start",
"class": "Sabre\\DAV\\Server",
"type": "->",
"args": []
},
{
"file": "/var/www/html/apps/dav/appinfo/v1/webdav.php",
"line": 84,
"function": "exec",
"class": "Sabre\\DAV\\Server",
"type": "->",
"args": []
},
{
"file": "/var/www/html/remote.php",
"line": 167,
"args": [
"/var/www/html/apps/dav/appinfo/v1/webdav.php"
],
"function": "require_once"
}
],
"File": "/var/www/html/lib/private/Log/ErrorHandler.php",
"Line": 91,
"CustomMessage": "--"
},
"userAgent": "Mozilla/5.0 (iOS) Nextcloud-iOS/3.4.0",
"version": "20.0.9.1"
} |
Hmm. Just drag-n-drop a file in the web interface generates this error in the log. Then when deleting the file the error is again there plus #26544. Also when deleting an error shows in the webinterface and the file is still present in the folder view. Only after a browser reload the deleted file is gone. This is something nasty. |
@icewind1991 Could there be a relation with PR #25136? |
Looking at the stack trace I noticed that this function is called: server/apps/files_trashbin/lib/Storage.php Line 231 in f031dd6
This happens both upon upload when the partfile is moved and upon delete when the filed is moved to the thrashbin. That function is something that has been introduced in this commit: b5db450 @icewind1991 Can you have a look pls? |
I still can't make much of this issue. Looking at the stack trace posted by @doc75 (#26473 (comment)) I notice that sabredav somehow identifies server/apps/dav/lib/Connector/Sabre/File.php Line 147 in 8ef920f
So in the example posted by @doc75 $this->path would have a value /Nextcloud/Photos/2021/04/IMG_9453.JPG (note: with a leading slash and without a storage prefix).Looking further up in the stack the internal path of the partfile becomes files/Nextcloud/Photos/2021/04/IMG_9453.JPG.ocTransferId1287283558.part . That's not really in the trashbin. So I'm not sure why the OCA\Files_Trashbin\Storage is involved here at all.@ChristophWurst Could you have a look into this behaviour of the Sabre connector? |
I'm not familiar with the files aspect of DAV, sorry, I'm as clueless as you :/ |
So adding files results in an inter-storage copy (from partfile to file) rather than an intra-storage rename. The behaviour we're seeing here implies a write amplification with a factor of two (including all the file handling overhead such as encryption). That's pretty inefficient, perhaps we should fix this. |
@jknockaert it did not happened on my side before 20.0.9 |
No I mean the inter-storage copying upon upload. It may have happened already before but without resulting in a cache-related error. |
I have the same issue |
I am having the same issue; reproducible on a fresh installation of Nextcloud, directly after enabling the encryption app. @schiessle @th3fallen Sorry for the direct reference, but I saw your names in the app description, and it seems there is a fundamental issue going on here with the encryption app. Who can take a look at this? |
+1, same issue here! |
#26980 might help with this one as well |
I just edited that file manually and it seems to work. Thanks for your work and the reference! 👍 |
@juliushaertl I've suggested before that #25568 (corresponding commit is b5db450) may have been causing this issue. So you're right that your fix may well help with this one as well. |
Just to give a hopefully last feedback: After 3 days still no errors. Had hundreds of log entrys before. Problem seems fixed to me with what @juliushaertl posted. |
I can confirm #26980 fixes issue for me |
How to use GitHub
Steps to reproduce
Expected behaviour
There should be no errors.
Actual behaviour
See Encryption errors:
See multiple errors:
Server configuration
Operating system: Ubuntu
Web server: Apache 2.4
Database: MySQL 5.7.28-nmm1-log (c.f. #26470)
PHP version: 7.4.14
Nextcloud version: 21.0.1
Updated from an older Nextcloud/ownCloud or fresh install: Update from 20.0.8 (c.f. #26469)
Where did you install Nextcloud from: Updater
Signing status:
Signing status
n/a
n/a
n/a
n/a
n/a
The text was updated successfully, but these errors were encountered: