Icecast Streaming Media Server

[JohnnyOh]

Hi together,

I have some weird behavior on my icecast-server:

I am getting a playlist-stream from ices0 to a shoutcast-server. My icecast-server relays this stream.

For some reaseon the stream stops playing after about 10 minutes at the icecast-server. It tries to rebuffer and then stops playing. The source is permanently connected to the shoutcast-server. When I am playing the stream from the shoutcast-server everything is working correct and the stream is available for years.
The shoutcast and icecast-server are running on the smae system, so there should not be any lan-problem.

If I am encoding from a live-feed (soundcard) to the same mountpoints/ports everything works fine on shoutcast and icecast. The stream is available for years

Unfortunately icecast does not log the reason for the disconnect, only the disconnect of the listening client (even in debug-mode).

Does anyone have an idea how to fix this problem?

I am looking forward to get your ideas. I am at the end of my ideas.

Kind regards

JohnnyOh

[Brutish]

Your Log level is 4?
_________________
www.Hobbycaster.com

[JohnnyOh]

yes, I get all debug-information in error.log.

unfortunately I do not find a logentry which says why the stream stops playing. I exspect it is an buffer-underrun, but I am not sure.
_________________
Icecast 2.4.0 (debian)
and
icecast 2.3.2-kh32 (debian)

shoutcast 1.9.5 (debian)

[karlH]

icecast may not know the reason for the disconnection, typically because the source client stopped or the link to where ever the source client is becomes unstable or changes like with an IP change.

karl.

[JohnnyOh]

Thank you Karl, but this is what I found strange. The stream is permanentely up at the shoutcast server.

only the connection between shoutcast server and icecast-server drops. But they are both on one system and the icecast relays the stream from loopback 127.0.0.1
_________________
Icecast 2.4.0 (debian)
and
icecast 2.3.2-kh32 (debian)

shoutcast 1.9.5 (debian)

[karlH]

you haven't actually said much in any detail, I don't see any log entries. Has the stream terminated for timing out, or just end of stream?

karl.

[JohnnyOh]

Hi Karl,

I only get these logentries in icecast's error.log:

[2010-07-13 18:36:41] DBUG source/source_apply_mount Applying mount information for "/mountpoint_test.mp3"
[2010-07-13 18:36:41] DBUG auth/add_client_to_source max on /mountpoint_test.mp3 is -1 (cur 0)
[2010-07-13 18:36:41] DBUG auth/add_client_to_source Added client to /mountpoint_test.mp3
[2010-07-13 18:36:41] INFO source/source_main listener count on /mountpoint_test.mp3 now 1
[2010-07-13 18:36:42] DBUG stats/process_source_event new source stat /mountpoint_test.mp3
[2010-07-13 18:36:42] DBUG stats/process_source_event new node listenurl (http://localhost:80/mountpoint_test.mp3)
[2010-07-13 18:38:29] DBUG auth/add_client_to_source max on /mountpoint_test.mp3 is -1 (cur 1)
[2010-07-13 18:38:29] DBUG auth/add_client_to_source Added client to /mountpoint_test.mp3
[2010-07-13 18:38:29] INFO source/source_main listener count on /mountpoint_test.mp3 now 2
[2010-07-13 19:07:05] INFO source/source_shutdown Source "/mountpoint_test.mp3" exiting
[2010-07-13 19:07:05] DBUG source/source_clear_source clearing source "/mountpoint_test.mp3"
[2010-07-13 19:07:05] DBUG stats/process_source_event delete source node /mountpoint_test.mp3
[2010-07-13 19:07:06] DBUG slave/check_relay_stream waiting for relay thread for "/mountpoint_test.mp3"

There should not be an end of stream because it is a 24/7-stream.

When the streams stops, the i.e. winamp player tries to buffer, but then stops playing.

this is what icecast-access-log logs:

xxx.xxx.xxx.xxx - - [13/Jul/2010:19:07:05 +0200] "GET /mountpoint_test.mp3 HTTP/1.0" 200 14962155 "-" "Icecast 2.3.2" 1824
xxx.xxx.xxx.xxx - - [13/Jul/2010:19:07:05 +0200] "GET /mountpoint_test.mp3 HTTP/1.0" 200 13703618 "-" "Icecast 2.3.2" 1716

or

xxx.xxx.xxx.xxx - - [13/Jul/2010:14:27:54 +0200] "GET /mountpoint_test.mp3 HTTP/1.0" 200 314019 "-" "WinampMPEG/5.56, Ultravox/2.1" 32

I hope it helps.

Kind regards

Johnny
_________________
Icecast 2.4.0 (debian)
and
icecast 2.3.2-kh32 (debian)

shoutcast 1.9.5 (debian)

[karlH]

I suspect you have removed too much here.

[2010-07-13 18:38:29] INFO source/source_main listener count on /mountpoint_test.mp3 now 2
[2010-07-13 19:07:05] INFO source/source_shutdown Source "/mountpoint_test.mp3" exiting

There are about 30 seconds between these 2 entries and each stream updates the stats every 5 seconds yet those are not appearing. Filtering the logs can be helpful as long as you know you are looking for something specifically but you are looking for a reason why the stream is terminating so lets see what is actually logged. For all we know, icecast may not be reading any data from the socket.

karl.

[JohnnyOh]

Hi Karl,

you are right. plase find below the unshortened log:

[2010-07-20 11:40:44] DBUG stats/modify_node_event update node total_bytes_read (1169733600)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node total_bytes_sent (2336174203)
[2010-07-20 11:40:44] DBUG source/get_next_buffer last 1279618833, timeout 10, now 1279618844
[2010-07-20 11:40:44] WARN source/get_next_buffer Disconnecting source due to socket timeout
[2010-07-20 11:40:44] INFO source/source_shutdown Source "/mountpoint_test.mp3" exiting
[2010-07-20 11:40:44] DBUG source/source_clear_source clearing source "/mountpoint_test.mp3"
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node total_bytes_read (44907962523)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node total_bytes_sent (45011328217)
[2010-07-20 11:40:44] DBUG stats/process_source_event delete source node /mountpoint_test.mp3
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node clients (61)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node clients (60)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node clients (59)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node clients (5
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node sources (21)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node clients (59)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node connections (51639933)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node clients (60)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node connections (51639934)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node clients (61)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node connections (51639935)
[2010-07-20 11:40:44] INFO fserve/fserve_client_create checking for file /missing_mountpoint.mp3 (/usr/local/share/icecast/web/missing_mountpoint.mp3)
[2010-07-20 11:40:44] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/missing_mountpoint.mp3" No such file or directory
[2010-07-20 11:40:44] DBUG fserve/fserve_add_client Adding client to file serving engine
[2010-07-20 11:40:44] DBUG slave/_slave_thread rescanning relay lists
[2010-07-20 11:40:44] DBUG slave/check_relay_stream waiting for relay thread for "/other5_mountpoint.mp3"
[2010-07-20 11:40:44] DBUG slave/check_relay_stream waiting for relay thread for "/mountpoint_test.mp3"
[2010-07-20 11:40:44] INFO slave/start_relay_stream Starting relayed source at mountpoint "/other_mountpoint.mp3"
[2010-07-20 11:40:44] INFO slave/start_relay_stream Starting relayed source at mountpoint "/other2_mountpoint.mp3"
[2010-07-20 11:40:44] INFO slave/start_relay_stream Starting relayed source at mountpoint "/other3_mountpoint.mp3"
[2010-07-20 11:40:44] INFO slave/start_relay_stream Starting relayed source at mountpoint "/other4_mountpoint.mp3"
[2010-07-20 11:40:44] EROR slave/start_relay_stream Error from relay request: Service Unavailable
[2010-07-20 11:40:44] DBUG source/source_clear_source clearing source "/other6_mountpoint.mp3"
[2010-07-20 11:40:44] EROR slave/start_relay_stream Error from relay request: Service Unavailable
[2010-07-20 11:40:44] DBUG source/source_clear_source clearing source "/other7_mountpoint.mp3"
[2010-07-20 11:40:44] EROR slave/start_relay_stream Error from relay request: Service Unavailable
[2010-07-20 11:40:44] DBUG source/source_clear_source clearing source "/other8_mountpoint.mp3"
[2010-07-20 11:40:44] EROR slave/start_relay_stream Error from relay request: Service Unavailable
[2010-07-20 11:40:44] DBUG source/source_clear_source clearing source "/other9_mountpoint.mp3"
[2010-07-20 11:40:44] INFO fserve/fserve_client_create checking for file /missing_mountpoint.mp3 (/usr/local/share/icecast/web/missing_mountpoint.mp3)
[2010-07-20 11:40:44] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/missing_mountpoint.mp3" No such file or directory
[2010-07-20 11:40:44] DBUG fserve/fserve_add_client Adding client to file serving engine
[2010-07-20 11:40:44] INFO fserve/fserve_client_create checking for file /missing_mountpoint2.mp3 (/usr/local/share/icecast/web/missing_mountpoint2.mp3)
[2010-07-20 11:40:44] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/missing_mountpoint2.mp3" No such file or directory
[2010-07-20 11:40:44] DBUG fserve/fserve_add_client Adding client to file serving engine
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node client_connections (51525214)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node client_connections (51525215)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node clients (60)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node clients (59)
[2010-07-20 11:40:44] DBUG stats/modify_node_event update node client_connections (51525216)
[2010-07-20 11:40:44] INFO fserve/fserve_client_create checking for file /missing_mountpoint.mp3 (/usr/local/share/icecast/web/missing_mountpoint.mp3)
[2010-07-20 11:40:44] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/missing_mountpoint.mp3" No such file or directory
[2010-07-20 11:40:44] DBUG fserve/fserve_add_client Adding client to file serving engine
[2010-07-20 11:40:44] INFO fserve/fserve_client_create checking for file /missing_mountpoint.mp3 (/usr/local/share/icecast/web/missing_mountpoint.mp3)
[2010-07-20 11:40:44] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/missing_mountpoint.mp3" No such file or directory
[2010-07-20 11:40:44] DBUG fserve/fserve_add_client Adding client to file serving engine
[2010-07-20 11:40:44] INFO fserve/fserve_client_create checking for file /missing_mountpoint2.mp3 (/usr/local/share/icecast/web/missing_mountpoint2.mp3)
[2010-07-20 11:40:44] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/missing_mountpoint2.mp3" No such file or directory
[2010-07-20 11:40:44] DBUG fserve/fserve_add_client Adding client to file serving engine
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (5
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (59)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node connections (51639936)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (60)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node connections (51639937)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (61)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node connections (51639938)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node client_connections (51525217)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node client_connections (51525218)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node client_connections (51525219)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_read (44910784800)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_sent (80216576139)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (60)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (59)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (5
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_read (13871484200)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_sent (24110753345)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_read (28874948200)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_sent (57744674957)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_read (365941800)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_sent (730972782)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_read (28068590200)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_sent (48539487025)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_read (13865549600)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_sent (24102365596)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_read (28067975408)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_sent (48539780956)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_read (439189021)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node total_bytes_sent (0)
[2010-07-20 11:40:45] INFO fserve/fserve_client_create checking for file /mountpoint_test.mp3 (/usr/local/share/icecast/web/mountpoint_test.mp3)
[2010-07-20 11:40:45] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/mountpoint_test.mp3" No such file or directory
[2010-07-20 11:40:45] DBUG fserve/fserve_add_client Adding client to file serving engine
[2010-07-20 11:40:45] DBUG slave/_slave_thread rescanning relay lists
[2010-07-20 11:40:45] DBUG slave/check_relay_stream waiting for relay thread for "/other_mountpoint.mp3"
[2010-07-20 11:40:45] DBUG slave/check_relay_stream waiting for relay thread for "/other2_mountpoint.mp3"
[2010-07-20 11:40:45] DBUG slave/check_relay_stream waiting for relay thread for "/other3_mountpoint.mp3"
[2010-07-20 11:40:45] DBUG slave/check_relay_stream waiting for relay thread for "/other4_mountpoint.mp3"
[2010-07-20 11:40:45] INFO slave/start_relay_stream Starting relayed source at mountpoint "/other5_mountpoint.mp3"
[2010-07-20 11:40:45] INFO slave/start_relay_stream Starting relayed source at mountpoint "/mountpoint_test.mp3"
[2010-07-20 11:40:45] EROR slave/start_relay_stream Error from relay request: Service Unavailable
[2010-07-20 11:40:45] DBUG source/source_clear_source clearing source "/other5_mountpoint.mp3"
[2010-07-20 11:40:45] DBUG connection/connection_complete_source sources count is 21
[2010-07-20 11:40:45] DBUG source/source_apply_mount Applying mount information for "/mountpoint_test.mp3"
[2010-07-20 11:40:45] DBUG source/source_apply_mount YP changed to 0
[2010-07-20 11:40:45] DBUG format-mp3/format_mp3_apply_settings mp3 interval 8192
[2010-07-20 11:40:45] DBUG source/source_update_settings public set to 0
[2010-07-20 11:40:45] DBUG source/source_update_settings max listeners to -1
[2010-07-20 11:40:45] DBUG source/source_update_settings queue size to 524288
[2010-07-20 11:40:45] DBUG source/source_update_settings burst size to 65535
[2010-07-20 11:40:45] DBUG source/source_update_settings source timeout to 10
[2010-07-20 11:40:45] DBUG source/source_update_settings fallback_when_full to 0
[2010-07-20 11:40:45] DBUG connection/connection_complete_source source is ready to start
[2010-07-20 11:40:45] DBUG source/source_init Source creation complete
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (59)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node connections (51639939)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node client_connections (51525220)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (60)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node sources (22)
[2010-07-20 11:40:45] DBUG stats/process_source_event new source stat /mountpoint_test.mp3
[2010-07-20 11:40:45] DBUG stats/process_source_event new node public (0)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node server_name (TEST Stream)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node server_description (Unspecified description)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node server_url (http://www.somewhere.com)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node genre ((null))
[2010-07-20 11:40:45] DBUG stats/process_source_event new node bitrate (64)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node server_type (audio/mpeg)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node max_listeners (unlimited)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node source_relay_connections (30036)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node source_ip (127.0.0.1)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node listenurl (http://localhost:80/mountpoint_test.mp3)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node source_total_connections (33901)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node slow_listeners (0)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node listeners (0)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node listener_peak (4)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node stream_start (Tue, 20 Jul 2010 11:40:45 +0200)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node total_bytes_read (0)
[2010-07-20 11:40:45] DBUG stats/process_source_event new node total_bytes_sent (0)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (59)
[2010-07-20 11:40:45] DBUG format-mp3/mp3_get_filter_meta shoutcast metadata StreamTitle='Test Stream - Mashup 6';StreamUrl='';
[2010-07-20 11:40:45] DBUG stats/process_source_event new node title (TEST Stream - Mashup 6)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node clients (60)
[2010-07-20 11:40:45] DBUG stats/modify_node_event update node connections (51639940)
[2010-07-20 11:40:45] DBUG auth/add_client_to_source max on /mountpoint_test.mp3 is -1 (cur 0)
[2010-07-20 11:40:45] DBUG auth/add_client_to_source Added client to /mountpoint_test.mp3
[2010-07-20 11:40:45] DBUG auth/add_authenticated_client client authenticated, passed to source
[2010-07-20 11:40:46] DBUG source/source_main Client added
[2010-07-20 11:40:46] INFO source/source_main listener count on /mountpoint_test.mp3 now 1
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node client_connections (51525221)
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node listener_connections (160638)
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node total_bytes_read (297056109)
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node total_bytes_sent (308554442)
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node total_bytes_read (345535400)
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node total_bytes_sent (1727628581)
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node total_bytes_read (1169562244)
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node total_bytes_sent (2336297654)
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node total_bytes_read (1169513779)
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node total_bytes_sent (2336277967)
[2010-07-20 11:40:46] DBUG stats/modify_node_event update node listeners (1)
[2010-07-20 11:40:46] DBUG format/format_check_http_buffer processing pending client headers
[2010-07-20 11:40:46] DBUG slave/_slave_thread rescanning relay lists

Please note that the mountpoint "mountpoint_test.mp3" is the one which is not working correctly. The others are working correct (if they are encoded)


I looked too close to the disconnect to my client-disconnect so I did not see the logentry

[2010-07-20 11:40:44] DBUG source/get_next_buffer last 1279618833, timeout 10, now 1279618844
[2010-07-20 11:40:44] WARN source/get_next_buffer Disconnecting source due to socket timeout
[2010-07-20 11:40:44] INFO source/source_shutdown Source "/mountpoint_test.mp3" exiting

Unfortunately there is no disconnect of the source on the shoutcast-server:

<07/20/10@11:16:57> [source] connected from 194.9.72.10
<07/20/10@11:16:57> [source] icy-name:Test Stream ; icy-genre:(null)
<07/20/10@11:16:57> [source] icy-pub:0 ; icy-br:64 ; icy-url:http://www.somewhere.com
<07/20/10@11:16:57> [source] icy-irc: ; icy-icq: ; icy-aim:
<07/20/10@11:16:57> [dest: 127.0.0.1] connection closed (417348 seconds) (UID: 7956)[L: 0]{Bytes: 2189646}(P: 0)
<07/20/10@11:16:59> [dest: 127.0.0.1] starting stream (UID: 215690)[L: 1]{A: Icecast 2.3.0}(P: 0)
<07/20/10@11:36:22> [dest: 127.0.0.1] connection closed (1163 seconds) (UID: 215690)[L: 0]{Bytes: 9469952}(P: 0)
<07/20/10@11:36:22> [dest: 127.0.0.1] starting stream (UID: 215691)[L: 1]{A: Icecast 2.3.0}(P: 0)
<07/20/10@11:40:45> [dest: 127.0.0.1] starting stream (UID: 215692)[L: 2]{A: Icecast 2.3.0}(P: 1)
<07/20/10@11:40:46> [dest: 127.0.0.1] connection closed (264 seconds) (UID: 215691)[L: 1]{Bytes: 2342912}(P: 0)

There are no other logentries from shoutcast-log during this time. I also was not disconnected with my client from the shoutcast-stream.

I really hope this will help you giving me a hint to resolve the problem.

Kind regards any many thanks for your effort.

Johnny
_________________
Icecast 2.4.0 (debian)
and
icecast 2.3.2-kh32 (debian)

shoutcast 1.9.5 (debian)

[karlH]

obviously icecast cannot do anything in the case of a timeout except drop the stream. A lack of data being received typically means a network outage however that looks to be over 127.0.0.1 so it's more unlikely but not impossible. It's possible that shoutcast is just not sending any data, maybe you should try with a separate downloader/wget/curl app to run in parallel just to see how that works out.

karl.