May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:t_lookup_request: start searching: hash=62105, isACK=0
May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:matching_3261: RFC3261 transaction matching failed
May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:t_lookup_request: no transaction found
May 20 14:46:15 ca ../kamailio[11533]: DBG:core:parse_headers: flags=ffffffffffffffff
May 20 14:46:15 ca ../kamailio[11533]: DBG:core:check_via_address: params 127.0.0.1, 127.0.0.1, 0
May 20 14:46:15 ca ../kamailio[11533]: DBG:core:_shm_resize: resize(0) called
May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:_reply_light: reply sent out. buf=0x8166c18: SIP/2.0 1..., shmem=0xb5ce0c18: SIP/2.0 1
May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:_reply_light: finished
May 20 14:46:15 ca ../kamailio[11533]: DBG:core:mk_proxy: doing DNS lookup...
May 20 14:46:15 ca ../kamailio[11533]: DBG:core:check_via_address: params 127.0.0.1, 127.0.0.1, 0
May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:set_timer: relative timeout is 500000
May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:insert_timer_unsafe: [4]: 0xb5cdf5dc (1500000)
May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:set_timer: relative timeout is 30
May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:insert_timer_unsafe: [0]: 0xb5cdf5f8 (32)
May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:t_relay_to: new transaction fwd'ed
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_msg: SIP Reply  (status):
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_msg:  version: <SIP/2.0>
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_msg:  status:  <503>
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_msg:  reason:  <Service Unavailable>
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_headers: flags=2
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK992f.ef7c45d2.0>; state=9
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_via: next_via
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-11583-1-0>; state=16
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_via: end of header reached, state=5
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_headers: via found, flags=2
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_headers: this is the first via
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:receive_msg: After parse_msg...
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:forward_reply: found module tm, passing reply to it
May 20 14:46:15 ca ../kamailio[11536]: DBG:tm:t_check: start=0xffffffff
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_headers: flags=22
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_to_param: tag=1
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_to: end of header reached, state=29
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_to: display={sut}, ruri={sip:49721123456785@127.0.0.1:5060}
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:49721123456785@127.0.0.1:5060]
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:get_hdr_field: to body [sut <sip:49721123456785@127.0.0.1:5060>]
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
May 20 14:46:15 ca ../kamailio[11536]: DBG:core:parse_headers: flags=8
May 20 14:46:15 ca ../kamailio[11536]: DBG:tm:t_reply_matching: hash 62105 label 760530942 branch 0
May 20 14:46:15 ca ../kamailio[11533]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
May 20 14:46:15 ca ../kamailio[11533]: DBG:core:destroy_avp_list: destroying list (nil)
May 20 14:46:15 ca ../kamailio[11533]: DBG:core:receive_msg: cleaning up
May 20 14:46:15 ca ../kamailio[11536]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
May 20 14:46:15 ca ../kamailio[11536]: DBG:tm:t_reply_matching: reply matched (T=0xb5cdf490)!
May 20 14:46:15 ca ../kamailio[11536]: DBG:tm:t_check: end=0xb5cdf490







May 20 14:43:56 ca ../../ser[11292]: DEBUG: tm [t_lookup.c:507]: t_lookup_request: start searching: hash=46761, isACK=0
May 20 14:43:56 ca ../../ser[11292]: DEBUG: tm [t_lookup.c:466]: DEBUG: RFC3261 transaction matching failed
May 20 14:43:56 ca ../../ser[11292]: DEBUG: tm [t_lookup.c:690]: DEBUG: t_lookup_request: no transaction found
May 20 14:43:56 ca ../../ser[11292]: DEBUG: tm [t_funcs.c:329]: SER: new INVITE
May 20 14:43:56 ca ../../ser[11292]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=ffffffffffffffff
May 20 14:43:56 ca ../../ser[11292]: DEBUG: <core> [msg_translator.c:200]: check_via_address(127.0.0.1, 127.0.0.1, 0)
May 20 14:43:56 ca ../../ser[11292]: DEBUG: <core> [mem/shm_mem.c:117]: WARNING:vqm_resize: resize(0) called
May 20 14:43:56 ca ../../ser[11292]: DEBUG: tm [t_reply.c:605]: DEBUG: reply sent out. buf=0x82afa7c: SIP/2.0 1..., shmem=0xb5aba8c0: SIP/2.0 1
May 20 14:43:56 ca ../../ser[11292]: DEBUG: tm [t_reply.c:615]: DEBUG: _reply_light: finished
May 20 14:43:56 ca ../../ser[11292]: DEBUG: <core> [msg_translator.c:200]: check_via_address(127.0.0.1, 127.0.0.1, 0)
May 20 14:43:56 ca ../../ser[11292]: DEBUG: tm [t_funcs.c:366]: SER: new transaction fwd'ed
May 20 14:43:56 ca ../../ser[11292]: DEBUG: <core> [usr_avp.c:634]: DEBUG:destroy_avp_list: destroying list (nil)
May 20 14:43:56 ca last message repeated 5 times
May 20 14:43:56 ca ../../ser[11292]: DEBUG: <core> [receive.c:244]: receive_msg: cleaning up
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:604]: SIP Reply  (status):
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:606]:  version: <SIP/2.0>
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:608]:  status:  <503>
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:610]:  reason:  <Service Unavailable>
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=2
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK9a6b.2b6779d.0>; state=9
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/parse_via.c:2339]: parse_via: next_via
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-11343-1-0>; state=16
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:493]: parse_headers: Via found, flags=2
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: this is the first via
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [receive.c:120]: After parse_msg...
May 20 14:43:56 ca ../../ser[11295]: DEBUG: tm [t_lookup.c:1057]: DEBUG: t_check_msg: msg id=1 global id=0 T start=0xffffffff
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:318]: parse_headers: flags=22
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=1
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [47]; uri=[sip:49721123456785@127.0.0.1:5060]
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [sut <sip:49721123456785@127.0.0.1:5060>]
May 20 14:43:56 ca ../../ser[11295]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <>
May 20 14:43:56 ca ../../ser[11295]: DEBUG: tm [t_lookup.c:945]: DEBUG: t_reply_matching: hash 46761 label 228030130 branch 0
May 20 14:43:56 ca ../../ser[11295]: DEBUG: tm [t_lookup.c:1029]: DEBUG: t_reply_matching: no matching transaction exists
May 20 14:43:56 ca ../../ser[11295]: DEBUG: tm [t_lookup.c:1032]: DEBUG: t_reply_matching: failure to match a transaction
May 20 14:43:56 ca ../../ser[11295]: DEBUG: tm [t_lookup.c:1126]: DEBUG: t_check_msg: msg id=1 global id=1 T end=(nil)