search

sentriz / gonic

music streaming server / free-software subsonic server API implementation
ircs://irc.libera.chat/#gonic
GNU General Public License v3.0
1.57k stars 112 forks source link

Cannot update remote players databases #271

Closed AlessandroZanatta closed 1 year ago

AlessandroZanatta commented 1 year ago

Hi,

I'm currently receiving a panic every time I try to update the library of a subsonic player (official Android app). In particular, the following error is logged:

2022/12/12 10:37:08 response  200  for `/rest/getPlaylists.view?c=android&p=REDACTED&u=kalex&v=1.2.0`
2022/12/12 10:37:10 response  200  for `/rest/getMusicFolders.view?c=android&p=REDACTED&u=kalex&v=1.2.0`
2022/12/12 10:33:53 http: panic serving 172.18.0.3:45892: runtime error: index out of range [1] with length 1
goroutine 541 [running]:
net/http.(*conn).serve.func1()
    /usr/local/go/src/net/http/server.go:1850 +0xb8
panic({0xb0a180, 0x400078e6a8})
    /usr/local/go/src/runtime/panic.go:890 +0x260
go.senan.xyz/gonic/server/ctrlsubsonic.getMusicFolder({0x400024ac40, 0x1, 0xcb2f20?}, 0x0?)
    /src/server/ctrlsubsonic/handlers_common.go:40 +0xcc
go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).ServeGetIndexes(0x40004721b0, 0x40009aca00)
    /src/server/ctrlsubsonic/handlers_by_folder.go:28 +0x198
go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).H.func1({0xcb9870, 0x40000a45e8}, 0x40009dd518?)
    /src/server/ctrlsubsonic/ctrl.go:107 +0x34
net/http.HandlerFunc.ServeHTTP(0xcba380?, {0xcb9870?, 0x40000a45e8?}, 0xcb22f0?)
    /usr/local/go/src/net/http/server.go:2109 +0x38
go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithUser.func1({0xcb9870, 0x40000a45e8}, 0x40009ac900)
    /src/server/ctrlsubsonic/middleware.go:87 +0x4a0
net/http.HandlerFunc.ServeHTTP(0x40009c0620?, {0xcb9870?, 0x40000a45e8?}, 0xa6eca0?)
    /usr/local/go/src/net/http/server.go:2109 +0x38
go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithRequiredParams.func1({0xcb9870, 0x40000a45e8}, 0x40009ac900)
    /src/server/ctrlsubsonic/middleware.go:50 +0xcc
net/http.HandlerFunc.ServeHTTP(0xcba380?, {0xcb9870?, 0x40000a45e8?}, 0xcb2398?)
    /usr/local/go/src/net/http/server.go:2109 +0x38
go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithParams.func1({0xcb9870, 0x40000a45e8}, 0x40009ac800)
    /src/server/ctrlsubsonic/middleware.go:33 +0x144
net/http.HandlerFunc.ServeHTTP(0xafacc0?, {0xcb9870?, 0x40000a45e8?}, 0x1c?)
    /usr/local/go/src/net/http/server.go:2109 +0x38
go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithCORS.func1({0xcb9870, 0x40000a45e8}, 0x40009ac800)
    /src/server/ctrlbase/ctrl.go:106 +0x278
net/http.HandlerFunc.ServeHTTP(0x400037a400?, {0xcb9870?, 0x40000a45e8?}, 0x76a784?)
    /usr/local/go/src/net/http/server.go:2109 +0x38
go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithLogging.func1({0xcb9d20?, 0x40009680e0}, 0x40009ac800)
    /src/server/ctrlbase/ctrl.go:83 +0xa0
net/http.HandlerFunc.ServeHTTP(0x40009ac700?, {0xcb9d20?, 0x40009680e0?}, 0x29bad7a09c?)
    /usr/local/go/src/net/http/server.go:2109 +0x38
github.com/gorilla/mux.(*Router).ServeHTTP(0x400015e000, {0xcb9d20, 0x40009680e0}, 0x40009ac600)
    /go/pkg/mod/github.com/gorilla/mux@v1.8.0/mux.go:210 +0x1a4
