search

karlheyes / icecast-kh

KH branch of icecast
GNU General Public License v2.0
300 stars 108 forks source link

clients not transferring to fallback #151

Open markymarrow opened 7 years ago

markymarrow commented 7 years ago

When a source stream disappears, a transfer to the fallback appears to be attempted but all the clients are dumped along the way

log:

[2017-03-08  15:00:09] INFO source/source_add_listener max on /stream1 is -1 (cur 22)
[2017-03-08  15:00:10] WARN source/source_read Disconnecting /stream1 due to socket timeout
[2017-03-08  15:00:10] WARN slave/relay_read stream for /stream1 timed out, skipping server for now
[2017-03-08  15:00:10] INFO slave/relay_read fallback on /stream1 not attempted
[2017-03-08  15:00:10] INFO source/source_shutdown Source "/stream1" exiting
[2017-03-08  15:00:10] INFO slave/relay_read standing by to restart relay on /stream1
[2017-03-08  15:00:10] INFO slave/relay_startup starting on-demand relay /stream1
[2017-03-08  15:00:10] INFO slave/start_relay_stream Starting relayed source at mountpoint "/stream1"
[2017-03-08  15:00:10] INFO slave/open_relay skipping main-server:8000 for /stream1
[2017-03-08  15:00:10] INFO slave/start_relay_stream listener count remaining on /stream1 is 22
[2017-03-08  15:00:10] INFO slave/relay_reset servers to be retried on /stream1
[2017-03-08  15:00:10] INFO slave/relay_read fallback on /stream1 attempted
[2017-03-08  15:00:10] INFO source/source_shutdown Source "/stream1" exiting
[2017-03-08  15:00:10] INFO source/source_set_fallback fallback set on /stream1 to /stream1fb(0) with 22 listeners
[2017-03-08  15:00:10] INFO slave/relay_startup starting on-demand relay /stream1fb
[2017-03-08  15:00:10] INFO slave/start_relay_stream Starting relayed source at mountpoint "/stream1fb"
[2017-03-08  15:00:10] INFO slave/open_relay_connection connecting to 127.0.0.1:8000 for /stream1fb
[2017-03-08  15:00:10] INFO source/source_init Source /stream1fb initialised
[2017-03-08  15:00:10] INFO slave/start_relay_stream source /stream1fb is ready to start
[2017-03-08  15:00:10] INFO source/source_read listener count on /stream1fb now 22
[2017-03-08  15:00:10] INFO source/source_set_override no override for /stream1fb set
[2017-03-08  15:00:10] INFO slave/relay_read standing by to restart relay on /stream1 in 3 seconds
[2017-03-08  15:00:10] INFO slave/relay_reset servers to be retried on /stream1
[2017-03-08  15:00:10] INFO source/source_read listener count on /stream1fb now 0

config:

   <relay> 
        <server>127.0.0.1</server> 
        <port>8000</port> 
        <mount>/blank</mount> 
        <local-mount>/stream1fb</local-mount> 
        <relay-shoutcast-metadata>0</relay-shoutcast-metadata> 
        <on-demand>1</on-demand> 
    </relay> 

    <relay> 
        <server>main-server</server> 
        <port>8000</port> 
        <mount>/stream1</mount> 
        <local-mount>/stream1</local-mount> 
        <on-demand>1</on-demand> 
    </relay> 

    <mount> 
        <mount-name>/stream1</mount-name> 
        <password>xxx</password> 
        <authentication type="url"> 
            <option name="listener_add" value="http://localhost:81/listener_add.php"/> 
            <option name="listener_remove" value="http://localhost:81/listener_remove.php"/> 
            <option name="auth_header" value="icecast-auth-user: 1"/> 
            <option name="timelimit_header" value="icecast-auth-timelimit:"/> 
            <option name="presume_innocent" value="yes"/> 
        </authentication> 

        <fallback-mount>/stream1fb</fallback-mount> 
        <fallback-override>1</fallback-override> 
        <burst-size>300000</burst-size> 
        <bitrate>128</bitrate> 
        <charset>UTF-8</charset> 
        <mp3-metadata-interval>4096</mp3-metadata-interval> 
    </mount> 

    <mount> 
        <mount-name>/stream1fb</mount-name> 
        <hidden>0</hidden> 
        <burst-size>100000</burst-size> 
        <bitrate>128</bitrate> 
        <charset>UTF-8</charset> 
    </mount>

