[asterisk-bugs] [Asterisk 0016382]: SIP OPTIONS qualify message forever

Asterisk Bug Tracker noreply at bugs.digium.com
Tue Dec 22 03:34:56 CST 2009 

The following issue has been REOPENED. 
====================================================================== 
https://issues.asterisk.org/view.php?id=16382 
====================================================================== 
Reported By:                lftsy
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   16382
Category:                   Channels/chan_sip/DatabaseSupport
Reproducibility:            always
Severity:                   minor
Priority:                   normal
Status:                     new
Asterisk Version:           1.4.27.1 
JIRA:                       SWP-478 
Regression:                 No 
Reviewboard Link:            
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2009-12-03 10:04 CST
Last Modified:              2009-12-22 03:34 CST
====================================================================== 
Summary:                    SIP OPTIONS qualify message forever
Description: 
Hello, I have a trouble with different Asterisk versions (1.4.26, 1.4.27,
1.4.27.1). When I use the steps below, Asterisk starts to send SIP OPTIONS
to the previous IP/port used by a SIP realtime peer (that has been pruned)
and will keep trying to send SIP OPTIONS pings forever, event if the peer
is connected with a new IP/port address.

I have just checked with my old Asterisk 1.2.27 with the same sip.conf and
I do not have the problem, the SIP OPTIONS stops once register timer has
expired.

During my experience to reproduce the bug, I have been able to have 10
IP/port currently pinged by the Asterisk server for one single peer.
And the only way to stop it is to restart Asterisk...

Thank you for your attention!
Marc Leurent
======================================================================
Relationships       ID      Summary
----------------------------------------------------------------------
related to          0015716 [patch] chan_sip fails to destroy chann...
related to          0015627 [patch] Asterisk runs out of sockets
====================================================================== 

---------------------------------------------------------------------- 
 (0115633) lftsy (reporter) - 2009-12-22 03:34
 https://issues.asterisk.org/view.php?id=16382#c115633 
---------------------------------------------------------------------- 
Good morning!
Sorry, but the problem is still there...
I have applied the patch you suggested on the Asterisk 1.4.28-rc1 version.
But I still have the problem.

My Asterisk is using 100% of one of my CPU, is flooding one of my peer
with SIP OPTIONS and is flooding my MySQL server with requests (about
35Mbps of bandwidth)

Here is the SIP message sent to the proxy in front of the users from
Asterisk each 10^-6s (so there is a lot of messages!!)
 OPTIONS sip:212.147.44.91 SIP/2.0
 Via: SIP/2.0/UDP 212.147.45.83:5060;branch=z9hG4bK496a1eaf;rport
 From: "asterisk" <sip:asterisk at 212.147.45.83>;tag=as57017886
 To: <sip:212.147.44.91>
 Contact: <sip:asterisk at 212.147.45.83>
 Call-ID: 3d82b1ef25ae14a2462447f3529bb8cf at 212.147.45.83
 CSeq: 102 OPTIONS
 User-Agent: Asterisk
 Max-Forwards: 70
 Date: Tue, 22 Dec 2009 08:21:42 GMT
 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
 Supported: replaces
 Content-Length: 0

 SIP/2.0 403 Forbidden - Flood Detection
 Via: SIP/2.0/UDP 212.147.45.83:5060;branch=z9hG4bK7c87247c;rport=5060
 From: "asterisk" <sip:asterisk at 212.147.45.83>;tag=as086c62f2
 To: <sip:212.147.44.91>;tag=00f65ed7cfd3e4fbbaec16b7a8524c0b.9ba2
 Call-ID: 1584ec2d6084f6e67f56917a70e77f20 at 212.147.45.83
 CSeq: 102 OPTIONS
 Server: SIP Proxy
 Content-Length: 0


And here is the MySQL request also sent by Asterisk each 10^-3 s
 SELECT * FROM sip_users WHERE name = '024xxxxxxx' AND host = 'dynamic'


I have blocked with iptables the requests so I can keep the Asterisk in
this flooding mode to be able to give you as many bug report as we will
need!!!


