error when loading playlist

[Byter09]

Hello, recently gonic started throwing errors when I want to play a playlist. I tried multiple clients until I had a look at my logs today. Just to have a clean and reproducable setup, I restarted the docker client and did the absolut minimum to cause it again.

Steps:

1. start gonic using sentriz/gonic:latest@sha256:2033827c90073f3dfdcbea26e9482521595fb8ce27257410af1b35796d6
2. Go to any client. I tried Audinaut, DSub and Music Stash.
3. Open a playlist.

Thats it. Upon opening the playlist it shows the below errors in the log and every client responds a bit different but most say there was a server error.

logs

``` 2020/05/26 16:25:04 starting gonic v0.8.8 2020/05/26 16:25:04 provided config 2020/05/26 16:25:04 cache-path /cache 2020/05/26 16:25:04 config-path 2020/05/26 16:25:04 db-path /data/gonic.db 2020/05/26 16:25:04 jukebox-enabled false 2020/05/26 16:25:04 listen-addr :80 2020/05/26 16:25:04 music-path /music 2020/05/26 16:25:04 proxy-prefix 2020/05/26 16:25:04 scan-interval 720 2020/05/26 16:25:04 version false 2020/05/26 16:25:04 starting job 'scan timer' 2020/05/26 16:25:04 starting job 'session clean' 2020/05/26 16:25:04 starting job 'http' 2020/05/26 16:25:15 http: panic serving 172.17.0.1:42946: runtime error: invalid memory address or nil pointer dereference goroutine 34 [running]: net/http.(*conn).serve.func1(0xc000488000) /usr/local/go/src/net/http/server.go:1772 +0x139 panic(0xa34380, 0xf90e60) /usr/local/go/src/runtime/panic.go:975 +0x3e3 go.senan.xyz/gonic/server/ctrlsubsonic/spec.NewTCTrackByFolder(0xc0000ee0f0, 0x0, 0xc0000ee0f0) /src/server/ctrlsubsonic/spec/construct_by_folder.go:49 +0xae go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).ServeGetPlaylist(0xc000382d00, 0xc000498400, 0xc0002ec500) /src/server/ctrlsubsonic/handlers_common.go:169 +0x6fb go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).H.func1(0xbc55e0, 0xc0004800a0, 0xc000498400) /src/server/ctrlsubsonic/ctrl.go:91 +0x33 net/http.HandlerFunc.ServeHTTP(0xc0003c4940, 0xbc55e0, 0xc0004800a0, 0xc000498400) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithUser.func1(0xbc55e0, 0xc0004800a0, 0xc000498300) /src/server/ctrlsubsonic/middleware.go:88 +0x4cb net/http.HandlerFunc.ServeHTTP(0xc000480020, 0xbc55e0, 0xc0004800a0, 0xc000498300) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithRequiredParams.func1(0xbc55e0, 0xc0004800a0, 0xc000498300) /src/server/ctrlsubsonic/middleware.go:52 +0x121 net/http.HandlerFunc.ServeHTTP(0xc0002e43f0, 0xbc55e0, 0xc0004800a0, 0xc000498300) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithParams.func1(0xbc55e0, 0xc0004800a0, 0xc000498200) /src/server/ctrlsubsonic/middleware.go:33 +0x17c net/http.HandlerFunc.ServeHTTP(0xc000480040, 0xbc55e0, 0xc0004800a0, 0xc000498200) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithCORS.func1(0xbc55e0, 0xc0004800a0, 0xc000498200) /src/server/ctrlbase/ctrl.go:82 +0x300 net/http.HandlerFunc.ServeHTTP(0xc000480060, 0xbc55e0, 0xc0004800a0, 0xc000498200) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithLogging.func1(0xbc5920, 0xc0004a4000, 0xc000498200) /src/server/ctrlbase/ctrl.go:65 +0x9d net/http.HandlerFunc.ServeHTTP(0xc000480080, 0xbc5920, 0xc0004a4000, 0xc000498200) /usr/local/go/src/net/http/server.go:2012 +0x44 github.com/gorilla/mux.(*Router).ServeHTTP(0xc0000f0600, 0xbc5920, 0xc0004a4000, 0xc000498000) /go/pkg/mod/github.com/gorilla/mux@v1.7.4/mux.go:210 +0xe2 net/http.serverHandler.ServeHTTP(0xc0000e42a0, 0xbc5920, 0xc0004a4000, 0xc000498000) /usr/local/go/src/net/http/server.go:2807 +0xa3 net/http.(*conn).serve(0xc000488000, 0xbc7060, 0xc000482040) /usr/local/go/src/net/http/server.go:1895 +0x86c created by net/http.(*Server).Serve /usr/local/go/src/net/http/server.go:2933 +0x35c 2020/05/26 16:25:15 http: panic serving 172.17.0.1:42950: runtime error: invalid memory address or nil pointer dereference goroutine 54 [running]: net/http.(*conn).serve.func1(0xc0000a2320) /usr/local/go/src/net/http/server.go:1772 +0x139 panic(0xa34380, 0xf90e60) /usr/local/go/src/runtime/panic.go:975 +0x3e3 go.senan.xyz/gonic/server/ctrlsubsonic/spec.NewTCTrackByFolder(0xc0004d0d20, 0x0, 0xc0004d0d20) /src/server/ctrlsubsonic/spec/construct_by_folder.go:49 +0xae go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).ServeGetPlaylist(0xc000382d00, 0xc000222400, 0xc00021e480) /src/server/ctrlsubsonic/handlers_common.go:169 +0x6fb go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).H.func1(0xbc55e0, 0xc000198100, 0xc000222400) /src/server/ctrlsubsonic/ctrl.go:91 +0x33 net/http.HandlerFunc.ServeHTTP(0xc0003c4940, 0xbc55e0, 0xc000198100, 0xc000222400) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithUser.func1(0xbc55e0, 0xc000198100, 0xc000222300) /src/server/ctrlsubsonic/middleware.go:88 +0x4cb net/http.HandlerFunc.ServeHTTP(0xc000198000, 0xbc55e0, 0xc000198100, 0xc000222300) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithRequiredParams.func1(0xbc55e0, 0xc000198100, 0xc000222300) /src/server/ctrlsubsonic/middleware.go:52 +0x121 net/http.HandlerFunc.ServeHTTP(0xc00008d380, 0xbc55e0, 0xc000198100, 0xc000222300) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithParams.func1(0xbc55e0, 0xc000198100, 0xc000222200) /src/server/ctrlsubsonic/middleware.go:33 +0x17c net/http.HandlerFunc.ServeHTTP(0xc000198040, 0xbc55e0, 0xc000198100, 0xc000222200) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithCORS.func1(0xbc55e0, 0xc000198100, 0xc000222200) /src/server/ctrlbase/ctrl.go:82 +0x300 net/http.HandlerFunc.ServeHTTP(0xc000198080, 0xbc55e0, 0xc000198100, 0xc000222200) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithLogging.func1(0xbc5920, 0xc0004a40e0, 0xc000222200) /src/server/ctrlbase/ctrl.go:65 +0x9d net/http.HandlerFunc.ServeHTTP(0xc0001980c0, 0xbc5920, 0xc0004a40e0, 0xc000222200) /usr/local/go/src/net/http/server.go:2012 +0x44 github.com/gorilla/mux.(*Router).ServeHTTP(0xc0000f0600, 0xbc5920, 0xc0004a40e0, 0xc000222000) /go/pkg/mod/github.com/gorilla/mux@v1.7.4/mux.go:210 +0xe2 net/http.serverHandler.ServeHTTP(0xc0000e42a0, 0xbc5920, 0xc0004a40e0, 0xc000222000) /usr/local/go/src/net/http/server.go:2807 +0xa3 net/http.(*conn).serve(0xc0000a2320, 0xbc7060, 0xc0001c0000) /usr/local/go/src/net/http/server.go:1895 +0x86c created by net/http.(*Server).Serve /usr/local/go/src/net/http/server.go:2933 +0x35c ```

