Recipes icon indicating copy to clipboard operation
Recipes copied to clipboard
verified publisher icon CommunitySolidServer

Lock error on uncaught exception

Open bourgeoa opened this issue 1 year ago • 7 comments

http and mashlib with subdomain

2025-01-19T12:18:01.710Z [MemoryResourceLocker] {Primary} debug: Released lock for http://localhost:8443/.internal/accounts/data/0145e06c-21f9-4edf-9195-242bdcdaa6de. 1 active locks remaining.
Process is halting due to an uncaughtException with error ENOENT: no such file or directory, stat '/mnt/d/github/pivot/data/.internal/locks/633155acad9c251831c4240f44d91c3a'
/mnt/d/github/pivot/node_modules/@solid/community-server/dist/util/locking/FileSystemResourceLocker.js:159
            throw err;
            ^

[Error: ENOENT: no such file or directory, stat '/mnt/d/github/pivot/data/.internal/locks/633155acad9c251831c4240f44d91c3a'] {
  errno: -2,
  code: 'ECOMPROMISED',
  syscall: 'stat',
  path: '/mnt/d/github/pivot/data/.internal/locks/633155acad9c251831c4240f44d91c3a'
}

Node.js v20.18.0

bourgeoa avatar Jan 19 '25 12:01 bourgeoa

Is this a consistent problem and if yes can you give me the steps to reproduce including the configuration? I just tried it myself with a subdomain configuration but did not have any errors.

One thing that is weird from your log is that it contains both a message from the MemoryResourceLocker, and an error thrown from the FileSystemResourceLocker. The first is the locker that is used when you import util/resource-locker/memory.json and the second one is from util/resource-locker/file.json. So the fact that both occur in the same log makes me wonder how they both got instantiated.

joachimvh avatar Jan 20 '25 08:01 joachimvh

The issue happened yesterday once again I shall try to reproduce it.

  • Context CSS 1.7.3 with mashlib on http
  • node 20.18 and WSL on W11
  • one account/pod created
  • mashlib with (I added text/html as disabled)
        "options_disabledMediaRanges": [
          "image/*",
          "application/pdf",
          "text/html"
        ]
  • I was trying to resolve/reproduce the #41 #43 issues in differents ACL's context and I thing the browser URL was test.html document http://bob.localhost:8443/public/test.html I was logged in and was editing ACL of the same document with the mashlib aclApp (/test.html.acl)

It is a change of authorisation on a loaded document (?? in memory document)

bourgeoa avatar Jan 20 '25 10:01 bourgeoa

Well just reproduced but this is not what I explained. Full logs from GET

