Mar 14 11:15:54 [4779] DBG:core:parse_msg: SIP Request: Mar 14 11:15:54 [4779] DBG:core:parse_msg: method: Mar 14 11:15:54 [4779] DBG:core:parse_msg: uri: Mar 14 11:15:54 [4779] DBG:core:parse_msg: version: Mar 14 11:15:54 [4779] DBG:core:parse_headers: flags=2 Mar 14 11:15:54 [4779] DBG:core:parse_via_param: found param type 235, = ; state=6 Mar 14 11:15:54 [4779] DBG:core:parse_via_param: found param type 232, = ; state=16 Mar 14 11:15:54 [4779] DBG:core:parse_via: end of header reached, state=5 Mar 14 11:15:54 [4779] DBG:core:parse_headers: via found, flags=2 Mar 14 11:15:54 [4779] DBG:core:parse_headers: this is the first via Mar 14 11:15:54 [4779] DBG:core:receive_msg: After parse_msg... Mar 14 11:15:54 [4779] DBG:core:receive_msg: preparing to run routing scripts... Mar 14 11:15:54 [4779] DBG:core:parse_headers: flags=100 Mar 14 11:15:54 [4779] DBG:core:parse_to: end of header reached, state=10 Mar 14 11:15:54 [4779] DBG:core:parse_to: display={}, ruri={sip:shine_sip2@192.168.2.100} Mar 14 11:15:54 [4779] DBG:core:get_hdr_field: [32]; uri=[sip:shine_sip2@192.168.2.100] Mar 14 11:15:54 [4779] DBG:core:get_hdr_field: to body [ ] Mar 14 11:15:54 [4779] DBG:core:get_hdr_field: cseq : <313> Mar 14 11:15:54 [4779] DBG:maxfwd:is_maxfwd_present: value = 20 Mar 14 11:15:54 [4779] DBG:core:parse_headers: flags=200 Mar 14 11:15:54 [4779] DBG:core:get_hdr_field: content_length=350 Mar 14 11:15:54 [4779] DBG:core:get_hdr_field: found end of header Mar 14 11:15:54 [4779] DBG:rr:find_first_route: No Route headers found Mar 14 11:15:54 [4779] DBG:rr:loose_route: There is no Route HF Mar 14 11:15:54 [4779] DBG:core:grep_sock_info: checking if host==us: 13==13 && [192.168.2.100] == [192.168.2.100] Mar 14 11:15:54 [4779] DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 14 11:15:54 [4779] DBG:registrar:lookup: 'shine_sip2' Not found in usrloc Mar 14 11:15:54 [4779] DBG:core:grep_sock_info: checking if host==us: 13==13 && [192.168.2.100] == [192.168.2.100] Mar 14 11:15:54 [4779] DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 14 11:15:54 [4779] DBG:core:rewrite_uri: rewriting Request-URI with 'sip:shine_sip2@192.168.2.101:5070' Mar 14 11:15:54 [4779] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4779] DBG:tm:t_newtran: transaction on entrance=0xffffffff Mar 14 11:15:54 [4779] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4779] DBG:core:parse_headers: flags=78 Mar 14 11:15:54 [4779] DBG:tm:t_lookup_request: start searching: hash=61857, isACK=0 Mar 14 11:15:54 [4779] DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 14 11:15:54 [4779] DBG:tm:t_lookup_request: no transaction found Mar 14 11:15:54 [4779] DBG:core:parse_to_param: tag=8617 Mar 14 11:15:54 [4779] DBG:core:parse_to: end of header reached, state=29 Mar 14 11:15:54 [4779] DBG:core:parse_to: display={"Shine"}, ruri={sip:shine_sip@192.168.2.100} Mar 14 11:15:54 [4779] DBG:tm:run_reqin_callbacks: trans=0xb3c21aa0, callback type 1, id 0 entered Mar 14 11:15:54 [4779] DBG:seas:w_as_relay_t: new INVITE Mar 14 11:15:54 [4779] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4779] DBG:core:check_via_address: params 192.168.2.102, 192.168.2.102, 0 Mar 14 11:15:54 [4779] DBG:core:_shm_resize: resize(0) called Mar 14 11:15:54 [4779] DBG:tm:_reply_light: reply sent out. buf=0x8183f70: SIP/2.0 1..., shmem=0xb3c238b8: SIP/2.0 1 Mar 14 11:15:54 [4779] DBG:tm:_reply_light: finished Mar 14 11:15:54 [4779] DBG:seas:w_as_relay_t: as found ! (app_server_one) processor id = 1 Mar 14 11:15:54 [4779] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4779] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4779] DBG:core:parse_methods: methods 0x143F Mar 14 11:15:54 [4779] DBG:seas:encode_msg: msglen = 863,msg starts at 200 Mar 14 11:15:54 [4779] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 14 11:15:54 [4779] DBG:core:destroy_avp_list: destroying list (nil) Mar 14 11:15:54 [4779] DBG:core:receive_msg: cleaning up Mar 14 11:15:54 [-1212851371] DBG:seas:dispatch_relay: Event relaied to app_server_one AS Mar 14 11:15:54 [-1212851371] DBG:seas:dispatch_relay: Event type FINAL_REPLY Mar 14 11:15:54 [-1212851371] DBG:seas:dispatcher_main_loop: Scanning data from 1 AS Mar 14 11:15:54 [-1212851371] DBG:seas:dispatcher_main_loop: Scanning data from 0 uncomplete AS Mar 14 11:15:54 [-1212851371] INFO:seas:dispatcher_main_loop: polling [2 ServSock] [1 pipe] [1 App Servers] [0 Uncomplete AS] Mar 14 11:15:54 [4838] DBG:seas:process_input: read 325 bytes from AS action socket (total = 325) Mar 14 11:15:54 [4838] DBG:seas:process_action: Processing action 325 bytes long Mar 14 11:15:54 [4838] DBG:seas:process_action: Processing a REPLY action from AS (length=325): app_server_one Mar 14 11:15:54 [4838] DBG:tm:t_lookup_ident: REF_UNSAFE: after is 1 Mar 14 11:15:54 [4838] DBG:tm:t_lookup_ident: transaction found Mar 14 11:15:54 [4838] DBG:seas:parse_ac_msg: Action Message:[SIP/2.0 481 Call Leg/Transaction Does Not Exist Via: SIP/2.0/UDP 192.168.2.102:5061;rport;branch=z9hG4bK703532 To: From: "Shine" ;tag=8617 Call-ID: 1205473800-3532-BSB093-31@10.108.3.84 CSeq: 313 INVITE Max-Forwards: 19 Content-Length: 0 ] Mar 14 11:15:54 [4838] DBG:core:parse_msg: SIP Reply (status): Mar 14 11:15:54 [4838] DBG:core:parse_msg: version: Mar 14 11:15:54 [4838] DBG:core:parse_msg: status: <481> Mar 14 11:15:54 [4838] DBG:core:parse_msg: reason: Mar 14 11:15:54 [4838] DBG:core:parse_headers: flags=2 Mar 14 11:15:54 [4838] DBG:core:parse_via_param: found param type 235, = ; state=6 Mar 14 11:15:54 [4838] DBG:core:parse_via_param: found param type 232, = ; state=16 Mar 14 11:15:54 [4838] DBG:core:parse_via: end of header reached, state=5 Mar 14 11:15:54 [4838] DBG:core:parse_headers: via found, flags=2 Mar 14 11:15:54 [4838] DBG:core:parse_headers: this is the first via Mar 14 11:15:54 [4838] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4838] DBG:core:parse_to: end of header reached, state=10 Mar 14 11:15:54 [4838] DBG:core:parse_to: display={}, ruri={sip:shine_sip2@192.168.2.100} Mar 14 11:15:54 [4838] DBG:core:get_hdr_field: [32]; uri=[sip:shine_sip2@192.168.2.100] Mar 14 11:15:54 [4838] DBG:core:get_hdr_field: to body [ ] Mar 14 11:15:54 [4838] DBG:core:get_hdr_field: cseq : <313> Mar 14 11:15:54 [4838] DBG:core:get_hdr_field: content_length=0 Mar 14 11:15:54 [4838] DBG:core:get_hdr_field: found end of header Mar 14 11:15:54 [4838] DBG:seas:ac_reply: Using totag=[] Mar 14 11:15:54 [4838] DBG:seas:ac_reply: Recordroute Diff = 0 Mar 14 11:15:54 [4838] DBG:seas:extract_allowed_headers: Skipping header (Via) Mar 14 11:15:54 [4838] DBG:seas:extract_allowed_headers: Skipping header (To) Mar 14 11:15:54 [4838] DBG:seas:extract_allowed_headers: Skipping header (From) Mar 14 11:15:54 [4838] DBG:seas:extract_allowed_headers: Skipping header (Call-ID) Mar 14 11:15:54 [4838] DBG:seas:extract_allowed_headers: Skipping header (CSeq) Mar 14 11:15:54 [4838] DBG:seas:extract_allowed_headers: Skipping header (Content-Length) Mar 14 11:15:54 [4838] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4838] DBG:seas:ac_reply: Trying to construct a SipReply with: ReasonPhrase:[Call Leg/Transaction Does Not Exist] body:[] headers:[Max-Forwards: 19 ] totag:[] Mar 14 11:15:54 [4838] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4838] DBG:core:check_via_address: params 192.168.2.102, 192.168.2.102, 0 Mar 14 11:15:54 [4838] DBG:tm:t_reply_with_body: buffer computed Mar 14 11:15:54 [4838] DBG:tm:cleanup_uac_timers: RETR/FR timers reset Mar 14 11:15:54 [4838] DBG:tm:set_timer: relative timeout is 500000 Mar 14 11:15:54 [4838] DBG:tm:insert_timer_unsafe: [4]: 0xb3c21b68 (1556600000) Mar 14 11:15:54 [4838] DBG:tm:set_timer: relative timeout is 30 Mar 14 11:15:54 [4838] DBG:tm:insert_timer_unsafe: [0]: 0xb3c21b84 (1586) Mar 14 11:15:54 [4838] DBG:tm:_reply_light: reply sent out. buf=0x817ae50: SIP/2.0 4..., shmem=0xb3c238b8: SIP/2.0 4 Mar 14 11:15:54 [4838] DBG:tm:_reply_light: finished Mar 14 11:15:54 [4838] DBG:tm:t_reply_with_body: UNREF_UNSAFE: after is 0 Mar 14 11:15:54 [4838] DBG:seas:process_input: (Action dispatched,buffer.len=0) Mar 14 11:15:54 [4782] DBG:core:parse_msg: SIP Request: Mar 14 11:15:54 [4782] DBG:core:parse_msg: method: Mar 14 11:15:54 [4782] DBG:core:parse_msg: uri: Mar 14 11:15:54 [4782] DBG:core:parse_msg: version: Mar 14 11:15:54 [4782] DBG:core:parse_headers: flags=2 Mar 14 11:15:54 [4782] DBG:core:parse_via_param: found param type 235, = ; state=6 Mar 14 11:15:54 [4782] DBG:core:parse_via_param: found param type 232, = ; state=16 Mar 14 11:15:54 [4782] DBG:core:parse_via: end of header reached, state=5 Mar 14 11:15:54 [4782] DBG:core:parse_headers: via found, flags=2 Mar 14 11:15:54 [4782] DBG:core:parse_headers: this is the first via Mar 14 11:15:54 [4782] DBG:core:receive_msg: After parse_msg... Mar 14 11:15:54 [4782] DBG:core:receive_msg: preparing to run routing scripts... Mar 14 11:15:54 [4782] DBG:sl:sl_filter_ACK: to late to be a local ACK! Mar 14 11:15:54 [4782] DBG:core:parse_headers: flags=100 Mar 14 11:15:54 [4782] DBG:core:parse_to: end of header reached, state=10 Mar 14 11:15:54 [4782] DBG:core:parse_to: display={}, ruri={sip:shine_sip2@192.168.2.100} Mar 14 11:15:54 [4782] DBG:core:get_hdr_field: [32]; uri=[sip:shine_sip2@192.168.2.100] Mar 14 11:15:54 [4782] DBG:core:get_hdr_field: to body [ ] Mar 14 11:15:54 [4782] DBG:core:get_hdr_field: cseq : <313> Mar 14 11:15:54 [4782] DBG:maxfwd:is_maxfwd_present: value = 20 Mar 14 11:15:54 [4782] DBG:core:parse_headers: flags=200 Mar 14 11:15:54 [4782] DBG:core:get_hdr_field: content_length=0 Mar 14 11:15:54 [4782] DBG:core:get_hdr_field: found end of header Mar 14 11:15:54 [4782] DBG:rr:find_first_route: No Route headers found Mar 14 11:15:54 [4782] DBG:rr:loose_route: There is no Route HF Mar 14 11:15:54 [4782] DBG:core:grep_sock_info: checking if host==us: 13==13 && [192.168.2.100] == [192.168.2.100] Mar 14 11:15:54 [4782] DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 14 11:15:54 [4782] DBG:registrar:lookup: 'shine_sip2' Not found in usrloc Mar 14 11:15:54 [4782] DBG:core:grep_sock_info: checking if host==us: 13==13 && [192.168.2.100] == [192.168.2.100] Mar 14 11:15:54 [4782] DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 14 11:15:54 [4782] DBG:core:rewrite_uri: rewriting Request-URI with 'sip:shine_sip2@192.168.2.101:5070' Mar 14 11:15:54 [4782] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4782] DBG:tm:t_newtran: transaction on entrance=0xffffffff Mar 14 11:15:54 [4782] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4782] DBG:core:parse_headers: flags=78 Mar 14 11:15:54 [4782] DBG:tm:t_lookup_request: start searching: hash=61857, isACK=1 Mar 14 11:15:54 [4782] DBG:tm:matching_3261: RFC3261 transaction matched, tid=703532 Mar 14 11:15:54 [4782] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1 Mar 14 11:15:54 [4782] DBG:tm:t_lookup_request: transaction found (T=0xb3c21aa0) Mar 14 11:15:54 [4782] DBG:tm:cleanup_uac_timers: RETR/FR timers reset Mar 14 11:15:54 [4782] DBG:tm:insert_timer_unsafe: [2]: 0xb3c21ae8 (1561) Mar 14 11:15:54 [4782] DBG:seas:w_as_relay_t: as found ! (app_server_one) processor id = 1 Mar 14 11:15:54 [4782] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4782] DBG:core:parse_headers: flags=ffffffffffffffff Mar 14 11:15:54 [4782] DBG:core:parse_to_param: tag=8617 Mar 14 11:15:54 [4782] DBG:core:parse_to: end of header reached, state=29 Mar 14 11:15:54 [4782] DBG:core:parse_to: display={"Shine"}, ruri={sip:shine_sip@192.168.2.100} Mar 14 11:15:54 [4782] DBG:seas:encode_msg: msglen = 345,msg starts at 147 Mar 14 11:15:54 [4782] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 14 11:15:54 [4782] DBG:core:destroy_avp_list: destroying list (nil) Mar 14 11:15:54 [4782] DBG:core:receive_msg: cleaning up Mar 14 11:15:54 [-1212851371] DBG:seas:dispatch_relay: Event relaied to app_server_one AS Mar 14 11:15:54 [-1212851371] DBG:seas:dispatch_relay: Event type FINAL_REPLY Mar 14 11:15:54 [-1212851371] DBG:seas:dispatcher_main_loop: Scanning data from 1 AS Mar 14 11:15:54 [-1212851371] DBG:seas:dispatcher_main_loop: Scanning data from 0 uncomplete AS Mar 14 11:15:54 [-1212851371] INFO:seas:dispatcher_main_loop: polling [2 ServSock] [1 pipe] [1 App Servers] [0 Uncomplete AS] Mar 14 11:15:54 [4784] DBG:tm:utimer_routine: timer routine:4,tl=0xb3c21b68 next=(nil), timeout=1556600000 Mar 14 11:15:59 [4784] DBG:tm:timer_routine: timer routine:2,tl=0xb3c21ae8 next=(nil), timeout=1561 Mar 14 11:15:59 [4784] DBG:tm:wait_handler: removing 0xb3c21aa0 from table Mar 14 11:15:59 [4784] DBG:tm:delete_cell: delete transaction 0xb3c21aa0 Mar 14 11:15:59 [4784] DBG:tm:wait_handler: done