[Serusers] Not Recognizing ACK

Mike Morrison mmorrison at pointone.com
Wed Apr 7 00:35:50 CEST 2004


The ACK came .0784 seconds after the 503 was returned according to the
ethereal dump.
Mike
-----Original Message-----
From: Jan Janak [mailto:jan at iptel.org] 
Sent: Tuesday, April 06, 2004 5:21 PM
To: Mike Morrison
Cc: 'serusers at 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 at 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 at 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 at 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 at 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 at 10.31.14.200:5060] 
>  0(29441) DEBUG: to body [<sip:5551111234 at 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 at 10.31.14.200:5060] 
>  0(29441) DEBUG: to body [<sip:5551111234 at 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 at 10.31.14.200:5060] 
>  0(29441) DEBUG: to body [<sip:5551111234 at 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 at 10.31.14.253:4000>;pstn-params=808182808882;tag=72
> To: <sip:5551111234 at 10.31.14.200:5060>;tag=61
> Call-ID: 947552_97051161 at 10.31.14.253
> CSeq: 3267 INVITE
> Record-Route: <sip:5551111234 at 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 at 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 at 10.31.14.200:5060] 
>  0(29441) DEBUG: to body [<sip:5551111234 at 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 at 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 at 10.31.14.200:5060] 
>  0(29441) DEBUG: to body [<sip:5551111235 at 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 at 10.31.14.200:5060] 
>  0(29441) DEBUG: to body [<sip:5551111235 at 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 at 10.31.14.200:5060] 
>  0(29441) DEBUG: to body [<sip:5551111235 at 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 at 10.31.14.253:4000>;pstn-params=808182808882;tag=72
> To: <sip:5551111235 at 10.31.14.200:5060>;tag=61
> Call-ID: 947553_97051261 at 10.31.14.253
> CSeq: 5023 INVITE
> Record-Route: <sip:5551111235 at 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 at 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 at 10.31.14.200:5060] 
>  0(29441) DEBUG: to body [<sip:5551111235 at 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 at lists.iptel.org
> http://lists.iptel.org/mailman/listinfo/serusers




More information about the sr-users mailing list