starred/audiobookshelf
1
0
Fork 0
mirror of https://github.com/advplyr/audiobookshelf.git synced 2026-05-30 23:40:40 +02:00
Code Issues 1.0k Packages Projects Releases 10 Wiki Activity

[Bug]: New version and old issue is back... #536

New Issue
Closed
opened 2026-04-24 23:12:16 +02:00 by adam · 14 comments
adam commented 2026-04-24 23:12:16 +02:00
Owner
Copy Link
Copy Source

Originally created by @plague-doctor on GitHub (Jul 19, 2022).

Describe the issue

It was so nice - no issues until an upgrade to 2.1.0:

Config /config /metadata
[2022-07-19 13:30:46]  INFO: === Starting Server ===
[2022-07-19 13:30:46]  INFO: [Server] Init v2.1.0
[2022-07-19 13:30:46]  INFO: [DB] 0 Collections Loaded
[2022-07-19 13:30:46]  INFO: [DB] 6 Users Loaded
[2022-07-19 13:30:46]  INFO: [DB] 2 Libraries Loaded
[2022-07-19 13:30:46]  INFO: [DB] 271 Authors Loaded
[2022-07-19 13:30:46]  INFO: [DB] 164 Series Loaded
[2022-07-19 13:30:47]  INFO: [DB] 1025 Library Items Loaded
[2022-07-19 13:30:57] ERROR: [DB] Update entity settings Failed: Error: Lock file is already being held
[2022-07-19 13:31:07] ERROR: [DB] Update entity settings Failed: Error: Lock file is already being held
[2022-07-19 13:31:07]  WARN: [Auth] User user1 api token has been updated using new token secret
[2022-07-19 13:31:07]  WARN: [Auth] User user2 api token has been updated using new token secret
[2022-07-19 13:31:07]  WARN: [Auth] User user3 api token has been updated using new token secret
[2022-07-19 13:31:16] ERROR: [DB] Update user Failed: Error: Lock file is already being held
[2022-07-19 13:31:25] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held
[2022-07-19 13:31:25]  INFO: [BackupManager] 2 Backups Found
[2022-07-19 13:31:25]  INFO: [LogManager] Init current daily log filename: 2022-07-19.txt
[2022-07-19 13:31:25]  INFO: [Watcher] Initializing watcher for "Polskie".
[2022-07-19 13:31:25]  INFO: [Watcher] Initializing watcher for "English".
[2022-07-19 13:31:25]  INFO: Listening on http://0.0.0.0:80
[2022-07-19 13:31:25]  INFO: [Watcher] "English" Ready
[2022-07-19 13:31:28]  INFO: [Watcher] "Polskie" Ready
[2022-07-19 13:31:45]  INFO: Recieved ping
[2022-07-19 13:32:07]  INFO: [Server] Socket Connected Kf08....AAB
[2022-07-19 13:32:07] ERROR: JWT Verify Token Failed JsonWebTokenError: invalid signature
    at /server/libs/jsonwebtoken/verify.js:133:19
    at getSecret (/server/libs/jsonwebtoken/verify.js:90:14)
    at Object.module.exports [as verify] (/server/libs/jsonwebtoken/verify.js:94:10)
    at /server/Auth.js:106:11
    at new Promise (<anonymous>)
    at Auth.verifyToken (/server/Auth.js:105:12)
    at Auth.authenticateUser (/server/Auth.js:101:17)
    at Server.authenticateSocket (/server/Server.js:422:32)
    at Socket.<anonymous> (/server/Server.js:279:41)
    at Socket.emit (node:events:527:28)
[2022-07-19 13:32:07] ERROR: Cannot validate socket - invalid token
[2022-07-19 13:32:15]  INFO: Recieved ping
[2022-07-19 13:32:45]  INFO: Recieved ping
[2022-07-19 13:32:55]  INFO: [Server] Unauth socket Kf08XnGgBToeIBITAAAB disconnected (Reason: transport close)
[2022-07-19 13:32:55] ERROR: JWT Verify Token Failed JsonWebTokenError: invalid signature
    at /server/libs/jsonwebtoken/verify.js:133:19
    at getSecret (/server/libs/jsonwebtoken/verify.js:90:14)
    at Object.module.exports [as verify] (/server/libs/jsonwebtoken/verify.js:94:10)
    at /server/Auth.js:106:11
    at new Promise (<anonymous>)
    at Auth.verifyToken (/server/Auth.js:105:12)
    at Auth.authMiddleware (/server/Auth.js:70:27)
    at Server.authMiddleware (/server/Server.js:120:15)
    at Layer.handle [as handle_request] (/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/node_modules/express/lib/router/index.js:328:13)
