Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Allowed memory size of 536870912 bytes exhausted on activity stream #31528

Closed
5 of 8 tasks
nickvergessen opened this issue Mar 11, 2022 · 14 comments
Closed
5 of 8 tasks
Labels
Milestone

Comments

@nickvergessen
Copy link
Member

⚠️ This issue respects the following points: ⚠️

  • This is a bug, not a question or a configuration/webserver/proxy issue.
  • This issue is not already reported on Github (I've searched it).
  • Nextcloud Server is up to date. See Maintenance and Release Schedule for supported versions.
  • I agree to follow Nextcloud's Code of Conduct.

Bug description

Something in the recent version changed something which now causes memory issues on the activity stream.

Steps to reproduce

  1. Go to the activity app
  2. Wait ~16s until the stream shows
  3. Check the nextcloud.log
{"reqId":"","level":3,"time":"2022-03-11T07:35:58+00:00","remoteAddr":"","user":"","app":"PHP","method":"GET","url":"/ocs/v2.php/apps/activity/api/v2/activity/all?format=json&previews=true&since=55712887","message":"Allowed memory size of 536870912 bytes exhausted (tried to allocate 20480 bytes) at /var/www/html/lib/private/AppFramework/Utility/SimpleContainer.php#138","userAgent":"Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:97.0) Gecko/20100101 Firefox/97.0","version":"23.0.3.0"}

Try it another time same error in a different place

{"reqId":"","level":3,"time":"2022-03-10T22:20:24+00:00","remoteAddr":"","user":"","app":"PHP","method":"GET","url":"/ocs/v2.php/apps/activity/api/v2/activity/all?format=json&previews=true&since=0","message":"Allowed memory size of 536870912 bytes exhausted (tried to allocate 131072 bytes) at /var/www/html/lib/private/AppFramework/Middleware/CompressionMiddleware.php#89","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:99.0) Gecko/20100101 Firefox/99.0","version":"23.0.3.0","id":"622a7aaeb8c9b"} 

Expected behavior

No error and the page shows quickly

Installation method

Manual installation

Operating system

Debian/Ubuntu

PHP engine version

PHP 7.4

Web server

Apache (supported)

Database engine version

MariaDB

Is this bug present after an update or on a fresh install?

Updated from a minor version (ex. 22.2.3 to 22.2.4)

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

What user-backends are you using?

  • Default user-backend (database)
  • LDAP/ Active Directory
  • SSO - SAML
  • Other

Configuration report

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "github.client_id": "***REMOVED SENSITIVE VALUE***",
        "github.client_secret": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "updater.release.channel": "beta",
        "zammad.secret": "***REMOVED SENSITIVE VALUE***",
        "zammad.portal.secret": "***REMOVED SENSITIVE VALUE***",
        "zammad.download.secret": "***REMOVED SENSITIVE VALUE***",
        "log.condition": {
            "apps": [
                "perf_debug"
            ]
        },
        "trusted_domains": [
            "cloud.nextcloud.com"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "htaccess.RewriteBase": "\/",
        "overwrite.cli.url": "https:\/\/cloud.nextcloud.com\/",
        "version": "23.0.3.0",
        "dbtype": "mysql",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "mysql.utf8mb4": true,
        "logtimezone": "UTC",
        "log_rotate_size": 104857600,
        "loglevel": "2",
        "installed": true,
        "mail_smtpmode": "smtp",
        "ldapIgnoreNamingRules": false,
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpsecure": "ssl",
        "mail_smtpauth": 1,
        "mail_smtpauthtype": "LOGIN",
        "mail_smtpport": "465",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "appstore.experimental.enabled": true,
        "theme": "",
        "ldapProviderFactory": "\\OCA\\User_LDAP\\LDAPProviderFactory",
        "trashbin_retention_obligation": "auto, 30",
        "maintenance": false,
        "sentry.dsn": "***REMOVED SENSITIVE VALUE***",
        "sentry.public-dsn": "***REMOVED SENSITIVE VALUE***",
        "sentry.minimum.log.level": 3,
        "files_no_background_scan": true,
        "trusted_proxies": "***REMOVED SENSITIVE VALUE***",
        "twofactor_enforced": "true",
        "twofactor_enforced_groups": [
            "General"
        ],
        "twofactor_enforced_excluded_groups": [],
        "debug": false,
        "minimum.supported.desktop.version": "3.4.1"
    }
}

List of activated Apps

N/A

