7 Apr
2004
7 Apr
'04
1:35 a.m.
The ACK came .0784 seconds after the 503 was returned according to the
ethereal dump.
Mike
-----Original Message-----
From: Jan Janak [mailto:jan@iptel.org]
Sent: Tuesday, April 06, 2004 5:21 PM
To: Mike Morrison
Cc: 'serusers(a)lists.iptel.org'
Subject: Re: [Serusers] Not Recognizing ACK
Are you sure that the ACK comes no later than 2 seconds after 503 is
sent ?
Jan.
On 05-04 13:28, Mike Morrison wrote:
Running SER 0.8.12 on Solaris 8 -SPARC with MySQL
installed.
The issue that I'm running into is that when the originating GW receives a
response and generates an ACK the SER doesn't seem to stop the timer for
resending the message. If you look in the log, you can see where the
server
receives it, but the server resends the same response
as if the ACK was
ignored. It the attached case a 503 response is sent back, but the same
situation occurs when other responses are sent.
Thanks, Mike
Script started on Tue 30 Mar 2004 04:56:58 PM CST
# /usr/local/sbin/ser
0(29441) loading module /usr/local/lib/ser/modules/mysql.so
0(29441) loading module /usr/local/lib/ser/modules/sl.so
0(29441) loading module /usr/local/lib/ser/modules/tm.so
0(29441) loading module /usr/local/lib/ser/modules/rr.so
0(29441) loading module /usr/local/lib/ser/modules/maxfwd.so
0(29441) loading module /usr/local/lib/ser/modules/usrloc.so
0(29441) loading module /usr/local/lib/ser/modules/registrar.so
0(29441) set_mod_param_regex: usrloc matches module usrloc
0(29441) set_mod_param_regex: found <db_mode> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) set_mod_param_regex: rr matches module rr
0(29441) set_mod_param_regex: found <enable_full_lr> in module rr
[/usr/local/lib/ser/modules/rr.so]
0(29441) find_export: found
<mf_process_maxfwd_header> in module
maxfwd_module
[/usr/local/lib/ser/modules/maxfwd.so]
0(29441) find_export: found <sl_send_reply> in
module sl_module
[/usr/local/lib/ser/modules/sl.so]
0(29441) find_export: found <sl_send_reply> in
module sl_module
[/usr/local/lib/ser/modules/sl.so]
0(29441) find_export: found <record_route> in
module rr
[/usr/local/lib/ser/modules/rr.so]
0(29441) find_export: found <sl_send_reply> in
module sl_module
[/usr/local/lib/ser/modules/sl.so]
0(29441) find_export: found <t_relay> in module
tm
[/usr/local/lib/ser/modules/tm.so]
0(29441) find_export: found <sl_reply_error> in
module sl_module
[/usr/local/lib/ser/modules/sl.so]
0(29441) routing table 0:
0(29441) if ( 0(29441) NOT( 0(29441) external_module_call( 0(29441)
f_ptr<fcf20ca0> 0(29441) , "10" 0(29441) ); 0(29441)
external_module_call(
0(29441) f_ptr<fcf20ca0> 0(29441) , "10" 0(29441) ); 0(29441) ) 0(29441)
)
{ 0(29441) external_module_call( 0(29441) f_ptr<ff1518c0> 0(29441) ,
"483"
0(29441) , "Too Many Hops" 0(29441) ); 0(29441) drop( 0(29441) type<0>
0(29441) ); 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) UNKNOWN
0(29441) <UNKNOWN> 0(29441) 65535 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518c0> 0(29441) , "513" 0(29441)
,
"Message too big" 0(29441) ); 0(29441) drop( 0(29441) type<0> 0(29441)
);
0(29441) } else { 0(29441) }; 0(29441) external_module_call( 0(29441)
f_ptr<fcf435e0> 0(29441) ); 0(29441) if ( 0(29441) method 0(29441) ==
0(29441) "REGISTER" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED REGISTER
******************************
" 0(29441) ); 0(29441) external_module_call(
0(29441) f_ptr<ff1518c0>
0(29441) , "200" 0(29441) , "ok"
0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "OPTIONS" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED OPTIONS MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "INFO" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED INFO MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport( 0(29441)
"10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT( 0(29441)
external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) UNKNOWN
0(29441) <UNKNOWN> 0(29441) 65535 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518c0> 0(29441) , "513" 0(29441)
,
"Message too big" 0(29441) ); 0(29441) drop( 0(29441) type<0> 0(29441)
);
0(29441) } else { 0(29441) }; 0(29441) external_module_call( 0(29441)
f_ptr<fcf435e0> 0(29441) ); 0(29441) if ( 0(29441) method 0(29441) ==
0(29441) "REGISTER" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED REGISTER
******************************
" 0(29441) ); 0(29441) external_module_call(
0(29441) f_ptr<ff1518c0>
0(29441) , "200" 0(29441) , "ok"
0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "OPTIONS" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED OPTIONS MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "INFO" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED INFO MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport( 0(29441)
"10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT( 0(29441)
external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441)
external_module_call( 0(29441) f_ptr<fcf435e0> 0(29441) ); 0(29441) if (
0(29441) method 0(29441) == 0(29441) "REGISTER" 0(29441) ) { 0(29441) log(
0(29441) 1 0(29441) , "************************** RECEIVED REGISTER
******************************
" 0(29441) ); 0(29441) external_module_call(
0(29441) f_ptr<ff1518c0>
0(29441) , "200" 0(29441) , "ok"
0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "OPTIONS" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED OPTIONS MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "INFO" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED INFO MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport( 0(29441)
"10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT( 0(29441)
external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "REGISTER" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED REGISTER
******************************
" 0(29441) ); 0(29441) external_module_call(
0(29441) f_ptr<ff1518c0>
0(29441) , "200" 0(29441) , "ok"
0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "OPTIONS" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED OPTIONS MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "INFO" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED INFO MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport( 0(29441)
"10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT( 0(29441)
external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "OPTIONS" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED OPTIONS MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "INFO" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED INFO MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport( 0(29441)
"10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT( 0(29441)
external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "INFO" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"********************* RECEIVED INFO MESSAGE ****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport( 0(29441)
"10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT( 0(29441)
external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "CANCEL" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441)
, "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport( 0(29441)
"10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT( 0(29441)
external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "ACK" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport( 0(29441)
"10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT( 0(29441)
external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441)
, "************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport( 0(29441)
"10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT( 0(29441)
external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441)
Listening on
10.31.14.200 [10.31.14.200]:5060
Aliases: loghost:5060 caveman:5060
WARNING: no fork mode
0(29441) DEBUG: init_mod: mysql
0(29441) mysql - initializing
0(29441) DEBUG: init_mod: sl_module
stateless - initializing
0(29441) DEBUG: register_fifo_cmd: new command (sl_stats) registered
0(29441) DEBUG: MD5 calculated: 9c818f52bcc4fffa9610568f4be52539
0(29441) DEBUG: init_mod: tm
0(29441) TM - initializing...
0(29441) Call-ID initialization: '58282eed'
0(29441) DEBUG: register_fifo_cmd: new command (t_uac_dlg) registered
0(29441) DEBUG: register_fifo_cmd: new command (t_hash) registered
0(29441) DEBUG: lock_initialize: lock initialization started
0(29441) DEBUG: register_fifo_cmd: new command (t_stats) registered
0(29441) Warning: uac does not spread accross the whole hash table
0(29441) DEBUG: MD5 calculated: 6846af86154c482b36472261b1d13258
0(29441) DEBUG: MD5 calculated: 19d4d767dedba5e9d0a57f60eb631aa7
0(29441) DEBUG: init_mod: rr
0(29441) rr - initializing
0(29441) DEBUG: init_mod: maxfwd_module
Maxfwd module- initializing
0(29441) DEBUG: init_mod: usrloc
0(29441) usrloc - initializing
0(29441) DEBUG: register_fifo_cmd: new command (ul_stats) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_rm) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_rm_contact) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_dump) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_flush) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_add) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_show_contact)
registered
0(29441) find_export: found <db_use_table> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_init> in module
mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_close> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_query> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_raw_query> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_free_query> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_insert> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_delete> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_update> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
> 0(29441) mod_init(): Database connection opened successfuly
> 0(29441) DEBUG: init_mod: registrar
> 0(29441) registrar - initializing
0(29441) find_export: found <sl_send_reply> in
module sl_module
[/usr/local/lib/ser/modules/sl.so]
0(29441) find_export: found <ul_bind_usrloc> in
module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_register_udomain> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_get_all_ucontacts> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found <ul_insert_urecord>
in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found <ul_delete_urecord>
in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found <ul_get_urecord> in
module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found <ul_lock_udomain>
in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found <ul_unlock_udomain>
in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_release_urecord> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_insert_ucontact> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_delete_ucontact> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found <ul_get_ucontact>
in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_update_ucontact> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(0) fixing /usr/local/lib/ser/modules/maxfwd.so
mf_process_maxfwd_header
0(0) fixing /usr/local/lib/ser/modules/sl.so sl_send_reply
0(0) fixing /usr/local/lib/ser/modules/sl.so sl_send_reply
0(0) fixing /usr/local/lib/ser/modules/rr.so record_route
0(0) fixing /usr/local/lib/ser/modules/sl.so sl_send_reply
0(0) fixing /usr/local/lib/ser/modules/tm.so t_relay
0(0) fixing /usr/local/lib/ser/modules/sl.so sl_reply_error
0(0) INFO: udp_init: SO_RCVBUF is initially 8192
0(0) DEBUG: udp_init: trying SO_RCVBUF: 16384
0(0) DEBUG: setting SO_RCVBUF; set=16384,verify=16384
0(0) DEBUG: udp_init: trying SO_RCVBUF: 32768
0(0) DEBUG: setting SO_RCVBUF; set=32768,verify=32768
0(0) DEBUG: udp_init: trying SO_RCVBUF: 65536
0(0) DEBUG: setting SO_RCVBUF; set=65536,verify=65536
0(0) DEBUG: udp_init: trying SO_RCVBUF: 131072
0(0) DEBUG: setting SO_RCVBUF; set=131072,verify=131072
0(0) DEBUG: udp_init: trying SO_RCVBUF: 262144
0(0) DEBUG: setting SO_RCVBUF; set=262144,verify=262144
0(0) INFO: udp_init: SO_RCVBUF is finally 262144
1(0) DEBUG: init_mod_child (-1): tm
1(0) DEBUG: callid: '58282eed-0(a)10.31.14.200'
1(0) DEBUG: init_mod_child (-1): usrloc
1(29442) DBG: open_uac_fifo: opening fifo...
1(29442) DEBUG: open_fifo_server: FIFO stat failed: Error 0
1(29442) DEBUG: FIFO created @ /tmp/ser_fifo
1(29442) DEBUG: fifo /tmp/ser_fifo opened, mode=432
2(0) INFO: fifo process starting: 29443
2(0) DEBUG: init_mod_child (-2): tm
2(0) DEBUG: callid: '58282eed-0(a)10.31.14.200'
2(0) DEBUG: init_mod_child (-2): usrloc
2(29443) SER: open_uac_fifo: fifo server up at /tmp/ser_fifo...
0(29441) DEBUG: init_mod_child (1): tm
0(29441) DEBUG: callid: '58282eed-29441(a)10.31.14.200'
0(29441) DEBUG: init_mod_child (1): usrloc
0(29441) SIP Request:
0(29441) method: <INVITE>
0(29441) uri: <sip:5551111234@10.31.14.200;dtg=LAB_LA_TERM>
0(29441) version: <SIP/2.0>
0(29441) parse_headers: flags=1
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) preparing to run routing scripts...
0(29441) DEBUG : is_maxfwd_present: searching for max_forwards header
0(29441) parse_headers: flags=128
0(29441) end of header reached, state=9
0(29441) DEBUG: get_hdr_field: <To> [36];
uri=[sip:5551111234@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111234@10.31.14.200:5060>
]
0(29441) get_hdr_field: cseq <CSeq>: <3267> <INVITE>
0(29441) DEBUG: get_hdr_body : content_length=152
0(29441) found end of header
0(29441) DEBUG: is_maxfwd_present: max_forwards header not found!
0(29441) DEBUG: add_param: pstn-params=808182808882
0(29441) DEBUG: add_param: tag=72
0(29441) end of header reached, state=29
0(29441) ************************** RECEIVED INVITE
********************************
0(29441) DEBUG: t_addifnew: msg id=1 , global msg
id=0 , T on
entrance=ffffffff
0(29441) parse_headers: flags=-1
0(29441) parse_headers: flags=60
0(29441) t_lookup_request: start searching: hash=35190, isACK=0
0(29441) DEBUG: proceeding to pre-RFC3261 transaction matching
0(29441) DEBUG: t_lookup_request: no transaction found
0(29441) SER: new INVITE
0(29441) parse_headers: flags=-1
0(29441) check_via_address(10.31.14.253, 10.31.14.253, 0)
0(29441) WARNING:vqm_resize: resize(0) called
0(29441) DEBUG: reply sent out. buf=9c390: SIP/2.0 1..., shmem=fd184a28:
SIP/2.0
1
0(29441) DEBUG: t_reply: finished
0(29441) DEBUG: mk_proxy: doing DNS lookup...
0(29441) check_via_address(10.31.14.253, 10.31.14.253, 0)
0(29441) DEBUG: add_to_tail_of_timer[4]: fd18332c
0(29441) DEBUG: add_to_tail_of_timer[0]: fd183340
0(29441) SER: new transaction fwd'ed
0(29441) receive_msg: cleaning up
0(29441) SIP Reply (status):
0(29441) version: <SIP/2.0>
0(29441) status: <100>
0(29441) reason: <Trying>
0(29441) parse_headers: flags=1
0(29441) Found param type 232, <branch> = <z9hG4bK6798.3d17.0>; state=16
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) check_self - checking if host==us: 12==12 && [10.31.14.200] ==
[10.31.14.200]
0(29441) check_self - checking if port 5060 matches
port 5060
0(29441) forward_reply: found module tm, passing reply to it
0(29441) DEBUG: t_check: msg id=2 global id=1 T start=ffffffff
0(29441) parse_headers: flags=17
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=17
0(29441) parse_headers: this is the second via
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111234@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111234@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <3267> <INVITE>
0(29441) parse_headers: flags=4
0(29441) DEBUG: t_reply_matching: hash 35190 label 29139 branch 0
0(29441) DEBUG: t_reply_matching: reply matched (T=fd183200)!
0(29441) DEBUG: t_check: msg id=2 global id=2 T end=fd183200
0(29441) DEBUG: t_on_reply: org. status uas=100, uac[0]=0 local=0
is_invite=1)
0(29441) ->>>>>>>>>
T_code=100, new_code=100
0(29441) DEBUG: relay_reply: branch=0, save=0, relay=-1
0(29441) DEBUG: add_to_tail_of_timer[1]: fd183340
0(29441) receive_msg: cleaning up
0(29441) SIP Reply (status):
0(29441) version: <SIP/2.0>
0(29441) status: <503>
0(29441) reason: <Service Unavailable>
0(29441) parse_headers: flags=1
0(29441) Found param type 232, <branch> = <z9hG4bK6798.3d17.0>; state=16
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) check_self - checking if host==us: 12==12 && [10.31.14.200] ==
[10.31.14.200]
0(29441) check_self - checking if port 5060 matches
port 5060
0(29441) forward_reply: found module tm, passing reply to it
0(29441) DEBUG: t_check: msg id=3 global id=2 T start=ffffffff
0(29441) parse_headers: flags=17
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=17
0(29441) parse_headers: this is the second via
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111234@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111234@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <3267> <INVITE>
0(29441) parse_headers: flags=4
0(29441) DEBUG: t_reply_matching: hash 35190 label 29139 branch 0
0(29441) DEBUG: t_reply_matching: reply matched (T=fd183200)!
0(29441) DEBUG: t_check: msg id=3 global id=3 T end=fd183200
0(29441) DEBUG: t_on_reply: org. status uas=100, uac[0]=100 local=0
is_invite=1)
0(29441) parse_headers: flags=4
0(29441) ->>>>>>>>> T_code=100, new_code=503
0(29441) DEBUG: relay_reply: branch=0, save=0, relay=0
0(29441) old size: 385, new size: 328
0(29441) build_res_from_sip_res: copied size: orig:90, new: 33, rest: 295
msg=
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 10.31.14.253:4000
From: <sip:5127351243@10.31.14.253:4000>;pstn-params=808182808882;tag=72
To: <sip:5551111234@10.31.14.200:5060>;tag=61
Call-ID: 947552_97051161(a)10.31.14.253
CSeq: 3267 INVITE
Record-Route: <sip:5551111234@10.31.14.200;ftag=72;lr=on>
Content-Length: 0
0(29441) DEBUG: reply relayed. buf=9c5d0: SIP/2.0 5..., shmem=fd1850e0:
SIP/2.0 5
0(29441) DEBUG: cleanup_uacs: RETR/FR timers reset
0(29441) DEBUG: add_to_tail_of_timer[4]: fd1832b4
0(29441) DEBUG: add_to_tail_of_timer[0]: fd1832c8
0(29441) receive_msg: cleaning up
0(29441) SIP Request:
0(29441) method: <ACK>
0(29441) uri: <sip:5551111234@10.31.14.200>
0(29441) version: <SIP/2.0>
0(29441) parse_headers: flags=1
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) DEBUG : sl_filter_ACK: to late to be a local ACK!
0(29441) preparing to run routing scripts...
0(29441) DEBUG : is_maxfwd_present: searching for max_forwards header
0(29441) parse_headers: flags=128
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111234@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111234@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <3267> <ACK>
0(29441) DEBUG: get_hdr_body : content_length=0
0(29441) found end of header
0(29441) DEBUG: is_maxfwd_present: max_forwards header not found!
0(29441) DEBUG: add_param: pstn-params=808182808882
0(29441) DEBUG: add_param: tag=72
0(29441) end of header reached, state=29
0(29441) ************************** RECEIVED ACK
***********************************
0(29441) receive_msg: cleaning up
1(29442) DEBUG: timer routine:1,tl=fd183340 next=0
1(29442) DEBUG: timer routine:4,tl=fd18332c next=fd1832b4
1(29442) DEBUG: timer routine:4,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[5]: fd1832b4
1(29442) DEBUG: retransmission_handler : done
0(29441) SIP Request:
0(29441) method: <INVITE>
0(29441) uri: <sip:5551111235@10.31.14.200;dtg=LAB_LA_TERM>
0(29441) version: <SIP/2.0>
0(29441) parse_headers: flags=1
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) preparing to run routing scripts...
0(29441) DEBUG : is_maxfwd_present: searching for max_forwards header
0(29441) parse_headers: flags=128
0(29441) end of header reached, state=9
0(29441) DEBUG: get_hdr_field: <To> [36];
uri=[sip:5551111235@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111235@10.31.14.200:5060>
]
0(29441) get_hdr_field: cseq <CSeq>: <5023> <INVITE>
0(29441) DEBUG: get_hdr_body : content_length=152
0(29441) found end of header
0(29441) DEBUG: is_maxfwd_present: max_forwards header not found!
0(29441) DEBUG: add_param: pstn-params=808182808882
0(29441) DEBUG: add_param: tag=72
0(29441) end of header reached, state=29
0(29441) ************************** RECEIVED INVITE
********************************
0(29441) DEBUG: t_addifnew: msg id=5 , global msg
id=3 , T on
entrance=ffffffff
0(29441) parse_headers: flags=-1
0(29441) parse_headers: flags=60
0(29441) t_lookup_request: start searching: hash=48741, isACK=0
0(29441) DEBUG: proceeding to pre-RFC3261 transaction matching
0(29441) DEBUG: t_lookup_request: no transaction found
0(29441) SER: new INVITE
0(29441) parse_headers: flags=-1
0(29441) check_via_address(10.31.14.253, 10.31.14.253, 0)
0(29441) WARNING:vqm_resize: resize(0) called
0(29441) DEBUG: reply sent out. buf=9c728: SIP/2.0 1..., shmem=fd184a28:
SIP/2.0
1
0(29441) DEBUG: t_reply: finished
0(29441) DEBUG: mk_proxy: doing DNS lookup...
0(29441) check_via_address(10.31.14.253, 10.31.14.253, 0)
0(29441) DEBUG: add_to_tail_of_timer[4]: fd18538c
0(29441) DEBUG: add_to_tail_of_timer[0]: fd1853a0
0(29441) SER: new transaction fwd'ed
0(29441) receive_msg: cleaning up
0(29441) SIP Reply (status):
0(29441) version: <SIP/2.0>
0(29441) status: <100>
0(29441) reason: <Trying>
0(29441) parse_headers: flags=1
0(29441) Found param type 232, <branch> = <z9hG4bK56eb.77a1.0>; state=16
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) check_self - checking if host==us: 12==12 && [10.31.14.200] ==
[10.31.14.200]
0(29441) check_self - checking if port 5060 matches
port 5060
0(29441) forward_reply: found module tm, passing reply to it
0(29441) DEBUG: t_check: msg id=6 global id=5 T start=ffffffff
0(29441) parse_headers: flags=17
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=17
0(29441) parse_headers: this is the second via
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111235@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111235@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <5023> <INVITE>
0(29441) parse_headers: flags=4
0(29441) DEBUG: t_reply_matching: hash 48741 label 6775 branch 0
0(29441) DEBUG: t_reply_matching: reply matched (T=fd185260)!
0(29441) DEBUG: t_check: msg id=6 global id=6 T end=fd185260
0(29441) DEBUG: t_on_reply: org. status uas=100, uac[0]=0 local=0
is_invite=1)
0(29441) ->>>>>>>>>
T_code=100, new_code=100
0(29441) DEBUG: relay_reply: branch=0, save=0, relay=-1
0(29441) DEBUG: add_to_tail_of_timer[1]: fd1853a0
0(29441) receive_msg: cleaning up
0(29441) SIP Reply (status):
0(29441) version: <SIP/2.0>
0(29441) status: <503>
0(29441) reason: <Service Unavailable>
0(29441) parse_headers: flags=1
0(29441) Found param type 232, <branch> = <z9hG4bK56eb.77a1.0>; state=16
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) check_self - checking if host==us: 12==12 && [10.31.14.200] ==
[10.31.14.200]
0(29441) check_self - checking if port 5060 matches
port 5060
0(29441) forward_reply: found module tm, passing reply to it
0(29441) DEBUG: t_check: msg id=7 global id=6 T start=ffffffff
0(29441) parse_headers: flags=17
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=17
0(29441) parse_headers: this is the second via
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111235@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111235@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <5023> <INVITE>
0(29441) parse_headers: flags=4
0(29441) DEBUG: t_reply_matching: hash 48741 label 6775 branch 0
0(29441) DEBUG: t_reply_matching: reply matched (T=fd185260)!
0(29441) DEBUG: t_check: msg id=7 global id=7 T end=fd185260
0(29441) DEBUG: t_on_reply: org. status uas=100, uac[0]=100 local=0
is_invite=1)
0(29441) parse_headers: flags=4
0(29441) ->>>>>>>>> T_code=100, new_code=503
0(29441) DEBUG: relay_reply: branch=0, save=0, relay=0
0(29441) old size: 385, new size: 328
0(29441) build_res_from_sip_res: copied size: orig:90, new: 33, rest: 295
msg=
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 10.31.14.253:4000
From: <sip:5127351244@10.31.14.253:4000>;pstn-params=808182808882;tag=72
To: <sip:5551111235@10.31.14.200:5060>;tag=61
Call-ID: 947553_97051261(a)10.31.14.253
CSeq: 5023 INVITE
Record-Route: <sip:5551111235@10.31.14.200;ftag=72;lr=on>
Content-Length: 0
0(29441) DEBUG: reply relayed. buf=9c5d0: SIP/2.0 5..., shmem=fd186e60:
SIP/2.0 5
0(29441) DEBUG: cleanup_uacs: RETR/FR timers reset
0(29441) DEBUG: add_to_tail_of_timer[4]: fd185314
0(29441) DEBUG: add_to_tail_of_timer[0]: fd185328
0(29441) receive_msg: cleaning up
0(29441) SIP Request:
0(29441) method: <ACK>
0(29441) uri: <sip:5551111235@10.31.14.200>
0(29441) version: <SIP/2.0>
0(29441) parse_headers: flags=1
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) DEBUG : sl_filter_ACK: to late to be a local ACK!
0(29441) preparing to run routing scripts...
0(29441) DEBUG : is_maxfwd_present: searching for max_forwards header
0(29441) parse_headers: flags=128
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111235@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111235@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <5023> <ACK>
0(29441) DEBUG: get_hdr_body : content_length=0
0(29441) found end of header
0(29441) DEBUG: is_maxfwd_present: max_forwards header not found!
0(29441) DEBUG: add_param: pstn-params=808182808882
0(29441) DEBUG: add_param: tag=72
0(29441) end of header reached, state=29
0(29441) ************************** RECEIVED ACK
***********************************
0(29441) receive_msg: cleaning up
1(29442) DEBUG: timer routine:1,tl=fd1853a0 next=0
1(29442) DEBUG: timer routine:4,tl=fd18538c next=fd185314
1(29442) DEBUG: timer routine:4,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[5]: fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:5,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[6]: fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:5,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[6]: fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:6,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:6,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted. buf=fcf957a8:
SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]: fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:0,tl=fd1832c8 next=0
1(29442) DEBUG: add_to_tail_of_timer[2]: fd183248
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: timer routine:0,tl=fd185328 next=0
1(29442) DEBUG: add_to_tail_of_timer[2]: fd1852a8
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: timer routine:2,tl=fd183248 next=0
1(29442) DEBUG: wait_handler : removing fd183200 from table
1(29442) DEBUG: delete transaction fd183200
1(29442) DEBUG: wait_handler : done
1(29442) DEBUG: timer routine:2,tl=fd1852a8 next=0
1(29442) DEBUG: wait_handler : removing fd185260 from table
1(29442) DEBUG: delete transaction fd185260
1(29442) DEBUG: wait_handler : done
^C 0(29441) INT received, program terminates
1( 1( 1(29442) INFO: signal 15 received
1(29442) Memory status (pkg):
1(29442) fm_status (99f88):
1(29442) heap size= 1047440
1(29442) dumping free list:
1(29442) hash = 1 fragments no.: 3,
bucket size: 8 - 8 (first 8)
1(29442) hash = 2 fragments no.: 1,
bucket size: 16 - 16 (first 16)
1(29442) hash = 4 fragments no.: 1,
bucket size: 32 - 32 (first 32)
1(29442) hash = 46 fragments no.: 1,
bucket size: 368 - 368 (first 368)
1(29442) hash = 265 fragments no.: 1,
bucket size: 524288 - 1048576 (first 1042560)
1(29442) TOTAL: 7 free fragments = 1043000 free bytes
1(29442) -----------------------------
0(29441) DEBUG: tm_shutdown : start
0(29441) DEBUG: tm_shutdown : empting DELETE list
0(29441) DEBUG: tm_shutdown : empting hash table
0(29441) DEBUG: tm_shutdown: releasing timers
0(29441) DEBUG: tm_shutdown : removing semaphores
0(29441) DEBUG: tm_shutdown : done
0(29441) Memory status (pkg):
0(29441) fm_status (99f88):
0(29441) heap size= 1047440
0(29441) dumping free list:
0(29441) hash = 1 fragments no.: 7,
bucket size: 8 - 8 (first 8)
0(29441) hash = 2 fragments no.: 31,
bucket size: 16 - 16 (first 16)
0(29441) hash = 3 fragments no.: 7,
bucket size: 24 - 24 (first 24)
0(29441) hash = 4 fragments no.: 38,
bucket size: 32 - 32 (first 32)
0(29441) hash = 5 fragments no.: 2,
bucket size: 40 - 40 (first 40)
0(29441) hash = 7 fragments no.: 1,
bucket size: 56 - 56 (first 56)
0(29441) hash = 8 fragments no.: 1,
bucket size: 64 - 64 (first 64)
0(29441) hash = 9 fragments no.: 1,
bucket size: 72 - 72 (first 72)
0(29441) hash = 15 fragments no.: 2,
bucket size: 120 - 120 (first 120)
0(29441) hash = 17 fragments no.: 1,
bucket size: 136 - 136 (first 136)
0(29441) hash = 42 fragments no.: 1,
bucket size: 336 - 336 (first 336)
0(29441) hash = 68 fragments no.: 1,
bucket size: 544 - 544 (first 544)
0(29441) hash = 71 fragments no.: 1,
bucket size: 568 - 568 (first 2( 2( 2(29443)
INFO:
signal 15 received
2(29443) Memory status (pkg):
2(29443) fm_status (99f88):
2(29443) heap size= 1047440
2(29443) dumping free list:
2(29443) hash = 1 fragments no.: 3,
bucket size: 8 - 8 (first 8)
2(29443) hash = 2 fragments no.: 1,
bucket size: 16 - 16 (first 16)
2(29443) hash = 4 fragments no.: 1,
bucket size: 32 - 32 (first 32)
2(29443) hash = 46 fragments no.: 1,
bucket size: 368 - 368 (first 368)
2(29443) hash = 265 fragments no.: 1,
bucket size: 524288 - 1048576 (first 1042560)
2(29443) TOTAL: 7 free fragments = 1043000 free bytes
2(29443) -----------------------------
568)
0(29441) hash = 93 fragments no.: 1,
bucket size: 744 - 744 (first 744)
0(29441) hash = 122 fragments no.: 1,
bucket size: 976 - 976 (first 976)
0(29441) hash = 128 fragments no.: 1,
bucket size: 1024 - 1024 (first 1024)
0(29441) hash = 265 fragments no.: 1,
bucket size: 524288 - 1048576 (first 1036808)
0(29441) TOTAL: 98 free fragments = 1043584 free bytes
0(29441) -----------------------------
0(29441) Memory status (shm):
0(29441) fm_status (fd000000):
0(29441) heap size= 33553296
0(29441) dumping free list:
0(29441) hash = 1 fragments no.: 4,
bucket size: 8 - 8 (first 8)
0(29441) hash = 2 fragments no.: 1,
bucket size: 16 - 16 (first 16)
0(29441) hash = 5 fragments no.: 3,
bucket size: 40 - 40 (first 40)
0(29441) hash = 6 fragments no.: 3,
bucket size: 48 - 48 (first 48)
0(29441) hash = 41 fragments no.: 2,
bucket size: 328 - 328 (first 328)
0(29441) hash = 48 fragments no.: 1,
bucket size: 384 - 384 (first 384)
0(29441) hash = 91 fragments no.: 1,
bucket size: 728 - 728 (first 728)
0(29441) hash = 122 fragments no.: 2,
bucket size: 976 - 976 (first 976)
0(29441) hash = 130 fragments no.: 1,
bucket size: 1040 - 1040 (first 1040)
0(29441) hash = 210 fragments no.: 1,
bucket size: 1680 - 1680 (first 1680)
0(29441) hash = 257 fragments no.: 4,
bucket size: 2048 - 4096 (first 3080)
0(29441) hash = 258 fragments no.: 2,
bucket size: 4096 - 8192 (first 4096)
0(29441) hash = 266 fragments no.: 1,
bucket size: 1048576 - 2097152 (first 1572864)
0(29441) hash = 270 fragments no.: 1,
bucket size: 16777216 - 33554432 (first 31952928)
0(29441) TOTAL: 27 free fragments = 33553072 free bytes
0(29441) -----------------------------
0(29441) shm_mem_destroy
0(29441) destroying the shared memory lock
0(29441) Thank you for flying ser
#
script done on Tue 30 Mar 2004 05:11:06 PM CST
_______________________________________________
Serusers mailing list
serusers(a)lists.iptel.org
http://lists.iptel.org/mailman/listinfo/serusers
8 Apr
8 Apr
12:25 a.m.
New subject: [Serusers] Not Recognizing ACK
OK, in that case you probably found a bug. Could you, please, send me
the ethereal dump and full ser logs in a private email ?
Jan.
On 06-04 17:35, Mike Morrison wrote:
The ACK came .0784 seconds after the 503 was returned according to the
ethereal dump.
Mike
-----Original Message-----
From: Jan Janak [mailto:jan@iptel.org]
Sent: Tuesday, April 06, 2004 5:21 PM
To: Mike Morrison
Cc: 'serusers(a)lists.iptel.org'
Subject: Re: [Serusers] Not Recognizing ACK
Are you sure that the ACK comes no later than 2 seconds after 503 is
sent ?
Jan.
On 05-04 13:28, Mike Morrison wrote:
Running SER 0.8.12 on Solaris 8 -SPARC with MySQL
installed.
The issue that I'm running into is that when the originating GW receives a
response and generates an ACK the SER doesn't seem to stop the timer for
resending the message. If you look in the log, you can see where the
server
receives it, but the server resends the same
response as if the ACK was
ignored. It the attached case a 503 response is sent back, but the same
situation occurs when other responses are sent.
Thanks, Mike
Script started on Tue 30 Mar 2004 04:56:58 PM
CST
# /usr/local/sbin/ser
0(29441) loading module /usr/local/lib/ser/modules/mysql.so
0(29441) loading module /usr/local/lib/ser/modules/sl.so
0(29441) loading module /usr/local/lib/ser/modules/tm.so
0(29441) loading module /usr/local/lib/ser/modules/rr.so
0(29441) loading module /usr/local/lib/ser/modules/maxfwd.so
0(29441) loading module /usr/local/lib/ser/modules/usrloc.so
0(29441) loading module /usr/local/lib/ser/modules/registrar.so
0(29441) set_mod_param_regex: usrloc matches module usrloc
0(29441) set_mod_param_regex: found <db_mode> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) set_mod_param_regex: rr matches module
rr
0(29441) set_mod_param_regex: found <enable_full_lr> in module rr
[/usr/local/lib/ser/modules/rr.so]
0(29441) find_export: found
<mf_process_maxfwd_header> in module
maxfwd_module
[/usr/local/lib/ser/modules/maxfwd.so]
0(29441) find_export: found
<sl_send_reply> in module sl_module
[/usr/local/lib/ser/modules/sl.so]
0(29441) find_export: found
<sl_send_reply> in module sl_module
[/usr/local/lib/ser/modules/sl.so]
0(29441) find_export: found <record_route>
in module rr
[/usr/local/lib/ser/modules/rr.so]
0(29441) find_export: found
<sl_send_reply> in module sl_module
[/usr/local/lib/ser/modules/sl.so]
0(29441) find_export: found <t_relay> in
module tm
[/usr/local/lib/ser/modules/tm.so]
0(29441) find_export: found
<sl_reply_error> in module sl_module
[/usr/local/lib/ser/modules/sl.so]
0(29441) routing table 0:
0(29441) if ( 0(29441) NOT( 0(29441) external_module_call( 0(29441)
f_ptr<fcf20ca0> 0(29441) , "10" 0(29441) ); 0(29441)
external_module_call(
0(29441) f_ptr<fcf20ca0> 0(29441) , "10" 0(29441) ); 0(29441) )
0(29441) )
{ 0(29441) external_module_call( 0(29441) f_ptr<ff1518c0> 0(29441) ,
"483"
0(29441) , "Too Many Hops" 0(29441) ); 0(29441) drop( 0(29441) type<0>
0(29441) ); 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) UNKNOWN
0(29441) <UNKNOWN> 0(29441) 65535 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518c0> 0(29441) , "513" 0(29441)
,
"Message too big" 0(29441) ); 0(29441) drop( 0(29441) type<0> 0(29441)
);
0(29441) } else { 0(29441) }; 0(29441) external_module_call( 0(29441)
f_ptr<fcf435e0> 0(29441) ); 0(29441) if ( 0(29441) method 0(29441) ==
0(29441) "REGISTER" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED REGISTER
******************************
" 0(29441) ); 0(29441)
external_module_call( 0(29441) f_ptr<ff1518c0>
0(29441) , "200"
0(29441) , "ok" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "OPTIONS" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED OPTIONS MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "INFO" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED INFO MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport(
0(29441) "10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT(
0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) UNKNOWN
0(29441) <UNKNOWN> 0(29441) 65535 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518c0> 0(29441) , "513" 0(29441)
,
"Message too big" 0(29441) ); 0(29441) drop( 0(29441) type<0> 0(29441)
);
0(29441) } else { 0(29441) }; 0(29441) external_module_call( 0(29441)
f_ptr<fcf435e0> 0(29441) ); 0(29441) if ( 0(29441) method 0(29441) ==
0(29441) "REGISTER" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED REGISTER
******************************
" 0(29441) ); 0(29441)
external_module_call( 0(29441) f_ptr<ff1518c0>
0(29441) , "200"
0(29441) , "ok" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "OPTIONS" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED OPTIONS MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "INFO" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED INFO MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport(
0(29441) "10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT(
0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441)
external_module_call( 0(29441) f_ptr<fcf435e0> 0(29441) ); 0(29441) if (
0(29441) method 0(29441) == 0(29441) "REGISTER" 0(29441) ) { 0(29441) log(
0(29441) 1 0(29441) , "************************** RECEIVED REGISTER
******************************
" 0(29441) ); 0(29441)
external_module_call( 0(29441) f_ptr<ff1518c0>
0(29441) , "200"
0(29441) , "ok" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "OPTIONS" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED OPTIONS MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "INFO" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED INFO MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport(
0(29441) "10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT(
0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "REGISTER" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED REGISTER
******************************
" 0(29441) ); 0(29441)
external_module_call( 0(29441) f_ptr<ff1518c0>
0(29441) , "200"
0(29441) , "ok" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "OPTIONS" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED OPTIONS MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "INFO" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED INFO MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport(
0(29441) "10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT(
0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "OPTIONS" 0(29441) ) { 0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED OPTIONS MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "INFO" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED INFO MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport(
0(29441) "10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT(
0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "INFO" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"********************* RECEIVED INFO MESSAGE ****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "CANCEL" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport(
0(29441) "10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT(
0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "CANCEL" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441)
, "********************* RECEIVED CANCEL MESSAGE
****************************
" 0(29441) ); 0(29441) } else { 0(29441) };
0(29441) if ( 0(29441)
method 0(29441) == 0(29441) "ACK" 0(29441) ) {
0(29441) log( 0(29441) 1
0(29441) , "************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport(
0(29441) "10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT(
0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "ACK" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED ACK
***********************************
" 0(29441) ); 0(29441) drop( 0(29441)
type<0> 0(29441) ); 0(29441) }
else { 0(29441) }; 0(29441) if ( 0(29441)
method 0(29441) == 0(29441)
"INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441) ,
"************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport(
0(29441) "10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT(
0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441) if ( 0(29441) method
0(29441) == 0(29441) "INVITE" 0(29441) ) { 0(29441) log( 0(29441) 1 0(29441)
, "************************** RECEIVED INVITE
********************************
" 0(29441) ); 0(29441) sethostport(
0(29441) "10.31.15.253:4000" 0(29441)
); 0(29441) if ( 0(29441) NOT(
0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) external_module_call( 0(29441)
f_ptr<fcf79e00> 0(29441) ); 0(29441) ) 0(29441) ) { 0(29441)
external_module_call( 0(29441) f_ptr<ff1518e0> 0(29441) ); 0(29441) } else
{ 0(29441) }; 0(29441) } else { 0(29441) }; 0(29441)
Listening on
10.31.14.200 [10.31.14.200]:5060
Aliases: loghost:5060 caveman:5060
WARNING: no fork mode
0(29441) DEBUG: init_mod: mysql
0(29441) mysql - initializing
0(29441) DEBUG: init_mod: sl_module
stateless - initializing
0(29441) DEBUG: register_fifo_cmd: new command (sl_stats) registered
0(29441) DEBUG: MD5 calculated: 9c818f52bcc4fffa9610568f4be52539
0(29441) DEBUG: init_mod: tm
0(29441) TM - initializing...
0(29441) Call-ID initialization: '58282eed'
0(29441) DEBUG: register_fifo_cmd: new command (t_uac_dlg) registered
0(29441) DEBUG: register_fifo_cmd: new command (t_hash) registered
0(29441) DEBUG: lock_initialize: lock initialization started
0(29441) DEBUG: register_fifo_cmd: new command (t_stats) registered
0(29441) Warning: uac does not spread accross the whole hash table
0(29441) DEBUG: MD5 calculated: 6846af86154c482b36472261b1d13258
0(29441) DEBUG: MD5 calculated: 19d4d767dedba5e9d0a57f60eb631aa7
0(29441) DEBUG: init_mod: rr
0(29441) rr - initializing
0(29441) DEBUG: init_mod: maxfwd_module
Maxfwd module- initializing
0(29441) DEBUG: init_mod: usrloc
0(29441) usrloc - initializing
0(29441) DEBUG: register_fifo_cmd: new command (ul_stats) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_rm) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_rm_contact) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_dump) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_flush) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_add) registered
0(29441) DEBUG: register_fifo_cmd: new command (ul_show_contact)
registered
0(29441) find_export: found <db_use_table>
in module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_init> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_close> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_query> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_raw_query>
in module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found
<db_free_query> in module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_insert> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_delete> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
0(29441) find_export: found <db_update> in
module mysql
[/usr/local/lib/ser/modules/mysql.so]
> 0(29441) mod_init(): Database connection opened successfuly
> 0(29441) DEBUG: init_mod: registrar
> 0(29441) registrar - initializing
0(29441) find_export: found
<sl_send_reply> in module sl_module
[/usr/local/lib/ser/modules/sl.so]
0(29441) find_export: found
<ul_bind_usrloc> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_register_udomain> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_get_all_ucontacts> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_insert_urecord> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_delete_urecord> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_get_urecord> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_lock_udomain> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_unlock_udomain> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_release_urecord> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_insert_ucontact> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_delete_ucontact> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_get_ucontact> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(29441) find_export: found
<ul_update_ucontact> in module usrloc
[/usr/local/lib/ser/modules/usrloc.so]
0(0) fixing /usr/local/lib/ser/modules/maxfwd.so
mf_process_maxfwd_header
0(0) fixing /usr/local/lib/ser/modules/sl.so sl_send_reply
0(0) fixing /usr/local/lib/ser/modules/sl.so sl_send_reply
0(0) fixing /usr/local/lib/ser/modules/rr.so record_route
0(0) fixing /usr/local/lib/ser/modules/sl.so sl_send_reply
0(0) fixing /usr/local/lib/ser/modules/tm.so t_relay
0(0) fixing /usr/local/lib/ser/modules/sl.so sl_reply_error
0(0) INFO: udp_init: SO_RCVBUF is initially 8192
0(0) DEBUG: udp_init: trying SO_RCVBUF: 16384
0(0) DEBUG: setting SO_RCVBUF; set=16384,verify=16384
0(0) DEBUG: udp_init: trying SO_RCVBUF: 32768
0(0) DEBUG: setting SO_RCVBUF; set=32768,verify=32768
0(0) DEBUG: udp_init: trying SO_RCVBUF: 65536
0(0) DEBUG: setting SO_RCVBUF; set=65536,verify=65536
0(0) DEBUG: udp_init: trying SO_RCVBUF: 131072
0(0) DEBUG: setting SO_RCVBUF; set=131072,verify=131072
0(0) DEBUG: udp_init: trying SO_RCVBUF: 262144
0(0) DEBUG: setting SO_RCVBUF; set=262144,verify=262144
0(0) INFO: udp_init: SO_RCVBUF is finally 262144
1(0) DEBUG: init_mod_child (-1): tm
1(0) DEBUG: callid: '58282eed-0(a)10.31.14.200'
1(0) DEBUG: init_mod_child (-1): usrloc
1(29442) DBG: open_uac_fifo: opening fifo...
1(29442) DEBUG: open_fifo_server: FIFO stat failed: Error 0
1(29442) DEBUG: FIFO created @ /tmp/ser_fifo
1(29442) DEBUG: fifo /tmp/ser_fifo opened, mode=432
2(0) INFO: fifo process starting: 29443
2(0) DEBUG: init_mod_child (-2): tm
2(0) DEBUG: callid: '58282eed-0(a)10.31.14.200'
2(0) DEBUG: init_mod_child (-2): usrloc
2(29443) SER: open_uac_fifo: fifo server up at /tmp/ser_fifo...
0(29441) DEBUG: init_mod_child (1): tm
0(29441) DEBUG: callid: '58282eed-29441(a)10.31.14.200'
0(29441) DEBUG: init_mod_child (1): usrloc
0(29441) SIP Request:
0(29441) method: <INVITE>
0(29441) uri: <sip:5551111234@10.31.14.200;dtg=LAB_LA_TERM>
0(29441) version: <SIP/2.0>
0(29441) parse_headers: flags=1
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) preparing to run routing scripts...
0(29441) DEBUG : is_maxfwd_present: searching for max_forwards header
0(29441) parse_headers: flags=128
0(29441) end of header reached, state=9
0(29441) DEBUG: get_hdr_field: <To> [36];
uri=[sip:5551111234@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111234@10.31.14.200:5060>
]
0(29441) get_hdr_field: cseq <CSeq>: <3267> <INVITE>
0(29441) DEBUG: get_hdr_body : content_length=152
0(29441) found end of header
0(29441) DEBUG: is_maxfwd_present: max_forwards header not found!
0(29441) DEBUG: add_param: pstn-params=808182808882
0(29441) DEBUG: add_param: tag=72
0(29441) end of header reached, state=29
0(29441) ************************** RECEIVED INVITE
********************************
0(29441) DEBUG: t_addifnew: msg id=1 , global
msg id=0 , T on
entrance=ffffffff
0(29441) parse_headers: flags=-1
0(29441) parse_headers: flags=60
0(29441) t_lookup_request: start searching: hash=35190, isACK=0
0(29441) DEBUG: proceeding to pre-RFC3261 transaction matching
0(29441) DEBUG: t_lookup_request: no transaction found
0(29441) SER: new INVITE
0(29441) parse_headers: flags=-1
0(29441) check_via_address(10.31.14.253, 10.31.14.253, 0)
0(29441) WARNING:vqm_resize: resize(0) called
0(29441) DEBUG: reply sent out. buf=9c390: SIP/2.0 1..., shmem=fd184a28:
SIP/2.0
1
0(29441) DEBUG: t_reply: finished
0(29441) DEBUG: mk_proxy: doing DNS lookup...
0(29441) check_via_address(10.31.14.253, 10.31.14.253, 0)
0(29441) DEBUG: add_to_tail_of_timer[4]: fd18332c
0(29441) DEBUG: add_to_tail_of_timer[0]: fd183340
0(29441) SER: new transaction fwd'ed
0(29441) receive_msg: cleaning up
0(29441) SIP Reply (status):
0(29441) version: <SIP/2.0>
0(29441) status: <100>
0(29441) reason: <Trying>
0(29441) parse_headers: flags=1
0(29441) Found param type 232, <branch> = <z9hG4bK6798.3d17.0>; state=16
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) check_self - checking if host==us: 12==12 && [10.31.14.200] ==
[10.31.14.200]
0(29441) check_self - checking if port 5060
matches port 5060
0(29441) forward_reply: found module tm, passing reply to it
0(29441) DEBUG: t_check: msg id=2 global id=1 T start=ffffffff
0(29441) parse_headers: flags=17
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=17
0(29441) parse_headers: this is the second via
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111234@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111234@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <3267> <INVITE>
0(29441) parse_headers: flags=4
0(29441) DEBUG: t_reply_matching: hash 35190 label 29139 branch 0
0(29441) DEBUG: t_reply_matching: reply matched (T=fd183200)!
0(29441) DEBUG: t_check: msg id=2 global id=2 T end=fd183200
0(29441) DEBUG: t_on_reply: org. status uas=100, uac[0]=0 local=0
is_invite=1)
0(29441) ->>>>>>>>>
T_code=100, new_code=100
0(29441) DEBUG: relay_reply: branch=0, save=0, relay=-1
0(29441) DEBUG: add_to_tail_of_timer[1]: fd183340
0(29441) receive_msg: cleaning up
0(29441) SIP Reply (status):
0(29441) version: <SIP/2.0>
0(29441) status: <503>
0(29441) reason: <Service Unavailable>
0(29441) parse_headers: flags=1
0(29441) Found param type 232, <branch> = <z9hG4bK6798.3d17.0>; state=16
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) check_self - checking if host==us: 12==12 && [10.31.14.200] ==
[10.31.14.200]
0(29441) check_self - checking if port 5060
matches port 5060
0(29441) forward_reply: found module tm, passing reply to it
0(29441) DEBUG: t_check: msg id=3 global id=2 T start=ffffffff
0(29441) parse_headers: flags=17
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=17
0(29441) parse_headers: this is the second via
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111234@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111234@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <3267> <INVITE>
0(29441) parse_headers: flags=4
0(29441) DEBUG: t_reply_matching: hash 35190 label 29139 branch 0
0(29441) DEBUG: t_reply_matching: reply matched (T=fd183200)!
0(29441) DEBUG: t_check: msg id=3 global id=3 T end=fd183200
0(29441) DEBUG: t_on_reply: org. status uas=100, uac[0]=100 local=0
is_invite=1)
0(29441) parse_headers: flags=4
0(29441) ->>>>>>>>> T_code=100, new_code=503
0(29441) DEBUG: relay_reply: branch=0, save=0, relay=0
0(29441) old size: 385, new size: 328
0(29441) build_res_from_sip_res: copied size: orig:90, new: 33, rest: 295
msg=
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 10.31.14.253:4000
From: <sip:5127351243@10.31.14.253:4000>;pstn-params=808182808882;tag=72
To: <sip:5551111234@10.31.14.200:5060>;tag=61
Call-ID: 947552_97051161(a)10.31.14.253
CSeq: 3267 INVITE
Record-Route: <sip:5551111234@10.31.14.200;ftag=72;lr=on>
Content-Length: 0
0(29441) DEBUG: reply relayed. buf=9c5d0: SIP/2.0 5..., shmem=fd1850e0:
SIP/2.0
5
0(29441) DEBUG: cleanup_uacs: RETR/FR timers
reset
0(29441) DEBUG: add_to_tail_of_timer[4]: fd1832b4
0(29441) DEBUG: add_to_tail_of_timer[0]: fd1832c8
0(29441) receive_msg: cleaning up
0(29441) SIP Request:
0(29441) method: <ACK>
0(29441) uri: <sip:5551111234@10.31.14.200>
0(29441) version: <SIP/2.0>
0(29441) parse_headers: flags=1
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) DEBUG : sl_filter_ACK: to late to be a local ACK!
0(29441) preparing to run routing scripts...
0(29441) DEBUG : is_maxfwd_present: searching for max_forwards header
0(29441) parse_headers: flags=128
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111234@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111234@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <3267> <ACK>
0(29441) DEBUG: get_hdr_body : content_length=0
0(29441) found end of header
0(29441) DEBUG: is_maxfwd_present: max_forwards header not found!
0(29441) DEBUG: add_param: pstn-params=808182808882
0(29441) DEBUG: add_param: tag=72
0(29441) end of header reached, state=29
0(29441) ************************** RECEIVED ACK
***********************************
0(29441) receive_msg: cleaning up
1(29442) DEBUG: timer routine:1,tl=fd183340 next=0
1(29442) DEBUG: timer routine:4,tl=fd18332c next=fd1832b4
1(29442) DEBUG: timer routine:4,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[5]:
fd1832b4
1(29442) DEBUG: retransmission_handler : done
0(29441) SIP Request:
0(29441) method: <INVITE>
0(29441) uri: <sip:5551111235@10.31.14.200;dtg=LAB_LA_TERM>
0(29441) version: <SIP/2.0>
0(29441) parse_headers: flags=1
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) preparing to run routing scripts...
0(29441) DEBUG : is_maxfwd_present: searching for max_forwards header
0(29441) parse_headers: flags=128
0(29441) end of header reached, state=9
0(29441) DEBUG: get_hdr_field: <To> [36];
uri=[sip:5551111235@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111235@10.31.14.200:5060>
]
0(29441) get_hdr_field: cseq <CSeq>: <5023> <INVITE>
0(29441) DEBUG: get_hdr_body : content_length=152
0(29441) found end of header
0(29441) DEBUG: is_maxfwd_present: max_forwards header not found!
0(29441) DEBUG: add_param: pstn-params=808182808882
0(29441) DEBUG: add_param: tag=72
0(29441) end of header reached, state=29
0(29441) ************************** RECEIVED INVITE
********************************
0(29441) DEBUG: t_addifnew: msg id=5 , global
msg id=3 , T on
entrance=ffffffff
0(29441) parse_headers: flags=-1
0(29441) parse_headers: flags=60
0(29441) t_lookup_request: start searching: hash=48741, isACK=0
0(29441) DEBUG: proceeding to pre-RFC3261 transaction matching
0(29441) DEBUG: t_lookup_request: no transaction found
0(29441) SER: new INVITE
0(29441) parse_headers: flags=-1
0(29441) check_via_address(10.31.14.253, 10.31.14.253, 0)
0(29441) WARNING:vqm_resize: resize(0) called
0(29441) DEBUG: reply sent out. buf=9c728: SIP/2.0 1..., shmem=fd184a28:
SIP/2.0
1
0(29441) DEBUG: t_reply: finished
0(29441) DEBUG: mk_proxy: doing DNS lookup...
0(29441) check_via_address(10.31.14.253, 10.31.14.253, 0)
0(29441) DEBUG: add_to_tail_of_timer[4]: fd18538c
0(29441) DEBUG: add_to_tail_of_timer[0]: fd1853a0
0(29441) SER: new transaction fwd'ed
0(29441) receive_msg: cleaning up
0(29441) SIP Reply (status):
0(29441) version: <SIP/2.0>
0(29441) status: <100>
0(29441) reason: <Trying>
0(29441) parse_headers: flags=1
0(29441) Found param type 232, <branch> = <z9hG4bK56eb.77a1.0>; state=16
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) check_self - checking if host==us: 12==12 && [10.31.14.200] ==
[10.31.14.200]
0(29441) check_self - checking if port 5060
matches port 5060
0(29441) forward_reply: found module tm, passing reply to it
0(29441) DEBUG: t_check: msg id=6 global id=5 T start=ffffffff
0(29441) parse_headers: flags=17
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=17
0(29441) parse_headers: this is the second via
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111235@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111235@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <5023> <INVITE>
0(29441) parse_headers: flags=4
0(29441) DEBUG: t_reply_matching: hash 48741 label 6775 branch 0
0(29441) DEBUG: t_reply_matching: reply matched (T=fd185260)!
0(29441) DEBUG: t_check: msg id=6 global id=6 T end=fd185260
0(29441) DEBUG: t_on_reply: org. status uas=100, uac[0]=0 local=0
is_invite=1)
0(29441) ->>>>>>>>>
T_code=100, new_code=100
0(29441) DEBUG: relay_reply: branch=0, save=0, relay=-1
0(29441) DEBUG: add_to_tail_of_timer[1]: fd1853a0
0(29441) receive_msg: cleaning up
0(29441) SIP Reply (status):
0(29441) version: <SIP/2.0>
0(29441) status: <503>
0(29441) reason: <Service Unavailable>
0(29441) parse_headers: flags=1
0(29441) Found param type 232, <branch> = <z9hG4bK56eb.77a1.0>; state=16
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) check_self - checking if host==us: 12==12 && [10.31.14.200] ==
[10.31.14.200]
0(29441) check_self - checking if port 5060
matches port 5060
0(29441) forward_reply: found module tm, passing reply to it
0(29441) DEBUG: t_check: msg id=7 global id=6 T start=ffffffff
0(29441) parse_headers: flags=17
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=17
0(29441) parse_headers: this is the second via
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111235@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111235@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <5023> <INVITE>
0(29441) parse_headers: flags=4
0(29441) DEBUG: t_reply_matching: hash 48741 label 6775 branch 0
0(29441) DEBUG: t_reply_matching: reply matched (T=fd185260)!
0(29441) DEBUG: t_check: msg id=7 global id=7 T end=fd185260
0(29441) DEBUG: t_on_reply: org. status uas=100, uac[0]=100 local=0
is_invite=1)
0(29441) parse_headers: flags=4
0(29441) ->>>>>>>>> T_code=100, new_code=503
0(29441) DEBUG: relay_reply: branch=0, save=0, relay=0
0(29441) old size: 385, new size: 328
0(29441) build_res_from_sip_res: copied size: orig:90, new: 33, rest: 295
msg=
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 10.31.14.253:4000
From: <sip:5127351244@10.31.14.253:4000>;pstn-params=808182808882;tag=72
To: <sip:5551111235@10.31.14.200:5060>;tag=61
Call-ID: 947553_97051261(a)10.31.14.253
CSeq: 5023 INVITE
Record-Route: <sip:5551111235@10.31.14.200;ftag=72;lr=on>
Content-Length: 0
0(29441) DEBUG: reply relayed. buf=9c5d0: SIP/2.0 5..., shmem=fd186e60:
SIP/2.0
5
0(29441) DEBUG: cleanup_uacs: RETR/FR timers
reset
0(29441) DEBUG: add_to_tail_of_timer[4]: fd185314
0(29441) DEBUG: add_to_tail_of_timer[0]: fd185328
0(29441) receive_msg: cleaning up
0(29441) SIP Request:
0(29441) method: <ACK>
0(29441) uri: <sip:5551111235@10.31.14.200>
0(29441) version: <SIP/2.0>
0(29441) parse_headers: flags=1
0(29441) end of header reached, state=5
0(29441) parse_headers: Via found, flags=1
0(29441) parse_headers: this is the first via
0(29441) After parse_msg...
0(29441) DEBUG : sl_filter_ACK: to late to be a local ACK!
0(29441) preparing to run routing scripts...
0(29441) DEBUG : is_maxfwd_present: searching for max_forwards header
0(29441) parse_headers: flags=128
0(29441) DEBUG: add_param: tag=61
0(29441) end of header reached, state=29
0(29441) DEBUG: get_hdr_field: <To> [43];
uri=[sip:5551111235@10.31.14.200:5060]
0(29441) DEBUG: to body
[<sip:5551111235@10.31.14.200:5060>]
0(29441) get_hdr_field: cseq <CSeq>: <5023> <ACK>
0(29441) DEBUG: get_hdr_body : content_length=0
0(29441) found end of header
0(29441) DEBUG: is_maxfwd_present: max_forwards header not found!
0(29441) DEBUG: add_param: pstn-params=808182808882
0(29441) DEBUG: add_param: tag=72
0(29441) end of header reached, state=29
0(29441) ************************** RECEIVED ACK
***********************************
0(29441) receive_msg: cleaning up
1(29442) DEBUG: timer routine:1,tl=fd1853a0 next=0
1(29442) DEBUG: timer routine:4,tl=fd18538c next=fd185314
1(29442) DEBUG: timer routine:4,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[5]:
fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:5,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[6]:
fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:5,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[6]:
fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:6,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:6,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd183200,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd1850e0: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd1832b4
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: retransmission_handler : reply resending (t=fd185260,
SIP/2.0 5
... )
1(29442) DEBUG: reply retransmitted.
buf=fcf957a8: SIP/2.0 5...,
shmem=fd186e60: SIP/2.0 5
1(29442) DEBUG: add_to_tail_of_timer[7]:
fd185314
1(29442) DEBUG: retransmission_handler : done
1(29442) DEBUG: timer routine:0,tl=fd1832c8 next=0
1(29442) DEBUG: add_to_tail_of_timer[2]: fd183248
1(29442) DEBUG: timer routine:7,tl=fd1832b4 next=0
1(29442) DEBUG: timer routine:0,tl=fd185328 next=0
1(29442) DEBUG: add_to_tail_of_timer[2]: fd1852a8
1(29442) DEBUG: timer routine:7,tl=fd185314 next=0
1(29442) DEBUG: timer routine:2,tl=fd183248 next=0
1(29442) DEBUG: wait_handler : removing fd183200 from table
1(29442) DEBUG: delete transaction fd183200
1(29442) DEBUG: wait_handler : done
1(29442) DEBUG: timer routine:2,tl=fd1852a8 next=0
1(29442) DEBUG: wait_handler : removing fd185260 from table
1(29442) DEBUG: delete transaction fd185260
1(29442) DEBUG: wait_handler : done
^C 0(29441) INT received, program terminates
1( 1( 1(29442) INFO: signal 15 received
1(29442) Memory status (pkg):
1(29442) fm_status (99f88):
1(29442) heap size= 1047440
1(29442) dumping free list:
1(29442) hash = 1 fragments no.: 3,
bucket size: 8 - 8 (first 8)
1(29442) hash = 2 fragments no.: 1,
bucket size: 16 - 16 (first 16)
1(29442) hash = 4 fragments no.: 1,
bucket size: 32 - 32 (first 32)
1(29442) hash = 46 fragments no.: 1,
bucket size: 368 - 368 (first 368)
1(29442) hash = 265 fragments no.: 1,
bucket size: 524288 - 1048576 (first 1042560)
1(29442) TOTAL: 7 free fragments = 1043000 free bytes
1(29442) -----------------------------
0(29441) DEBUG: tm_shutdown : start
0(29441) DEBUG: tm_shutdown : empting DELETE list
0(29441) DEBUG: tm_shutdown : empting hash table
0(29441) DEBUG: tm_shutdown: releasing timers
0(29441) DEBUG: tm_shutdown : removing semaphores
0(29441) DEBUG: tm_shutdown : done
0(29441) Memory status (pkg):
0(29441) fm_status (99f88):
0(29441) heap size= 1047440
0(29441) dumping free list:
0(29441) hash = 1 fragments no.: 7,
bucket size: 8 - 8 (first 8)
0(29441) hash = 2 fragments no.: 31,
bucket size: 16 - 16 (first 16)
0(29441) hash = 3 fragments no.: 7,
bucket size: 24 - 24 (first 24)
0(29441) hash = 4 fragments no.: 38,
bucket size: 32 - 32 (first 32)
0(29441) hash = 5 fragments no.: 2,
bucket size: 40 - 40 (first 40)
0(29441) hash = 7 fragments no.: 1,
bucket size: 56 - 56 (first 56)
0(29441) hash = 8 fragments no.: 1,
bucket size: 64 - 64 (first 64)
0(29441) hash = 9 fragments no.: 1,
bucket size: 72 - 72 (first 72)
0(29441) hash = 15 fragments no.: 2,
bucket size: 120 - 120 (first 120)
0(29441) hash = 17 fragments no.: 1,
bucket size: 136 - 136 (first 136)
0(29441) hash = 42 fragments no.: 1,
bucket size: 336 - 336 (first 336)
0(29441) hash = 68 fragments no.: 1,
bucket size: 544 - 544 (first 544)
0(29441) hash = 71 fragments no.: 1,
bucket size: 568 - 568 (first 2( 2( 2(29443)
INFO:
signal 15 received
2(29443) Memory status (pkg):
2(29443) fm_status (99f88):
2(29443) heap size= 1047440
2(29443) dumping free list:
2(29443) hash = 1 fragments no.: 3,
bucket size: 8 - 8 (first 8)
2(29443) hash = 2 fragments no.: 1,
bucket size: 16 - 16 (first 16)
2(29443) hash = 4 fragments no.: 1,
bucket size: 32 - 32 (first 32)
2(29443) hash = 46 fragments no.: 1,
bucket size: 368 - 368 (first 368)
2(29443) hash = 265 fragments no.: 1,
bucket size: 524288 - 1048576 (first 1042560)
2(29443) TOTAL: 7 free fragments = 1043000 free bytes
2(29443) -----------------------------
568)
0(29441) hash = 93 fragments no.: 1,
bucket size: 744 - 744 (first 744)
0(29441) hash = 122 fragments no.: 1,
bucket size: 976 - 976 (first 976)
0(29441) hash = 128 fragments no.: 1,
bucket size: 1024 - 1024 (first 1024)
0(29441) hash = 265 fragments no.: 1,
bucket size: 524288 - 1048576 (first 1036808)
0(29441) TOTAL: 98 free fragments = 1043584 free bytes
0(29441) -----------------------------
0(29441) Memory status (shm):
0(29441) fm_status (fd000000):
0(29441) heap size= 33553296
0(29441) dumping free list:
0(29441) hash = 1 fragments no.: 4,
bucket size: 8 - 8 (first 8)
0(29441) hash = 2 fragments no.: 1,
bucket size: 16 - 16 (first 16)
0(29441) hash = 5 fragments no.: 3,
bucket size: 40 - 40 (first 40)
0(29441) hash = 6 fragments no.: 3,
bucket size: 48 - 48 (first 48)
0(29441) hash = 41 fragments no.: 2,
bucket size: 328 - 328 (first 328)
0(29441) hash = 48 fragments no.: 1,
bucket size: 384 - 384 (first 384)
0(29441) hash = 91 fragments no.: 1,
bucket size: 728 - 728 (first 728)
0(29441) hash = 122 fragments no.: 2,
bucket size: 976 - 976 (first 976)
0(29441) hash = 130 fragments no.: 1,
bucket size: 1040 - 1040 (first 1040)
0(29441) hash = 210 fragments no.: 1,
bucket size: 1680 - 1680 (first 1680)
0(29441) hash = 257 fragments no.: 4,
bucket size: 2048 - 4096 (first 3080)
0(29441) hash = 258 fragments no.: 2,
bucket size: 4096 - 8192 (first 4096)
0(29441) hash = 266 fragments no.: 1,
bucket size: 1048576 - 2097152 (first 1572864)
0(29441) hash = 270 fragments no.: 1,
bucket size: 16777216 - 33554432 (first 31952928)
0(29441) TOTAL: 27 free fragments = 33553072 free bytes
0(29441) -----------------------------
0(29441) shm_mem_destroy
0(29441) destroying the shared memory lock
0(29441) Thank you for flying ser
#
script done on Tue 30 Mar 2004 05:11:06 PM CST
> _______________________________________________
> Serusers mailing list
> serusers(a)lists.iptel.org
> http://lists.iptel.org/mailman/listinfo/serusers
7538
days inactive
7539
days old
1 comments
2 participants
participants (2)
-
'Jan Janak' -
Mike Morrison