Icecast Streaming Media Server

[iunderwood]

I've seen this twice now on KH28, so I don't think it's just me.

I have seen a condition where the first listener in a list gets stuck and lists a lag of 78-84mb, and all listeners on that mountpoint are unable to stream. Once I kick the first listener, all the rest process their disconnections.

Here's an oddity in the log, during the problem:

[2010-12-15 13:47:33] DBUG slave/relay_read counts are 1 and 21 (/pf-128k.mp3)
[2010-12-15 13:47:33] DBUG slave/relay_read counts are 1 and 21 (/pf-128k.mp3)

And here's a snippet from the log right at the start:

[2010-12-15 08:05:49] INFO auth/queue_auth_client auth on /pf-128k.mp3 has 1 pending
[2010-12-15 08:05:49] DBUG auth/auth_run_thread Authentication thread 4 started for /pf-128k.mp3
[2010-12-15 08:05:49] DBUG auth/auth_run_thread 1 client(s) pending on /pf-128k.mp3
[2010-12-15 08:05:50] INFO source/source_add_listener max on /pf-128k.mp3 is -1 (cur 0)
[2010-12-15 08:05:50] DBUG auth/auth_release ...refcount on auth_t /pf-128k.mp3 is now 1
[2010-12-15 08:05:50] INFO source/source_shutdown Source "/pf-128k.mp3" exiting
[2010-12-15 08:05:50] DBUG stats/modify_node_event update "/pf-128k.mp3" outgoing_kbitrate (11)
[2010-12-15 08:05:50] DBUG stats/modify_node_event update "/pf-128k.mp3" incoming_bitrate (127568)
[2010-12-15 08:05:50] DBUG stats/modify_node_event update "/pf-128k.mp3" total_bytes_read (65241465)
[2010-12-15 08:05:50] DBUG stats/modify_node_event update "/pf-128k.mp3" total_bytes_sent (69686272)
[2010-12-15 08:05:50] DBUG stats/modify_node_event update "/pf-128k.mp3" total_mbytes_sent (66)
[2010-12-15 08:05:50] DBUG stats/modify_node_event update "/pf-128k.mp3" connected (4157)
[2010-12-15 08:05:50] INFO auth/auth_stream_end request source end for "/pf-128k.mp3"
[2010-12-15 08:05:50] INFO auth/queue_auth_client auth on /pf-128k.mp3 has 1 pending
[2010-12-15 08:05:50] DBUG slave/relay_read counts are 1 and 1 (/pf-128k.mp3)
[2010-12-15 08:05:50] DBUG auth/auth_run_thread Authentication thread 4 started for /pf-128k.mp3
[2010-12-15 08:05:50] DBUG auth/auth_run_thread 1 client(s) pending on /pf-128k.mp3
[2010-12-15 08:05:50] DBUG auth/auth_release ...refcount on auth_t /pf-128k.mp3 is now 1
[2010-12-15 08:05:50] DBUG slave/relay_read counts are 1 and 1 (/pf-128k.mp3)
[2010-12-15 08:05:50] DBUG slave/relay_read counts are 1 and 1 (/pf-128k.mp3)
[2010-12-15 08:05:50] DBUG slave/relay_read counts are 1 and 1 (/pf-128k.mp3)
[2010-12-15 08:05:50] DBUG slave/relay_read counts are 1 and 1 (/pf-128k.mp3)
[2010-12-15 08:05:50] DBUG slave/relay_read counts are 1 and 1 (/pf-128k.mp3)
[2010-12-15 08:05:50] DBUG slave/relay_read counts are 1 and 1 (/pf-128k.mp3)
[2010-12-15 08:05:51] DBUG slave/relay_read counts are 1 and 1 (/pf-128k.mp3)

Unfortunately, there seems to be no easy way to duplicate this, so I'm not sure what else I can offer.
_________________
++I;

[karlH]

Can you try 28.4. I think this is down to listeners going into an incorrect state.

karl.

[iunderwood]

If you've got a link, I'd love to give it a go!
_________________
++I;

[karlH]

actually try the latest snapshot at

www.xiphicecast.webspace.virginmedia.com/icecast-2.3.2-kh28.5.tar.gz

karl.

[iunderwood]

I'll install it on my relay after I get up in the morning.
_________________
++I;

[iunderwood]

So far, so good. I've been running on this for 14 hours w/o any incident.
_________________
++I;

[iunderwood]

Saw this on 28.5 today, but have upgraded to 28.9.
_________________
++I;

[iunderwood]

Had a hiccup in 28.9 too, but it seems to have been math driven:

Mount Point /pf-64k.ogg
Login
List ClientsMove ListenersUpdate MetadataKill SourceManage Authentication

4294919294 Listener(s)

Definitely not the right number of listeners.

From the error log:

[karlH]

ok, I think I see a possibility there, looks like an inadequate test on a listener termination leading to multiple attempts to remove from the source.

icecast-2.3.2-kh28.10.tar.gz is up

karl.

[iunderwood]

Installed and logging.
_________________
++I;