Nextcloud Signing status

No response

Nextcloud Logs

{"reqId":"","level":3,"time":"2022-03-10T22:20:24+00:00","remoteAddr":"","user":"","app":"PHP","method":"GET","url":"/ocs/v2.php/apps/activity/api/v2/activity/all?format=json&previews=true&since=0","message":"Allowed memory size of 536870912 bytes exhausted (tried to allocate 131072 bytes) at /var/www/html/lib/private/AppFramework/Middleware/CompressionMiddleware.php#89","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:99.0) Gecko/20100101 Firefox/99.0","version":"23.0.3.0","id":"622a7aaeb8c9b"}

Additional info

Error started occuring after update from 23.0.2 to 23.0.3rc1

@nickvergessen nickvergessen added bug 0. Needs triage Pending check for reproducibility or if it fits our roadmap 1. to develop Accepted and waiting to be taken care of high regression performance 🚀 and removed 0. Needs triage Pending check for reproducibility or if it fits our roadmap labels Mar 11, 2022
@szaimen szaimen added this to the Nextcloud 23.0.3 milestone Mar 11, 2022
@szaimen szaimen added the 23-feedback Feedback from 23.x releases label Mar 11, 2022
@nickvergessen
Copy link
Member Author

Activities in the range:

        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_deleted",
        "app": "files",
        "type": "file_created",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_created",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_created",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_created",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_changed",
        "app": "files",
        "type": "file_changed",

@PVince81
Copy link
Member

sadly no full stack trace, so harder to pinpoint the exact code location

@nickvergessen
Copy link
Member Author

nickvergessen commented Mar 11, 2022

I debugged the used memory:

\OC::$server->get(\Psr\Log\LoggerInterface::class)->error('Description#' . memory_get_usage(), ['app' => 'nickv']);

First file in the activity loop

9.772.896 ~9MB before this line
https://github.com/nextcloud/activity/blob/8481eb8aa8d688fd8127c7348f4dc6019cd8be5f/lib/Controller/APIv2Controller.php#L353
353.482.232 ~350MB after getInfoById

https://github.com/nextcloud/activity/blob/8481eb8aa8d688fd8127c7348f4dc6019cd8be5f/lib/Controller/APIv2Controller.php#L375
438.144.720 ~438MB after getFileInfo

The a second file without preview

440.345.368 ~440MB before this line
https://github.com/nextcloud/activity/blob/8481eb8aa8d688fd8127c7348f4dc6019cd8be5f/lib/Controller/APIv2Controller.php#L353
526.768.408 ~526MB after getInfoById and exiting here:
https://github.com/nextcloud/activity/blob/8481eb8aa8d688fd8127c7348f4dc6019cd8be5f/lib/Controller/APIv2Controller.php#L356

@nickvergessen
Copy link
Member Author

@PVince81
Copy link
Member

@icewind1991 do you remember what else we changed that could be related ?

@icewind1991
Copy link
Member

No idea what could cause this and can't reproduce

@PVince81
Copy link
Member

are these entries connected to shares ? if yes there's a slight chance they could be connected to the wrong share owner values case ? ref #30791 and #28503 (comment)

@nickvergessen
Copy link
Member Author

nickvergessen commented Mar 14, 2022

Baseline

Point of measurement: https://github.com/nextcloud/activity/blob/8481eb8aa8d688fd8127c7348f4dc6019cd8be5f/lib/ViewInfoCache.php#L114
Before: 9.685.496 ~9.6 MB
After: 359.500.144 ~ 360 MB

Disabling Circles, Deck and Talk if $userId === me

$shares = array_merge($shares, $this->shareManager->getSharedWith($user->getUID(), IShare::TYPE_CIRCLE, null, -1));
$shares = array_merge($shares, $this->shareManager->getSharedWith($user->getUID(), IShare::TYPE_ROOM, null, -1));
$shares = array_merge($shares, $this->shareManager->getSharedWith($user->getUID(), IShare::TYPE_DECK, null, -1));

Before: 9.685.336 ~9.6 MB
After: 99.907.184 ~100 MB

Disabling Talk only if $userId === me

$shares = array_merge($shares, $this->shareManager->getSharedWith($user->getUID(), IShare::TYPE_ROOM, null, -1));

Before: 9.685.336 ~9.6 MB
After: 100.058.336 ~100 MB

DB ref

