Icecast 2.3.3-kh9 never recovering from "too many clients awaiting authentication"-state

[niko]

On serveral occasions we encountered an issue where Icecast 2.3.3-kh9 would go into "too many clients awaiting authentication"-state and never recover. Over the course of about 1,5 hours our authentication service didn't receive a single requests while all new listeners got a 403. This is especially unfortunate in combination with issue #62. It seems as if mountinfo->auth->pending_count (https://github.com/karlheyes/icecast-kh/blob/92697d6f99f66c603389387d142b8199400142b6/src/auth.c#L608) would not count down and return to a value that allows new auth requests.

[karlheyes]

sounds like the auth threads are getting blocked or prevented from starting. I'll try the case you mentioned to see if I see something similar, any information that could be helpful to isolate the issue further?

karl.

[niko]

I was not able to reproduce the issue in a controlled way. It just occurred on several occasion during the last two weeks. I'll post logs from last occurrence on Sunday, Sept. 22nd. This is the first log entry in the icecast log:

[2013-09-22 10:18:39] WARN auth/auth_add_listener too many clients awaiting authentication

The frequency of these entries then quickly rise until the logfile is about 3/4 this kind of entries. We proxy the auth requests through nginx for better logging of what's going on. The nginx log looks like this:

10.0.0.100 [22/Sep/2013:10:18:23 +0200] "POST /add HTTP/1.1" 404 476<-->0 0.009 0.008
10.0.0.100 [22/Sep/2013:10:18:23 +0200] "POST /add HTTP/1.1" 200 344<-->0 0.008 0.008
10.0.0.100 [22/Sep/2013:10:18:23 +0200] "POST /remove HTTP/1.1" 200 337<-->0 0.007 0.007
10.0.0.100 [22/Sep/2013:10:18:23 +0200] "POST /add HTTP/1.1" 200 415<-->0 0.008 0.008
10.0.0.100 [22/Sep/2013:10:18:23 +0200] "POST /remove HTTP/1.1" 200 341<-->0 0.005 0.005
10.0.0.100 [22/Sep/2013:10:18:24 +0200] "POST /remove HTTP/1.1" 200 368<-->0 0.006 0.006
10.0.0.100 [22/Sep/2013:10:18:24 +0200] "POST /remove HTTP/1.1" 200 342<-->0 0.005 0.005
10.0.0.100 [22/Sep/2013:10:18:24 +0200] "POST /add HTTP/1.1" 404 355<-->0 0.008 0.008
10.0.0.100 [22/Sep/2013:10:18:24 +0200] "POST /add HTTP/1.1" 200 410<-->0 0.008 0.008
10.0.0.100 [22/Sep/2013:10:18:24 +0200] "POST /remove HTTP/1.1" 200 361<-->0 0.008 0.007
10.0.0.100 [22/Sep/2013:10:18:24 +0200] "POST /add HTTP/1.1" 404 371<-->0 0.006 0.006
10.0.0.100 [22/Sep/2013:10:18:24 +0200] "POST /remove HTTP/1.1" 200 336<-->0 0.006 0.006
10.0.0.100 [22/Sep/2013:10:18:24 +0200] "POST /add HTTP/1.1" 404 378<-->0 0.007 0.007
10.0.0.100 [22/Sep/2013:10:18:24 +0200] "POST /add HTTP/1.1" 200 378<-->0 0.009 0.008
10.0.0.100 [22/Sep/2013:10:19:24 +0200] "POST /add HTTP/1.1" 200 487<-->122587 60.014 0.008

with this being the log format:

log_format stats  '$remote_addr [$time_local] "$request" '
                  '$status $request_length<-->$body_bytes_sent '
                  '$request_time $upstream_response_time';

and then it suddenly ends, that means no requests are sent by icecast at all until it's restarted. The nginx error log states:

2013/09/22 10:19:24 [info] 26777#0: *337777435 client timed out (110: Connection timed out) while sending to client, client: 10.0.0.100, server: my-auth-server, request: "POST /add HTTP/1.1", upstream: "http://127.0.0.1:3333/add", host: "my-auth-server-nginx-proxy:3334"

