View previous topic :: View next topic |
Author |
Message |
iunderwood
Joined: 23 Aug 2008 Posts: 114 Location: Leicester, MA
|
Posted: Tue Nov 03, 2009 4:23 am Post subject: Possible Stream Regression in KH17 |
|
|
I've been observing an interesting stream regression in KH17, which I'm having a difficult time pinning down. I've been clued into this by a listener and friend who was initially complaining about buffering. The initial server I was building off of was a Win2k3 box, so I figured I would try a fresh FreeBSD box to rule out any OS issue.
I've done some testing in both VLC and in Winamp on the listening side of this and Winamp seems to recover from most of the problems and continues to play. However, VLC goes to pot and every subsequent packet until the next song change is counted as a lost buffer. Presumably, something is getting corrupted going to output which causes it to choke.
When I revert to the mainline 2.3.2, I can stream for hours without any loss at all, but I don't get the benefit of all the neat features of KH17.
I've been running some debug logging and have been able to determine the following happened right around one of the observed outages:
[2009-11-02 23:09:02] DBUG stats/modify_node_event update "global" stream_kbytes_sent (19721)
[2009-11-02 23:09:02] DBUG stats/modify_node_event update "global" stream_kbytes_read (19631)
[2009-11-02 23:09:02] DBUG stats/modify_node_event update "global" outgoing_kbitrate (81)
[2009-11-02 23:09:03] DBUG stats/modify_node_event update "global" outgoing_kbitrate (84)
[2009-11-02 23:09:04] DBUG format-vorbis/initiate_flush adding EOS packet
[2009-11-02 23:09:04] DBUG format-ogg/format_ogg_free_headers releasing header pages
[2009-11-02 23:09:04] DBUG format-ogg/format_ogg_free_headers releasing header pages
[2009-11-02 23:09:04] DBUG format-ogg/free_ogg_codecs freeing codecs
[2009-11-02 23:09:04] DBUG format-vorbis/vorbis_codec_free freeing vorbis codec
[2009-11-02 23:09:04] DBUG stats/process_source_event delete node audio_bitrate
[2009-11-02 23:09:04] DBUG stats/process_source_event delete node audio_channels
[2009-11-02 23:09:04] DBUG stats/process_source_event delete node audio_samplerate
[2009-11-02 23:09:04] DBUG format-vorbis/initial_vorbis_page checking for vorbis codec
[2009-11-02 23:09:04] INFO format-vorbis/initial_vorbis_page seen initial vorbis header
[2009-11-02 23:09:04] DBUG format-ogg/process_initial_page Vorbis codec has filter mark 0
[2009-11-02 23:09:04] DBUG format-vorbis/process_vorbis_page processing incoming header packet (1)
[2009-11-02 23:09:04] DBUG format-vorbis/process_vorbis_page processing incoming header packet (2)
[2009-11-02 23:09:04] DBUG format-vorbis/process_vorbis_page we have the header packets now
[2009-11-02 23:09:04] DBUG stats/process_source_event new node on /pf-64k.ogg "audio_samplerate" (44100)
[2009-11-02 23:09:04] DBUG stats/process_source_event new node on /pf-64k.ogg "audio_channels" (2)
[2009-11-02 23:09:04] DBUG stats/process_source_event new node on /pf-64k.ogg "audio_bitrate" (64000)
[2009-11-02 23:09:04] DBUG stats/modify_node_event update "/pf-64k.ogg" ice-bitrate (64)
[2009-11-02 23:09:04] DBUG format-vorbis/process_vorbis_headers Adding the 3 header packets
[2009-11-02 23:09:04] DBUG format-ogg/format_ogg_attach_header attaching BOS page
[2009-11-02 23:09:04] DBUG format-ogg/format_ogg_attach_header attaching header page
[2009-11-02 23:09:04] DBUG stats/modify_node_event update "/pf-64k.ogg" artist (Tor Linløkken)
[2009-11-02 23:09:04] DBUG stats/modify_node_event update "/pf-64k.ogg" title (Unicorn)
[2009-11-02 23:09:04] DBUG stats/modify_node_event update "/pf-64k.ogg" metadata_updated (Mon, 02 Nov 2009 23:09:04 -0500)
[2009-11-02 23:09:04] DBUG stats/modify_node_event update "/pf-64k.ogg" subtype (Vorbis)
[2009-11-02 23:09:04] DBUG stats/modify_node_event update "global" outgoing_kbitrate (95)
However, that's somewhat hit-or-miss since I had another client croak here, w/o any change in information in the log:
2009-11-02 23:11:00] DBUG stats/modify_node_event update "global" outgoing_kbitrate (65)
[2009-11-02 23:11:00] DBUG stats/modify_node_event update "global" clients (3)
[2009-11-02 23:11:00] DBUG stats/modify_node_event update "global" connections (453)
[2009-11-02 23:11:00] DBUG stats/modify_node_event update "global" connections (454)
[2009-11-02 23:11:00] DBUG client/worker 0x2871a100 now has 3 clients
[2009-11-02 23:11:00] DBUG connection/_handle_get_request start with /admin/stats.xml
[2009-11-02 23:11:00] DBUG stats/modify_node_event update "global" client_connections (224)
[2009-11-02 23:11:00] INFO admin/admin_handle_general_request processing file stats.xml
[2009-11-02 23:11:00] DBUG stats/modify_node_event update "global" clients (2)
[2009-11-02 23:11:00] DBUG client/worker 0x2871a100 now has 2 clients
[2009-11-02 23:11:01] DBUG stats/modify_node_event update "global" outgoing_kbitrate (80)
[2009-11-02 23:11:02] DBUG stats/modify_node_event update "/pf-64k.ogg" outgoing_kbitrate (66)
[2009-11-02 23:11:02] DBUG stats/modify_node_event update "/pf-64k.ogg" incoming_bitrate (54064)
[2009-11-02 23:11:02] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_read (18238203)
[2009-11-02 23:11:02] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_sent (21280768)
[2009-11-02 23:11:02] DBUG stats/modify_node_event update "/pf-64k.ogg" total_mbytes_sent (20)
[2009-11-02 23:11:02] DBUG stats/modify_node_event update "/pf-64k.ogg" connected (15978)
[2009-11-02 23:11:02] DBUG stats/modify_node_event update "global" stream_kbytes_sent (20782)
[2009-11-02 23:11:02] DBUG stats/modify_node_event update "global" stream_kbytes_read (20622)
[2009-11-02 23:11:02] DBUG stats/modify_node_event update "global" outgoing_kbitrate (75)
[2009-11-02 23:11:03] DBUG stats/modify_node_event update "global" outgoing_kbitrate (73)
[2009-11-02 23:11:04] DBUG stats/modify_node_event update "global" outgoing_kbitrate (71)
[2009-11-02 23:11:05] DBUG stats/modify_node_event update "global" outgoing_kbitrate (70)
[2009-11-02 23:11:05] DBUG stats/modify_node_event update "global" clients (3)
[2009-11-02 23:11:05] DBUG stats/modify_node_event update "global" connections (455)
[2009-11-02 23:11:05] DBUG stats/modify_node_event update "global" connections (456)
[2009-11-02 23:11:05] DBUG client/worker 0x2871a100 now has 3 clients
[2009-11-02 23:11:05] DBUG connection/_handle_get_request start with /admin/stats.xml
[2009-11-02 23:11:05] DBUG stats/modify_node_event update "global" client_connections (225)
[2009-11-02 23:11:05] INFO admin/admin_handle_general_request processing file stats.xml
[2009-11-02 23:11:05] DBUG stats/modify_node_event update "global" clients (2)
[2009-11-02 23:11:05] DBUG client/worker 0x2871a100 now has 2 clients
[2009-11-02 23:11:06] DBUG stats/modify_node_event update "global" outgoing_kbitrate (85)
[2009-11-02 23:11:07] DBUG stats/modify_node_event update "/pf-64k.ogg" outgoing_kbitrate (68)
[2009-11-02 23:11:07] DBUG stats/modify_node_event update "/pf-64k.ogg" incoming_bitrate (54064)
[2009-11-02 23:11:07] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_read (18270971)
[2009-11-02 23:11:07] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_sent (21324800)
[2009-11-02 23:11:07] DBUG stats/modify_node_event update "/pf-64k.ogg" total_mbytes_sent (20)
[2009-11-02 23:11:07] DBUG stats/modify_node_event update "/pf-64k.ogg" connected (15983)
[2009-11-02 23:11:07] DBUG stats/modify_node_event update "global" stream_kbytes_sent (20825)
[2009-11-02 23:11:07] DBUG stats/modify_node_event update "global" stream_kbytes_read (20666)
[2009-11-02 23:11:07] DBUG stats/modify_node_event update "global" outgoing_kbitrate (74)
[2009-11-02 23:11:08] DBUG stats/modify_node_event update "global" clients (3)
[2009-11-02 23:11:08] DBUG stats/modify_node_event update "global" connections (457)
[2009-11-02 23:11:08] DBUG stats/modify_node_event update "global" connections (458)
[2009-11-02 23:11:08] DBUG client/worker 0x2871a100 now has 3 clients
[2009-11-02 23:11:08] DBUG connection/_handle_get_request start with /admin/stats.xml
[2009-11-02 23:11:08] DBUG stats/modify_node_event update "global" client_connections (226)
[2009-11-02 23:11:08] INFO admin/admin_handle_general_request processing file stats.xml
[2009-11-02 23:11:08] DBUG stats/modify_node_event update "global" clients (2)
[2009-11-02 23:11:08] DBUG client/worker 0x2871a100 now has 2 clients
[2009-11-02 23:11:08] DBUG stats/modify_node_event update "global" outgoing_kbitrate (88)
[2009-11-02 23:11:09] DBUG stats/modify_node_event update "global" outgoing_kbitrate (74)
[2009-11-02 23:11:10] DBUG stats/modify_node_event update "global" outgoing_kbitrate (72)
[2009-11-02 23:11:11] DBUG stats/modify_node_event update "global" outgoing_kbitrate (71)
[2009-11-02 23:11:12] DBUG stats/modify_node_event update "/pf-64k.ogg" outgoing_kbitrate (67)
[2009-11-02 23:11:12] DBUG stats/modify_node_event update "/pf-64k.ogg" incoming_bitrate (54608)
[2009-11-02 23:11:12] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_read (18303739)
[2009-11-02 23:11:12] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_sent (21366784)
[2009-11-02 23:11:12] DBUG stats/modify_node_event update "/pf-64k.ogg" total_mbytes_sent (20)
[2009-11-02 23:11:12] DBUG stats/modify_node_event update "/pf-64k.ogg" connected (15988)
[2009-11-02 23:11:12] DBUG stats/modify_node_event update "global" stream_kbytes_sent (20866)
[2009-11-02 23:11:12] DBUG stats/modify_node_event update "global" stream_kbytes_read (20706)
[2009-11-02 23:11:12] DBUG stats/modify_node_event update "global" outgoing_kbitrate (69)
[2009-11-02 23:11:13] DBUG stats/modify_node_event update "global" outgoing_kbitrate (68)
[2009-11-02 23:11:14] DBUG stats/modify_node_event update "global" outgoing_kbitrate (68)
[2009-11-02 23:11:15] DBUG stats/modify_node_event update "global" outgoing_kbitrate (68)
[2009-11-02 23:11:16] DBUG stats/modify_node_event update "global" outgoing_kbitrate (67)
[2009-11-02 23:11:17] DBUG stats/modify_node_event update "/pf-64k.ogg" outgoing_kbitrate (65)
[2009-11-02 23:11:17] DBUG stats/modify_node_event update "/pf-64k.ogg" incoming_bitrate (55152)
[2009-11-02 23:11:17] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_read (18340603)
[2009-11-02 23:11:17] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_sent (21407744)
[2009-11-02 23:11:17] DBUG stats/modify_node_event update "/pf-64k.ogg" total_mbytes_sent (20)
[2009-11-02 23:11:17] DBUG stats/modify_node_event update "/pf-64k.ogg" connected (15993)
[2009-11-02 23:11:17] DBUG stats/modify_node_event update "global" stream_kbytes_sent (20906)
[2009-11-02 23:11:17] DBUG stats/modify_node_event update "global" stream_kbytes_read (20747)
[2009-11-02 23:11:17] DBUG stats/modify_node_event update "global" outgoing_kbitrate (67)
[2009-11-02 23:11:18] DBUG stats/modify_node_event update "global" outgoing_kbitrate (65)
[2009-11-02 23:11:19] DBUG stats/modify_node_event update "global" outgoing_kbitrate (66)
[2009-11-02 23:11:20] DBUG stats/modify_node_event update "global" outgoing_kbitrate (65)
[2009-11-02 23:11:21] DBUG stats/modify_node_event update "global" outgoing_kbitrate (64)
[2009-11-02 23:11:22] DBUG stats/modify_node_event update "/pf-64k.ogg" outgoing_kbitrate (65)
[2009-11-02 23:11:22] DBUG stats/modify_node_event update "/pf-64k.ogg" incoming_bitrate (54608)
[2009-11-02 23:11:22] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_read (18373371)
[2009-11-02 23:11:22] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_sent (21449728)
[2009-11-02 23:11:22] DBUG stats/modify_node_event update "/pf-64k.ogg" total_mbytes_sent (20)
[2009-11-02 23:11:22] DBUG stats/modify_node_event update "/pf-64k.ogg" connected (15998)
[2009-11-02 23:11:22] DBUG stats/modify_node_event update "global" stream_kbytes_sent (20947)
[2009-11-02 23:11:22] DBUG stats/modify_node_event update "global" stream_kbytes_read (20787)
[2009-11-02 23:11:22] DBUG stats/modify_node_event update "global" outgoing_kbitrate (65)
[2009-11-02 23:11:23] DBUG stats/modify_node_event update "global" outgoing_kbitrate (64)
[2009-11-02 23:11:24] DBUG stats/modify_node_event update "global" outgoing_kbitrate (64)
[2009-11-02 23:11:25] DBUG stats/modify_node_event update "global" outgoing_kbitrate (64)
[2009-11-02 23:11:26] DBUG stats/modify_node_event update "global" outgoing_kbitrate (64)
[2009-11-02 23:11:27] DBUG stats/modify_node_event update "/pf-64k.ogg" outgoing_kbitrate (64)
[2009-11-02 23:11:27] DBUG stats/modify_node_event update "/pf-64k.ogg" incoming_bitrate (54064)
[2009-11-02 23:11:27] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_read (18406139)
[2009-11-02 23:11:27] DBUG stats/modify_node_event update "/pf-64k.ogg" total_bytes_sent (21490688)
[2009-11-02 23:11:27] DBUG stats/modify_node_event update "/pf-64k.ogg" total_mbytes_sent (20)
[2009-11-02 23:11:27] DBUG stats/modify_node_event update "/pf-64k.ogg" connected (16003)
[2009-11-02 23:11:27] DBUG stats/modify_node_event update "global" stream_kbytes_sent (20987)
[2009-11-02 23:11:27] DBUG stats/modify_node_event update "global" stream_kbytes_read (20828)
[2009-11-02 23:11:27] DBUG stats/modify_node_event update "global" outgoing_kbitrate (65)
[2009-11-02 23:11:28] DBUG stats/modify_node_event update "global" outgoing_kbitrate (65)
[2009-11-02 23:11:29] DBUG stats/modify_node_event update "global" outgoing_kbitrate (64)
[2009-11-02 23:11:30] DBUG stats/modify_node_event update "global" outgoing_kbitrate (64)
The following is my XML Config:
Code: |
<icecast>
<location>New England</location>
<admin>eyetack@powerfrag.fm</admin>
<limits>
<clients>100</clients>
<sources>2</sources>
<queue-size>262114</queue-size>
<client-timeout>30</client-timeout>
<header-timeout>15</header-timeout>
<source-timeout>10</source-timeout>
<burst-size>65535</burst-size>
<max-bandwidth>90M</max-bandwidth>
</limits>
<authentication>
<source-password></source-password>
<admin-user></admin-user>
<admin-password></admin-password>
</authentication>
<directory>
<yp-url-timeout>15</yp-url-timeout>
<yp-url>http://dir.xiph.org/cgi-bin/yp-cgi</yp-url>
</directory>
<hostname>68.112.x.x</hostname>
<port>2112</port>
<listen-socket>
<port>2112</port>
</listen-socket>
<mount>
<mount-name>/pf-64k.ogg</mount-name>
<authentication type="url">
<option name="listener_add" value="http://www.powerfrag.fm/modules/uhq_iceauth/auth.php"/>
<option name="listener_remove" value="http://www.powerfrag.fm/modules/uhq_iceauth/auth.php"/>
<option name="mount_add" value="http://www.powerfrag.fm/modules/uhq_iceauth/auth.php"/>
<option name="mount_remove" value="http://www.powerfrag.fm/modules/uhq_iceauth/auth.php"/>
<option name="stream_auth" value="http://www.powerfrag.fm/modules/uhq_iceauth/auth.php"/>
<option name="user" value="user"/>
<option name="pass" value="pass"/>
<option name="auth_header" value="icecast-auth-user: ok"/>
<option name="timelimit_header" value="icecast-auth-timelimit:"/>
</authentication>
</mount>
<fileserve>1</fileserve>
<paths>
<basedir>/usr/local/share/icecast</basedir>
<logdir>/usr/local/var/log/icecast</logdir>
<webroot>/usr/local/share/icecast/web</webroot>
<adminroot>/usr/local/share/icecast/admin</adminroot>
<alias source="/" dest="/index.html"/>
</paths>
<logging>
<accesslog>access.log</accesslog>
<errorlog>error.log</errorlog>
<!-- <accesslog_ip>0<accesslog_ip> -->
<playlistlog>playlist.log</playlistlog>
<loglevel>4</loglevel> <!-- 4 Debug, 3 Info, 2 Warn, 1 Error -->
<logsize>10000</logsize> <!-- Max size of a logfile -->
<logarchive>1</logarchive>
</logging>
<security>
<chroot>0</chroot>
<changeowner>
<user>nobody</user>
<group>nogroup</group>
</changeowner>
</security>
</icecast>
|
Is there any other information I can try and grab?? _________________ ++I; |
|
Back to top |
|
|
karlH Code Warrior
Joined: 13 Jun 2005 Posts: 5476 Location: UK
|
Posted: Tue Nov 03, 2009 4:15 pm Post subject: |
|
|
The fact that it seems to affect one player and not another would tend to indicate something player specific. If you want to send me a URL I can try it from here.
The logs you posted didn't show a listener disconnecting, only a logical stream change in the first one and a couple of stats requests in the second, so I'm not sure what I'm supposed to be looking for even the outgoing bitrate stats look reasonable.
karl. |
|
Back to top |
|
|
iunderwood
Joined: 23 Aug 2008 Posts: 114 Location: Leicester, MA
|
Posted: Wed Nov 04, 2009 2:40 am Post subject: |
|
|
I agree that it looks somewhat strange. I've been considering regressing through the prior KH branch and seeing if I can find out what version this started occurring on.
I'll PM you the info in a moment. _________________ ++I; |
|
Back to top |
|
|
iunderwood
Joined: 23 Aug 2008 Posts: 114 Location: Leicester, MA
|
Posted: Wed Nov 04, 2009 2:52 am Post subject: |
|
|
Info sent.
For grins, I'm going to regress further back and see what version I can get to behave. _________________ ++I; |
|
Back to top |
|
|
iunderwood
Joined: 23 Aug 2008 Posts: 114 Location: Leicester, MA
|
Posted: Wed Nov 04, 2009 3:06 am Post subject: |
|
|
KH15b - Unable to keep started:
Nov 3 21:53:53 sinewave kernel: pid 1516 (icecast), uid 65534: exited on signal 11
Running KH12 now ... will report before I sack out for the night. _________________ ++I; |
|
Back to top |
|
|
iunderwood
Joined: 23 Aug 2008 Posts: 114 Location: Leicester, MA
|
Posted: Wed Nov 04, 2009 8:51 pm Post subject: |
|
|
So far, patches made last night seem to be holding up well! _________________ ++I; |
|
Back to top |
|
|
iunderwood
Joined: 23 Aug 2008 Posts: 114 Location: Leicester, MA
|
Posted: Thu Nov 05, 2009 4:48 pm Post subject: |
|
|
This appears to be resolved in KH18! Much thanks! _________________ ++I; |
|
Back to top |
|
|
|