Icecast Streaming Media Server

[audiorapture]

Hello,

I have been using Darkice+Icecast2 on Ubuntu since May of this year for a 24/7 live radio broadcast.

From the start, I had reports of clients disconnecting randomly after as little as 5 seconds to about 1 hour. Some clients reached the mount-specific maximum of 24 hours.
I tried to track whether only specific clients (e.g. iTunes, WMP, WinAMP, ...) exhibit the problem, but is seems to be client-independent.

The box is a P3-500 with 128MB RAM and a 20GB HDD.
It runs Ubuntu Server LTS 8.04.3.
Originally I had installed darkice 0.18 and icecast 2.3.1 that are included in Ubuntu 8.04.
few weeks back I manually upgraded to darkice 0.19.1 and icecast 2.3.2.
The problem persisted.
Now I am running icecast 2.3.2-kh12 and the problem is still there.
darkice is using about 15% CPU, icecast about 2%. Memory usage is at 108MB of 128MB.

This morning, I connected iTunes 8.2.1 to the stream, and after about 30 minutes the audio stopped, and iTunes displayed a "Buffering..." window. In icecast's client list, the lag for my client increased until I heard a split-second of audio, then the stream got disconnected. Below is the error.log during that time.

There are currently 2 streams, the main 64k stream and a test 128k that is only known to a handful of people.
The main stream has up to 50 concurrent clients, but the problem occurs independently of the client count.

I have listed what I think might be relevant log/config parts below. If there is anything else I am missing, please let me know.

-Jason

I think it is related to icecast thinking a client lags:
client list:
a.b.c.d 43 381503280 NSPlayer/10.0.0.4066 WMFSDK/10.0 Kick
e.f.g.h 144 0 NSPlayer/10.0.0.3647 /10.0 Kick
i.j.k.l 0 iTunes/8.0.1 (Macintosh; N; Intel) Kick
m.n.o.p 580 0 NSPlayer/11.0.5721.5251 WMFSDK/11.0 Kick
q.r.s.t 588 1041652 WinampMPEG/5.56, Ultravox/2.1 Kick

icecast.xml:
<icecast>
<limits>
<clients>500</clients>
<sources>5</sources>
<threadpool>10</threadpool>
<queue-size>2097152</queue-size>
<client-timeout>60</client-timeout>
<header-timeout>15</header-timeout>
<source-timeout>5</source-timeout>
<burst-size>65535</burst-size>
</limits>
<mount>
<public>1</public>
<mount-name>/wnrn.mp3</mount-name>
<max-listener-duration>86400</max-listener-duration>
<intro>/wnrn-intro-64.mp3</intro>
<fallback-mount>/wnrn-fallback-64.mp3</fallback-mount>
<fallback-override>1</fallback-override>
<!--
<fallback-when-full>1</fallback-when-full>
-->
</mount>

