[Serusers] Not Recognizing ACK
Jan Janak
jan at iptel.org
Wed Apr 7 00:21:15 CEST 2004
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