U 172.19.172.176:6282 -> 172.19.172.101:5070
  INVITE sip:85218852323@172.19.172.101:5070 SIP/2.0..Via: SIP/2.0/UDP 172.19.172.176:6282;bra
  nch=z9hG4bK-d87543-b83e88433e70eb69-1--d87543-;rport..Max-Forwards: 70..Contact: <sip:1234@
  172.19.172.176:6282>..To: "85218852323"<sip:85218852323@172.19.172.101:5070>..From: "laobai"<
  sip:1234@172.19.172.101:5070>;tag=027d4704..Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYj
  g0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 INVITE..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NO
  TIFY, MESSAGE, SUBSCRIBE, INFO..Content-Type: application/sdp..User-Agent: eyeBeam release
  1003s stamp 31159..Content-Length: 375....v=0..o=- 0 2 IN IP4 172.19.172.176..s=CounterPath
   eyeBeam 1.5..c=IN IP4 172.19.172.176..t=0 0..m=audio 44828 RTP/AVP 100 0 98 18 3 101..a=al
  t:1 1 : rzpPedV3 flhxO9/B 172.19.172.176 44828..a=fmtp:18 annexb=no..a=fmtp:101 0-15..a=rtp
  map:100 SPEEX/16000..a=rtpmap:98 iLBC/8000..a=rtpmap:101 telephone-event/8000..a=sendrecv..
  a=x-rtp-session-id:DE04D24180A140628EF78DF90BD0E5BB..
Mar 26 00:39:44 [5951] DBG:core:parse_msg: SIP Request:
Mar 26 00:39:44 [5951] DBG:core:parse_msg:  method:  <INVITE>
Mar 26 00:39:44 [5951] DBG:core:parse_msg:  uri:     <sip:85218852323@172.19.172.101:5070>
Mar 26 00:39:44 [5951] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=2
Mar 26 00:39:44 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-b83e88433e70eb69-1--d87543->; state=6
Mar 26 00:39:44 [5951] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Mar 26 00:39:44 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:44 [5951] DBG:core:parse_headers: via found, flags=2
Mar 26 00:39:44 [5951] DBG:core:parse_headers: this is the first via
Mar 26 00:39:44 [5951] DBG:core:receive_msg: After parse_msg...
Mar 26 00:39:44 [5951] DBG:core:receive_msg: preparing to run routing scripts...
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=100
Mar 26 00:39:44 [5951] DBG:maxfwd:is_maxfwd_present: value = 70
Method: INVITE
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=10
Mar 26 00:39:44 [5951] DBG:core:parse_to: end of header reached, state=10
Mar 26 00:39:44 [5951] DBG:core:parse_to: display={"85218852323"}, ruri={sip:85218852323@172.19.172.101:5070}
Mar 26 00:39:44 [5951] DBG:core:get_hdr_field: <To> [50]; uri=[sip:85218852323@172.19.172.101:5070]
Mar 26 00:39:44 [5951] DBG:core:get_hdr_field: to body ["85218852323"<sip:85218852323@172.19.172.101:5070>
]
Mar 26 00:39:44 [5951] DBG:core:parse_to_param: tag=027d4704
Mar 26 00:39:44 [5951] DBG:core:parse_to: end of header reached, state=29
Mar 26 00:39:44 [5951] DBG:core:parse_to: display={"laobai"}, ruri={sip:1234@172.19.172.101:5070}
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=200
Mar 26 00:39:44 [5951] DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
Mar 26 00:39:44 [5951] DBG:core:get_hdr_field: content_length=375
Mar 26 00:39:44 [5951] DBG:core:get_hdr_field: found end of header
Mar 26 00:39:44 [5951] DBG:rr:find_first_route: No Route headers found
Mar 26 00:39:44 [5951] DBG:rr:loose_route: There is no Route HF
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [172.19.172.101] == [127.0.0.1]
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [172.19.172.101] == [172.19.172.101]
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:44 [5951] DBG:registrar:lookup: '85218852323' Not found in usrloc
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [172.19.172.101] == [127.0.0.1]
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [172.19.172.101] == [172.19.172.101]
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [172.19.172.101] == [127.0.0.1]
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [172.19.172.101] == [172.19.172.101]
Mar 26 00:39:44 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 26 00:39:44 [5951] DBG:core:run_transformations: return val is 0
Mar 26 00:39:44 [5951] DBG:avpops:ops_op_avp:  use <30> and <2>
Mar 26 00:39:44 [5951] DBG:avpops:ops_op_avp: done
tr_eval_string: i=1 j=28
Mar 26 00:39:44 [5951] DBG:core:run_transformations: return val is 0
Mar 26 00:39:44 [5951] DBG:core:run_transformations: return val is 0
requested for cli: INVITE
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=78
Mar 26 00:39:44 [5951] DBG:core:MDStringArray: MD5 calculated: 79441acdcd6d0baf5fc8f3d656800a36
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_CONTENT_LENGTH=375
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_USER_AGENT=eyeBeam release 1003s stamp 31159
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_CONTENT_TYPE=application/sdp
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_ALLOW=INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_CSEQ=1 INVITE
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_CALLID=4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY.
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_FROM="laobai"<sip:1234@172.19.172.101:5070>;tag=027d4704
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_TO="85218852323"<sip:85218852323@172.19.172.101:5070>
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_CONTACT=<sip:1234@172.19.172.176:6282>
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_MAX_FORWARDS=69
Mar 26 00:39:44 [5951] DBG:exec:print_hf_var: SIP_HF_VIA=SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88433e70eb69-1--d87543-;rport
Mar 26 00:39:44 [5951] DBG:exec:w_exec_avp: executing [/home/baishi/proj/teliwave/cli/twcli '172.19.172.176' '4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY.']
Mar 26 00:39:44 [5951] DBG:core:sig_usr: SIGCHLD received: we do not worry about grand-children
172.19.172.176 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY. 172.19.172.101
newcli: 852133143235
Mar 26 00:39:44 [5951] DBG:core:run_transformations: return val is 0
Mar 26 00:39:44 [5951] DBG:uac:replace_from: removing display ["laobai"]
Mar 26 00:39:44 [5951] DBG:uac:replace_from: uri to replace [sip:1234@172.19.172.101:5070]
Mar 26 00:39:44 [5951] DBG:uac:replace_from: replacement uri is [sip:852133143235@172.19.172.101:5070]
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 26 00:39:44 [5951] DBG:core:run_transformations: return val is 0
Mar 26 00:39:44 [5951] DBG:core:run_transformations: return val is 0
INVITE
route 1 reached
Mar 26 00:39:44 [5951] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=78
Mar 26 00:39:44 [5951] DBG:tm:t_lookup_request: start searching: hash=55260, isACK=0
Mar 26 00:39:44 [5951] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 26 00:39:44 [5951] DBG:tm:t_lookup_request: no transaction found
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 26 00:39:44 [5951] DBG:core:check_via_address: params 172.19.172.176, 172.19.172.176, 0
Mar 26 00:39:44 [5951] DBG:core:_shm_resize: resize(0) called
Mar 26 00:39:44 [5951] DBG:tm:_reply_light: reply sent out. buf=0x818a158: SIP/2.0 1..., shmem=0xb5e8a178: SIP/2.0 1
Mar 26 00:39:44 [5951] DBG:tm:_reply_light: finished
Mar 26 00:39:44 [5951] DBG:core:mk_proxy: doing DNS lookup...
Mar 26 00:39:44 [5951] DBG:core:check_via_address: params 172.19.172.176, 172.19.172.176, 0
#
U 172.19.172.101:5070 -> 172.19.172.176:6282
  SIP/2.0 100 Giving a try..Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88
  433e70eb69-1--d87543-;rport=6282..To: "85218852323"<sip:85218852323@172.19.172.101:5070>..Fro
  m: "laobai"<sip:1234@172.19.172.101:5070>;tag=027d4704..Call-ID: 4f7a5e16a762614eYmQxNjQ4ND
  A1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 INVITE..Server: OpenSER (1.3.1-notls (i386/linu
  x))..Content-Length: 0....
