Navidrome paylist not updated by Symfonium

vurt · February 15, 2025, 5:40pm

Issue description:

I freshly imported a playlist from my Navidrome as “online first”.

I tried to add a song to the playlist and received an “error sync”.

Logs:

Upload description: Username: vurt Issue: Navidrome not updating online playlist Symfonium log attached.

Additional information:

Navidrome log: time="2025-02-15T15:56:53Z" level=info msg="Now Playing" artist="Eelke Kleijn" player="Symfonium [Symfonium/Android]" requestId=02985631574e/0M1kiHAFHp-000633 title="DAYS like NIGHTS 378 - Complot Outdoor, Santa Fe, Argentina" user=vurt time="2025-02-15T15:56:59Z" level=info msg="Now Playing" artist="Eelke Kleijn" player="Symfonium [Symfonium/Android]" requestId=02985631574e/0M1kiHAFHp-000635 title="DAYS like NIGHTS 378 - Complot Outdoor, Santa Fe, Argentina" user=vurt time="2025-02-15T16:38:27Z" level=warning msg="API: Failed response" endpoint=/rest/updatePlaylist.view error=10 message="missing parameter: 'playlistId'" requestId=02985631574e/0M1kiHAFHp-000737 time="2025-02-15T16:40:18Z" level=info msg="Now Playing" artist="Eelke Kleijn" player="Symfonium [Symfonium/Android]" requestId=02985631574e/0M1kiHAFHp-000750 title="DAYS like NIGHTS 378 - Complot Outdoor, Santa Fe, Argentina" user=vurt time="2025-02-15T16:40:58Z" level=warning msg="API: Failed response" endpoint=/rest/updatePlaylist.view error=10 message="missing parameter: 'playlistId'" requestId=02985631574e/0M1kiHAFHp-000761 time="2025-02-15T16:55:10Z" level=warning msg="HTTP: GET http://192.168.1.252:4533/api/transcoding?_end=1000&_order=ASC&_sort=name&_start=0" elapsedTime="58.955µs" httpStatus=401 remoteAddr="192.168.1.50:56802" requestId=02985631574e/0M1kiHAFHp-000800 responseSize=29 time="2025-02-15T16:55:10Z" level=warning msg="HTTP: GET http://192.168.1.252:4533/api/playlist?_end=0&_sort=name&_start=-100" elapsedTime=7.5ms httpStatus=401 remoteAddr="192.168.1.50:56803" requestId=02985631574e/0M1kiHAFHp-000799 responseSize=29 time="2025-02-15T16:55:10Z" level=warning msg="HTTP: GET http://192.168.1.252:4533/api/playlist?_end=15&_order=ASC&_sort=id&_start=0" elapsedTime="56.505µs" httpStatus=401 remoteAddr="192.168.1.50:56802" requestId=02985631574e/0M1kiHAFHp-000801 responseSize=29 time="2025-02-15T16:55:10Z" level=warning msg="HTTP: GET http://192.168.1.252:4533/api/user?_end=0&_order=ASC&_sort=name&_start=0" elapsedTime="27.828µs" httpStatus=401 remoteAddr="192.168.1.50:56803" requestId=02985631574e/0M1kiHAFHp-000804 responseSize=29 time="2025-02-15T16:56:00Z" level=info msg="Loaded translations" languages="[ar bg ca cs da de eo es eu fa fi fr gl hu id it ja ko nl pl pt ru sl sr sv th tr uk zh-Hans zh-Hant]"

Reproduction steps:

Media provider:

Subsonic

Screenshots:

Tolriq · February 15, 2025, 5:54pm

For @deluan

The Symfonium side:

SubsonicLogger  --> [271] POST http://xxxx.xxx.net/rest/updatePlaylist.view?u=REDACTED&t=REDACTED&s=REDACTED&v=1.13.0&c=Symfonium&f=json (187-byte body)
SubsonicLogger  --> [271] playlistId=3abe7416-a442-41a0-a0f7-1622a97b884b&songIndexToRemove=0&songIndexToRemove=1&songIndexToRemove=2&songIndexToRemove=3&songIndexToRemove=4&songIndexToRemove=5&songIndexToRemove=6
SubsonicLogger  --> [271] END POST (187-byte body)
SubsonicLogger  <-- [271] 200 https://xxx.xxx.net/rest/updatePlaylist.view?u=REDACTED&t=REDACTED&s=REDACTED&v=1.13.0&c=Symfonium&f=json (9ms, unknown-length body)
SubsonicLogger  <-- [271] {"subsonic-response":{"status":"failed","version":"1.16.1","type":"navidrome","serverVersion":"0.54.4 (73ccfbd8)","openSubsonic":true,"error":{"code":10,"message":"missing parameter: 'playlistId'"}}}