net/http.serverHandler.ServeHTTP({0x40004c32c0?}, {0xcb9d20, 0x40009680e0}, 0x40009ac600)
    /usr/local/go/src/net/http/server.go:2947 +0x2cc
net/http.(*conn).serve(0x40002a8000, {0xcba380, 0x40004c30e0})
    /usr/local/go/src/net/http/server.go:1991 +0x544
created by net/http.(*Server).Serve
    /usr/local/go/src/net/http/server.go:3102 +0x43c

I've tried to understand if this error was related to my music library, but after removing everything from it and updating gonic's library the error persisted. Even stranger, I had this error appear some time ago. After a while I tried other software for my music, but I eventually came back to gonic. For some time, everything worked. Then this error came back. I don't really know how this error can be reproduced, but maybe the trace is informative enough for someone who's familiar with the code base (and Go).

I'm using the following docker-compose, if it is of any help. It should be fairly similar to the suggested one anyway.

version: "3"

services:
  gonic:
    image: sentriz/gonic:latest
    volumes:
      - ./data:/data         # gonic db etc
      - /srv/music:/music:ro    # your music
      - ./podcasts:/podcasts # your podcasts
      - ./cache:/cache       # transcode / covers / etc cache dir
    labels:
      - "traefik.enable=true"
      - "traefik.http.routers.gonic.rule=Host(`myhostname`)"
      - "traefik.http.routers.gonic.entrypoints=websecure"
      - "traefik.http.routers.gonic.tls=true"
      - "traefik.http.services.gonic.loadbalancer.server.port=80"
    networks:
      - traefik-net
    restart: unless-stopped
    # set the following two sections if you've enabled jukebox
    # group_add:
    # - audio
    # devices:
    # - /dev/snd:/dev/snd

networks:
  traefik-net:
    external: true
sentriz commented 1 year ago

hi, can you show the output from gonic when it first starts? it should print stuff like the version and a list of config options

AlessandroZanatta commented 1 year ago

Yeah sure, sorry about that. Here it is:

