[Icecast] Icecast is shutdown / client auth failed with ""

subscription at nextdial.com.br subscription at nextdial.com.br
Wed Aug 29 12:45:38 UTC 2018 

Hello,
  
 In order to identify if was some issue regard to the auth api we include 
some trace logs and we move it to other machine.

Bellow is what trace we are generating (date, result, elapsed time in 
milleseconds, request):
    [8/29/18 11:49:00 AM]     200       0.3721    
action=listener_add&server=r22&port=443&client=2616&mount=/alphafmsp&user=&p
ass=&ip=177.223.XX&agent=Mozilla/5.0 (Windows NT 10.0; Win64; x64) 
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36
[8/29/18 11:49:00 AM]     200       0.6181    
action=listener_remove&server=r22&port=443&client=673&mount=/aradiorock&user
=&pass=&duration=983&ip=191.206.XX&agent=NxApp/1.18.07.10 (Xamarin; 
Android; 27; Mi A2 Lite; Xiaomi)
[8/29/18 11:49:00 AM]     200       0.4407    
action=listener_add&server=r22&port=443&client=2618&mount=/alphafmsp&user=&p
ass=&ip=177.138.XX&agent=Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 
(KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36
[8/29/18 11:49:00 AM]     200       0.3872    
action=listener_add&server=r20&port=443&client=3040&mount=/aradiorock&user=&
pass=&ip=189.8.XX&agent=Mozilla/5.0 (Windows NT 10.0; Win64; x64) 
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36
  
 Even with responses quickly responses we still getting:
  
 [2018-08-29  11:49:08] INFO auth_url/url_add_listener client auth 
(http://10.68.0.136:8001/listener/add) failed with ""
  
 And sometimes the icecast process just shutdown! Bellow is the last second 
logged:
  
 AUTH ACCESS.LOG
  
 [8/29/18 11:49:10 AM]    200   0.3864    
action=listener_add&server=r20&port=443&client=3071&mount=/amorfm&user=&pass
=&ip=191.39.XXX&agent=App/2.4.2 (Linux;Android 7.0) ExoPlayerLib/2.5.4
[8/29/18 11:49:10 AM]    200   0.204      
action=listener_add&server=r20&port=443&client=3070&mount=/alphafmsp&user=&p
ass=&ip=201.81.XXX&agent=Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 
(KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36
[8/29/18 11:49:10 AM]    200   0.2598    
action=listener_remove&server=r22&port=443&client=2625&mount=/alphafmsp&user
=&pass=&duration=6&ip=177.95.XXX&agent=Mozilla/5.0 (Windows NT 6.1) 
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36
[8/29/18 11:49:10 AM]    200   0.1067    
action=listener_remove&server=r20&port=443&client=512&mount=/aradiorock&user
=&pass=&duration=1087&ip=179.127.XXX&agent=Mozilla/5.0 (Windows NT 6.1; 
Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.139 
Safari/537.36
[8/29/18 11:49:10 AM]    200   0.4311    
action=listener_add&server=r20&port=443&client=3072&mount=/alphafmsp&user=&p
ass=&ip=201.52.XXX&agent=Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 
(KHTML, like Gecko) Chrome/43.0.2357.132 Safari/537.36
[8/29/18 11:49:10 AM]    200   0.3617    
action=listener_add&server=r22&port=443&client=2638&mount=/aradiorock&user=&
pass=&ip=179.241.XXX&agent=NxApp/1.18.07.10 (Xamarin; Android; 26; moto x4; 
motorola)
  
 ICECAST ERROR.LOG (machine named "r20")
  
 [2018-08-29  11:49:10] DBUG auth/auth_run_thread 1 client(s) pending on 
/amorfm
[2018-08-29  11:49:10] DBUG auth/auth_run_thread 1 client(s) pending on 
/alphafmsp
[2018-08-29  11:49:10] DBUG auth/add_listener_to_source max on /amorfm is 
-1 (cur 6)
[2018-08-29  11:49:10] DBUG auth/add_listener_to_source Added client to 
/amorfm
[2018-08-29  11:49:10] DBUG auth/add_authenticated_listener client 
authenticated, passed to source
[2018-08-29  11:49:10] DBUG auth/add_listener_to_source max on /alphafmsp 
is 750 (cur 750)
[2018-08-29  11:49:10] DBUG fserve/fserve_add_client Adding client to file 
serving engine
[2018-08-29  11:49:10] DBUG fserve/fserve_add_pending fserve handler waking 
up
[2018-08-29  11:49:10] DBUG auth/auth_release ...refcount on auth_t 
/alphafmsp is now 751
[2018-08-29  11:49:10] INFO auth/auth_new_listener client 3070 failed
[2018-08-29  11:49:10] DBUG fserve/fserv_thread_function fserve handler 
exit
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global 
client_connections (2719)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global 
client_connections (2720)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global clients 
(1331)
[2018-08-29  11:49:10] DBUG client/client_read_bytes reading from 
connection has failed
[2018-08-29  11:49:10] INFO source/send_to_listener Client 512 
(179.127.XXX) has fallen too far behind, removing
[2018-08-29  11:49:10] DBUG auth/queue_auth_client ...refcount on auth_t 
/aradiorock is now 502
[2018-08-29  11:49:10] INFO auth/queue_auth_client auth on /aradiorock has 
1 pending
[2018-08-29  11:49:10] DBUG source/source_main Client removed
[2018-08-29  11:49:10] INFO source/source_main listener count on 
/aradiorock now 500
[2018-08-29  11:49:10] DBUG source/source_main Client added for mountpoint 
(/amorfm)
[2018-08-29  11:49:10] INFO source/source_main listener count on /amorfm 
now 7
[2018-08-29  11:49:10] INFO auth/auth_add_listener adding client for 
authentication
[2018-08-29  11:49:10] DBUG auth/queue_auth_client ...refcount on auth_t 
/alphafmsp is now 752
[2018-08-29  11:49:10] INFO auth/queue_auth_client auth on /alphafmsp has 1 
pending
[2018-08-29  11:49:10] DBUG auth/auth_run_thread 1 client(s) pending on 
/aradiorock
[2018-08-29  11:49:10] DBUG auth/auth_release ...refcount on auth_t 
/aradiorock is now 501
[2018-08-29  11:49:10] DBUG format/format_check_http_buffer processing 
pending client headers
[2018-08-29  11:49:10] DBUG auth/auth_run_thread 1 client(s) pending on 
/alphafmsp
[2018-08-29  11:49:10] DBUG auth/add_listener_to_source max on /alphafmsp 
is 750 (cur 750)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global clients 
(1332)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global 
connections (3046)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global clients 
(1331)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update "/aradiorock" 
slow_listeners (63)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global listeners 
(1317)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update "/aradiorock" 
listeners (500)
[2018-08-29  11:49:10] DBUG fserve/fserve_add_client Adding client to file 
serving engine
[2018-08-29  11:49:10] DBUG fserve/fserve_add_pending fserve handler waking 
up
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global clients 
(1332)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global 
connections (3047)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update "/amorfm" 
listener_peak (7)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update "/amorfm" 
listeners (7)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global 
client_connections (2721)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global clients 
(1331)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global listeners 
(1318)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global 
listener_connections (2347)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global clients 
(1332)
[2018-08-29  11:49:10] DBUG stats/modify_node_event update global 
connections (3048)
[2018-08-29  11:49:10] DBUG auth/auth_release ...refcount on auth_t 
/alphafmsp is now 751
[2018-08-29  11:49:10] INFO auth/auth_new_listener client 3072 failed
[2018-08-29  11:49:10] DBUG auth/queue_auth_client ...refcount on auth_t 
/alphafmsp is now 751
[2018-08-29  11:49:10] INFO auth/queue_auth_client auth on /alphafmsp has 1 
pending
[2018-08-29  11:49:10] DBUG fserve/fserv_thread_function fserve handler 
exit
[2018-08-29  11:49:10] DBUG auth/auth_run_thread 1 client(s) pending on 
/alphafmsp
  
 I can't figure out why icecast is shutting down and why sometimes it can't 
authenticate the request.
  
 It happens with different loads. Sometimes with about 2500, others with 
3000 and others with about 4200 listeners.
  
 Other useful info: we have a hearbeat api that do a "status-json.xsl" 
request at every 4s.
  
 Any ideas?
  

  
  
 Best,
 Thiago
  
  

----------------------------------------
 De: "subscription at nextdial.com.br" <subscription at nextdial.com.br>
Enviado: sexta-feira, 24 de agosto de 2018 20:51
Para: icecast at xiph.org
Assunto: Client auth failed with ""   
  Hello,
 We are using url authentication and getting the item bellow at the log:
  
 [2018-08-24  23:26:05] INFO auth_url/url_add_listener client auth 
(http://127.0.0.1:8001/listener/add) failed with ""
  
 I put try/catch and reviewed all my code ensure always return a proper 
status and header error code, so what trigger this kind of error?

    
    
   Regards,
   Thiago
    


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.xiph.org/pipermail/icecast/attachments/20180829/359a515a/attachment.htm>

More information about the Icecast mailing list