rendered paste body 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 <db_mode> 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 <enable_full_lr> 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 <nat_flag> 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 <natping_interval> 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 <ping_nated_only> in module nathelper [/usr/lib/openser/modules/nathelper.so]
0(8358) find_cmd_export_t: found <mf_process_maxfwd_header>(1) in module maxfwd [/usr/lib/openser/modules/maxfwd.so]
0(8358) find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/lib/openser/modules/sl.so]
0(8358) find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/lib/openser/modules/sl.so]
0(8358) find_cmd_export_t: found <nat_uac_test>(1) in module nathelper [/usr/lib/openser/modules/nathelper.so]
0(8358) find_cmd_export_t: found <search>(1) in module textops [/usr/lib/openser/modules/textops.so]
0(8358) find_cmd_export_t: found <fix_nated_contact>(0) in module nathelper [/usr/lib/openser/modules/nathelper.so]
0(8358) find_cmd_export_t: found <fix_nated_sdp>(1) in module nathelper [/usr/lib/openser/modules/nathelper.so]
0(8358) find_cmd_export_t: found <record_route>(0) in module rr [/usr/lib/openser/modules/rr.so]
0(8358) find_cmd_export_t: found <loose_route>(0) in module rr [/usr/lib/openser/modules/rr.so]
0(8358) find_cmd_export_t: found <append_hf>(1) in module textops [/usr/lib/openser/modules/textops.so]
0(8358) find_cmd_export_t: found <append_hf>(1) in module textops [/usr/lib/openser/modules/textops.so]
0(8358) find_cmd_export_t: found <save>(1) in module registrar [/usr/lib/openser/modules/registrar.so]
0(8358) find_cmd_export_t: found <lookup>(1) in module registrar [/usr/lib/openser/modules/registrar.so]
0(8358) find_cmd_export_t: found <append_hf>(1) in module textops [/usr/lib/openser/modules/textops.so]
0(8358) find_cmd_export_t: found <lookup>(1) in module registrar [/usr/lib/openser/modules/registrar.so]
0(8358) find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/lib/openser/modules/sl.so]
0(8358) find_cmd_export_t: found <append_hf>(1) in module textops [/usr/lib/openser/modules/textops.so]
0(8358) find_cmd_export_t: found <search>(1) in module textops [/usr/lib/openser/modules/textops.so]
0(8358) find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/lib/openser/modules/sl.so]
0(8358) find_cmd_export_t: found <force_rtp_proxy>(0) in module nathelper [/usr/lib/openser/modules/nathelper.so]
0(8358) find_cmd_export_t: found <t_on_reply>(1) in module tm [/usr/lib/openser/modules/tm.so]
0(8358) find_cmd_export_t: found <t_relay>(0) in module tm [/usr/lib/openser/modules/tm.so]
0(8358) find_cmd_export_t: found <sl_reply_error>(0) in module sl [/usr/lib/openser/modules/sl.so]
0(8358) find_cmd_export_t: found <fix_nated_contact>(0) in module nathelper [/usr/lib/openser/modules/nathelper.so]
0(8358) find_cmd_export_t: found <force_rtp_proxy>(0) in module nathelper [/usr/lib/openser/modules/nathelper.so]
0(8358) find_cmd_export_t: found <nat_uac_test>(1) in module nathelper [/usr/lib/openser/modules/nathelper.so]
0(8358) find_cmd_export_t: found <fix_nated_contact>(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<mf_process_maxfwd_header> 0(8358) , "10" 0(8358) ); 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f<sl_send_reply> 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<sl_send_reply> 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<nat_uac_test> 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<search> 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<fix_nated_contact> 0(8358) ); 0(8358) if ( 0(8358) method 0(8358) == 0(8358) "INVITE" 0(8358) ) { 0(8358) external_module_call( 0(8358) f<fix_nated_sdp> 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<record_route> 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) if ( 0(8358) external_module_call( 0(8358) f<loose_route> 0(8358) ); 0(8358) ) { 0(8358) external_module_call( 0(8358) f<append_hf> 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<append_hf> 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<save> 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<lookup> 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<append_hf> 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<lookup> 0(8358) , "location" 0(8358) ); 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f<sl_send_reply> 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<append_hf> 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<search> 0(8358) , "^Route:" 0(8358) ); 0(8358) ) 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f<sl_send_reply> 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<force_rtp_proxy> 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) external_module_call( 0(8358) f<t_on_reply> 0(8358) , "1" 0(8358) ); 0(8358) if ( 0(8358) NOT( 0(8358) external_module_call( 0(8358) f<t_relay> 0(8358) ); 0(8358) ) 0(8358) ) { 0(8358) external_module_call( 0(8358) f<sl_reply_error> 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<fix_nated_contact> 0(8358) ); 0(8358) external_module_call( 0(8358) f<force_rtp_proxy> 0(8358) ); 0(8358) } else { 0(8358) if ( 0(8358) external_module_call( 0(8358) f<nat_uac_test> 0(8358) , "1" 0(8358) ); 0(8358) ) { 0(8358) external_module_call( 0(8358) f<fix_nated_contact> 0(8358) ); 0(8358) } else { 0(8358) }; 0(8358) }; 0(8358)
0(8358) DEBUG:socket2str: <udp:127.0.0.1:5060>
0(8358) DEBUG:socket2str: <udp:169.198.11.95:5060>
0(8358) DEBUG:socket2str: <udp:169.198.11.110:5060>
0(8358) DEBUG:socket2str: <tcp:127.0.0.1:5060>
0(8358) DEBUG:socket2str: <tcp:169.198.11.95:5060>
0(8358) DEBUG:socket2str: <tcp:169.198.11.110:5060>
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 <serial_branch> 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 <sl_send_reply>(2) in module sl [/usr/lib/openser/modules/sl.so]
0(0) find_cmd_export_t: found <ul_bind_usrloc>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_register_udomain>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_get_all_ucontacts>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_insert_urecord>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_delete_urecord>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_get_urecord>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_lock_udomain>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_unlock_udomain>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_release_urecord>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_insert_ucontact>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_delete_ucontact>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_get_ucontact>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_update_ucontact>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_register_watcher>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_unregister_watcher>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_register_ulcb>(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 <ul_bind_usrloc>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_register_udomain>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_get_all_ucontacts>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_insert_urecord>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_delete_urecord>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_get_urecord>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_lock_udomain>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_unlock_udomain>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_release_urecord>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_insert_ucontact>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_delete_ucontact>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_get_ucontact>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_update_ucontact>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_register_watcher>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_unregister_watcher>(1) in module usrloc [/usr/lib/openser/modules/usrloc.so]
0(0) find_cmd_export_t: found <ul_register_ulcb>(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 <unix:/var/run/rtpproxy.sock> 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 <unix:/var/run/rtpproxy.sock> found, support for it enabled
3(8363) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
4(8364) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
5(8365) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
6(8366) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
7(8367) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
8(8368) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
9(8369) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
10(8370) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
11(8371) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
12(8372) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
13(8373) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
14(8374) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
15(8375) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
15(8375) DBG: io_watch_add(0x80dfe80, 29, 1, (nil)), fd_no=0
16(8376) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
16(8376) DBG: io_watch_add(0x80dfe80, 31, 1, (nil)), fd_no=0
17(8377) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
17(8377) DBG: io_watch_add(0x80dfe80, 33, 1, (nil)), fd_no=0
18(8378) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> found, support for it enabled
18(8378) DBG: io_watch_add(0x80dfe80, 35, 1, (nil)), fd_no=0
19(8379) rtpp_test: RTP proxy <unix:/var/run/rtpproxy.sock> 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 <unix:/var/run/rtpproxy.sock> found, support for it enabled
10(8370) SIP Request:
10(8370) method: <REGISTER>
10(8370) uri: <sip:169.198.11.110>
10(8370) version: <SIP/2.0>
10(8370) parse_headers: flags=2
10(8370) get_hdr_field: cseq <CSeq>: <1> <REGISTER>
10(8370) Found param type 232, <branch> = <z9hG4bK7282f5f0-32ec-db11-9653-001372710463>; state=6
10(8370) Found param type 235, <rport> = <n/a>; 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: <To> [27]; uri=[sip:test@169.198.11.110]
10(8370) DEBUG: to body [<sip:test@169.198.11.110>
]
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: <sip:test@169.198.11.19:5061;transport=udp>;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: <SUBSCRIBE>
12(8372) uri: <sip:test@169.198.11.110>
12(8372) version: <SIP/2.0>
12(8372) parse_headers: flags=2
12(8372) get_hdr_field: cseq <CSeq>: <2> <SUBSCRIBE>
12(8372) Found param type 232, <branch> = <z9hG4bK225ef6f0-32ec-db11-9653-001372710463>; state=6
12(8372) Found param type 235, <rport> = <n/a>; 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: <To> [27]; uri=[sip:test@169.198.11.110]
12(8372) DEBUG: to body [<sip:test@169.198.11.110>
]
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: <SIP/2.0>
10(8370) status: <405>
10(8370) reason: <Method Not Allowed>
10(8370) parse_headers: flags=2
10(8370) get_hdr_field: cseq <CSeq>: <2> <SUBSCRIBE>
10(8370) Found param type 232, <branch> = <z9hG4bK4936.11151682.0>; 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, <branch> = <z9hG4bK225ef6f0-32ec-db11-9653-001372710463>; state=6
10(8370) Found param type 235, <rport> = <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: <To> [27]; uri=[sip:test@169.198.11.110]
10(8370) DEBUG: to body [<sip:test@169.198.11.110>
]
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: <sip:test@169.198.11.110>;tag=c457f6f0-32ec-db11-9653-001372710463
Call-ID: 6a2af6f0-32ec-db11-9653-001372710463@maxedout
To: <sip:test@169.198.11.110>
Allow: INVITE
Content-Length: 0
Record-Route: <sip:169.198.11.110;lr=on;ftag=c457f6f0-32ec-db11-9653-001372710463>
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: <REGISTER>
12(8372) uri: <sip:169.198.11.110>
12(8372) version: <SIP/2.0>
12(8372) parse_headers: flags=2
12(8372) get_hdr_field: cseq <CSeq>: <1> <REGISTER>
12(8372) Found param type 232, <branch> = <z9hG4bK2c2fc8ec-75ec-db11-9c5e-00187185e000>; state=6
12(8372) Found param type 235, <rport> = <n/a>; 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: <To> [33]; uri=[sip:test_store@169.198.11.110]
12(8372) DEBUG: to body [<sip:test_store@169.198.11.110>
]
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: <sip:test_store@169.198.11.175:5061;transport=udp>;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: <SUBSCRIBE>
10(8370) uri: <sip:test_store@169.198.11.110>
10(8370) version: <SIP/2.0>
10(8370) parse_headers: flags=2
10(8370) get_hdr_field: cseq <CSeq>: <2> <SUBSCRIBE>
10(8370) Found param type 232, <branch> = <z9hG4bKa4bac9ec-75ec-db11-9c5e-00187185e000>; state=6
10(8370) Found param type 235, <rport> = <n/a>; 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: <To> [33]; uri=[sip:test_store@169.198.11.110]
10(8370) DEBUG: to body [<sip:test_store@169.198.11.110>
]
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: <SIP/2.0>
12(8372) status: <405>
12(8372) reason: <Method Not Allowed>
12(8372) parse_headers: flags=2
12(8372) get_hdr_field: cseq <CSeq>: <2> <SUBSCRIBE>
12(8372) Found param type 232, <branch> = <z9hG4bK6ebe.5e66ab47.0>; 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, <received> = <169.198.11.175>; state=6
12(8372) Found param type 232, <branch> = <z9hG4bKa4bac9ec-75ec-db11-9c5e-00187185e000>; state=6
12(8372) Found param type 235, <rport> = <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: <To> [33]; uri=[sip:test_store@169.198.11.110]
12(8372) DEBUG: to body [<sip:test_store@169.198.11.110>
]
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: <sip:test_store@169.198.11.110>;tag=96afc9ec-75ec-db11-9c5e-00187185e000
Call-ID: c841c9ec-75ec-db11-9c5e-00187185e000@10.20.30.25
To: <sip:test_store@169.198.11.110>
Allow: INVITE
Content-Length: 0
Record-Route: <sip:169.198.11.110;lr=on;ftag=96afc9ec-75ec-db11-9c5e-00187185e000>
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: <INVITE>
11(8371) uri: <sip:test@169.198.11.110>
11(8371) version: <SIP/2.0>
11(8371) parse_headers: flags=2
11(8371) get_hdr_field: cseq <CSeq>: <1> <INVITE>
11(8371) Found param type 232, <branch> = <z9hG4bKd42631f8-75ec-db11-9c5e-00187185e000>; state=6
11(8371) Found param type 235, <rport> = <n/a>; 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: <To> [27]; uri=[sip:test@169.198.11.110]
11(8371) DEBUG: to body [<sip:test@169.198.11.110>
]
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 <application/sdp> 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 <application/sdp> 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: <SIP/2.0>
10(8370) status: <100>
10(8370) reason: <Trying>
10(8370) parse_headers: flags=2
10(8370) get_hdr_field: cseq <CSeq>: <1> <INVITE>
10(8370) Found param type 232, <branch> = <z9hG4bK7fbf.981bd094.0>; 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, <received> = <169.198.11.175>; state=6
10(8370) Found param type 232, <branch> = <z9hG4bKd42631f8-75ec-db11-9c5e-00187185e000>; state=6
10(8370) Found param type 235, <rport> = <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: <To> [27]; uri=[sip:test@169.198.11.110]
10(8370) DEBUG: to body [<sip:test@169.198.11.110>
]
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: <SIP/2.0>
12(8372) status: <100>
12(8372) reason: <Trying>
12(8372) parse_headers: flags=2
12(8372) get_hdr_field: cseq <CSeq>: <1> <INVITE>
12(8372) Found param type 232, <branch> = <z9hG4bK7fbf.981bd094.0>; 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, <received> = <169.198.11.175>; state=6
12(8372) Found param type 232, <branch> = <z9hG4bKd42631f8-75ec-db11-9c5e-00187185e000>; state=6
12(8372) Found param type 235, <rport> = <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: <To> [68]; uri=[sip:test@169.198.11.110]
12(8372) DEBUG: to body [<sip:test@169.198.11.110>]
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: <SIP/2.0>
11(8371) status: <502>
11(8371) reason: <Bad Gateway>
11(8371) parse_headers: flags=2
11(8371) get_hdr_field: cseq <CSeq>: <1> <INVITE>
11(8371) Found param type 232, <branch> = <z9hG4bK7fbf.981bd094.0>; 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, <received> = <169.198.11.175>; state=6
11(8371) Found param type 232, <branch> = <z9hG4bKd42631f8-75ec-db11-9c5e-00187185e000>; state=6
11(8371) Found param type 235, <rport> = <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: <To> [68]; uri=[sip:test@169.198.11.110]
11(8371) DEBUG: to body [<sip:test@169.198.11.110>]
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=<From: "Test Store" <sip:test_store@169.198.11.110>;tag=fcbe2ff8-75ec-db11-9c5e-00187185e000
>, TO=<To: <sip:test@169.198.11.110>;tag=8ed11bfa-33ec-db11-9653-001372710463
>, CSEQ_N=<CSeq: 1>
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" <sip:test_store@169.198.11.110>;tag=fcbe2ff8-75ec-db11-9c5e-00187185e000
Call-ID: 14b12ff8-75ec-db11-9c5e-00187185e000@10.20.30.25
To: <sip:test@169.198.11.110>;tag=8ed11bfa-33ec-db11-9653-001372710463
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Content-Length: 0
Record-Route: <sip:169.198.11.110;lr=on;ftag=fcbe2ff8-75ec-db11-9c5e-00187185e000>
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: <ACK>
12(8372) uri: <sip:test@169.198.11.110>
12(8372) version: <SIP/2.0>
12(8372) parse_headers: flags=2
12(8372) get_hdr_field: cseq <CSeq>: <1> <ACK>
12(8372) Found param type 232, <branch> = <z9hG4bKd42631f8-75ec-db11-9c5e-00187185e000>; state=6
12(8372) Found param type 235, <rport> = <n/a>; 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: <To> [68]; uri=[sip:test@169.198.11.110]
12(8372) DEBUG: to body [<sip:test@169.198.11.110>]
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: <SIP/2.0>
11(8371) status: <200>
11(8371) reason: <OK>
11(8371) parse_headers: flags=2
11(8371) get_hdr_field: cseq <CSeq>: <1> <INVITE>
11(8371) Found param type 232, <branch> = <z9hG4bK7fbf.981bd094.0>; 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, <received> = <169.198.11.175>; state=6
11(8371) Found param type 232, <branch> = <z9hG4bKd42631f8-75ec-db11-9c5e-00187185e000>; state=6
11(8371) Found param type 235, <rport> = <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: <To> [68]; uri=[sip:test@169.198.11.110]
11(8371) DEBUG: to body [<sip:test@169.198.11.110>]
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 <application/sdp> 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" <sip:test_store@169.198.11.110>;tag=fcbe2ff8-75ec-db11-9c5e-00187185e000
Call-ID: 14b12ff8-75ec-db11-9c5e-00187185e000@10.20.30.25
To: <sip:test@169.198.11.110>;tag=8ed11bfa-33ec-db11-9653-001372710463
Contact: <sip:test@169.198.11.19:5063;transport=udp>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Content-Type: application/sdp
Content-Length: 173
Record-Route: <sip:169.198.11.110;lr=on;ftag=fcbe2ff8-75ec-db11-9c5e-00187185e000>
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