#
U 172.19.172.101:5070 -> gatewayip:5060
  INVITE sip:85218852323@gatewayip:5060 SIP/2.0..Record-Route: <sip:172.19.172.101:5070;lr
  =on;ftag=027d4704>..Via: SIP/2.0/UDP 172.19.172.101:5070;branch=z9hG4bKcd7d.54768e85.0..Via
  : SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88433e70eb69-1--d87543-;rport=6
  282..Max-Forwards: 69..To: "85218852323"<sip:85218852323@172.19.172.101:5070>..From: "8521331
  43235"<sip:852133143235@172.19.172.101:5070>;tag=027d4704..Call-ID: 4f7a5e16a762614eYmQxNjQ
  4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...Contact: <sip:852133143235@172.19.172.176:6282>..CSe
  q: 1 INVITE..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, I
  NFO..Content-Type: application/sdp..User-Agent: eyeBeam release 1003s stamp 31159..Content-
  Length: 375....v=0..o=- 0 2 IN IP4 172.19.172.176..s=CounterPath eyeBeam 1.5..c=IN IP4 172.
  19.172.176..t=0 0..m=audio 44828 RTP/AVP 100 0 98 18 3 101..a=alt:1 1 : rzpPedV3 flhxO9/B 1
  72.19.172.176 44828..a=fmtp:18 annexb=no..a=fmtp:101 0-15..a=rtpmap:100 SPEEX/16000..a=rtpm
  ap:98 iLBC/8000..a=rtpmap:101 telephone-event/8000..a=sendrecv..a=x-rtp-session-id:DE04D241
  80A140628EF78DF90BD0E5BB..
Mar 26 00:39:44 [5951] DBG:tm:set_timer: relative timeout is 500000
Mar 26 00:39:44 [5951] DBG:tm:insert_timer_unsafe: [4]: 0xb5e8855c (10200000)
Mar 26 00:39:44 [5951] DBG:tm:set_timer: relative timeout is 30
Mar 26 00:39:44 [5951] DBG:tm:insert_timer_unsafe: [0]: 0xb5e88578 (39)
Mar 26 00:39:44 [5951] DBG:tm:t_relay_to: new transaction fwd'ed
Mar 26 00:39:44 [5951] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 26 00:39:44 [5951] DBG:core:destroy_avp_list: destroying list (nil)
Mar 26 00:39:44 [5951] DBG:core:receive_msg: cleaning up
#
U gatewayip:5060 -> 172.19.172.101:5070
  SIP/2.0 100 Trying..Via: SIP/2.0/UDP 172.19.172.101:5070;branch=z9hG4bKcd7d.54768e85.0;rece
  ived=172.19.172.101..Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88433e7
  0eb69-1--d87543-;rport=6282..Record-Route: <sip:172.19.172.101:5070;lr=on;ftag=027d4704>..F
  rom: "852133143235"<sip:852133143235@172.19.172.101:5070>;tag=027d4704..To: "85218852323"<si
  p:85218852323@172.19.172.101:5070>..Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjE
  zNjY2NWU5MGY...CSeq: 1 INVITE..User-Agent: Asterisk PBX..Allow: INVITE, ACK, CANCEL, OPTION
  S, BYE, REFER, SUBSCRIBE, NOTIFY..Supported: replaces..Contact: <sip:85218852323@203.125.27.
  84>..Content-Length: 0....