[2022-07-19 13:32:55] ERROR: Verify Token User Not Found eyJhbGciOiJIUzI1NiIsInR5cCI6...L_4tGFpsqMrmOGDOapUI1iiJ8
[2022-07-19 13:33:00]  INFO: [Server] Socket Connected l2ZWkHs-Hk6rs6WaAAAD
[2022-07-19 13:33:09] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held
[2022-07-19 13:33:16]  INFO: Recieved ping

and the old issue is back...

[2022-07-19 13:36:54] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held
[2022-07-19 13:36:55] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held
[2022-07-19 13:36:59] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held
[2022-07-19 13:37:00] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held
[2022-07-19 13:37:04] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held
[2022-07-19 13:37:05] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held
[2022-07-19 13:37:09] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held
[2022-07-19 13:37:10] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held
[2022-07-19 13:37:13] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held
[2022-07-19 13:37:14] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held
[2022-07-19 13:37:18]  INFO: Recieved ping

Steps to reproduce the issue

  1. start the container

Audiobookshelf version

2.1.0

How are you running audiobookshelf?

Docker

Originally created by @plague-doctor on GitHub (Jul 19, 2022). ### Describe the issue It was so nice - no issues until an upgrade to 2.1.0: ``` Config /config /metadata [2022-07-19 13:30:46] INFO: === Starting Server === [2022-07-19 13:30:46] INFO: [Server] Init v2.1.0 [2022-07-19 13:30:46] INFO: [DB] 0 Collections Loaded [2022-07-19 13:30:46] INFO: [DB] 6 Users Loaded [2022-07-19 13:30:46] INFO: [DB] 2 Libraries Loaded [2022-07-19 13:30:46] INFO: [DB] 271 Authors Loaded [2022-07-19 13:30:46] INFO: [DB] 164 Series Loaded [2022-07-19 13:30:47] INFO: [DB] 1025 Library Items Loaded [2022-07-19 13:30:57] ERROR: [DB] Update entity settings Failed: Error: Lock file is already being held [2022-07-19 13:31:07] ERROR: [DB] Update entity settings Failed: Error: Lock file is already being held [2022-07-19 13:31:07] WARN: [Auth] User user1 api token has been updated using new token secret [2022-07-19 13:31:07] WARN: [Auth] User user2 api token has been updated using new token secret [2022-07-19 13:31:07] WARN: [Auth] User user3 api token has been updated using new token secret [2022-07-19 13:31:16] ERROR: [DB] Update user Failed: Error: Lock file is already being held [2022-07-19 13:31:25] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held [2022-07-19 13:31:25] INFO: [BackupManager] 2 Backups Found [2022-07-19 13:31:25] INFO: [LogManager] Init current daily log filename: 2022-07-19.txt [2022-07-19 13:31:25] INFO: [Watcher] Initializing watcher for "Polskie". [2022-07-19 13:31:25] INFO: [Watcher] Initializing watcher for "English". [2022-07-19 13:31:25] INFO: Listening on http://0.0.0.0:80 [2022-07-19 13:31:25] INFO: [Watcher] "English" Ready [2022-07-19 13:31:28] INFO: [Watcher] "Polskie" Ready [2022-07-19 13:31:45] INFO: Recieved ping [2022-07-19 13:32:07] INFO: [Server] Socket Connected Kf08....AAB [2022-07-19 13:32:07] ERROR: JWT Verify Token Failed JsonWebTokenError: invalid signature at /server/libs/jsonwebtoken/verify.js:133:19 at getSecret (/server/libs/jsonwebtoken/verify.js:90:14) at Object.module.exports [as verify] (/server/libs/jsonwebtoken/verify.js:94:10) at /server/Auth.js:106:11 at new Promise (<anonymous>) at Auth.verifyToken (/server/Auth.js:105:12) at Auth.authenticateUser (/server/Auth.js:101:17) at Server.authenticateSocket (/server/Server.js:422:32) at Socket.<anonymous> (/server/Server.js:279:41) at Socket.emit (node:events:527:28) [2022-07-19 13:32:07] ERROR: Cannot validate socket - invalid token [2022-07-19 13:32:15] INFO: Recieved ping [2022-07-19 13:32:45] INFO: Recieved ping [2022-07-19 13:32:55] INFO: [Server] Unauth socket Kf08XnGgBToeIBITAAAB disconnected (Reason: transport close) [2022-07-19 13:32:55] ERROR: JWT Verify Token Failed JsonWebTokenError: invalid signature at /server/libs/jsonwebtoken/verify.js:133:19 at getSecret (/server/libs/jsonwebtoken/verify.js:90:14) at Object.module.exports [as verify] (/server/libs/jsonwebtoken/verify.js:94:10) at /server/Auth.js:106:11 at new Promise (<anonymous>) at Auth.verifyToken (/server/Auth.js:105:12) at Auth.authMiddleware (/server/Auth.js:70:27) at Server.authMiddleware (/server/Server.js:120:15) at Layer.handle [as handle_request] (/node_modules/express/lib/router/layer.js:95:5) at trim_prefix (/node_modules/express/lib/router/index.js:328:13) [2022-07-19 13:32:55] ERROR: Verify Token User Not Found eyJhbGciOiJIUzI1NiIsInR5cCI6...L_4tGFpsqMrmOGDOapUI1iiJ8 [2022-07-19 13:33:00] INFO: [Server] Socket Connected l2ZWkHs-Hk6rs6WaAAAD [2022-07-19 13:33:09] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held [2022-07-19 13:33:16] INFO: Recieved ping ``` and the old issue is back... ``` [2022-07-19 13:36:54] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held [2022-07-19 13:36:55] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held [2022-07-19 13:36:59] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held [2022-07-19 13:37:00] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held [2022-07-19 13:37:04] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held [2022-07-19 13:37:05] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held [2022-07-19 13:37:09] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held [2022-07-19 13:37:10] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held [2022-07-19 13:37:13] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held [2022-07-19 13:37:14] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held [2022-07-19 13:37:18] INFO: Recieved ping ``` ### Steps to reproduce the issue 1. start the container ### Audiobookshelf version 2.1.0 ### How are you running audiobookshelf? Docker
adam added the bug label 2026-04-24 23:12:16 +02:00
adam closed this issue 2026-04-24 23:12:16 +02:00
adam commented 2026-04-24 23:12:17 +02:00
Author
Owner
Copy Link
Copy Source