I have typed Asterisk debugging on google and I have found
http://www.voip-info.org/wiki/view/Asterisk+debugging
But I have some trouble understanding it...

Here a set of command I have typed:

(SCREEN):root at bas-flu-vp-ast-03:[~]# asterisk -rx "show version"
Asterisk 1.4.28-rc1 built by root @ bas-flu-vp-ast-03 on a x86_64 running
Linux on 2009-12-11 16:34:43 UTC
(SCREEN):root at bas-flu-vp-ast-03:[~]#     

(SCREEN):root at bas-flu-vp-ast-03:[~]# asterisk -rx "database show"
/SIP/Registry/0245667945



(gdb) info thread
  15 Thread 0x4201e940 (LWP 30774)  0x00000032642ca556 in poll () from
/lib64/libc.so.6
  14 Thread 0x412ed940 (LWP 30775)  0x00000032642ca556 in poll () from
/lib64/libc.so.6
  13 Thread 0x4074d940 (LWP 30776)  0x0000003264e0d56b in connect () from
/lib64/libpthread.so.0
  12 Thread 0x409b4940 (LWP 30777)  0x00000032642cc5e2 in select () from
/lib64/libc.so.6
  11 Thread 0x40554940 (LWP 30778)  0x00000032642cc5e2 in select () from
/lib64/libc.so.6
  10 Thread 0x40e4f940 (LWP 30779)  0x00000032642cc5e2 in select () from
/lib64/libc.so.6
  9 Thread 0x41ab3940 (LWP 30787)  ast_sched_add_variable (con=0x19eef820,
when=4000, callback=0x2aaab9654f70 <sip_poke_noanswer>,
    data=0x2aaaac3daee0, variable=0) at sched.c:178
  8 Thread 0x41ec0940 (LWP 30788)  0x0000003264e0a899 in
pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  7 Thread 0x411fb940 (LWP 30789)  0x00000032642cc5e2 in select () from
/lib64/libc.so.6
  6 Thread 0x401df940 (LWP 30791)  0x00000032642ca556 in poll () from
/lib64/libc.so.6
  5 Thread 0x4042f940 (LWP 30792)  0x0000003264e0db71 in nanosleep () from
/lib64/libpthread.so.0
  4 Thread 0x40937940 (LWP 30794)  0x00000032642ca556 in poll () from
/lib64/libc.so.6
  3 Thread 0x4209a940 (LWP 30805)  0x00000032642ca556 in poll () from
/lib64/libc.so.6
  2 Thread 0x41e3e940 (LWP 30809)  0x0000003264e0a899 in
pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
* 1 Thread 0x2b964422c510 (LWP 30770)  0x0000003264e0d2cb in read () from
/lib64/libpthread.so.0
(gdb)




Thread 15 (Thread 0x4201e940 (LWP 30774)):
https://issues.asterisk.org/view.php?id=0  0x00000032642ca556 in poll () from
/lib64/libc.so.6
https://issues.asterisk.org/view.php?id=1  0x0000000000422774 in listener
(unused=<value optimized out>) at
asterisk.c:1010
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 14 (Thread 0x412ed940 (LWP 30775)):
https://issues.asterisk.org/view.php?id=0  0x00000032642ca556 in poll () from
/lib64/libc.so.6
https://issues.asterisk.org/view.php?id=1  0x000000000046a591 in accept_thread
(ignore=<value optimized out>) at
manager.c:2484
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 13 (Thread 0x4074d940 (LWP 30776)):
https://issues.asterisk.org/view.php?id=0  0x0000003264e0d56b in connect () from
/lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=1  0x00002aaab3e243b6 in my_connect ()
from
/usr/lib64/mysql/libmysqlclient.so.15
https://issues.asterisk.org/view.php?id=2  0x00002aaab3e26b8d in
mysql_real_connect () from
/usr/lib64/mysql/libmysqlclient.so.15
https://issues.asterisk.org/view.php?id=3  0x00002aaab6fcd9d0 in ?? () from
/usr/lib/asterisk/modules/res_config_mysql.so
https://issues.asterisk.org/view.php?id=4  0x00002aaab6fcec41 in ?? () from
/usr/lib/asterisk/modules/res_config_mysql.so
https://issues.asterisk.org/view.php?id=5  0x0000000000446ee4 in
ast_load_realtime (family=0x2aaab967d8e2
"sippeers") at config.c:1428
https://issues.asterisk.org/view.php?id=6  0x00002aaab964bc13 in find_peer
(peer=0x4074cb20 "0245667911",
sin=0x0, realtime=<value optimized out>, devstate_only=1)
    at chan_sip.c:2671