Mar 26 00:39:44 [5951] DBG:core:parse_msg: SIP Reply  (status):
Mar 26 00:39:44 [5951] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 26 00:39:44 [5951] DBG:core:parse_msg:  status:  <100>
Mar 26 00:39:44 [5951] DBG:core:parse_msg:  reason:  <Trying>
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=2
Mar 26 00:39:44 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKcd7d.54768e85.0>; state=6
Mar 26 00:39:44 [5951] DBG:core:parse_via_param: found param type 234, <received> = <172.19.172.101>; state=16
Mar 26 00:39:44 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:44 [5951] DBG:core:parse_headers: via found, flags=2
Mar 26 00:39:44 [5951] DBG:core:parse_headers: this is the first via
Mar 26 00:39:44 [5951] DBG:core:receive_msg: After parse_msg...
Mar 26 00:39:44 [5951] DBG:core:forward_reply: found module tm, passing reply to it
Mar 26 00:39:44 [5951] DBG:tm:t_check: start=0xffffffff
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=22
Mar 26 00:39:44 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-b83e88433e70eb69-1--d87543->; state=6
Mar 26 00:39:44 [5951] DBG:core:parse_via_param: found param type 235, <rport> = <6282>; state=16
Mar 26 00:39:44 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:44 [5951] DBG:core:parse_headers: via found, flags=22
Mar 26 00:39:44 [5951] DBG:core:parse_headers: parse_headers: this is the second via
Mar 26 00:39:44 [5951] DBG:core:parse_to: end of header reached, state=10
Mar 26 00:39:44 [5951] DBG:core:parse_to: display={"85218852323"}, ruri={sip:85218852323@172.19.172.101:5070}
Mar 26 00:39:44 [5951] DBG:core:get_hdr_field: <To> [50]; uri=[sip:85218852323@172.19.172.101:5070]
Mar 26 00:39:44 [5951] DBG:core:get_hdr_field: to body ["85218852323"<sip:85218852323@172.19.172.101:5070>
]
Mar 26 00:39:44 [5951] DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
Mar 26 00:39:44 [5951] DBG:core:parse_headers: flags=8
Mar 26 00:39:44 [5951] DBG:tm:t_reply_matching: hash 55260 label 1491625797 branch 0
Mar 26 00:39:44 [5951] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 26 00:39:44 [5951] DBG:tm:t_reply_matching: reply matched (T=0xb5e88410)!
Mar 26 00:39:44 [5951] DBG:tm:t_check: end=0xb5e88410
Mar 26 00:39:44 [5951] DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Mar 26 00:39:44 [5951] DBG:tm:t_check_status: checked status is <100>
Mar 26 00:39:44 [5951] DBG:tm:t_should_relay_response: T_code=100, new_code=100
Mar 26 00:39:44 [5951] DBG:tm:relay_reply: branch=0, save=0, relay=-1
Mar 26 00:39:44 [5951] DBG:tm:set_timer: relative timeout is 120
Mar 26 00:39:44 [5951] DBG:tm:insert_timer_unsafe: [1]: 0xb5e88578 (129)
Mar 26 00:39:44 [5951] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 26 00:39:44 [5951] DBG:core:destroy_avp_list: destroying list (nil)
Mar 26 00:39:44 [5951] DBG:core:receive_msg: cleaning up
#
U gatewayip:5060 -> 172.19.172.101:5070
  SIP/2.0 183 Session Progress..Via: SIP/2.0/UDP 172.19.172.101:5070;branch=z9hG4bKcd7d.54768
  e85.0;received=172.19.172.101..Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b
  83e88433e70eb69-1--d87543-;rport=6282..Record-Route: <sip:172.19.172.101:5070;lr=on;ftag=02
  7d4704>..From: "852133143235"<sip:852133143235@172.19.172.101:5070>;tag=027d4704..To: "6581
  685963"<sip:85218852323@172.19.172.101:5070>;tag=as01c9920d..Call-ID: 4f7a5e16a762614eYmQxNj
  Q4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 INVITE..User-Agent: Asterisk PBX..Allow: IN
  VITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY..Supported: replaces..Contact: <s
  ip:85218852323@gatewayip>..Content-Type: application/sdp..Content-Length: 289....v=0..o=
  root 10059 10059 IN IP4 gatewayip..s=session..c=IN IP4 gatewayip..t=0 0..m=audio 10
  518 RTP/AVP 18 0 101..a=rtpmap:18 G729/8000..a=fmtp:18 annexb=no..a=rtpmap:0 PCMU/8000..a=r
  tpmap:101 telephone-event/8000..a=fmtp:101 0-16..a=silenceSupp:off - - - -..a=ptime:20..a=s
  endrecv..
Mar 26 00:39:45 [5951] DBG:core:parse_msg: SIP Reply  (status):
Mar 26 00:39:45 [5951] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 26 00:39:45 [5951] DBG:core:parse_msg:  status:  <183>
Mar 26 00:39:45 [5951] DBG:core:parse_msg:  reason:  <Session Progress>
Mar 26 00:39:45 [5951] DBG:core:parse_headers: flags=2
Mar 26 00:39:45 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKcd7d.54768e85.0>; state=6
Mar 26 00:39:45 [5951] DBG:core:parse_via_param: found param type 234, <received> = <172.19.172.101>; state=16
Mar 26 00:39:45 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:45 [5951] DBG:core:parse_headers: via found, flags=2
Mar 26 00:39:45 [5951] DBG:core:parse_headers: this is the first via
Mar 26 00:39:45 [5951] DBG:core:receive_msg: After parse_msg...
Mar 26 00:39:45 [5951] DBG:core:forward_reply: found module tm, passing reply to it
Mar 26 00:39:45 [5951] DBG:tm:t_check: start=0xffffffff
Mar 26 00:39:45 [5951] DBG:core:parse_headers: flags=22
Mar 26 00:39:45 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-b83e88433e70eb69-1--d87543->; state=6
Mar 26 00:39:45 [5951] DBG:core:parse_via_param: found param type 235, <rport> = <6282>; state=16
Mar 26 00:39:45 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:45 [5951] DBG:core:parse_headers: via found, flags=22
Mar 26 00:39:45 [5951] DBG:core:parse_headers: parse_headers: this is the second via
Mar 26 00:39:45 [5951] DBG:core:parse_to_param: tag=as01c9920d
Mar 26 00:39:45 [5951] DBG:core:parse_to: end of header reached, state=29
Mar 26 00:39:45 [5951] DBG:core:parse_to: display={"85218852323"}, ruri={sip:85218852323@172.19.172.101:5070}
Mar 26 00:39:45 [5951] DBG:core:get_hdr_field: <To> [65]; uri=[sip:85218852323@172.19.172.101:5070]
Mar 26 00:39:45 [5951] DBG:core:get_hdr_field: to body ["85218852323"<sip:85218852323@172.19.172.101:5070>]
Mar 26 00:39:45 [5951] DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
Mar 26 00:39:45 [5951] DBG:core:parse_headers: flags=8
Mar 26 00:39:45 [5951] DBG:tm:t_reply_matching: hash 55260 label 1491625797 branch 0
Mar 26 00:39:45 [5951] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 26 00:39:45 [5951] DBG:tm:t_reply_matching: reply matched (T=0xb5e88410)!
Mar 26 00:39:45 [5951] DBG:tm:t_check: end=0xb5e88410
Mar 26 00:39:45 [5951] DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
Mar 26 00:39:45 [5951] DBG:tm:t_check_status: checked status is <183>
Mar 26 00:39:45 [5951] DBG:tm:t_should_relay_response: T_code=100, new_code=183
Mar 26 00:39:45 [5951] DBG:tm:relay_reply: branch=0, save=0, relay=0
Mar 26 00:39:45 [5951] DBG:core:build_res_buf_from_sip_res:  old size: 1010, new size: 918
Mar 26 00:39:45 [5951] DBG:core:build_res_buf_from_sip_res: copied size: orig:122, new: 30, rest: 888 msg=
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88433e70eb69-1--d87543-;rport=6282
Record-Route: <sip:172.19.172.101:5070;lr=on;ftag=027d4704>
From: "852133143235"<sip:852133143235@172.19.172.101:5070>;tag=027d4704
To: "85218852323"<sip:85218852323@172.19.172.101:5070>;tag=as01c9920d
Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY.
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:85218852323@gatewayip>
Content-Type: application/sdp
Content-Length: 289