The playlistId is definitively sent.

deluan · February 15, 2025, 7:21pm

~~What version of Navidrome is this?~~ nvm, so it in the log above. Will take a look

deluan · February 15, 2025, 8:02pm

I can’t reproduce it. Can you please change Navidrome’s LogLevel to trace and send me the related section of the logs when trying to update the playlist?

deluan · February 15, 2025, 8:06pm

Actually I am able to reproduce it, if the request does not have the content-type set to application/x-www-form-urlencoded. @Tolriq can you confirm from the logs that the content-type is set correctly?

Tolriq · February 15, 2025, 8:17pm

No the logs don’t show the header but it’s handled by the http library and since the content is form-url encoded it’s certain it’s there else the call would fail.

Just tested with the demo server of Navidrome and everything works as expected as with my old personal instance.

@vurt do you have a proxy or something in front of your server that could rewrite the headers ?

vurt · February 15, 2025, 8:27pm

@Tolriq Ah yes, it is reverse-proxied with nginx.

The Navidrome is installed as a docker on an Unraid NAS and reverse proxied.

Symfonium connects fine to it outside the LAN but I don’t know enough to know what happens between Synfonium and Navidrome via nginx.

Tolriq · February 15, 2025, 8:41pm

@deluan can Navidrome log the headers on it’s side to see what reach it ?

deluan · February 15, 2025, 8:51pm

@deluan can Navidrome log the headers on it’s side to see what reach it ?

Yes, by setting log level to trace

vurt · February 15, 2025, 9:06pm

Hi @deluan , I set the log level to “trace” and this is what I got:

time="2025-02-15T21:05:42Z" level=warning msg="API: Failed response" endpoint=/rest/updatePlaylist.view error=10 message="missing parameter: 'playlistId'" requestId=02985631574e/5T9DMWbuEJ-000186   
time="2025-02-15T21:10:36Z" level=warning msg="API: Failed response" endpoint=/rest/updatePlaylist.view error=10 message="missing parameter: 'playlistId'" requestId=02985631574e/5T9DMWbuEJ-000295

deluan · February 15, 2025, 9:18pm

You are only posting the error. Please add the full logs for the request. Example:

DEBU[0015] API: New request /rest/updatePlaylist         client=NavidromeUI requestId=Mac.lan/7TOEL9X6di-000002 username=admin version=1.8.0
TRAC[0015] SQL: `SELECT * FROM user WHERE user_name = {:p0} COLLATE NOCASE`  args="map[p0:admin]" elapsedTime="853.666µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=1
TRAC[0015] SQL: `UPDATE user SET last_access_at = {:p0} WHERE id = {:p1}`  args="map[p0:2025-02-15 16:17:20.46454 -0500 EST m=+15.704714335 p1:6f9786e8-3b84-4d9d-865e-1f8dda2682a5]" elapsedTime="527.417µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=1
TRAC[0015] Update user's lastAccessAt                    elapsed=2.2ms requestId=Mac.lan/7TOEL9X6di-000002 username=admin
TRAC[0015] playerId found in cookies                     playerId=aba5499a-0748-49cf-9bae-b49fc941587d requestId=Mac.lan/7TOEL9X6di-000002
TRAC[0015] SQL: `SELECT player.*, user.user_name username FROM player JOIN user ON player.user_id = user.id WHERE player.id = {:p0}`  args="map[p0:aba5499a-0748-49cf-9bae-b49fc941587d]" elapsedTime="981.041µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=1
TRAC[0015] SQL: `UPDATE player SET client = {:p0}, id = {:p1}, ip = {:p2}, last_seen = {:p3}, max_bit_rate = {:p4}, name = {:p5}, report_real_path = {:p6}, scrobble_enabled = {:p7}, transcoding_id = {:p8}, user_agent = {:p9}, user_id = {:p10} WHERE id = {:p11}`  args="map[p0:NavidromeUI p1:aba5499a-0748-49cf-9bae-b49fc941587d p10:6f9786e8-3b84-4d9d-865e-1f8dda2682a5 p11:aba5499a-0748-49cf-9bae-b49fc941587d p2:127.0.0.1 p3:2025-02-15T16:17:20.472275-05:00 p4:0 p5:NavidromeUI [IntelliJ HTTP Client] p6:false p7:true p8: p9:IntelliJ HTTP Client]" elapsedTime="531.083µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=1
DEBU[0015] Updating playlist                             id=30b3d166-0c26-42b7-bbe2-681fbbda04d2 requestId=Mac.lan/7TOEL9X6di-000002
TRAC[0015] -- Adding: '[]'                               requestId=Mac.lan/7TOEL9X6di-000002
TRAC[0015] -- Removing: '[0]'                            requestId=Mac.lan/7TOEL9X6di-000002
TRAC[0015] SQL: `SELECT playlist.*, user.user_name as owner_name FROM playlist JOIN user on user.id = owner_id WHERE (playlist.id = {:p0} AND (1=1))`  args="map[p0:30b3d166-0c26-42b7-bbe2-681fbbda04d2]" elapsedTime="699.792µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=1
TRAC[0015] SQL: `SELECT playlist.*, user.user_name as owner_name FROM playlist JOIN user on user.id = owner_id WHERE (playlist.id = {:p0} AND (1=1))`  args="map[p0:30b3d166-0c26-42b7-bbe2-681fbbda04d2]" elapsedTime="298.25µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=1
TRAC[0015] SQL: `SELECT coalesce(starred, 0) as starred, starred_at, coalesce(play_count, 0) as play_count, play_date, coalesce(rating, 0) as rating, f.*, playlist_tracks.* FROM playlist_tracks LEFT JOIN annotation on (annotation.item_id = media_file_id AND annotation.item_type = 'media_file' AND annotation.user_id = '6f9786e8-3b84-4d9d-865e-1f8dda2682a5') JOIN media_file f on f.id = media_file_id WHERE playlist_id = {:p0} ORDER BY playlist_tracks.id`  args="map[p0:30b3d166-0c26-42b7-bbe2-681fbbda04d2]" elapsedTime=7.2ms requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=31
TRAC[0015] SQL: `SELECT count(*) as exist FROM playlist WHERE (id = {:p0} AND (1=1))`  args="map[p0:30b3d166-0c26-42b7-bbe2-681fbbda04d2]" elapsedTime="155.875µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=1
TRAC[0015] SQL: `UPDATE playlist SET comment = {:p0}, duration = {:p1}, evaluated_at = {:p2}, id = {:p3}, name = {:p4}, owner_id = {:p5}, path = {:p6}, public = {:p7}, size = {:p8}, song_count = {:p9}, sync = {:p10}, updated_at = {:p11} WHERE id = {:p12}`  args="map[p0:Auto-imported from 'yussef.m3u' p1:7410.33 p10:true p11:2025-02-15T16:17:20.494073-05:00 p12:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p2:<nil> p3:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p4:yussef p5:6f9786e8-3b84-4d9d-865e-1f8dda2682a5 p6:/Users/deluan/Music/Picard/yussef.m3u p7:false p8:1070813888 p9:31]" elapsedTime="462.459µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=1
TRAC[0015] SQL: `DELETE FROM playlist_tracks WHERE playlist_id = {:p0}`  args="map[p0:30b3d166-0c26-42b7-bbe2-681fbbda04d2]" elapsedTime="92.208µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=31
TRAC[0015] SQL: `INSERT INTO playlist_tracks (playlist_id,media_file_id,id) VALUES ({:p0},{:p1},{:p2}),({:p3},{:p4},{:p5}),({:p6},{:p7},{:p8}),({:p9},{:p10},{:p11}),({:p12},{:p13},{:p14}),({:p15},{:p16},{:p17}),({:p18},{:p19},{:p20}),({:p21},{:p22},{:p23}),({:p24},{:p25},{:p26}),({:p27},{:p28},{:p29}),({:p30},{:p31},{:p32}),({:p33},{:p34},{:p35}),({:p36},{:p37},{:p38}),({:p39},{:p40},{:p41}),({:p42},{:p43},{:p44}),({:p45},{:p46},{:p47}),({:p48},{:p49},{:p50}),({:p51},{:p52},{:p53}),({:p54},{:p55},{:p56}),({:p57},{:p58},{:p59}),({:p60},{:p61},{:p62}),({:p63},{:p64},{:p65}),({:p66},{:p67},{:p68}),({:p69},{:p70},{:p71}),({:p72},{:p73},{:p74}),({:p75},{:p76},{:p77}),({:p78},{:p79},{:p80}),({:p81},{:p82},{:p83}),({:p84},{:p85},{:p86}),({:p87},{:p88},{:p89})`  args="map[p0:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p1:517cb6295429baa4123a97a217c973e1 p10:7b35b4acd3b2ead425765b92edd71013 p11:4 p12:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p13:0b7cf959a86e860d02066de75f6187c3 p14:5 p15:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p16:b8102798b50325ec4e040c49e4174538 p17:6 p18:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p19:7c9df4d9b053de14ae8ece57193ee035 p2:1 p20:7 p21:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p22:6f9a5149bdea3f8340ae306cf411d994 p23:8 p24:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p25:550472955d6c0b5280c068330fe6c294 p26:9 p27:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p28:053df360495b418fbde46693e22ff653 p29:10 p3:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p30:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p31:966ccc58ad50f2a50f35944f235d67f8 p32:11 p33:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p34:7fdc686997f95ee0580090a3c5ba37e5 p35:12 p36:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p37:11a225797f2990b04142c3c4dfc46abe p38:13 p39:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p4:0cec72db00eaeb2e6052b27c89bc025c p40:1aed50ec237d97cfdd53a219022ae4fe p41:14 p42:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p43:9c7cf72a7430ad6ecd5fe64339713b3c p44:15 p45:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p46:e177248c4ae82032f5d6a8c36f54ce63 p47:16 p48:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p49:7f8918dd5b39475b92a60a99de9351d9 p5:2 p50:17 p51:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p52:674d2382f722b161deba1bd33ab136da p53:18 p54:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p55:2bb62dd15368bfad501e779813e67428 p56:19 p57:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p58:5c2f5c7a1103ba15e6942fe4b5116f0b p59:20 p6:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p60:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p61:7649395d36b6d2a376c945ca6f9ea5fc p62:21 p63:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p64:5a081c2f89662321e799d9adf91a0a1d p65:22 p66:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p67:802d9d8829507c4522509a5f8aa209fb p68:23 p69:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p7:9f940731c4351ea65a1458d652b92082 p70:192366c25ae6a8946a1641f6c2be8a5a p71:24 p72:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p73:dc7bac3704729ea87ca4963272971f3d p74:25 p75:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p76:605030f56891f7ab211b2fe710f2e532 p77:26 p78:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p79:86333730b5c871161146aab89630c909 p8:3 p80:27 p81:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p82:59770d8f8c6b233e44591e600841b608 p83:28 p84:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p85:ac44fd741353a5e739dca182dec53404 p86:29 p87:30b3d166-0c26-42b7-bbe2-681fbbda04d2 p88:d36b1427daa1bbbba72aebfe6bb855f6 p89:30 p9:30b3d166-0c26-42b7-bbe2-681fbbda04d2]" elapsedTime="656.083µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=30
TRAC[0015] SQL: `SELECT coalesce(sum(duration), 0) as duration, coalesce(sum(size), 0) as size, count(*) as count FROM media_file JOIN playlist_tracks f on f.media_file_id = media_file.id WHERE playlist_id = {:p0}`  args="map[p0:30b3d166-0c26-42b7-bbe2-681fbbda04d2]" elapsedTime="287.583µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=1
TRAC[0015] SQL: `UPDATE playlist SET duration = {:p0}, size = {:p1}, song_count = {:p2}, updated_at = {:p3} WHERE id = {:p4}`  args="map[p0:7213.89 p1:1.0340683e+09 p2:30 p3:2025-02-15 16:17:20.510207 -0500 EST m=+15.750381293 p4:30b3d166-0c26-42b7-bbe2-681fbbda04d2]" elapsedTime="136.125µs" requestId=Mac.lan/7TOEL9X6di-000002 rowsAffected=1
DEBU[0015] API: Successful response                      body="{\"subsonic-response\":{\"status\":\"ok\",\"version\":\"1.16.1\",\"type\":\"navidrome\",\"serverVersion\":\"dev\",\"openSubsonic\":true}}" endpoint=/rest/updatePlaylist requestId=Mac.lan/7TOEL9X6di-000002 status=OK
DEBU[0015] HTTP: POST http://localhost:4533/rest/updatePlaylist?u=admin&p=[REDACTED]&f=json&v=1.8.0&c=NavidromeUI  elapsedTime=56.2ms header="{\"Accept\":[\"*/*\"],\"Accept-Encoding\":[\"br, deflate, gzip, x-gzip\"],\"Content-Length\":[\"67\"],\"Content-Type\":[\"application/x-www-form-urlencoded\"],\"Cookie\":[\"nd-player-61646d696e=aba5499a-0748-49cf-9bae-b49fc941587d\"],\"User-Agent\":[\"IntelliJ HTTP Client/IntelliJ IDEA 2024.3.2.2\"]}" httpStatus=200 remoteAddr="127.0.0.1:51465" requestId=Mac.lan/7TOEL9X6di-000002 responseSize=117