@plague-doctor commented on GitHub (Jul 19, 2022):

This time changing the volume does not help... #653

@plague-doctor commented on GitHub (Jul 19, 2022): This time changing the volume does not help... #653
adam commented 2026-04-24 23:12:17 +02:00
Author
Owner
Copy Link
Copy Source

@plague-doctor commented on GitHub (Jul 19, 2022):

ok. I've got more to this, so maybe this time we will definitely nail it.
I've got the

[2022-07-19 13:37:09] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held
[2022-07-19 13:37:10] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held

issue only when using NFS share for /config and /metadata. Looks like the locking does not work properly on nfs share.
Can you please, double check the locking mechanism you use, and if it is compatible with nfs? Or maybe the nfs share needs to be mounted in a particular way?

@plague-doctor commented on GitHub (Jul 19, 2022): ok. I've got more to this, so maybe this time we will definitely nail it. I've got the ``` [2022-07-19 13:37:09] ERROR: [DB] Update entity session Failed: Error: Lock file is already being held [2022-07-19 13:37:10] ERROR: [DB] Update entity user Failed: Error: Lock file is already being held ``` issue only when using NFS share for `/config` and `/metadata`. Looks like the locking does not work properly on nfs share. Can you please, double check the locking mechanism you use, and if it is compatible with nfs? Or maybe the nfs share needs to be mounted in a particular way?
adam commented 2026-04-24 23:12:17 +02:00
Author
Owner
Copy Link
Copy Source

@advplyr commented on GitHub (Jul 19, 2022):

You need to make sure that abs has full read and write permission to those folders. I don't recommend using an NFS share for the /config folder.

@advplyr commented on GitHub (Jul 19, 2022): You need to make sure that abs has full read and write permission to those folders. I don't recommend using an NFS share for the `/config` folder.
adam commented 2026-04-24 23:12:18 +02:00
Author
Owner
Copy Link
Copy Source

@plague-doctor commented on GitHub (Jul 19, 2022):

It does have full read and write permission. Why don't you recommend using NFS?
What lib do you use for locking?

@plague-doctor commented on GitHub (Jul 19, 2022): It does have full read and write permission. Why don't you recommend using NFS? What lib do you use for locking?
adam commented 2026-04-24 23:12:18 +02:00
Author
Owner
Copy Link
Copy Source

@advplyr commented on GitHub (Jul 19, 2022):

NFS share will be slower and this is the database. I've seen many different issues with NFS shares that are incorrectly attributed to abs so generally when an NFS share is involved I don't want to spend much time digging into it.
Abs uses https://github.com/moxystudio/node-proper-lockfile