Not sure if this is relevant but I recently started renaming a few songs. I'm pretty sure this should not affect anything but I just thought it could help pinpoint the problem.

Thanks for gonic btw :)

[sentriz]

interesting. thanks for investigating :) by any change do you have any audio files in your root dir? eg /music/a.mp3?

[Byter09]

I do not. The only two interesting folders I have in there are !unsorted and .stfolder. The rest of them are alphanumerical so shouldn't cause any errors. I had these before though, so it once worked. Could it be some file in an album that has some non-ascii chars? Haven't looked at the code yet. Just guessing at this point :smile:

[sentriz]

hey could you try again with sentriz/gonic:latest again please and check the logs?

sha256:00c7c3986d6f63150c901cdca75ab7050ee445369ce2f96ac01b7a0c5c4ffe1b

[Byter09]

Was kind of wondering why watchtower didn't already pull the latest one haha.

Am now on sentriz/gonic:latest@sha256:bba999e44b70256c21d5ac165fc981c1ab44fedd416e4244d5c354ccf5e1b34b

And it updates automatically as soon as you publish a new one :)

Same issue though :(

``` 2020/05/26 17:59:15 starting gonic v0.8.8 2020/05/26 17:59:15 provided config 2020/05/26 17:59:15 cache-path /cache 2020/05/26 17:59:15 config-path 2020/05/26 17:59:15 db-path /data/gonic.db 2020/05/26 17:59:15 jukebox-enabled false 2020/05/26 17:59:15 listen-addr :80 2020/05/26 17:59:15 music-path /music 2020/05/26 17:59:15 proxy-prefix 2020/05/26 17:59:15 scan-interval 720 2020/05/26 17:59:15 version false 2020/05/26 17:59:15 starting job 'scan timer' 2020/05/26 17:59:15 starting job 'session clean' 2020/05/26 17:59:15 starting job 'http' 2020/05/26 18:00:32 http: panic serving 172.17.0.1:37838: runtime error: invalid memory address or nil pointer dereference goroutine 52 [running]: net/http.(*conn).serve.func1(0xc000122280) /usr/local/go/src/net/http/server.go:1772 +0x139 panic(0xa34380, 0xf90e60) /usr/local/go/src/runtime/panic.go:975 +0x3e3 go.senan.xyz/gonic/server/ctrlsubsonic/spec.NewTCTrackByFolder(0xc0000c0ff0, 0x0, 0xc0000c0ff0) /src/server/ctrlsubsonic/spec/construct_by_folder.go:49 +0xae go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).ServeGetPlaylist(0xc0004888a0, 0xc000218400, 0xc00021e480) /src/server/ctrlsubsonic/handlers_common.go:169 +0x6fb go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).H.func1(0xbc55e0, 0xc00000e1c0, 0xc000218400) /src/server/ctrlsubsonic/ctrl.go:91 +0x33 net/http.HandlerFunc.ServeHTTP(0xc000485750, 0xbc55e0, 0xc00000e1c0, 0xc000218400) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithUser.func1(0xbc55e0, 0xc00000e1c0, 0xc000218300) /src/server/ctrlsubsonic/middleware.go:88 +0x4cb net/http.HandlerFunc.ServeHTTP(0xc00000e0a0, 0xbc55e0, 0xc00000e1c0, 0xc000218300) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithRequiredParams.func1(0xbc55e0, 0xc00000e1c0, 0xc000218300) /src/server/ctrlsubsonic/middleware.go:52 +0x121 net/http.HandlerFunc.ServeHTTP(0xc00010d4d0, 0xbc55e0, 0xc00000e1c0, 0xc000218300) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithParams.func1(0xbc55e0, 0xc00000e1c0, 0xc000218200) /src/server/ctrlsubsonic/middleware.go:33 +0x17c net/http.HandlerFunc.ServeHTTP(0xc00000e0c0, 0xbc55e0, 0xc00000e1c0, 0xc000218200) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithCORS.func1(0xbc55e0, 0xc00000e1c0, 0xc000218200) /src/server/ctrlbase/ctrl.go:82 +0x300 net/http.HandlerFunc.ServeHTTP(0xc00000e0e0, 0xbc55e0, 0xc00000e1c0, 0xc000218200) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithLogging.func1(0xbc5920, 0xc0005920e0, 0xc000218200) /src/server/ctrlbase/ctrl.go:65 +0x9d net/http.HandlerFunc.ServeHTTP(0xc00000e100, 0xbc5920, 0xc0005920e0, 0xc000218200) /usr/local/go/src/net/http/server.go:2012 +0x44 github.com/gorilla/mux.(*Router).ServeHTTP(0xc000170600, 0xbc5920, 0xc0005920e0, 0xc000218000) /go/pkg/mod/github.com/gorilla/mux@v1.7.4/mux.go:210 +0xe2 net/http.serverHandler.ServeHTTP(0xc000592000, 0xbc5920, 0xc0005920e0, 0xc000218000) /usr/local/go/src/net/http/server.go:2807 +0xa3 net/http.(*conn).serve(0xc000122280, 0xbc7060, 0xc000076000) /usr/local/go/src/net/http/server.go:1895 +0x86c created by net/http.(*Server).Serve /usr/local/go/src/net/http/server.go:2933 +0x35c 2020/05/26 18:00:32 http: panic serving 172.17.0.1:37842: runtime error: invalid memory address or nil pointer dereference goroutine 54 [running]: net/http.(*conn).serve.func1(0xc0001228c0) /usr/local/go/src/net/http/server.go:1772 +0x139 panic(0xa34380, 0xf90e60) /usr/local/go/src/runtime/panic.go:975 +0x3e3 go.senan.xyz/gonic/server/ctrlsubsonic/spec.NewTCTrackByFolder(0xc000358960, 0x0, 0xc000358960) /src/server/ctrlsubsonic/spec/construct_by_folder.go:49 +0xae go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).ServeGetPlaylist(0xc0004888a0, 0xc0002f9200, 0xc000224480) /src/server/ctrlsubsonic/handlers_common.go:169 +0x6fb go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).H.func1(0xbc55e0, 0xc0002ee160, 0xc0002f9200) /src/server/ctrlsubsonic/ctrl.go:91 +0x33 net/http.HandlerFunc.ServeHTTP(0xc000485750, 0xbc55e0, 0xc0002ee160, 0xc0002f9200) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithUser.func1(0xbc55e0, 0xc0002ee160, 0xc0002f8a00) /src/server/ctrlsubsonic/middleware.go:88 +0x4cb net/http.HandlerFunc.ServeHTTP(0xc0002ee040, 0xbc55e0, 0xc0002ee160, 0xc0002f8a00) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithRequiredParams.func1(0xbc55e0, 0xc0002ee160, 0xc0002f8a00) /src/server/ctrlsubsonic/middleware.go:52 +0x121 net/http.HandlerFunc.ServeHTTP(0xc000409ce0, 0xbc55e0, 0xc0002ee160, 0xc0002f8a00) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithParams.func1(0xbc55e0, 0xc0002ee160, 0xc0002f8500) /src/server/ctrlsubsonic/middleware.go:33 +0x17c net/http.HandlerFunc.ServeHTTP(0xc0002ee080, 0xbc55e0, 0xc0002ee160, 0xc0002f8500) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithCORS.func1(0xbc55e0, 0xc0002ee160, 0xc0002f8500) /src/server/ctrlbase/ctrl.go:82 +0x300 net/http.HandlerFunc.ServeHTTP(0xc0002ee0a0, 0xbc55e0, 0xc0002ee160, 0xc0002f8500) /usr/local/go/src/net/http/server.go:2012 +0x44 go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithLogging.func1(0xbc5920, 0xc00033c000, 0xc0002f8500) /src/server/ctrlbase/ctrl.go:65 +0x9d net/http.HandlerFunc.ServeHTTP(0xc0002ee0e0, 0xbc5920, 0xc00033c000, 0xc0002f8500) /usr/local/go/src/net/http/server.go:2012 +0x44 github.com/gorilla/mux.(*Router).ServeHTTP(0xc000170600, 0xbc5920, 0xc00033c000, 0xc0002f8100) /go/pkg/mod/github.com/gorilla/mux@v1.7.4/mux.go:210 +0xe2 net/http.serverHandler.ServeHTTP(0xc000592000, 0xbc5920, 0xc00033c000, 0xc0002f8100) /usr/local/go/src/net/http/server.go:2807 +0xa3 net/http.(*conn).serve(0xc0001228c0, 0xbc7060, 0xc0003f4100) /usr/local/go/src/net/http/server.go:1895 +0x86c created by net/http.(*Server).Serve /usr/local/go/src/net/http/server.go:2933 +0x35c ```

EDIT: Aaaand watchtower just pulled sha256:f3e05970af708efb4c638e9f3cb10ab9b602776bd954047b9b988d87b20e8159. Testing ...

[sentriz]

sorry I just pushed a new one. can you find b33734a0091ecb8e22b0fb36b6a5a7704bd10cad6ca758a4968b7d0744efa4e?

[sentriz]

ah yes f3... will do too

[Byter09]

Apart from

2020/05/26 18:06:46 wasn't able to find track with id 'Υ',

It appears to work fine now.

[Byter09]

Just had a look at the commit and the typical ID stuff in my logs. This... id is not supposed to be a letter... right? Is this somehow my fault?

[sentriz]

Oh is it a literal Y in your logs?

[Byter09]

I copied the above directly from my docker logs. So I assume yes.

[Byter09]

Do you maybe need my database or so? I assume nothing personal is in there so I have no trouble sharing it :)

EDIT: Oh right... usernames and passwords. They're hashed right? :smiley:

[sentriz]

they are not hashed unfortunately due to a limitation in the subsonic api. but you can make a copy of the db then $ sqlite3 path/to/dbcopy.db "delete from users" and that will remove it from the copy, then you could send that?

[Byter09]

There you go. I manually used a sqlite viewer to verify the user table was empty.

Note: The gonic.db has 1.2 MiB, the gonic.db-wal has 4.1 MiB. I'm not certain how exactly this works but I hope everything you need is in the .db file.

gonic.db.tar.gz

[sentriz]

thanks for the db! turns out that Y was a stupid mistake on my part (fixed now, you should get a real id) but unfortunately this is a problem with gonic :( #54 is the same issue

[sentriz]

as something in the meantime, I need to make a mechanism to export playlists to m3u or something. that way we can have backups when the migration is written