It starts with API: New request /rest/updatePlaylist and ends with HTTP: POST http://localhost:4533/rest/updatePlaylist

EDIT: What we are looking for is the HTTP: POST http://localhost:4533/rest/updatePlaylist line, that shows the request headers

vurt · February 15, 2025, 9:35pm

Hi @deluan , I restarted Navidrome, this is a fresh log. I can’t seem to find the line you’re referring to. I wonder if it’s my Navidrome config?

Navidrome config:

PlaylistsPath='_Playlists:_Playlists/**'
AutoImportPlaylists=true
RecentlyAddedByModTime=true
EnableTranscodingConfig=true
DefaultTheme='Spotify-ish'
Scanner.GroupAlbumReleases=true
LogLevel = 'trace'

Navidrome log:

 _   _             _     _
| \ | |           (_)   | |
|  \| | __ ___   ___  __| |_ __ ___  _ __ ___   ___
| . ` |/ _` \ \ / / |/ _` | '__/ _ \| '_ ` _ \ / _ \
| |\  | (_| |\ V /| | (_| | | | (_) | | | | | |  __/
\_| \_/\__,_| \_/ |_|\__,_|_|  \___/|_| |_| |_|\___|
                          Version: 0.54.4 (73ccfbd8)

time="2025-02-15T21:31:55Z" level=info msg="goose: no migrations to run. current version: 20241024125533\n"
time="2025-02-15T21:31:55Z" level=info msg="Starting signaler"
time="2025-02-15T21:31:55Z" level=error msg="Agent not available. Check configuration" name=lastfm
time="2025-02-15T21:31:55Z" level=error msg="Agent not available. Check configuration" name=spotify
time="2025-02-15T21:31:55Z" level=info msg="Configuring Media Folder" name="Music Library" path=/music
time="2025-02-15T21:31:55Z" level=info msg="Found ffmpeg" path=/usr/bin/ffmpeg
time="2025-02-15T21:31:55Z" level=info msg="Creating Image cache" maxSize="200 MB" path=/data/cache/images
time="2025-02-15T21:31:55Z" level=info msg="Starting Insight Collector"
time="2025-02-15T21:31:55Z" level=info msg="Starting scheduler"
time="2025-02-15T21:31:55Z" level=warning msg="Periodic backup is DISABLED"
time="2025-02-15T21:31:55Z" level=error msg="Agent not available. Check configuration" name=lastfm
time="2025-02-15T21:31:55Z" level=error msg="Agent not available. Check configuration" name=spotify
time="2025-02-15T21:31:55Z" level=info msg="Scheduling periodic scan" schedule="@every 1m"
time="2025-02-15T21:31:55Z" level=info msg="Setting Session Timeout" value=24h
time="2025-02-15T21:31:55Z" level=info msg="Login rate limit set" requestLimit=5 windowLength=2
time="2025-02-15T21:31:55Z" level=info msg="Spotify integration is not enabled: missing ID/Secret"
time="2025-02-15T21:31:55Z" level=info msg="Mounting Native API routes" path=/api
time="2025-02-15T21:31:55Z" level=error msg="Agent not available. Check configuration" name=lastfm
time="2025-02-15T21:31:55Z" level=error msg="Agent not available. Check configuration" name=spotify
time="2025-02-15T21:31:55Z" level=info msg="Creating Transcoding cache" maxSize="100 MB" path=/data/cache/transcoding
time="2025-02-15T21:31:55Z" level=info msg="Mounting Subsonic API routes" path=/rest
time="2025-02-15T21:31:55Z" level=error msg="Agent not available. Check configuration" name=lastfm
time="2025-02-15T21:31:55Z" level=error msg="Agent not available. Check configuration" name=spotify
time="2025-02-15T21:31:55Z" level=info msg="Mounting Public Endpoints routes" path=/share
time="2025-02-15T21:31:55Z" level=info msg="Mounting LastFM Auth routes" path=/api/lastfm
time="2025-02-15T21:31:55Z" level=info msg="Mounting ListenBrainz Auth routes" path=/api/listenbrainz
time="2025-02-15T21:31:55Z" level=info msg="Mounting Background images routes" path=/backgrounds
time="2025-02-15T21:31:55Z" level=info msg="Mounting WebUI routes" path=/app
time="2025-02-15T21:31:55Z" level=info msg="Creating backgrounds cache" maxSize="100 MB" path=/data/cache/backgrounds
time="2025-02-15T21:31:55Z" level=info msg="Finished initializing cache" cache=Transcoding elapsedTime=9.1ms maxSize=100MB
time="2025-02-15T21:31:55Z" level=info msg="Finished initializing cache" cache=backgrounds elapsedTime=11.3ms maxSize=100MB
time="2025-02-15T21:31:55Z" level=info msg="----> Navidrome server is ready!" address="0.0.0.0:4533" startupTime=160.4ms tlsEnabled=false
time="2025-02-15T21:31:57Z" level=info msg="Configuring Media Folder" name="Music Library" path=/music
time="2025-02-15T21:32:03Z" level=info msg="Finished initializing cache" cache=Image elapsedTime=8.38s maxSize=200MB
time="2025-02-15T21:32:43Z" level=info msg="Now Playing" artist="Anja Schneider" player="Symfonium [Symfonium/Android]" requestId=02985631574e/uUOZ5TxDSq-000007 title="Club Room 354 with Anja Schneider" user=vurt
time="2025-02-15T21:32:44Z" level=info msg="Now Playing" artist="Anja Schneider" player="Symfonium [Symfonium/Android]" requestId=02985631574e/uUOZ5TxDSq-000008 title="Club Room 354 with Anja Schneider" user=vurt
time="2025-02-15T21:32:44Z" level=info msg="Now Playing" artist="Anja Schneider" player="Symfonium [Symfonium/Android]" requestId=02985631574e/uUOZ5TxDSq-000009 title="Club Room 354 with Anja Schneider" user=vurt
time="2025-02-15T21:32:45Z" level=info msg="Now Playing" artist="Anja Schneider" player="Symfonium [Symfonium/Android]" requestId=02985631574e/uUOZ5TxDSq-000010 title="Club Room 354 with Anja Schneider" user=vurt
time="2025-02-15T21:33:33Z" level=warning msg="API: Failed response" endpoint=/rest/updatePlaylist.view error=10 message="missing parameter: 'playlistId'" requestId=02985631574e/uUOZ5TxDSq-000019

deluan · February 15, 2025, 9:49pm

Doesn’t seem that Navidrome is loading this config file. The logs you posted here are not trace/debug logs. When trace/debug is active, the first line you should see after the banner is the config file path:

 _   _             _     _
| \ | |           (_)   | |
|  \| | __ ___   ___  __| |_ __ ___  _ __ ___   ___
| . ` |/ _` \ \ / / |/ _` | '__/ _ \| '_ ` _ \ / _ \
| |\  | (_| |\ V /| | (_| | | | (_) | | | | | |  __/
\_| \_/\__,_| \_/ |_|\__,_|_|  \___/|_| |_| |_|\___|
                                        Version: dev

Loaded configuration from '/home/deluan/development/navidrome/navidrome.toml': &conf.configOptions{
    ConfigFile:                      "/home/deluan/development/navidrome/navidrome.toml",
    Address:                         "0.0.0.0",
    Port:                            4533,
    UnixSocketPerm:                  "0660",
...

vurt · February 15, 2025, 10:05pm

Thank you for the clarification. This is odd, I looked at the docker compose and noticed in the template there is a setting for loglevel, even though I also have a navidrome.toml file.

I got a new log with the proper detail now. It’s too long to post the whole thing, but I searched and found this section:


time="2025-02-15T21:58:00Z" level=debug msg="API: New request /rest/updatePlaylist.view" client=Symfonium requestId=83a493bc950c/Lsil03q9UT-000007 username=vurt version=1.13.0
time="2025-02-15T21:58:00Z" level=trace msg="SQL: `SELECT * FROM user WHERE user_name = {:p0} COLLATE NOCASE`" args="map[p0:vurt]" elapsedTime="171.275µs" requestId=83a493bc950c/Lsil03q9UT-000007 rowsAffected=1
time="2025-02-15T21:58:00Z" level=trace msg="SQL: `SELECT player.*, user.user_name username FROM player JOIN user ON player.user_id = user.id WHERE (client = {:p0} AND user_agent = {:p1} AND user_id = {:p2})`" args="map[p0:Symfonium p1:Symfonium/Android p2:e7d2b8f5-f9e8-4612-a178-37c3b3a82465]" elapsedTime="132.525µs" requestId=83a493bc950c/Lsil03q9UT-000007 rowsAffected=1
time="2025-02-15T21:58:00Z" level=debug msg="Found matching player" client=Symfonium id=49609f78-1c61-42ce-ad26-dcf1b96d8f67 requestId=83a493bc950c/Lsil03q9UT-000007 type=Symfonium/Android username=vurt
time="2025-02-15T21:58:00Z" level=trace msg="SQL: `UPDATE player SET client = {:p0}, id = {:p1}, ip = {:p2}, last_seen = {:p3}, max_bit_rate = {:p4}, name = {:p5}, report_real_path = {:p6}, scrobble_enabled = {:p7}, transcoding_id = {:p8}, user_agent = {:p9}, user_id = {:p10} WHERE id = {:p11}`" args="map[p0:Symfonium p1:49609f78-1c61-42ce-ad26-dcf1b96d8f67 p10:e7d2b8f5-f9e8-4612-a178-37c3b3a82465 p11:49609f78-1c61-42ce-ad26-dcf1b96d8f67 p2: p3:2025-02-15T21:58:00.505022554Z p4:0 p5:Symfonium [Symfonium/Android] p6:false p7:true p8: p9:Symfonium/Android]" elapsedTime="779.533µs" requestId=83a493bc950c/Lsil03q9UT-000007 rowsAffected=1
time="2025-02-15T21:58:00Z" level=warning msg="API: Failed response" endpoint=/rest/updatePlaylist.view error=10 message="missing parameter: 'playlistId'" requestId=83a493bc950c/Lsil03q9UT-000007
time="2025-02-15T21:58:00Z" level=debug msg="HTTP: GET http://xxxxxt/rest/updatePlaylist.view?u=vurt&t=[REDACTED]&s=[REDACTED]&v=1.13.0&c=Symfonium&f=json" elapsedTime=2.5ms header="{\"Accept-Encoding\":[\"gzip\"],\"Connection\":[\"close\"],\"User-Agent\":[\"Symfonium/11.6.0 (Linux;Android 15)\"],\"X-Forwarded-For\":[\"192.168.1.1\"],\"X-Forwarded-Host\":[\"xxx.xxxx.net\"],\"X-Forwarded-Method\":[\"GET\"],\"X-Forwarded-Port\":[\"443\"],\"X-Forwarded-Proto\":[\"https\"],\"X-Forwarded-Server\":[\"xxx.xxxx.net\"],\"X-Forwarded-Ssl\":[\"on\"],\"X-Forwarded-Uri\":[\"/rest/updatePlaylist.view?u=xxx&s=xxxx\\u0026v=1.13.0\\u0026c=Symfonium\\u0026f=json\"],\"X-Original-Method\":[\"GET\"],\"X-Original-Url\":[\"https://xxxx/rest/updatePlaylist.view?u=xxxxx&s=xxxx\\u0026v=1.13.0\\u0026c=Symfonium\\u0026f=json\"],\"X-Real-Ip\":[\"192.168.1.1\"]}" httpStatus=200 remoteAddr=192.168.1.1 requestId=83a493bc950c/Lsil03q9UT-000007 responseSize=199

Tolriq · February 16, 2025, 8:29am

Beware you have exposed your host and a login / password hash in those logs.

@deluan maybe you can redact the proxy data too?

?u=vurt\\u0026t=xxxx\\u0026s=xxx

Anyway @vurt those logs shows that the proxy remove the content-type header and seems to say the request was a get when it was a post.

Try to connect without the proxy to see that all works correctly then try to figure out how to fix the proxy configuration to work with Navidrome.

vurt · February 16, 2025, 2:35pm

Thank you very much @Tolriq , I’ll take a look at nginx.

(I don’t recognize which are the login/password hash!)