@advplyr commented on GitHub (Jul 19, 2022): NFS share will be slower and this is the database. I've seen many different issues with NFS shares that are incorrectly attributed to abs so generally when an NFS share is involved I don't want to spend much time digging into it. Abs uses https://github.com/moxystudio/node-proper-lockfile
adam commented 2026-04-24 23:12:19 +02:00
Author
Owner
Copy Link
Copy Source

@justinwoodland commented on GitHub (Jul 19, 2022):

I'm also experiencing this issue with the update to 2.1.0. I am also using an NFS share for /config/ and /metadata/ because I'm using kubernetes. I'm happy to help provide more information if needed.

@justinwoodland commented on GitHub (Jul 19, 2022): I'm also experiencing this issue with the update to 2.1.0. I am also using an NFS share for `/config/` and `/metadata/` because I'm using kubernetes. I'm happy to help provide more information if needed.
adam commented 2026-04-24 23:12:19 +02:00
Author
Owner
Copy Link
Copy Source

@justinwoodland commented on GitHub (Jul 20, 2022):

I also tried rolling back to 2.0.24, but that didn't help.

@justinwoodland commented on GitHub (Jul 20, 2022): I also tried rolling back to 2.0.24, but that didn't help.
adam commented 2026-04-24 23:12:20 +02:00
Author
Owner
Copy Link
Copy Source

@plague-doctor commented on GitHub (Jul 20, 2022):

@justinwoodland we are just kissed with the old (very old) NFS issue. You can read more about here O_EXCL over nfs.

tl;dr;

On NFS, O_EXCL is only supported when using NFSv3 or later on kernel 2.6 or later. In NFS environments where O_EXCL support is not provided, programs that rely on it for performing locking tasks will contain a race condition.

I will test this later today on NFSv3. However I wouldn't hold my breath it will bring much difference.

