listener_remove reliability #6

DuncanFairley · 2012-03-22T00:14:45Z

My icecast setup is pretty vanilla - the only real difference from the norm is that I have listener_add and listener_remove calling a PHP script which adds and removes a row to a MySQL database for that listener's session.

The script is really basic, and I'm very confident it's not to blame here. The MySQL database is also local, using a stable build, etc., etc.
Quite rarely, listener_remove somehow won't call the PHP script when a listener drops. I haven't been able to replicate the situation where this occurs. It might happen once every couple weeks, but it's enough to throw off my stats.

I rarely restart Icecast itself, but I do kill -HUP every couple weeks for config changes.

Any pointers on where I should be looking to recreate this issue so it can get fixed?

karlheyes · 2012-03-22T01:15:43Z

Difficult to come up with a simple way to spot any issue. Obviously updating to the latest on github is a good start as I'm in a slow-down to release, but I'm not aware of any listener_remove issue in recent times. There has been cases of a stuck listener which is where a lack of writing did not trigger a termination and therefore the auth trigger.

You could in the listener_add script query the global listeners count (a custom xsl could make it simple) from icecast and compare that number with the row count in your table.

karl.

Allmoz · 2012-03-22T11:42:20Z

since i do something similar, i will try to confirm if this happens to me too in the next weeks

Allmoz · 2012-03-29T04:38:58Z

hu i was sure i had reply to this one again....well...
sinece the last post i got 9 missing listener remove from almost 50.000 listener_add ( 53k clientId )

karlheyes · 2012-03-29T11:03:24Z

On 29/03/12 05:38, Allmoz wrote:

hu i was sure i had reply to this one again....well...
sinece the last post i got 9 missing listener remove from almost 50.000 listener_add ( 53k clientId )

Can you tells me what your configuration is like and what requests are
being made by listeners. I'm wondering if it is because of alias or
on-demand relay failures.

karl.

Allmoz · 2012-03-29T11:28:00Z

hum for some time was whit / so it got all the trafic.
im not using relays nor alias. since it seams that doing / and after adding /stream
dont work to extend a single mountpoint configuration y had to make an include to a folder whit each mount configuration.
since then, there were 3 more lost listener_remove, the last two had the same listener_add timestamp.

icecast.xml

<limits>
    <clients>500</clients>
    <sources>6</sources>
    <queue-size>524288</queue-size>
    <client-timeout>120</client-timeout>
    <header-timeout>60</header-timeout>
    <source-timeout>40</source-timeout>
    <burst-size>65535</burst-size>
</limits>

<authentication>
    <source-password>hackme</source-password>
    <admin-user>admin</admin-user>
    <admin-password>hackme</admin-password>
</authentication>

<hostname>radio.cemzoo.com</hostname>

<directory>
    <yp-url-timeout>15</yp-url-timeout>
    <yp-url>http://dir.xiph.org/cgi-bin/yp-cgi</yp-url>
</directory>

<listen-socket>
    <port>8000</port>
    <bind-address>207.150.162.160</bind-address>
    <shoutcast-mount>/stream</shoutcast-mount>
</listen-socket>

<fileserve>1</fileserve>

<paths>
    <basedir>/usr/local/share/icecast</basedir>
    <logdir>/var/log/icecast</logdir>
    <webroot>/usr/local/share/icecast/web</webroot>
    <adminroot>/usr/local/share/icecast/admin</adminroot>
    <pidfile>/var/run/icecast/icecast.pid</pidfile>
    <alias source="/" dest="/index.html"/>
</paths>

<logging>
    <accesslog>access2.log</accesslog>
    <errorlog>error2.log</errorlog>
    <playlistlog>playlist.log</playlistlog>
    <loglevel>3</loglevel> <!-- 4 Debug, 3 Info, 2 Warn, 1 Error -->
</logging>

<security>
    <chroot>0</chroot>
    <changeowner>
        <user>icecast</user>
        <group>icecast</group>
    </changeowner>
</security>

<include>/opt/radio/xml/mounts/8000*.xml</include>

8000stream.xml

<mount>
    <mount-name>/stream</mount-name>
    <stream-description>CemZoo Radiostation</stream-description>
    <stream-url>http://radio.cemzoo.com:8000</stream-url>
    <fallback-mount>/fallback</fallback-mount>
    <fallback-override>1</fallback-override>
    <authentication type="url">
         <option name="stream_auth"    value="http://radio.xxxxxx.com/bin/ice_auth.php"/>
         <option name="mount_add"    value="http://radio.xxxxxx.com/bin/ice_auth.php"/>
         <option name="mount_remove" value="http://radio.xxxxxx.com/bin/ice_auth.php"/>
         <option name="listener_add"    value="http://radio.xxxxxx.com/bin/ice_auth.php"/>
         <option name="listener_remove" value="http://radio.xxxxxxxx.com/bin/ice_auth.php"/>
    </authentication>
    <on-connect>/usr/local/bin/icecast_connect</on-connect>
    <on-disconnect>/usr/local/bin/icecast_disconnect</on-disconnect>    
    <dump-file>/home/radio/dump/cz.radio.ogg</dump-file> 
</mount>