SELECT share_type, COUNT(id) FROM oc_share WHERE share_with = 'me =)' GROUP BY share_type;
+------------+-----------+
| share_type | COUNT(id) |
+------------+-----------+
|          0 |        23 |
|          2 |        27 |
|         11 |      1360 |
|         13 |        15 |
+------------+-----------+

Talk RoomShareProvider if $userId === me

https://github.com/nextcloud/spreed/blob/dc518c46a710e13485feb0977b0f1343eea6d2ec/lib/Share/RoomShareProvider.php#L784-L845

Before: 10.815.296 ~10.8 MB
After: 18.674.088 ~18.6 MB

MountProvider total if $userId === me

// filter out excluded shares and group shares that includes self
$shares = array_filter($shares, function (\OCP\Share\IShare $share) use ($user) {
return $share->getPermissions() > 0 && $share->getShareOwner() !== $user->getUID();
});
$superShares = $this->buildSuperShares($shares, $user);
$mounts = [];
$view = new View('/' . $user->getUID() . '/files');
$ownerViews = [];
$sharingDisabledForUser = $this->shareManager->sharingDisabledForUser($user->getUID());
$foldersExistCache = new CappedMemoryCache();
foreach ($superShares as $share) {
try {
/** @var \OCP\Share\IShare $parentShare */
$parentShare = $share[0];
if ($parentShare->getStatus() !== IShare::STATUS_ACCEPTED &&
($parentShare->getShareType() === IShare::TYPE_GROUP ||
$parentShare->getShareType() === IShare::TYPE_USERGROUP ||
$parentShare->getShareType() === IShare::TYPE_USER)) {
continue;
}
$owner = $parentShare->getShareOwner();
if (!isset($ownerViews[$owner])) {
$ownerViews[$owner] = new View('/' . $parentShare->getShareOwner() . '/files');
}
$mount = new SharedMount(
'\OCA\Files_Sharing\SharedStorage',
$mounts,
[
'user' => $user->getUID(),
// parent share
'superShare' => $parentShare,
// children/component of the superShare
'groupedShares' => $share[1],
'ownerView' => $ownerViews[$owner],
'sharingDisabledForUser' => $sharingDisabledForUser
],
$loader,
$view,
$foldersExistCache
);
$event = new ShareMountedEvent($mount);
$this->eventDispatcher->dispatchTyped($event);
$mounts[$mount->getMountPoint()] = $mount;
foreach ($event->getAdditionalMounts() as $additionalMount) {
$mounts[$additionalMount->getMountPoint()] = $additionalMount;
}
} catch (\Exception $e) {
$this->logger->logException($e);
$this->logger->error('Error while trying to create shared mount');
}
}

Before: 18.532.088 ~18.5 MB
After: 20.741.552 ~20.7 MB

Filesystem::getMountManager

$manager = Filesystem::getMountManager();
$mounts = $manager->findIn($this->fakeRoot);
$mounts[] = $manager->find($this->fakeRoot);

Actually this seems to loop and setup all users again:
first-time

For the first call to: $path = $this->view->getPath($fileId);
https://github.com/nextcloud/activity/blob/fee285e6496e7dde396cab573ab4113920601d87/lib/ViewInfoCache.php#L114

We end up logging 428 times inside the View::getPath
I basically have all the company employees and former employees logged with:
\OC::$server->get(\Psr\Log\LoggerInterface::class)->error('getPath1#' . json_encode([$this->fakeRoot]) . memory_get_usage(), ['app' => 'nickv']);

{"reqId":"J5eVMi3H4zguIogiQQZk","level":3,"time":"2022-03-14T21:18:04+00:00","remoteAddr":"…","user":"joas","app":"nickv","method":"GET","url":"/ocs/v2.php/apps/activity/api/v2/activity/all?format=json&previews=true&since=0","message":"getPath1#[\"\\/joas\\/files\"]9371808","userAgent":"Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:98.0) Gecko/20100101 Firefox/98.0","version":"23.0.3.0"}
{"reqId":"J5eVMi3H4zguIogiQQZk","level":3,"time":"2022-03-14T21:18:04+00:00","remoteAddr":"…","user":"joas","app":"nickv","method":"GET","url":"/ocs/v2.php/apps/activity/api/v2/activity/all?format=json&previews=true&since=0","message":"getPath1#[\"\\/lukas\\/files\"]27903304","userAgent":"Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:98.0) Gecko/20100101 Firefox/98.0","version":"23.0.3.0"}
{"reqId":"J5eVMi3H4zguIogiQQZk","level":3,"time":"2022-03-14T21:18:04+00:00","remoteAddr":"…","user":"joas","app":"nickv","method":"GET","url":"/ocs/v2.php/apps/activity/api/v2/activity/all?format=json&previews=true&since=0","message":"getPath1#[\"\\/anna\\/files\"]40533712","userAgent":"Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:98.0) Gecko/20100101 Firefox/98.0","version":"23.0.3.0"}
{"reqId":"J5eVMi3H4zguIogiQQZk","level":3,"time":"2022-03-14T21:18:05+00:00","remoteAddr":"…","user":"joas","app":"nickv","method":"GET","url":"/ocs/v2.php/apps/activity/api/v2/activity/all?format=json&previews=true&since=0","message":"getPath1#[\"\\/jos\\/files\"]49765304","userAgent":"Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:98.0) Gecko/20100101 Firefox/98.0","version":"23.0.3.0"}
…
Repeat 424 times with different and repeating users

