9(21136) SIP Request: 9(21136) method: 9(21136) uri: 9(21136) version: 9(21136) parse_headers: flags=2 9(21136) DEBUG:parse_to:end of header reached, state=9 9(21136) DEBUG: get_hdr_field: [31]; uri=[sip:4321@OPENSER-SERVER] 9(21136) DEBUG: to body [ ] 9(21136) Found param type 232, = ; state=6 9(21136) Found param type 235, = ; state=17 9(21136) end of header reached, state=5 9(21136) parse_headers: Via found, flags=2 9(21136) parse_headers: this is the first via 9(21136) After parse_msg... 9(21136) preparing to run routing scripts... 9(21136) parse_headers: flags=100 9(21136) get_hdr_field: cseq : <1> 9(21136) DEBUG:maxfwd:is_maxfwd_present: value = 70 9(21136) parse_headers: flags=80 9(21136) DEBUG:rr:add_rr_param: rr_param_buf=<;nat=yes> 9(21136) DEBUG: add_param: tag=936ebe41 9(21136) DEBUG:parse_to:end of header reached, state=29 9(21136) parse_headers: flags=200 9(21136) DEBUG: get_hdr_body : content_length=268 9(21136) found end of header 9(21136) find_first_route: No Route headers found 9(21136) loose_route: There is no Route HF 9(21136) parse_headers: flags=80 9(21136) parse_headers: flags=80 9(21136) parse_headers: flags=ffffffffffffffff 9(21136) parse_headers: flags=4000000 9(21136) error: use_media_proxy(): empty response from mediaproxy 9(21136) DEBUG: t_newtran: msg id=20 , global msg id=19 , T on entrance=0xffffffff 9(21136) parse_headers: flags=ffffffffffffffff 9(21136) parse_headers: flags=78 9(21136) t_lookup_request: start searching: hash=44175, isACK=0 9(21136) DEBUG: RFC3261 transaction matching failed 9(21136) DEBUG: t_lookup_request: no transaction found 9(21136) DEBUG:tm:t_relay: new INVITE 9(21136) parse_headers: flags=ffffffffffffffff 9(21136) check_via_address(IP-FIREWALL, 10.32.9.225, 0) 9(21136) WARNING:vqm_resize: resize(0) called 9(21136) DEBUG:tm:_reply_light: reply sent out. buf=0x812e9d8: SIP/2.0 1..., shmem=0xb60ca190: SIP/2.0 1 9(21136) DEBUG:tm:_reply_light: finished 9(21136) DEBUG: mk_proxy: doing DNS lookup... 9(21136) check_via_address(IP-FIREWALL, 10.32.9.225, 0) 9(21136) DEBUG: add_to_tail_of_timer[4]: 0xb60c7734 9(21136) DEBUG: add_to_tail_of_timer[0]: 0xb60c7744 9(21136) SER: new transaction fwd'ed 9(21136) DEBUG:destroy_avp_list: destroying list (nil) 9(21136) receive_msg: cleaning up 8(21135) SIP Reply (status): 8(21135) version: 8(21135) status: <407> 8(21135) reason: 8(21135) parse_headers: flags=2 8(21135) Found param type 232, = ; state=6 8(21135) Found param type 234, = ; state=16 8(21135) end of header reached, state=5 8(21135) parse_headers: Via found, flags=2 8(21135) parse_headers: this is the first via 8(21135) After parse_msg... 8(21135) forward_reply: found module tm, passing reply to it 8(21135) DEBUG: t_check: msg id=17 global id=16 T start=0xffffffff 8(21135) parse_headers: flags=22 8(21135) Found param type 234, = ; state=6 8(21135) Found param type 232, = ; state=6 8(21135) Found param type 235, = <15963>; state=16 8(21135) end of header reached, state=5 8(21135) parse_headers: Via found, flags=22 8(21135) parse_headers: this is the second via 8(21135) DEBUG: add_param: tag=as1b82a541 8(21135) DEBUG:parse_to:end of header reached, state=29 8(21135) DEBUG: get_hdr_field: [46]; uri=[sip:4321@OPENSER-SERVER] 8(21135) DEBUG: to body [] 8(21135) get_hdr_field: cseq : <1> 8(21135) parse_headers: flags=8 8(21135) DEBUG: t_reply_matching: hash 44175 label 1981334487 branch 0 8(21135) DEBUG: t_reply_matching: reply matched (T=0xb60c7618)! 8(21135) DEBUG: t_check: msg id=17 global id=17 T end=0xb60c7618 8(21135) DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) 8(21135) parse_headers: flags=8 8(21135) DEBUG:tm:build_local: using FROM=;tag=936ebe41 >, TO=;tag=as1b82a541 >, CSEQ_N= 8(21135) parse_headers: flags=80 8(21135) DEBUG:tm:t_should_relay_response: T_code=100, new_code=407 8(21135) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 8(21135) old size: 612, new size: 525 8(21135) build_res_from_sip_res: copied size: orig:130, new: 43, rest: 482 msg= SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.32.9.225:8042;received=IP-FIREWALL;branch=z9hG4bK-d87543-499259966-1--d87543-;rport=15963 From: fidias;tag=936ebe41 To: ;tag=as1b82a541 Call-ID: 872d797c9d234d02 CSeq: 1 INVITE User-Agent: Planeta LAB1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Proxy-Authenticate: Digest realm="asterisk", nonce="1e91494d" Content-Length: 0 8(21135) DEBUG: add_to_tail_of_timer[4]: 0xb60c76c8 8(21135) DEBUG: add_to_tail_of_timer[0]: 0xb60c76d8 8(21135) DEBUG:tm:relay_reply: sent buf=0x812f2c8: SIP/2.0 4..., shmem=0xb60cb908: SIP/2.0 4 8(21135) DEBUG: cleanup_uac_timers: RETR/FR timers reset 8(21135) DEBUG:destroy_avp_list: destroying list (nil) 8(21135) receive_msg: cleaning up 7(21134) SIP Request: 7(21134) method: 7(21134) uri: 7(21134) version: 7(21134) parse_headers: flags=2 7(21134) DEBUG: add_param: tag=as1b82a541 7(21134) DEBUG:parse_to:end of header reached, state=29 7(21134) DEBUG: get_hdr_field: [46]; uri=[sip:4321@OPENSER-SERVER] 7(21134) DEBUG: to body [] 7(21134) Found param type 232, = ; state=6 7(21134) Found param type 235, = ; state=17 7(21134) end of header reached, state=5 7(21134) parse_headers: Via found, flags=2 7(21134) parse_headers: this is the first via 7(21134) After parse_msg... 7(21134) preparing to run routing scripts... 7(21134) DEBUG : sl_filter_ACK: to late to be a local ACK! 7(21134) parse_headers: flags=100 7(21134) get_hdr_field: cseq : <1> 7(21134) DEBUG: get_hdr_body : content_length=0 7(21134) found end of header 7(21134) DEBUG: is_maxfwd_present: max_forwards header not found! 7(21134) DEBUG: add_param: tag=936ebe41 7(21134) DEBUG:parse_to:end of header reached, state=29 7(21134) parse_headers: flags=200 7(21134) find_first_route: No Route headers found 7(21134) loose_route: There is no Route HF 7(21134) DEBUG: t_newtran: msg id=17 , global msg id=16 , T on entrance=0xffffffff 7(21134) parse_headers: flags=ffffffffffffffff 7(21134) parse_headers: flags=78 7(21134) t_lookup_request: start searching: hash=44175, isACK=1 7(21134) DEBUG: RFC3261 transaction matched, tid=-d87543-499259966-1--d87543- 7(21134) DEBUG: t_lookup_request: transaction found (T=0xb60c7618) 7(21134) DEBUG: cleanup_uac_timers: RETR/FR timers reset 7(21134) DEBUG: add_to_tail_of_timer[2]: 0xb60c7660 7(21134) DEBUG:destroy_avp_list: destroying list (nil) 7(21134) receive_msg: cleaning up 9(21136) SIP Request: 9(21136) method: 9(21136) uri: 9(21136) version: 9(21136) parse_headers: flags=2 9(21136) DEBUG:parse_to:end of header reached, state=9 9(21136) DEBUG: get_hdr_field: [31]; uri=[sip:4321@OPENSER-SERVER] 9(21136) DEBUG: to body [ ] 9(21136) Found param type 232, = ; state=6 9(21136) Found param type 235, = ; state=17 9(21136) end of header reached, state=5 9(21136) parse_headers: Via found, flags=2 9(21136) parse_headers: this is the first via 9(21136) After parse_msg... 9(21136) preparing to run routing scripts... 9(21136) parse_headers: flags=100 9(21136) get_hdr_field: cseq : <2> 9(21136) DEBUG:maxfwd:is_maxfwd_present: value = 70 9(21136) parse_headers: flags=80 9(21136) DEBUG:rr:add_rr_param: rr_param_buf=<;nat=yes> 9(21136) DEBUG: add_param: tag=936ebe41 9(21136) DEBUG:parse_to:end of header reached, state=29 9(21136) parse_headers: flags=200 9(21136) DEBUG: get_hdr_body : content_length=268 9(21136) found end of header 9(21136) find_first_route: No Route headers found 9(21136) loose_route: There is no Route HF 9(21136) parse_headers: flags=80 9(21136) parse_headers: flags=80 9(21136) parse_headers: flags=ffffffffffffffff 9(21136) parse_headers: flags=4000000 9(21136) error: use_media_proxy(): empty response from mediaproxy 9(21136) DEBUG: t_newtran: msg id=21 , global msg id=20 , T on entrance=0xffffffff 9(21136) parse_headers: flags=ffffffffffffffff 9(21136) parse_headers: flags=78 9(21136) t_lookup_request: start searching: hash=44172, isACK=0 9(21136) DEBUG: RFC3261 transaction matching failed 9(21136) DEBUG: t_lookup_request: no transaction found 9(21136) DEBUG:tm:t_relay: new INVITE 9(21136) parse_headers: flags=ffffffffffffffff 9(21136) check_via_address(IP-FIREWALL, 10.32.9.225, 0) 9(21136) WARNING:vqm_resize: resize(0) called 9(21136) DEBUG:tm:_reply_light: reply sent out. buf=0x812e9d8: SIP/2.0 1..., shmem=0xb60ca190: SIP/2.0 1 9(21136) DEBUG:tm:_reply_light: finished 9(21136) DEBUG: mk_proxy: doing DNS lookup... 9(21136) check_via_address(IP-FIREWALL, 10.32.9.225, 0) 9(21136) DEBUG: add_to_tail_of_timer[4]: 0xb60c8f8c 9(21136) DEBUG: add_to_tail_of_timer[0]: 0xb60c8f9c 9(21136) SER: new transaction fwd'ed 9(21136) DEBUG:destroy_avp_list: destroying list (nil) 9(21136) receive_msg: cleaning up 7(21134) SIP Reply (status): 7(21134) version: 7(21134) status: <100> 7(21134) reason: 7(21134) parse_headers: flags=2 7(21134) Found param type 232, = ; state=6 7(21134) Found param type 234, = ; state=16 7(21134) end of header reached, state=5 7(21134) parse_headers: Via found, flags=2 7(21134) parse_headers: this is the first via 7(21134) After parse_msg... 7(21134) forward_reply: found module tm, passing reply to it 7(21134) DEBUG: t_check: msg id=18 global id=17 T start=0xffffffff 7(21134) parse_headers: flags=22 7(21134) Found param type 234, = ; state=6 7(21134) Found param type 232, = ; state=6 7(21134) Found param type 235, = <15963>; state=16 7(21134) end of header reached, state=5 7(21134) parse_headers: Via found, flags=22 7(21134) parse_headers: this is the second via 7(21134) DEBUG:parse_to:end of header reached, state=9 7(21134) DEBUG: get_hdr_field: [31]; uri=[sip:4321@OPENSER-SERVER] 7(21134) DEBUG: to body [ ] 7(21134) get_hdr_field: cseq : <2> 7(21134) parse_headers: flags=8 7(21134) DEBUG: t_reply_matching: hash 44172 label 600360520 branch 0 7(21134) DEBUG: t_reply_matching: reply matched (T=0xb60c8e70)! 7(21134) DEBUG: t_check: msg id=18 global id=18 T end=0xb60c8e70 7(21134) DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) 7(21134) parse_headers: flags=80 7(21134) DEBUG:tm:t_should_relay_response: T_code=100, new_code=100 7(21134) DEBUG:tm:relay_reply: branch=0, save=0, relay=-1 7(21134) DEBUG: add_to_tail_of_timer[1]: 0xb60c8f9c 7(21134) DEBUG:destroy_avp_list: destroying list (nil) 7(21134) receive_msg: cleaning up 9(21136) SIP Request: 9(21136) method: 9(21136) uri: 9(21136) version: 9(21136) parse_headers: flags=2 9(21136) Found param type 232, = ; state=6 9(21136) Found param type 235, = ; state=17 9(21136) end of header reached, state=5 9(21136) parse_headers: Via found, flags=2 9(21136) parse_headers: this is the first via 9(21136) After parse_msg... 9(21136) preparing to run routing scripts... 9(21136) parse_headers: flags=100 9(21136) DEBUG:parse_to:end of header reached, state=9 9(21136) DEBUG: get_hdr_field: [34]; uri=[sip:4321@10.11.128.11:5060] 9(21136) DEBUG: to body [ ] 9(21136) get_hdr_field: cseq : <102> 9(21136) DEBUG:maxfwd:is_maxfwd_present: value = 70 9(21136) parse_headers: flags=80 9(21136) check_via_address(ASTERISK-SERVER, ASTERISK-SERVER, 0) 9(21136) parse_headers: flags=4000000 9(21136) DEBUG: add_param: tag=as2e7cfd85 9(21136) DEBUG:parse_to:end of header reached, state=29 9(21136) parse_headers: flags=200 9(21136) DEBUG: get_hdr_body : content_length=163 9(21136) found end of header 9(21136) find_first_route: No Route headers found 9(21136) loose_route: There is no Route HF 9(21136) parse_headers: flags=80 9(21136) check_via_address(ASTERISK-SERVER, ASTERISK-SERVER, 0) 9(21136) parse_headers: flags=4000000 9(21136) DEBUG: t_newtran: msg id=22 , global msg id=21 , T on entrance=0xffffffff 9(21136) parse_headers: flags=ffffffffffffffff 9(21136) parse_headers: flags=78 9(21136) t_lookup_request: start searching: hash=47904, isACK=0 9(21136) DEBUG: RFC3261 transaction matching failed 9(21136) DEBUG: t_lookup_request: no transaction found 9(21136) ERROR: parse_uri: bad port in uri (error at char : in state 8) parsed: (33) / (38) 9(21136) ERROR: parse_sip_msg_uri: bad uri 9(21136) ERROR: new_t: uri invalid 9(21136) ERROR: t_newtran: new_t failed 9(21136) parse_headers: flags=ffffffffffffffff 9(21136) check_via_address(ASTERISK-SERVER, ASTERISK-SERVER, 0) 9(21136) ERROR: sl_reply_error used: I'm terribly sorry, server error occurred (1/SL) 9(21136) DEBUG:destroy_avp_list: destroying list (nil) 9(21136) receive_msg: cleaning up 8(21135) SIP Request: 8(21135) method: 8(21135) uri: 8(21135) version: 8(21135) parse_headers: flags=2 8(21135) Found param type 232, = ; state=6 8(21135) Found param type 235, = ; state=17 8(21135) end of header reached, state=5 8(21135) parse_headers: Via found, flags=2 8(21135) parse_headers: this is the first via 8(21135) After parse_msg... 8(21135) preparing to run routing scripts... 8(21135) parse_headers: flags=8 8(21135) DEBUG: add_param: tag=329cfeaa6ded039da25ff8cbb8668bd2.1799 8(21135) DEBUG:parse_to:end of header reached, state=29 8(21135) DEBUG: get_hdr_field: [76]; uri=[sip:4321@10.11.128.11:5060] 8(21135) DEBUG: to body [] 8(21135) DEBUG: sl_filter_ACK : local ACK found -> dropping it! 8(21135) DEBUG:destroy_avp_list: destroying list (nil) 8(21135) receive_msg: cleaning up 7(21134) SIP Reply (status): 7(21134) version: 7(21134) status: <500> 7(21134) reason: 7(21134) parse_headers: flags=2 7(21134) Found param type 232, = ; state=6 7(21134) Found param type 234, = ; state=16 7(21134) end of header reached, state=5 7(21134) parse_headers: Via found, flags=2 7(21134) parse_headers: this is the first via 7(21134) After parse_msg... 7(21134) forward_reply: found module tm, passing reply to it 7(21134) DEBUG: t_check: msg id=19 global id=18 T start=0xffffffff 7(21134) parse_headers: flags=22 7(21134) Found param type 234, = ; state=6 7(21134) Found param type 232, = ; state=6 7(21134) Found param type 235, = <15963>; state=16 7(21134) end of header reached, state=5 7(21134) parse_headers: Via found, flags=22 7(21134) parse_headers: this is the second via 7(21134) DEBUG: add_param: tag=as32318925 7(21134) DEBUG:parse_to:end of header reached, state=29 7(21134) DEBUG: get_hdr_field: [46]; uri=[sip:4321@OPENSER-SERVER] 7(21134) DEBUG: to body [] 7(21134) get_hdr_field: cseq : <2> 7(21134) parse_headers: flags=8 7(21134) DEBUG: t_reply_matching: hash 44172 label 600360520 branch 0 7(21134) DEBUG: t_reply_matching: reply matched (T=0xb60c8e70)! 7(21134) DEBUG: t_check: msg id=19 global id=19 T end=0xb60c8e70 7(21134) DEBUG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) 7(21134) parse_headers: flags=8 7(21134) DEBUG:tm:build_local: using FROM=;tag=936ebe41 >, TO=;tag=as32318925 >, CSEQ_N= 7(21134) parse_headers: flags=80 7(21134) DEBUG:tm:t_should_relay_response: T_code=100, new_code=500 7(21134) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 7(21134) old size: 543, new size: 456 7(21134) build_res_from_sip_res: copied size: orig:124, new: 37, rest: 419 msg= SIP/2.0 500 Server internal failure Via: SIP/2.0/UDP 10.32.9.225:8042;received=IP-FIREWALL;branch=z9hG4bK-d87543-945638322-1--d87543-;rport=15963 From: fidias;tag=936ebe41 To: ;tag=as32318925 Call-ID: 872d797c9d234d02 CSeq: 2 INVITE User-Agent: Planeta LAB1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 7(21134) DEBUG: add_to_tail_of_timer[4]: 0xb60c8f20 7(21134) DEBUG: add_to_tail_of_timer[0]: 0xb60c8f30 7(21134) DEBUG:tm:relay_reply: sent buf=0x812ece0: SIP/2.0 5..., shmem=0xb60ca480: SIP/2.0 5 7(21134) DEBUG: cleanup_uac_timers: RETR/FR timers reset 7(21134) DEBUG:destroy_avp_list: destroying list (nil) 7(21134) receive_msg: cleaning up 8(21135) SIP Request: 8(21135) method: 8(21135) uri: 8(21135) version: 8(21135) parse_headers: flags=2 8(21135) DEBUG: add_param: tag=as32318925 8(21135) DEBUG:parse_to:end of header reached, state=29 8(21135) DEBUG: get_hdr_field: [46]; uri=[sip:4321@OPENSER-SERVER] 8(21135) DEBUG: to body [] 8(21135) Found param type 232, = ; state=6 8(21135) Found param type 235, = ; state=17 8(21135) end of header reached, state=5 8(21135) parse_headers: Via found, flags=2 8(21135) parse_headers: this is the first via 8(21135) After parse_msg... 8(21135) preparing to run routing scripts... 8(21135) parse_headers: flags=8 8(21135) parse_headers: flags=100 8(21135) get_hdr_field: cseq : <2> 8(21135) DEBUG: get_hdr_body : content_length=0 8(21135) found end of header 8(21135) DEBUG: is_maxfwd_present: max_forwards header not found! 8(21135) DEBUG: add_param: tag=936ebe41 8(21135) DEBUG:parse_to:end of header reached, state=29 8(21135) parse_headers: flags=200 8(21135) find_first_route: No Route headers found 8(21135) loose_route: There is no Route HF 8(21135) DEBUG: t_newtran: msg id=19 , global msg id=17 , T on entrance=0xffffffff 8(21135) parse_headers: flags=ffffffffffffffff 8(21135) parse_headers: flags=78 8(21135) t_lookup_request: start searching: hash=44172, isACK=1 8(21135) DEBUG: RFC3261 transaction matched, tid=-d87543-945638322-1--d87543- 8(21135) DEBUG: t_lookup_request: transaction found (T=0xb60c8e70) 8(21135) DEBUG: cleanup_uac_timers: RETR/FR timers reset 8(21135) DEBUG: add_to_tail_of_timer[2]: 0xb60c8eb8 8(21135) DEBUG:destroy_avp_list: destroying list (nil) 8(21135) receive_msg: cleaning up 10(21137) DEBUG: timer routine:0,tl=0xb60c8f30 next=0xb60c76d8 10(21137) DEBUG: timer routine:0,tl=0xb60c76d8 next=0xb60c7744 10(21137) DEBUG: timer routine:0,tl=0xb60c7744 next=(nil) 10(21137) DEBUG: timer routine:1,tl=0xb60c8f9c next=(nil) 10(21137) DEBUG: timer routine:4,tl=0xb60c8f20 next=0xb60c8f8c 10(21137) DEBUG: timer routine:4,tl=0xb60c8f8c next=0xb60c76c8 10(21137) DEBUG: timer routine:4,tl=0xb60c76c8 next=0xb60c7734 10(21137) DEBUG: timer routine:4,tl=0xb60c7734 next=(nil) 10(21137) DEBUG: timer routine:2,tl=0xb60c7660 next=0xb60c8eb8 10(21137) DEBUG: wait_handler : removing 0xb60c7618 from table 10(21137) DEBUG: delete transaction 0xb60c7618 10(21137) DEBUG: wait_handler : done 10(21137) DEBUG: timer routine:2,tl=0xb60c8eb8 next=(nil) 10(21137) DEBUG: wait_handler : removing 0xb60c8e70 from table 10(21137) DEBUG: delete transaction 0xb60c8e70 10(21137) DEBUG: wait_handler : done 7(21134) udp_rcv_loop: probing packet received from IP-FIREWALL 23358 9(21136) udp_rcv_loop: probing packet received from IP-FIREWALL 34110