error.log:
[2009-08-21 09:17:30] DBUG client/find_least_busy_handler handler 0x80941d0 has 31 clients
[2009-08-21 09:17:30] DBUG stats/modify_node_event update "global" connections (1573)
[2009-08-21 09:17:30] DBUG client/worker 0x80941d0 now has 32 clients
[2009-08-21 09:17:30] DBUG connection/_handle_get_request start with /wnrn.mp3
[2009-08-21 09:17:30] DBUG stats/modify_node_event update "global" client_connections (1567)
[2009-08-21 09:17:30] INFO source/source_add_listener max on /wnrn.mp3 is -1 (cur 29)
[2009-08-21 09:17:30] DBUG format/format_prepare_headers processing listener headers
[2009-08-21 09:17:30] DBUG stats/modify_node_event update "global" listeners (30)
[2009-08-21 09:17:30] DBUG stats/modify_node_event update "global" listener_connections (216)
[2009-08-21 09:17:30] DBUG stats/modify_node_event update "/wnrn.mp3" listener_connections (216)
[2009-08-21 09:17:30] INFO source/source_read listener count on /wnrn.mp3 now 30
[2009-08-21 09:17:30] DBUG stats/modify_node_event update "/wnrn.mp3" listeners (30)
[2009-08-21 09:17:31] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1715)
[2009-08-21 09:17:32] DBUG client/find_least_busy_handler handler 0x80941d0 has 32 clients
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn-128.mp3" outgoing_kbitrate (0)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn-128.mp3" incoming_bitrate (130744)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn-128.mp3" total_bytes_read (755957848)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn-128.mp3" total_bytes_sent (0)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn-128.mp3" total_mbytes_sent (0)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn-128.mp3" connected (47244)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "global" stream_kbytes_sent (2026480)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "global" stream_kbytes_read (1107318)
[2009-08-21 09:17:32] DBUG client/find_least_busy_handler handler 0x80941d0 has 32 clients
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn.mp3" outgoing_kbitrate (1815)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn.mp3" incoming_bitrate (65368)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn.mp3" total_bytes_read (377979164)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn.mp3" total_bytes_sent (2076244992)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn.mp3" total_mbytes_sent (1980)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "/wnrn.mp3" connected (47244)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "global" stream_kbytes_sent (2027583)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "global" stream_kbytes_read (1107358)
[2009-08-21 09:17:32] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1785)
[2009-08-21 09:17:33] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1750)
[2009-08-21 09:17:34] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1755)
[2009-08-21 09:17:35] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1759)
[2009-08-21 09:17:36] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1762)
[2009-08-21 09:17:37] DBUG client/find_least_busy_handler handler 0x80941d0 has 32 clients
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn-128.mp3" outgoing_kbitrate (0)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn-128.mp3" incoming_bitrate (130672)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn-128.mp3" total_bytes_read (756037676)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn-128.mp3" total_bytes_sent (0)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn-128.mp3" total_mbytes_sent (0)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn-128.mp3" connected (47249)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "global" stream_kbytes_sent (2027583)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "global" stream_kbytes_read (1107436)
[2009-08-21 09:17:37] DBUG client/find_least_busy_handler handler 0x80941d0 has 32 clients
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn.mp3" outgoing_kbitrate (1836)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn.mp3" incoming_bitrate (65336)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn.mp3" total_bytes_read (378018885)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn.mp3" total_bytes_sent (2077303808)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn.mp3" total_mbytes_sent (1981)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "/wnrn.mp3" connected (47249)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "global" stream_kbytes_sent (2028617)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "global" stream_kbytes_read (1107474)
[2009-08-21 09:17:37] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1765)
[2009-08-21 09:17:38] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1745)
[2009-08-21 09:17:39] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1748)
[2009-08-21 09:17:39] DBUG stats/modify_node_event update "global" clients (33)
[2009-08-21 09:17:39] DBUG client/find_least_busy_handler handler 0x80941d0 has 32 clients
[2009-08-21 09:17:39] DBUG stats/modify_node_event update "global" connections (1574)
[2009-08-21 09:17:39] DBUG client/worker 0x80941d0 now has 33 clients
[2009-08-21 09:17:39] DBUG connection/_handle_get_request start with /wnrn.mp3
[2009-08-21 09:17:39] DBUG stats/modify_node_event update "global" client_connections (1568)
[2009-08-21 09:17:39] INFO source/source_add_listener max on /wnrn.mp3 is -1 (cur 30)
[2009-08-21 09:17:39] INFO source/source_read listener count on /wnrn.mp3 now 31
[2009-08-21 09:17:39] DBUG stats/modify_node_event update "/wnrn.mp3" listeners (31)
[2009-08-21 09:17:39] DBUG format/format_prepare_headers processing listener headers
[2009-08-21 09:17:39] DBUG stats/modify_node_event update "global" listeners (31)
[2009-08-21 09:17:39] DBUG stats/modify_node_event update "global" listener_connections (217)
[2009-08-21 09:17:39] DBUG stats/modify_node_event update "/wnrn.mp3" listener_connections (217)
[2009-08-21 09:17:40] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1775)
[2009-08-21 09:17:40] DBUG client/client_send_bytes Client connection died
[2009-08-21 09:17:40] DBUG stats/modify_node_event update "global" listeners (30)
[2009-08-21 09:17:40] DBUG stats/modify_node_event update "/wnrn.mp3" listeners (30)
[2009-08-21 09:17:40] DBUG stats/modify_node_event update "global" clients (32)
[2009-08-21 09:17:40] INFO source/source_read listener count on /wnrn.mp3 now 30
[2009-08-21 09:17:40] DBUG stats/modify_node_event update "/wnrn.mp3" listeners (30)
[2009-08-21 09:17:40] DBUG client/worker 0x80941d0 now has 32 clients
[2009-08-21 09:17:41] DBUG stats/modify_node_event update "global" outgoing_kbitrate (2629)
[2009-08-21 09:17:42] DBUG client/find_least_busy_handler handler 0x80941d0 has 32 clients
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn-128.mp3" outgoing_kbitrate (0)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn-128.mp3" incoming_bitrate (130600)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn-128.mp3" total_bytes_read (756117495)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn-128.mp3" total_bytes_sent (0)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn-128.mp3" total_mbytes_sent (0)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn-128.mp3" connected (47254)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "global" stream_kbytes_sent (2028617)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "global" stream_kbytes_read (1107552)
[2009-08-21 09:17:42] DBUG client/find_least_busy_handler handler 0x80941d0 has 32 clients
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn.mp3" outgoing_kbitrate (1892)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn.mp3" incoming_bitrate (65304)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn.mp3" total_bytes_read (378059016)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn.mp3" total_bytes_sent (2078472192)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn.mp3" total_mbytes_sent (1982)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "/wnrn.mp3" connected (47254)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "global" stream_kbytes_sent (2029758)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "global" stream_kbytes_read (1107592)
[2009-08-21 09:17:42] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1707)
[2009-08-21 09:17:43] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1747)
[2009-08-21 09:17:43] DBUG yp/send_to_yp YP touch at http://dir.xiph.org/cgi-bin/yp-cgi succeeded
[2009-08-21 09:17:44] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1760)
[2009-08-21 09:17:44] DBUG client/client_send_bytes Client connection died
[2009-08-21 09:17:44] DBUG stats/modify_node_event update "global" listeners (29)
[2009-08-21 09:17:44] DBUG stats/modify_node_event update "/wnrn.mp3" listeners (29)
[2009-08-21 09:17:44] DBUG stats/modify_node_event update "global" clients (31)
[2009-08-21 09:17:44] INFO source/source_read listener count on /wnrn.mp3 now 29
[2009-08-21 09:17:44] DBUG stats/modify_node_event update "/wnrn.mp3" listeners (29)
[2009-08-21 09:17:44] DBUG client/worker 0x80941d0 now has 31 clients
[2009-08-21 09:17:45] DBUG stats/modify_node_event update "global" outgoing_kbitrate (6048)
[2009-08-21 09:17:46] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1997)

