Recipes
Recipes copied to clipboard
CommunitySolidServer
mashlib with subdomain : serverRoot/.acl lock errors and server breaks on .internal/accounts/index/owner/
[email protected] with [email protected] (both are latest)
Server root/.acl errors on lock every hour https://solidcommunity.net:8443/.internal/accounts/index/owner/
There is no account for www and the owner is not expected to exist
and then the server is killed and restarts
-
www directory
# ls -al /mnt/*04/test*/www
total 6732
drwxr-xr-x 4 root root 4096 Jan 24 08:26 .
drwxr-xr-x 16615 root root 487424 Jan 23 16:26 ..
-rw-r--r-- 1 root root 285 Jan 11 10:44 .acl
drwxr-xr-x 5 root root 4096 Jan 6 07:07 .internal
drwxr-xr-x 4 root root 4096 Jan 23 19:45 common
-rw-r--r-- 1 root root 5784 Jan 24 08:26 index.html
-rw-r--r-- 1 root root 1199 Jan 23 19:41 index.html-bak
-rw-r--r-- 1 root root 6358495 Jan 23 19:49 mashlib.js
-rw-r--r-- 1 root root 295 Jan 23 19:50 mashlib.js.acl
-rw-r--r-- 1 root root 5801 Jan 24 08:19 test.html
-rw-r--r-- 1 root root 294 Jan 24 08:19 test.html.acl
-
www/.acladding acl: default do not make any difference (I also tested with acl:default)
# cat /mnt/*04//test*/www/.acl
# Root ACL resource for the domain root
@prefix acl: <http://www.w3.org/ns/auth/acl#>.
@prefix foaf: <http://xmlns.com/foaf/0.1/>.
# The homepage is readable by the public
<#public>
a acl:Authorization;
acl:agentClass foaf:Agent;
acl:accessTo <./>;
acl:mode acl:Read.
-
detail of the logs
## every minutes logs
2025-01-26T09:15:27.013Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-01-26T09:15:27.020Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:8443/.acl
....
## every hour errors logs
2025-01-26T09:18:28.213Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-01-26T09:18:28.218Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:8443/.acl
2025-01-26T09:19:25.554Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-01-26T09:19:25.555Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-01-26T09:19:25.556Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-01-26T09:19:25.556Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-01-26T09:19:25.556Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-01-26T09:19:25.556Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-01-26T09:19:25.556Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-01-26T09:19:25.558Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-01-26T09:19:28.538Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-01-26T09:19:28.550Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:8443/.acl
## the server restarts log
2025-01-26T09:20:05.809Z [ServerInitializer] {Primary} info: Listening to server at https://localhost:8443/
## and back to every minutes logs
2025-01-26T09:20:29.111Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-01-26T09:20:29.129Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:8443/.acl
...
When you say it breaks the server, do you mean that the server crashes and stops working?
The class that is complaining is one that cleans up expired entries from disk every hour, and apparently is somehow unable to perform its action on the .internal/accounts/index/owner/ container. I can't say why though, could be disk issues or something else.
The server is killed and restarted by PM2.
When I add a WebId agent in www/.acl there are errors but the server is not killed.
Is there no output of the server throwing an error outside of the logging of some kind? That is what I would expect it if it fully stops. Now it seems like there are some errors (due to data corruption? not sure) every hour, but since there are also logs after those errors it seems like the server continues after that and then suddenly stops. This makes it quite hard to reproduce and find where the error is.
I have checked on the CSS test servers subdomain and suffix and the logs are a bit different
- subdomain the .acl has everybody Read but also an agent with Read, Write, Control
- every minute message
- every hour errors, but not a breaking server one
2025-02-03T08:00:28.883Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-03T08:00:28.889Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:3000/.acl
2025-02-03T08:00:35.382Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith')
2025-02-03T08:00:35.382Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith')
2025-02-03T08:00:35.382Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith')
2025-02-03T08:00:35.383Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith')
2025-02-03T08:01:29.128Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-03T08:01:29.133Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:3000/.acl
2025-02-03T08:02:29.436Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-03T08:02:29.443Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:3000/.acl
- suffix the .acl has everybody Read but also an agent with Read, Write, Control
- every 10 minutes message
- no hour errors
2025-02-03T08:04:39.618Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-03T08:14:39.694Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-03T08:24:39.782Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-03T08:34:39.867Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
The 1 hour errors seem to indicate that an internal path might be badly configured when using subdomains. I'll see if I can find the cause. Fortunately it doesn't crash the server
The 10 min logs indicate the server receives an external HTTP request from somewhere.
I did some small tests and can't reproduce the issue. The server seems to correctly map the URI to the expected folder when using subdomains. The issue could be that there is so much data the server can't iterate over it quickly enough when going through all the internal files, causing these locking issues.
If you are running the server as a singlethreaded process, you could switch the locking system to memory based instead of file based. This might end up solving all your issues with locking errors as that one will be much more performant.
I replaced locks in file with locks in memory and the issue is still exactly the same on the 2 subdomain servers
- subdomain https://solidcommunity.net:8443 with 17000 accounts still SGKILL 137 every hour
- subdomain https://solidcommunitynet:3000 with about 10 accounts still receives a non breaking server error every hour
- suffix https://solidcommunity.net:3100 a suffix server never has any issue
I also updated PM2 to latest. I shall update later or tomorrow morning on PM2 logs
2025-02-05T13:15:42: PM2 log: PM2 successfully stopped
2025-02-05T13:15:42: PM2 log: ===============================================================================
2025-02-05T13:15:42: PM2 log: --- New PM2 Daemon started ----------------------------------------------------
2025-02-05T13:15:42: PM2 log: Time : Wed Feb 05 2025 13:15:42 GMT+0000 (Coordinated Universal Time)
2025-02-05T13:15:42: PM2 log: PM2 version : 5.4.3
2025-02-05T13:15:42: PM2 log: Node.js version : 20.18.0
2025-02-05T13:15:42: PM2 log: Current arch : x64
2025-02-05T13:15:42: PM2 log: PM2 home : /root/.pm2
2025-02-05T13:15:42: PM2 log: PM2 PID file : /root/.pm2/pm2.pid
2025-02-05T13:15:42: PM2 log: RPC socket file : /root/.pm2/rpc.sock
2025-02-05T13:15:42: PM2 log: BUS socket file : /root/.pm2/pub.sock
2025-02-05T13:15:42: PM2 log: Application log path : /root/.pm2/logs
2025-02-05T13:15:42: PM2 log: Worker Interval : 30000
2025-02-05T13:15:42: PM2 log: Process dump file : /root/.pm2/dump.pm2
2025-02-05T13:15:42: PM2 log: Concurrent actions : 2
2025-02-05T13:15:42: PM2 log: SIGTERM timeout : 1600
2025-02-05T13:15:42: PM2 log: ===============================================================================
2025-02-05T13:15:42: PM2 log: App [css-subdomain:0] starting in -fork mode-
2025-02-05T13:15:42: PM2 log: App [css-suffix:1] starting in -fork mode-
2025-02-05T13:15:42: PM2 log: App [css-subdomain:0] online
2025-02-05T13:15:42: PM2 log: App [css-suffix:1] online
2025-02-05T13:15:42: PM2 log: App [solid:2] starting in -fork mode-
2025-02-05T13:15:42: PM2 log: App [solid:2] online
2025-02-05T13:15:42: PM2 log: App [pivot-8443-mnt04:3] starting in -fork mode-
2025-02-05T13:15:42: PM2 log: App [pivot-8443-mnt04:3] online
2025-02-05T13:15:42: PM2 log: App [pm2-logrotate:4] starting in -fork mode-
2025-02-05T13:15:42: PM2 log: App [pm2-logrotate:4] online
2025-02-05T14:16:37: PM2 log: App [pivot-8443-mnt04:3] exited with code [137] via signal [SIGINT]
2025-02-05T14:16:37: PM2 log: App [pivot-8443-mnt04:3] starting in -fork mode-
2025-02-05T14:16:37: PM2 log: App [pivot-8443-mnt04:3] online
2025-02-05T15:17:47: PM2 log: App [pivot-8443-mnt04:3] exited with code [137] via signal [SIGINT]
2025-02-05T15:17:47: PM2 log: App [pivot-8443-mnt04:3] starting in -fork mode-
2025-02-05T15:17:47: PM2 log: App [pivot-8443-mnt04:3] online
2025-02-05T15:50:19: PM2 log: Stopping app:pivot-8443-mnt04 id:3
2025-02-05T15:50:19: PM2 log: App [pivot-8443-mnt04:3] exited with code [0] via signal [SIGINT]
2025-02-05T15:50:19: PM2 log: pid=297159 msg=process killed
2025-02-05T15:50:19: PM2 log: App [pivot-8443-mnt04:3] starting in -fork mode-
2025-02-05T15:50:19: PM2 log: App [pivot-8443-mnt04:3] online
2025-02-05T16:21:22: PM2 log: Stopping app:css-subdomain id:0
2025-02-05T16:21:22: PM2 log: App [css-subdomain:0] exited with code [0] via signal [SIGINT]
2025-02-05T16:21:22: PM2 log: pid=296629 msg=process killed
2025-02-05T16:21:22: PM2 log: App [css-subdomain:0] starting in -fork mode-
2025-02-05T16:21:22: PM2 log: App [css-subdomain:0] online
2025-02-05T17:50:52: PM2 log: App [pivot-8443-mnt04:3] exited with code [137] via signal [SIGINT]
2025-02-05T17:50:52: PM2 log: App [pivot-8443-mnt04:3] starting in -fork mode-
2025-02-05T17:50:52: PM2 log: App [pivot-8443-mnt04:3] online
The problem is that I can't reproduce this which makes it hard to discover where the problem is exactly. What I tried now is setting up a server with the file.json config, but changing it so it uses subdomains. And then seeding 10 accounts, with 2 pods each. I changed the code in the server so it does that hourly check every minute instead of every hour, but still let it run for more than hour just to be sure. But I didn't get any error so I'm not sure where to look then. Do you have server logs from before the crash from the CSS itself? Because I assume they would be different when using the memory locker.
Hope this helps.
These are last hours logs The minute calls are not there anymore I stopped uptimeKuma checking if the server is up an running
2025-02-06T13:05:15.224Z [ServerInitializer] {Primary} info: Listening to server at https://localhost:8443/
2025-02-06T14:01:25.998Z [HandlerServerConfigurator] {Primary} info: Received GET request for /?XDEBUG_SESSION_START=phpstorm
2025-02-06T14:01:26.010Z [TargetExtractorErrorHandler] {Primary} warn: Unable to add identifier to error metadata: The identifier https://68.183.44.209:8443/ is outside the configured identifier space.
2025-02-06T14:05:24.108Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T14:05:24.144Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T14:05:24.177Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T14:05:24.218Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T14:05:24.236Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T14:05:24.282Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T14:05:24.284Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T14:05:24.325Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T14:05:57.812Z [ServerInitializer] {Primary} info: Listening to server at https://localhost:8443/
2025-02-06T14:19:02.780Z [HandlerServerConfigurator] {Primary} info: Received GET request for /remote/login?lang=en
2025-02-06T14:19:02.790Z [TargetExtractorErrorHandler] {Primary} warn: Unable to add identifier to error metadata: The request has an invalid Host header: https://68.183.44.209/
2025-02-06T14:19:03.012Z [HandlerServerConfigurator] {Primary} info: Received GET request for /remote/login?lang=en
2025-02-06T14:19:03.015Z [TargetExtractorErrorHandler] {Primary} warn: Unable to add identifier to error metadata: The request has an invalid Host header: https://68.183.44.209/
2025-02-06T14:22:42.775Z [HandlerServerConfigurator] {Primary} info: Received GET request for /actuator/gateway/routes
2025-02-06T14:22:42.783Z [TargetExtractorErrorHandler] {Primary} warn: Unable to add identifier to error metadata: The identifier https://68.183.44.209:8443/actuator/gateway/routes is outside the configured identifier space.
2025-02-06T14:36:58.822Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-06T14:36:58.826Z [TargetExtractorErrorHandler] {Primary} warn: Unable to add identifier to error metadata: The identifier https://68.183.44.209/ is outside the configured identifier space.
2025-02-06T14:36:59.004Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-06T14:36:59.008Z [TargetExtractorErrorHandler] {Primary} warn: Unable to add identifier to error metadata: The identifier https://68.183.44.209/ is outside the configured identifier space.
2025-02-06T15:01:20.708Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-06T15:01:20.730Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings
2025-02-06T15:01:20.745Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public
2025-02-06T15:01:20.785Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:8443/.acl
2025-02-06T15:01:20.890Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.solidcommunity.net:8443/.acl
2025-02-06T15:01:20.922Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.solidcommunity.net:8443/.acl
2025-02-06T15:01:20.949Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2025-02-06T15:01:20.971Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2025-02-06T15:01:20.992Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings//
2025-02-06T15:01:21.031Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/settings//.acl
2025-02-06T15:01:21.056Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2025-02-06T15:01:21.073Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings/
2025-02-06T15:01:21.098Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/settings/.acl
2025-02-06T15:01:21.118Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2025-02-06T15:01:21.143Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings
2025-02-06T15:01:21.190Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/.acl
2025-02-06T15:01:21.268Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings/
2025-02-06T15:01:21.289Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/settings/.acl
2025-02-06T15:01:21.311Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2025-02-06T15:06:05.635Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T15:06:05.684Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T15:06:05.701Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T15:06:05.742Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T15:06:05.754Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T15:06:05.782Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T15:06:05.790Z [WrappedExpiringReadWriteLocker] {Primary} error: Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T15:06:05.808Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Lock expired after 6000ms on https://solidcommunity.net:8443/.internal/accounts/index/owner/
2025-02-06T15:06:33.971Z [ServerInitializer] {Primary} info: Listening to server at https://localhost:8443/
2025-02-06T15:07:35.201Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card
2025-02-06T15:07:35.247Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/profile/card.acl
2025-02-06T15:07:35.431Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card
2025-02-06T15:07:35.437Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-06T15:07:35.491Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/profile/card.acl
2025-02-06T15:07:35.496Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/.acl
2025-02-06T15:07:35.643Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card.meta
2025-02-06T15:07:35.673Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/profile/card.acl
2025-02-06T15:07:41.325Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card
2025-02-06T15:07:41.353Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/profile/card.acl
2025-02-06T15:07:41.449Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card
2025-02-06T15:07:41.466Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/profile/card.acl
2025-02-06T15:07:41.597Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card.meta
2025-02-06T15:07:41.614Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/profile/card.acl
2025-02-06T15:08:03.409Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public/
2025-02-06T15:08:03.434Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/public/.acl
2025-02-06T15:08:03.680Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public/
2025-02-06T15:08:03.711Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/public/.acl
2025-02-06T15:08:03.932Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public/.meta
2025-02-06T15:08:03.953Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/public/.acl
2025-02-06T15:11:52.256Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card
2025-02-06T15:11:52.276Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/profile/card.acl
2025-02-06T15:11:52.405Z [HandlerServerConfigurator] {Primary} info: Received GET request for /mashlib.min.js
2025-02-06T15:11:52.408Z [HandlerServerConfigurator] {Primary} info: Received GET request for /mash.css
2025-02-06T15:11:53.038Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card
2025-02-06T15:11:53.045Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-06T15:11:53.100Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/profile/card.acl
2025-02-06T15:11:53.101Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/.acl
2025-02-06T15:11:53.246Z [HandlerServerConfigurator] {Primary} info: Received GET request for /favicon.ico
2025-02-06T15:11:53.396Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card.meta
2025-02-06T15:11:53.438Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/profile/card.acl
2025-02-06T15:15:26.298Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public
2025-02-06T15:15:26.326Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings
2025-02-06T15:15:26.332Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings//
2025-02-06T15:15:26.337Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings
2025-02-06T15:15:26.351Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings/
2025-02-06T15:15:26.363Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-06T15:15:26.423Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/settings//.acl
2025-02-06T15:15:26.428Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/settings/.acl
2025-02-06T15:15:26.432Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:8443/.acl
2025-02-06T15:15:26.437Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.solidcommunity.net:8443/.acl
2025-02-06T15:15:26.467Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2025-02-06T15:15:26.484Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2025-02-06T15:15:26.543Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/.acl
2025-02-06T15:15:26.580Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2025-02-06T15:15:26.619Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.solidcommunity.net:8443/.acl
2025-02-06T15:15:26.779Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2025-02-06T15:15:26.868Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings/
2025-02-06T15:15:26.889Z [WebAclReader] {Primary} info: Found applicable ACL document https://bourgeoa.solidcommunity.net:8443/settings/.acl
2025-02-06T15:15:26.901Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2025-02-06T15:15:27.032Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-02-06T15:15:27.047Z [HandlerServerConfigurator] {Primary} info: Received GET request for /common/js/index-buttons.js
2025-02-06T15:15:27.071Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:8443/.acl
2025-02-06T15:15:27.074Z [HandlerServerConfigurator] {Primary} info: Received GET request for /mashlib.js
2025-02-06T15:15:27.084Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:8443/common/js/index-buttons.js.acl
2025-02-06T15:15:27.123Z [HandlerServerConfigurator] {Primary} info: Received GET request for /mashlib.js
2025-02-06T15:15:27.176Z [HandlerServerConfigurator] {Primary} info: Received GET request for /common/js/index-buttons.js
2025-02-06T15:15:27.220Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidcommunity.net:8443/common/js/index-buttons.js.acl
2025-02-06T15:15:27.263Z [HandlerServerConfigurator] {Primary} info: Received GET request for /browse.html
2025-02-06T15:15:37.060Z [HandlerServerConfigurator] {Primary} error: Request error: aborted
2025-02-06T15:15:37.088Z [HandlerServerConfigurator] {Primary} error: Request error: aborted
2025-02-06T15:15:38.061Z [GuardedStream] {Primary} error: No error listener was attached but error was thrown: premature close
2025-02-06T15:15:38.089Z [GuardedStream] {Primary} error: No error listener was attached but error was thrown: premature close
PM2 logs on same period server killed/restarted every hour
2025-02-06T13:04:58: PM2 log: App [pivot-8443-mnt04:3] exited with code [137] via signal [SIGINT]
2025-02-06T13:04:58: PM2 log: App [pivot-8443-mnt04:3] starting in -fork mode-
2025-02-06T13:04:58: PM2 log: App [pivot-8443-mnt04:3] online
2025-02-06T14:05:41: PM2 log: App [pivot-8443-mnt04:3] exited with code [137] via signal [SIGINT]
2025-02-06T14:05:41: PM2 log: App [pivot-8443-mnt04:3] starting in -fork mode-
2025-02-06T14:05:41: PM2 log: App [pivot-8443-mnt04:3] online
2025-02-06T15:06:21: PM2 log: App [pivot-8443-mnt04:3] exited with code [137] via signal [SIGINT]
2025-02-06T15:06:21: PM2 log: App [pivot-8443-mnt04:3] starting in -fork mode-
2025-02-06T15:06:21: PM2 log: App [pivot-8443-mnt04:3] online
I am having new experiment. Always with all 17000 accounts.
- This night running CSS+mashlib with no server kill/restart
- I am now running again adding the pod-quota parameter
@joachimvh
I changed the code in the server so it does that hourly check every minute instead of every hour
Could you tell me how to do the same change, it will shorten my tests.
I am having new experiment. Always with all 17000 accounts.
- This night running CSS+mashlib with no server kill/restart
- I am now running again adding the pod-quota parameter
Good news after 2 hours the server did not stop/restart on the hourly actions I only get
2025-02-07T09:29:48.470Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidproject.solidcommunity.net:8443/.acl
2025-02-07T09:35:14.123Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith')
2025-02-07T09:35:14.180Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith')
2025-02-07T09:35:14.220Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith')
2025-02-07T09:35:14.228Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith')
I shall now continue the tests adding one by one changes made by Pivot
The first one will be "css:config/http/handler/default.json" to "pivot:config/http/handler/default.json" If URL without slash returns 404 then try adding a slash
Could you tell me how to do the same change, it will shorten my tests.
I did this by changing the code itself, change the 60 here to 1: https://github.com/CommunitySolidServer/CommunitySolidServer/blob/ca89c10dd448cd922792485d11cb507d23fbdc15/src/storage/keyvalue/WrappedExpiringStorage.ts#L24
Instead of changing the code, you can also do it by changing the relevant configuration for every instance of that storage, by adding the following to your configuration:
{
"@id": "urn:solid-server:default:CookieStorage",
"@type": "WrappedExpiringStorage",
"timeout": 1
},
{
"@id": "urn:solid-server:default:ForgotPasswordStorage",
"@type": "WrappedExpiringStorage",
"timeout": 1
},
{
"@id": "urn:solid-server:default:ExpiringTokenStorage",
"@type": "WrappedExpiringStorage",
"timeout": 1
}
This only changes 3 of the 4 instances as the 4th one doesn't have an explicit identifier. But I would guess that this should already be sufficient if there is an issue.
- I am now running again adding the pod-quota parameter
I did not enable quota during my previous tests, so potentially that part is also related. I had a quick look and some of the quota-related configurations seem to have hardcoded paths in them which might be a cause for conflict when the server is configured for subdomains. Would have to run some more extensive tests to be sure.
Good news after 2 hours the server did not stop/restart on the hourly actions I only get
2025-02-07T09:29:48.470Z [WebAclReader] {Primary} info: Found applicable ACL document https://solidproject.solidcommunity.net:8443/.acl 2025-02-07T09:35:14.123Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith') 2025-02-07T09:35:14.180Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith') 2025-02-07T09:35:14.220Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith') 2025-02-07T09:35:14.228Z [WrappedExpiringStorage] {Primary} error: Error during interval callback: Failed to remove expired entries - Cannot read properties of undefined (reading 'startsWith')I shall now continue the tests adding one by one changes made by Pivot
Seems that the kill/restart issue is in Pivot PATCH returning Pretty turtle.
The remaining hourly CSS issue is not a blocking problem. Because it does not break the server.