v=0
o=root 10059 10059 IN IP4 gatewayip
s=session
c=IN IP4 gatewayip
t=0 0
m=audio 10518 RTP/AVP 18 0 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

Mar 26 00:39:45 [5951] DBG:tm:relay_reply: sent buf=0x818a2e8: SIP/2.0 1..., shmem=0xb5e8a860: SIP/2.0 1
Mar 26 00:39:45 [5951] DBG:tm:set_timer: relative timeout is 120
#
U 172.19.172.101:5070 -> 172.19.172.176:6282
  SIP/2.0 183 Session Progress..Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b8
  3e88433e70eb69-1--d87543-;rport=6282..Record-Route: <sip:172.19.172.101:5070;lr=on;ftag=027
  d4704>..From: "852133143235"<sip:852133143235@172.19.172.101:5070>;tag=027d4704..To: "65816
  85963"<sip:85218852323@172.19.172.101:5070>;tag=as01c9920d..Call-ID: 4f7a5e16a762614eYmQxNjQ
  4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 INVITE..User-Agent: Asterisk PBX..Allow: INV
  ITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY..Supported: replaces..Contact: <si
  p:85218852323@gatewayip>..Content-Type: application/sdp..Content-Length: 289....v=0..o=r
  oot 10059 10059 IN IP4 gatewayip..s=session..c=IN IP4 gatewayip..t=0 0..m=audio 105
  18 RTP/AVP 18 0 101..a=rtpmap:18 G729/8000..a=fmtp:18 annexb=no..a=rtpmap:0 PCMU/8000..a=rt
  pmap:101 telephone-event/8000..a=fmtp:101 0-16..a=silenceSupp:off - - - -..a=ptime:20..a=se
  ndrecv..
Mar 26 00:39:45 [5951] DBG:tm:insert_timer_unsafe: [1]: 0xb5e88578 (129)
Mar 26 00:39:45 [5951] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 26 00:39:45 [5951] DBG:core:destroy_avp_list: destroying list (nil)
Mar 26 00:39:45 [5951] DBG:core:receive_msg: cleaning up
Mar 26 00:39:45 [5952] DBG:tm:utimer_routine: timer routine:4,tl=0xb5e8855c next=(nil), timeout=10200000
#
U gatewayip:5060 -> 172.19.172.101:5070
  SIP/2.0 180 Ringing..Via: SIP/2.0/UDP 172.19.172.101:5070;branch=z9hG4bKcd7d.54768e85.0;rec
  eived=172.19.172.101..Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88433e
  70eb69-1--d87543-;rport=6282..Record-Route: <sip:172.19.172.101:5070;lr=on;ftag=027d4704>..
  From: "852133143235"<sip:852133143235@172.19.172.101:5070>;tag=027d4704..To: "85218852323"<s
  ip:85218852323@172.19.172.101:5070>;tag=as01c9920d..Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU
  1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 INVITE..User-Agent: Asterisk PBX..Allow: INVITE, ACK
  , CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY..Supported: replaces..Contact: <sip:658168
  5963@gatewayip>..Content-Length: 0....
Mar 26 00:39:49 [5951] DBG:core:parse_msg: SIP Reply  (status):
Mar 26 00:39:49 [5951] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 26 00:39:49 [5951] DBG:core:parse_msg:  status:  <180>
Mar 26 00:39:49 [5951] DBG:core:parse_msg:  reason:  <Ringing>
Mar 26 00:39:49 [5951] DBG:core:parse_headers: flags=2
Mar 26 00:39:49 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKcd7d.54768e85.0>; state=6
Mar 26 00:39:49 [5951] DBG:core:parse_via_param: found param type 234, <received> = <172.19.172.101>; state=16
Mar 26 00:39:49 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:49 [5951] DBG:core:parse_headers: via found, flags=2
Mar 26 00:39:49 [5951] DBG:core:parse_headers: this is the first via
Mar 26 00:39:49 [5951] DBG:core:receive_msg: After parse_msg...
Mar 26 00:39:49 [5951] DBG:core:forward_reply: found module tm, passing reply to it
Mar 26 00:39:49 [5951] DBG:tm:t_check: start=0xffffffff
Mar 26 00:39:49 [5951] DBG:core:parse_headers: flags=22
Mar 26 00:39:49 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-b83e88433e70eb69-1--d87543->; state=6
Mar 26 00:39:49 [5951] DBG:core:parse_via_param: found param type 235, <rport> = <6282>; state=16
Mar 26 00:39:49 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:49 [5951] DBG:core:parse_headers: via found, flags=22
Mar 26 00:39:49 [5951] DBG:core:parse_headers: parse_headers: this is the second via
Mar 26 00:39:49 [5951] DBG:core:parse_to_param: tag=as01c9920d
Mar 26 00:39:49 [5951] DBG:core:parse_to: end of header reached, state=29
Mar 26 00:39:49 [5951] DBG:core:parse_to: display={"85218852323"}, ruri={sip:85218852323@172.19.172.101:5070}
Mar 26 00:39:49 [5951] DBG:core:get_hdr_field: <To> [65]; uri=[sip:85218852323@172.19.172.101:5070]
Mar 26 00:39:49 [5951] DBG:core:get_hdr_field: to body ["85218852323"<sip:85218852323@172.19.172.101:5070>]
Mar 26 00:39:49 [5951] DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
Mar 26 00:39:49 [5951] DBG:core:parse_headers: flags=8
Mar 26 00:39:49 [5951] DBG:tm:t_reply_matching: hash 55260 label 1491625797 branch 0
Mar 26 00:39:49 [5951] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 26 00:39:49 [5951] DBG:tm:t_reply_matching: reply matched (T=0xb5e88410)!
Mar 26 00:39:49 [5951] DBG:tm:t_check: end=0xb5e88410
Mar 26 00:39:49 [5951] DBG:tm:reply_received: org. status uas=183, uac[0]=183 local=0 is_invite=1)
Mar 26 00:39:49 [5951] DBG:tm:t_check_status: checked status is <180>
Mar 26 00:39:49 [5951] DBG:tm:t_should_relay_response: T_code=183, new_code=180
Mar 26 00:39:49 [5951] DBG:tm:relay_reply: branch=0, save=0, relay=0
Mar 26 00:39:49 [5951] DBG:core:build_res_buf_from_sip_res:  old size: 679, new size: 587
Mar 26 00:39:49 [5951] DBG:core:build_res_buf_from_sip_res: copied size: orig:113, new: 21, rest: 566 msg=
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88433e70eb69-1--d87543-;rport=6282
Record-Route: <sip:172.19.172.101:5070;lr=on;ftag=027d4704>
From: "852133143235"<sip:852133143235@172.19.172.101:5070>;tag=027d4704
To: "85218852323"<sip:85218852323@172.19.172.101:5070>;tag=as01c9920d
Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY.
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:85218852323@gatewayip>
Content-Length: 0


