Jump to content

Emby 4.8.1.0 + TrueNAS SCALE 22.12.3.2 + Primare NP5 + DLNA = no play


KneelBeforeZod

Recommended Posts

KneelBeforeZod

Emby 4.8.1.0 running as an app on TrueNAS SCALE

Emby app on Android (v8 IIRC) phone

TrueNAS SCALE 22.12.3.2

Primare NP5 network streamer`

FireFox 122.0.1 (64-bit) (but this is not browser related)

First let me say that in experimenting with this, I installed Jellyfin onto the TrueNAS box with the same default settings as  had installed Emby and it worked (only one of Jellyfin or Emeby running at the same time).

So the installation onto the TrueNAS box (as an app from the Truecharts catalogue) worked fine and the server started up ok.  Added a library and all well.  From the web client I can play music to my laptop.  Android app also works.

The Primare NP5 is a network streamer hardwired via an Ethernet cable to the TrueNAS box.  The Primare Prisma Android app detects the NP5 on the network and connect (but the app is rubbish and I do not wish to use it).  Emby detects the NP5 too.  "Enable DLNA Play To" is enabled I can select the NP5 as the target, yet no music is played and the player control does not appear at the bottom of the screen as it would normally do.  It's as if the "Play" contrrol had not been clicked.

When I tested with Jellyfin, I can select the NP5 as the target and streat a file to it.  The playbacl control bar appears at the bottom of the browser window and the Jellyfin also reflects the NP% playback state.  In addition, the Primare Prisma Android app reflects the playback state too, showing the file being played and the elapsed time etc.  But I don't want to use Jellyfin as I prefer Emby (although I know that JF is a fork of Emby).  So devices do seem to be correctly connected on the network and communicating.  Same FireFox 122.0.1 (64-bit) browser used in all cases and from a fresh restart with all data cleared.

The attached logs are from a completely fresh install of the Emby app on TrueNAS and the defaults accepted.

I have spent most of today fiddling around with Emby, Jellyfin and Plex (urgh), searching for answers online and even looking at the source code but with no success.  I'd be very grateful for your help in resolving this issue.  I filed it in the DLNA forum category although I do not know for sure that this is DLNA related.

embyserver.txt hardware_detection-63843186219.txt

Edited by KneelBeforeZod
Link to comment
Share on other sites

KneelBeforeZod

So I enabled debug logging and looked into this in more detail.

This always appears in the logs when trying to play a track on the NP5:

2024-02-12 13:04:15.587 Warn Server: AUTH-ERROR: 192.168.0.125 - Access token is invalid or expired.
2024-02-12 13:04:15.588 Error Server: Access token is invalid or expired.

It looks like Emby successfully establlishes a session with the NP5 and an API key is generated but later that same key is rejected.  It's not clear to me from the logs whether the key is rejected by Emby or the NP5.

I have attached the latest server debug log and the XML files retrieved from the NP5 when the session is established.

It's worth mentioning that although the log files suggest a successful session to the NP5 has been established, and I can select the NP5 as a target for playback, the NP5 is not shown in the "Devices" screen (other clients are such as the web browser and Android phone).

@LukeAre you able to help with this?

embyserver.txt np5-AVTransport.xml np5-ConnectionManager.xml np5-description.xml

Link to comment
Share on other sites

Hi, the access token in the log shows up in the api keys section, right? 

This seems to only happen with certain devices and in my experience so far, devices that are running very old dlna software. We currently don't have a device that this reproduces on and are actively searching for one.

But my theory is that I don't think the server is invaliding or rejecting the api key. I think it has something to do with the way the url is being encoded.

Link to comment
Share on other sites

KneelBeforeZod

Yes, the Emby Server DLNA API key 5c4470bd78514eb786c22cd87bbd768c is the same as in the logs and on these lines:

2024-02-12 13:04:15.475 Info Server: http/1.1 HEAD http://‌‍‍192.168.0.200‌:8096/audio/5/original.mp3?DeviceProfileId=f24c1c58d22d43b1abfdfed9a3b687b2&DeviceId=uuid:bcd8c2e2-c9a6-11ee-99f2-717963a9709d&MediaSourceId=5d59a0a15e3b2e4b35f1958ce478e1da&PlaySessionId=686b050854c94cc6aa78beb6428540e6&api_key=‌5c4470bd78514eb786c22cd87bbd768c‌. Accept=text/html,application/xhtml+xml,application/xml;q=0.9,audio/*;q=0.6, Host=‌‍‍192.168.0.200:8096‌, User-Agent=CyberGarage-HTTP/1.0
2024-02-12 13:04:15.516 Info Server: http/1.1 Response 200 to ‌‍‍192.168.0.125‌. Time: 40ms. HEAD http://‌‍‍192.168.0.200‌:8096/audio/5/original.mp3?DeviceProfileId=f24c1c58d22d43b1abfdfed9a3b687b2&DeviceId=uuid:bcd8c2e2-c9a6-11ee-99f2-717963a9709d&MediaSourceId=5d59a0a15e3b2e4b35f1958ce478e1da&PlaySessionId=686b050854c94cc6aa78beb6428540e6&api_key=‌5c4470bd78514eb786c22cd87bbd768c‌
2024-02-12 13:04:15.587 Info Server: http/1.1 GET http://‌‍‍192.168.0.200‌:8096/audio/5/original.mp3?DeviceProfileId=f24c1c58d22d43b1abfdfed9a3b687b2&DeviceId=uuid:bcd8c2e2-c9a6-11ee-99f2-717963a9709d&MediaSourceId=5d59a0a15e3b2e4b35f1958ce478e1da&PlaySessionId=686b050854c94cc6aa78beb6428540e6&api_key=‌5c4470bd78514eb786c22cd87bbd768c‌. Connection=keep-alive, Host=‌‍‍192.168.0.200:8096‌, User-Agent=stagefright/1.2 (Linux;Android, Accept-Encoding=gzip,deflate
2024-02-12 13:04:15.587 Warn Server: AUTH-ERROR: 192.168.0.125 - Access token is invalid or expired.
2024-02-12 13:04:15.588 Error Server: Access token is invalid or expired.
2024-02-12 13:04:15.589 Info Server: http/1.1 Response 401 to ‌‍‍192.168.0.125‌. Time: 4ms. GET http://‌‍‍192.168.0.200‌:8096/audio/5/original.mp3?DeviceProfileId=f24c1c58d22d43b1abfdfed9a3b687b2&DeviceId=uuid:bcd8c2e2-c9a6-11ee-99f2-717963a9709d&MediaSourceId=5d59a0a15e3b2e4b35f1958ce478e1da&PlaySessionId=686b050854c94cc6aa78beb6428540e6&api_key=‌5c4470bd78514eb786c22cd87bbd768c‌

image.png.9e697e5d6f18e03f57c649cedce9400f.png

Link to comment
Share on other sites

Ok I think I will need to update the logging to be more specific about the access token that was checked. I bet it is either empty or has something else tacked onto it.

Link to comment
Share on other sites

KneelBeforeZod

Thanks Luke.

I can provide Wireshark logs if that would help.  I did have a dig around with Wireshark but didn't find it useful (but that's more to do with my lack of expertise with that software).

Interesting that Jellyfin does not have this issue.  There doesn't seem to be a verbose logging option so I can't capture anything for comparison there, but perhaps the Wireshark capture would be a useful comparison.

Edited by KneelBeforeZod
Link to comment
Share on other sites

it's our old code from a long time ago when those dlna api's did not have any authentication on them.

Link to comment
Share on other sites

6 hours ago, KneelBeforeZod said:

I did have a dig around with Wireshark but didn't find it useful (but that's more to do with my lack of expertise with that software).

 

Were you able to locate this request from player to server in the wireshark logs?

2024-02-12 13:04:15.587 Info Server: http/1.1 GET http://‌‍‍192.168.0.200‌:8096/audio/5/original.mp3?DeviceProfileId=f24c1c58d22d43b1abfdfed9a3b687b2&DeviceId=uuid:bcd8c2e2-c9a6-11ee-99f2-717963a9709d&MediaSourceId=5d59a0a15e3b2e4b35f1958ce478e1da&PlaySessionId=686b050854c94cc6aa78beb6428540e6&api_key=‌5c4470bd78514eb786c22cd87bbd768c‌. Connection=keep-alive, Host=‌‍‍192.168.0.200:8096‌, User-Agent=stagefright/1.2 (Linux;Android, Accept-Encoding=gzip,deflate

 

Link to comment
Share on other sites

KneelBeforeZod

No I wasn't, but that might be a lack of expertise with Wireshark.  I added "ip.addr == 192.168.0.200" as a filter, selected the NP5 as the DLNA target and hit the play button for a test track Emby (web client).  This was all I saw after capturing packets for a few seconds:

No.    Time    Source    Destination    Protocol    Length    Info
35    2024-02-13 08:31:20.714744    192.168.0.50    192.168.0.200    TLSv1.2    133    Application Data
36    2024-02-13 08:31:20.726119    192.168.0.200    192.168.0.50    TLSv1.2    128    Application Data
37    2024-02-13 08:31:20.726186    192.168.0.50    192.168.0.200    TCP    66    64078 → 443 [ACK] Seq=68 Ack=63 Win=2047 Len=0 TSval=2322010559 TSecr=2790627383
38    2024-02-13 08:31:21.584496    192.168.0.50    192.168.0.200    HTTP    824    POST /emby/Sessions/7f33799a4daa89c0c2e98e85ed06326f/Playing?ItemIds=5&PlayCommand=PlayNow&X-Emby-Client=Emby+Web&X-Emby-Device-Name=Firefox+macOS&X-Emby-Device-Id=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTAuMTU7IHJ2OjEyMi4wKSBHZWNrby8yMDEwMDEwMSBGaXJlZm94LzEyMi4wfDE3MDc2NzEzNzM2MDA1&X-Emby-Client-Version=4.8.1.0&X-Emby-Token=d7b4f9b1041c457994356616b4a2e9b4&X-Emby-Language=en-gb HTTP/1.1
39    2024-02-13 08:31:21.629341    192.168.0.200    192.168.0.50    TCP    66    8096 → 64223 [ACK] Seq=1 Ack=759 Win=501 Len=0 TSval=2790628288 TSecr=955075932
40    2024-02-13 08:31:22.025683    192.168.0.200    192.168.0.50    HTTP    1018    HTTP/1.1 204 No Content
41    2024-02-13 08:31:22.025805    192.168.0.50    192.168.0.200    TCP    66    64223 → 8096 [ACK] Seq=759 Ack=953 Win=2033 Len=0 TSval=955076371 TSecr=2790628659
44    2024-02-13 08:31:23.205532    192.168.0.50    192.168.0.200    TCP    54    64224 → 8096 [ACK] Seq=1 Ack=1 Win=2048 Len=0
48    2024-02-13 08:31:23.216498    192.168.0.200    192.168.0.50    TCP    66    [TCP ACKed unseen segment] 8096 → 64224 [ACK] Seq=1 Ack=2 Win=501 Len=0 TSval=2790629873 TSecr=1884196675
51    2024-02-13 08:31:23.316608    192.168.0.50    192.168.0.200    TCP    54    64221 → 8096 [ACK] Seq=1 Ack=1 Win=2048 Len=0
52    2024-02-13 08:31:23.318390    192.168.0.200    192.168.0.50    TCP    66    [TCP ACKed unseen segment] 8096 → 64221 [ACK] Seq=1 Ack=2 Win=501 Len=0 TSval=2790629977 TSecr=2096720768
73    2024-02-13 08:31:27.198630    192.168.0.50    192.168.0.200    TLSv1.2    133    Application Data
74    2024-02-13 08:31:27.209170    192.168.0.200    192.168.0.50    TLSv1.2    129    Application Data
75    2024-02-13 08:31:27.209311    192.168.0.50    192.168.0.200    TCP    66    64078 → 443 [ACK] Seq=135 Ack=126 Win=2047 Len=0 TSval=2322017015 TSecr=2790633866

 

Link to comment
Share on other sites

KneelBeforeZod

I'll do 15 seconds with the filter set to "ip.addr == 192.168.0.200 or ip.addr == 192.168.0.125".

Edited by KneelBeforeZod
Link to comment
Share on other sites

KneelBeforeZod

15 seconds with filter "ip.addr == 192.168.0.200 or ip.addr == 192.168.0.125":

No.	Time	Source	Destination	Protocol	Length	Info
11	2024-02-13 08:49:22.889346	192.168.0.50	192.168.0.125	TCP	176	64072 → 8009 [PSH, ACK] Seq=1 Ack=1 Win=2048 Len=110 TSval=40786254 TSecr=7104248 [TCP segment of a reassembled PDU]
12	2024-02-13 08:49:22.899375	192.168.0.125	192.168.0.50	TCP	176	8009 → 64072 [PSH, ACK] Seq=1 Ack=111 Win=351 Len=110 TSval=7104749 TSecr=40786254 [TCP segment of a reassembled PDU]
13	2024-02-13 08:49:22.899507	192.168.0.50	192.168.0.125	TCP	66	64072 → 8009 [ACK] Seq=111 Ack=111 Win=2046 Len=0 TSval=40786264 TSecr=7104749
21	2024-02-13 08:49:24.991903	192.168.0.50	192.168.0.200	TCP	78	64383 → 8096 [SYN] Seq=0 Win=65535 Len=0 MSS=1460 WS=64 TSval=250622665 TSecr=0 SACK_PERM
22	2024-02-13 08:49:24.994451	192.168.0.200	192.168.0.50	TCP	74	8096 → 64383 [SYN, ACK] Seq=0 Ack=1 Win=65160 Len=0 MSS=1460 SACK_PERM TSval=2791711661 TSecr=250622665 WS=128
23	2024-02-13 08:49:24.994511	192.168.0.50	192.168.0.200	TCP	66	64383 → 8096 [ACK] Seq=1 Ack=1 Win=131712 Len=0 TSval=250622667 TSecr=2791711661
24	2024-02-13 08:49:24.994756	192.168.0.50	192.168.0.200	HTTP	824	POST /emby/Sessions/7f33799a4daa89c0c2e98e85ed06326f/Playing?ItemIds=5&PlayCommand=PlayNow&X-Emby-Client=Emby+Web&X-Emby-Device-Name=Firefox+macOS&X-Emby-Device-Id=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTAuMTU7IHJ2OjEyMi4wKSBHZWNrby8yMDEwMDEwMSBGaXJlZm94LzEyMi4wfDE3MDc2NzEzNzM2MDA1&X-Emby-Client-Version=4.8.1.0&X-Emby-Token=d7b4f9b1041c457994356616b4a2e9b4&X-Emby-Language=en-gb HTTP/1.1 
25	2024-02-13 08:49:24.998266	192.168.0.200	192.168.0.50	TCP	66	8096 → 64383 [ACK] Seq=1 Ack=759 Win=64512 Len=0 TSval=2791711664 TSecr=250622667
26	2024-02-13 08:49:25.087868	192.168.0.200	192.168.0.50	HTTP	1018	HTTP/1.1 204 No Content 
27	2024-02-13 08:49:25.087973	192.168.0.50	192.168.0.200	TCP	66	64383 → 8096 [ACK] Seq=759 Ack=953 Win=130816 Len=0 TSval=250622759 TSecr=2791711751
39	2024-02-13 08:49:27.905180	192.168.0.50	192.168.0.125	TCP	176	64072 → 8009 [PSH, ACK] Seq=111 Ack=111 Win=2048 Len=110 TSval=40791248 TSecr=7104749 [TCP segment of a reassembled PDU]
40	2024-02-13 08:49:27.920380	192.168.0.125	192.168.0.50	TCP	176	8009 → 64072 [PSH, ACK] Seq=111 Ack=221 Win=351 Len=110 TSval=7105251 TSecr=40791248 [TCP segment of a reassembled PDU]
41	2024-02-13 08:49:27.920529	192.168.0.50	192.168.0.125	TCP	66	64072 → 8009 [ACK] Seq=221 Ack=221 Win=2046 Len=0 TSval=40791263 TSecr=7105251
57	2024-02-13 08:49:32.922510	192.168.0.50	192.168.0.125	TCP	176	64072 → 8009 [PSH, ACK] Seq=221 Ack=221 Win=2048 Len=110 TSval=40796252 TSecr=7105251 [TCP segment of a reassembled PDU]
58	2024-02-13 08:49:32.932749	192.168.0.125	192.168.0.50	TCP	176	8009 → 64072 [PSH, ACK] Seq=221 Ack=331 Win=351 Len=110 TSval=7105752 TSecr=40796252 [TCP segment of a reassembled PDU]
59	2024-02-13 08:49:32.932861	192.168.0.50	192.168.0.125	TCP	66	64072 → 8009 [ACK] Seq=331 Ack=331 Win=2046 Len=0 TSval=40796262 TSecr=7105752
65	2024-02-13 08:49:33.429160	192.168.0.125	224.0.0.251	MDNS	413	Standard query response 0x0000 PTR Primare-NP5-c3790e1fad7bbb5facce46a806c6f6b2._googlecast._tcp.local TXT, cache flush SRV, cache flush 0 0 8009 c3790e1f-ad7b-bb5f-acce-46a806c6f6b2.local A, cache flush 192.168.0.125
68	2024-02-13 08:49:35.179910	192.168.0.50	192.168.0.200	TCP	54	[TCP Keep-Alive] 64383 → 8096 [ACK] Seq=758 Ack=953 Win=131072 Len=0
69	2024-02-13 08:49:35.189196	192.168.0.200	192.168.0.50	TCP	66	[TCP Keep-Alive ACK] 8096 → 64383 [ACK] Seq=953 Ack=759 Win=64512 Len=0 TSval=2791721856 TSecr=250622759
79	2024-02-13 08:49:37.933746	192.168.0.50	192.168.0.125	TCP	176	64072 → 8009 [PSH, ACK] Seq=331 Ack=331 Win=2048 Len=110 TSval=40801248 TSecr=7105752 [TCP segment of a reassembled PDU]
80	2024-02-13 08:49:37.945833	192.168.0.125	192.168.0.50	TCP	176	8009 → 64072 [PSH, ACK] Seq=331 Ack=441 Win=351 Len=110 TSval=7106254 TSecr=40801248 [TCP segment of a reassembled PDU]
81	2024-02-13 08:49:37.945903	192.168.0.50	192.168.0.125	TCP	66	64072 → 8009 [ACK] Seq=441 Ack=441 Win=2046 Len=0 TSval=40801260 TSecr=7106254
82	2024-02-13 08:49:38.465708	192.168.0.50	192.168.0.200	TLSv1.2	131	Application Data
83	2024-02-13 08:49:38.467010	192.168.0.50	192.168.0.200	TLSv1.2	132	Application Data
84	2024-02-13 08:49:38.467764	192.168.0.50	192.168.0.200	TLSv1.2	130	Application Data
85	2024-02-13 08:49:38.468517	192.168.0.50	192.168.0.200	TLSv1.2	133	Application Data
86	2024-02-13 08:49:38.476235	192.168.0.200	192.168.0.50	TCP	66	443 → 64078 [ACK] Seq=1 Ack=263 Win=501 Len=0 TSval=2791725142 TSecr=2323102343
87	2024-02-13 08:49:38.478967	192.168.0.200	192.168.0.50	TLSv1.2	132	Application Data
88	2024-02-13 08:49:38.478978	192.168.0.200	192.168.0.50	TLSv1.2	131	Application Data
89	2024-02-13 08:49:38.478981	192.168.0.200	192.168.0.50	TLSv1.2	131	Application Data
90	2024-02-13 08:49:38.478984	192.168.0.200	192.168.0.50	TLSv1.2	131	Application Data
91	2024-02-13 08:49:38.479142	192.168.0.50	192.168.0.200	TCP	66	64078 → 443 [ACK] Seq=263 Ack=197 Win=2044 Len=0 TSval=2323102354 TSecr=2791725145
92	2024-02-13 08:49:38.479143	192.168.0.50	192.168.0.200	TCP	66	64078 → 443 [ACK] Seq=263 Ack=262 Win=2043 Len=0 TSval=2323102354 TSecr=2791725145
160	2024-02-13 08:49:42.948848	192.168.0.50	192.168.0.125	TCP	176	64072 → 8009 [PSH, ACK] Seq=441 Ack=441 Win=2048 Len=110 TSval=40806237 TSecr=7106254 [TCP segment of a reassembled PDU]
161	2024-02-13 08:49:42.952126	192.168.0.125	192.168.0.50	TCP	176	8009 → 64072 [PSH, ACK] Seq=441 Ack=551 Win=351 Len=110 TSval=7106754 TSecr=40806237 [TCP segment of a reassembled PDU]
162	2024-02-13 08:49:42.952223	192.168.0.50	192.168.0.125	TCP	66	64072 → 8009 [ACK] Seq=551 Ack=551 Win=2046 Len=0 TSval=40806240 TSecr=7106754
174	2024-02-13 08:49:45.281838	192.168.0.50	192.168.0.200	TCP	54	[TCP Keep-Alive] 64383 → 8096 [ACK] Seq=758 Ack=953 Win=131072 Len=0
175	2024-02-13 08:49:45.291462	192.168.0.200	192.168.0.50	TCP	66	[TCP Keep-Alive ACK] 8096 → 64383 [ACK] Seq=953 Ack=759 Win=64512 Len=0 TSval=2791731958 TSecr=250622759
182	2024-02-13 08:49:47.956203	192.168.0.50	192.168.0.125	TCP	176	64072 → 8009 [PSH, ACK] Seq=551 Ack=551 Win=2048 Len=110 TSval=40811225 TSecr=7106754 [TCP segment of a reassembled PDU]
183	2024-02-13 08:49:47.972033	192.168.0.125	192.168.0.50	TCP	176	8009 → 64072 [PSH, ACK] Seq=551 Ack=661 Win=351 Len=110 TSval=7107256 TSecr=40811225 [TCP segment of a reassembled PDU]
184	2024-02-13 08:49:47.972146	192.168.0.50	192.168.0.125	TCP	66	64072 → 8009 [ACK] Seq=661 Ack=661 Win=2046 Len=0 TSval=40811240 TSecr=7107256

 

  • Thanks 1
Link to comment
Share on other sites

Hi, did you say that you just recently setup Emby? In other words, if you're still experimenting are you fine with installing the beta server to help narrow this down? I added a logging statement to the 4.9 beta channel that will tell us what access token was rejected. Thanks.

Link to comment
Share on other sites

KneelBeforeZod

Hello Luke.  Yes, I recently set-up Emby and I will install 4.9 beta, enable all the logging and report back.  Is the beta available on the TrueNAS SCALE catalogue?

I kinda gave up on the NP5 for the moment and borrowed a Pro-Jekt Stream Box S2 Ultra and and Emby connects to that just fine... until the connection is lost, but I guess that's a different topic.  If I can get the NP5 working though then I'll stick with that.

Edited by KneelBeforeZod
Link to comment
Share on other sites

KneelBeforeZod

Forget TrueNAS SCALE - I can install the beta on macOS and test it from there.  2019 Intel MacBook Pro.

I did install Emby on macOS to see if this issue persisted, and it it did so I know I can reproduce the problem with a beta release.

Can't see a beta channel for macOS though - only WIndows.

Edited by KneelBeforeZod
Link to comment
Share on other sites

OK, I still need more logging, so what I've done is I've replaced the macOS 4.9.0.5 builds with an updated version that will print more the log for me.

Can you please download it again from our website, install over the top of your current version, repeat the test a provide a new log? Thanks.

  • Thanks 1
Link to comment
Share on other sites

OK, thanks. Going to have to do this one more time. 

I've replaced the macOS 4.9.0.5 builds with an updated version that will print more the log for me.

Can you please download it again from our website, install over the top of your current version, repeat the test a provide a new log? Thanks.

  • Thanks 1
Link to comment
Share on other sites

KneelBeforeZod

Hello Luke.  Thank you for your continuing support with this issue.  I am happy to do this as many times as necessary in order to get an answer to the problem.

New log attached.

I had already eraased Emby from my Mac (plus its config directory) so did a clean install.

embyserver.txt

Link to comment
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
×
×
  • Create New...