That looks like the final requests that icecast makes takes too long so the nginx timeout kicks in. It's response body is big so it must be a prestream response. All responses before icecast stops to make auth requests seem to be snappy.

I remember having seen this issue some months ago. Then we deployed the icecast version with the prestream issue (Icecast 2.3.3-kh8 I think) and these errors disappeared. So I guess it could have something to do with the prestream handling.

I hope this error description helps at least a little bit. If you have any further questions don't hesitate.

[karlheyes]

The url engine in icecast does have a disable capability if there is a timeout for example (5 seconds), if this is triggered then the listeners still go through the auth queue but the urls are not issued (listeners are either denied or passed depending on the presume innocent setting). This should last for about 60 seconds and then urls will be issued again. I don't know if that 60 seconds in your list is significant, is it just down to add requests with intro content, if so, what content type header are you supplying?

karl.

[niko]

The content type is audio/mpeg:

Status: 200 OK Connection: close Content-Type: audio/mpeg icecast-auth-user: withintro icecast-auth-timelimit: 28800 Last-Modified: Sun, 15 Sep 2013 22:00:03 GMT Content-Length: 568104

To me it seems as if Icecast stopps handling HTTP auth requests completely, including receiving the response of already issued requests. As far as I can tell our auth server is always fast enough. We're monitoring the service with Newrelic and the listener_add requests are handled within the application on average in 7 - 8ms. The maximum duration for single requests is consistently at about 250 - 270ms. As said this is within the application, queuing time is not recorded. BUT the nginx log confirms the measured times with an average of 8ms.

We'll gonna try the new build. So if this occurs again, at least we don't block new listeners with a 403. :)

Thanks a lot. For this particular effort and Icecast in general. Great software!

Niko.

[karlheyes]

I've just found a possible stall issue, now fixed in git. This would only occur in certain cases, quite rare, as it is very time dependent with a very small window but could leave a listener waiting to be auth'd on the queue until a another new listener comes in to kick off a thread. In such cases the log would report that the max handlers was reached but it actually means max handlers were closing down.

karl.

[karlheyes]

As mentioned on the previously referenced bug report, this looks now to be resolved. While a possible case mentioned before identified a possible cause, the actual cause in this case was a busy loop in the mpeg parsing triggered by a larger than normal buffer passed by libcurl. Over time, each auth thread became stuck in the callback and didn't timeout and therefore did not free-up the incoming client details.

karl.

[musarano]

Hi Karl, Dalton Here, im facing icecast restarts every 2 or so minutes, im runing 2.3.3kh9 is it any patch available already for the mentioned apparently issues?

Thank You

[karlheyes]

The above issue was down to the auth threads getting stuck in processing mpeg data, a busy loop, which meant it didn't get back to releasing clients which in turn led to the clients count increasing to the max limit. There was no crashes with this so it would not be restarting unless you had something external that was killing icecast because of no response.

karl.

[musarano]

Humm, could it be DoS attacks? or too many calls to the web/status?.xsl's i have from adobe flash player application?

But the funny thing is that it was working perfect! or fine!! two days and backwards or until 2 days ago.. Since then, it been kind of a nightmare for me with all the clients...

Im trying different aproaches here.. to find some release.. :)

On Tue, Oct 29, 2013 at 10:27 PM, Karl Heyes notifications@github.comwrote:

The above issue was down to the auth threads getting stuck in processing mpeg data, a busy loop, which meant it didn't get back to releasing clients which in turn led to the clients count increasing to the max limit. There was no crashes with this so it would not be restarting unless you had something external that was killing icecast because of no response.

karl.

— Reply to this email directly or view it on GitHubhttps://github.com/karlheyes/icecast-kh/issues/64#issuecomment-27360773 .

[karlheyes]

a DoS is always a possibility but your log should show a common pattern is such cases. obviously try to avoid auth in cases which are not needed, even if that means adding an empty mount before such as