and the listener_end SQL

    $db = Registry::getPdoDb();
    $st = $db->prepare("
        UPDATE logListener SET
            end = :end,
            duration = :duration
        WHERE
            server = :server AND
            port = :port AND
            clientId = :clientId AND
            ip = :ip AND
            ISNULL(end)
        ");

    $st->bindValue(':end', date("Y-m-d H:i:s",time()));
    $st->bindValue(':duration', $icececast->duration);
    $st->bindValue(':server', $icececast->server);
    $st->bindValue(':port', $icececast->port);
    $st->bindValue(':clientId', $icececast->clientId);
    $st->bindValue(':ip', $icececast->ip);
    $st->execute();

one option is that in rare cases the end ip is different from the start one, here is the entries

tell me what more should i seek for ^^

karlheyes · 2012-03-29T18:06:10Z

On 29/03/12 12:28, Allmoz wrote:

hum for some time was whit/ so it got all the trafic.
im not using relays nor alias. since it seams that doing/ and after adding/stream
dont work to extend a single mountpoint configuration y had to make an include to a folder whit each mount configuration.
since then, there were 3 more lost listener_remove, the last one whit had the same listener_add timestamp.

If you use the /* matching then you can exclude certain requests by
placing them before the /* This may be ideal for requests like /.xsl
or /images/ etc where you do not want url auth to be used. eg

8000stream.xml
/stream CemZoo Radiostation http://radio.cemzoo.com:8000 /fallback 1 /usr/local/bin/icecast_connect /usr/local/bin/icecast_disconnect /home/radio/dump/cz.radio.ogg

What is fallback (file or stream) and are these listeners getting to
fallback when they disconnect? The code as it is currently, if listener
requests /stream and the above mount matches then listener_add is called
as you expect, if they disconnect or fallback and disconnect then
/stream is picked out again and should match this mountpoint again for
the listener_remove

I'm just wondering if there were any rejections after auth that caused
listeners to drop before getting to the stream. Look for GET /stream
attempts from access log that had a short duration or a 4xx response
instead of the usual 200

karl.

Allmoz · 2012-03-29T21:27:11Z

nice, anyway i need to add

    <on-connect>/usr/local/bin/icecast_connect</on-connect>
    <on-disconnect>/usr/local/bin/icecast_disconnect</on-disconnect>
    <dump-file>/home/radio/dump/cz.radio.ogg</dump-file>

to certain mount point, so i need to configure them anyway
im think to make php create the mount xml files to the folder, and send the configuration update request

the /fallback is just a mount point

<mount>
    <mount-name>/fallback</mount-name>
    <hidden>1</hidden>
    <stream-description>CemZoo Radiostation</stream-description>
    <stream-url>http://radio.cemzoo.com:8000</stream-url>
    <authentication type="url">
         <option name="stream_auth"    value="http://radio.xxxxxx.com/bin/ice_auth.php"/>
         <option name="mount_add"    value="http://radio.xxxxxxx.com/bin/ice_auth.php"/>
         <option name="mount_remove" value="http://radio.xxxxxx.com/bin/ice_auth.php"/>
         <option name="listener_add"    value="http://radio.xxxxx.com/bin/ice_auth.php"/>
         <option name="listener_remove" value="http://radio.xxxxxx.com/bin/ice_auth.php"/>
    </authentication>
</mount>

fallback is almost not used, since most of ppl dont know that exist, or how to use it

that are the only 2 mount points configurated... also the fallback configuration is only working after y separated the mount to the include path, cose that info whas after the /* match.

whit 4xx there are hundreds.. cose ppl leave winamp trying to conect... every 1 second after the stream ends....

Allmoz · 2012-03-29T21:56:31Z

if ti help for the missing listener_remove on ip 201.215.228.235 there is no access error in the log whit that ip
i use header('icecast-auth-user: 1') to authenticate

karlheyes · 2012-03-29T23:42:16Z

I do not have access to your logs, what messages appeared at the time that IP connected, did you see the listener count increasing?

karl.

karlheyes · 2012-04-18T00:58:09Z

Can you check against kh32. I did fix a case where a listener_remove may not of been done

karl.

Allmoz · 2012-04-18T10:14:04Z

yups, im testing that since moonday, already got 3, listener add, whiout their listener remove

2012-04-17 21:35:52 14 radio.xxx.yyy 8000 /stream 64.76.13.x Argentina
2012-04-17 21:36:27 - radio.xxx.yyy 8000 /stream 64.76.13.x Argentina
2012-04-17 21:37:42 387 radio.xxx.yyy 8000 /stream 64.76.13.x Argentina

2012-04-18 00:04:36 3 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:04:36 103 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:04:39 109 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:06:23 53 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:06:58 7 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:07:05 17 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:07:23 35 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:07:26 34 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:08:01 22 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:08:10 140 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:08:26 131 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:10:36 177 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:10:45 - radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:14:01 447 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico
2012-04-18 00:14:02 447 radio.xxx.yyy 8000 /stream 189.183.172.x Mexico

2012-04-18 02:28:26 - radio.xxx.yyy 8000 /stream 201.102.92.x Mexico
2012-04-18 02:30:47 894 radio.xxx.yyy 8000 /stream 201.102.92.x Mexico

the ones whitout duration are the issues...

now in kh32

Allmoz · 2012-04-18T15:46:54Z

well... when a conection is refused for a add_listener
for example for a bad password in aprivate mount, there will be no listener_remove <-- could it be that is something related to this ?

karlheyes · 2012-04-18T16:14:35Z

On 18/04/12 16:46, Allmoz wrote:

well... when a conection is refused for a add_listener
for example for a bad password in aprivate mount, there will be no listener_remove<-- could it be that is something related to this ?

If the listener_add rejects the listener then listener_remove will not
be called but other than that it should be called even if they are
rejected for other reasons. You may be finding a way that is not handled
and that is what needs to be identified.

karl

Allmoz · 2012-04-18T20:05:05Z

ok... is fine that if it is rejected then there is no listener_remove,
i havent fully implemented private mount point, so im allowing all, so is not the case in here,
but maybe the server is mistaking some listener_add reponse as rejected and it dont send the listener_remove
(how should i look for that ?)

Allmoz · 2012-04-24T03:58:08Z

¿there is a time limit for the response for listener_add ?
if there is, it could be that icecast denies the listener by time out on the authentication
and the script logs it as a valid, since he don't know that it did timeout sending the authentication response.

Allmoz · 2012-05-22T15:38:26Z

1 week
and no listener_remove missing
:D

karlheyes · 2012-05-25T14:07:21Z

shall we close this for now if the issue looks to be resolved.

karl.

Allmoz · 2012-05-25T19:51:58Z

ok, but i will keep an eye on it, since there is not too much trafic on my server ( max 15 listener lately )

DuncanFairley · 2012-05-25T20:04:12Z

I intend to update tonight and flush the database. I'll let you know in a couple days how it goes.

DuncanFairley · 2012-06-02T06:42:21Z

I've been running kh32 for about a week now.
So far there's 6 stray listeners that didn't call listener_remove.

Allmoz · 2012-06-08T02:35:02Z

just to keep track i will start listing the circunstances of the my lost listeners_remove:

1 - d59776c - type=.flv - inestable source & 10 minutes before mount_remove (4 listeners_remove effective)

Allmoz · 2012-06-08T02:54:36Z

i did just realize that.... i get extra listener remove.... from the source....

action=listener_remove&server=radio.xxxxx.com&port=8000&client=3473&mount=/stream&user=source&pass=xxxxxxxxxxx&ip=201.157.xxx.xxx&duration=0

afther some

action=stream_auth&mount=/stream&ip=201.157.xxx.xxx&server=radio.xxxxxx.com&port=8000&user=source&pass=xxxxxxi&admin=1

but not always

karlheyes · 2012-06-09T00:54:30Z

The duration of 0 may be of interest here, what can you tell me about client 3473 (or any others in a similar position) what reason led them to disconnect immediately?

The second URL is an admin request wanting verifying, probably /admin/metadata

karl.

Allmoz · 2012-06-09T01:42:47Z

well... je is the source.... and the id it should be the one of that action=stream_auth
cose there is no listener_add whit that id, and it kinds of... fit
i will try to contact that source to see if she is using edcast / shoutcast or other source

Allmoz · 2012-06-09T02:45:44Z

it has happend 14 times, of.... 46,017 calls to the auth
i will clean al log again.... i will try to log it a litle ... cleaner

Allmoz · 2012-06-09T23:21:15Z

24 listener_remove whit source logging data on a laggy (20 reconnections, over 3g internet)

the client id "12740" seems to be in order whit normal listener_add client id..

the last id before that is added 40 second before "12736" then a admin=1 source_auth, after that
"12736" is removed, then a normal source_auth ( same source ).
and then the "12740" listener_remove whit the user pass and ip of the source

happens especially on laggy source connections

i will keep an eye if it happens too whit 619ae4a

Allmoz · 2012-06-12T00:01:35Z

ok...
the extra listener_remove .. come as response of a stream_auth ( whitout admin=1 , but theres is one near) in the same second.... nearly before... a mount_remove....

so.. it seems to be related to metadata update, and disconnection by no data from the source....

beside that, no listener_remove missing yet

karlheyes · 2012-06-12T01:47:10Z

A typical non-ogg metadata update does need to authenticate as the update is based on a GET request on /admin/metadata, you should be able to see it on the access log. The &admin=1 is there just so that you know that it's authenticating from /admin requests and not SOURCE.

karl.

Allmoz · 2012-06-25T21:26:04Z

hum....
action=listener_remove&server=radio.xxxxxxx.com&port=8000&client=4894&mount=/stream&user=source&pass=xxxxxxx&ip=186.66.53.xxx&duration=0&sent=59

all of them are &sent=59

karlheyes · 2012-06-25T21:40:37Z

sent is supposed to be the bytes sent to that client. It could be down to a stalled stream but the size wouldn't indicate that. I think it may be down to a 64bit issue. Mines ok and that was ok for the prople reporting it, but if you are on a 32bit setup then that may be the cause.

Fix committed for that, but should be no impact otherwise. How are we about the reliability of these being called now?

karl.

Allmoz · 2013-03-21T21:59:02Z

ok :D! find in which case a listener_remove whit source data is generated!

there is a stream in /stream <-- just fine

some ones try to conect as source at /stream
url_auth sends the ok head to icecast ( i havent implemented override yet) <-- the source client was shoutcast
the listener remove is generated whit that source info

♪that's the way you doit!♫

karlheyes · 2013-03-22T13:15:23Z

fixed in github. The source attempt passed url auth as expected but as there was no hijack set then the connection failed because the stream was active. This case then drops via the 403 handler which triggered the listener_remove. I've no expanded the test on that to make sure it only applies to GET requests and therefore you should be ok on that.

Allmoz · 2013-03-24T14:16:29Z

nice, i will give feedback as soon as i can

karlheyes · 2013-04-24T21:28:59Z

just release kh7 so if you are to confirm a fix then this would be the one to try.

karl.

Allmoz · 2013-04-24T22:08:54Z

i'm still having a few of listener_remove duplicated
but there is no listener_remove whit source data anymore, yay! :3

karlheyes · 2013-04-24T23:36:57Z

make sure you are on kh7 and then let me know what happens for the duplicated case, just like you did for the source client triggering listener_remove.

karl.

Allmoz · 2013-04-25T00:49:00Z

ok, im on that 👍

Allmoz · 2013-04-27T03:30:31Z

up to now :3 perfect record
i will report about this in one week

Allmoz · 2013-05-01T00:36:55Z

: / sad

happend 2 times

Allmoz · 2013-05-01T00:42:33Z

size of the data send by that source both times 0 ( stream dump files are size 0 )

karlheyes · 2013-05-01T01:42:48Z

I see there is a mount_remove event at the same time, can you find out in what way the mount terminated, was it a normal close or a timeout for example. Just wondering if there was any odd error case leading to it.

karl.

Allmoz · 2013-05-01T02:24:25Z

it only triggers if there is a listener on that empy mount after 10 seconds is "kicked"
the mount remains free
the source does not detect that was disconnected (maybe that send=77 was for him)

     <clients>500<clients>
     <sources>4<sources>
     <queue-size>327680<queue-size>
     <client-timeout>60<client-timeout>
     <header-timeout>30<header-timeout>
     <source-timeout>20<source-timeout>
     <burst-size>131072<burst-size>

stoped the servers, cleaned al log started, trigered, closed the servers... y didnt see anything suspicius in the logs but here thay are

Allmoz · 2013-05-01T02:24:34Z

190.160.242.44 - - [30/Apr/2013:22:15:38 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:39 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:40 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:41 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:42 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 1
190.160.242.44 - - [30/Apr/2013:22:15:42 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:54 -0400] "GET /stream HTTP/1.0" 404 77 "-" "WinampMPEG/5.63, Ultravox/2.1" 11
190.160.242.44 - source [30/Apr/2013:22:15:54 -0400] "SOURCE /stream ICE/1.0" 200 0 "-" "-" 12
190.160.242.44 - - [30/Apr/2013:22:15:55 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:55 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:56 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:57 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:58 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:58 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:15:59 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0
190.160.242.44 - - [30/Apr/2013:22:16:00 -0400] "GET /stream HTTP/1.0" 404 105 "-" "WinampMPEG/5.63, Ultravox/2.1" 0

Allmoz · 2013-05-01T02:25:07Z

[2013-04-30 22:15:33] INFO thread/ lock abort set to 0
[2013-04-30 22:15:33] INFO main/server_process Icecast 2.3.3-kh7 server started
[2013-04-30 22:15:33] WARN slave/slave_startup process has 4096 max file descriptor limit
[2013-04-30 22:15:33] INFO client/workers_adjust requested worker count 1
[2013-04-30 22:15:33] DBUG yp/yp_recheck_config Updating YP configuration
[2013-04-30 22:15:33] INFO yp/yp_recheck_config Adding new YP server "http://dir.xiph.org/cgi-bin/yp-cgi" (timeout 15s, default interval 600s)
[2013-04-30 22:15:33] INFO yp/yp_client_add Starting Directory client for YP processing
[2013-04-30 22:15:33] DBUG source/source_recheck_mounts fallback checking /fallback (nil)
[2013-04-30 22:15:33] DBUG source/source_recheck_mounts fallback checking /stream (nil)
[2013-04-30 22:15:33] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:33] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:33] INFO connection/connection_thread connection thread started
[2013-04-30 22:15:33] INFO connection/get_ssl_certificate No SSL capability on any configured ports
[2013-04-30 22:15:33] DBUG client/worker 0xef0aa0 now has 0 clients
[2013-04-30 22:15:33] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:33] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:33] DBUG yp/check_servers Add pending yps http://dir.xiph.org/cgi-bin/yp-cgi
[2013-04-30 22:15:34] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:34] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:35] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:35] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:36] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:36] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:37] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:37] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:38] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:38] DBUG stats/modify_node_event update "global" connections (1)
[2013-04-30 22:15:38] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:38] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:38] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:38] DBUG stats/modify_node_event update "global" client_connections (1)
[2013-04-30 22:15:38] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:38] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:38] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:38] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:38] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:38] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:38] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:38] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:38] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:38] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:38] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:38] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:38] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:38] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:38] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:38] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:38] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:38] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:38] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:38] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:38] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:38] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:38] DBUG stats/modify_node_event update "global" outgoing_kbitrate (21)
[2013-04-30 22:15:39] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:39] DBUG stats/modify_node_event update "global" connections (2)
[2013-04-30 22:15:39] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:39] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:39] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:39] DBUG stats/modify_node_event update "global" client_connections (2)
[2013-04-30 22:15:39] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:39] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:39] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:39] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:39] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:39] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:39] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:39] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:39] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:39] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:39] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:39] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:39] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:39] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:39] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:39] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:39] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:39] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:39] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:39] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:39] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:39] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:39] DBUG stats/modify_node_event update "global" outgoing_kbitrate (4)
[2013-04-30 22:15:40] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:40] DBUG stats/modify_node_event update "global" connections (3)
[2013-04-30 22:15:40] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:40] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:40] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:40] DBUG stats/modify_node_event update "global" client_connections (3)
[2013-04-30 22:15:40] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:40] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:40] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:40] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:40] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:40] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:40] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:40] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:40] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:40] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:40] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:40] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:40] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:40] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:40] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:40] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:40] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:40] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:40] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:40] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:40] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:40] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:40] DBUG stats/modify_node_event update "global" outgoing_kbitrate (1)
[2013-04-30 22:15:41] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:41] DBUG stats/modify_node_event update "global" connections (4)
[2013-04-30 22:15:41] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:41] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:41] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:41] DBUG stats/modify_node_event update "global" client_connections (4)
[2013-04-30 22:15:41] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:41] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:41] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:41] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:41] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:41] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:41] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:41] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:41] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:41] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:41] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:41] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:41] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:41] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:41] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:41] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:41] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:41] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:41] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:41] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:41] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:41] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:41] DBUG stats/modify_node_event update "global" connections (5)
[2013-04-30 22:15:41] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:41] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:41] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:41] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:42] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:42] DBUG stats/modify_node_event update "global" client_connections (5)
[2013-04-30 22:15:42] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:42] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:42] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:42] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:42] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:42] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:42] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:42] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:42] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:42] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:42] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:42] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:42] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:42] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:42] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:42] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:42] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:42] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:42] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:42] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:42] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:42] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:42] DBUG stats/modify_node_event update "global" connections (6)
[2013-04-30 22:15:42] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:42] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:42] DBUG stats/modify_node_event update "global" clients (2)
[2013-04-30 22:15:42] DBUG stats/modify_node_event update "global" connections (7)
[2013-04-30 22:15:42] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:42] DBUG client/worker 0xef0aa0 now has 3 clients
[2013-04-30 22:15:42] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:42] DBUG stats/modify_node_event update "global" client_connections (6)
[2013-04-30 22:15:42] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:42] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:42] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:42] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:42] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:42] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:42] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:42] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:42] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:42] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:42] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:42] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:42] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:42] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:42] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:42] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:42] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:42] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:42] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:42] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:42] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:42] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:42] DBUG stats/modify_node_event update "global" outgoing_kbitrate (4)
[2013-04-30 22:15:43] INFO connection/_handle_source_request Source logging in at mountpoint "/stream"
[2013-04-30 22:15:43] INFO auth/auth_stream_authenticate request source auth for "/stream"
[2013-04-30 22:15:43] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:43] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:43] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:43] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:43] DBUG auth/auth_postprocess_source on mountpoint /stream
[2013-04-30 22:15:43] INFO source/source_startup sources count is now 1
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "global" sources (1)
[2013-04-30 22:15:43] DBUG stats/stats_handle new source stat /stream
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "listenurl" (http://oye.piratasradio.com:9000/stream)
[2013-04-30 22:15:43] INFO source/source_apply_mount Applying mount information for "/stream"
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "listener_peak" (0)
[2013-04-30 22:15:43] DBUG format-mp3/format_mp3_apply_settings sending metadata interval 16000
[2013-04-30 22:15:43] DBUG format-mp3/format_mp3_apply_settings charset ISO8859-1
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "public" (1)
[2013-04-30 22:15:43] DBUG source/source_apply_mount YP changed to 1
[2013-04-30 22:15:43] DBUG yp/yp_add Adding /stream to http://dir.xiph.org/cgi-bin/yp-cgi
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "server_name" (Pirate Test!)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "server_description" (Pirata's Radio)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "server_url" (http://oye.piratasradio.com:9000/stream)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "genre" (Allmoz)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "bitrate" (64)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "server_type" (audio/mpeg)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "authenticator" (url)
[2013-04-30 22:15:43] DBUG source/source_update_settings max listeners to -1
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "max_listeners" (-1)
[2013-04-30 22:15:43] DBUG source/source_update_settings public set to 1
[2013-04-30 22:15:43] DBUG source/source_update_settings queue size to 327680
[2013-04-30 22:15:43] DBUG source/source_update_settings min queue size to 131072
[2013-04-30 22:15:43] DBUG source/source_update_settings burst size to 131072
[2013-04-30 22:15:43] DBUG source/source_update_settings source timeout to 10
[2013-04-30 22:15:43] INFO source/source_startup source /stream is ready to start
[2013-04-30 22:15:43] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:43] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "global" source_client_connections (1)
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "global" source_total_connections (1)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "slow_listeners" (0)
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "/stream" server_type (audio/mpeg)
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "/stream" listener_peak (0)
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "/stream" listener_peak (0)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "listener_connections" (0)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "stream_start" (30/Apr/2013:22:15:43 -0400)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "total_mbytes_sent" (0)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "total_bytes_sent" (0)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "total_bytes_read" (0)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "outgoing_kbitrate" (0)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "incoming_bitrate" (0)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "queue_size" (0)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "connected" (0)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "source_ip" (190.160.242.44)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "ice-samplerate" (44100)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "ice-bitrate" (64)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "ice-channels" (2)
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "audio_info" (ice-samplerate=44100;ice-bitrate=64;ice-channels=2)
[2013-04-30 22:15:43] INFO auth/auth_stream_start request source start for "/stream"
[2013-04-30 22:15:43] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:43] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:43] INFO source/source_set_override for /stream
[2013-04-30 22:15:43] DBUG source/source_set_override checking for /fallback on /stream
[2013-04-30 22:15:43] DBUG fserve/find_fh /fallback (4) not found
[2013-04-30 22:15:43] INFO source/source_init Source /stream initialised
[2013-04-30 22:15:43] INFO source/source_read listener count on /stream now 0
[2013-04-30 22:15:43] DBUG stats/process_source_stat new node on /stream "listeners" (0)
[2013-04-30 22:15:43] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:43] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:43] DBUG auth_url/url_stream_start handler 0 sending request
[2013-04-30 22:15:43] DBUG auth_url/url_stream_start handler 0 request finished
[2013-04-30 22:15:43] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:43] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "global" clients (2)
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "global" connections (8)
[2013-04-30 22:15:43] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:43] DBUG client/worker 0xef0aa0 now has 3 clients
[2013-04-30 22:15:43] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "global" client_connections (7)
[2013-04-30 22:15:43] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:43] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:43] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:43] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:43] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:43] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:43] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:43] INFO source/source_add_listener max on /stream is -1 (cur 0)
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "global" listeners (1)
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "global" listener_connections (1)
[2013-04-30 22:15:43] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:43] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:43] INFO source/source_read listener count on /stream now 1
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "/stream" listeners (1)
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "/stream" listener_peak (1)
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:43] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:43] DBUG yp/add_pending_yp 1 YP entries added to http://dir.xiph.org/cgi-bin/yp-cgi
[2013-04-30 22:15:44] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:44] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:45] DBUG source/source_recheck_mounts fallback checking /fallback (nil)
[2013-04-30 22:15:45] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:45] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:46] DBUG stats/modify_node_event update "/stream" outgoing_kbitrate (0)
[2013-04-30 22:15:46] DBUG stats/modify_node_event update "/stream" incoming_bitrate (0)
[2013-04-30 22:15:46] DBUG stats/modify_node_event update "/stream" total_bytes_read (0)
[2013-04-30 22:15:46] DBUG stats/modify_node_event update "/stream" total_bytes_sent (0)
[2013-04-30 22:15:46] DBUG stats/modify_node_event update "/stream" total_mbytes_sent (0)
[2013-04-30 22:15:46] DBUG stats/modify_node_event update "/stream" queue_size (0)
[2013-04-30 22:15:46] DBUG stats/modify_node_event update "/stream" connected (4)
[2013-04-30 22:15:46] WARN source/source_read Nothing received on /stream for 3 seconds
[2013-04-30 22:15:46] WARN source/source_read Nothing received on /stream for 3 seconds
[2013-04-30 22:15:46] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:46] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:47] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:47] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:48] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:48] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:49] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:49] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:50] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:50] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:51] DBUG stats/modify_node_event update "/stream" outgoing_kbitrate (0)
[2013-04-30 22:15:51] DBUG stats/modify_node_event update "/stream" incoming_bitrate (0)
[2013-04-30 22:15:51] DBUG stats/modify_node_event update "/stream" total_bytes_read (0)
[2013-04-30 22:15:51] DBUG stats/modify_node_event update "/stream" total_bytes_sent (0)
[2013-04-30 22:15:51] DBUG stats/modify_node_event update "/stream" total_mbytes_sent (0)
[2013-04-30 22:15:51] DBUG stats/modify_node_event update "/stream" queue_size (0)
[2013-04-30 22:15:51] DBUG stats/modify_node_event update "/stream" connected (9)
[2013-04-30 22:15:51] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:51] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:52] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:52] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:53] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:53] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:54] DBUG source/source_read last 1367374543, timeout 10, now 1367374554
[2013-04-30 22:15:54] WARN source/source_read Disconnecting /stream due to socket timeout
[2013-04-30 22:15:54] INFO source/source_shutdown Source "/stream" exiting
[2013-04-30 22:15:54] DBUG source/source_listeners_wakeup listener on /stream was ahead by 199
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "/stream" outgoing_kbitrate (0)
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "/stream" incoming_bitrate (0)
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "/stream" total_bytes_read (0)
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "/stream" total_bytes_sent (0)
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "/stream" total_mbytes_sent (0)
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "/stream" queue_size (0)
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "/stream" connected (12)
[2013-04-30 22:15:54] INFO auth/auth_stream_end request source end for "/stream"
[2013-04-30 22:15:54] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:54] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:54] INFO source/source_set_fallback fallback set on /stream to /fallback(0) with 1 listeners
[2013-04-30 22:15:54] DBUG source/source_client_read removing source /stream from tree
[2013-04-30 22:15:54] DBUG stats/_free_source_stats delete source node /stream
[2013-04-30 22:15:54] DBUG source/source_client_read /stream waiting (1, 1)
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "global" listeners (0)
[2013-04-30 22:15:54] DBUG auth/queue_auth_client starting auth thread 1
[2013-04-30 22:15:54] DBUG auth/queue_auth_client auth on /stream has 2 pending
[2013-04-30 22:15:54] DBUG auth/auth_run_thread Authentication thread 1 started for /stream
[2013-04-30 22:15:54] DBUG auth/auth_run_thread 2 client(s) pending on /stream
[2013-04-30 22:15:54] DBUG auth_url/url_stream_end handler 1 sending request
[2013-04-30 22:15:54] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:54] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:54] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:54] DBUG auth_url/url_stream_end handler 1 request finished
[2013-04-30 22:15:54] DBUG auth/auth_run_thread Authenication thread 1 shutting down
[2013-04-30 22:15:54] DBUG auth/auth_release ...refcount on auth_t /stream is now 2
[2013-04-30 22:15:54] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:54] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:54] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:54] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:54] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:54] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:54] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:54] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:54] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:54] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:54] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:54] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:54] INFO source/source_client_read no more listeners on /stream
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "global" sources (0)
[2013-04-30 22:15:54] DBUG source/source_clear_source clearing source "/stream"
[2013-04-30 22:15:54] DBUG yp/yp_remove release /stream on YP http://dir.xiph.org/cgi-bin/yp-cgi
[2013-04-30 22:15:54] INFO source/_free_source freeing source "/stream"
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:54] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:54] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:54] DBUG yp/delete_marked_yp removed /stream from YP server http://dir.xiph.org/cgi-bin/yp-cgi
[2013-04-30 22:15:55] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:55] DBUG stats/modify_node_event update "global" connections (9)
[2013-04-30 22:15:55] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:55] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:55] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:55] DBUG stats/modify_node_event update "global" client_connections (8)
[2013-04-30 22:15:55] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:55] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:55] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:55] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:55] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:55] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:55] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:55] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:55] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:55] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:55] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:55] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:55] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:55] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:55] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:55] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:55] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:55] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:55] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:55] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:55] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:55] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:55] DBUG stats/modify_node_event update "global" connections (10)
[2013-04-30 22:15:55] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:55] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:55] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:55] DBUG stats/modify_node_event update "global" client_connections (9)
[2013-04-30 22:15:55] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:55] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:55] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:55] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:55] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:55] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:55] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:55] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:55] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:55] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:55] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:55] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:55] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:55] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:55] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:55] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:55] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:55] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:55] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:55] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:55] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:55] DBUG source/source_recheck_mounts fallback checking /fallback (nil)
[2013-04-30 22:15:55] DBUG source/source_recheck_mounts fallback checking /stream (nil)
[2013-04-30 22:15:55] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:55] DBUG stats/modify_node_event update "global" outgoing_kbitrate (13)
[2013-04-30 22:15:56] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:56] DBUG stats/modify_node_event update "global" connections (11)
[2013-04-30 22:15:56] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:56] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:56] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:56] DBUG stats/modify_node_event update "global" client_connections (10)
[2013-04-30 22:15:56] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:56] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:56] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:56] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:56] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:56] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:56] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:56] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:56] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:56] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:56] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:56] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:56] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:56] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:56] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:56] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:56] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:56] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:56] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:56] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:56] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:56] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:56] DBUG stats/modify_node_event update "global" outgoing_kbitrate (2)
[2013-04-30 22:15:57] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:57] DBUG stats/modify_node_event update "global" connections (12)
[2013-04-30 22:15:57] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:57] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:57] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:57] DBUG stats/modify_node_event update "global" client_connections (11)
[2013-04-30 22:15:57] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:57] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:57] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:57] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:57] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:57] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:57] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:57] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:57] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:57] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:57] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:57] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:57] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:57] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:57] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:57] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:57] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:57] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:57] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:57] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:57] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:57] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:57] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:58] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:58] DBUG stats/modify_node_event update "global" connections (13)
[2013-04-30 22:15:58] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:58] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:58] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:58] DBUG stats/modify_node_event update "global" client_connections (12)
[2013-04-30 22:15:58] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:58] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:58] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:58] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:58] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:58] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:58] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:58] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:58] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:58] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:58] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:58] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:58] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:58] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:58] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:58] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:58] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:58] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:58] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:58] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:58] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:58] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:58] DBUG stats/modify_node_event update "global" connections (14)
[2013-04-30 22:15:58] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:58] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:58] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:58] DBUG stats/modify_node_event update "global" client_connections (13)
[2013-04-30 22:15:58] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:58] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:58] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:58] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:58] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:58] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:58] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:58] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:15:58] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:58] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:58] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:58] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:58] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:58] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:58] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:58] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:58] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:58] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:58] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:58] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:58] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:58] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:58] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:59] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:15:59] DBUG stats/modify_node_event update "global" connections (15)
[2013-04-30 22:15:59] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:15:59] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:15:59] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:15:59] DBUG stats/modify_node_event update "global" client_connections (14)
[2013-04-30 22:15:59] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:15:59] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:59] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:59] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:59] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:59] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:15:59] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:15:59] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:15:59] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:15:59] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:59] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:59] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:15:59] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:15:59] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:15:59] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:15:59] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:15:59] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:15:59] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:15:59] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:15:59] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:15:59] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:15:59] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:15:59] DBUG stats/modify_node_event update "global" outgoing_kbitrate (2)
[2013-04-30 22:16:00] DBUG stats/modify_node_event update "global" clients (1)
[2013-04-30 22:16:00] DBUG stats/modify_node_event update "global" connections (16)
[2013-04-30 22:16:00] DBUG client/worker_add_pending_clients Added 1 pending clients to 0xef0aa0
[2013-04-30 22:16:00] DBUG client/worker 0xef0aa0 now has 2 clients
[2013-04-30 22:16:00] DBUG connection/_handle_get_request start with /stream
[2013-04-30 22:16:00] DBUG stats/modify_node_event update "global" client_connections (15)
[2013-04-30 22:16:00] DBUG auth/auth_add_listener adding client for authentication
[2013-04-30 22:16:00] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:16:00] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:16:00] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:16:00] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:16:00] DBUG auth_url/url_add_listener handler 0 sending request
[2013-04-30 22:16:00] DBUG auth_url/url_add_listener handler 0 request finished
[2013-04-30 22:16:00] DBUG fserve/fserve_client_create checking for file /stream (/usr/local/share/icecast/web/stream)
[2013-04-30 22:16:00] WARN fserve/fserve_client_create req for file "/usr/local/share/icecast/web/stream" No such file or directory
[2013-04-30 22:16:00] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:16:00] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:16:00] DBUG auth/queue_auth_client starting auth thread 0
[2013-04-30 22:16:00] DBUG auth/queue_auth_client auth on /stream has 1 pending
[2013-04-30 22:16:00] DBUG client/worker 0xef0aa0 now has 1 clients
[2013-04-30 22:16:00] DBUG auth/auth_run_thread Authentication thread 0 started for /stream
[2013-04-30 22:16:00] DBUG auth/auth_run_thread 1 client(s) pending on /stream
[2013-04-30 22:16:00] DBUG auth_url/url_remove_listener ...handler 0 sending request
[2013-04-30 22:16:00] DBUG auth_url/url_remove_listener ...handler 0 request complete
[2013-04-30 22:16:00] DBUG stats/modify_node_event update "global" clients (0)
[2013-04-30 22:16:00] DBUG auth/auth_run_thread Authenication thread 0 shutting down
[2013-04-30 22:16:00] DBUG auth/auth_release ...refcount on auth_t /stream is now 1
[2013-04-30 22:16:00] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:16:00] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:16:01] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:16:01] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:16:02] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:16:02] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:16:03] DBUG stats/modify_node_event update "global" banned_IPs (0)
[2013-04-30 22:16:03] DBUG stats/modify_node_event update "global" outgoing_kbitrate (0)
[2013-04-30 22:16:04] DBUG connection/wait_for_serversock signalfd received a termination
[2013-04-30 22:16:04] INFO connection/connection_thread connection thread finished
[2013-04-30 22:16:04] INFO connection/connection_thread_shutdown shutting down connection thread
[2013-04-30 22:16:04] INFO slave/_slave_thread shutting down current relays
[2013-04-30 22:16:04] INFO slave/_slave_thread Slave thread shutdown complete
[2013-04-30 22:16:04] DBUG yp/yp_stop YP client is now stopped
[2013-04-30 22:16:04] INFO client/workers_adjust requested worker count 0
[2013-04-30 22:16:04] DBUG client/worker 0xef0aa0 now has 0 clients
[2013-04-30 22:16:04] INFO client/worker shutting down
[2013-04-30 22:16:04] INFO main/server_process Shutting down
[2013-04-30 22:16:04] INFO auth/auth_shutdown Auth shutdown complete
[2013-04-30 22:16:04] INFO connection/connection_listen_sockets_close Closing port 9001 on 199.101.48.140
[2013-04-30 22:16:04] INFO connection/connection_listen_sockets_close Closing port 9000 on 199.101.48.140
[2013-04-30 22:16:04] DBUG yp/yp_shutdown releasing directory details
[2013-04-30 22:16:04] DBUG yp/destroy_yp_server Removing YP server entry for http://dir.xiph.org/cgi-bin/yp-cgi
[2013-04-30 22:16:04] INFO yp/yp_shutdown YP cleanup complete
[2013-04-30 22:16:04] INFO fserve/fserve_shutdown file serving stopped

Allmoz · 2013-05-01T02:29:04Z

:3 there it is trigered whit all events
fully replicable

Allmoz · 2013-05-01T02:35:38Z

huu! found it!

[2013-04-30 22:15:54] WARN source/source_read Disconnecting /stream due to socket timeout

karlheyes · 2013-05-01T21:21:17Z

ok, found the trigger case. Because the stream dies without sending content, the listener does not get to send anything so the first time through a 404 is issued but it still classed as authenticated so when it completes the 404 response it tries to run the listener remove again. I've now drop that classification the first time through so no auth should be considered. fixed in git

Allmoz · 2013-05-01T23:17:21Z

nice! working as expected, thanks!
will test for one week :)

Allmoz · 2013-05-08T21:43:56Z

perfect score :D!

Allmoz · 2013-05-13T11:30:51Z

:) looks nice

karlheyes · 2013-05-13T22:21:06Z

has that been 2 weeks now without failure

karl.

Allmoz · 2013-05-14T02:38:30Z

yeps,it has been! and the two kinds extra data are fixed

send=59 --> source_auth on a used mount
send=70 --> stream dead without content

... :3 so anything that happens from now is new

karlheyes · 2013-05-16T12:09:24Z

we will take that as issue closed now. I'll be cutting a kh8 release shortly so that should keep things up to date.

karl.

Add missing makefile

Matthias78 mentioned this issue Mar 12, 2013

SEGV in format_mp3.c #45

Closed

ghost assigned karlheyes May 1, 2013

karlheyes closed this as completed May 16, 2013

Ciurica mentioned this issue May 7, 2014

Deadlock in IceCast process 2.3.3-kh9 #87

Open

LeonarddeR mentioned this issue Dec 9, 2014

Ill signal after disconnecting mount #102

Closed

asantoni mentioned this issue May 5, 2017

pthread_rwlock_unlock on unlocked rwlock causes undefined behaviour, or illegal instruction #157

Open

CodeSteele pushed a commit to CodeSteele/icecast-kh that referenced this issue Nov 3, 2018

Merge pull request karlheyes#6 from CodeSteele/bug/missing-files

c061da6

Add missing makefile

listener_remove reliability #6

listener_remove reliability #6

Comments

DuncanFairley commented Mar 22, 2012

karlheyes commented Mar 22, 2012

Allmoz commented Mar 22, 2012

Allmoz commented Mar 29, 2012

karlheyes commented Mar 29, 2012

Allmoz commented Mar 29, 2012

karlheyes commented Mar 29, 2012

Allmoz commented Mar 29, 2012

Allmoz commented Mar 29, 2012

karlheyes commented Mar 29, 2012

karlheyes commented Apr 18, 2012

Allmoz commented Apr 18, 2012

Allmoz commented Apr 18, 2012

karlheyes commented Apr 18, 2012

Allmoz commented Apr 18, 2012

Allmoz commented Apr 24, 2012

Allmoz commented May 22, 2012

karlheyes commented May 25, 2012

Allmoz commented May 25, 2012

DuncanFairley commented May 25, 2012

DuncanFairley commented Jun 2, 2012

Allmoz commented Jun 8, 2012

Allmoz commented Jun 8, 2012

karlheyes commented Jun 9, 2012

Allmoz commented Jun 9, 2012

Allmoz commented Jun 9, 2012

Allmoz commented Jun 9, 2012

Allmoz commented Jun 12, 2012

karlheyes commented Jun 12, 2012

Allmoz commented Jun 25, 2012

karlheyes commented Jun 25, 2012

Allmoz commented Mar 21, 2013

karlheyes commented Mar 22, 2013

Allmoz commented Mar 24, 2013

karlheyes commented Apr 24, 2013

Allmoz commented Apr 24, 2013

karlheyes commented Apr 24, 2013

Allmoz commented Apr 25, 2013

Allmoz commented Apr 27, 2013

Allmoz commented May 1, 2013

Allmoz commented May 1, 2013

karlheyes commented May 1, 2013

Allmoz commented May 1, 2013

Allmoz commented May 1, 2013

Allmoz commented May 1, 2013

Allmoz commented May 1, 2013

Allmoz commented May 1, 2013

karlheyes commented May 1, 2013

Allmoz commented May 1, 2013

Allmoz commented May 8, 2013

Allmoz commented May 13, 2013

karlheyes commented May 13, 2013

Allmoz commented May 14, 2013

karlheyes commented May 16, 2013