Skip to content

Lock error on uncaught exception #44

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.

Sign up for GitHub

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

Jump to bottom
Open
bourgeoa opened this issue Jan 19, 2025 · 7 comments
Open

Lock error on uncaught exception #44

bourgeoa opened this issue Jan 19, 2025 · 7 comments

Comments

@bourgeoa
Copy link

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
@joachimvh
Copy link
Member

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.

@bourgeoa
Copy link
Author

bourgeoa commented Jan 20, 2025 •
edited
Loading

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

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

@bourgeoa
Copy link
Author

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
Copy link
Author

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

@joachimvh
Copy link
Member

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 joachimvh mentioned this issue Jan 21, 2025
Merged
@joachimvh
Copy link
Member

The crashing will be fixed by CommunitySolidServer/CommunitySolidServer#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 joachimvh mentioned this issue Jan 23, 2025
Closed
@joachimvh
Copy link
Member

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@bourgeoa @joachimvh