[iunderwood]

Better, but this still happens:

[2011-01-01 09:34:15] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2011-01-01 09:34:15] DBUG stats/modify_node_event update "global" outgoing_kbitrate (13)
[2011-01-01 09:34:16] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2011-01-01 09:34:16] DBUG stats/modify_node_event update "global" outgoing_kbitrate (12)
[2011-01-01 09:34:17] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2011-01-01 09:34:17] DBUG stats/modify_node_event update "global" outgoing_kbitrate (12)
[2011-01-01 09:34:18] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2011-01-01 09:34:18] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "global" clients (6)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2011-01-01 09:34:19] DBUG client/worker_add_pending_clients Added 1 pending clients to 0x2872b100
[2011-01-01 09:34:19] DBUG connection/_handle_get_request start with /pf-64k.aacp
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "global" client_connections (31957)
[2011-01-01 09:34:19] DBUG auth/auth_add_listener adding client for authentication
[2011-01-01 09:34:19] DBUG auth/queue_auth_client starting auth thread 0
[2011-01-01 09:34:19] DBUG auth/queue_auth_client auth on /pf-64k.aacp has 1 pending
[2011-01-01 09:34:19] DBUG client/worker 0x2872b100 now has 7 clients
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "global" connections (31958)
[2011-01-01 09:34:19] DBUG auth/auth_run_thread Authentication thread 2 started for /pf-64k.aacp
[2011-01-01 09:34:19] DBUG auth/auth_run_thread 1 client(s) pending on /pf-64k.aacp
[2011-01-01 09:34:19] DBUG auth_url/url_add_listener handler 2 sending request
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" outgoing_kbitrate (0)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" incoming_bitrate (63565)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" total_bytes_read (1999922)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" total_bytes_sent (199680)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" total_mbytes_sent (0)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" connected (243)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "global" stream_kbytes_read (1559184)
[2011-01-01 09:34:19] DBUG auth_url/url_add_listener handler 2 request finished
[2011-01-01 09:34:19] DBUG source/source_add_listener server outgoing bitrate is 0
[2011-01-01 09:34:19] INFO source/source_add_listener max on /pf-64k.aacp is -1 (cur 0)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "global" listeners (1)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "global" listener_connections (1551)
[2011-01-01 09:34:19] DBUG source/source_setup_listener woke up relay
[2011-01-01 09:34:19] DBUG auth/auth_release ...refcount on auth_t /pf-64k.aacp is now 1
[2011-01-01 09:34:19] DBUG auth/auth_run_thread Authenication thread 2 shutting down
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "global" sources (0)
[2011-01-01 09:34:19] INFO source/source_shutdown Source "/pf-64k.aacp" exiting
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" outgoing_kbitrate (0)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" incoming_bitrate (63636)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" total_bytes_read (2006137)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" total_bytes_sent (199680)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" total_mbytes_sent (0)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "/pf-64k.aacp" connected (243)
[2011-01-01 09:34:19] DBUG stats/modify_node_event update "global" stream_kbytes_read (1559191)
[2011-01-01 09:34:19] INFO auth/auth_stream_end request source end for "/pf-64k.aacp"
[2011-01-01 09:34:19] DBUG auth/queue_auth_client starting auth thread 0
[2011-01-01 09:34:19] DBUG auth/queue_auth_client auth on /pf-64k.aacp has 1 pending
[2011-01-01 09:34:19] DBUG slave/relay_read counts are 1 and 1 (/pf-64k.aacp)
[2011-01-01 09:34:19] DBUG auth/auth_run_thread Authentication thread 2 started for /pf-64k.aacp
[2011-01-01 09:34:19] DBUG auth/auth_run_thread 1 client(s) pending on /pf-64k.aacp
[2011-01-01 09:34:19] DBUG auth_url/url_stream_end handler 2 sending request
[2011-01-01 09:34:19] DBUG auth_url/url_stream_end handler 2 request finished
[2011-01-01 09:34:19] DBUG auth/auth_release ...refcount on auth_t /pf-64k.aacp is now 1
[2011-01-01 09:34:19] DBUG auth/auth_run_thread Authenication thread 2 shutting down
[2011-01-01 09:34:19] DBUG slave/relay_read counts are 1 and 1 (/pf-64k.aacp)
[2011-01-01 09:34:19] DBUG slave/relay_read counts are 1 and 1 (/pf-64k.aacp)
[2011-01-01 09:34:19] DBUG slave/relay_read counts are 1 and 1 (/pf-64k.aacp)

Needed to kill -9 and restart after attempting to kick the first listener.
_________________
++I;

[karlH]

I flushed out an older bug with relay restarts a few days ago, and so far I haven't heard of any similar issues, namely these "counts are N and M" messages yet. I've also tried limiting the listener thread loop, preventing lots of new listeners coming in, when things are saturated or just starting up, that may need more tuning but should be ok as-is.

icecast-2.3.2-kh28.13.tar.gz is up

karl

[iunderwood]

Installed and logging.
_________________
++I;