Mar 26 00:39:49 [5951] DBG:tm:relay_reply: sent buf=0x818a2e8: SIP/2.0 1..., shmem=0xb5e8a860: SIP/2.0 1
Mar 26 00:39:49 [5951] DBG:tm:set_timer: relative timeout is 120
Mar 26 00:39:49 [5951] DBG:tm:insert_timer_unsafe: [1]: 0xb5e88578 (134)
Mar 26 00:39:49 [5951] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 26 00:39:49 [5951] DBG:core:destroy_avp_list: destroying list (nil)
Mar 26 00:39:49 [5951] DBG:core:receive_msg: cleaning up
#
U 172.19.172.101:5070 -> 172.19.172.176:6282
  SIP/2.0 180 Ringing..Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88433e7
  0eb69-1--d87543-;rport=6282..Record-Route: <sip:172.19.172.101:5070;lr=on;ftag=027d4704>..F
  rom: "852133143235"<sip:852133143235@172.19.172.101:5070>;tag=027d4704..To: "85218852323"<si
  p:85218852323@172.19.172.101:5070>;tag=as01c9920d..Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1
  ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 INVITE..User-Agent: Asterisk PBX..Allow: INVITE, ACK,
   CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY..Supported: replaces..Contact: <sip:6581685
  963@gatewayip>..Content-Length: 0....
#
U 172.19.172.176:6282 -> 172.19.172.101:5070
  CANCEL sip:85218852323@172.19.172.101:5070 SIP/2.0..Via: SIP/2.0/UDP 172.19.172.176:6282;bra
  nch=z9hG4bK-d87543-b83e88433e70eb69-1--d87543-;rport..To: "85218852323"<sip:85218852323@172.1
  9.172.101:5070>..From: "laobai"<sip:1234@172.19.172.101:5070>;tag=027d4704..Call-ID: 4f7a5e
  16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 CANCEL..User-Agent: eyeBeam
   release 1003s stamp 31159..Content-Length: 0....