each user adding their ~10 MB. When you mounted ~50 users the 512 MB of memory limit are up.

@nickvergessen
Copy link
Member Author

Tried reverting those two:

but the problem persisted. So might be coincidentally just occur now since someone shared something with me causing more users to be mounted for me?

@blizzz blizzz modified the milestones: Nextcloud 23.0.3, Nextcloud 24 Mar 16, 2022
@blizzz blizzz modified the milestones: Nextcloud 24, Nextcloud 25 Apr 21, 2022
@JakobPP
Copy link

JakobPP commented Sep 29, 2022

I have this issue, just got it with the latest snap version for 24.

Whenever I try to upload a file more than 500Mb nextcloud just fails and produces that exact error in the log. This issue filled my trashbin so my server ran out of space. What can I do/provide to be of more help?

Version: 8.0.23

Memory limit: 512 MB

Max execution time: 3600

Upload max size: 16 GB

Extensions: Core, date, libxml, openssl, pcre, zlib, bcmath, bz2, ctype, curl, dom, hash, fileinfo, filter, ftp, gd, gmp, SPL, iconv, intl, json, ldap, mbstring, pcntl, PDO, session, posix, Reflection, standard, SimpleXML, mysqlnd, exif, tokenizer, xml, xmlreader, xmlwriter, zip, pdo_mysql, cgi-fcgi, redis, Zend OPcache

@blizzz blizzz modified the milestones: Nextcloud 25, Nextcloud 26 Oct 19, 2022
@szaimen
Copy link
Contributor

szaimen commented Jan 9, 2023

Hi, please update to 24.0.8 or better 25.0.2 and report back if it fixes the issue. Thank you!

@szaimen szaimen added needs info 0. Needs triage Pending check for reproducibility or if it fits our roadmap and removed 1. to develop Accepted and waiting to be taken care of labels Jan 9, 2023
@nickvergessen nickvergessen added 1. to develop Accepted and waiting to be taken care of and removed 0. Needs triage Pending check for reproducibility or if it fits our roadmap 23-feedback Feedback from 23.x releases labels Jan 9, 2023
@nickvergessen
Copy link
Member Author

Seems to be not happening directly on activity anymore.
But we still logged 250+ memory exhausted messages on our instance this year

@szaimen
Copy link
Contributor

szaimen commented Jan 9, 2023

Seems to be not happening directly on activity anymore. But we still logged 250+ memory exhausted messages on our instance this year

closing because we already have another open issue about the general issue

@szaimen szaimen closed this as completed Jan 9, 2023
@h0lley
Copy link

h0lley commented Feb 4, 2024

this can still / again happen on Nextcloud 28.0.2.

Allowed memory size of 536870912 bytes exhausted (tried to allocate 65062824 bytes) at /var/www/html/lib/private/AppFramework/Middleware/CompressionMiddleware.php#88

full log entry:

{"reqId":"8ivbWlWIHtnsi3YteECA","level":3,"time":"2024-02-04T03:00:18+00:00","remoteAddr":"82.82.77.165","user":"holly","app":"PHP","method":"GET","url":"/apps/logreader/api/poll?lastReqId=","message":"Allowed memory size of 536870912 bytes exhausted (tried to allocate 65062824 bytes) at /var/www/html/lib/private/AppFramework/Middleware/CompressionMiddleware.php#88","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36","version":"28.0.2.5","data":{"app":"PHP"}}

only one line off this time, so I'd guess it's the same issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

7 participants