0(8358) loading module /usr/lib/openser/modules/sl.so 0(8358) loading module /usr/lib/openser/modules/tm.so 0(8358) loading module /usr/lib/openser/modules/rr.so 0(8358) loading module /usr/lib/openser/modules/maxfwd.so 0(8358) loading module /usr/lib/openser/modules/usrloc.so 0(8358) loading module /usr/lib/openser/modules/registrar.so 0(8358) loading module /usr/lib/openser/modules/textops.so 0(8358) loading module /usr/lib/openser/modules/nathelper.so 0(8358) set_mod_param_regex: usrloc matches module usrloc 0(8358) set_mod_param_regex: found in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(8358) set_mod_param_regex: rr matches module rr 0(8358) set_mod_param_regex: found in module rr [/usr/lib/openser/modules/rr.so] 0(8358) set_mod_param_regex: registrar matches module registrar 0(8358) set_mod_param_regex: found in module registrar [/usr/lib/openser/modules/registrar.so] 0(8358) set_mod_param_regex: nathelper matches module nathelper 0(8358) set_mod_param_regex: found in module nathelper [/usr/lib/openser/modules/nathelper.so] 0(8358) set_mod_param_regex: nathelper matches module nathelper 0(8358) set_mod_param_regex: found in module nathelper [/usr/lib/openser/modules/nathelper.so] 0(8358) find_cmd_export_t: found (1) in module maxfwd [/usr/lib/openser/modules/maxfwd.so] 0(8358) find_cmd_export_t: found (2) in module sl [/usr/lib/openser/modules/sl.so] 0(8358) find_cmd_export_t: found (2) in module sl [/usr/lib/openser/modules/sl.so] 0(8358) find_cmd_export_t: found (1) in module nathelper [/usr/lib/openser/modules/nathelper.so] 0(8358) find_cmd_export_t: found (1) in module textops [/usr/lib/openser/modules/textops.so] 0(8358) find_cmd_export_t: found (0) in module nathelper [/usr/lib/openser/modules/nathelper.so] 0(8358) find_cmd_export_t: found (1) in module nathelper [/usr/lib/openser/modules/nathelper.so] 0(8358) find_cmd_export_t: found (0) in module rr [/usr/lib/openser/modules/rr.so] 0(8358) find_cmd_export_t: found (0) in module rr [/usr/lib/openser/modules/rr.so] 0(8358) find_cmd_export_t: found (1) in module textops [/usr/lib/openser/modules/textops.so] 0(8358) find_cmd_export_t: found (1) in module textops [/usr/lib/openser/modules/textops.so] 0(8358) find_cmd_export_t: found (1) in module registrar [/usr/lib/openser/modules/registrar.so] 0(8358) find_cmd_export_t: found (1) in module registrar [/usr/lib/openser/modules/registrar.so] 0(8358) find_cmd_export_t: found (1) in module textops [/usr/lib/openser/modules/textops.so] 0(8358) find_cmd_export_t: found (1) in module registrar [/usr/lib/openser/modules/registrar.so] 0(8358) find_cmd_export_t: found (2) in module sl [/usr/lib/openser/modules/sl.so] 0(8358) find_cmd_export_t: found (1) in module textops [/usr/lib/openser/modules/textops.so] 0(8358) find_cmd_export_t: found (1) in module textops [/usr/lib/openser/modules/textops.so] 0(8358) find_cmd_export_t: found (2) in module sl [/usr/lib/openser/modules/sl.so] 0(8358) find_cmd_export_t: found (0) in module nathelper [/usr/lib/openser/modules/nathelper.so] 0(8358) find_cmd_export_t: found (1) in module tm [/usr/lib/openser/modules/tm.so] 0(8358) find_cmd_export_t: found (0) in module tm [/usr/lib/openser/modules/tm.so] 0(8358) find_cmd_export_t: found (0) in module sl [/usr/lib/openser/modules/sl.so] 0(8358) find_cmd_export_t: found (0) in module nathelper [/usr/lib/openser/modules/nathelper.so] 0(8358) find_cmd_export_t: found (0) in module nathelper [/usr/lib/openser/modules/nathelper.so] 0(8358) find_cmd_export_t: found (1) in module nathelper [/usr/lib/openser/modules/nathelper.so] 0(8358) find_cmd_export_t: found (0) in module nathelper [/usr/lib/openser/modules/nathelper.so] 0(8358) routing table 0: 0(8358) if ( 0(8358) NOT( 0(8358) external_module_call( 0(8358) f 0(8358) , "10" 0(8358) ); 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) , "483" 0(8358) , "Too Many Hops" 0(8358) ); 0(8358) return( 0(8358) 1 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) if ( 0(8358) UNKNOWN 0(8358) >= 0(8358) 65535 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) , "513" 0(8358) , "Message too big" 0(8358) ); 0(8358) return( 0(8358) 1 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) if ( 0(8358) external_module_call( 0(8358) f 0(8358) , "3" 0(8358) ); 0(8358) ) { 0(8358) if ( 0(8358) OR( 0(8358) method 0(8358) == 0(8358) "REGISTER" 0(8358) , 0(8358) NOT( 0(8358) external_module_call( 0(8358) f 0(8358) , "^Record-Route:" 0(8358) ); 0(8358) ) 0(8358) ) 0(8358) ) { 0(8358) log( 0(8358) 4 0(8358) , "LOG: Someone trying to register from private IP, rewriting " 0(8358) ); 0(8358) external_module_call( 0(8358) f 0(8358) ); 0(8358) if ( 0(8358) method 0(8358) == 0(8358) "INVITE" 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) , "1" 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) force_rport( 0(8358) type<0> 0(8358) ); 0(8358) setflag( 0(8358) 6 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) } else { 0(8358) }; 0(8358) if ( 0(8358) NOT( 0(8358) method 0(8358) == 0(8358) "REGISTER" 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) if ( 0(8358) external_module_call( 0(8358) f 0(8358) ); 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) , "P-hint: rr-enforced " 0(8358) ); 0(8358) route( 0(8358) 1 0(8358) ); 0(8358) return( 0(8358) 1 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) if ( 0(8358) NOT( 0(8358) uri 0(8358) == 0(8358) _myself_ 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) , "P-hint: outbound " 0(8358) ); 0(8358) route( 0(8358) 1 0(8358) ); 0(8358) return( 0(8358) 1 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) if ( 0(8358) uri 0(8358) == 0(8358) _myself_ 0(8358) ) { 0(8358) if ( 0(8358) method 0(8358) == 0(8358) "REGISTER" 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) , "location" 0(8358) ); 0(8358) return( 0(8358) 1 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) external_module_call( 0(8358) f 0(8358) , "aliases" 0(8358) ); 0(8358) if ( 0(8358) NOT( 0(8358) uri 0(8358) == 0(8358) _myself_ 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) , "P-hint: outbound alias " 0(8358) ); 0(8358) route( 0(8358) 1 0(8358) ); 0(8358) return( 0(8358) 1 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) if ( 0(8358) NOT( 0(8358) external_module_call( 0(8358) f 0(8358) , "location" 0(8358) ); 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) , "404" 0(8358) , "Not Found" 0(8358) ); 0(8358) return( 0(8358) 1 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) } else { 0(8358) }; 0(8358) external_module_call( 0(8358) f 0(8358) , "P-hint: usrloc applied " 0(8358) ); 0(8358) route( 0(8358) 1 0(8358) ); 0(8358) 0(8358) routing table 1: 0(8358) if ( 0(8358) AND( 0(8358) uri 0(8358) =~ 0(8358) "[@:](192\.168\.|10\.|172\.(1[6-9]|2[0-9]|3[0-1])\.)" 0(8358) , 0(8358) NOT( 0(8358) external_module_call( 0(8358) f 0(8358) , "^Route:" 0(8358) ); 0(8358) ) 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) , "479" 0(8358) , "We don't forward to private IP addresses" 0(8358) ); 0(8358) return( 0(8358) 1 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) if ( 0(8358) isflagset( 0(8358) 6 0(8358) ); 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) external_module_call( 0(8358) f 0(8358) , "1" 0(8358) ); 0(8358) if ( 0(8358) NOT( 0(8358) external_module_call( 0(8358) f 0(8358) ); 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) 0(8358) onreply routing table 1: 0(8358) if ( 0(8358) AND( 0(8358) isflagset( 0(8358) 6 0(8358) ); 0(8358) , 0(8358) uri 0(8358) =~ 0(8358) "(183)|2[0-9][0-9]" 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) ); 0(8358) external_module_call( 0(8358) f 0(8358) ); 0(8358) } else { 0(8358) if ( 0(8358) external_module_call( 0(8358) f 0(8358) , "1" 0(8358) ); 0(8358) ) { 0(8358) external_module_call( 0(8358) f 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) }; 0(8358) 0(8358) DEBUG:socket2str: 0(8358) DEBUG:socket2str: 0(8358) DEBUG:socket2str: 0(8358) DEBUG:socket2str: 0(8358) DEBUG:socket2str: 0(8358) DEBUG:socket2str: 0(8358) fm_malloc_init: F_OPTIMIZE=16384, /ROUNDTO=2048 0(8358) fm_malloc_init: F_HASH_SIZE=2067, fm_block size=16560 0(8358) fm_malloc_init(0xb5d3f000, 33554432), start=0xb5d3f000 0(8358) shm_mem_init: success 0(8358) init_tcp: using epoll_lt as the io watch method (auto detected) 0(0) core dump limits set to 4294967295 0(0) DEBUG:add_avp_galias: registering for avp id <16725044> 0(0) DEBUG: register_fifo_cmd: new command (get_statistics) registered 0(0) DEBUG: register_fifo_cmd: new command (reset_statistics) registered 0(0) INFO: statistics manager successfully initialized 0(0) DEBUG: init_mod: sl 0(0) StateLess module - initializing 0(0) DEBUG: MD5 calculated: 329cfeaa6ded039da25ff8cbb8668bd2 0(0) DEBUG: init_stats: sl 0(0) DEBUG: init_mod: tm 0(0) TM - initializing... 0(0) Call-ID initialization: '67d5ffff' 0(0) DEBUG: register_fifo_cmd: new command (t_uac_dlg) registered 0(0) DEBUG: register_fifo_cmd: new command (t_uac_cancel) registered 0(0) DEBUG: register_fifo_cmd: new command (t_hash) registered 0(0) DEBUG: register_fifo_cmd: new command (t_reply) registered 0(0) unixsock_register_cmd: New command (t_uac_dlg) registered 0(0) unixsock_register_cmd: New command (t_uac_cancel) registered 0(0) unixsock_register_cmd: New command (t_hash) registered 0(0) unixsock_register_cmd: New command (t_reply) registered 0(0) DEBUG: lock_initialize: lock initialization started 0(0) DEBUG: MD5 calculated: 533cb9e91f4b999cf76861cbb9ed54ed 0(0) DEBUG: MD5 calculated: fa997f81440371de71ab448ebdb9af56 0(0) xl_add_extra_spec: extra items list is not initialized 0(0) xl_add_extra_spec: inserting extra item [T_branch_idx] at [0] 0(0) DEBUG: init_stats: tm 0(0) DEBUG: init_mod: rr 0(0) rr - initializing 0(0) DEBUG: init_mod: maxfwd 0(0) Maxfwd module- initializing 0(0) DEBUG: init_mod: usrloc 0(0) usrloc - initializing 0(0) DEBUG: register_fifo_cmd: new command (ul_rm) registered 0(0) DEBUG: register_fifo_cmd: new command (ul_rm_contact) registered 0(0) DEBUG: register_fifo_cmd: new command (ul_dump) registered 0(0) DEBUG: register_fifo_cmd: new command (ul_flush) registered 0(0) DEBUG: register_fifo_cmd: new command (ul_add) registered 0(0) DEBUG: register_fifo_cmd: new command (ul_show_contact) registered 0(0) unixsock_register_cmd: New command (ul_rm) registered 0(0) unixsock_register_cmd: New command (ul_rm_contact) registered 0(0) unixsock_register_cmd: New command (ul_dump) registered 0(0) unixsock_register_cmd: New command (ul_flush) registered 0(0) unixsock_register_cmd: New command (ul_add) registered 0(0) unixsock_register_cmd: New command (ul_show_contact) registered 0(0) DEBUG: init_mod: registrar 0(0) registrar - initializing 0(0) find_cmd_export_t: found (2) in module sl [/usr/lib/openser/modules/sl.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) DEBUG: init_mod: textops 0(0) TextOPS - initializing 0(0) DEBUG: init_mod: nathelper 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) find_cmd_export_t: found (1) in module usrloc [/usr/lib/openser/modules/usrloc.so] 0(0) fixing mf_process_maxfwd_header, line 96 0(0) fixing sl_send_reply, line 97 0(0) fixing sl_send_reply, line 101 0(0) fixing nat_uac_test, line 111 0(0) fixing search, line 116 0(0) module - fixing ^Record-Route: 0(0) fixing fix_nated_contact, line 125 0(0) fixing fix_nated_sdp, line 127 0(0) fixing record_route, line 138 0(0) fixing loose_route, line 142 0(0) fixing append_hf, line 144 0(0) xl_parse_format: parsing [P-hint: rr-enforced ] 0(0) xl_parse_format: format parsed OK: [1] items 0(0) fixing append_hf, line 151 0(0) xl_parse_format: parsing [P-hint: outbound ] 0(0) xl_parse_format: format parsed OK: [1] items 0(0) fixing save, line 169 0(0) fixing lookup, line 173 0(0) fixing append_hf, line 175 0(0) xl_parse_format: parsing [P-hint: outbound alias ] 0(0) xl_parse_format: format parsed OK: [1] items 0(0) fixing lookup, line 181 0(0) fixing sl_send_reply, line 182 0(0) fixing append_hf, line 186 0(0) xl_parse_format: parsing [P-hint: usrloc applied ] 0(0) xl_parse_format: format parsed OK: [1] items 0(0) fixing search, line 193 0(0) module - fixing ^Route: 0(0) fixing sl_send_reply, line 194 0(0) fixing force_rtp_proxy, line 200 0(0) fixing t_on_reply, line 206 0(0) fixing t_relay, line 210 0(0) fixing sl_reply_error, line 211 0(0) fixing fix_nated_contact, line 219 0(0) fixing force_rtp_proxy, line 220 0(0) fixing nat_uac_test, line 223 0(0) fixing fix_nated_contact, line 224 0(0) INFO: udp_init: SO_RCVBUF is initially 109568 0(0) DEBUG: udp_init: trying SO_RCVBUF: 219136 0(0) DEBUG: setting SO_RCVBUF; set=219136,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 221184 0(0) DEBUG: setting SO_RCVBUF; set=221184,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 223232 0(0) DEBUG: setting SO_RCVBUF; set=223232,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 225280 0(0) DEBUG: setting SO_RCVBUF; set=225280,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 227328 0(0) DEBUG: setting SO_RCVBUF; set=227328,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 229376 0(0) DEBUG: setting SO_RCVBUF; set=229376,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 231424 0(0) DEBUG: setting SO_RCVBUF; set=231424,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 233472 0(0) DEBUG: setting SO_RCVBUF; set=233472,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 235520 0(0) DEBUG: setting SO_RCVBUF; set=235520,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 237568 0(0) DEBUG: setting SO_RCVBUF; set=237568,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 239616 0(0) DEBUG: setting SO_RCVBUF; set=239616,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 241664 0(0) DEBUG: setting SO_RCVBUF; set=241664,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 243712 0(0) DEBUG: setting SO_RCVBUF; set=243712,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 245760 0(0) DEBUG: setting SO_RCVBUF; set=245760,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 247808 0(0) DEBUG: setting SO_RCVBUF; set=247808,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 249856 0(0) DEBUG: setting SO_RCVBUF; set=249856,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 251904 0(0) DEBUG: setting SO_RCVBUF; set=251904,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 253952 0(0) DEBUG: setting SO_RCVBUF; set=253952,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 256000 0(0) DEBUG: setting SO_RCVBUF; set=256000,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 258048 0(0) DEBUG: setting SO_RCVBUF; set=258048,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 260096 0(0) DEBUG: setting SO_RCVBUF; set=260096,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 262144 0(0) DEBUG: setting SO_RCVBUF; set=262144,verify=262142 0(0) DEBUG: setting SO_RCVBUF has no effect 0(0) INFO: udp_init: SO_RCVBUF is finally 262142 0(0) INFO: udp_init: SO_RCVBUF is initially 109568 0(0) DEBUG: udp_init: trying SO_RCVBUF: 219136 0(0) DEBUG: setting SO_RCVBUF; set=219136,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 221184 0(0) DEBUG: setting SO_RCVBUF; set=221184,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 223232 0(0) DEBUG: setting SO_RCVBUF; set=223232,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 225280 0(0) DEBUG: setting SO_RCVBUF; set=225280,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 227328 0(0) DEBUG: setting SO_RCVBUF; set=227328,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 229376 0(0) DEBUG: setting SO_RCVBUF; set=229376,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 231424 0(0) DEBUG: setting SO_RCVBUF; set=231424,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 233472 0(0) DEBUG: setting SO_RCVBUF; set=233472,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 235520 0(0) DEBUG: setting SO_RCVBUF; set=235520,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 237568 0(0) DEBUG: setting SO_RCVBUF; set=237568,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 239616 0(0) DEBUG: setting SO_RCVBUF; set=239616,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 241664 0(0) DEBUG: setting SO_RCVBUF; set=241664,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 243712 0(0) DEBUG: setting SO_RCVBUF; set=243712,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 245760 0(0) DEBUG: setting SO_RCVBUF; set=245760,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 247808 0(0) DEBUG: setting SO_RCVBUF; set=247808,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 249856 0(0) DEBUG: setting SO_RCVBUF; set=249856,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 251904 0(0) DEBUG: setting SO_RCVBUF; set=251904,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 253952 0(0) DEBUG: setting SO_RCVBUF; set=253952,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 256000 0(0) DEBUG: setting SO_RCVBUF; set=256000,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 258048 0(0) DEBUG: setting SO_RCVBUF; set=258048,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 260096 0(0) DEBUG: setting SO_RCVBUF; set=260096,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 262144 0(0) DEBUG: setting SO_RCVBUF; set=262144,verify=262142 0(0) DEBUG: setting SO_RCVBUF has no effect 0(0) INFO: udp_init: SO_RCVBUF is finally 262142 0(0) INFO: udp_init: SO_RCVBUF is initially 109568 0(0) DEBUG: udp_init: trying SO_RCVBUF: 219136 0(0) DEBUG: setting SO_RCVBUF; set=219136,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 221184 0(0) DEBUG: setting SO_RCVBUF; set=221184,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 223232 0(0) DEBUG: setting SO_RCVBUF; set=223232,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 225280 0(0) DEBUG: setting SO_RCVBUF; set=225280,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 227328 0(0) DEBUG: setting SO_RCVBUF; set=227328,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 229376 0(0) DEBUG: setting SO_RCVBUF; set=229376,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 231424 0(0) DEBUG: setting SO_RCVBUF; set=231424,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 233472 0(0) DEBUG: setting SO_RCVBUF; set=233472,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 235520 0(0) DEBUG: setting SO_RCVBUF; set=235520,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 237568 0(0) DEBUG: setting SO_RCVBUF; set=237568,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 239616 0(0) DEBUG: setting SO_RCVBUF; set=239616,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 241664 0(0) DEBUG: setting SO_RCVBUF; set=241664,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 243712 0(0) DEBUG: setting SO_RCVBUF; set=243712,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 245760 0(0) DEBUG: setting SO_RCVBUF; set=245760,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 247808 0(0) DEBUG: setting SO_RCVBUF; set=247808,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 249856 0(0) DEBUG: setting SO_RCVBUF; set=249856,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 251904 0(0) DEBUG: setting SO_RCVBUF; set=251904,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 253952 0(0) DEBUG: setting SO_RCVBUF; set=253952,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 256000 0(0) DEBUG: setting SO_RCVBUF; set=256000,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 258048 0(0) DEBUG: setting SO_RCVBUF; set=258048,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 260096 0(0) DEBUG: setting SO_RCVBUF; set=260096,verify=262142 0(0) DEBUG: udp_init: trying SO_RCVBUF: 262144 0(0) DEBUG: setting SO_RCVBUF; set=262144,verify=262142 0(0) DEBUG: setting SO_RCVBUF has no effect 0(0) INFO: udp_init: SO_RCVBUF is finally 262142 0(0) DBG: open_uac_fifo: opening fifo... 0(0) DEBUG: FIFO created @ /tmp/ser_fifo 0(0) DEBUG: fifo /tmp/ser_fifo opened, mode=432 0(0) init_unixsock_socket: No unix domain socket will be opened 1(8361) INFO: fifo process starting: 8361 1(8361) DEBUG:init_mod_child: PROC_FIFO , rank=-2, module=tm 1(8361) DEBUG: callid: '67d5ffff-8361@127.0.0.1' 1(8361) DEBUG:init_mod_child: PROC_FIFO , rank=-2, module=usrloc 1(8361) DEBUG:init_mod_child: PROC_FIFO , rank=-2, module=nathelper 1(8361) rtpp_test: RTP proxy found, support for it enabled 1(8361) INFO:open_uac_fifo: fifo server up at /tmp/ser_fifo... 1(8361) DEBUG: register_fifo_cmd: new command (print) registered 1(8361) DEBUG: register_fifo_cmd: new command (uptime) registered 1(8361) DEBUG: register_fifo_cmd: new command (version) registered 1(8361) DEBUG: register_fifo_cmd: new command (pwd) registered 1(8361) DEBUG: register_fifo_cmd: new command (arg) registered 1(8361) DEBUG: register_fifo_cmd: new command (which) registered 1(8361) DEBUG: register_fifo_cmd: new command (ps) registered 1(8361) DEBUG: register_fifo_cmd: new command (kill) registered 1(8361) DEBUG: register_fifo_cmd: new command (meminfo) registered 1(8361) INFO: no fifo_db_url given - fifo DB commands disabled! 2(8362) DEBUG:init_mod_child: CHILD , rank=1, module=tm 2(8362) DEBUG: callid: '67d5ffff-8362@127.0.0.1' 2(8362) DEBUG:init_mod_child: CHILD , rank=1, module=usrloc 2(8362) DEBUG:init_mod_child: CHILD , rank=1, module=nathelper 3(8363) DEBUG:init_mod_child: CHILD , rank=2, module=tm 3(8363) DEBUG: callid: '67d5ffff-8363@127.0.0.1' 3(8363) DEBUG:init_mod_child: CHILD , rank=2, module=usrloc 3(8363) DEBUG:init_mod_child: CHILD , rank=2, module=nathelper 4(8364) DEBUG:init_mod_child: CHILD , rank=3, module=tm 4(8364) DEBUG: callid: '67d5ffff-8364@127.0.0.1' 4(8364) DEBUG:init_mod_child: CHILD , rank=3, module=usrloc 4(8364) DEBUG:init_mod_child: CHILD , rank=3, module=nathelper 5(8365) DEBUG:init_mod_child: CHILD , rank=4, module=tm 5(8365) DEBUG: callid: '67d5ffff-8365@127.0.0.1' 5(8365) DEBUG:init_mod_child: CHILD , rank=4, module=usrloc 5(8365) DEBUG:init_mod_child: CHILD , rank=4, module=nathelper 6(8366) DEBUG:init_mod_child: CHILD , rank=5, module=tm 6(8366) DEBUG: callid: '67d5ffff-8366@169.198.11.95' 6(8366) DEBUG:init_mod_child: CHILD , rank=5, module=usrloc 6(8366) DEBUG:init_mod_child: CHILD , rank=5, module=nathelper 7(8367) DEBUG:init_mod_child: CHILD , rank=6, module=tm 7(8367) DEBUG: callid: '67d5ffff-8367@169.198.11.95' 7(8367) DEBUG:init_mod_child: CHILD , rank=6, module=usrloc 7(8367) DEBUG:init_mod_child: CHILD , rank=6, module=nathelper 8(8368) DEBUG:init_mod_child: CHILD , rank=7, module=tm 8(8368) DEBUG: callid: '67d5ffff-8368@169.198.11.95' 8(8368) DEBUG:init_mod_child: CHILD , rank=7, module=usrloc 8(8368) DEBUG:init_mod_child: CHILD , rank=7, module=nathelper 9(8369) DEBUG:init_mod_child: CHILD , rank=8, module=tm 9(8369) DEBUG: callid: '67d5ffff-8369@169.198.11.95' 9(8369) DEBUG:init_mod_child: CHILD , rank=8, module=usrloc 9(8369) DEBUG:init_mod_child: CHILD , rank=8, module=nathelper 10(8370) DEBUG:init_mod_child: CHILD , rank=9, module=tm 10(8370) DEBUG: callid: '67d5ffff-8370@169.198.11.110' 10(8370) DEBUG:init_mod_child: CHILD , rank=9, module=usrloc 10(8370) DEBUG:init_mod_child: CHILD , rank=9, module=nathelper 11(8371) DEBUG:init_mod_child: CHILD , rank=10, module=tm 11(8371) DEBUG: callid: '67d5ffff-8371@169.198.11.110' 11(8371) DEBUG:init_mod_child: CHILD , rank=10, module=usrloc 11(8371) DEBUG:init_mod_child: CHILD , rank=10, module=nathelper 12(8372) DEBUG:init_mod_child: CHILD , rank=11, module=tm 12(8372) DEBUG: callid: '67d5ffff-8372@169.198.11.110' 12(8372) DEBUG:init_mod_child: CHILD , rank=11, module=usrloc 12(8372) DEBUG:init_mod_child: CHILD , rank=11, module=nathelper 13(8373) DEBUG:init_mod_child: CHILD , rank=12, module=tm 13(8373) DEBUG: callid: '67d5ffff-8373@169.198.11.110' 13(8373) DEBUG:init_mod_child: CHILD , rank=12, module=usrloc 13(8373) DEBUG:init_mod_child: CHILD , rank=12, module=nathelper 14(8374) DEBUG:init_mod_child: PROC_TIMER , rank=-1, module=tm 14(8374) DEBUG: callid: '67d5ffff-8374@127.0.0.1' 14(8374) DEBUG:init_mod_child: PROC_TIMER , rank=-1, module=usrloc 14(8374) DEBUG:init_mod_child: PROC_TIMER , rank=-1, module=nathelper 15(8375) DEBUG:init_mod_child: CHILD , rank=13, module=tm 15(8375) DEBUG: callid: '67d5ffff-8375@127.0.0.1' 15(8375) DEBUG:init_mod_child: CHILD , rank=13, module=usrloc 15(8375) DEBUG:init_mod_child: CHILD , rank=13, module=nathelper 16(8376) DEBUG:init_mod_child: CHILD , rank=14, module=tm 16(8376) DEBUG: callid: '67d5ffff-8376@127.0.0.1' 16(8376) DEBUG:init_mod_child: CHILD , rank=14, module=usrloc 16(8376) DEBUG:init_mod_child: CHILD , rank=14, module=nathelper 17(8377) DEBUG:init_mod_child: CHILD , rank=15, module=tm 17(8377) DEBUG: callid: '67d5ffff-8377@127.0.0.1' 17(8377) DEBUG:init_mod_child: CHILD , rank=15, module=usrloc 17(8377) DEBUG:init_mod_child: CHILD , rank=15, module=nathelper 18(8378) DEBUG:init_mod_child: CHILD , rank=16, module=tm 18(8378) DEBUG: callid: '67d5ffff-8378@127.0.0.1' 18(8378) DEBUG:init_mod_child: CHILD , rank=16, module=usrloc 18(8378) DEBUG:init_mod_child: CHILD , rank=16, module=nathelper 19(8379) DEBUG:init_mod_child: PROC_TCP_MAIN , rank=-4, module=tm 19(8379) DEBUG: callid: '67d5ffff-8379@127.0.0.1' 19(8379) DEBUG:init_mod_child: PROC_TCP_MAIN , rank=-4, module=usrloc 19(8379) DEBUG:init_mod_child: PROC_TCP_MAIN , rank=-4, module=nathelper 0(8360) DEBUG:init_mod_child: PROC_MAIN , rank=0, module=tm 0(8360) DEBUG: callid: '67d5ffff-8360@127.0.0.1' 0(8360) DEBUG:init_mod_child: PROC_MAIN , rank=0, module=usrloc 0(8360) DEBUG:init_mod_child: PROC_MAIN , rank=0, module=nathelper 2(8362) rtpp_test: RTP proxy found, support for it enabled 3(8363) rtpp_test: RTP proxy found, support for it enabled 4(8364) rtpp_test: RTP proxy found, support for it enabled 5(8365) rtpp_test: RTP proxy found, support for it enabled 6(8366) rtpp_test: RTP proxy found, support for it enabled 7(8367) rtpp_test: RTP proxy found, support for it enabled 8(8368) rtpp_test: RTP proxy found, support for it enabled 9(8369) rtpp_test: RTP proxy found, support for it enabled 10(8370) rtpp_test: RTP proxy found, support for it enabled 11(8371) rtpp_test: RTP proxy found, support for it enabled 12(8372) rtpp_test: RTP proxy found, support for it enabled 13(8373) rtpp_test: RTP proxy found, support for it enabled 14(8374) rtpp_test: RTP proxy found, support for it enabled 15(8375) rtpp_test: RTP proxy found, support for it enabled 15(8375) DBG: io_watch_add(0x80dfe80, 29, 1, (nil)), fd_no=0 16(8376) rtpp_test: RTP proxy found, support for it enabled 16(8376) DBG: io_watch_add(0x80dfe80, 31, 1, (nil)), fd_no=0 17(8377) rtpp_test: RTP proxy found, support for it enabled 17(8377) DBG: io_watch_add(0x80dfe80, 33, 1, (nil)), fd_no=0 18(8378) rtpp_test: RTP proxy found, support for it enabled 18(8378) DBG: io_watch_add(0x80dfe80, 35, 1, (nil)), fd_no=0 19(8379) rtpp_test: RTP proxy found, support for it enabled 19(8379) DBG: io_watch_add(0x80dfd20, 7, 1, 0x8119550), fd_no=0 19(8379) DBG: io_watch_add(0x80dfd20, 8, 1, 0x81195e0), fd_no=1 19(8379) DBG: io_watch_add(0x80dfd20, 9, 1, 0x8119670), fd_no=2 19(8379) DBG: io_watch_add(0x80dfd20, 12, 4, 0xb5d45194), fd_no=3 19(8379) DBG: io_watch_add(0x80dfd20, 13, 4, 0xb5d45220), fd_no=4 19(8379) DBG: io_watch_add(0x80dfd20, 14, 4, 0xb5d452ac), fd_no=5 19(8379) DBG: io_watch_add(0x80dfd20, 15, 4, 0xb5d45338), fd_no=6 19(8379) DBG: io_watch_add(0x80dfd20, 16, 4, 0xb5d453c4), fd_no=7 19(8379) DBG: io_watch_add(0x80dfd20, 17, 4, 0xb5d45450), fd_no=8 19(8379) DBG: io_watch_add(0x80dfd20, 18, 4, 0xb5d454dc), fd_no=9 19(8379) DBG: io_watch_add(0x80dfd20, 19, 4, 0xb5d45568), fd_no=10 19(8379) DBG: io_watch_add(0x80dfd20, 20, 4, 0xb5d455f4), fd_no=11 19(8379) DBG: io_watch_add(0x80dfd20, 21, 4, 0xb5d45680), fd_no=12 19(8379) DBG: io_watch_add(0x80dfd20, 22, 4, 0xb5d4570c), fd_no=13 19(8379) DBG: io_watch_add(0x80dfd20, 23, 4, 0xb5d45798), fd_no=14 19(8379) DBG: io_watch_add(0x80dfd20, 24, 4, 0xb5d45824), fd_no=15 19(8379) DBG: io_watch_add(0x80dfd20, 25, 4, 0xb5d458b0), fd_no=16 19(8379) DBG: io_watch_add(0x80dfd20, 26, 4, 0xb5d4593c), fd_no=17 19(8379) DBG: io_watch_add(0x80dfd20, 27, 4, 0xb5d459c8), fd_no=18 19(8379) DBG: io_watch_add(0x80dfd20, 29, 4, 0xb5d45a54), fd_no=19 19(8379) DBG: io_watch_add(0x80dfd20, 31, 4, 0xb5d45ae0), fd_no=20 19(8379) DBG: io_watch_add(0x80dfd20, 28, 3, 0x8111300), fd_no=21 19(8379) DBG: io_watch_add(0x80dfd20, 30, 3, 0x8111314), fd_no=22 19(8379) DBG: io_watch_add(0x80dfd20, 32, 3, 0x8111328), fd_no=23 19(8379) DBG: io_watch_add(0x80dfd20, 34, 3, 0x811133c), fd_no=24 0(8360) rtpp_test: RTP proxy found, support for it enabled 10(8370) SIP Request: 10(8370) method: 10(8370) uri: 10(8370) version: 10(8370) parse_headers: flags=2 10(8370) get_hdr_field: cseq : <1> 10(8370) Found param type 232, = ; state=6 10(8370) Found param type 235, = ; state=17 10(8370) end of header reached, state=5 10(8370) parse_headers: Via found, flags=2 10(8370) parse_headers: this is the first via 10(8370) After parse_msg... 10(8370) preparing to run routing scripts... 10(8370) parse_headers: flags=100 10(8370) DEBUG:parse_to:end of header reached, state=10 10(8370) DBUG:parse_to: display={}, ruri={sip:test@169.198.11.110} 10(8370) DEBUG: get_hdr_field: [27]; uri=[sip:test@169.198.11.110] 10(8370) DEBUG: to body [ ] 10(8370) DEBUG: get_hdr_body : content_length=0 10(8370) DEBUG:maxfwd:is_maxfwd_present: value = 70 10(8370) check_via_address(169.198.11.19, 169.198.11.19, 0) 10(8370) parse_headers: flags=80 10(8370) parse_headers: flags=200 10(8370) found end of header 10(8370) find_first_route: No Route headers found 10(8370) loose_route: There is no Route HF 10(8370) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) parse_headers: flags=ffffffffffffffff 10(8370) parse_headers: flags=8000000 10(8370) parse_headers: flags=ffffffffffffffff 10(8370) build_contact(): Created Contact HF: Contact: ;expires=3600 10(8370) parse_headers: flags=ffffffffffffffff 10(8370) check_via_address(169.198.11.19, 169.198.11.19, 0) 10(8370) DEBUG:destroy_avp_list: destroying list (nil) 10(8370) receive_msg: cleaning up 12(8372) SIP Request: 12(8372) method: 12(8372) uri: 12(8372) version: 12(8372) parse_headers: flags=2 12(8372) get_hdr_field: cseq : <2> 12(8372) Found param type 232, = ; state=6 12(8372) Found param type 235, = ; state=17 12(8372) end of header reached, state=5 12(8372) parse_headers: Via found, flags=2 12(8372) parse_headers: this is the first via 12(8372) After parse_msg... 12(8372) preparing to run routing scripts... 12(8372) parse_headers: flags=100 12(8372) DEBUG:parse_to:end of header reached, state=10 12(8372) DBUG:parse_to: display={}, ruri={sip:test@169.198.11.110} 12(8372) DEBUG: get_hdr_field: [27]; uri=[sip:test@169.198.11.110] 12(8372) DEBUG: to body [ ] 12(8372) DEBUG: get_hdr_body : content_length=0 12(8372) DEBUG:maxfwd:is_maxfwd_present: value = 70 12(8372) check_via_address(169.198.11.19, 169.198.11.19, 0) 12(8372) parse_headers: flags=80 12(8372) DEBUG: add_param: tag=c457f6f0-32ec-db11-9653-001372710463 12(8372) DEBUG:parse_to:end of header reached, state=29 12(8372) DBUG:parse_to: display={}, ruri={sip:test@169.198.11.110} 12(8372) parse_headers: flags=200 12(8372) found end of header 12(8372) find_first_route: No Route headers found 12(8372) loose_route: There is no Route HF 12(8372) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) lookup(): 'test' Not found in usrloc 12(8372) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) rewrite_uri: Rewriting Request-URI with 'sip:test@169.198.11.19:5061;transport=udp' 12(8372) parse_headers: flags=ffffffffffffffff 12(8372) DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffff 12(8372) parse_headers: flags=ffffffffffffffff 12(8372) parse_headers: flags=78 12(8372) t_lookup_request: start searching: hash=25492, isACK=0 12(8372) DEBUG: RFC3261 transaction matching failed 12(8372) DEBUG: t_lookup_request: no transaction found 12(8372) DEBUG: mk_proxy: doing DNS lookup... 12(8372) check_via_address(169.198.11.19, 169.198.11.19, 0) 12(8372) DEBUG: add_to_tail_of_timer[4]: 0xb5ecaed4 12(8372) DEBUG: add_to_tail_of_timer[0]: 0xb5ecaee4 12(8372) SER: new transaction fwd'ed 12(8372) DEBUG:tm:UNREF_UNSAFE: after is 0 12(8372) DEBUG:destroy_avp_list: destroying list (nil) 12(8372) receive_msg: cleaning up 10(8370) SIP Reply (status): 10(8370) version: 10(8370) status: <405> 10(8370) reason: 10(8370) parse_headers: flags=2 10(8370) get_hdr_field: cseq : <2> 10(8370) Found param type 232, = ; state=16 10(8370) end of header reached, state=5 10(8370) parse_headers: Via found, flags=2 10(8370) parse_headers: this is the first via 10(8370) After parse_msg... 10(8370) forward_reply: found module tm, passing reply to it 10(8370) DEBUG: t_check: msg id=2 global id=0 T start=0xffffffff 10(8370) parse_headers: flags=22 10(8370) DEBUG: t_reply_matching: hash 25492 label 677466385 branch 0 10(8370) DEBUG:tm:REF_UNSAFE: after is 1 10(8370) DEBUG: t_reply_matching: reply matched (T=0xb5ecadb8)! 10(8370) DEBUG: t_check: msg id=2 global id=2 T end=0xb5ecadb8 10(8370) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 10(8370) parse_headers: flags=80 10(8370) Found param type 232, = ; state=6 10(8370) Found param type 235, = <5062>; state=16 10(8370) end of header reached, state=5 10(8370) parse_headers: Via found, flags=80 10(8370) parse_headers: this is the second via 10(8370) DEBUG:parse_to:end of header reached, state=10 10(8370) DBUG:parse_to: display={}, ruri={sip:test@169.198.11.110} 10(8370) DEBUG: get_hdr_field: [27]; uri=[sip:test@169.198.11.110] 10(8370) DEBUG: to body [ ] 10(8370) DEBUG: get_hdr_body : content_length=0 10(8370) found end of header 10(8370) DEBUG:tm:t_should_relay_response: T_code=0, new_code=405 10(8370) DEBUG:tm:t_pick_branch: picked branch 0, code 405 10(8370) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 10(8370) old size: 494, new size: 431 10(8370) build_res_from_sip_res: copied size: orig:114, new: 51, rest: 380 msg= SIP/2.0 405 Method Not Allowed CSeq: 2 SUBSCRIBE Via: SIP/2.0/UDP 169.198.11.19:5062;branch=z9hG4bK225ef6f0-32ec-db11-9653-001372710463;rport=5062 From: ;tag=c457f6f0-32ec-db11-9653-001372710463 Call-ID: 6a2af6f0-32ec-db11-9653-001372710463@maxedout To: Allow: INVITE Content-Length: 0 Record-Route: 10(8370) WARNING:vqm_resize: resize(0) called 10(8370) DEBUG: add_to_tail_of_timer[2]: 0xb5ecae00 10(8370) DEBUG:tm:relay_reply: sent buf=0x8119dc8: SIP/2.0 4..., shmem=0xb5ecc7b8: SIP/2.0 4 10(8370) DEBUG: cleanup_uac_timers: RETR/FR timers reset 10(8370) DEBUG:tm:UNREF_UNSAFE: after is 0 10(8370) DEBUG:destroy_avp_list: destroying list (nil) 10(8370) receive_msg: cleaning up 14(8374) DEBUG: timer routine:0,tl=0xb5ecaee4 next=(nil) 14(8374) DEBUG: timer routine:4,tl=0xb5ecaed4 next=(nil) 14(8374) DEBUG: timer routine:2,tl=0xb5ecae00 next=(nil) 14(8374) DEBUG: wait_handler : removing 0xb5ecadb8 from table 14(8374) DEBUG: delete transaction 0xb5ecadb8 14(8374) DEBUG: wait_handler : done 12(8372) SIP Request: 12(8372) method: 12(8372) uri: 12(8372) version: 12(8372) parse_headers: flags=2 12(8372) get_hdr_field: cseq : <1> 12(8372) Found param type 232, = ; state=6 12(8372) Found param type 235, = ; state=17 12(8372) end of header reached, state=5 12(8372) parse_headers: Via found, flags=2 12(8372) parse_headers: this is the first via 12(8372) After parse_msg... 12(8372) preparing to run routing scripts... 12(8372) parse_headers: flags=100 12(8372) DEBUG:parse_to:end of header reached, state=10 12(8372) DBUG:parse_to: display={}, ruri={sip:test_store@169.198.11.110} 12(8372) DEBUG: get_hdr_field: [33]; uri=[sip:test_store@169.198.11.110] 12(8372) DEBUG: to body [ ] 12(8372) DEBUG: get_hdr_body : content_length=0 12(8372) DEBUG:maxfwd:is_maxfwd_present: value = 70 12(8372) check_via_address(169.198.11.175, 10.20.30.25, 0) 12(8372) LOG: Someone trying to register from private IP, rewriting 12(8372) parse_headers: flags=80 12(8372) parse_headers: flags=200 12(8372) found end of header 12(8372) find_first_route: No Route headers found 12(8372) loose_route: There is no Route HF 12(8372) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) parse_headers: flags=ffffffffffffffff 12(8372) parse_headers: flags=8000000 12(8372) parse_headers: flags=ffffffffffffffff 12(8372) build_contact(): Created Contact HF: Contact: ;expires=3600 12(8372) parse_headers: flags=ffffffffffffffff 12(8372) check_via_address(169.198.11.175, 10.20.30.25, 0) 12(8372) DEBUG:destroy_avp_list: destroying list (nil) 12(8372) receive_msg: cleaning up 10(8370) SIP Request: 10(8370) method: 10(8370) uri: 10(8370) version: 10(8370) parse_headers: flags=2 10(8370) get_hdr_field: cseq : <2> 10(8370) Found param type 232, = ; state=6 10(8370) Found param type 235, = ; state=17 10(8370) end of header reached, state=5 10(8370) parse_headers: Via found, flags=2 10(8370) parse_headers: this is the first via 10(8370) After parse_msg... 10(8370) preparing to run routing scripts... 10(8370) parse_headers: flags=100 10(8370) DEBUG:parse_to:end of header reached, state=10 10(8370) DBUG:parse_to: display={}, ruri={sip:test_store@169.198.11.110} 10(8370) DEBUG: get_hdr_field: [33]; uri=[sip:test_store@169.198.11.110] 10(8370) DEBUG: to body [ ] 10(8370) DEBUG: get_hdr_body : content_length=0 10(8370) DEBUG:maxfwd:is_maxfwd_present: value = 70 10(8370) check_via_address(169.198.11.175, 10.20.30.25, 0) 10(8370) LOG: Someone trying to register from private IP, rewriting 10(8370) parse_headers: flags=80 10(8370) DEBUG: add_param: tag=96afc9ec-75ec-db11-9c5e-00187185e000 10(8370) DEBUG:parse_to:end of header reached, state=29 10(8370) DBUG:parse_to: display={}, ruri={sip:test_store@169.198.11.110} 10(8370) parse_headers: flags=200 10(8370) found end of header 10(8370) find_first_route: No Route headers found 10(8370) loose_route: There is no Route HF 10(8370) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) lookup(): 'test_store' Not found in usrloc 10(8370) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 10(8370) grep_sock_info - checking if port 5060 matches port 5060 10(8370) rewrite_uri: Rewriting Request-URI with 'sip:test_store@169.198.11.175:5061;transport=udp' 10(8370) parse_headers: flags=ffffffffffffffff 10(8370) parse_headers: flags=ffffffffffffffff 10(8370) ERROR: extract_body: message body has length zero 10(8370) ERROR: force_rtp_proxy2: can't extract body from the message 10(8370) DEBUG: t_newtran: msg id=3 , global msg id=2 , T on entrance=0xffffffff 10(8370) parse_headers: flags=ffffffffffffffff 10(8370) parse_headers: flags=78 10(8370) t_lookup_request: start searching: hash=60390, isACK=0 10(8370) DEBUG: RFC3261 transaction matching failed 10(8370) DEBUG: t_lookup_request: no transaction found 10(8370) DEBUG: mk_proxy: doing DNS lookup... 10(8370) check_via_address(169.198.11.175, 10.20.30.25, 0) 10(8370) DEBUG: add_to_tail_of_timer[4]: 0xb5ecaed4 10(8370) DEBUG: add_to_tail_of_timer[0]: 0xb5ecaee4 10(8370) SER: new transaction fwd'ed 10(8370) DEBUG:tm:UNREF_UNSAFE: after is 0 10(8370) DEBUG:destroy_avp_list: destroying list (nil) 10(8370) receive_msg: cleaning up 12(8372) SIP Reply (status): 12(8372) version: 12(8372) status: <405> 12(8372) reason: 12(8372) parse_headers: flags=2 12(8372) get_hdr_field: cseq : <2> 12(8372) Found param type 232, = ; state=16 12(8372) end of header reached, state=5 12(8372) parse_headers: Via found, flags=2 12(8372) parse_headers: this is the first via 12(8372) After parse_msg... 12(8372) forward_reply: found module tm, passing reply to it 12(8372) DEBUG: t_check: msg id=3 global id=1 T start=0xffffffff 12(8372) parse_headers: flags=22 12(8372) DEBUG: t_reply_matching: hash 60390 label 1958373093 branch 0 12(8372) DEBUG:tm:REF_UNSAFE: after is 1 12(8372) DEBUG: t_reply_matching: reply matched (T=0xb5ecadb8)! 12(8372) DEBUG: t_check: msg id=3 global id=3 T end=0xb5ecadb8 12(8372) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 12(8372) parse_headers: flags=80 12(8372) Found param type 234, = <169.198.11.175>; state=6 12(8372) Found param type 232, = ; state=6 12(8372) Found param type 235, = <5062>; state=16 12(8372) end of header reached, state=5 12(8372) parse_headers: Via found, flags=80 12(8372) parse_headers: this is the second via 12(8372) DEBUG:parse_to:end of header reached, state=10 12(8372) DBUG:parse_to: display={}, ruri={sip:test_store@169.198.11.110} 12(8372) DEBUG: get_hdr_field: [33]; uri=[sip:test_store@169.198.11.110] 12(8372) DEBUG: to body [ ] 12(8372) DEBUG: get_hdr_body : content_length=0 12(8372) found end of header 12(8372) DEBUG:tm:t_should_relay_response: T_code=0, new_code=405 12(8372) DEBUG:tm:t_pick_branch: picked branch 0, code 405 12(8372) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 12(8372) old size: 531, new size: 468 12(8372) build_res_from_sip_res: copied size: orig:114, new: 51, rest: 417 msg= SIP/2.0 405 Method Not Allowed CSeq: 2 SUBSCRIBE Via: SIP/2.0/UDP 10.20.30.25:5062;received=169.198.11.175;branch=z9hG4bKa4bac9ec-75ec-db11-9c5e-00187185e000;rport=5062 From: ;tag=96afc9ec-75ec-db11-9c5e-00187185e000 Call-ID: c841c9ec-75ec-db11-9c5e-00187185e000@10.20.30.25 To: Allow: INVITE Content-Length: 0 Record-Route: 12(8372) WARNING:vqm_resize: resize(0) called 12(8372) DEBUG: add_to_tail_of_timer[2]: 0xb5ecae00 12(8372) DEBUG:tm:relay_reply: sent buf=0x811a760: SIP/2.0 4..., shmem=0xb5ecc4a8: SIP/2.0 4 12(8372) DEBUG: cleanup_uac_timers: RETR/FR timers reset 12(8372) DEBUG:tm:UNREF_UNSAFE: after is 0 12(8372) DEBUG:destroy_avp_list: destroying list (nil) 12(8372) receive_msg: cleaning up 14(8374) DEBUG: timer routine:0,tl=0xb5ecaee4 next=(nil) 14(8374) DEBUG: timer routine:4,tl=0xb5ecaed4 next=(nil) 14(8374) DEBUG: timer routine:2,tl=0xb5ecae00 next=(nil) 14(8374) DEBUG: wait_handler : removing 0xb5ecadb8 from table 14(8374) DEBUG: delete transaction 0xb5ecadb8 14(8374) DEBUG: wait_handler : done 11(8371) SIP Request: 11(8371) method: 11(8371) uri: 11(8371) version: 11(8371) parse_headers: flags=2 11(8371) get_hdr_field: cseq : <1> 11(8371) Found param type 232, = ; state=6 11(8371) Found param type 235, = ; state=17 11(8371) end of header reached, state=5 11(8371) parse_headers: Via found, flags=2 11(8371) parse_headers: this is the first via 11(8371) After parse_msg... 11(8371) preparing to run routing scripts... 11(8371) parse_headers: flags=100 11(8371) DEBUG:parse_to:end of header reached, state=10 11(8371) DBUG:parse_to: display={}, ruri={sip:test@169.198.11.110} 11(8371) DEBUG: get_hdr_field: [27]; uri=[sip:test@169.198.11.110] 11(8371) DEBUG: to body [ ] 11(8371) DEBUG: get_hdr_body : content_length=227 11(8371) DEBUG:maxfwd:is_maxfwd_present: value = 70 11(8371) check_via_address(169.198.11.175, 10.20.30.25, 0) 11(8371) LOG: Someone trying to register from private IP, rewriting 11(8371) parse_headers: flags=80 11(8371) parse_headers: flags=ffffffffffffffff 11(8371) found end of header 11(8371) DEBUG:check_content_type: type found valid 11(8371) DEBUG: add_param: tag=fcbe2ff8-75ec-db11-9c5e-00187185e000 11(8371) DEBUG:parse_to:end of header reached, state=29 11(8371) DBUG:parse_to: display={"Test Store"}, ruri={sip:test_store@169.198.11.110} 11(8371) parse_headers: flags=200 11(8371) find_first_route: No Route headers found 11(8371) loose_route: There is no Route HF 11(8371) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 11(8371) grep_sock_info - checking if port 5060 matches port 5060 11(8371) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 11(8371) grep_sock_info - checking if port 5060 matches port 5060 11(8371) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 11(8371) grep_sock_info - checking if port 5060 matches port 5060 11(8371) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 11(8371) grep_sock_info - checking if port 5060 matches port 5060 11(8371) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 11(8371) grep_sock_info - checking if port 5060 matches port 5060 11(8371) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 11(8371) grep_sock_info - checking if port 5060 matches port 5060 11(8371) lookup(): 'test' Not found in usrloc 11(8371) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 11(8371) grep_sock_info - checking if port 5060 matches port 5060 11(8371) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 11(8371) grep_sock_info - checking if port 5060 matches port 5060 11(8371) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 11(8371) grep_sock_info - checking if port 5060 matches port 5060 11(8371) rewrite_uri: Rewriting Request-URI with 'sip:test@169.198.11.19:5061;transport=udp' 11(8371) parse_headers: flags=ffffffffffffffff 11(8371) parse_headers: flags=ffffffffffffffff 11(8371) DEBUG:check_content_type: type found valid 11(8371) parse_headers: flags=40 11(8371) force_rtp_proxy2: proxy reply: 35000 169.198.11.110 11(8371) force_rtp_proxy2: proxy reply: 35002 169.198.11.110 11(8371) DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffff 11(8371) parse_headers: flags=ffffffffffffffff 11(8371) parse_headers: flags=78 11(8371) t_lookup_request: start searching: hash=64503, isACK=0 11(8371) DEBUG: RFC3261 transaction matching failed 11(8371) DEBUG: t_lookup_request: no transaction found 11(8371) DEBUG:tm:t_relay: new INVITE 11(8371) parse_headers: flags=ffffffffffffffff 11(8371) check_via_address(169.198.11.175, 10.20.30.25, 0) 11(8371) WARNING:vqm_resize: resize(0) called 11(8371) DEBUG:tm:_reply_light: reply sent out. buf=0x811a7b8: SIP/2.0 1..., shmem=0xb5ecb8d0: SIP/2.0 1 11(8371) DEBUG:tm:_reply_light: finished 11(8371) DEBUG: mk_proxy: doing DNS lookup... 11(8371) parse_headers: flags=2000 11(8371) parse_headers: flags=ffffffffffffffff 11(8371) clen_builder: content-length: 270 (270) 11(8371) check_via_address(169.198.11.175, 10.20.30.25, 0) 11(8371) DEBUG: add_to_tail_of_timer[4]: 0xb5ecaed4 11(8371) DEBUG: add_to_tail_of_timer[0]: 0xb5ecaee4 11(8371) SER: new transaction fwd'ed 11(8371) DEBUG:tm:UNREF_UNSAFE: after is 0 11(8371) DEBUG:destroy_avp_list: destroying list (nil) 11(8371) receive_msg: cleaning up 10(8370) SIP Reply (status): 10(8370) version: 10(8370) status: <100> 10(8370) reason: 10(8370) parse_headers: flags=2 10(8370) get_hdr_field: cseq : <1> 10(8370) Found param type 232, = ; state=16 10(8370) end of header reached, state=5 10(8370) parse_headers: Via found, flags=2 10(8370) parse_headers: this is the first via 10(8370) After parse_msg... 10(8370) forward_reply: found module tm, passing reply to it 10(8370) DEBUG: t_check: msg id=4 global id=3 T start=0xffffffff 10(8370) parse_headers: flags=22 10(8370) parse_headers: flags=8 10(8370) Found param type 234, = <169.198.11.175>; state=6 10(8370) Found param type 232, = ; state=6 10(8370) Found param type 235, = <5063>; state=16 10(8370) end of header reached, state=5 10(8370) parse_headers: Via found, flags=8 10(8370) parse_headers: this is the second via 10(8370) DEBUG:parse_to:end of header reached, state=10 10(8370) DBUG:parse_to: display={}, ruri={sip:test@169.198.11.110} 10(8370) DEBUG: get_hdr_field: [27]; uri=[sip:test@169.198.11.110] 10(8370) DEBUG: to body [ ] 10(8370) DEBUG: t_reply_matching: hash 64503 label 1225634185 branch 0 10(8370) DEBUG:tm:REF_UNSAFE: after is 1 10(8370) DEBUG: t_reply_matching: reply matched (T=0xb5ecadb8)! 10(8370) DEBUG: t_check: msg id=4 global id=4 T end=0xb5ecadb8 10(8370) DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) 10(8370) parse_headers: flags=80 10(8370) DEBUG: get_hdr_body : content_length=0 10(8370) found end of header 10(8370) DEBUG:tm:t_should_relay_response: T_code=100, new_code=100 10(8370) DEBUG:tm:relay_reply: branch=0, save=0, relay=-1 10(8370) DEBUG: add_to_tail_of_timer[1]: 0xb5ecaee4 10(8370) DEBUG:tm:UNREF_UNSAFE: after is 0 10(8370) DEBUG:destroy_avp_list: destroying list (nil) 10(8370) receive_msg: cleaning up 12(8372) SIP Reply (status): 12(8372) version: 12(8372) status: <100> 12(8372) reason: 12(8372) parse_headers: flags=2 12(8372) get_hdr_field: cseq : <1> 12(8372) Found param type 232, = ; state=16 12(8372) end of header reached, state=5 12(8372) parse_headers: Via found, flags=2 12(8372) parse_headers: this is the first via 12(8372) After parse_msg... 12(8372) forward_reply: found module tm, passing reply to it 12(8372) DEBUG: t_check: msg id=4 global id=3 T start=0xffffffff 12(8372) parse_headers: flags=22 12(8372) parse_headers: flags=8 12(8372) Found param type 234, = <169.198.11.175>; state=6 12(8372) Found param type 232, = ; state=6 12(8372) Found param type 235, = <5063>; state=16 12(8372) end of header reached, state=5 12(8372) parse_headers: Via found, flags=8 12(8372) parse_headers: this is the second via 12(8372) DEBUG: add_param: tag=8ed11bfa-33ec-db11-9653-001372710463 12(8372) DEBUG:parse_to:end of header reached, state=29 12(8372) DBUG:parse_to: display={}, ruri={sip:test@169.198.11.110} 12(8372) DEBUG: get_hdr_field: [68]; uri=[sip:test@169.198.11.110] 12(8372) DEBUG: to body [] 12(8372) DEBUG: t_reply_matching: hash 64503 label 1225634185 branch 0 12(8372) DEBUG:tm:REF_UNSAFE: after is 1 12(8372) DEBUG: t_reply_matching: reply matched (T=0xb5ecadb8)! 12(8372) DEBUG: t_check: msg id=4 global id=4 T end=0xb5ecadb8 12(8372) DEBUG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) 12(8372) parse_headers: flags=80 12(8372) DEBUG: get_hdr_body : content_length=0 12(8372) found end of header 12(8372) DEBUG:tm:t_should_relay_response: T_code=100, new_code=100 12(8372) DEBUG:tm:relay_reply: branch=0, save=0, relay=-1 12(8372) DEBUG: add_to_tail_of_timer[1]: 0xb5ecaee4 12(8372) DEBUG:tm:UNREF_UNSAFE: after is 0 12(8372) DEBUG:destroy_avp_list: destroying list (nil) 12(8372) receive_msg: cleaning up 11(8371) SIP Reply (status): 11(8371) version: 11(8371) status: <502> 11(8371) reason: 11(8371) parse_headers: flags=2 11(8371) get_hdr_field: cseq : <1> 11(8371) Found param type 232, = ; state=16 11(8371) end of header reached, state=5 11(8371) parse_headers: Via found, flags=2 11(8371) parse_headers: this is the first via 11(8371) After parse_msg... 11(8371) forward_reply: found module tm, passing reply to it 11(8371) DEBUG: t_check: msg id=2 global id=1 T start=0xffffffff 11(8371) parse_headers: flags=22 11(8371) parse_headers: flags=8 11(8371) Found param type 234, = <169.198.11.175>; state=6 11(8371) Found param type 232, = ; state=6 11(8371) Found param type 235, = <5063>; state=16 11(8371) end of header reached, state=5 11(8371) parse_headers: Via found, flags=8 11(8371) parse_headers: this is the second via 11(8371) DEBUG: add_param: tag=8ed11bfa-33ec-db11-9653-001372710463 11(8371) DEBUG:parse_to:end of header reached, state=29 11(8371) DBUG:parse_to: display={}, ruri={sip:test@169.198.11.110} 11(8371) DEBUG: get_hdr_field: [68]; uri=[sip:test@169.198.11.110] 11(8371) DEBUG: to body [] 11(8371) DEBUG: t_reply_matching: hash 64503 label 1225634185 branch 0 11(8371) DEBUG:tm:REF_UNSAFE: after is 1 11(8371) DEBUG: t_reply_matching: reply matched (T=0xb5ecadb8)! 11(8371) DEBUG: t_check: msg id=2 global id=2 T end=0xb5ecadb8 11(8371) DEBUG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) 11(8371) parse_headers: flags=8 11(8371) DEBUG:tm:build_local: using FROM=;tag=fcbe2ff8-75ec-db11-9c5e-00187185e000 >, TO=;tag=8ed11bfa-33ec-db11-9653-001372710463 >, CSEQ_N= 11(8371) parse_headers: flags=80 11(8371) DEBUG: get_hdr_body : content_length=0 11(8371) found end of header 11(8371) DEBUG:tm:t_should_relay_response: T_code=100, new_code=502 11(8371) DEBUG:tm:t_pick_branch: picked branch 0, code 502 11(8371) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 11(8371) old size: 613, new size: 550 11(8371) build_res_from_sip_res: copied size: orig:104, new: 41, rest: 509 msg= SIP/2.0 502 Bad Gateway CSeq: 1 INVITE Via: SIP/2.0/UDP 10.20.30.25:5063;received=169.198.11.175;branch=z9hG4bKd42631f8-75ec-db11-9c5e-00187185e000;rport=5063 From: "Test Store" ;tag=fcbe2ff8-75ec-db11-9c5e-00187185e000 Call-ID: 14b12ff8-75ec-db11-9c5e-00187185e000@10.20.30.25 To: ;tag=8ed11bfa-33ec-db11-9653-001372710463 Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Content-Length: 0 Record-Route: 11(8371) DEBUG: add_to_tail_of_timer[4]: 0xb5ecae68 11(8371) DEBUG: add_to_tail_of_timer[0]: 0xb5ecae78 11(8371) DEBUG:tm:relay_reply: sent buf=0x811aac8: SIP/2.0 5..., shmem=0xb5ecc4a8: SIP/2.0 5 11(8371) DEBUG: cleanup_uac_timers: RETR/FR timers reset 11(8371) DEBUG:tm:UNREF_UNSAFE: after is 0 11(8371) DEBUG:destroy_avp_list: destroying list (nil) 11(8371) receive_msg: cleaning up 12(8372) SIP Request: 12(8372) method: 12(8372) uri: 12(8372) version: 12(8372) parse_headers: flags=2 12(8372) get_hdr_field: cseq : <1> 12(8372) Found param type 232, = ; state=6 12(8372) Found param type 235, = ; state=17 12(8372) end of header reached, state=5 12(8372) parse_headers: Via found, flags=2 12(8372) parse_headers: this is the first via 12(8372) After parse_msg... 12(8372) preparing to run routing scripts... 12(8372) DEBUG : sl_filter_ACK: to late to be a local ACK! 12(8372) parse_headers: flags=100 12(8372) DEBUG: add_param: tag=8ed11bfa-33ec-db11-9653-001372710463 12(8372) DEBUG:parse_to:end of header reached, state=29 12(8372) DBUG:parse_to: display={}, ruri={sip:test@169.198.11.110} 12(8372) DEBUG: get_hdr_field: [68]; uri=[sip:test@169.198.11.110] 12(8372) DEBUG: to body [] 12(8372) DEBUG: get_hdr_body : content_length=0 12(8372) DEBUG:maxfwd:is_maxfwd_present: value = 70 12(8372) check_via_address(169.198.11.175, 10.20.30.25, 0) 12(8372) LOG: Someone trying to register from private IP, rewriting 12(8372) parse_headers: flags=80 12(8372) found end of header 12(8372) DEBUG: add_param: tag=fcbe2ff8-75ec-db11-9c5e-00187185e000 12(8372) DEBUG:parse_to:end of header reached, state=29 12(8372) DBUG:parse_to: display={"Test Store"}, ruri={sip:test_store@169.198.11.110} 12(8372) parse_headers: flags=200 12(8372) find_first_route: No Route headers found 12(8372) loose_route: There is no Route HF 12(8372) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) lookup(): 'test' Not found in usrloc 12(8372) grep_sock_info - checking if host==us: 14==9 && [169.198.11.110] == [127.0.0.1] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==13 && [169.198.11.110] == [169.198.11.95] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) grep_sock_info - checking if host==us: 14==14 && [169.198.11.110] == [169.198.11.110] 12(8372) grep_sock_info - checking if port 5060 matches port 5060 12(8372) rewrite_uri: Rewriting Request-URI with 'sip:test@169.198.11.19:5061;transport=udp' 12(8372) parse_headers: flags=ffffffffffffffff 12(8372) parse_headers: flags=ffffffffffffffff 12(8372) ERROR: extract_body: message body has length zero 12(8372) ERROR: force_rtp_proxy2: can't extract body from the message 12(8372) DEBUG: t_newtran: msg id=5 , global msg id=4 , T on entrance=0xffffffff 12(8372) parse_headers: flags=ffffffffffffffff 12(8372) parse_headers: flags=78 12(8372) t_lookup_request: start searching: hash=64503, isACK=1 12(8372) DEBUG: RFC3261 transaction matched, tid=d42631f8-75ec-db11-9c5e-00187185e000 12(8372) DEBUG:tm:REF_UNSAFE: after is 1 12(8372) DEBUG: t_lookup_request: transaction found (T=0xb5ecadb8) 12(8372) DEBUG: cleanup_uac_timers: RETR/FR timers reset 12(8372) DEBUG: add_to_tail_of_timer[2]: 0xb5ecae00 12(8372) DEBUG:tm:UNREF_UNSAFE: after is 0 12(8372) DEBUG:destroy_avp_list: destroying list (nil) 12(8372) receive_msg: cleaning up 14(8374) DEBUG: timer routine:0,tl=0xb5ecae78 next=(nil) 14(8374) DEBUG: timer routine:1,tl=0xb5ecaee4 next=(nil) 14(8374) DEBUG: timer routine:4,tl=0xb5ecae68 next=0xb5ecaed4 14(8374) DEBUG: timer routine:4,tl=0xb5ecaed4 next=(nil) 11(8371) SIP Reply (status): 11(8371) version: 11(8371) status: <200> 11(8371) reason: 11(8371) parse_headers: flags=2 11(8371) get_hdr_field: cseq : <1> 11(8371) Found param type 232, = ; state=16 11(8371) end of header reached, state=5 11(8371) parse_headers: Via found, flags=2 11(8371) parse_headers: this is the first via 11(8371) After parse_msg... 11(8371) forward_reply: found module tm, passing reply to it 11(8371) DEBUG: t_check: msg id=3 global id=2 T start=0xffffffff 11(8371) parse_headers: flags=22 11(8371) parse_headers: flags=8 11(8371) Found param type 234, = <169.198.11.175>; state=6 11(8371) Found param type 232, = ; state=6 11(8371) Found param type 235, = <5063>; state=16 11(8371) end of header reached, state=5 11(8371) parse_headers: Via found, flags=8 11(8371) parse_headers: this is the second via 11(8371) DEBUG: add_param: tag=8ed11bfa-33ec-db11-9653-001372710463 11(8371) DEBUG:parse_to:end of header reached, state=29 11(8371) DBUG:parse_to: display={}, ruri={sip:test@169.198.11.110} 11(8371) DEBUG: get_hdr_field: [68]; uri=[sip:test@169.198.11.110] 11(8371) DEBUG: to body [] 11(8371) DEBUG: t_reply_matching: hash 64503 label 1225634185 branch 0 11(8371) DEBUG:tm:REF_UNSAFE: after is 1 11(8371) DEBUG: t_reply_matching: reply matched (T=0xb5ecadb8)! 11(8371) DEBUG: t_check: msg id=3 global id=3 T end=0xb5ecadb8 11(8371) DEBUG:tm:reply_received: org. status uas=502, uac[0]=502 local=0 is_invite=1) 11(8371) parse_headers: flags=80 11(8371) parse_headers: flags=ffffffffffffffff 11(8371) DEBUG: get_hdr_body : content_length=153 11(8371) found end of header 11(8371) DEBUG:check_content_type: type found valid 11(8371) parse_headers: flags=40 11(8371) DEBUG: add_param: tag=fcbe2ff8-75ec-db11-9c5e-00187185e000 11(8371) DEBUG:parse_to:end of header reached, state=29 11(8371) DBUG:parse_to: display={"Test Store"}, ruri={sip:test_store@169.198.11.110} 11(8371) force_rtp_proxy2: proxy reply: 35004 169.198.11.110 11(8371) DEBUG:tm:t_should_relay_response: T_code=502, new_code=200 11(8371) DEBUG:tm:t_should_relay_response: 200 OK for INVITE after final sent 11(8371) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 11(8371) parse_headers: flags=2000 11(8371) parse_headers: flags=ffffffffffffffff 11(8371) clen_builder: content-length: 173 (173) 11(8371) old size: 844, new size: 801 11(8371) build_res_from_sip_res: copied size: orig:844, new: 801, rest: 0 msg= SIP/2.0 200 OK CSeq: 1 INVITE Via: SIP/2.0/UDP 10.20.30.25:5063;received=169.198.11.175;branch=z9hG4bKd42631f8-75ec-db11-9c5e-00187185e000;rport=5063 From: "Test Store" ;tag=fcbe2ff8-75ec-db11-9c5e-00187185e000 Call-ID: 14b12ff8-75ec-db11-9c5e-00187185e000@10.20.30.25 To: ;tag=8ed11bfa-33ec-db11-9653-001372710463 Contact: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Content-Type: application/sdp Content-Length: 173 Record-Route: v=0 o=- 1176912192 1176912192 IN IP4 169.198.11.19 s=Opal SIP Session c=IN IP4 169.198.11.110 t=0 0 m=video 35004 RTP/AVP 31 a=rtpmap:31 H261/90000 a=nortpproxy:yes 11(8371) DEBUG:tm:relay_reply: sent buf=0x811aac8: SIP/2.0 2..., shmem=0xb5ecb8d0: SIP/2.0 2 11(8371) DEBUG:tm:UNREF_UNSAFE: after is 0 11(8371) DEBUG:destroy_avp_list: destroying list (nil) 11(8371) receive_msg: cleaning up 14(8374) DEBUG: timer routine:2,tl=0xb5ecae00 next=(nil) 14(8374) DEBUG: wait_handler : removing 0xb5ecadb8 from table 14(8374) DEBUG: delete transaction 0xb5ecadb8 14(8374) DEBUG: wait_handler : done 10(8370) INFO: signal 15 received 10(8370) Memory status (pkg): 10(8370) fm_status (0x8111b00): 10(8370) heap size= 1048576 10(8370) used= 13648, used+overhead=32768, free=1015808 10(8370) max used (+overhead)= 38536 10(8370) dumping free list: 10(8370) hash = 1 fragments no.: 5, unused: 0 bucket size: 8 - 8 (first 8) 10(8370) hash = 2 fragments no.: 5, unused: 0 bucket size: 16 - 16 (first 16) 10(8370) hash = 3 fragments no.: 5, unused: 0 bucket size: 24 - 24 (first 24) 10(8370) hash = 4 fragments no.: 28, unused: 0 bucket size: 32 - 32 (first 32) 10(8370) hash = 5 fragments no.: 8, unused: 0 bucket size: 40 - 40 (first 40) 10(8370) hash = 6 fragments no.: 8, unused: 0 bucket size: 48 - 48 (first 48) 10(8370) hash = 7 fragments no.: 2, unused: 0 bucket size: 56 - 56 (first 56) 10(8370) hash = 8 fragments no.: 3, unused: 0 bucket size: 64 - 64 (first 64) 10(8370) hash = 9 fragments no.: 2, unused: 0 bucket size: 72 - 72 (first 72) 10(8370) hash = 10 fragments no.: 2, unused: 0 bucket size: 80 - 80 (first 80) 10(8370) hash = 15 fragments no.: 2, unused: 0 bucket size: 120 - 120 (first 120) 10(8370) hash = 87 fragments no.: 1, unused: 0 bucket size: 696 - 696 (first 696) 10(8370) hash = 99 fragments no.: 1, unused: 0 bucket size: 792 - 792 (first 792) 10(8370) hash = 447 fragments no.: 1, unused: 0 bucket size: 3576 - 3576 (first 3576) 10(8370) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 10(8370) TOTAL: 74 free fragments = 1015808 free bytes 10(8370) ----------------------------- 19(8379) ERROR: receive_fd: EOF on 21 19(8379) DBG: handle_ser_child: dead child 10, pid 8370 (shutting down?) 19(8379) DBG: io_watch_del (0x80dfd20, 21, -1, 0x0) fd_no=25 called 12(8372) INFO: signal 15 received 12(8372) Memory status (pkg): 12(8372) fm_status (0x8111b00): 12(8372) heap size= 1048576 12(8372) used= 13616, used+overhead=32696, free=1015880 12(8372) max used (+overhead)= 38536 12(8372) dumping free list: 12(8372) hash = 1 fragments no.: 8, unused: 0 bucket size: 8 - 8 (first 8) 12(8372) hash = 2 fragments no.: 2, unused: 0 bucket size: 16 - 16 (first 16) 12(8372) hash = 3 fragments no.: 5, unused: 0 bucket size: 24 - 24 (first 24) 12(8372) hash = 4 fragments no.: 24, unused: 0 bucket size: 32 - 32 (first 32) 12(8372) hash = 5 fragments no.: 8, unused: 0 bucket size: 40 - 40 (first 40) 12(8372) hash = 6 fragments no.: 7, unused: 0 bucket size: 48 - 48 (first 48) 12(8372) hash = 7 fragments no.: 1, unused: 0 bucket size: 56 - 56 (first 56) 12(8372) hash = 8 fragments no.: 1, unused: 0 bucket size: 64 - 64 (first 64) 12(8372) hash = 9 fragments no.: 2, unused: 0 bucket size: 72 - 72 (first 72) 12(8372) hash = 10 fragments no.: 4, unused: 0 bucket size: 80 - 80 (first 80) 12(8372) hash = 15 fragments no.: 1, unused: 0 bucket size: 120 - 120 (first 120) 12(8372) hash = 16 fragments no.: 1, unused: 0 bucket size: 128 - 128 (first 128) 12(8372) hash = 68 fragments no.: 1, unused: 0 bucket size: 544 - 544 (first 544) 12(8372) hash = 87 fragments no.: 1, unused: 0 bucket size: 696 - 696 (first 696) 12(8372) hash = 99 fragments no.: 1, unused: 0 bucket size: 792 - 792 (first 792) 12(8372) hash = 415 fragments no.: 1, unused: 0 bucket size: 3320 - 3320 (first 3320) 12(8372) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 12(8372) TOTAL: 69 free fragments = 1015880 free bytes 12(8372) ----------------------------- 19(8379) ERROR: receive_fd: EOF on 23 19(8379) DBG: handle_ser_child: dead child 12, pid 8372 (shutting down?) 19(8379) DBG: io_watch_del (0x80dfd20, 23, -1, 0x0) fd_no=24 called 14(8374) INFO: signal 15 received 14(8374) Memory status (pkg): 14(8374) fm_status (0x8111b00): 14(8374) heap size= 1048576 14(8374) used= 13488, used+overhead=32112, free=1016464 14(8374) max used (+overhead)= 38536 14(8374) dumping free list: 14(8374) hash = 1 fragments no.: 1, unused: 0 bucket size: 8 - 8 (first 8) 14(8374) hash = 9 fragments no.: 1, unused: 0 bucket size: 72 - 72 (first 72) 14(8374) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 14(8374) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 14(8374) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 14(8374) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 14(8374) TOTAL: 14 free fragments = 1016464 free bytes 14(8374) ----------------------------- 19(8379) ERROR: receive_fd: EOF on 25 19(8379) DBG: handle_ser_child: dead child 14, pid 8374 (shutting down?) 19(8379) DBG: io_watch_del (0x80dfd20, 25, -1, 0x0) fd_no=23 called 19(8379) INFO: signal 15 received 19(8379) Memory status (pkg): 19(8379) fm_status (0x8111b00): 19(8379) heap size= 1048576 19(8379) used= 63728, used+overhead=82360, free=966216 19(8379) max used (+overhead)= 82360 19(8379) dumping free list: 19(8379) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) 19(8379) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 19(8379) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 19(8379) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 19(8379) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 957800) 19(8379) TOTAL: 13 free fragments = 966216 free bytes 19(8379) ----------------------------- 0(8360) child process 8370 exited normally, status=0 0(8360) child process 8372 exited normally, status=0 0(8360) child process 8374 exited normally, status=0 0(8360) child process 8379 exited normally, status=0 0(8360) INFO: terminating due to SIGCHLD 1(8361) INFO: signal 15 received 1(8361) Memory status (pkg): 1(8361) fm_status (0x8111b00): 1(8361) heap size= 1048576 1(8361) used= 13648, used+overhead=32320, free=1016256 1(8361) max used (+overhead)= 38536 1(8361) dumping free list: 1(8361) hash = 16 fragments no.: 8, unused: 0 bucket size: 128 - 128 (first 128) 1(8361) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 1(8361) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 1(8361) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 1(8361) TOTAL: 11 free fragments = 1016256 free bytes 1(8361) ----------------------------- 2(8362) INFO: signal 15 received 2(8362) Memory status (pkg): 2(8362) fm_status (0x8111b00): 2(8362) heap size= 1048576 2(8362) used= 13520, used+overhead=32144, free=1016432 2(8362) max used (+overhead)= 38536 2(8362) dumping free list: 2(8362) hash = 6 fragments no.: 1, unused: 0 bucket size: 48 - 48 (first 48) 2(8362) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 2(8362) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 2(8362) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 2(8362) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 2(8362) TOTAL: 13 free fragments = 1016432 free bytes 2(8362) ----------------------------- 3(8363) INFO: signal 15 received 3(8363) Memory status (pkg): 3(8363) fm_status (0x8111b00): 3(8363) heap size= 1048576 3(8363) used= 13520, used+overhead=32144, free=1016432 3(8363) max used (+overhead)= 38536 3(8363) dumping free list: 3(8363) hash = 6 fragments no.: 1, unused: 0 bucket size: 48 - 48 (first 48) 3(8363) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 3(8363) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 3(8363) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 3(8363) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 3(8363) TOTAL: 13 free fragments = 1016432 free bytes 3(8363) ----------------------------- 4(8364) INFO: signal 15 received 4(8364) Memory status (pkg): 4(8364) fm_status (0x8111b00): 4(8364) heap size= 1048576 4(8364) used= 13520, used+overhead=32144, free=1016432 4(8364) max used (+overhead)= 38536 4(8364) dumping free list: 4(8364) hash = 6 fragments no.: 1, unused: 0 bucket size: 48 - 48 (first 48) 4(8364) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 4(8364) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 4(8364) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 4(8364) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 4(8364) TOTAL: 13 free fragments = 1016432 free bytes 4(8364) ----------------------------- 5(8365) INFO: signal 15 received 5(8365) Memory status (pkg): 5(8365) fm_status (0x8111b00): 5(8365) heap size= 1048576 5(8365) used= 13520, used+overhead=32144, free=1016432 5(8365) max used (+overhead)= 38536 5(8365) dumping free list: 5(8365) hash = 6 fragments no.: 1, unused: 0 bucket size: 48 - 48 (first 48) 5(8365) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 5(8365) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 5(8365) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 5(8365) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 5(8365) TOTAL: 13 free fragments = 1016432 free bytes 5(8365) ----------------------------- 6(8366) INFO: signal 15 received 6(8366) Memory status (pkg): 6(8366) fm_status (0x8111b00): 6(8366) heap size= 1048576 6(8366) used= 13520, used+overhead=32144, free=1016432 6(8366) max used (+overhead)= 38536 6(8366) dumping free list: 6(8366) hash = 6 fragments no.: 1, unused: 0 bucket size: 48 - 48 (first 48) 6(8366) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 6(8366) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 6(8366) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 6(8366) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 6(8366) TOTAL: 13 free fragments = 1016432 free bytes 6(8366) ----------------------------- 7(8367) INFO: signal 15 received 7(8367) Memory status (pkg): 7(8367) fm_status (0x8111b00): 7(8367) heap size= 1048576 7(8367) used= 13520, used+overhead=32144, free=1016432 7(8367) max used (+overhead)= 38536 7(8367) dumping free list: 7(8367) hash = 6 fragments no.: 1, unused: 0 bucket size: 48 - 48 (first 48) 7(8367) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 7(8367) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 7(8367) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 7(8367) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 7(8367) TOTAL: 13 free fragments = 1016432 free bytes 7(8367) ----------------------------- 8(8368) INFO: signal 15 received 8(8368) Memory status (pkg): 8(8368) fm_status (0x8111b00): 8(8368) heap size= 1048576 8(8368) used= 13520, used+overhead=32144, free=1016432 8(8368) max used (+overhead)= 38536 8(8368) dumping free list: 8(8368) hash = 6 fragments no.: 1, unused: 0 bucket size: 48 - 48 (first 48) 8(8368) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 8(8368) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 8(8368) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 8(8368) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 8(8368) TOTAL: 13 free fragments = 1016432 free bytes 8(8368) ----------------------------- 9(8369) INFO: signal 15 received 9(8369) Memory status (pkg): 9(8369) fm_status (0x8111b00): 9(8369) heap size= 1048576 9(8369) used= 13520, used+overhead=32144, free=1016432 9(8369) max used (+overhead)= 38536 9(8369) dumping free list: 9(8369) hash = 6 fragments no.: 1, unused: 0 bucket size: 48 - 48 (first 48) 9(8369) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 9(8369) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 9(8369) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 9(8369) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 9(8369) TOTAL: 13 free fragments = 1016432 free bytes 9(8369) ----------------------------- 15(8375) INFO: signal 15 received 15(8375) Memory status (pkg): 15(8375) fm_status (0x8111b00): 15(8375) heap size= 1048576 15(8375) used= 63728, used+overhead=82360, free=966216 15(8375) max used (+overhead)= 82360 15(8375) dumping free list: 15(8375) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) 15(8375) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 15(8375) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 15(8375) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 15(8375) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 957800) 15(8375) TOTAL: 13 free fragments = 966216 free bytes 15(8375) ----------------------------- 16(8376) INFO: signal 15 received 16(8376) Memory status (pkg): 16(8376) fm_status (0x8111b00): 16(8376) heap size= 1048576 16(8376) used= 63728, used+overhead=82360, free=966216 16(8376) max used (+overhead)= 82360 16(8376) dumping free list: 16(8376) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) 16(8376) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 16(8376) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 16(8376) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 16(8376) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 957800) 16(8376) TOTAL: 13 free fragments = 966216 free bytes 16(8376) ----------------------------- 17(8377) INFO: signal 15 received 17(8377) Memory status (pkg): 17(8377) fm_status (0x8111b00): 17(8377) heap size= 1048576 17(8377) used= 63728, used+overhead=82360, free=966216 17(8377) max used (+overhead)= 82360 17(8377) dumping free list: 17(8377) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) 17(8377) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 17(8377) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 17(8377) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 17(8377) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 957800) 17(8377) TOTAL: 13 free fragments = 966216 free bytes 17(8377) ----------------------------- 18(8378) INFO: signal 15 received 18(8378) Memory status (pkg): 18(8378) fm_status (0x8111b00): 18(8378) heap size= 1048576 18(8378) used= 63728, used+overhead=82360, free=966216 18(8378) max used (+overhead)= 82360 18(8378) dumping free list: 18(8378) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) 18(8378) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 18(8378) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 18(8378) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 18(8378) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 957800) 18(8378) TOTAL: 13 free fragments = 966216 free bytes 18(8378) ----------------------------- 11(8371) INFO: signal 15 received 11(8371) Memory status (pkg): 11(8371) fm_status (0x8111b00): 11(8371) heap size= 1048576 11(8371) used= 13520, used+overhead=32776, free=1015800 11(8371) max used (+overhead)= 38536 11(8371) dumping free list: 11(8371) hash = 1 fragments no.: 10, unused: 0 bucket size: 8 - 8 (first 8) 11(8371) hash = 2 fragments no.: 3, unused: 0 bucket size: 16 - 16 (first 16) 11(8371) hash = 3 fragments no.: 8, unused: 0 bucket size: 24 - 24 (first 24) 11(8371) hash = 4 fragments no.: 40, unused: 0 bucket size: 32 - 32 (first 32) 11(8371) hash = 5 fragments no.: 7, unused: 0 bucket size: 40 - 40 (first 40) 11(8371) hash = 6 fragments no.: 8, unused: 0 bucket size: 48 - 48 (first 48) 11(8371) hash = 8 fragments no.: 3, unused: 0 bucket size: 64 - 64 (first 64) 11(8371) hash = 9 fragments no.: 2, unused: 0 bucket size: 72 - 72 (first 72) 11(8371) hash = 10 fragments no.: 4, unused: 0 bucket size: 80 - 80 (first 80) 11(8371) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) 11(8371) hash = 15 fragments no.: 1, unused: 0 bucket size: 120 - 120 (first 120) 11(8371) hash = 16 fragments no.: 1, unused: 0 bucket size: 128 - 128 (first 128) 11(8371) hash = 99 fragments no.: 1, unused: 0 bucket size: 792 - 792 (first 792) 11(8371) hash = 119 fragments no.: 1, unused: 0 bucket size: 952 - 952 (first 952) 11(8371) hash = 343 fragments no.: 1, unused: 0 bucket size: 2744 - 2744 (first 2744) 11(8371) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 11(8371) TOTAL: 92 free fragments = 1015800 free bytes 11(8371) ----------------------------- 13(8373) INFO: signal 15 received 13(8373) Memory status (pkg): 13(8373) fm_status (0x8111b00): 13(8373) heap size= 1048576 13(8373) used= 13520, used+overhead=32144, free=1016432 13(8373) max used (+overhead)= 38536 13(8373) dumping free list: 13(8373) hash = 6 fragments no.: 1, unused: 0 bucket size: 48 - 48 (first 48) 13(8373) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 13(8373) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 13(8373) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 13(8373) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 13(8373) TOTAL: 13 free fragments = 1016432 free bytes 13(8373) ----------------------------- 0(8360) DEBUG: tm_shutdown : start 0(8360) DEBUG: unlink_timer_lists : emptying DELETE list 0(8360) DEBUG: tm_shutdown : emptying hash table 0(8360) DEBUG: tm_shutdown : releasing timers 0(8360) DEBUG: tm_shutdown : removing semaphores 0(8360) DEBUG: tm_shutdown : destroying tmcb lists 0(8360) DEBUG: tm_shutdown : done 0(8360) Memory status (pkg): 0(8360) fm_status (0x8111b00): 0(8360) heap size= 1048576 0(8360) used= 12888, used+overhead=31504, free=1017072 0(8360) max used (+overhead)= 38536 0(8360) dumping free list: 0(8360) hash = 2 fragments no.: 33, unused: 0 bucket size: 16 - 16 (first 16) 0(8360) hash = 3 fragments no.: 3, unused: 0 bucket size: 24 - 24 (first 24) 0(8360) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) 0(8360) hash = 16 fragments no.: 9, unused: 0 bucket size: 128 - 128 (first 128) 0(8360) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 0(8360) hash = 800 fragments no.: 1, unused: 0 bucket size: 6400 - 6400 (first 6400) 0(8360) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 1008056) 0(8360) TOTAL: 49 free fragments = 1017072 free bytes 0(8360) ----------------------------- 0(8360) Memory status (shm): 0(8360) fm_status (0xb5d3f000): 0(8360) heap size= 33554432 0(8360) used= 8, used+overhead=17584, free=33536848 0(8360) max used (+overhead)= 1631040 0(8360) dumping free list: 0(8360) hash = 1 fragments no.: 44, unused: 0 bucket size: 8 - 8 (first 8) 0(8360) hash = 2 fragments no.: 10, unused: 0 bucket size: 16 - 16 (first 16) 0(8360) hash = 3 fragments no.: 3, unused: 0 bucket size: 24 - 24 (first 24) 0(8360) hash = 4 fragments no.: 37, unused: 0 bucket size: 32 - 32 (first 32) 0(8360) hash = 5 fragments no.: 5, unused: 0 bucket size: 40 - 40 (first 40) 0(8360) hash = 6 fragments no.: 5, unused: 0 bucket size: 48 - 48 (first 48) 0(8360) hash = 8 fragments no.: 2, unused: 0 bucket size: 64 - 64 (first 64) 0(8360) hash = 11 fragments no.: 2, unused: 0 bucket size: 88 - 88 (first 88) 0(8360) hash = 13 fragments no.: 1, unused: 0 bucket size: 104 - 104 (first 104) 0(8360) hash = 16 fragments no.: 1, unused: 0 bucket size: 128 - 128 (first 128) 0(8360) hash = 40 fragments no.: 1, unused: 0 bucket size: 320 - 320 (first 320) 0(8360) hash = 97 fragments no.: 1, unused: 0 bucket size: 776 - 776 (first 776) 0(8360) hash = 103 fragments no.: 1, unused: 0 bucket size: 824 - 824 (first 824) 0(8360) hash = 130 fragments no.: 1, unused: 0 bucket size: 1040 - 1040 (first 1040) 0(8360) hash = 135 fragments no.: 1, unused: 0 bucket size: 1080 - 1080 (first 1080) 0(8360) hash = 138 fragments no.: 1, unused: 0 bucket size: 1104 - 1104 (first 1104) 0(8360) hash = 350 fragments no.: 1, unused: 0 bucket size: 2800 - 2800 (first 2800) 0(8360) hash = 354 fragments no.: 1, unused: 0 bucket size: 2832 - 2832 (first 2832) 0(8360) hash = 396 fragments no.: 1, unused: 0 bucket size: 3168 - 3168 (first 3168) 0(8360) hash = 466 fragments no.: 1, unused: 0 bucket size: 3728 - 3728 (first 3728) 0(8360) hash = 512 fragments no.: 2, unused: 0 bucket size: 4096 - 4096 (first 4096) 0(8360) hash = 1024 fragments no.: 2, unused: 0 bucket size: 8192 - 8192 (first 8192) 0(8360) hash = 2055 fragments no.: 1, unused: 0 bucket size: 1048576 - 2097152 (first 1572864) 0(8360) hash = 2059 fragments no.: 1, unused: 0 bucket size: 16777216 - 33554432 (first 31918992) 0(8360) TOTAL: 126 free fragments = 33536848 free bytes 0(8360) ----------------------------- 0(8360) shm_mem_destroy 0(8360) destroying the shared memory lock 0(8360) terminating due to SIGCHLD