https://issues.asterisk.org/view.php?id=7  0x00002aaab9654dcc in sip_devicestate
(data=0x4074cfa4) at
chan_sip.c:17255
https://issues.asterisk.org/view.php?id=8  0x000000000044c803 in
ast_device_state (device=0x2aaac401a148
"SIP/0245667911") at devicestate.c:170
https://issues.asterisk.org/view.php?id=9  0x000000000044cc90 in do_state_change
(device=0x5 <Address 0x5 out of
bounds>) at devicestate.c:285
https://issues.asterisk.org/view.php?id=10 0x000000000044cd6d in
do_devstate_changes (data=<value optimized out>)
at devicestate.c:346
https://issues.asterisk.org/view.php?id=11 0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=12 0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=13 0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 12 (Thread 0x409b4940 (LWP 30777)):
https://issues.asterisk.org/view.php?id=0  0x00000032642cc5e2 in select () from
/lib64/libc.so.6
https://issues.asterisk.org/view.php?id=1  0x00002aaab1025a4f in
do_parking_thread (ignore=<value optimized out>)
at /usr/src/asterisk-1.4.28-rc1/include/asterisk/channel.h:1378
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6


Thread 11 (Thread 0x40554940 (LWP 30778)):
https://issues.asterisk.org/view.php?id=0  0x00000032642cc5e2 in select () from
/lib64/libc.so.6
https://issues.asterisk.org/view.php?id=1  0x00002aaab31956ab in sound_thread
(arg=<value optimized out>) at
/usr/src/asterisk-1.4.28-rc1/include/asterisk/channel.h:1378
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 10 (Thread 0x40e4f940 (LWP 30779)):
https://issues.asterisk.org/view.php?id=0  0x00000032642cc5e2 in select () from
/lib64/libc.so.6
https://issues.asterisk.org/view.php?id=1  0x00002aaab31956ab in sound_thread
(arg=<value optimized out>) at
/usr/src/asterisk-1.4.28-rc1/include/asterisk/channel.h:1378
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 9 (Thread 0x41ab3940 (LWP 30787)):
https://issues.asterisk.org/view.php?id=0  ast_sched_add_variable
(con=0x19eef820, when=4000,
callback=0x2aaab9654f70 <sip_poke_noanswer>, data=0x2aaaac3daee0,
variable=0)
    at sched.c:178
https://issues.asterisk.org/view.php?id=1  0x00002aaab9648bd8 in sip_poke_peer
(peer=0x2aaaac3daee0) at
chan_sip.c:17186
https://issues.asterisk.org/view.php?id=2  0x00002aaab9666509 in sip_poke_peer_s
(data=0x211e3c90) at
chan_sip.c:8497
https://issues.asterisk.org/view.php?id=3  0x00000000004a3728 in ast_sched_runq
(con=<value optimized out>) at
sched.c:363
https://issues.asterisk.org/view.php?id=4  0x00002aaab9662ae5 in do_monitor
(data=<value optimized out>) at
chan_sip.c:17020
https://issues.asterisk.org/view.php?id=5  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=6  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=7  0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 8 (Thread 0x41ec0940 (LWP 30788)):
https://issues.asterisk.org/view.php?id=0  0x0000003264e0a899 in
pthread_cond_wait@@GLIBC_2.3.2 () from
/lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=1  0x00002aaaba09a79b in
device_state_thread (data=<value optimized out>)
at /usr/src/asterisk-1.4.28-rc1/include/asterisk/lock.h:791
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6


