Unable to play 'Song' access denied about bonob HOT 22 OPEN

Is there any log from bonob/navidrome when this occurs?

from bonob.

Nothing that seems to allude to an error in either. Navidrome works outside the context of the Sonos integration. It's logs all seem related to scanning and finishing scanning my music directory. Thanks for looking into this with me.

{
    "message": {
        "level": "debug",
        "data": "<?xml version=\"1.0\" encoding=\"utf-8\"?><soap:Envelope xmlns:soap=\"http://schemas.xmlsoap.org/soap/envelope/\"  xmlns:tns=\"http://www.sonos.com/Services/1.1\"><soap:Body><getExtendedMetadataResponse xmlns=\"http://www.sonos.com/Services/1.1\"><getExtendedMetadataResult><mediaMetadata><itemType>track</itemType><id>track:f890af842bc1938804a73a4f6f615f99</id><mimeType>audio/mpeg</mimeType><title>Little Bit Of Inner Air</title><trackMetadata><album>Made In England</album><albumId>album:344ca27c20dc286135ff77fbb0494c72</albumId><albumArtist>Atomic Rooster</albumArtist><albumArtistId>artist:4cd6c3da277df8ea18b236624ec642aa</albumArtistId><albumArtURI>http://192.168.0.100:4534/art/bnb%3As%3Aart%3Af890af842bc1938804a73a4f6f615f99/size/180?bat=32b269e9c1af02e1bcee39d43eefdd85be332b0505186a9249a4d20b8e5547aa</albumArtURI><artist>Atomic Rooster</artist><artistId>artist:4cd6c3da277df8ea18b236624ec642aa</artistId><duration>159</duration><genre>Unknown</genre><genreId>VW5rbm93bg==</genreId><trackNumber>3</trackNumber></trackMetadata><dynamic><property><name>rating</name><value>100</value></property></dynamic></mediaMetadata></getExtendedMetadataResult></getExtendedMetadataResponse></soap:Body></soap:Envelope>"
    },
    "level": "debug",
    "service": "bonob",
    "timestamp": "2022-03-25 10:26:42"
}

from bonob.

Playing a track on a Sonos device results in many requests between Sonos and bonob.

When Sonos tries to stream a track it will hit a /stream end point in bonob. Are there any logs related to that?

from bonob.

Yes there are many logs related to streams. Is there any sensitive information in here I should obfuscate before I post it ?

from bonob.

I don't think so, however better to be safe than sorry. Email it to; simojenki at gmail

from bonob.

@simojenki thanks for this project!
any words on this specific problem? I have the same combo navidrome + bonob everything hosted externally with reverse proxy via cloudflare, everything works just fine except the requests to /stream/track/d418ad5ae77cdec697828984d26e60ed endpoint as example that return a 401 in nginx logs from bonob

all the other endpoints like /art/bnb%3As%3Aart%3A5aa52ebee25bc0a4c3f45bb8f286579b/size/600?bat=00de344f89ae1735535209042a7023c1c9fbf967ba49dd8d0588aeb1e5e2bd28 seem to work just fine directly from browser without any kind of auth

I have some fairly good knowledge on docker & networking if you'd like to give have an extra hand in debugging 👋

from bonob.

At this point I don't know if this is an issue with bonob or not. Auth for streams works using 2 request headers: bnbt & bnbk. Both of those are passed from the sonos device to bonob as headers.
Does your setup with the various reverse proxies (nginx & cloudflare) propagate all the request headers?
Do you see either of these messages in the bonob log?
"Missing bnbt header" or "Missing bnbk header"

from bonob.

thanks for reply @simojenki

the bnbt and bnbk headers seem to be present (they are marked as ***** in the logs) but i haven't got all the way through to enable deeper log on nginx's side and actually see their values.

i'll debug further by replicating the setup locally on internal network and then move forward to external hosting and see what goes wrong on this side and let you know. 🙂

from bonob.

Unfortunately as the code is currently written the presence of the log line with the **** doesn't necessarily mean that the header is present. here

However if you are not seeing the error Missing bnbt header then it would appear that the headers are being propagated correctly.

Does it always fail, or does it sometimes work?
If you restart bonob what happens?
What about if you re-authorise your account between sonos/bonob/navidrome?

from bonob.

something odd happen: now it's working 😶

basically, after multiple reauthorizations/container recreations/reverse proxy checks and whatnots I simply gave up and left it as it was then after the weekend I gave it another "play" in iOS app and just worked.
to answer your questions:

Does it always fail, or does it sometimes work?

always

If you restart bonob what happens?

no change in behavior

What about if you re-authorise your account between sonos/bonob/navidrome?

did it multiple times, with no immediate positive results

now I feel kinda down, I was hoping to find a real debugging solution to post it here for further help. the only thing that crosses my mind is that somehow sonos was not properly reaching the newly created subdomain and/or being an external source sonos somehow must validate it on their side 1st 🤷‍♂️

I still have some of the error logs from that time both from nginx reverse proxy and bonob's but I don't think it'll shed much more light now that's it's working as expected. I could give more in-depth details on my setup but basically navidrome + bonob reside on same internal docker network with bonob being externally accessible via a cloudflare http[with S] -> reverse proxy nginx http[no S]

update: I forgot to mention that over this period I checked and no automated updates were done to either navidrome/bonob/nginx/docker, the only unknown dependency in this case would be CloudFlare itself but I kinda doubt it might be the culprit

from bonob.

Strange that it just starting working, though better than staying broken!