Mar 26 00:39:51 [5951] DBG:core:parse_msg: SIP Request:
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  method:  <CANCEL>
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  uri:     <sip:85218852323@172.19.172.101:5070>
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=2
Mar 26 00:39:51 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-b83e88433e70eb69-1--d87543->; state=6
Mar 26 00:39:51 [5951] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Mar 26 00:39:51 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:51 [5951] DBG:core:parse_headers: via found, flags=2
Mar 26 00:39:51 [5951] DBG:core:parse_headers: this is the first via
Mar 26 00:39:51 [5951] DBG:core:receive_msg: After parse_msg...
Mar 26 00:39:51 [5951] DBG:core:receive_msg: preparing to run routing scripts...
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=100
Mar 26 00:39:51 [5951] DBG:core:parse_to: end of header reached, state=10
Mar 26 00:39:51 [5951] DBG:core:parse_to: display={"85218852323"}, ruri={sip:85218852323@172.19.172.101:5070}
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: <To> [50]; uri=[sip:85218852323@172.19.172.101:5070]
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: to body ["85218852323"<sip:85218852323@172.19.172.101:5070>
]
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: cseq <CSeq>: <1> <CANCEL>
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: content_length=0
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: found end of header
Mar 26 00:39:51 [5951] DBG:maxfwd:is_maxfwd_present: max_forwards header not found!
Method: CANCEL
Mar 26 00:39:51 [5951] DBG:core:parse_to_param: tag=027d4704
Mar 26 00:39:51 [5951] DBG:core:parse_to: end of header reached, state=29
Mar 26 00:39:51 [5951] DBG:core:parse_to: display={"laobai"}, ruri={sip:1234@172.19.172.101:5070}
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=200
Mar 26 00:39:51 [5951] DBG:rr:find_first_route: No Route headers found
Mar 26 00:39:51 [5951] DBG:rr:loose_route: There is no Route HF
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [172.19.172.101] == [127.0.0.1]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [172.19.172.101] == [172.19.172.101]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:registrar:lookup: '85218852323' Not found in usrloc
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [172.19.172.101] == [127.0.0.1]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [172.19.172.101] == [172.19.172.101]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [172.19.172.101] == [127.0.0.1]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [172.19.172.101] == [172.19.172.101]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
NON-LOOSEROUTE CANCLE OR BYE
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=78
Mar 26 00:39:51 [5951] DBG:core:MDStringArray: MD5 calculated: 79441acdcd6d0baf5fc8f3d656800a36
Mar 26 00:39:51 [5951] DBG:exec:print_hf_var: SIP_HF_CONTENT_LENGTH=0
Mar 26 00:39:51 [5951] DBG:exec:print_hf_var: SIP_HF_USER_AGENT=eyeBeam release 1003s stamp 31159
Mar 26 00:39:51 [5951] DBG:exec:print_hf_var: SIP_HF_CSEQ=1 CANCEL
Mar 26 00:39:51 [5951] DBG:exec:print_hf_var: SIP_HF_CALLID=4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY.
Mar 26 00:39:51 [5951] DBG:exec:print_hf_var: SIP_HF_FROM="laobai"<sip:1234@172.19.172.101:5070>;tag=027d4704
Mar 26 00:39:51 [5951] DBG:exec:print_hf_var: SIP_HF_TO="85218852323"<sip:85218852323@172.19.172.101:5070>
Mar 26 00:39:51 [5951] DBG:exec:print_hf_var: SIP_HF_VIA=SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88433e70eb69-1--d87543-;rport
Mar 26 00:39:51 [5951] DBG:exec:w_exec_avp: executing [/home/baishi/proj/teliwave/cli/unlock '4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY.']
Mar 26 00:39:51 [5951] DBG:core:sig_usr: SIGCHLD received: we do not worry about grand-children
Mar 26 00:39:51 [5951] DBG:uac:replace_from: removing display ["laobai"]
Mar 26 00:39:51 [5951] DBG:uac:replace_from: uri to replace [sip:1234@172.19.172.101:5070]
Mar 26 00:39:51 [5951] DBG:uac:replace_from: replacement uri is [sip:852133143235@172.19.172.176]
CLI: 852133143235
CANCEL
route 1 reached
Mar 26 00:39:51 [5951] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=78
Mar 26 00:39:51 [5951] DBG:tm:t_lookup_request: start searching: hash=55260, isACK=0
Mar 26 00:39:51 [5951] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 26 00:39:51 [5951] DBG:tm:t_lookup_request: no transaction found
Mar 26 00:39:51 [5951] DBG:tm:t_lookupOriginalT: searching on hash entry 55260
Mar 26 00:39:51 [5951] DBG:tm:matching_3261: RFC3261 transaction matched, tid=-d87543-b83e88433e70eb69-1--d87543-
Mar 26 00:39:51 [5951] DBG:tm:t_lookupOriginalT: canceled transaction found (0xb5e88410)!
Mar 26 00:39:51 [5951] DBG:tm:t_lookupOriginalT: REF_UNSAFE: after is 1
Mar 26 00:39:51 [5951] DBG:tm:t_lookupOriginalT: t_lookupOriginalT completed
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 26 00:39:51 [5951] DBG:core:check_via_address: params 172.19.172.176, 172.19.172.176, 0
Mar 26 00:39:51 [5951] DBG:core:_shm_resize: resize(0) called
Mar 26 00:39:51 [5951] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 26 00:39:51 [5951] DBG:tm:insert_timer_unsafe: [2]: 0xb5e8ace8 (21)
Mar 26 00:39:51 [5951] DBG:tm:_reply_light: reply sent out. buf=0x818a2e8: SIP/2.0 2..., shmem=0xb5e8c6e0: SIP/2.0 2
Mar 26 00:39:51 [5951] DBG:tm:_reply_light: finished
Mar 26 00:39:51 [5951] DBG:tm:build_local: using FROM=<From: "laobai"<sip:1234@172.19.172.101:5070>;tag=027d4704
>, TO=<To: "85218852323"<sip:85218852323@172.19.172.101:5070>
>, CSEQ_N=<CSeq: 1>
Mar 26 00:39:51 [5951] DBG:tm:cancel_branch: sending cancel...
Mar 26 00:39:51 [5951] DBG:tm:set_timer: relative timeout is 500000
Mar 26 00:39:51 [5951] DBG:tm:insert_timer_unsafe: [4]: 0xb5e885d8 (16500000)
Mar 26 00:39:51 [5951] DBG:tm:set_timer: relative timeout is 30
Mar 26 00:39:51 [5951] DBG:tm:insert_timer_unsafe: [0]: 0xb5e885f4 (46)
Mar 26 00:39:51 [5951] DBG:tm:t_relay_to: new transaction fwd'ed
Mar 26 00:39:51 [5951] DBG:tm:t_unref_cell: UNREF_UNSAFE: after is 0
Mar 26 00:39:51 [5951] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 26 00:39:51 [5951] DBG:core:destroy_avp_list: destroying list (nil)
Mar 26 00:39:51 [5951] DBG:core:receive_msg: cleaning up
#
U 172.19.172.101:5070 -> 172.19.172.176:6282
  SIP/2.0 200 canceling..Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88433
  e70eb69-1--d87543-;rport=6282..To: "85218852323"<sip:85218852323@172.19.172.101:5070>;tag=06c
  52d26462d9835792f0cb3537991da-8bf9..From: "laobai"<sip:1234@172.19.172.101:5070>;tag=027d47
  04..Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 CANCEL..
  Server: OpenSER (1.3.1-notls (i386/linux))..Content-Length: 0....
#
U 172.19.172.101:5070 -> gatewayip:5060
  CANCEL sip:85218852323@gatewayip:5060 SIP/2.0..Via: SIP/2.0/UDP 172.19.172.101:5070;bran
  ch=z9hG4bKcd7d.54768e85.0..From: "laobai"<sip:1234@172.19.172.101:5070>;tag=027d4704..Call-
  ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...To: "85218852323"<sip:6581
  685963@172.19.172.101:5070>..CSeq: 1 CANCEL..Max-Forwards: 70..User-Agent: OpenSER (1.3.1-n
  otls (i386/linux))..Content-Length: 0....
#
U gatewayip:5060 -> 172.19.172.101:5070
  SIP/2.0 487 Request Terminated..Via: SIP/2.0/UDP 172.19.172.101:5070;branch=z9hG4bKcd7d.547
  68e85.0;received=172.19.172.101..Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543
  -b83e88433e70eb69-1--d87543-;rport=6282..From: "852133143235"<sip:852133143235@172.19.172.1
Mar 26 00:39:51 [5951] DBG:core:parse_msg: SIP Reply  (status):
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  status:  <487>
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  reason:  <Request Terminated>
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=2
Mar 26 00:39:51 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKcd7d.54768e85.0>; state=6
Mar 26 00:39:51 [5951] DBG:core:parse_via_param: found param type 234, <received> = <172.19.172.101>; state=16
Mar 26 00:39:51 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:51 [5951] DBG:core:parse_headers: via found, flags=2
Mar 26 00:39:51 [5951] DBG:core:parse_headers: this is the first via
Mar 26 00:39:51 [5951] DBG:core:receive_msg: After parse_msg...
Mar 26 00:39:51 [5951] DBG:core:forward_reply: found module tm, passing reply to it
Mar 26 00:39:51 [5951] DBG:tm:t_check: start=0xffffffff
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=22
Mar 26 00:39:51 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-b83e88433e70eb69-1--d87543->; state=6
Mar 26 00:39:51 [5951] DBG:core:parse_via_param: found param type 235, <rport> = <6282>; state=16
Mar 26 00:39:51 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:51 [5951] DBG:core:parse_headers: via found, flags=22
Mar 26 00:39:51 [5951] DBG:core:parse_headers: parse_headers: this is the second via
Mar 26 00:39:51 [5951] DBG:core:parse_to_param: tag=as01c9920d
Mar 26 00:39:51 [5951] DBG:core:parse_to: end of header reached, state=29
Mar 26 00:39:51 [5951] DBG:core:parse_to: display={"85218852323"}, ruri={sip:85218852323@172.19.172.101:5070}
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: <To> [65]; uri=[sip:85218852323@172.19.172.101:5070]
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: to body ["85218852323"<sip:85218852323@172.19.172.101:5070>]
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=8
Mar 26 00:39:51 [5951] DBG:tm:t_reply_matching: hash 55260 label 1491625797 branch 0
Mar 26 00:39:51 [5951] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 26 00:39:51 [5951] DBG:tm:t_reply_matching: reply matched (T=0xb5e88410)!
Mar 26 00:39:51 [5951] DBG:tm:t_check: end=0xb5e88410
Mar 26 00:39:51 [5951] DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=8
Mar 26 00:39:51 [5951] DBG:tm:build_local: using FROM=<From: "laobai"<sip:1234@172.19.172.101:5070>;tag=027d4704
>, TO=<To: "85218852323"<sip:85218852323@172.19.172.101:5070>;tag=as01c9920d
>, CSEQ_N=<CSeq: 1>
  01:5070>;tag=027d4704..To: "85218852323"<sip:85218852323@172.19.172.101:5070>;tag=as01c9920d.