Thread 7 (Thread 0x411fb940 (LWP 30789)):
https://issues.asterisk.org/view.php?id=0  0x00000032642cc5e2 in select () from
/lib64/libc.so.6
https://issues.asterisk.org/view.php?id=1  0x00002aaaba865bca in
agent_check_and_process () from
/usr/lib64/libnetsnmpagent.so.10
https://issues.asterisk.org/view.php?id=2  0x00002aaaba2aebfa in agent_thread
(arg=<value optimized out>) at
snmp/agent.c:162
https://issues.asterisk.org/view.php?id=3  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=4  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=5  0x00000032642d309d in clone () from
/lib64/libc.so.6


Thread 6 (Thread 0x401df940 (LWP 30791)):
https://issues.asterisk.org/view.php?id=0  0x00000032642ca556 in poll () from
/lib64/libc.so.6
https://issues.asterisk.org/view.php?id=1  0x00002aaabf4491fb in do_monitor
(data=<value optimized out>) at
chan_dahdi.c:7333
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 5 (Thread 0x4042f940 (LWP 30792)):
https://issues.asterisk.org/view.php?id=0  0x0000003264e0db71 in nanosleep ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=1  0x00002aaac23edd4a in scan_thread
(unused=<value optimized out>) at
pbx_spool.c:458
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 4 (Thread 0x40937940 (LWP 30794)):
https://issues.asterisk.org/view.php?id=0  0x00000032642ca556 in poll () from
/lib64/libc.so.6
https://issues.asterisk.org/view.php?id=1  0x0000000000420a65 in
monitor_sig_flags (unused=<value optimized out>)
at asterisk.c:2679
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 3 (Thread 0x4209a940 (LWP 30805)):
https://issues.asterisk.org/view.php?id=0  0x00000032642ca556 in poll () from
/lib64/libc.so.6
https://issues.asterisk.org/view.php?id=1  0x0000000000422bdd in netconsole
(vconsole=<value optimized out>) at
asterisk.c:959
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 2 (Thread 0x41e3e940 (LWP 30809)):
https://issues.asterisk.org/view.php?id=0  0x0000003264e0a899 in
pthread_cond_wait@@GLIBC_2.3.2 () from
/lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=1  0x000000000042a2e5 in autoservice_run
(ign=<value optimized out>) at
/usr/src/asterisk-1.4.28-rc1/include/asterisk/lock.h:791
https://issues.asterisk.org/view.php?id=2  0x00000000004b00bc in dummy_start
(data=<value optimized out>) at
utils.c:856
https://issues.asterisk.org/view.php?id=3  0x0000003264e06367 in start_thread ()
from /lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=4  0x00000032642d309d in clone () from
/lib64/libc.so.6

Thread 1 (Thread 0x2b964422c510 (LWP 30770)):
https://issues.asterisk.org/view.php?id=0  0x0000003264e0d2cb in read () from
/lib64/libpthread.so.0
https://issues.asterisk.org/view.php?id=1  0x00000000004ba9e0 in read_char
(el=0x19e6df20, cp=0x7fffbb9960ff "")
at read.c:298
https://issues.asterisk.org/view.php?id=2  0x00000000004b59a0 in el_getc
(el=0x19e6df20, cp=0x7fffbb9960ff "") at
read.c:350
https://issues.asterisk.org/view.php?id=3  0x00000000004b5e00 in el_gets
(el=0x19e6df20, nread=0x7fffbb9966dc) at
read.c:243
https://issues.asterisk.org/view.php?id=4  0x0000000000427059 in main
(argc=<value optimized out>, argv=0x1) at
asterisk.c:3212 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2009-12-22 03:34 lftsy          Note Added: 0115633                          
2009-12-22 03:34 lftsy          Status                   closed => new       
2009-12-22 03:34 lftsy          Resolution               fixed => reopened   
======================================================================

More information about the asterisk-bugs mailing list