[karlH]

the log does not indicate that the queue size was reached, just that the client closed the connection, which tends to indicate that the player closed the connection. Does the log cover any connections where a client was dropped. I don't see the url to try it myself.

karl.

[audiorapture]

Thank you for your reply.

The log file excerpt covers the entire time that my test client (iTunes 8.2.1) exhibited the problem.
The only indicator that there is a problem is the lag time in the new "List Clients" table of kh12.

The URL to the stream is: http://broadcast.wnrn.org:8000/wnrn.mp3.m3u

[karlH]

the lag values are informational only, they are not used to make decisions about dropping a listener. Those figures are in bytes, so that first one looks wrong but the others look ok.

The payload size look smaller than normal, causing some small packets being issued, you could try adding into the <mount> section a smaller blocking factor with say <qblock-size>1320</qblock-size>.

I don't see it causing a listener drop but it's easy enough to check.

karl.

[audiorapture]

I have added the <qblock-size> to the mount definition and reloaded the config using the UI botton.

I also have collected a log file during the time a WMP11 client had a 5 minute hang before it suddenly resumed (any normal user would have stopped and restarted the stream).
It is 14k compressed, if you want to see it, where should I put it?

[audiorapture]

Summary from a private conversation:

VERY IMPORTANT:
Check your network card for errors! "ifconfig" showed a high count for TX errors and carrier. This most likely was the culprit for a lot of the observed problems.
"mii-tool -v" showed that the auto-negotiated link was 100/half - even though the switch is configured for 100/full.
After forcing the network card to 100/full stopped the error count was constant.

Also, besides finding the above problem, Karl tirelessly worked on timing issues in the software, those fixes will most likely find their way into kh13 and hopefully 2.3.3, soon. ;-)

Thank you!