Icecast Streaming Media Server Forum Index Icecast Streaming Media Server
Icecast is a Xiph Foundation Project
 
 FAQFAQ   SearchSearch   MemberlistMemberlist   UsergroupsUsergroups   RegisterRegister 
 ProfileProfile   Log in to check your private messagesLog in to check your private messages   Log inLog in 

Possible Stream Regression in KH17

 
Post new topic   Reply to topic    Icecast Streaming Media Server Forum Index -> Dev Branches
View previous topic :: View next topic  
Author Message
iunderwood



Joined: 23 Aug 2008
Posts: 114
Location: Leicester, MA

PostPosted: Tue Nov 03, 2009 4:23 am    Post subject: Possible Stream Regression in KH17 Reply with quote

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
View user's profile Send private message
karlH
Code Warrior
Code Warrior


Joined: 13 Jun 2005
Posts: 5476
Location: UK

PostPosted: Tue Nov 03, 2009 4:15 pm    Post subject: Reply with quote

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
View user's profile Send private message Send e-mail Visit poster's website
iunderwood



Joined: 23 Aug 2008
Posts: 114
Location: Leicester, MA

PostPosted: Wed Nov 04, 2009 2:40 am    Post subject: Reply with quote

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
View user's profile Send private message
iunderwood



Joined: 23 Aug 2008
Posts: 114
Location: Leicester, MA

PostPosted: Wed Nov 04, 2009 2:52 am    Post subject: Reply with quote

Info sent.

For grins, I'm going to regress further back and see what version I can get to behave.
_________________
++I;
Back to top
View user's profile Send private message
iunderwood



Joined: 23 Aug 2008
Posts: 114
Location: Leicester, MA

PostPosted: Wed Nov 04, 2009 3:06 am    Post subject: Reply with quote

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
View user's profile Send private message
iunderwood



Joined: 23 Aug 2008
Posts: 114
Location: Leicester, MA

PostPosted: Wed Nov 04, 2009 8:51 pm    Post subject: Reply with quote

So far, patches made last night seem to be holding up well!
_________________
++I;
Back to top
View user's profile Send private message
iunderwood



Joined: 23 Aug 2008
Posts: 114
Location: Leicester, MA

PostPosted: Thu Nov 05, 2009 4:48 pm    Post subject: Reply with quote

This appears to be resolved in KH18! Much thanks!
_________________
++I;
Back to top
View user's profile Send private message
Display posts from previous:   
Post new topic   Reply to topic    Icecast Streaming Media Server Forum Index -> Dev Branches All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum


Powered by phpBB © 2001, 2002 phpBB Group
subRebel style by ktauber