gonic_1  | 2022/12/12 19:16:57 starting gonic v0.15.0
gonic_1  | 2022/12/12 19:16:57 provided config
gonic_1  | 2022/12/12 19:16:57     cache-path                /cache
gonic_1  | 2022/12/12 19:16:57     config-path               
gonic_1  | 2022/12/12 19:16:57     db-path                   /data/gonic.db
gonic_1  | 2022/12/12 19:16:57     genre-split               
gonic_1  | 2022/12/12 19:16:57     http-log                  true
gonic_1  | 2022/12/12 19:16:57     jukebox-enabled           false
gonic_1  | 2022/12/12 19:16:57     jukebox-mpv-extra-args    
gonic_1  | 2022/12/12 19:16:57     listen-addr               :80
gonic_1  | 2022/12/12 19:16:57     music-path                /music
gonic_1  | 2022/12/12 19:16:57     podcast-path              /podcasts
gonic_1  | 2022/12/12 19:16:57     podcast-purge-age         0
gonic_1  | 2022/12/12 19:16:57     proxy-prefix              
gonic_1  | 2022/12/12 19:16:57     scan-at-start-enabled     false
gonic_1  | 2022/12/12 19:16:57     scan-interval             0
gonic_1  | 2022/12/12 19:16:57     scan-watcher-enabled      false
gonic_1  | 2022/12/12 19:16:57     tls-cert                  
gonic_1  | 2022/12/12 19:16:57     tls-key                   
gonic_1  | 2022/12/12 19:16:57     version                   false
gonic_1  | 2022/12/12 19:16:57 starting job 'podcast refresher'
gonic_1  | 2022/12/12 19:16:57 starting job 'http'
gonic_1  | 2022/12/12 19:16:57 starting job 'session clean'
gonic_1  | 2022/12/12 19:17:05 response  200  for `/rest/getRandomSongs.view?c=android&p=REDACTED&size=50&u=kalex&v=1.2.0`
gonic_1  | 2022/12/12 19:17:05 response  200  for `/rest/getPlaylists.view?c=android&p=REDACTED&u=kalex&v=1.2.0`
gonic_1  | 2022/12/12 19:17:08 response  200  for `/rest/getMusicFolders.view?c=android&p=REDACTED&u=kalex&v=1.2.0`
gonic_1  | 2022/12/12 19:17:09 http: panic serving 172.18.0.3:49470: runtime error: index out of range [1] with length 1
gonic_1  | goroutine 16 [running]:
gonic_1  | net/http.(*conn).serve.func1()
gonic_1  |  /usr/local/go/src/net/http/server.go:1850 +0xb8
gonic_1  | panic({0xb0a180, 0x4000316ea0})
gonic_1  |  /usr/local/go/src/runtime/panic.go:890 +0x260
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.getMusicFolder({0x400024ac40, 0x1, 0xcb2f20?}, 0x0?)
gonic_1  |  /src/server/ctrlsubsonic/handlers_common.go:40 +0xcc
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).ServeGetIndexes(0x40003241b0, 0x4000314f00)
gonic_1  |  /src/server/ctrlsubsonic/handlers_by_folder.go:28 +0x198
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).H.func1({0xcb9870, 0x4000318198}, 0x400021b518?)
gonic_1  |  /src/server/ctrlsubsonic/ctrl.go:107 +0x34
gonic_1  | net/http.HandlerFunc.ServeHTTP(0xcba380?, {0xcb9870?, 0x4000318198?}, 0xcb22f0?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithUser.func1({0xcb9870, 0x4000318198}, 0x4000314e00)
gonic_1  |  /src/server/ctrlsubsonic/middleware.go:87 +0x4a0
gonic_1  | net/http.HandlerFunc.ServeHTTP(0x40002e54d0?, {0xcb9870?, 0x4000318198?}, 0xa6eca0?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithRequiredParams.func1({0xcb9870, 0x4000318198}, 0x4000314e00)
gonic_1  |  /src/server/ctrlsubsonic/middleware.go:50 +0xcc
gonic_1  | net/http.HandlerFunc.ServeHTTP(0xcba380?, {0xcb9870?, 0x4000318198?}, 0xcb2398?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithParams.func1({0xcb9870, 0x4000318198}, 0x4000314d00)
gonic_1  |  /src/server/ctrlsubsonic/middleware.go:33 +0x144
gonic_1  | net/http.HandlerFunc.ServeHTTP(0xafacc0?, {0xcb9870?, 0x4000318198?}, 0x1c?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithCORS.func1({0xcb9870, 0x4000318198}, 0x4000314d00)
gonic_1  |  /src/server/ctrlbase/ctrl.go:106 +0x278
gonic_1  | net/http.HandlerFunc.ServeHTTP(0x4000044c00?, {0xcb9870?, 0x4000318198?}, 0x76a784?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithLogging.func1({0xcb9d20?, 0x400057e000}, 0x4000314d00)
gonic_1  |  /src/server/ctrlbase/ctrl.go:83 +0xa0
gonic_1  | net/http.HandlerFunc.ServeHTTP(0x4000314c00?, {0xcb9d20?, 0x400057e000?}, 0x1542777c33?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | github.com/gorilla/mux.(*Router).ServeHTTP(0x400015e9c0, {0xcb9d20, 0x400057e000}, 0x4000314900)
gonic_1  |  /go/pkg/mod/github.com/gorilla/mux@v1.8.0/mux.go:210 +0x1a4
gonic_1  | net/http.serverHandler.ServeHTTP({0x400022e570?}, {0xcb9d20, 0x400057e000}, 0x4000314900)
gonic_1  |  /usr/local/go/src/net/http/server.go:2947 +0x2cc
gonic_1  | net/http.(*conn).serve(0x400056c0a0, {0xcba380, 0x40001b8000})
gonic_1  |  /usr/local/go/src/net/http/server.go:1991 +0x544
gonic_1  | created by net/http.(*Server).Serve
gonic_1  |  /usr/local/go/src/net/http/server.go:3102 +0x43c
sentriz commented 1 year ago

ah, it looks like i messed up some logic for checking if the client is requesting a valid music folder. that part should be fixed now

however something weird is still happening. the client is requesting music folder number 1 (0 indexed) but you only have one music folder (/music)

i would expect to see a &musicFolderId=1 in your logs, but i don't very strange.

or maybe could be something to do with the official subsonic app. i've never used that one btw. is there any reason you use it over dsub/audinaut?

sentriz commented 1 year ago

PS there's a nightly image building here

when its done you can test the changes with the sentriz/gonic:nightly image

then you can see if that issue is fixed, and also any more logs that may be relevant

AlessandroZanatta commented 1 year ago

PS there's a nightly image building here

when its done you can test the changes with the sentriz/gonic:nightly image

then you can see if that issue is fixed, and also any more logs that may be relevant

I quickly tried it out, the error is still happening with the Subsonic client:

gonic_1  | 2022/12/12 20:17:30 starting gonic v0.15.0
gonic_1  | 2022/12/12 20:17:30 provided config
gonic_1  | 2022/12/12 20:17:30     cache-path                /cache
gonic_1  | 2022/12/12 20:17:30     config-path               
gonic_1  | 2022/12/12 20:17:30     db-path                   /data/gonic.db
gonic_1  | 2022/12/12 20:17:30     genre-split               
gonic_1  | 2022/12/12 20:17:30     http-log                  true
gonic_1  | 2022/12/12 20:17:30     jukebox-enabled           false
gonic_1  | 2022/12/12 20:17:30     jukebox-mpv-extra-args    
gonic_1  | 2022/12/12 20:17:30     listen-addr               :80
gonic_1  | 2022/12/12 20:17:30     music-path                /music
gonic_1  | 2022/12/12 20:17:30     podcast-path              /podcasts
gonic_1  | 2022/12/12 20:17:30     podcast-purge-age         0
gonic_1  | 2022/12/12 20:17:30     proxy-prefix              
gonic_1  | 2022/12/12 20:17:30     scan-at-start-enabled     false
gonic_1  | 2022/12/12 20:17:30     scan-interval             0
gonic_1  | 2022/12/12 20:17:30     scan-watcher-enabled      false
gonic_1  | 2022/12/12 20:17:30     tls-cert                  
gonic_1  | 2022/12/12 20:17:30     tls-key                   
gonic_1  | 2022/12/12 20:17:30     version                   false
gonic_1  | 2022/12/12 20:17:30 starting job 'podcast refresher'
gonic_1  | 2022/12/12 20:17:30 starting job 'http'
gonic_1  | 2022/12/12 20:17:30 starting job 'session clean'
gonic_1  | 2022/12/12 20:17:34 response  200  for `/rest/getPlaylists.view?c=android&p=REDACTED&u=kalex&v=1.2.0`
gonic_1  | 2022/12/12 20:17:35 response  200  for `/rest/getRandomSongs.view?c=android&p=REDACTED&size=50&u=kalex&v=1.2.0`
gonic_1  | 2022/12/12 20:17:37 response  200  for `/rest/getMusicFolders.view?c=android&p=REDACTED&u=kalex&v=1.2.0`
gonic_1  | 2022/12/12 20:17:37 http: panic serving 172.18.0.3:51476: runtime error: index out of range [1] with length 1
gonic_1  | goroutine 8 [running]:
gonic_1  | net/http.(*conn).serve.func1()
gonic_1  |  /usr/local/go/src/net/http/server.go:1850 +0xb8
gonic_1  | panic({0xb0d400, 0x4000288d08})
gonic_1  |  /usr/local/go/src/runtime/panic.go:890 +0x260
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.getMusicFolder({0x4000250100, 0x1, 0xcb6408?}, 0x0?)
gonic_1  |  /src/server/ctrlsubsonic/handlers_common.go:41 +0xc8
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).ServeGetIndexes(0x40002902d0, 0x40002e1500)
gonic_1  |  /src/server/ctrlsubsonic/handlers_by_folder.go:28 +0x198
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).H.func1({0xcbcd50, 0x40002a0918}, 0x40001ab518?)
gonic_1  |  /src/server/ctrlsubsonic/ctrl.go:108 +0x34
gonic_1  | net/http.HandlerFunc.ServeHTTP(0xcbd860?, {0xcbcd50?, 0x40002a0918?}, 0xcb57c8?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithUser.func1({0xcbcd50, 0x40002a0918}, 0x40002e1400)
gonic_1  |  /src/server/ctrlsubsonic/middleware.go:87 +0x4a0
gonic_1  | net/http.HandlerFunc.ServeHTTP(0x4000021250?, {0xcbcd50?, 0x40002a0918?}, 0xa71dc0?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithRequiredParams.func1({0xcbcd50, 0x40002a0918}, 0x40002e1400)
gonic_1  |  /src/server/ctrlsubsonic/middleware.go:50 +0xcc
gonic_1  | net/http.HandlerFunc.ServeHTTP(0xcbd860?, {0xcbcd50?, 0x40002a0918?}, 0xcb5870?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | go.senan.xyz/gonic/server/ctrlsubsonic.(*Controller).WithParams.func1({0xcbcd50, 0x40002a0918}, 0x40002e1300)
gonic_1  |  /src/server/ctrlsubsonic/middleware.go:33 +0x144
gonic_1  | net/http.HandlerFunc.ServeHTTP(0xafdf40?, {0xcbcd50?, 0x40002a0918?}, 0x1c?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithCORS.func1({0xcbcd50, 0x40002a0918}, 0x40002e1300)
gonic_1  |  /src/server/ctrlbase/ctrl.go:106 +0x278
gonic_1  | net/http.HandlerFunc.ServeHTTP(0x4000044800?, {0xcbcd50?, 0x40002a0918?}, 0x76b9c4?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | go.senan.xyz/gonic/server/ctrlbase.(*Controller).WithLogging.func1({0xcbd200?, 0x40001920e0}, 0x40002e1300)
gonic_1  |  /src/server/ctrlbase/ctrl.go:83 +0xa0
gonic_1  | net/http.HandlerFunc.ServeHTTP(0x40002e1200?, {0xcbd200?, 0x40001920e0?}, 0x143ea479c4?)
gonic_1  |  /usr/local/go/src/net/http/server.go:2109 +0x38
gonic_1  | github.com/gorilla/mux.(*Router).ServeHTTP(0x40002d2000, {0xcbd200, 0x40001920e0}, 0x40002e1100)
gonic_1  |  /go/pkg/mod/github.com/gorilla/mux@v1.8.0/mux.go:210 +0x1a4
gonic_1  | net/http.serverHandler.ServeHTTP({0x4000455b30?}, {0xcbd200, 0x40001920e0}, 0x40002e1100)
gonic_1  |  /usr/local/go/src/net/http/server.go:2947 +0x2cc
gonic_1  | net/http.(*conn).serve(0x4000153ae0, {0xcbd860, 0x4000455a40})
gonic_1  |  /usr/local/go/src/net/http/server.go:1991 +0x544
gonic_1  | created by net/http.(*Server).Serve
gonic_1  |  /usr/local/go/src/net/http/server.go:3102 +0x43c

As a sidenote, the UI of the admin page looks somewhat squashed in the nightly build: image

or maybe could be something to do with the official subsonic app. i've never used that one btw. is there any reason you use it over dsub/audinaut?

While the official Subsonic app gives me the above error, I've just tried to install dsub, and it appears to be working fine actually.

sentriz commented 1 year ago

thanks, can you try it again from the official subsonic client when this is done? somehow the app is sending a malformed music folder index, by passing the out of bounds check, or something. with the latest change it should print the request url and params, even if theres a panic

https://github.com/sentriz/gonic/actions/runs/3680148975

AlessandroZanatta commented 1 year ago

It looks like everything is working correctly now! Thanks a lot