Mar 26 00:39:51 [5951] DBG:tm:t_check_status: checked status is <487>
487 received
Mar 26 00:39:51 [5951] DBG:tm:t_should_relay_response: T_code=180, new_code=487
Mar 26 00:39:51 [5951] DBG:tm:t_pick_branch: picked branch 0, code 487
Mar 26 00:39:51 [5951] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=487, flags=2
Mar 26 00:39:51 [5951] DBG:tm:t_check_status: checked status is <487>
Mar 26 00:39:51 [5951] DBG:tm:relay_reply: branch=0, save=0, relay=0
Mar 26 00:39:51 [5951] DBG:core:build_res_buf_from_sip_res:  old size: 588, new size: 496
Mar 26 00:39:51 [5951] DBG:core:build_res_buf_from_sip_res: copied size: orig:124, new: 32, rest: 464 msg=
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-b83e88433e70eb69-1--d87543-;rport=6282
From: "852133143235"<sip:852133143235@172.19.172.101:5070>;tag=027d4704
To: "85218852323"<sip:85218852323@172.19.172.101:5070>;tag=as01c9920d
Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY.
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


Mar 26 00:39:51 [5951] DBG:tm:set_timer: relative timeout is 500000
Mar 26 00:39:51 [5951] DBG:tm:insert_timer_unsafe: [4]: 0xb5e884d8 (16500000)
Mar 26 00:39:51 [5951] DBG:tm:set_timer: relative timeout is 30
Mar 26 00:39:51 [5951] DBG:tm:insert_timer_unsafe: [0]: 0xb5e884f4 (46)
Mar 26 00:39:51 [5951] DBG:tm:relay_reply: sent buf=0x818a4a0: SIP/2.0 4..., shmem=0xb5e8a860: SIP/2.0 4
Mar 26 00:39:51 [5951] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 26 00:39:51 [5951] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 26 00:39:51 [5951] DBG:core:destroy_avp_list: destroying list (nil)
Mar 26 00:39:51 [5951] DBG:core:receive_msg: cleaning up
  .Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 INVITE..Use
  r-Agent: Asterisk PBX..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY..
  Supported: replaces..Content-Length: 0....
Mar 26 00:39:51 [5951] DBG:core:parse_msg: SIP Request:
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  method:  <ACK>
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  uri:     <sip:85218852323@172.19.172.101:5070>
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=2
Mar 26 00:39:51 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-b83e88433e70eb69-1--d87543->; state=6
Mar 26 00:39:51 [5951] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Mar 26 00:39:51 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:51 [5951] DBG:core:parse_headers: via found, flags=2
Mar 26 00:39:51 [5951] DBG:core:parse_headers: this is the first via
Mar 26 00:39:51 [5951] DBG:core:receive_msg: After parse_msg...
Mar 26 00:39:51 [5951] DBG:core:receive_msg: preparing to run routing scripts...
Mar 26 00:39:51 [5951] DBG:sl:sl_filter_ACK: to late to be a local ACK!
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=100
Mar 26 00:39:51 [5951] DBG:core:parse_to_param: tag=as01c9920d
Mar 26 00:39:51 [5951] DBG:core:parse_to: end of header reached, state=29
Mar 26 00:39:51 [5951] DBG:core:parse_to: display={"85218852323"}, ruri={sip:85218852323@172.19.172.101:5070}
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: <To> [65]; uri=[sip:85218852323@172.19.172.101:5070]
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: to body ["85218852323"<sip:85218852323@172.19.172.101:5070>]
#
U 172.19.172.101:5070 -> gatewayip:5060
  ACK sip:85218852323@gatewayip:5060 SIP/2.0..Via: SIP/2.0/UDP 172.19.172.101:5070;branch=
  z9hG4bKcd7d.54768e85.0..From: "laobai"<sip:1234@172.19.172.101:5070>;tag=027d4704..Call-ID:
   4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...To: "85218852323"<sip:6581685
  963@172.19.172.101:5070>;tag=as01c9920d..CSeq: 1 ACK..Max-Forwards: 70..User-Agent: OpenSER
   (1.3.1-notls (i386/linux))..Content-Length: 0....
#
U 172.19.172.101:5070 -> 172.19.172.176:6282
  SIP/2.0 487 Request Terminated..Via: SIP/2.0/UDP 172.19.172.176:6282;branch=z9hG4bK-d87543-
  b83e88433e70eb69-1--d87543-;rport=6282..From: "852133143235"<sip:852133143235@172.19.172.10
  1:5070>;tag=027d4704..To: "85218852323"<sip:85218852323@172.19.172.101:5070>;tag=as01c9920d..
  Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 INVITE..User
  -Agent: Asterisk PBX..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY..S
  upported: replaces..Content-Length: 0....