@plague-doctor commented on GitHub (Jul 20, 2022): @justinwoodland we are just kissed with the old (very old) NFS issue. You can read more about here [O_EXCL over nfs](https://duckduckgo.com/?q=O_EXCL+over+nfs+&va=j&ia=web). tl;dr; > On NFS, O_EXCL is only supported when using NFSv3 or later on kernel 2.6 or later. In NFS environments where O_EXCL support is not provided, programs that rely on it for performing locking tasks will contain a race condition. I will test this later today on NFSv3. However I wouldn't hold my breath it will bring much difference.
adam commented 2026-04-24 23:12:20 +02:00
Author
Owner
Copy Link
Copy Source

@advplyr commented on GitHub (Jul 20, 2022):

Proper lockfile is not using O_EXCL

https://github.com/moxystudio/node-proper-lockfile#comparison

This library is similar to lockfile but the latter has some drawbacks:

It relies on open with O_EXCL flag which has problems in network file systems. proper-lockfile uses mkdir which doesn't have this issue.

@advplyr commented on GitHub (Jul 20, 2022): Proper lockfile is not using O_EXCL https://github.com/moxystudio/node-proper-lockfile#comparison > This library is similar to [lockfile](https://github.com/isaacs/lockfile) but the latter has some drawbacks: > > It relies on open with O_EXCL flag which has problems in network file systems. proper-lockfile uses mkdir which doesn't have this issue.
adam commented 2026-04-24 23:12:21 +02:00
Author
Owner
Copy Link
Copy Source

@plague-doctor commented on GitHub (Jul 20, 2022):

They still use some kind of voodoo which require obtaining exclusive locking, and this is not easy using network sharing.
By the way @justinwoodland, as I expected - NFSv3 doesn't help.

However I do have an idea on how to address this once for all. If you @advplyr, could move the locks away from the directories which need to be persistent (/config and /metadata) to somewhere else like /tmp or /var this will fix this issue forever. No more problems for swarm, Kubernetes and others.

@plague-doctor commented on GitHub (Jul 20, 2022): They still use some kind of voodoo which require obtaining exclusive locking, and this is not easy using network sharing. By the way @justinwoodland, as I expected - NFSv3 doesn't help. However I do have an idea on how to address this once for all. If you @advplyr, could move the locks away from the directories which need to be persistent (`/config` and `/metadata`) to somewhere else like `/tmp` or `/var` this will fix this issue forever. No more problems for swarm, Kubernetes and others.
adam commented 2026-04-24 23:12:21 +02:00
Author
Owner
Copy Link
Copy Source

@MidnightSnowleopard commented on GitHub (Jul 20, 2022):

For what it's worth, I run this off of NFSv4 on kubernetes without any real issues

@MidnightSnowleopard commented on GitHub (Jul 20, 2022): For what it's worth, I run this off of NFSv4 on kubernetes without any real issues
adam commented 2026-04-24 23:12:22 +02:00
Author
Owner
Copy Link
Copy Source

@advplyr commented on GitHub (Jul 20, 2022):

I imagine there are thousands of users using this over NFS without a problem because this is the first time this was brought up.
I think the lockfiles should stay with the database. Abs also runs as a debian package and will eventually run as a windows exe.

I don't think this database system will be staying around forever. If the issue with sqlite binaries gets figured out then that will likely replace the json database.

@advplyr commented on GitHub (Jul 20, 2022): I imagine there are thousands of users using this over NFS without a problem because this is the first time this was brought up. I think the lockfiles should stay with the database. Abs also runs as a debian package and will eventually run as a windows exe. I don't think this database system will be staying around forever. If the issue with sqlite binaries gets figured out then that will likely replace the json database.
adam commented 2026-04-24 23:12:23 +02:00
Author
Owner
Copy Link
Copy Source

@plague-doctor commented on GitHub (Jul 20, 2022):

I wanted to suggest using sqlite too. This will be even better take.
I guess this pesky NFS bug is more likely to bite users who use multiple nodes (swarm, kubernetes, etc) when the abs service jumps between the nodes.
When abs service settles on a single node the problem seams to disappear. I was working fine on my configuration for weeks...

@plague-doctor commented on GitHub (Jul 20, 2022): I wanted to suggest using sqlite too. This will be even better take. I guess this pesky NFS bug is more likely to bite users who use multiple nodes (swarm, kubernetes, etc) when the abs service jumps between the nodes. When abs service settles on a single node the problem seams to disappear. I was working fine on my configuration for weeks...
adam commented 2026-04-24 23:12:23 +02:00
Author
Owner
Copy Link
Copy Source

@jt196 commented on GitHub (Jul 20, 2022):

Something similar, without the lockfile. I managed to resolve it by removing the profile on the app and re-adding the config.

[2022-07-20 09:59:10]  INFO: Recieved ping
[2022-07-20 09:59:26] ERROR: Verify Token User Not Found 
    [token]
    at Layer.handle [as handle_request] (/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/node_modules/express/lib/router/index.js:328:13)
    at Server.authMiddleware (/server/Server.js:120:15)
    at Auth.authMiddleware (/server/Auth.js:70:27)
    at Auth.verifyToken (/server/Auth.js:105:12)
    at new Promise (<anonymous>)
    at /server/Auth.js:106:11
    at getSecret (/server/libs/jsonwebtoken/verify.js:90:14)
    at Object.module.exports [as verify] (/server/libs/jsonwebtoken/verify.js:94:10)
    at /server/libs/jsonwebtoken/verify.js:133:19
[2022-07-20 09:59:26] ERROR: JWT Verify Token Failed JsonWebTokenError: invalid signature
@jt196 commented on GitHub (Jul 20, 2022): Something similar, without the lockfile. I managed to resolve it by removing the profile on the app and re-adding the config. ``` [2022-07-20 09:59:10] INFO: Recieved ping [2022-07-20 09:59:26] ERROR: Verify Token User Not Found [token] at Layer.handle [as handle_request] (/node_modules/express/lib/router/layer.js:95:5) at trim_prefix (/node_modules/express/lib/router/index.js:328:13) at Server.authMiddleware (/server/Server.js:120:15) at Auth.authMiddleware (/server/Auth.js:70:27) at Auth.verifyToken (/server/Auth.js:105:12) at new Promise (<anonymous>) at /server/Auth.js:106:11 at getSecret (/server/libs/jsonwebtoken/verify.js:90:14) at Object.module.exports [as verify] (/server/libs/jsonwebtoken/verify.js:94:10) at /server/libs/jsonwebtoken/verify.js:133:19 [2022-07-20 09:59:26] ERROR: JWT Verify Token Failed JsonWebTokenError: invalid signature ```
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
authentication
backlog
bug
chapter editor
config-issue
ebooks
encoding/embedding
enhancement
help wanted
listening sessions & progress
planned
possible plugin
progress sync
pull-request
Mirrored from GitHub Pull Request
 sorting/filtering/searching
unable to reproduce
upload
users & permissions
waiting
No Label bug
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
adam (Adam Melkus)
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: starred/audiobookshelf#536
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?