2025-01-20T11:49:38.441Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public/
2025-01-20T11:49:38.441Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.442Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.442Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.443Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.443Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.443Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.443Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.444Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.444Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.444Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.445Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.445Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.445Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.445Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.446Z [SubdomainIdentifierStrategy] {Primary} debug: Identifier http://bob.localhost:8443/public/ is part of http://localhost:8443/
2025-01-20T11:49:38.446Z [BasicConditionsParser] {Primary} debug: Found the following conditions: {"notMatchesETag":["\"1737373388000-text/turtle\""]}
2025-01-20T11:49:38.446Z [RawBodyParser] {Primary} debug: HTTP request does not have a body, or its empty body is missing a Content-Type header
2025-01-20T11:49:38.447Z [AuthorizingHttpHandler] {Primary} verbose: Extracted credentials: {}
2025-01-20T11:49:38.447Z [AuthorizingHttpHandler] {Primary} verbose: Retrieved required modes: { http://bob.localhost:8443/public/: read }
2025-01-20T11:49:38.448Z [OwnerPermissionReader] {Primary} debug: No authorization resources found that need an ownership check.
2025-01-20T11:49:38.448Z [WebAclReader] {Primary} debug: Retrieving permissions of an unknown agent
2025-01-20T11:49:38.448Z [WebAclReader] {Primary} debug: Searching ACL data for http://bob.localhost:8443/public/
2025-01-20T11:49:38.448Z [WebAclReader] {Primary} debug: Trying to read the direct ACL document of http://bob.localhost:8443/public/
2025-01-20T11:49:38.449Z [WebAclReader] {Primary} debug: Determining existence of  http://bob.localhost:8443/public/.acl
2025-01-20T11:49:38.449Z [MemoryResourceLocker] {Primary} debug: Acquiring lock for http://bob.localhost:8443/public/
2025-01-20T11:49:38.449Z [MemoryResourceLocker] {Primary} debug: Acquired lock for http://bob.localhost:8443/public/. 1 locks active.
2025-01-20T11:49:38.449Z [FileSystemResourceLocker] {Primary} debug: Acquiring lock for http://bob.localhost:8443/public/
Process is halting due to an uncaughtException with error Unable to update lock within the stale threshold
/mnt/d/github/pivot/node_modules/@solid/community-server/dist/util/locking/FileSystemResourceLocker.js:159
            throw err;
            ^

Error: Unable to update lock within the stale threshold
    at /mnt/d/github/pivot/node_modules/proper-lockfile/lib/lockfile.js:136:25
    at callback (/mnt/d/github/pivot/node_modules/graceful-fs/polyfills.js:306:20)
    at FSReqCallback.oncomplete (node:fs:198:5) {
  code: 'ECOMPROMISED'
}

Node.js v20.18.0

bourgeoa avatar Jan 20 '25 11:01 bourgeoa

Just reproduced again on a pure CSS 1.7.3 not pivot

  • logged in
  • The issue arise when I put a double // like in http://bob.localhost:3000/public// then no issue
  • then force reload page (I use chrome Version 131.0.6778.265 (Build officiel) (64 bits))
2025-01-20T14:33:51.915Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public//
2025-01-20T14:33:51.918Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card
2025-01-20T14:33:51.920Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: http://bob.localhost:3000/profile/card#me, client ID: HWPX91MFAlCrwRnkNwA_i, issuer: http://localhost:3000/
2025-01-20T14:33:51.922Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: http://bob.localhost:3000/profile/card#me, client ID: HWPX91MFAlCrwRnkNwA_i, issuer: http://localhost:3000/
2025-01-20T14:33:51.926Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/public//.acl
2025-01-20T14:33:51.927Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/profile/card.acl
2025-01-20T14:33:51.955Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/profile/card.acl
2025-01-20T14:33:51.956Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/public//.acl
2025-01-20T14:33:52.010Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public//.meta
2025-01-20T14:33:52.013Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2025-01-20T14:33:52.016Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public/
2025-01-20T14:33:52.020Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings/prefs.ttl
2025-01-20T14:33:52.024Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: http://bob.localhost:3000/profile/card#me, client ID: HWPX91MFAlCrwRnkNwA_i, issuer: http://localhost:3000/
2025-01-20T14:33:52.025Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: http://bob.localhost:3000/profile/card#me, client ID: HWPX91MFAlCrwRnkNwA_i, issuer: http://localhost:3000/
2025-01-20T14:33:52.029Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: http://bob.localhost:3000/profile/card#me, client ID: HWPX91MFAlCrwRnkNwA_i, issuer: http://localhost:3000/
2025-01-20T14:33:52.031Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: http://bob.localhost:3000/profile/card#me, client ID: HWPX91MFAlCrwRnkNwA_i, issuer: http://localhost:3000/
2025-01-20T14:33:52.034Z [PermissionBasedAuthorizer] {Primary} warn: Agent {"agent":{"webId":"http://bob.localhost:3000/profile/card#me"},"issuer":{"url":"http://localhost:3000/"},"client":{"clientId":"HWPX91MFAlCrwRnkNwA_i"}} has no read permissions
2025-01-20T14:33:52.042Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/public//.acl
2025-01-20T14:33:52.043Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/.acl
2025-01-20T14:33:52.047Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/settings/.acl
2025-01-20T14:33:52.079Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/public//.acl
2025-01-20T14:33:52.094Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/settings/.acl
2025-01-20T14:33:52.095Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/.acl
2025-01-20T14:33:52.139Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings/publicTypeIndex.ttl
2025-01-20T14:33:52.141Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings/privateTypeIndex.ttl
2025-01-20T14:33:52.144Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: http://bob.localhost:3000/profile/card#me, client ID: HWPX91MFAlCrwRnkNwA_i, issuer: http://localhost:3000/
2025-01-20T14:33:52.145Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: http://bob.localhost:3000/profile/card#me, client ID: HWPX91MFAlCrwRnkNwA_i, issuer: http://localhost:3000/
2025-01-20T14:33:52.148Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/settings/publicTypeIndex.ttl.acl
2025-01-20T14:33:52.151Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/settings/.acl
2025-01-20T14:33:52.169Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/settings/publicTypeIndex.ttl.acl
2025-01-20T14:33:52.177Z [WebAclReader] {Primary} info: Found applicable ACL document http://bob.localhost:3000/settings/.acl
Process is halting due to an uncaughtException with error ENOENT: no such file or directory, stat '/mnt/d/github/solidos/workspaces/css-mashlib/data/.internal/locks/cb3138f7691ac12e9038d30cd7ea5658'
/mnt/d/github/solidos/workspaces/css-mashlib/node_modules/@solid/community-server/dist/util/locking/FileSystemResourceLocker.js:159
            throw err;
            ^

[Error: ENOENT: no such file or directory, stat '/mnt/d/github/solidos/workspaces/css-mashlib/data/.internal/locks/cb3138f7691ac12e9038d30cd7ea5658'] {
  errno: -2,
  code: 'ECOMPROMISED',
  syscall: 'stat',
  path: '/mnt/d/github/solidos/workspaces/css-mashlib/data/.internal/locks/cb3138f7691ac12e9038d30cd7ea5658'
}

Node.js v20.18.0

bourgeoa avatar Jan 20 '25 14:01 bourgeoa

I did some tests and can reproduce indeed. Only when combining with mashlib though, not the CSS in itself. But even then this should not cause the server to completely halt so I'll have a look if I can prevent that.

joachimvh avatar Jan 21 '25 08:01 joachimvh

The crashing will be fixed by https://github.com/CommunitySolidServer/CommunitySolidServer/pull/1980. Best would be if the error just wouldn't happen but I can't say what the cause is as it currently seems to only happen in combination with mashlib.

joachimvh avatar Jan 21 '25 11:01 joachimvh

The server crashing when a lock is compromised has been fixed in v7.1.5. Not sure yet why this error occurs when combining mashlib and CSS with a double slash URL though.

joachimvh avatar Jan 23 '25 08:01 joachimvh