Sha: 39856a004855953347f7427a1ed8b1aa16c996b4 breaks Windows Phone 7.5 streaming

[niko]

Sha: 39856a004855953347f7427a1ed8b1aa16c996b4 breaks Windows Phone streaming. Affected is our own native app (which is not developed in house so it's difficult to debug), the native app of radio.de and our website (http://laut.fm) which is using a HTML5 audio tag.

All clients produce the same pattern in the Icecast logfiles: Two short listens are logged, sometimes overlapping, sometimes adjacent (at least it seems so). The user agent is the same for all clients.

[2013-10-29  14:52:47] DBUG connection/_handle_get_request start with /ende
[2013-10-29  14:52:47] INFO source/source_add_listener max on /ende is -1 (cur 0)
[2013-10-29  14:52:47] DBUG source/listener_change_worker moving listener from 0x1f800b0 to 0x1f7fe70
[2013-10-29  14:52:47] DBUG client/worker_add_pending_clients Added 1 pending clients to 0x1f7fe70
[2013-10-29  14:52:47] DBUG client/worker 0x1f800b0 now has 0 clients
[2013-10-29  14:52:47] DBUG source/locate_start_on_queue Joining queue on /ende (568843, 503641)
[2013-10-29  14:52:47] DBUG client/worker 0x1f7fe70 now has 2 clients

==> /tmp/logs/icecast-access.log <==
217.24.207.26 - - [29/Oct/2013:14:52:47 +0100] "GET /ende HTTP/1.1" 200 17520 "-" "NSPlayer/07.00.0000.0000 WMFSDK/07.00.0000.0000" 0

==> /tmp/logs/icecast-error.log <==
[2013-10-29  14:52:47] INFO source/source_read listener count on /ende now 1
[2013-10-29  14:52:47] DBUG client/worker_add_pending_clients Added 1 pending clients to 0x1f800b0
[2013-10-29  14:52:47] DBUG client/worker 0x1f800b0 now has 1 clients
[2013-10-29  14:52:47] DBUG connection/_handle_get_request start with /ende
[2013-10-29  14:52:47] INFO source/source_add_listener max on /ende is -1 (cur 1)
[2013-10-29  14:52:47] DBUG source/listener_change_worker moving listener from 0x1f800b0 to 0x1f7fe70
[2013-10-29  14:52:47] DBUG client/worker_add_pending_clients Added 1 pending clients to 0x1f7fe70
[2013-10-29  14:52:47] DBUG client/worker 0x1f800b0 now has 0 clients
[2013-10-29  14:52:47] DBUG source/locate_start_on_queue Joining queue on /ende (568843, 503641)
[2013-10-29  14:52:47] DBUG client/worker 0x1f7fe70 now has 3 clients
[2013-10-29  14:52:47] DBUG client/client_send_bytes Client connection died
[2013-10-29  14:52:47] INFO source/source_read listener count on /ende now 2
[2013-10-29  14:52:47] DBUG client/worker 0x1f7fe70 now has 2 clients
[2013-10-29  14:52:48] INFO source/source_read listener count on /ende now 1

==> /tmp/logs/icecast-access.log <==
217.24.207.26 - - [29/Oct/2013:14:52:49 +0100] "GET /ende HTTP/1.1" 200 81502 "-" "NSPlayer/07.00.0000.0000 WMFSDK/07.00.0000.0000" 2

==> /tmp/logs/icecast-error.log <==
[2013-10-29  14:52:49] DBUG client/client_send_bytes Client connection died
[2013-10-29  14:52:49] DBUG client/worker 0x1f7fe70 now has 1 clients
[2013-10-29  14:52:49] INFO source/source_read listener count on /ende now 0
[2013-10-29  14:52:50] DBUG client/find_least_busy_handler handler 0x1f800b0 has 0 clients
[2013-10-29  14:52:50] DBUG client/find_least_busy_handler handler 0x1f7fe70 has 1 clients
[2013-10-29  14:52:50] DBUG client/find_least_busy_handler handler 0x1f7fc30 has 0 clients
[2013-10-29  14:52:50] DBUG client/find_least_busy_handler handler 0x1f81070 has 0 clients
[2013-10-29  14:52:50] DBUG client/find_least_busy_handler handler 0x1f758e0 has 0 clients
[2013-10-29  14:52:52] DBUG connection/wait_for_serversock signalfd received a termination
[2013-10-29  14:52:52] INFO connection/connection_thread connection thread finished
[2013-10-29  14:52:52] INFO slave/relay_read fallback on /ende not attempted
[2013-10-29  14:52:52] INFO source/source_shutdown Source "/ende" exiting

Tried on Nokia Lumia 800 w/ Windows Phone 7.5.

Niko.

[niko]

We have a user report about a Nokia Lumia 925 with the very same issue. I'll post the OS version as soon as I know it.

[karlheyes]

If you think it's the ICY response then you could try

http://..../mountpoint?_hdr=0

if that works then it handles HTTP but not ICY, which would be a pain as windows media player uses a similar header in which case you would need to collect them to see what works and what does not.

At the moment, for those UA that contain those 2 strings, _hdr=1 is assumed

karl.

[niko]

I'm not sure if I get this… the UA should determine the response format, right? In my - probably naiv - attempts to reproduce this using curl I didn't get different responses at all:

curl -isA 'WMFSDK' http://stream1.laut.fm/ende | head
ICY 200 OK
Content-Type: audio/mpeg
icy-description:Just some tinkering
icy-genre:Jazz,Rap,Soul,Funk
icy-name:laut.fm/ende
icy-pub:1
icy-url:laut.fm/ende
Server: Icecast 2.3.3-kh9
Cache-Control: no-cache
Pragma: no-cache

curl -isA 'just some other client' http://stream1.laut.fm/ende | head
HTTP/1.0 200 OK
Content-Type: audio/mpeg
icy-description: Just some tinkering
icy-genre: Jazz,Rap,Soul,Funk
icy-name: laut.fm/ende
icy-pub: 1
icy-url: laut.fm/ende
Server: Icecast 2.3.3-kh9
Cache-Control: no-cache
Pragma: no-cache

What am I doing wrong!?

Niko.

[karlheyes]

Firstly, check if windows phone works against say a shoutcast server as that should return ICY also. use wireshark or tcpdump to get hold of the network packets eg tcpdump -w capture -s 0 host . You don't need to be connected for long as we just need to see what a working connection does and why the current connection fails.

karl.

[niko]

Oops, my bad. Completely overlooked the first response line.

It's HTTP/1.0 200 OK up to and including Sha: 9a21ee1bb02c3bb3fda95194dede15f34d8f1634 and ICY 200 OK for Sha: d364a6e02b84313ea8e7eef599484aa6d41e7576 and later.

It seems like we have to collect the exact user agents for the different WMFSDK version. I'll collect UAs from our logs. Together with some duration statistics it should give us a pretty good idea about which UA is served best with wich protocol.

[niko]

Not so easy. Even when grepping just for the UA of the Lumia 800 there seem to be clients which actually work. I'd consider every stream over 3 seconds as "working":

$ grep 'NSPlayer/07.00.0000.0000' /export/logs/icecast-access.log /export/logs/icecast-access.log.2013102* | awk '{print $14"s"}' | sort -n | uniq -c
   1954 0s
   2846 1s
    952 2s
    350 3s
    158 4s
    104 5s
     60 6s
     55 7s
     28 8s
     34 9s
     26 10s
     23 11s
     30 12s
     21 13s
     12 14s
     12 15s
      9 16s
      7 17s
      3 18s
      7 19s
      6 20s
      6 21s
      8 22s
      2 23s
      6 24s
      7 25s
      3 26s
      3 27s
      4 28s
      1 29s
      1 30s
      9 31s
      2 32s
      1 33s
      3 34s
      4 35s
      1 36s
      4 37s
      6 38s
      1 39s
      1 42s
      1 43s
      3 45s
      1 46s
      1 47s
      1 50s
      2 51s
      4 52s
      1 53s
      2 56s
      1 59s
      7 60s
      1 61s
      1 73s
      1 99s
      1 103s
      1 106s
      1 110s
      1 115s
      7 116s
      1 117s
      3 118s
      1 120s
      1 149s
      1 300s
      1 440s
      1 504s
      1 875s
      1 958s
      1 972s
      1 2252s
      1 6169s
      1 6307s
      1 24980s
      1 26662s

$ grep 'NSPlayer/07.00.0000.0000' /export/logs/icecast-access.log /export/logs/icecast-access.log.2013102* | awk '{print ($14 > 3 ? "#" : "!")}' | sort | uniq -c
   6102 !
    723 #

Something seems broken for most of the users with this UA but not for all. :s

We've always had surprisingly many "listeners" with a duration of just a few seconds. But NSPlayer 07.0 really stands out.

Just as comparison the durations of Mozilla, iPhone, Opera, Andoid UAs:

$ grep -i 'WMFSDK' /export/logs/icecast-access.log /export/logs/icecast-access.log.2013102* | awk '{print ($14 > 3 ? "#" : "!")}' | sort | uniq -c
 671303 !
 318909 #
$ grep 'Mozilla' /export/logs/icecast-access.log /export/logs/icecast-access.log.2013102* | awk '{print ($14 > 3 ? "#" : "!")}' | sort | uniq -c
2765449 !
1017172 #
$ grep 'Opera' /export/logs/icecast-access.log /export/logs/icecast-access.log.2013102* | awk '{print ($14 > 3 ? "#" : "!")}' | sort | uniq -c
      7 !
  16282 #
$ grep 'iPhone' /export/logs/icecast-access.log /export/logs/icecast-access.log.2013102* | awk '{print ($14 > 3 ? "#" : "!")}' | sort | uniq -c
    583 !
 505848 #
$ grep -i 'Android' /export/logs/icecast-access.log /export/logs/icecast-access.log.2013102* | awk '{print ($14 > 3 ? "#" : "!")}' | sort | uniq -c
 294411 !
 371781 #

I'm considering deploying a version of icecast with Sha: 39856a004855953347f7427a1ed8b1aa16c996b4 reverted and then just and look at the WMFSDK statistics again. We've never gotten complaints from Windows Phone users before this patch. Now there are several within 14 days.

Niko.

[karlheyes]

You may find that the short ones are down to some stupid behaviour like doing range requests (useless for streaming really and just makes a mess for most cases). As for the WMFSDK thing, it was put in to resolve a recent change as it stopped working but if that also stops others from working then fine. I'm not too fussed about changing those but I have no pattern to test the full cases. It's one of the reasons I added the ?_hdr=1 and ?_hdr=0 mechanisms as it allows to test easily but all players have some stupid quirks and I do not have access to most of them so feedback is always welcome.

karl.

[niko]

We're now sort of overriding the Icecast format detection. We're using NGinX to redirect listeners to the actual streaming server. Now we're plainly appending ?_hdr=0 when redirecting a WMFSDK client. We'll see if people complain.

Off topic: We're now also blocking range requests in NGinX. We'll see if that changes the duration distribution.

Niko.

[niko]

So far we've no complaints from WMFSDK listeners… so at least our listeners seem OK if WMFSDK UAs do get HTTP and not ICY responses. I don't know what exactly Sha: 39856a004855953347f7427a1ed8b1aa16c996b4 was fixing… for us it rather breaks things. Perhaps @icedream can chime in and explain which versions of WMP profit of the Sha: 39856a004855953347f7427a1ed8b1aa16c996b4 fix.

[icedream]

I made this patch since I noticed that the Windows Media Player on Windows 7 doesn't display any metadata with icecast-kh servers but on ShoutCast servers for example it does, just a minimal feature change. I looked up what was causing this to happen and it seems to be that Windows Media Player expects the server to respond via the ICY protocol if they are able to stream metadata to clients. The problem is not all players seem to like this behavior, and Windows Media Player uses not-so-exact User-Agents (and also different or very similar names on different versions) and therefore it's difficult to determine via the User-Agent with 100% safety that a client is connecting via WMP.

I'll look at this issue and will try to provide an alternative as soon as possible, most likely will provide an exception for Windows Phone to fall back to HTTP instead or use some other small tweak.

[niko]

I had a look at Win7/WMP and you're right: It only shows title info if streaming ICY. I looked at the UA and its "NSPlayer/12.00.7601.17514 WMFSDK/12.00.7601.17514" in my case. It would be nice to find out wether "WMFSDK/12" would be an appropriate trigger for an ICY response. Perhaps we can collect more WMP UAs and behaviour for other Windows versions as well.

Offtopic: When adding a station URL to WMP it issues a separate request. Supposedly to verify the URL. Funny enough the UA is different:

217.24.207.26 - - [05/Nov/2013:16:04:30 +0100] "GET /ende HTTP/1.1" 200 15928 "-" "Windows-Media-Player/12.0.7601.17514" 0
217.24.207.26 - - [05/Nov/2013:16:04:45 +0100] "GET /ende HTTP/1.1" 200 305946 "-" "NSPlayer/12.00.7601.17514 WMFSDK/12.00.7601.17514" 15

Then we looked at the request pattern of our Synology backup drive (which can play webradio streams as well) and low and behold it makes even five separate requests per stream start:

217.24.207.26 - - [05/Nov/2013:16:08:46 +0100] "GET /ende HTTP/1.1" 200 65201 "-" "AudioStation/2.0 (Synology)" 1
217.24.207.26 - - [05/Nov/2013:16:08:46 +0100] "GET /ende HTTP/1.1" 200 65201 "-" "AudioStation/2.0 (Synology)" 1
217.24.207.26 - - [05/Nov/2013:16:08:48 +0100] "GET /ende HTTP/1.1" 200 65202 "-" "AudioStation/2.0 (Synology)" 1
217.24.207.26 - - [05/Nov/2013:16:08:48 +0100] "GET /ende HTTP/1.1" 200 65202 "-" "AudioStation/2.0 (Synology)" 1
217.24.207.26 - - [05/Nov/2013:16:09:04 +0100] "GET /ende HTTP/1.1" 200 321061 "-" "AudioStation/2.0 (Synology)" 17

At least the UA is consistent.

So if anyone ever wonders where all the 0 and 1 second listeners are coming from… here you go.

[karlheyes]

Just to add to the confusion, you may find that some players react differently if you start from a playlist, eg m3u/pls. The multiple request bug is not uncommon and is a pain if auth is involved.

karl.

[icedream]

I know about players which use "fallback user-agents" to show the server in some way that they have similar functionalities, in case a response to the original user-agent fails to fulfill specific conditions player-side. NSPlayer originally used to be a user-agent for another player, but the "WMFSDK" addition shows compatibility with Windows-Media-related content. Sometimes I really think why isn't there a header for capabilities or something like that... :/

Therefore, the "multiple requests bug" isn't really unrelated and not really a bug. Also not only the user-agent changes, I analyzed that via Wireshark, it also sends additional headers on special conditions, for example icy-metadata: 1.

Also I don't think it's enough to just say WMFSDK/12 is safe to trigger the ICY protocol. Other versions of Windows Media Player may support it and still it would trigger ICY protocol for Windows Phone if it is trying to use a similar user-agent. I'm not sure at it and I can't try it with Windows Phone as I don't have one such phone.

I will make another analysis with Wireshark and my version of Windows Media Player.