/*.xsl

karl.

[musarano]

Sure, thanks for the advice Karl, what im using from flash for the counters is this:

http://ice.eleden.com:8000/status3.xsl?mount=/lax.ogg

http://ice.eleden.com:8000/status3.xsl?mount=/lax.aac

http://ice.eleden.com:8000/status3.xsl?mount=/amanecer.mp3

from for example: http://www.eleden.net/fmm2/flashcast.php?broadcast=lax

Tha is the one im on the needing yet.. the one saids: "32?" ?

( another example: http://www.eleden.net/fp1.php?broadcast=wzol also has alternate links near end of page )

Installing the patch now....

let you know in a few...

On Tue, Oct 29, 2013 at 10:46 PM, Karl Heyes notifications@github.comwrote:

a DoS is always a possibility but your log should show a common pattern is such cases. obviously try to avoid auth in cases which are not needed, even if that means adding an empty mount before such as

/*.xsl

karl.

— Reply to this email directly or view it on GitHubhttps://github.com/karlheyes/icecast-kh/issues/64#issuecomment-27361393 .

[musarano]

This is one of the messages that are coming out before trying the new patch:

Fault bucket , type 0 Event Name: APPCRASH Response: Not available Cab Id: 0

Problem signature: P1: icecast.exe P2: 0.0.0.0 P3: 520d61a6 P4: icecast.exe P5: 0.0.0.0 P6: 520d61a6 P7: 40000015 P8: 0002f795 P9: P10:

Attached files:

These files may be available here: C:\ProgramData\Microsoft\Windows\WER\ReportQueue\AppCrash_icecast.exe_d4912774a04d5a5977bb3f16795aff876e3798_39ef716a

Analysis symbol: Rechecking for solution: 0 Report Id: fa626cdb-410e-11e3-8ef6-0025904ef02d Report Status: 0

Trying the one newer now..

On Tue, Oct 29, 2013 at 10:57 PM, Dalton Acosta daltonacosta@gmail.comwrote:

Sure, thanks for the advice Karl, what im using from flash for the counters is this:

http://ice.eleden.com:8000/status3.xsl?mount=/lax.ogg

http://ice.eleden.com:8000/status3.xsl?mount=/lax.aac

http://ice.eleden.com:8000/status3.xsl?mount=/amanecer.mp3

from for example: http://www.eleden.net/fmm2/flashcast.php?broadcast=lax

Tha is the one im on the needing yet.. the one saids: "32?" ?

( another example: http://www.eleden.net/fp1.php?broadcast=wzol also has alternate links near end of page )

Installing the patch now....

let you know in a few...

On Tue, Oct 29, 2013 at 10:46 PM, Karl Heyes notifications@github.comwrote:

a DoS is always a possibility but your log should show a common pattern is such cases. obviously try to avoid auth in cases which are not needed, even if that means adding an empty mount before such as

/*.xsl

karl.

— Reply to this email directly or view it on GitHubhttps://github.com/karlheyes/icecast-kh/issues/64#issuecomment-27361393 .

[musarano]

Patch has Started...

On Tue, Oct 29, 2013 at 11:02 PM, Dalton Acosta daltonacosta@gmail.comwrote:

This is one of the messages that are coming out before trying the new patch:

Fault bucket , type 0 Event Name: APPCRASH Response: Not available Cab Id: 0

Problem signature: P1: icecast.exe P2: 0.0.0.0 P3: 520d61a6 P4: icecast.exe P5: 0.0.0.0 P6: 520d61a6 P7: 40000015 P8: 0002f795 P9: P10:

Attached files:

These files may be available here:

C:\ProgramData\Microsoft\Windows\WER\ReportQueue\AppCrash_icecast.exe_d4912774a04d5a5977bb3f16795aff876e3798_39ef716a

Analysis symbol: Rechecking for solution: 0 Report Id: fa626cdb-410e-11e3-8ef6-0025904ef02d Report Status: 0

Trying the one newer now..

On Tue, Oct 29, 2013 at 10:57 PM, Dalton Acosta daltonacosta@gmail.comwrote:

Sure, thanks for the advice Karl, what im using from flash for the counters is this:

http://ice.eleden.com:8000/status3.xsl?mount=/lax.ogg

http://ice.eleden.com:8000/status3.xsl?mount=/lax.aac

http://ice.eleden.com:8000/status3.xsl?mount=/amanecer.mp3

from for example: http://www.eleden.net/fmm2/flashcast.php?broadcast=lax

Tha is the one im on the needing yet.. the one saids: "32?" ?

( another example: http://www.eleden.net/fp1.php?broadcast=wzol also has alternate links near end of page )

Installing the patch now....

let you know in a few...

On Tue, Oct 29, 2013 at 10:46 PM, Karl Heyes notifications@github.comwrote:

a DoS is always a possibility but your log should show a common pattern is such cases. obviously try to avoid auth in cases which are not needed, even if that means adding an empty mount before such as

/*.xsl

karl.

— Reply to this email directly or view it on GitHubhttps://github.com/karlheyes/icecast-kh/issues/64#issuecomment-27361393 .

[musarano]

Reporting so far:

I have hicups and long pauses in my custom flash player or if i tried to listening directly from icecast, AAC, OGG,...

If i use jwplayer from wowza icecast-restreaming, is not happening neither with relayed mounts so far...

pretty interesting situation now....

im still analyzing...

On Tue, Oct 29, 2013 at 11:18 PM, Dalton Acosta daltonacosta@gmail.comwrote:

Patch has Started...

On Tue, Oct 29, 2013 at 11:02 PM, Dalton Acosta daltonacosta@gmail.comwrote:

This is one of the messages that are coming out before trying the new patch:

Fault bucket , type 0 Event Name: APPCRASH Response: Not available Cab Id: 0

Problem signature: P1: icecast.exe P2: 0.0.0.0 P3: 520d61a6 P4: icecast.exe P5: 0.0.0.0 P6: 520d61a6 P7: 40000015 P8: 0002f795 P9: P10:

Attached files:

These files may be available here:

C:\ProgramData\Microsoft\Windows\WER\ReportQueue\AppCrash_icecast.exe_d4912774a04d5a5977bb3f16795aff876e3798_39ef716a

Analysis symbol: Rechecking for solution: 0 Report Id: fa626cdb-410e-11e3-8ef6-0025904ef02d Report Status: 0

Trying the one newer now..

On Tue, Oct 29, 2013 at 10:57 PM, Dalton Acosta daltonacosta@gmail.comwrote:

Sure, thanks for the advice Karl, what im using from flash for the counters is this:

http://ice.eleden.com:8000/status3.xsl?mount=/lax.ogg

http://ice.eleden.com:8000/status3.xsl?mount=/lax.aac

http://ice.eleden.com:8000/status3.xsl?mount=/amanecer.mp3

from for example: http://www.eleden.net/fmm2/flashcast.php?broadcast=lax

Tha is the one im on the needing yet.. the one saids: "32?" ?

( another example: http://www.eleden.net/fp1.php?broadcast=wzol also has alternate links near end of page )

Installing the patch now....

let you know in a few...

On Tue, Oct 29, 2013 at 10:46 PM, Karl Heyes notifications@github.comwrote:

a DoS is always a possibility but your log should show a common pattern is such cases. obviously try to avoid auth in cases which are not needed, even if that means adding an empty mount before such as

/*.xsl

karl.

— Reply to this email directly or view it on GitHubhttps://github.com/karlheyes/icecast-kh/issues/64#issuecomment-27361393 .

[musarano]

Hi Karl,

I have uninstalled the patch, and also re-installed the months ago, been used version: (the hicups and long mutes or silences are gone) i will wait for tomorrow peek time.. and report back to you..

InformationLocationUSAdminicemaster@localhostHostice.eleden.comVersionIcecast 2.3.2-kh29.1 <== .1StartedWed, 30 Oct 2013 00:19:12Downloadicecast.orghttp://icecast.org/download.php Subversionclick here http://icecast.org/svn.phpDocumentationclick herehttp://icecast.org/docs.phpStream Directorydir.xiph.org http://dir.xiph.org/index.phpCommunity forum.icecast.org

On Tue, Oct 29, 2013 at 11:49 PM, Dalton Acosta daltonacosta@gmail.comwrote:

Reporting so far:

I have hicups and long pauses in my custom flash player or if i tried to listening directly from icecast, AAC, OGG,...

If i use jwplayer from wowza icecast-restreaming, is not happening neither with relayed mounts so far...

pretty interesting situation now....

im still analyzing...

On Tue, Oct 29, 2013 at 11:18 PM, Dalton Acosta daltonacosta@gmail.comwrote:

Patch has Started...

On Tue, Oct 29, 2013 at 11:02 PM, Dalton Acosta daltonacosta@gmail.comwrote:

This is one of the messages that are coming out before trying the new patch:

Fault bucket , type 0 Event Name: APPCRASH Response: Not available Cab Id: 0

Problem signature: P1: icecast.exe P2: 0.0.0.0 P3: 520d61a6 P4: icecast.exe P5: 0.0.0.0 P6: 520d61a6 P7: 40000015 P8: 0002f795 P9: P10:

Attached files:

These files may be available here:

C:\ProgramData\Microsoft\Windows\WER\ReportQueue\AppCrash_icecast.exe_d4912774a04d5a5977bb3f16795aff876e3798_39ef716a

Analysis symbol: Rechecking for solution: 0 Report Id: fa626cdb-410e-11e3-8ef6-0025904ef02d Report Status: 0

Trying the one newer now..

On Tue, Oct 29, 2013 at 10:57 PM, Dalton Acosta daltonacosta@gmail.comwrote:

Sure, thanks for the advice Karl, what im using from flash for the counters is this:

http://ice.eleden.com:8000/status3.xsl?mount=/lax.ogg

http://ice.eleden.com:8000/status3.xsl?mount=/lax.aac

http://ice.eleden.com:8000/status3.xsl?mount=/amanecer.mp3

from for example: http://www.eleden.net/fmm2/flashcast.php?broadcast=lax

Tha is the one im on the needing yet.. the one saids: "32?" ?

( another example: http://www.eleden.net/fp1.php?broadcast=wzol also has alternate links near end of page )

Installing the patch now....

let you know in a few...

On Tue, Oct 29, 2013 at 10:46 PM, Karl Heyes notifications@github.comwrote:

a DoS is always a possibility but your log should show a common pattern is such cases. obviously try to avoid auth in cases which are not needed, even if that means adding an empty mount before such as

/*.xsl

karl.

— Reply to this email directly or view it on GitHubhttps://github.com/karlheyes/icecast-kh/issues/64#issuecomment-27361393 .

[musarano]

Hi Karl,

Status Report on Behavior of KH-29.1 for windows.

With the downgrade of the icecast to the KH29.1 the system has been up all the time without any issues and with a cpu usage lower than 4%, instead with the latest when upto 17%

No issues at all with the crash or restart of the service...

I can still see the logon windows attack by thousands by minute... as usual. But im using TS_Block to correct and take care of this. ( https://github.com/EvanAnderson/ts_block )

Hope this helps to clarify what does the KH29.1 has or what kind of implementation had at that time... that perhaps is not caching the way it did with that version at that time....

Cord,

Dalton www.Eleden.Net

On Wed, Oct 30, 2013 at 12:24 AM, Dalton Acosta daltonacosta@gmail.comwrote:

Hi Karl,

I have uninstalled the patch, and also re-installed the months ago, been used version: (the hicups and long mutes or silences are gone) i will wait for tomorrow peek time.. and report back to you..

Information LocationUSAdmin icemaster@localhostHostice.eleden.com VersionIcecast 2.3.2-kh29.1 <== .1 StartedWed, 30 Oct 2013 00:19:12 Downloadicecast.orghttp://icecast.org/download.php Subversionclick here http://icecast.org/svn.php Documentationclick herehttp://icecast.org/docs.php Stream Directorydir.xiph.org http://dir.xiph.org/index.php Community forum.icecast.org

On Tue, Oct 29, 2013 at 11:49 PM, Dalton Acosta daltonacosta@gmail.comwrote:

Reporting so far:

I have hicups and long pauses in my custom flash player or if i tried to listening directly from icecast, AAC, OGG,...

If i use jwplayer from wowza icecast-restreaming, is not happening neither with relayed mounts so far...

pretty interesting situation now....

im still analyzing...

On Tue, Oct 29, 2013 at 11:18 PM, Dalton Acosta daltonacosta@gmail.comwrote:

Patch has Started...

On Tue, Oct 29, 2013 at 11:02 PM, Dalton Acosta daltonacosta@gmail.comwrote:

This is one of the messages that are coming out before trying the new patch:

Fault bucket , type 0 Event Name: APPCRASH Response: Not available Cab Id: 0

Problem signature: P1: icecast.exe P2: 0.0.0.0 P3: 520d61a6 P4: icecast.exe P5: 0.0.0.0 P6: 520d61a6 P7: 40000015 P8: 0002f795 P9: P10:

Attached files:

These files may be available here:

C:\ProgramData\Microsoft\Windows\WER\ReportQueue\AppCrash_icecast.exe_d4912774a04d5a5977bb3f16795aff876e3798_39ef716a

Analysis symbol: Rechecking for solution: 0 Report Id: fa626cdb-410e-11e3-8ef6-0025904ef02d Report Status: 0

Trying the one newer now..

On Tue, Oct 29, 2013 at 10:57 PM, Dalton Acosta <daltonacosta@gmail.com

wrote:

Sure, thanks for the advice Karl, what im using from flash for the counters is this:

http://ice.eleden.com:8000/status3.xsl?mount=/lax.ogg

http://ice.eleden.com:8000/status3.xsl?mount=/lax.aac

http://ice.eleden.com:8000/status3.xsl?mount=/amanecer.mp3

from for example: http://www.eleden.net/fmm2/flashcast.php?broadcast=lax

Tha is the one im on the needing yet.. the one saids: "32?" ?

( another example: http://www.eleden.net/fp1.php?broadcast=wzol also has alternate links near end of page )

Installing the patch now....

let you know in a few...

On Tue, Oct 29, 2013 at 10:46 PM, Karl Heyes <notifications@github.com

wrote:

a DoS is always a possibility but your log should show a common pattern is such cases. obviously try to avoid auth in cases which are not needed, even if that means adding an empty mount before such as

/*.xsl

karl.

— Reply to this email directly or view it on GitHubhttps://github.com/karlheyes/icecast-kh/issues/64#issuecomment-27361393 .

[karlheyes]

It doesn't help identify anything that I can work on, kh29.x was some time ago and you seem to be suffering a DoS which I'm unclear on whether that is related. If you really were getting a lot of messages about the client limit being reached then it should of only affected 1 thread.

karl.

[mr-deamon]

Is it possible that this has been fixed when working with URL, but might still happen when using command-based authentication? Or am i required to use listener_remove if using listener_add? I am currently on KH11 and am still getting these messages. Current workaround is a icecast reload if it happens, it looks like the queue gets cleared this way

chris

[musarano]

Thank You Karl & Chris,

Im trying the Icecast 2.3.3-kh12pre Version Now, and see how it goes... So far, no issues yet... (Windows 2008 Enterprise ED R2 64bits @ 128G Ram

-Dalton

On Wed, Jun 10, 2015 at 6:19 AM, Christian notifications@github.com wrote:

Is it possible that this has been fixed when working with URL, but might still happen when using command-based authentication? Or am i required to use listener_remove if using listener_add? I am currently on KH11 and am still getting these messages. Current workaround is a icecast reload if it happens, it looks like the queue gets cleared this way

chris

— Reply to this email directly or view it on GitHub https://github.com/karlheyes/icecast-kh/issues/64#issuecomment-110683351 .

[mr-deamon]

Oh, don't thank me :) But you are using url-auth, don't you?

[musarano]

Yes, im using both with and without, depends on the case of the mount-point.

On Wed, Jun 10, 2015 at 9:13 AM, Christian notifications@github.com wrote:

Oh, don't thank me :) But you are using url-auth, don't you?

— Reply to this email directly or view it on GitHub https://github.com/karlheyes/icecast-kh/issues/64#issuecomment-110745682 .