I've been recreating the above scenario (which was caused by a power cut at the source end) by adding a firewall rule on the main-server to DROP any packets from the server showing the issue iptables -I INPUT -s slave-server -p tcp --dport 8000 -j DROP

I can make it behave as expected by modifying source/listener_waiting_on_source

if (source->fallback.mount)
    {
        int ret;

        source_listener_detach (source, client);
+        client->connection.error = 0; // going to fallback

This also appears to fix an issue where a new connection gets a 404 when the main stream is not available and there are not yet any listeners on the fallback. Likely not the correct fix but appears to work-for-me-tm

karlheyes commented 7 years ago

The (0) would indicate no bitrate established, you can add 128k or change the fallback filename to include [128].mp3 at the end.

karl.

markymarrow commented 7 years ago

the fallback mount already has <bitrate>128</bitrate> and it's a relayed source, not a static file. Changing the mount name to /stream1fb-128.mp3 doesn't make a difference. Having the fallback relay being on-demand or always there doesn't make a difference either.

karlheyes commented 7 years ago

note that the 128 was in []

looks like my tags got dropped in the previous post, grr

<limit-rate>128k</limit-rate>

the bitrate field is for YP information.

karl

markymarrow commented 7 years ago

adding limit-rate does change the (0) to (128000) but the listener is still disconnected instead of being moved to the fallback stream

[2017-03-28  08:57:26] INFO mpeg/check_for_mp3 MPEG 1 Layer 3 detected (44100, 1) on 109.169.31.170
[2017-03-28  08:57:26] INFO source/source_set_override for /stream1 set to /stream1fb-128.mp3
[2017-03-28  08:57:42] WARN source/source_read Nothing received on /stream1 for 3 seconds
[2017-03-28  08:57:42] WARN source/source_read Nothing received on /stream1 for 3 seconds
[2017-03-28  08:57:44] WARN source/source_read Disconnecting /stream1 due to socket timeout
[2017-03-28  08:57:44] WARN slave/relay_read stream for /stream1 timed out, skipping server for now
[2017-03-28  08:57:44] INFO slave/relay_read fallback on /stream1 not attempted
[2017-03-28  08:57:44] INFO source/source_shutdown Source "/stream1" exiting
[2017-03-28  08:57:44] INFO slave/relay_read standing by to restart relay on /stream1
[2017-03-28  08:57:44] INFO source/source_apply_mount Applying mount information for "/stream1"
[2017-03-28  08:57:44] INFO slave/relay_startup starting on-demand relay /stream1
[2017-03-28  08:57:44] INFO slave/start_relay_stream Starting relayed source at mountpoint "/stream1"
[2017-03-28  08:57:44] INFO slave/open_relay skipping 109.169.31.170:8000 for /stream1
[2017-03-28  08:57:44] INFO slave/start_relay_stream listener count remaining on /stream1 is 1
[2017-03-28  08:57:44] INFO slave/relay_reset servers to be retried on /stream1
[2017-03-28  08:57:44] INFO slave/relay_read fallback on /stream1 attempted
[2017-03-28  08:57:44] INFO source/source_shutdown Source "/stream1" exiting
[2017-03-28  08:57:44] INFO source/source_set_fallback fallback set on /stream1 to /stream1fb-128.mp3(128000) with 1 listeners
[2017-03-28  08:57:44] INFO slave/relay_read standing by to restart relay on /stream1 in 3 seconds
[2017-03-28  08:57:44] INFO slave/relay_reset servers to be retried on /stream1
[2017-03-28  08:57:47] INFO source/source_apply_mount Applying mount information for "/stream1"
karlheyes commented 7 years ago

hmm, this would indicate no disconnections for the listener. 3 seconds retry time is quite short and it does not go far enough to see what happens at 47 seconds. I'll try a bit later to see the behaviour for a 3 second 44khz mono stream falling back to a 44khz mono file.

karl.

acorkin commented 7 years ago

Just wondering if there is any update with this?

We have tried implementing fallbacks on our relay servers however it's unreliable, only falling back 10% of the time.

Example config from devs:

    <limits>
        <clients>10000</clients>
        <workers>4</workers>
        <sources>5000</sources>
        <queue-size>102400</queue-size>
        <source-timeout>10</source-timeout>
    </limits>

...

<relay>
        <server>X.X.X.X</server>
        <port>XXXX</port>
        <mount>/s123456789/listen</mount>
        <local-mount>/s123456789/listen</local-mount>
        <on-demand>1</on-demand>
        <retry-delay>10</retry-delay>
        <run-on>300</run-on>
    </relay> 
   <mount>
        <mount-name>/fallback_mp3_128</mount-name>
        <bitrate>128</bitrate>
        <limit-rate>128k</limit-rate>
    </mount>

    <mount>
        <mount-name>/*</mount-name>
        <fallback-mount>/fallback_mp3_128</fallback-mount>
        <fallback-override>1</fallback-override>
    </mount>
ErwinP commented 7 years ago

I'm having a similar issue:

from the logs, upon changing a song:

[2017-07-28  09:53:43] INFO source/source_read End of Stream /mopidy.mp3
[2017-07-28  09:53:43] INFO source/source_shutdown Source "/mopidy.mp3" exiting
[2017-07-28  09:53:43] INFO source/source_set_fallback fallback set on /mopidy.mp3 to /mopidy[320].mp3(18231) with 1 listeners
[2017-07-28  09:53:43] INFO fserve/open_fh lookup of fallback file "/mopidy[320].mp3" (18231)
[2017-07-28  09:53:43] INFO mpeg/mpeg_complete_frames no frame sync on 192.168.0.205, re-checking after skipping 25 (8192)
[2017-07-28  09:53:43] INFO mpeg/check_for_mp3 MPEG 2.5 Layer 3 detected (8000, 2) on 192.168.0.205
[2017-07-28  09:53:43] INFO source/source_client_read no more listeners on /mopidy.mp3
[2017-07-28  09:53:43] INFO source/_free_source freeing source "/mopidy.mp3"
[2017-07-28  09:53:45] INFO connection/_handle_source_request Source logging in at mountpoint "/mopidy.mp3"
[2017-07-28  09:53:45] INFO source/source_startup sources count is now 1
[2017-07-28  09:53:45] INFO source/source_apply_mount Applying mount information for "/mopidy.mp3"
[2017-07-28  09:53:45] INFO source/source_startup source /mopidy.mp3 is ready to start
[2017-07-28  09:53:45] INFO source/source_set_override for /mopidy.mp3
[2017-07-28  09:53:45] INFO fserve/fserve_set_override move clients from /mopidy[320].mp3 to /mopidy.mp3
[2017-07-28  09:53:45] INFO source/source_init Source /mopidy.mp3 initialised
[2017-07-28  09:53:45] INFO source/source_read listener count on /mopidy.mp3 now 0

This is the code in my xml:

<mount>
             <mount-name>/mopidy.mp3</mount-name>
             <fallback-mount>/mopidy[320].mp3</fallback-mount>
             <fallback-override>1</fallback-override>
             <bitrate>320</bitrate>
             <limit-rate>320k</limit-rate>
</mount>

Any thoughts on how to get this working?

Thank you in advance, Erwin