#
U 172.19.172.176:6282 -> 172.19.172.101:5070
  ACK sip:85218852323@172.19.172.101:5070 SIP/2.0..Via: SIP/2.0/UDP 172.19.172.176:6282;branch
  =z9hG4bK-d87543-b83e88433e70eb69-1--d87543-;rport..To: "85218852323"<sip:85218852323@172.19.1
  72.101:5070>;tag=as01c9920d..From: "laobai"<sip:1234@172.19.172.101:5070>;tag=027d4704..Cal
  l-ID: 4f7a5e16a762614eYmQxNjQ4NDA1OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 ACK..Content-Le
  ngth: 0....
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: cseq <CSeq>: <1> <ACK>
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: content_length=0
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: found end of header
Mar 26 00:39:51 [5951] DBG:maxfwd:is_maxfwd_present: max_forwards header not found!
Method: ACK
Mar 26 00:39:51 [5951] DBG:core:parse_to_param: tag=027d4704
Mar 26 00:39:51 [5951] DBG:core:parse_to: end of header reached, state=29
Mar 26 00:39:51 [5951] DBG:core:parse_to: display={"laobai"}, ruri={sip:1234@172.19.172.101:5070}
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=200
Mar 26 00:39:51 [5951] DBG:rr:find_first_route: No Route headers found
Mar 26 00:39:51 [5951] DBG:rr:loose_route: There is no Route HF
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [172.19.172.101] == [127.0.0.1]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [172.19.172.101] == [172.19.172.101]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:registrar:lookup: '85218852323' Not found in usrloc
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [172.19.172.101] == [127.0.0.1]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [172.19.172.101] == [172.19.172.101]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [172.19.172.101] == [127.0.0.1]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [172.19.172.101] == [172.19.172.101]
Mar 26 00:39:51 [5951] DBG:core:grep_sock_info: checking if port 5070 matches port 5070
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=78
Mar 26 00:39:51 [5951] DBG:tm:t_lookup_request: start searching: hash=55260, isACK=1
Mar 26 00:39:51 [5951] DBG:tm:matching_3261: RFC3261 transaction matched, tid=-d87543-b83e88433e70eb69-1--d87543-
Mar 26 00:39:51 [5951] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
Mar 26 00:39:51 [5951] DBG:tm:t_lookup_request: transaction found (T=0xb5e88410)
ACK
route 1 reached
Mar 26 00:39:51 [5951] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 26 00:39:51 [5951] DBG:tm:insert_timer_unsafe: [2]: 0xb5e88458 (21)
Mar 26 00:39:51 [5951] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 26 00:39:51 [5951] DBG:core:destroy_avp_list: destroying list (nil)
Mar 26 00:39:51 [5951] DBG:core:receive_msg: cleaning up
#
Mar 26 00:39:51 [5951] DBG:core:parse_msg: SIP Reply  (status):
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  status:  <200>
Mar 26 00:39:51 [5951] DBG:core:parse_msg:  reason:  <OK>
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=2
Mar 26 00:39:51 [5951] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKcd7d.54768e85.0>; state=6
Mar 26 00:39:51 [5951] DBG:core:parse_via_param: found param type 234, <received> = <172.19.172.101>; state=16
Mar 26 00:39:51 [5951] DBG:core:parse_via: end of header reached, state=5
Mar 26 00:39:51 [5951] DBG:core:parse_headers: via found, flags=2
Mar 26 00:39:51 [5951] DBG:core:parse_headers: this is the first via
Mar 26 00:39:51 [5951] DBG:core:receive_msg: After parse_msg...
Mar 26 00:39:51 [5951] DBG:core:forward_reply: found module tm, passing reply to it
Mar 26 00:39:51 [5951] DBG:tm:t_check: start=0xffffffff
Mar 26 00:39:51 [5951] DBG:core:parse_headers: flags=22
Mar 26 00:39:51 [5951] DBG:core:parse_to_param: tag=as01c9920d
Mar 26 00:39:51 [5951] DBG:core:parse_to: end of header reached, state=29
Mar 26 00:39:51 [5951] DBG:core:parse_to: display={"85218852323"}, ruri={sip:85218852323@172.19.172.101:5070}
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: <To> [65]; uri=[sip:85218852323@172.19.172.101:5070]
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: to body ["85218852323"<sip:85218852323@172.19.172.101:5070>]
Mar 26 00:39:51 [5951] DBG:core:get_hdr_field: cseq <CSeq>: <1> <CANCEL>
Mar 26 00:39:51 [5951] DBG:tm:t_reply_matching: hash 55260 label 1491625797 branch 0
Mar 26 00:39:51 [5951] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 26 00:39:51 [5951] DBG:tm:t_reply_matching: reply matched (T=0xb5e88410)!
Mar 26 00:39:51 [5951] DBG:tm:t_check: end=0xb5e88410
Mar 26 00:39:51 [5951] DBG:tm:reply_received: org. status uas=487, uac[0]=487 local=0 is_invite=1)
Mar 26 00:39:51 [5951] DBG:tm:reply_received: reply to local CANCEL processed
Mar 26 00:39:51 [5951] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 26 00:39:51 [5951] DBG:core:destroy_avp_list: destroying list (nil)
Mar 26 00:39:51 [5951] DBG:core:receive_msg: cleaning up
U gatewayip:5060 -> 172.19.172.101:5070
  SIP/2.0 200 OK..Via: SIP/2.0/UDP 172.19.172.101:5070;branch=z9hG4bKcd7d.54768e85.0;received
  =172.19.172.101..From: "laobai"<sip:1234@172.19.172.101:5070>;tag=027d4704..To: "85218852323
  "<sip:85218852323@172.19.172.101:5070>;tag=as01c9920d..Call-ID: 4f7a5e16a762614eYmQxNjQ4NDA1
  OTU1ZDgwYjg0ZTNmYjEzNjY2NWU5MGY...CSeq: 1 CANCEL..User-Agent: Asterisk PBX..Allow: INVITE,
  ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY..Supported: replaces..Contact: <sip:658
  1685963@gatewayip>..Content-Length: 0....
Mar 26 00:39:51 [5952] DBG:tm:utimer_routine: timer routine:4,tl=0xb5e885d8 next=0xb5e884d8, timeout=16500000
Mar 26 00:39:51 [5952] DBG:tm:utimer_routine: timer routine:4,tl=0xb5e884d8 next=(nil), timeout=16500000
Mar 26 00:39:56 [5952] DBG:tm:timer_routine: timer routine:2,tl=0xb5e8ace8 next=0xb5e88458, timeout=21
Mar 26 00:39:56 [5952] DBG:tm:wait_handler: removing 0xb5e8aca0 from table
Mar 26 00:39:56 [5952] DBG:tm:delete_cell: delete transaction 0xb5e8aca0
Mar 26 00:39:56 [5952] DBG:tm:wait_handler: done
Mar 26 00:39:56 [5952] DBG:tm:timer_routine: timer routine:2,tl=0xb5e88458 next=(nil), timeout=21
Mar 26 00:39:56 [5952] DBG:tm:wait_handler: removing 0xb5e88410 from table
Mar 26 00:39:56 [5952] DBG:tm:delete_cell: delete transaction 0xb5e88410
Mar 26 00:39:56 [5952] DBG:tm:wait_handler: done