502 Bad Gateway on most requests

[djl]

gonic version: nightly
docker tag: nightly

(Although I'm running on nightly at the moment this also happens on the most recent release)

As of about a week ago, I've started seeing 502 errors on almost all requests to my gonic instance.

Here's the logs just from GETting /home while logged in:

2025/10/24 14:20:01 response  200  GET /home
2025/10/24 14:20:12 error writing to response buffer: write tcp 172.17.0.9:4747->172.17.0.1:47186: i/o timeout
2025/10/24 14:20:12 response  200  GET /home
2025/10/24 14:20:20 error writing to response buffer: write tcp 172.17.0.9:4747->172.17.0.1:43696: i/o timeout
2025/10/24 14:20:20 response  200  GET /home

Even the subsonic API has similar issues:

2025/10/24 14:21:41 response  200  GET /getAvatar?u=guest&s=REDACTED&v=1.2.0&c=DSub&username=guest
2025/10/24 14:21:41 response  200  GET /getUser?u=guest&s=REDACTED&t=REDACTED&v=1.2.0&c=DSub&username=guest
2025/10/24 14:21:41 response  200  GET /getBookmarks?u=guest&s=REDACTED&t=REDACTED&v=1.2.0&c=DSub
2025/10/24 14:21:59 error writing subsonic response: write tcp 172.17.0.9:4747->172.17.0.1:55588: i/o timeout
2025/10/24 14:21:59 response  200  GET /getAlbumList2?u=guest&s=REDACTED&t=REDACTED&v=1.2.0&c=DSub&type=newest&size=20&offset=0
2025/10/24 14:22:00 response  200  GET /getCoverArt?u=guest&s=REDACTED&t=REDACTED&v=1.2.0&c=DSub&id=al-45762
2025/10/24 14:22:00 response  200  GET /getCoverArt?u=guest&s=REDACTED&t=REDACTED&v=1.2.0&c=DSub&id=al-46161

My only guess at the issue is that I'm hitting some sort of limit due to the size of my library (290517 tracks, ~29815 albums according to beet stats).

[sentriz]

hi @djl looks like we have some slow queries, can you please pull the latest :nightly and enable the log-db setting? then load some pages and it should log what the slow queries are

[djl]

Here's the output from a request to /home

gorm sql/src/podcast/podcast.go:4792.359605msSELECT * FROM "podcast_episodes"  WHERE (status=?) ORDER BY updated_at DESC[downloading] 0
gorm sql/go/pkg/mod/github.com/sentriz/gormstore@v0.0.0-20220105134332-64e31f7f6981/gormstore.go:1291.609375msSELECT * FROM "sessions"  WHERE (id = ? AND expires_at > ?) ORDER BY "sessions"."id" ASC LIMIT 1[SNIP SNIP] 1
gorm sql/src/db/db.go:1031.425327msSELECT * FROM "users"  WHERE (id=?) ORDER BY "users"."id" ASC LIMIT 1[1] 1
gorm sql/src/db/db.go:89375.619µsSELECT count(*) FROM "albums"  [] 0
gorm sql/src/db/db.go:901.033442msSELECT count(*) FROM ( SELECT count(*) as name  FROM "album_artists"   GROUP BY album_id ) AS count_table[] 0
gorm sql/src/db/db.go:911.080507msSELECT count(*) FROM ( SELECT count(*) as name  FROM "track_artists"   GROUP BY artist_id ) AS count_table[] 0
gorm sql/src/podcast/podcast.go:479529.553679msSELECT * FROM "podcast_episodes"  WHERE (status=?) ORDER BY updated_at DESC[downloading] 0
gorm sql/src/db/db.go:923.265451msSELECT count(*) FROM ( SELECT count(*) as name  FROM "album_artists"   GROUP BY artist_id ) AS count_table[] 0
gorm sql/src/db/db.go:93446.991µsSELECT count(*) FROM "tracks"  [] 0
gorm sql/src/db/db.go:94401.321µsSELECT count(*) FROM "internet_radio_stations"  [] 0
gorm sql/src/db/db.go:95331.342µsSELECT count(*) FROM "podcasts"  [] 0
gorm sql/src/db/db.go:160974.829µsSELECT * FROM "settings"  WHERE (key=?) ORDER BY "settings"."key" ASC LIMIT 1[lastfm_api_key] 0
gorm sql/src/server/ctrladmin/handlers.go:501.218879msSELECT * FROM "users"  [] 2
gorm sql/src/server/ctrladmin/handlers.go:562.879930671sSELECT * FROM "albums"   ORDER BY created_at DESC LIMIT 10[] 10
gorm sql/src/db/db.go:1601.530669msSELECT * FROM "settings"  WHERE (key=?) ORDER BY "settings"."key" ASC LIMIT 1[last_scan_time] 1
gorm sql/src/server/ctrladmin/handlers.go:671.14396msSELECT * FROM "transcode_preferences"  WHERE (user_id=?)[1] 0
gorm sql/src/server/ctrladmin/handlers.go:731.278219msSELECT * FROM "podcasts"  [] 0
gorm sql/src/server/ctrladmin/handlers.go:761.100552msSELECT * FROM "internet_radio_stations"  [] 0
gorm sql/go/pkg/mod/github.com/sentriz/gormstore@v0.0.0-20220105134332-64e31f7f6981/gormstore.go:1771.949776msINSERT INTO "sessions" ("id","data","created_at","updated_at","expires_at") VALUES (?,?,?,?,?)[SNIP] 1
gorm sql/go/pkg/mod/github.com/sentriz/gormstore@v0.0.0-20220105134332-64e31f7f6981/gormstore.go:1851.364749msUPDATE "sessions" SET "data" = ?, "created_at" = ?, "updated_at" = ?, "expires_at" = ?  WHERE "sessions"."id" = ?[SNIP] 1
2025/10/24 17:58:44 error writing to response buffer: write tcp 172.17.0.9:4747->172.17.0.1:56198: i/o timeout
2025/10/24 17:58:44 response  200  GET /home
gorm sql/go/pkg/mod/github.com/sentriz/gormstore@v0.0.0-20220105134332-64e31f7f6981/gormstore.go:1292.785177msSELECT * FROM "sessions"  WHERE (id = ? AND expires_at > ?) ORDER BY "sessions"."id" ASC LIMIT 1[SNIP] 1
gorm sql/src/db/db.go:1032.574099msSELECT * FROM "users"  WHERE (id=?) ORDER BY "users"."id" ASC LIMIT 1[1] 1
gorm sql/src/db/db.go:89594.532µsSELECT count(*) FROM "albums"  [] 0
gorm sql/src/db/db.go:901.110561msSELECT count(*) FROM ( SELECT count(*) as name  FROM "album_artists"   GROUP BY album_id ) AS count_table[] 0
gorm sql/src/podcast/podcast.go:47968.17317msSELECT * FROM "podcast_episodes"  WHERE (status=?) ORDER BY updated_at DESC[downloading] 0
gorm sql/src/db/db.go:913.376755msSELECT count(*) FROM ( SELECT count(*) as name  FROM "track_artists"   GROUP BY artist_id ) AS count_table[] 0
gorm sql/src/db/db.go:921.173593msSELECT count(*) FROM ( SELECT count(*) as name  FROM "album_artists"   GROUP BY artist_id ) AS count_table[] 0
gorm sql/src/podcast/podcast.go:47914.165208msSELECT * FROM "podcast_episodes"  WHERE (status=?) ORDER BY updated_at DESC[downloading] 0
gorm sql/src/db/db.go:932.502432msSELECT count(*) FROM "tracks"  [] 0
gorm sql/src/db/db.go:94377.771µsSELECT count(*) FROM "internet_radio_stations"  [] 0
gorm sql/src/db/db.go:95332.619µsSELECT count(*) FROM "podcasts"  [] 0
gorm sql/src/db/db.go:160918.521µsSELECT * FROM "settings"  WHERE (key=?) ORDER BY "settings"."key" ASC LIMIT 1[lastfm_api_key] 0
gorm sql/src/server/ctrladmin/handlers.go:501.30116msSELECT * FROM "users"  [] 2
gorm sql/src/server/ctrladmin/handlers.go:562.84118132sSELECT * FROM "albums"   ORDER BY created_at DESC LIMIT 10[] 10
gorm sql/src/db/db.go:1601.186326msSELECT * FROM "settings"  WHERE (key=?) ORDER BY "settings"."key" ASC LIMIT 1[last_scan_time] 1
gorm sql/src/server/ctrladmin/handlers.go:67965.662µsSELECT * FROM "transcode_preferences"  WHERE (user_id=?)[1] 0
gorm sql/src/server/ctrladmin/handlers.go:731.102752msSELECT * FROM "podcasts"  [] 0
gorm sql/src/server/ctrladmin/handlers.go:76713.059µsSELECT * FROM "internet_radio_stations"  [] 0
gorm sql/go/pkg/mod/github.com/sentriz/gormstore@v0.0.0-20220105134332-64e31f7f6981/gormstore.go:1771.427798msINSERT INTO "sessions" ("id","data","created_at","updated_at","expires_at") VALUES (?,?,?,?,?)[SNIP] 1
gorm sql/go/pkg/mod/github.com/sentriz/gormstore@v0.0.0-20220105134332-64e31f7f6981/gormstore.go:1852.496901msUPDATE "sessions" SET "data" = ?, "created_at" = ?, "updated_at" = ?, "expires_at" = ?  WHERE "sessions"."id" = ?[SNIP] 1
2025/10/24 17:58:53 error writing to response buffer: write tcp 172.17.0.9:4747->172.17.0.1:48876: i/o timeout
2025/10/24 17:58:53 response  200  GET /home

And one from the subsonic API ("Recently added" in DSub)

gorm sql/src/db/db.go:1151.853255msSELECT * FROM "users"  WHERE (name=?) ORDER BY "users"."id" ASC LIMIT 1[guest] 1
gorm sql/src/server/ctrlsubsonic/handlers_by_tags.go:20515.980158005sSELECT albums.*, count(tracks.id) child_count, sum(tracks.length) duration FROM "albums" LEFT JOIN tracks ON tracks.album_id=albums.id JOIN album_artists ON album_artists.album_id=albums.id  GROUP BY albums.id ORDER BY created_at DESC LIMIT 20 OFFSET 0[] 20
gorm sql/src/podcast/podcast.go:47913.144556797sSELECT * FROM "podcast_episodes"  WHERE (status=?) ORDER BY updated_at DESC[downloading] 0
gorm sql/src/server/ctrlsubsonic/handlers_by_tags.go:2057.372908msSELECT * FROM "artists" INNER JOIN "album_artists" ON "album_artists"."artist_id" = "artists"."id" WHERE ("album_artists"."album_id" IN (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?))[89982 89962 89973 65378 89986 89988 89950 89969 65016 89991 89992 89989 89984 89978 89955 89974 66734 89976 89959 89987] 0
gorm sql/src/podcast/podcast.go:47910.163381msSELECT * FROM "podcast_episodes"  WHERE (status=?) ORDER BY updated_at DESC[downloading] 0
gorm sql/src/server/ctrlsubsonic/handlers_by_tags.go:2054.29769msSELECT * FROM "genres" INNER JOIN "album_genres" ON "album_genres"."genre_id" = "genres"."id" WHERE ("album_genres"."album_id" IN (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?))[89973 89989 89992 89982 66734 89976 65016 65378 89987 89959 89986 89978 89969 89988 89984 89991 89962 89950 89955 89974] 0
gorm sql/src/server/ctrlsubsonic/handlers_by_tags.go:2052.452666msSELECT * FROM "album_stars"  WHERE ("album_id" IN (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)) AND (user_id=?)[89988 89962 89950 89973 89969 89989 89986 89991 89982 89974 89959 65378 89987 89978 66734 65016 89984 89992 89955 89976 2] 0
gorm sql/src/server/ctrlsubsonic/handlers_by_tags.go:2052.581503msSELECT * FROM "album_ratings"  WHERE ("album_id" IN (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)) AND (user_id=?)[89974 65378 89987 89955 89969 65016 89959 89986 89992 89973 66734 89976 89988 89978 89950 89989 89984 89991 89982 89962 2] 0
gorm sql/src/server/ctrlsubsonic/handlers_by_tags.go:2052.185253msSELECT * FROM "plays"  WHERE ("album_id" IN (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)) AND (user_id=?)[89992 89959 89989 89986 89988 89984 89987 89978 89962 89955 89991 89982 89950 89974 89973 66734 89976 65016 89969 65378 2] 0
2025/10/24 18:00:28 error writing subsonic response: write tcp 172.17.0.9:4747->172.17.0.1:50178: i/o timeout
2025/10/24 18:00:28 response  200  GET /getAlbumList2?u=guest&s=SNIP&t=SNIP&v=1.2.0&c=DSub&type=newest&size=20&offset=0

[djl]

Finally had some time to start debugging this a little bit.

So this query from handlers_by_tags.go:

gorm sql/src/server/ctrlsubsonic/handlers_by_tags.go:20515.980158005sSELECT albums.*, count(tracks.id) child_count, sum(tracks.length) duration FROM "albums" LEFT JOIN tracks ON tracks.album_id=albums.id JOIN album_artists ON album_artists.album_id=albums.id  GROUP BY albums.id ORDER BY created_at DESC LIMIT 20 OFFSET 0[] 20

If I'm reading this right, it's taking almost 16 seconds. If I run the query manually it only takes a few milliseconds and still returns the correct data:

time sqlite3 gonic.db 'SELECT albums.*, count(tracks.id) child_count, sum(tracks.length) duration FROM "albums" LEFT JOIN tracks ON tracks.album_id=albums.id JOIN album_artists ON album_artists.album_id=albums.id  GROUP BY albums.id ORDER BY created_at DESC LIMIT 20'
... SNIP ...
real    0m0.129s
user    0m0.113s
sys	    0m0.016s

Some sort of concurrency issue, maybe?

[djl]

A little bit more debugging from this morning.

If I comment out the c.db.Stats() call in ServeHome then the home page will load in a reasonable time (about four seconds). However, if I then attempt two concurrent requests to the homepage (with different users/clients) then the timeout is back.

Given that, I don't think this is a slow query issue after all. Especially since the queries, when run manually, all return very quickly.

Weird!

[sentriz]

@djl can you try again on the latest :nightly ?

[djl]

No dice, sadly, but this did give me motivation to start debugging again.

ServeHome still chokes when c.db.Stats() is called. I haven't been able to narrow down exactly which query is causing the problem yet.

ServeGetAlbumListTwo seems to be slow when the type parameter is newest. Ordering by albums.id instead of created_at makes the query near instant again. Ordering by a datetime column is apparently very slow?

[sentriz]

@djl thanks, i pushed an index. :nightly is building

[djl]

@sentriz the index does not seem to have helped any. Timeouts still happen in the rest API.

I still think there's an odd concurrency/locking issue somewhere. The queries, when run manually, are very fast:

$ time (sqlite3 gonic.db "SELECT albums.*, count(tracks.id) child_count, sum(tracks.length) duration FROM "albums" LEFT JOIN tracks ON tracks.album_id=albums.id JOIN album_artists ON album_artists.album_id=albums.id GROUP BY albums.id ORDER BY created_at DESC LIMIT 20 OFFSET 0" > /dev/null)

real	0m0.135s
user	0m0.123s
sys	0m0.012s

Even when /rest/ calls are hanging, the manually run queries are still near-instant.

[sentriz]

@djl was this an issue on v0.18.0? ie did it only become an issue since v0.19.0?

[djl]

@sentriz You may be on to something. I've just pulled the v0.18.0 tag and have started a rescan. No issues so far, but I'm only about 20% of the way through my library. Will report back when it's done.