[Serusers] Not Recognizing ACK
'Jan Janak'
jan at iptel.org
Wed Apr 7 23:25:42 CEST 2004
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 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