Skip to content

Server crashes due to locking problems #29

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
michielbdejong opened this issue Nov 21, 2024 · 6 comments
Open

Server crashes due to locking problems #29

michielbdejong opened this issue Nov 21, 2024 · 6 comments

Comments

@michielbdejong
Copy link
Collaborator

The server is crashing repeatedly when I try to log in to view https://michielbdejong.pivot.pondersource.com/README/
Investigating.
@michielbdejong
Copy link
Collaborator Author 

2024-11-21T13:59:09.109Z [HandlerServerConfigurator] {Primary} info: Received GET request for /README/
2024-11-21T13:59:09.131Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/.acl
2024-11-21T13:59:09.148Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2024-11-21T13:59:09.282Z [HandlerServerConfigurator] {Primary} info: Received GET request for /mash.css.map
2024-11-21T13:59:09.297Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/.acl
2024-11-21T13:59:09.319Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2024-11-21T13:59:09.469Z [HandlerServerConfigurator] {Primary} info: Received GET request for /.well-known/openid-configuration
2024-11-21T13:59:10.015Z [HandlerServerConfigurator] {Primary} info: Received GET request for /.well-known/openid-configuration
2024-11-21T13:59:10.272Z [HandlerServerConfigurator] {Primary} info: Received GET request for /.oidc/auth?client_id=iv8eipbxcqAu3HIEEn0Kx&redirect_uri=https%3A%2F%2Fmichielbdejong.pivot.pondersource.com%2FREADME%2F&response_type=code&scope=openid%20offline_access%20webid&state=920524e133f5481bb1f5e79160fd773f&code_challenge=fkUjOoIOhWqkw2f7k5h-4ZoULxXGkic0vv-iVXan_14&code_challenge_method=S256&prompt=none&response_mode=query
2024-11-21T13:59:10.768Z [HandlerServerConfigurator] {Primary} info: Received GET request for /README/?code=_FN9dxgjuOKQjruxq2dG3XFj0kELdtXd2FrtxOSjRyr&state=920524e133f5481bb1f5e79160fd773f&iss=https%3A%2F%2Fpivot.pondersource.com%2F
2024-11-21T13:59:10.777Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/.acl
2024-11-21T13:59:10.797Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2024-11-21T13:59:10.914Z [HandlerServerConfigurator] {Primary} info: Received GET request for /mash.css.map
2024-11-21T13:59:10.922Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/.acl
2024-11-21T13:59:10.933Z [PermissionBasedAuthorizer] {Primary} warn: Unauthenticated agent has no read permissions
2024-11-21T13:59:10.938Z [HandlerServerConfigurator] {Primary} info: Received GET request for /.well-known/openid-configuration
2024-11-21T13:59:11.039Z [HandlerServerConfigurator] {Primary} info: Received OPTIONS request for /.oidc/token
2024-11-21T13:59:11.130Z [HandlerServerConfigurator] {Primary} info: Received POST request for /.oidc/token
2024-11-21T13:59:11.334Z [HandlerServerConfigurator] {Primary} info: Received GET request for /.oidc/jwks
2024-11-21T13:59:11.439Z [HandlerServerConfigurator] {Primary} info: Received GET request for /README/
2024-11-21T13:59:11.455Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card
2024-11-21T13:59:11.473Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card
2024-11-21T13:59:11.488Z [HandlerServerConfigurator] {Primary} info: Received GET request for /profile/card
2024-11-21T13:59:11.499Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/profile/card.acl
2024-11-21T13:59:11.510Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/profile/card.acl
2024-11-21T13:59:11.773Z [HandlerServerConfigurator] {Primary} info: Received GET request for /.well-known/openid-configuration
2024-11-21T13:59:11.787Z [HandlerServerConfigurator] {Primary} info: Received GET request for /.well-known/openid-configuration
2024-11-21T13:59:11.790Z [HandlerServerConfigurator] {Primary} info: Received GET request for /.oidc/jwks
2024-11-21T13:59:11.798Z [HandlerServerConfigurator] {Primary} info: Received GET request for /.oidc/jwks
2024-11-21T13:59:11.806Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: https://michielbdejong.pivot.pondersource.com/profile/card#me, client ID: iv8eipbxcqAu3HIEEn0Kx, issuer: https://pivot.pondersource.com/
2024-11-21T13:59:11.810Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: https://michielbdejong.pivot.pondersource.com/profile/card#me, client ID: iv8eipbxcqAu3HIEEn0Kx, issuer: https://pivot.pondersource.com/
2024-11-21T13:59:11.815Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/profile/card.acl
2024-11-21T13:59:11.817Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/.acl
2024-11-21T13:59:11.857Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/profile/card.acl
2024-11-21T13:59:11.939Z [HandlerServerConfigurator] {Primary} info: Received GET request for /README
2024-11-21T13:59:11.947Z [DPoPWebIdExtractor] {Primary} warn: Error verifying WebID via DPoP-bound access token: The DPoP proof htu parameter must be the HTTP request URI without query and fragment parts.
Actual: https://michielbdejong.pivot.pondersource.com/README
Expected: https://michielbdejong.pivot.pondersource.com/README/
2024-11-21T13:59:11.952Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/README.acl
2024-11-21T13:59:11.981Z [HandlerServerConfigurator] {Primary} info: Received GET request for /README/
2024-11-21T13:59:12.014Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: https://michielbdejong.pivot.pondersource.com/profile/card#me, client ID: iv8eipbxcqAu3HIEEn0Kx, issuer: https://pivot.pondersource.com/
2024-11-21T13:59:12.030Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/.acl
2024-11-21T13:59:12.077Z [HandlerServerConfigurator] {Primary} info: Received GET request for /
2024-11-21T13:59:12.084Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: https://michielbdejong.pivot.pondersource.com/profile/card#me, client ID: iv8eipbxcqAu3HIEEn0Kx, issuer: https://pivot.pondersource.com/
2024-11-21T13:59:12.088Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/.acl
2024-11-21T13:59:12.117Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/.acl
2024-11-21T13:59:12.156Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings/prefs.ttl
2024-11-21T13:59:12.161Z [HandlerServerConfigurator] {Primary} info: Received GET request for /README.meta
2024-11-21T13:59:12.166Z [HandlerServerConfigurator] {Primary} info: Received GET request for /README/
2024-11-21T13:59:12.175Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: https://michielbdejong.pivot.pondersource.com/profile/card#me, client ID: iv8eipbxcqAu3HIEEn0Kx, issuer: https://pivot.pondersource.com/
2024-11-21T13:59:12.185Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: https://michielbdejong.pivot.pondersource.com/profile/card#me, client ID: iv8eipbxcqAu3HIEEn0Kx, issuer: https://pivot.pondersource.com/
2024-11-21T13:59:12.188Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: https://michielbdejong.pivot.pondersource.com/profile/card#me, client ID: iv8eipbxcqAu3HIEEn0Kx, issuer: https://pivot.pondersource.com/
2024-11-21T13:59:12.200Z [PermissionBasedAuthorizer] {Primary} warn: Agent {"agent":{"webId":"https://michielbdejong.pivot.pondersource.com/profile/card#me"},"issuer":{"url":"https://pivot.pondersource.com/"},"client":{"clientId":"iv8eipbxcqAu3HIEEn0Kx"}} has no read permissions
2024-11-21T13:59:12.222Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/settings/.acl
2024-11-21T13:59:12.223Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/.acl
2024-11-21T13:59:12.260Z [HandlerServerConfigurator] {Primary} info: Received GET request for /README
2024-11-21T13:59:12.280Z [DPoPWebIdExtractor] {Primary} warn: Error verifying WebID via DPoP-bound access token: The DPoP proof htu parameter must be the HTTP request URI without query and fragment parts.
Actual: https://michielbdejong.pivot.pondersource.com/README
Expected: https://michielbdejong.pivot.pondersource.com/README/
2024-11-21T13:59:12.298Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/settings/.acl
2024-11-21T13:59:12.405Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings/publicTypeIndex.ttl
2024-11-21T13:59:12.410Z [HandlerServerConfigurator] {Primary} info: Received GET request for /settings/privateTypeIndex.ttl
2024-11-21T13:59:12.420Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: https://michielbdejong.pivot.pondersource.com/profile/card#me, client ID: iv8eipbxcqAu3HIEEn0Kx, issuer: https://pivot.pondersource.com/
2024-11-21T13:59:12.422Z [DPoPWebIdExtractor] {Primary} info: Verified WebID via DPoP-bound access token. WebID: https://michielbdejong.pivot.pondersource.com/profile/card#me, client ID: iv8eipbxcqAu3HIEEn0Kx, issuer: https://pivot.pondersource.com/
2024-11-21T13:59:12.428Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/settings/publicTypeIndex.ttl.acl
2024-11-21T13:59:12.431Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/settings/.acl
2024-11-21T13:59:12.496Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/settings/publicTypeIndex.ttl.acl
2024-11-21T13:59:12.510Z [WebAclReader] {Primary} info: Found applicable ACL document https://michielbdejong.pivot.pondersource.com/settings/.acl
Process is halting due to an uncaughtException with error Cannot read properties of undefined (reading 'updateTimeout')
/root/pivot/node_modules/proper-lockfile/lib/lockfile.js:104
    if (lock.updateTimeout) {
             ^

TypeError: Cannot read properties of undefined (reading 'updateTimeout')
    at updateLock (/root/pivot/node_modules/proper-lockfile/lib/lockfile.js:104:14)
    at /root/pivot/node_modules/proper-lockfile/lib/lockfile.js:167:17
    at FSReqCallback.oncomplete (node:fs:187:23)

Node.js v20.18.0

@michielbdejong michielbdejong mentioned this issue Nov 21, 2024
Merged
@michielbdejong
Copy link
Collaborator Author

The server should of course never crash, but it seems related to this:

The DPoP proof htu parameter must be the HTTP request URI without query and fragment parts.
Actual: https://michielbdejong.pivot.pondersource.com/README
Expected: https://michielbdejong.pivot.pondersource.com/README/

And maybe the locking mechanism gets confused due to the with/without trailing slash confusion. It's probably better to find a different point in the architecture to address #4, and then fix it once and for all for both publish and non-public resources, and without confusing the DPoP checker and the locking mechanism.

@michielbdejong michielbdejong mentioned this issue Nov 21, 2024
Closed
@michielbdejong
Copy link
Collaborator Author

michielbdejong commented Feb 12, 2025 •
edited
Loading

Reportedly this still happens and is related to PATCH. Investigating.

@michielbdejong
Copy link
Collaborator Author

I updated https://asdf.pivot.pondersource.com/public/.acl to:

@prefix acl: <http://www.w3.org/ns/auth/acl#>.
@prefix foaf: <http://xmlns.com/foaf/0.1/>.

<#open>
    a acl:Authorization;
    acl:agentClass foaf:Agent;
    acl:default <./>;
    acl:mode acl:Read, acl:Write.

And I'm running this command on my test server:

npx community-solid-server -c ./config/prod.json ./config/customise-me.json -f ./data --httpsKey /etc/letsencrypt/live/pivot.pondersource.com/privkey.pem --httpsCert /etc/letsencrypt/live/pivot.pondersource.com/fullchain.pem -p 443 -b https://pivot.pondersource.com -m .

Then from my laptop I run:

curl -i -X PUT -d'<a> <b> ( <c> <d> ).' -H 'Content-Type: text/turtle' https://asdf.pivot.pondersource.com/public/test.ttl
curl https://asdf.pivot.pondersource.com/public/test.ttl
curl -i -X PATCH [email protected] -H'Content-Type: text/n3' https://asdf.pivot.pondersource.com/public/test.ttl
curl https://asdf.pivot.pondersource.com/public/test.ttl

I wait a bit longer.
The server does not crash.
These are the server logs:

2025-02-12T12:57:23.948Z [HandlerServerConfigurator] {Primary} info: Received PUT request for /public/test.ttl
2025-02-12T12:57:23.962Z [WebAclReader] {Primary} info: Found applicable ACL document https://asdf.pivot.pondersource.com/public/.acl
2025-02-12T12:57:26.357Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public/test.ttl
2025-02-12T12:57:26.368Z [WebAclReader] {Primary} info: Found applicable ACL document https://asdf.pivot.pondersource.com/public/.acl
2025-02-12T12:57:30.555Z [HandlerServerConfigurator] {Primary} info: Received PATCH request for /public/test.ttl
2025-02-12T12:57:30.572Z [WebAclReader] {Primary} info: Found applicable ACL document https://asdf.pivot.pondersource.com/public/.acl
2025-02-12T12:57:32.727Z [HandlerServerConfigurator] {Primary} info: Received GET request for /public/test.ttl
2025-02-12T12:57:32.741Z [WebAclReader] {Primary} info: Found applicable ACL document https://asdf.pivot.pondersource.com/public/.acl

@michielbdejong michielbdejong mentioned this issue Feb 12, 2025
Closed
@michielbdejong
Copy link
Collaborator Author

I also tested:

curl -i -X PATCH [email protected] -H'Content-Type: text/n3' https://asdf.pivot.pondersource.com/public/test.ttl

and got a 400 error 'Invalid N3' back as expected, but no locking issue or server crash. I also tried curl https://asdf.pivot.pondersource.com/public// but my server didn't crash.

I need more information to reproduce this problem. I'll have a look at the solidcommunity.net:8443 logs

@michielbdejong
Copy link
Collaborator Author

Testing this again now, with timeouts reduced from 60 minutes to 1 minutes, using CommunitySolidServer/Recipes#49 (comment)

@michielbdejong michielbdejong mentioned this issue Feb 12, 2025
Closed
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
1 participant
@michielbdejong