AFAIK there is no validation required on the sonos end, as we are pushing the source directly into the device.

from bonob.

Hi - I have just installed bonob in a Docker Swarm environment, using Traefik for reverse proxying. I am running Navidrome and Bonob in separate stacks, where each is available internally on my LAN at <app>.domain.tld. I have setup bonob with the following env vars;

BNB_PORT=4534
BNB_SECRET=secret

BNB_URL=https://bonob.domain.tld
BNB_SUBSONIC_URL=https://navidrome.domain.tld

BNB_SONOS_SERVICE_ID=246
BNB_SONOS_SERVICE_NAME=Navidrome
BNB_SONOS_AUTO_REGISTER=true
BNB_SONOS_DEVICE_DISCOVERY=true
BNB_SONOS_SEED_HOST=<sonos_device_ip>

Everything is working fine, up until the point of actually playing a track. Then I get the access denied message in the Sonos app. I don't see any Missing bnbt header messages in the bonob logs and there is nothing in the Navidrome logs at all.

I see the following in my bonob logs;

bonob_app.1.9cpogeuysdcy@nuc03    | ::ffff:172.16.200.95 - - [11/May/2022:02:34:11 +0000] "GET /stream/track/a567aed1942f6edf671caf8fbb83bf7c HTTP/1.1" 401 - "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/101.0.4951.54 Safari/537.36"

If I try accessing that URL in my browser I see the same 401 message.

Any ideas?

I presume Traefik is messing with the headers but I am not sure how to determine that for certain, or how to fix it...

from bonob.

Here is the info logging in bonob just prior to the 401, showing the request headers etc;

{
  "message": "3a21ed0b-e199-4717-89cd-aa12ff2580d0 bnb<- GET /stream/track/6bf5204f236b91fa8953e7c38a4b6303?{}, headers={\"host\":\"bonob.domain.tld\",\"user-agent\":\"Linux UPnP/1.0 Sonos/68.2-28040 (ZPS13)\",\"accept\":\"*/*\",\"bnbk\":\"*****\",\"bnbt\":\"*****\",\"x-forwarded-for\":\"192.168.10.1\",\"x-forwarded-host\":\"bonob.domain.tld\",\"x-forwarded-port\":\"443\",\"x-forwarded-proto\":\"https\",\"x-forwarded-server\":\"74b90835b9cc\",\"x-real-ip\":\"192.168.10.1\",\"x-sonos-firmware\":\"68.2-28040\",\"x-sonos-id-hash\":\"Uq6lYZFW0oVvwiPnC3Le1MpN3+q4EA+ZFTj9sqfp10k=\",\"x-sonos-muse-api\":\"1.28.0\",\"x-sonos-swgen\":\"2\",\"accept-encoding\":\"gzip\"}",
  "level": "info",
  "service": "bonob",
  "timestamp": "2022-05-11 14:36:30"
}

from bonob.

Perhaps the ND auth token has expired, so is failing to work.

What happens if you reduce the bonob auth timeout by setting BNB_AUTH_TIMEOUT to say 1m?

This should cause bonob to refresh the auth token every 1m, you will probably see auth token refresh messages in the logs.

from bonob.

Thanks for the suggestion - I just tried it but no luck.

Is there something different about the /stream endpoint in terms of authentication? Because it seems the Sonos app/client has no trouble access /art for example.

from bonob.

Yes, stream uses headers for the auth tokens, art uses query string Params.

Where possible I've tried to use headers as they are less likely to appear in access logs.

I'll try and improve the logging and see if we can find a root cause

from bonob.

Sounds good - more than happy to help test!

from bonob.

@sumnerboy12 if you read above I have a sort of similar setup like yours except my services are exposed to internet vs internal lan like yours.

@simojenki this might sound odd but I managed to re-trigger the 401 response on /stream/ endpoint by switching the connection from bonob <=> navidrome back to internal docker network, the weirdest thing is that it didn't fail right away but more like after the auth token had expired and could be properly refreshed again (although I had not seen any logs related to this yet)
to give a bit more context:
bonob instance (the way sonos is accessing it via internet) is located at https://bonob.somedomain.com
both bonob and navidrome are located in same docker instance/network
on bonob config I have
- BNB_SUBSONIC_URL=https://navidrome.somedomain.com - working
- BNB_SUBSONIC_URL=http://navidrome:4533 - (internal docker network) not working

could this be from the fact that once sonos accesses bonob via https all the upstream traffic must be continued via https too? odd question but I'm asking it anyway 😅
I'm not always near my sonos setup to test it but I'll drop more info if I discover something new

from bonob.

That is interesting;

If you re-start bonob and navidrome does everything work for a while with each of those configurations? ie. does it work and then fail after a while, as this might indicate and issue with the token expiring.

I don't think that whether the traffic between bonob -> navidrome being http or https should matter to the sonos devices, as all requests to navidrome are proxied through bonob, so the sonos device doesn't really know about navidrome. That much said I only use my setup locally so I do not use https.

Does it work ever work when you use the internal docker network? ie. does it work when things first start up and then start failing?

BNB_SUBSONIC_URL=http://navidrome:4533

I'm in the middle of a re-factor of the navidrome integration, I'll try and get that merged in ASAP with some more detailed logging, perhaps that will help identify the root cause.

from bonob.

Any progress on that re-factor with detailed logging?

from bonob.

Sorry, a bit slammed at the moment with work & life, unfortunately open source isn't getting any love

from bonob.

No worries at all, I know the feeling!

from bonob.