Jun 17 11:49:24 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2 T end=(nil)
Jun 17 11:49:24 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=1 T start=(nil)
Jun 17 11:49:24 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1046]: t_reply_matching(): DEBUG: t_reply_matching: failure to match a transaction
Jun 17 11:49:24 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2 T end=(nil)
Jun 17 11:49:32 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=1 T start=(nil)
Jun 17 11:49:32 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1046]: t_reply_matching(): DEBUG: t_reply_matching: failure to match a transaction
Jun 17 11:49:32 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2 T end=(nil)
Jun 17 11:49:32 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=1 T start=(nil)
Jun 17 11:49:32 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1046]: t_reply_matching(): DEBUG: t_reply_matching: failure to match a transaction
Jun 17 11:49:32 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2 T end=(nil)
Jun 17 11:49:35 sp2 proxy[12695]: NOTICE: <script>: New request on proxy - M=NOTIFY R=sip:92.42.136.48 F=sip:test1@demo.sipwise.com T=sip:92.42.136.48 IP=77.244.249.126:6774 (127.0.0.1:5060) ID=b23c1351-c0b54bc@10.15.20.112
Jun 17 11:49:36 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=3 global id=1 T start=(nil)
Jun 17 11:49:36 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1046]: t_reply_matching(): DEBUG: t_reply_matching: failure to match a transaction
Jun 17 11:49:36 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=3 global id=3 T end=(nil)
Jun 17 11:49:36 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=3 global id=2 T start=(nil)
Jun 17 11:49:36 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1046]: t_reply_matching(): DEBUG: t_reply_matching: failure to match a transaction
Jun 17 11:49:36 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=3 global id=3 T end=(nil)
Jun 17 11:49:37 sp2 proxy[12700]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:agranig.demo.sipwise.com:5060 F=sip:phone3@agranig.demo.sipwise.com T=sip:phone3@agranig.demo.sipwise.com IP=77.244.249.126:5061 (127.0.0.1:5060) ID=1946997887@10.15.20.167
Jun 17 11:49:37 sp2 proxy[12700]: NOTICE: <script>: Authentication failed, stale nonce - R=sip:agranig.demo.sipwise.com:5060 ID=1946997887@10.15.20.167
Jun 17 11:49:37 sp2 proxy[12697]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:agranig.demo.sipwise.com:5060 F=sip:phone3@agranig.demo.sipwise.com T=sip:phone3@agranig.demo.sipwise.com IP=77.244.249.126:5061 (127.0.0.1:5060) ID=1946997887@10.15.20.167
Jun 17 11:49:37 sp2 proxy[12697]: INFO: <script>: [LUA] Load caller preferences for uuid '57d1dc47-8a9c-4766-98cb-e1441aa48acd' and domain part of uri 'agranig.demo.sipwise.com' - R=sip:agranig.demo.sipwise.com:5060 ID=1946997887@10.15.20.167
Jun 17 11:49:37 sp2 proxy[12697]: INFO: <script>: IP authorization not provisioned, allow registration - R=sip:agranig.demo.sipwise.com:5060 ID=1946997887@10.15.20.167
Jun 17 11:49:37 sp2 proxy[12697]: NOTICE: <script>: Contacts successfully updated, expires in 3600s - R=sip:agranig.demo.sipwise.com:5060 ID=1946997887@10.15.20.167
Jun 17 11:49:38 sp2 proxy[12701]: NOTICE: <script>: New request on proxy - M=INVITE R=sip:0004399111111@agranig.demo.sipwise.com F=sip:phone2@agranig.demo.sipwise.com T=sip:0004399111111@agranig.demo.sipwise.com IP=77.244.249.126:46637 (127.0.0.1:5060) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12701]: INFO: <script>: Load domain preferences for callee - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12701]: INFO: <script>: Clean domain preferences for callee - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12701]: NOTICE: <script>: Authentication failed, no credentials - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: New request on proxy - M=INVITE R=sip:0004399111111@agranig.demo.sipwise.com F=sip:phone2@agranig.demo.sipwise.com T=sip:0004399111111@agranig.demo.sipwise.com IP=77.244.249.126:46637 (127.0.0.1:5060) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Load domain preferences for callee - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Clean domain preferences for callee - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Adding reply P-NGCP-Caller-Info '<sip:phone2@agranig.demo.sipwise.com>;ip=77.244.249.126;port=46637' - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Clear caller preferences - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Load caller preferences for uuid '0214786f-eb1c-4865-95ba-65d8c1c0bf32' and domain 'agranig.demo.sipwise.com' - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Load caller contract preferences for contract id '48' - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Caller is a member of huntgroup phones with uuid 'fb9b7336-f6c7-4137-a0fc-360645d31d0a' - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Use lb/rtp set id '50' for local caller - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Fetched dialplan IDs caller_in='25', callee_in='27' - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Use 'P-NGCP-Src-Ip' for CDR IP - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: IP authorization for caller not provisioned, allow call - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: User-Provided CLI 'phone2' taken from From-User - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Applying caller-in usr/domain rewrite rules on user-provided CLI using dpid '25' - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: No matching rewrite rules for 'phone2' found - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Checking User-provided CLI against allowed CLIs - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: User-provided CLI 'phone2' rejected, using network-provided CLI '43221000202' - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Setting '43221000202@agranig.demo.sipwise.com' as initiating user-provided CLI - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Setting '43221000202@agranig.demo.sipwise.com' as initiating network-provided CLI - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Searching for callee - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Applying callee-in usr/domain rewrite rules on called party using dpid '27' - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Rewriting called party '0004399111111' to '4399111111' - R=sip:0004399111111@agranig.demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Callee was aliased with base '4399111111' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Clear callee preferences - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Callee is local, uuid='e59611e6-01de-424c-a04f-e977409c54f6' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Check Administrative Contract NCOS level - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Check Administrative NCOS level - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Check Contract NCOS level - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Check User NCOS level - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Checking URI 'sip:test1@demo.sipwise.com' and CLI '4399111111' against admin contract block out lists - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Admin Contract caller block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Checking URI 'sip:test1@demo.sipwise.com' and CLI '4399111111' against block out lists - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Admin caller block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Checking URI 'sip:test1@demo.sipwise.com' and CLI '4399111111' against contract block out lists - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Contract caller block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Caller block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Load callee preferences for uuid 'e59611e6-01de-424c-a04f-e977409c54f6' domain: 'demo.sipwise.com'- R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Load callee contract preferences for contract id '64' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Use lb/rtp set id '50' for local callee - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Fetched dialplan IDs caller_out='21', callee_out='23' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Set callee dialogs: user, account to 'e59611e6-01de-424c-a04f-e977409c54f6/64' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Set callee dialogs: totaluser, totalaccount to 'e59611e6-01de-424c-a04f-e977409c54f6/64' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Checking UPN '43221000202' and NPN '43221000202' against block in lists - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Admin Contract callee block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Admin callee block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Contract callee block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Callee block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Set next hop to pbx because caller is a PBX user - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Dialog set total - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Set caller dialogs: totaluser, totaluserout, totalaccount, totalaccountout to '0214786f-eb1c-4865-95ba-65d8c1c0bf32/48' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Set caller dialogs: user, userout, account, accountout to '0214786f-eb1c-4865-95ba-65d8c1c0bf32/48' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Setting acc source-leg for uuid '0214786f-eb1c-4865-95ba-65d8c1c0bf32': '0214786f-eb1c-4865-95ba-65d8c1c0bf32|phone2|agranig.demo.sipwise.com|43221000202|||48|||0|call|77.244.249.126|1434534578.107169|||||||||||' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: ++++++ 2. ACC flag is set - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Setting acc destination-leg for uuid 'e59611e6-01de-424c-a04f-e977409c54f6': '0||comx|64|0004399111111|e59611e6-01de-424c-a04f-e977409c54f6|test1|demo.sipwise.com|4399111111|agranig.demo.sipwise.com|0|||||||||||' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Relaying request, du='<null>' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=3 , global msg id=2 , T on entrance=(nil)
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=42414, isACK=0
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 1, id 0 entered
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 1, id 0 entered
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Use mediaproxy for forward direction for IPv4/IPv4 - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Remove existing ICE candidates (if any) for callee - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Try protocol 'RTP/AVP' for callee - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Engaging rtpengine in request for caller did '50' and callee did '50' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Setting P-Caller-UUID to '0214786f-eb1c-4865-95ba-65d8c1c0bf32' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Setting P-Callee-UUID to 'e59611e6-01de-424c-a04f-e977409c54f6' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: User Agent header removed - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Don't set caller/callee for initial loop to PBX - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Sessions Timers disabled for caller - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Sessions Timers disabled for callee - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Writing pbx params ';pbx_moh_b=yes;pbx_moh_b_id=39;pbx_moh_b_loop=yes;aleg_sst_enable=no;sst_enable=no;a_park_domain=48;b_park_domain=64' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Forcing request via PBX 'sip:127.0.0.1:5085' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Adding P-NGCP-Caller-Info '<sip:phone2@agranig.demo.sipwise.com>;ip=77.244.249.126;port=46637' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Adding P-NGCP-Callee-Info '<sip:test1@demo.sipwise.com>;ip=127.0.0.1;port=5085' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Request leaving server, D-URI='sip:127.0.0.1:5085' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=2 T start=(nil)
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 42414 label 0 branch 0
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8da308)!
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 2, id 0 entered
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback called for t(0x7f421c8da308) event type 2, reply code 100
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 2, id 0 entered
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T end=0x7f421c8da308
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=1)
Jun 17 11:49:38 sp2 proxy[12695]: NOTICE: <script>: NAT-Reply - S=100 - Trying M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=100
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=-1 icode=0
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: New request on proxy - M=INVITE R=sip:test1@demo.sipwise.com F=sip:phone2@agranig.demo.sipwise.com T=sip:test1@agranig.demo.sipwise.com IP=77.244.249.126:46637 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Load domain preferences for callee - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Clean domain preferences for callee - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Call from hosted PBX server - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Skip accounting for call from PBX to device - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: PBX caller is 'phone2@agranig.demo.sipwise.com' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Found NO aliased caller for call from PBX, checking From/Referred-By 'phone2@agranig.demo.sipwise.com' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Setting From info for PBX call to 'phone2@agranig.demo.sipwise.com' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12696]: NOTICE: <script>: New request on proxy - M=PUBLISH R=sip:phone2@agranig.demo.sipwise.com F=sip:pbx@app.local T=sip:phone2@agranig.demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=sip:phone2@agranig.demo.sipwise.com
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=3 T start=(nil)
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=14873, isACK=0
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T end=(nil)
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=4 , global msg id=4 , T on entrance=(nil)
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=14873, isACK=0
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8e20a8, callback type 1, id 0 entered
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8e20a8, callback type 1, id 0 entered
Jun 17 11:49:38 sp2 proxy[12696]: NOTICE: <script>: Handling publish request - R=sip:phone2@agranig.demo.sipwise.com ID=sip:phone2@agranig.demo.sipwise.com
Jun 17 11:49:38 sp2 proxy[12700]: NOTICE: <script>: New request on proxy - M=PUBLISH R=sip:test1@demo.sipwise.com F=sip:pbx@app.local T=sip:test1@demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=sip:test1@demo.sipwise.com
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=2 T start=(nil)
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=52217, isACK=0
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T end=(nil)
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=4 , global msg id=4 , T on entrance=(nil)
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=52217, isACK=0
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8e4a90, callback type 1, id 0 entered
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8e4a90, callback type 1, id 0 entered
Jun 17 11:49:38 sp2 proxy[12700]: NOTICE: <script>: Handling publish request - R=sip:test1@demo.sipwise.com ID=sip:test1@demo.sipwise.com
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T start=0x7f421c8e20a8
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f4237d6ccf8: SIP/2.0 200 OK#015#012Via:..., shmem=0x7f421c8e7438: SIP/2.0 200 OK#015#012Via:
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T start=0x7f421c8e4a90
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T start=0x7f421c8e20a8
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:38 sp2 proxy[12696]: DEBUG: tm [t_funcs.c:180]: put_on_wait(): tm: put_on_wait: transaction 0x7f421c8e20a8 already on wait
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f4237d6ccf8: SIP/2.0 200 OK#015#012Via:..., shmem=0x7f421c8e76c0: SIP/2.0 200 OK#015#012Via:
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T start=0x7f421c8e4a90
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:38 sp2 proxy[12700]: DEBUG: tm [t_funcs.c:180]: put_on_wait(): tm: put_on_wait: transaction 0x7f421c8e4a90 already on wait
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Dialog set mark TOTAL - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Clear caller preferences - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Load caller preferences for uuid '0214786f-eb1c-4865-95ba-65d8c1c0bf32' and domain 'agranig.demo.sipwise.com' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Load caller contract preferences for contract id '48' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Use lb/rtp set id '50' for local caller - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Fetched dialplan IDs caller_in='25', callee_in='27' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Use 'P-NGCP-Src-Ip' for CDR IP - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: IP authorization for caller not provisioned, allow call - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: User-Provided CLI 'phone2' taken from From-User - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Applying caller-in usr/domain rewrite rules on user-provided CLI using dpid '25' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: No matching rewrite rules for 'phone2' found - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Checking User-provided CLI against allowed CLIs - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: User-provided CLI 'phone2' rejected, using network-provided CLI '43221000202' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Setting '43221000202@agranig.demo.sipwise.com' as initiating user-provided CLI - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Setting '43221000202@agranig.demo.sipwise.com' as initiating network-provided CLI - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Searching for callee - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Clear callee preferences - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Callee is local, uuid='e59611e6-01de-424c-a04f-e977409c54f6' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Skip NCOS level and block_out list check for call loop from PBX - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Load callee preferences for uuid 'e59611e6-01de-424c-a04f-e977409c54f6' domain: 'demo.sipwise.com'- R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Load callee contract preferences for contract id '64' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Use lb/rtp set id '50' for local callee - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Fetched dialplan IDs caller_out='21', callee_out='23' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Checking UPN '43221000202' and NPN '43221000202' against block in lists - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Admin Contract callee block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Admin callee block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Contract callee block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Callee block mode is 'blacklist' - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Dialog set mark type to local - R=sip:test1@demo.sipwise.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Relaying request, du='sip:lb@127.0.0.1;lr;received=sip:77.244.249.126:6774;socket=sip:92.42.136.48:5060' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=4 , global msg id=3 , T on entrance=(nil)
Jun 17 11:49:38 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=26163, isACK=0
Jun 17 11:49:38 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:38 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:38 sp2 proxy[12698]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 1, id 0 entered
Jun 17 11:49:38 sp2 proxy[12698]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 1, id 0 entered
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Use mediaproxy for forward direction for IPv4/IPv4 - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Remove existing ICE candidates (if any) for callee - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Try protocol 'RTP/AVP' for callee - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Engaging rtpengine in request for caller did '50' and callee did '50' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Local user online, using registered contact as user - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Sessions Timers disabled for caller - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Sessions Timers disabled for callee - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Applying caller-out usr/domain rewrite rules on first user-provided CLI using dpid '21' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Rewriting first user-provided CLI '43221000202' to '00043221000202' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Applying caller-out usr/domain rewrite rules on first network-provided CLI using dpid '21' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Rewriting first network-provided CLI '43221000202' to '00043221000202' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Setting userprovided caller domain - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Use first userprov caller domain 'agranig.demo.sipwise.com' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Prepare From display-name setting - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: No selector set, not setting CLI - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Prepare From username setting - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Setting caller_cli_userprov/caller_domain_userprov '00043221000202@agranig.demo.sipwise.com' for upn - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Setting From to '<sip:00043221000202@agranig.demo.sipwise.com>' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Prepare PAI username setting - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Setting caller_cli_netprov/caller_domain_netprov '00043221000202@agranig.demo.sipwise.com' for npn - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Setting PAI to '<sip:00043221000202@agranig.demo.sipwise.com>' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Prepare PPI username setting - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: No selector set, not setting CLI - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Prepare Diversion setting - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: No selector set, not setting CLI - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Applying callee-out usr/domain rewrite rules on called party using dpid '23' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: No matching rewrite rules for 'test1' found - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Prepare P-Called-Party-ID setting using selector 'callee' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Setting P-Called-Party-ID '<sip:test1@demo.sipwise.com>' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Writing sbc parameters  ;aleg_sst_enable=no;sst_enable=no;moh_a=yes;moh_a_id=16;moh_a_loop=no - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Adding P-NGCP-Caller-Info '<sip:phone2@agranig.demo.sipwise.com>;ip=77.244.249.126;port=46637' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Adding P-NGCP-Callee-Info '<sip:test1@demo.sipwise.com>;ip=77.244.249.126;port=6774' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Appending P-D-URI 'sip:lb@127.0.0.1;lr;received=sip:77.244.249.126:6774;socket=sip:92.42.136.48:5060' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Forcing request via B2BUA 'sip:127.0.0.1:5080' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: NOTICE: <script>: Request leaving server, D-URI='sip:127.0.0.1:5080' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12698]: DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed
Jun 17 11:49:38 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=2 T start=(nil)
Jun 17 11:49:38 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 26163 label 0 branch 0
Jun 17 11:49:38 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8f0800)!
Jun 17 11:49:38 sp2 proxy[12697]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:38 sp2 proxy[12697]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:38 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T end=0x7f421c8f0800
Jun 17 11:49:38 sp2 proxy[12697]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=1)
Jun 17 11:49:38 sp2 proxy[12697]: NOTICE: <script>: NAT-Reply - S=100 - Connecting M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5080) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12697]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=100
Jun 17 11:49:38 sp2 proxy[12697]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=-1 icode=0
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=2 T start=(nil)
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 26163 label 0 branch 0
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8f0800)!
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T end=0x7f421c8f0800
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=100 local=0 is_invite=1)
Jun 17 11:49:38 sp2 proxy[12701]: NOTICE: <script>: NAT-Reply - S=180 - Ringing M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5080) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=180
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 32, id 0 entered
Jun 17 11:49:38 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 1048576, id 0 entered
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=2 T start=(nil)
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 42414 label 0 branch 0
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8da308)!
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 2, id 0 entered
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback called for t(0x7f421c8da308) event type 2, reply code 180
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 2, id 0 entered
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T end=0x7f421c8da308
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=100 local=0 is_invite=1)
Jun 17 11:49:38 sp2 proxy[12699]: NOTICE: <script>: NAT-Reply - S=180 - Ringing M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12699]: ERROR: sca [sca_call_info.c:2006]: sca_call_info_update(): Failed to update Call-Info state for sip:127.0.0.1:5085;transport=udp
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=180
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 32, id 0 entered
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 1048576, id 0 entered
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 512, id 0 entered
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback called for t(0x7f421c8da308) event type 512, reply code 180
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: New request on proxy - M=PUBLISH R=sip:test1@demo.sipwise.com F=sip:pbx@app.local T=sip:test1@demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=sip:test1@demo.sipwise.com
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=3 T start=0xffffffffffffffff
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=52214, isACK=0
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T end=(nil)
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=4 , global msg id=4 , T on entrance=(nil)
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=52214, isACK=0
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8f5e10, callback type 1, id 0 entered
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8f5e10, callback type 1, id 0 entered
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Handling publish request - R=sip:test1@demo.sipwise.com ID=sip:test1@demo.sipwise.com
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T start=0x7f421c8f5e10
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f4237d3ca18: SIP/2.0 200 OK#015#012Via:..., shmem=0x7f421c8f8840: SIP/2.0 200 OK#015#012Via:
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=4 global id=4 T start=0x7f421c8f5e10
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:38 sp2 proxy[12702]: DEBUG: tm [t_funcs.c:180]: put_on_wait(): tm: put_on_wait: transaction 0x7f421c8f5e10 already on wait
Jun 17 11:49:40 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=4 T start=0xffffffffffffffff
Jun 17 11:49:40 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 26163 label 0 branch 0
Jun 17 11:49:40 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8f0800)!
Jun 17 11:49:40 sp2 proxy[12695]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:40 sp2 proxy[12695]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:40 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=5 T end=0x7f421c8f0800
Jun 17 11:49:40 sp2 proxy[12695]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: NAT-Reply - S=302 - Moved Temporarily M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5080) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=302
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Stop mediaproxy for current branch using first Via, caller did is '50' and callee did is '50' - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: ------ 1. ACC flag is NOT set - R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Redirect from UAC intercepted - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Clear caller preferences - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Load caller preferences for uuid 'e59611e6-01de-424c-a04f-e977409c54f6' and domain 'demo.sipwise.com' - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Load caller contract preferences for contract id '64' - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Use lb/rtp set id '50' for local caller - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Fetched dialplan IDs caller_in='17', callee_in='19' - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Use 'P-NGCP-Src-Ip' for CDR IP - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Searching for callee - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Setting network-provided info as user-provided info for call-forward - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Applying callee-in usr/domain rewrite rules on called party using dpid '19' - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: No matching rewrite rules for '4399111112' found - R=sip:4399111112@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Callee was aliased with base '4399111112' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Clear callee preferences - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Callee is local, uuid='72d04db7-6fd2-47c3-95a7-5685a5297715' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Check Administrative Contract NCOS level - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Check Administrative NCOS level - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Check Contract NCOS level - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Check User NCOS level - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Checking URI 'sip:test2@demo.sipwise.com' and CLI '4399111112' against admin contract block out lists - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Admin Contract caller block mode is 'blacklist' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Checking URI 'sip:test2@demo.sipwise.com' and CLI '4399111112' against block out lists - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Admin caller block mode is 'blacklist' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Checking URI 'sip:test2@demo.sipwise.com' and CLI '4399111112' against contract block out lists - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Contract caller block mode is 'blacklist' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Caller block mode is 'blacklist' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Load callee preferences for uuid '72d04db7-6fd2-47c3-95a7-5685a5297715' domain: 'demo.sipwise.com'- R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Load callee contract preferences for contract id '64' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Use lb/rtp set id '50' for local callee - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Fetched dialplan IDs caller_out='21', callee_out='23' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Set callee dialogs: user, account to '72d04db7-6fd2-47c3-95a7-5685a5297715/64' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Set callee dialogs: totaluser, totalaccount to '72d04db7-6fd2-47c3-95a7-5685a5297715/64' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Checking UPN 'phone2' and NPN 'phone2' against block in lists - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Admin Contract callee block mode is 'blacklist' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Admin callee block mode is 'blacklist' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Contract callee block mode is 'blacklist' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Callee block mode is 'blacklist' - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Dialog set mark type to local - R=sip:test2@demo.sipwise.com;alias=77.244.249.126~6774~1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Dialog set total - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Set caller dialogs: totaluser, totaluserout, totalaccount, totalaccountout to 'e59611e6-01de-424c-a04f-e977409c54f6/64' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Set caller dialogs: user, userout, account, accountout to 'e59611e6-01de-424c-a04f-e977409c54f6/64' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Setting acc source-leg for uuid 'e59611e6-01de-424c-a04f-e977409c54f6': 'e59611e6-01de-424c-a04f-e977409c54f6|test1|agranig.demo.sipwise.com|phone2||comx|64|||<null>|cfb|77.244.249.126|1434534580.186507|||||||||||' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: ++++++ 2. ACC flag is set - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Setting acc destination-leg for uuid '72d04db7-6fd2-47c3-95a7-5685a5297715': '0||comx|64|4399111112|72d04db7-6fd2-47c3-95a7-5685a5297715|test2|demo.sipwise.com|4399111112|demo.sipwise.com|0|||||||||||' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Relaying request, du='sip:lb@127.0.0.1;lr;received=sip:77.244.249.126:46637;socket=sip:92.42.136.48:5060' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Use mediaproxy for forward direction for IPv4/IPv4 - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Remove existing ICE candidates (if any) for callee - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Try protocol 'RTP/AVP' for callee - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Engaging rtpengine in request for caller did '50' and callee did '50' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Local user online, using registered contact as user - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Sessions Timers disabled for caller - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Sessions Timers disabled for callee - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Applying caller-out usr/domain rewrite rules on first user-provided CLI using dpid '21' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Rewriting first user-provided CLI '43221000202' to '00043221000202' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Applying caller-out usr/domain rewrite rules on first network-provided CLI using dpid '21' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Rewriting first network-provided CLI '43221000202' to '00043221000202' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Applying caller-out usr/domain rewrite rules on user-provided Redirecting CLI using dpid '21' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: No matching rewrite rules for 'test1' found - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Setting userprovided caller domain - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Use first userprov caller domain 'agranig.demo.sipwise.com' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Prepare From display-name setting - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: No selector set, not setting CLI - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Prepare From username setting - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Setting caller_cli_userprov/caller_domain_userprov '00043221000202@agranig.demo.sipwise.com' for upn - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Setting From to '<sip:00043221000202@agranig.demo.sipwise.com>' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Prepare PAI username setting - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Setting caller_cli_netprov/caller_domain_netprov '00043221000202@agranig.demo.sipwise.com' for npn - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Setting PAI to '<sip:00043221000202@agranig.demo.sipwise.com>' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Prepare PPI username setting - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: No selector set, not setting CLI - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Prepare Diversion setting - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: No selector set, not setting CLI - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Applying callee-out usr/domain rewrite rules on called party using dpid '23' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: No matching rewrite rules for '25704386' found - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Prepare P-Called-Party-ID setting using selector 'callee' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Setting P-Called-Party-ID '<sip:25704386@demo.sipwise.com>' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Writing sbc parameters  ;aleg_sst_enable=no;sst_enable=no;moh_b=yes;moh_b_id=16;moh_b_loop=no;moh_a=yes;moh_a_id=16;moh_a_loop=no - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Adding P-NGCP-Caller-Info '<sip:phone2@agranig.demo.sipwise.com>;ip=77.244.249.126;port=46637' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Adding P-NGCP-Callee-Info '<sip:test2@demo.sipwise.com>;ip=77.244.249.126;port=46637' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Appending P-D-URI 'sip:lb@127.0.0.1;lr;received=sip:77.244.249.126:46637;socket=sip:92.42.136.48:5060' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Forcing request via B2BUA 'sip:127.0.0.1:5080' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Request leaving server, D-URI='sip:127.0.0.1:5080' - R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=1, relay=-1 icode=0
Jun 17 11:49:40 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=4 T start=0xffffffffffffffff
Jun 17 11:49:40 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 26163 label 0 branch 1
Jun 17 11:49:40 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8f0800)!
Jun 17 11:49:40 sp2 proxy[12696]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:40 sp2 proxy[12696]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:40 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=5 T end=0x7f421c8f0800
Jun 17 11:49:40 sp2 proxy[12696]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=180, uac[1]=0 local=0 is_invite=1)
Jun 17 11:49:40 sp2 proxy[12696]: NOTICE: <script>: NAT-Reply - S=100 - Connecting M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5080) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12696]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=100
Jun 17 11:49:40 sp2 proxy[12696]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=1, save=0, relay=-1 icode=0
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=4 T start=0xffffffffffffffff
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 26163 label 0 branch 1
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8f0800)!
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=5 T end=0x7f421c8f0800
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=180, uac[1]=100 local=0 is_invite=1)
Jun 17 11:49:40 sp2 proxy[12700]: NOTICE: <script>: NAT-Reply - S=180 - Ringing M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5080) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=180
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=1, save=0, relay=1 icode=0
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 32, id 0 entered
Jun 17 11:49:40 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 1048576, id 0 entered
Jun 17 11:49:41 sp2 proxy[12698]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:agranig.demo.sipwise.com:5060 F=sip:phone2@agranig.demo.sipwise.com T=sip:phone2@agranig.demo.sipwise.com IP=86.59.95.122:6410 (127.0.0.1:5060) ID=2626876779@10.15.20.167
Jun 17 11:49:41 sp2 proxy[12698]: NOTICE: <script>: Authentication failed, stale nonce - R=sip:agranig.demo.sipwise.com:5060 ID=2626876779@10.15.20.167
Jun 17 11:49:41 sp2 proxy[12697]: NOTICE: <script>: New request on proxy - M=REGISTER R=sip:agranig.demo.sipwise.com:5060 F=sip:phone2@agranig.demo.sipwise.com T=sip:phone2@agranig.demo.sipwise.com IP=86.59.95.122:6410 (127.0.0.1:5060) ID=2626876779@10.15.20.167
Jun 17 11:49:41 sp2 proxy[12697]: INFO: <script>: [LUA] Load caller preferences for uuid '0214786f-eb1c-4865-95ba-65d8c1c0bf32' and domain part of uri 'agranig.demo.sipwise.com' - R=sip:agranig.demo.sipwise.com:5060 ID=2626876779@10.15.20.167
Jun 17 11:49:41 sp2 proxy[12697]: INFO: <script>: IP authorization not provisioned, allow registration - R=sip:agranig.demo.sipwise.com:5060 ID=2626876779@10.15.20.167
Jun 17 11:49:41 sp2 proxy[12697]: NOTICE: <script>: Contacts successfully updated, expires in 3600s - R=sip:agranig.demo.sipwise.com:5060 ID=2626876779@10.15.20.167
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=4 T start=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 26163 label 0 branch 1
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8f0800)!
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 2, id 0 entered
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=5 T end=0x7f421c8f0800
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=180, uac[1]=180 local=0 is_invite=1)
Jun 17 11:49:43 sp2 proxy[12701]: NOTICE: <script>: NAT-Reply - S=200 - OK M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5080) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=5 T start=0x7f421c8f0800
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:43 sp2 proxy[12701]: INFO: <script>: Remove existing ICE candidates (if any) for caller - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12701]: INFO: <script>: Use mediaproxy for backward direction - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12701]: INFO: <script>: Try protocol 'transparent' for caller - R=<null> ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12701]: INFO: <script>: Engaging rtpengine in reply for caller did '50' and callee did '50' - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=200
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=1, save=0, relay=1 icode=0
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 32, id 0 entered
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_reply.c:416]: update_totag_set(): DEBUG: update_totag_set: new totag 
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f0800, callback type 1048576, id 0 entered
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=4 T start=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 42414 label 0 branch 0
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8da308)!
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 2, id 0 entered
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback called for t(0x7f421c8da308) event type 2, reply code 200
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 2, id 0 entered
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=5 T end=0x7f421c8da308
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Jun 17 11:49:43 sp2 proxy[12699]: NOTICE: <script>: NAT-Reply - S=200 - OK M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [uac.c:284]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<sip:127.0.0.1;r2=on;lr=on;ftag=1348576402;nat=yes;ngcplb=yes;socket=udp:92.42.136.48:5060>
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [uac.c:185]: dlg2hash(): DEBUG: dlg2hash: 39335
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=5 global id=5 T start=0x7f421c8da308
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:43 sp2 proxy[12699]: INFO: <script>: Remove existing ICE candidates (if any) for caller - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12699]: INFO: <script>: Use mediaproxy for backward direction - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12699]: INFO: <script>: Try protocol 'transparent' for caller - R=<null> ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12699]: INFO: <script>: Engaging rtpengine in reply for caller did '50' and callee did '50' - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=200
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 32, id 0 entered
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:416]: update_totag_set(): DEBUG: update_totag_set: new totag 
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 1048576, id 0 entered
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8da308, callback type 512, id 0 entered
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback called for t(0x7f421c8da308) event type 512, reply code 200
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:43 sp2 proxy[12702]: NOTICE: <script>: New request on proxy - M=ACK R=sip:127.0.0.1:5085;prxroute=1 F=sip:phone2@agranig.demo.sipwise.com T=sip:0004399111111@agranig.demo.sipwise.com IP=77.244.249.126:46637 (127.0.0.1:5060) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12702]: INFO: <script>: Relaying request, du='<null>' - R=sip:127.0.0.1:5085;prxroute=1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=5 , global msg id=4 , T on entrance=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=42414, isACK=1
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_funcs.c:311]: t_relay_to(): SER: forwarding ACK  statelessly 
Jun 17 11:49:43 sp2 proxy[12695]: NOTICE: <script>: New request on proxy - M=ACK R=sip:25704386@127.0.0.1:5080 F=sip:phone2@agranig.demo.sipwise.com T=sip:test1@agranig.demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12695]: INFO: <script>: Relaying request, du='<null>' - R=sip:25704386@127.0.0.1:5080 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=6 , global msg id=5 , T on entrance=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=26163, isACK=1
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_funcs.c:311]: t_relay_to(): SER: forwarding ACK  statelessly 
Jun 17 11:49:43 sp2 proxy[12696]: NOTICE: <script>: New request on proxy - M=PUBLISH R=sip:test1@demo.sipwise.com F=sip:pbx@app.local T=sip:test1@demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=sip:test1@demo.sipwise.com
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=5 T start=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=52215, isACK=0
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=6 T end=(nil)
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=6 , global msg id=6 , T on entrance=(nil)
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=52215, isACK=0
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8e2e40, callback type 1, id 0 entered
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8e2e40, callback type 1, id 0 entered
Jun 17 11:49:43 sp2 proxy[12696]: NOTICE: <script>: Handling publish request - R=sip:test1@demo.sipwise.com ID=sip:test1@demo.sipwise.com
Jun 17 11:49:43 sp2 proxy[12700]: NOTICE: <script>: New request on proxy - M=INVITE R=sip:127.0.0.1:5085;prxroute=1 F=sip:phone2@agranig.demo.sipwise.com T=sip:0004399111111@agranig.demo.sipwise.com IP=77.244.249.126:46637 (127.0.0.1:5060) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12698]: NOTICE: <script>: New request on proxy - M=PUBLISH R=sip:phone2@agranig.demo.sipwise.com F=sip:pbx@app.local T=sip:phone2@agranig.demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=sip:phone2@agranig.demo.sipwise.com
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=4 T start=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=14870, isACK=0
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=6 T end=(nil)
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=6 , global msg id=6 , T on entrance=(nil)
Jun 17 11:49:43 sp2 proxy[12700]: INFO: <script>: Not switching caller did and callee did for downstream in-dialog, caller did is '50' and callee did is '50' - R=sip:127.0.0.1:5085;prxroute=1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=14870, isACK=0
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=6 T start=0x7f421c8e2e40
Jun 17 11:49:43 sp2 proxy[12700]: INFO: <script>: Remove existing ICE candidates (if any) for callee - R=sip:127.0.0.1:5085;prxroute=1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8fe388, callback type 1, id 0 entered
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f4237d6ceb0: SIP/2.0 200 OK#015#012Via:..., shmem=0x7f421c8e6310: SIP/2.0 200 OK#015#012Via:
Jun 17 11:49:43 sp2 proxy[12700]: INFO: <script>: Engage rtpengine for in-dialog request, caller did is '50' and callee did is '50' - R=sip:127.0.0.1:5085;prxroute=1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8fe388, callback type 1, id 0 entered
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=6 T start=0x7f421c8e2e40
Jun 17 11:49:43 sp2 proxy[12698]: NOTICE: <script>: Handling publish request - R=sip:phone2@agranig.demo.sipwise.com ID=sip:phone2@agranig.demo.sipwise.com
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_funcs.c:180]: put_on_wait(): tm: put_on_wait: transaction 0x7f421c8e2e40 already on wait
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=6 T start=0x7f421c8fe388
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f4237d39ff8: SIP/2.0 200 OK#015#012Via:..., shmem=0x7f421c8e6588: SIP/2.0 200 OK#015#012Via:
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=6 T start=0x7f421c8fe388
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_funcs.c:180]: put_on_wait(): tm: put_on_wait: transaction 0x7f421c8fe388 already on wait
Jun 17 11:49:43 sp2 proxy[12700]: INFO: <script>: Relaying request, du='<null>' - R=sip:127.0.0.1:5085;prxroute=1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=6 , global msg id=5 , T on entrance=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=42411, isACK=0
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c900dd8, callback type 1, id 0 entered
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c900dd8, callback type 1, id 0 entered
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=4 T start=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 42411 label 0 branch 0
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c900dd8)!
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c900dd8, callback type 2, id 0 entered
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=6 T end=0x7f421c900dd8
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=1)
Jun 17 11:49:43 sp2 proxy[12697]: NOTICE: <script>: NAT-Reply - S=100 - Trying M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=100
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=-1 icode=0
Jun 17 11:49:43 sp2 proxy[12701]: NOTICE: <script>: New request on proxy - M=INVITE R=sip:25704386@127.0.0.1:5080 F=sip:phone2@agranig.demo.sipwise.com T=sip:test1@agranig.demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12701]: INFO: <script>: Not switching caller did and callee did for downstream in-dialog, caller did is '50' and callee did is '50' - R=sip:25704386@127.0.0.1:5080 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12701]: INFO: <script>: Remove existing ICE candidates (if any) for callee - R=sip:25704386@127.0.0.1:5080 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12701]: INFO: <script>: Engage rtpengine for in-dialog request, caller did is '50' and callee did is '50' - R=sip:25704386@127.0.0.1:5080 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12701]: INFO: <script>: Relaying request, du='<null>' - R=sip:25704386@127.0.0.1:5080 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=6 , global msg id=5 , T on entrance=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=26164, isACK=0
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c905490, callback type 1, id 0 entered
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c905490, callback type 1, id 0 entered
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=5 T start=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 26164 label 0 branch 0
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c905490)!
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c905490, callback type 2, id 0 entered
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c905490, callback type 2, id 0 entered
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=6 T end=0x7f421c905490
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=1)
Jun 17 11:49:43 sp2 proxy[12699]: NOTICE: <script>: NAT-Reply - S=100 - Trying M=INVITE IP=127.0.0.1:5085 (127.0.0.1:5080) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=100
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=-1 icode=0
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=5 T start=(nil)
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 26164 label 0 branch 0
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c905490)!
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c905490, callback type 2, id 0 entered
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c905490, callback type 2, id 0 entered
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=6 T end=0x7f421c905490
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=100 local=0 is_invite=1)
Jun 17 11:49:43 sp2 proxy[12702]: NOTICE: <script>: NAT-Reply - S=200 - OK M=INVITE IP=127.0.0.1:5085 (127.0.0.1:5080) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=6 global id=6 T start=0x7f421c905490
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:43 sp2 proxy[12702]: INFO: <script>: Remove existing ICE candidates (if any) for caller - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12702]: INFO: <script>: Use mediaproxy for backward direction - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12702]: INFO: <script>: Engaging rtpengine in reply for caller did '50' and callee did '50' - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0
Jun 17 11:49:43 sp2 proxy[12702]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=6 T start=(nil)
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 42411 label 0 branch 0
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c900dd8)!
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c900dd8, callback type 2, id 0 entered
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=7 T end=0x7f421c900dd8
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=100 local=0 is_invite=1)
Jun 17 11:49:43 sp2 proxy[12695]: NOTICE: <script>: NAT-Reply - S=200 - OK M=INVITE IP=77.244.249.126:46637 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [uac.c:284]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<sip:127.0.0.1;r2=on;lr=on;ftag=1348576402;nat=yes;ngcplb=yes;socket=udp:92.42.136.48:5060>
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [uac.c:185]: dlg2hash(): DEBUG: dlg2hash: 39336
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=7 T start=0x7f421c900dd8
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:43 sp2 proxy[12695]: INFO: <script>: Remove existing ICE candidates (if any) for caller - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12695]: INFO: <script>: Use mediaproxy for backward direction - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12695]: INFO: <script>: Engaging rtpengine in reply for caller did '50' and callee did '50' - ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0
Jun 17 11:49:43 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:43 sp2 proxy[12696]: NOTICE: <script>: New request on proxy - M=ACK R=sip:127.0.0.1:5085;prxroute=1 F=sip:phone2@agranig.demo.sipwise.com T=sip:0004399111111@agranig.demo.sipwise.com IP=77.244.249.126:46637 (127.0.0.1:5060) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12696]: INFO: <script>: Relaying request, du='<null>' - R=sip:127.0.0.1:5085;prxroute=1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=7 , global msg id=6 , T on entrance=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=42411, isACK=1
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12696]: DEBUG: tm [t_funcs.c:311]: t_relay_to(): SER: forwarding ACK  statelessly 
Jun 17 11:49:43 sp2 proxy[12698]: NOTICE: <script>: New request on proxy - M=ACK R=sip:25704386@127.0.0.1:5080 F=sip:phone2@agranig.demo.sipwise.com T=sip:test1@agranig.demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12698]: INFO: <script>: Relaying request, du='<null>' - R=sip:25704386@127.0.0.1:5080 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=7 , global msg id=6 , T on entrance=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=26164, isACK=1
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12698]: DEBUG: tm [t_funcs.c:311]: t_relay_to(): SER: forwarding ACK  statelessly 
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=6 T start=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 39335 label 0 branch 0
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8f5ec0)!
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=7 T end=0x7f421c8f5ec0
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_reply.c:2076]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_reply.c:2113]: local_reply(): DEBUG: local transaction completed
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8f5ec0, callback type 1024, id 0 entered
Jun 17 11:49:43 sp2 proxy[12700]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=6 T start=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 39336 label 0 branch 0
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c909330)!
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=7 T end=0x7f421c909330
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_reply.c:2076]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_reply.c:2113]: local_reply(): DEBUG: local transaction completed
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c909330, callback type 1024, id 0 entered
Jun 17 11:49:43 sp2 proxy[12697]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:43 sp2 proxy[12701]: NOTICE: <script>: New request on proxy - M=SUBSCRIBE R=sip:phone2@agranig.demo.sipwise.com F=sip:phone2@agranig.demo.sipwise.com T=sip:phone2@agranig.demo.sipwise.com IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1577110477@10.15.20.167
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=6 T start=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=11193, isACK=0
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=7 T end=(nil)
Jun 17 11:49:43 sp2 proxy[12701]: NOTICE: <script>: Handling subscribe request for event 'call-info' - R=sip:phone2@agranig.demo.sipwise.com ID=1577110477@10.15.20.167
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [uac.c:284]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<sip:127.0.0.1;r2=on;lr=on;ftag=1348576402;nat=yes;ngcplb=yes;socket=udp:92.42.136.48:5060>
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [uac.c:185]: dlg2hash(): DEBUG: dlg2hash: 39333
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=7 T start=(nil)
Jun 17 11:49:43 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1147]: t_check_msg(): DEBUG: t_check_msg: T previously sought and not found
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=6 T start=0xffffffffffffffff
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 39333 label 0 branch 0
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c90c238)!
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=7 T end=0x7f421c90c238
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:2076]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:2113]: local_reply(): DEBUG: local transaction completed
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c90c238, callback type 1024, id 0 entered
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:44 sp2 proxy[12702]: NOTICE: <script>: New request on proxy - M=SUBSCRIBE R=sip:phone2@agranig.demo.sipwise.com F=sip:phone2@agranig.demo.sipwise.com T=sip:phone2@agranig.demo.sipwise.com IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1577110477@10.15.20.167
Jun 17 11:49:44 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=6 T start=0xffffffffffffffff
Jun 17 11:49:44 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=11193, isACK=0
Jun 17 11:49:44 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:44 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:44 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=7 T end=(nil)
Jun 17 11:49:44 sp2 proxy[12702]: NOTICE: <script>: Handling subscribe request for event 'call-info' - R=sip:phone2@agranig.demo.sipwise.com ID=1577110477@10.15.20.167
Jun 17 11:49:44 sp2 proxy[12702]: DEBUG: tm [uac.c:284]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<sip:127.0.0.1;r2=on;lr=on;ftag=1348576402;nat=yes;ngcplb=yes;socket=udp:92.42.136.48:5060>
Jun 17 11:49:44 sp2 proxy[12702]: DEBUG: tm [uac.c:185]: dlg2hash(): DEBUG: dlg2hash: 39334
Jun 17 11:49:44 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=7 global id=7 T start=(nil)
Jun 17 11:49:44 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1147]: t_check_msg(): DEBUG: t_check_msg: T previously sought and not found
Jun 17 11:49:44 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=7 T start=0xffffffffffffffff
Jun 17 11:49:44 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 39334 label 0 branch 0
Jun 17 11:49:44 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c90d878)!
Jun 17 11:49:44 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=8 T end=0x7f421c90d878
Jun 17 11:49:44 sp2 proxy[12695]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jun 17 11:49:44 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:44 sp2 proxy[12695]: DEBUG: tm [t_reply.c:2076]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0
Jun 17 11:49:44 sp2 proxy[12695]: DEBUG: tm [t_reply.c:2113]: local_reply(): DEBUG: local transaction completed
Jun 17 11:49:44 sp2 proxy[12695]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c90d878, callback type 1024, id 0 entered
Jun 17 11:49:44 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:45 sp2 proxy[12696]: NOTICE: <script>: New request on proxy - M=SUBSCRIBE R=sip:phone2@agranig.demo.sipwise.com F=sip:phone2@agranig.demo.sipwise.com T=sip:phone2@agranig.demo.sipwise.com IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1577110477@10.15.20.167
Jun 17 11:49:45 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=7 T start=(nil)
Jun 17 11:49:45 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=11193, isACK=0
Jun 17 11:49:45 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:45 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:45 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=8 T end=(nil)
Jun 17 11:49:45 sp2 proxy[12696]: NOTICE: <script>: Handling subscribe request for event 'call-info' - R=sip:phone2@agranig.demo.sipwise.com ID=1577110477@10.15.20.167
Jun 17 11:49:45 sp2 proxy[12696]: DEBUG: tm [uac.c:284]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<sip:127.0.0.1;r2=on;lr=on;ftag=1348576402;nat=yes;ngcplb=yes;socket=udp:92.42.136.48:5060>
Jun 17 11:49:45 sp2 proxy[12696]: DEBUG: tm [uac.c:185]: dlg2hash(): DEBUG: dlg2hash: 39331
Jun 17 11:49:45 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=8 T start=(nil)
Jun 17 11:49:45 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1147]: t_check_msg(): DEBUG: t_check_msg: T previously sought and not found
Jun 17 11:49:45 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=7 T start=(nil)
Jun 17 11:49:45 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 39331 label 0 branch 0
Jun 17 11:49:45 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c90ef40)!
Jun 17 11:49:45 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=8 T end=0x7f421c90ef40
Jun 17 11:49:45 sp2 proxy[12698]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jun 17 11:49:45 sp2 proxy[12698]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:45 sp2 proxy[12698]: DEBUG: tm [t_reply.c:2076]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0
Jun 17 11:49:45 sp2 proxy[12698]: DEBUG: tm [t_reply.c:2113]: local_reply(): DEBUG: local transaction completed
Jun 17 11:49:45 sp2 proxy[12698]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c90ef40, callback type 1024, id 0 entered
Jun 17 11:49:45 sp2 proxy[12698]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:45 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=7 T start=0xffffffffffffffff
Jun 17 11:49:45 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1046]: t_reply_matching(): DEBUG: t_reply_matching: failure to match a transaction
Jun 17 11:49:45 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=8 T end=(nil)
Jun 17 11:49:46 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=7 T start=0xffffffffffffffff
Jun 17 11:49:46 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1046]: t_reply_matching(): DEBUG: t_reply_matching: failure to match a transaction
Jun 17 11:49:46 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=8 T end=(nil)
Jun 17 11:49:47 sp2 proxy[12701]: NOTICE: <script>: New request on proxy - M=SUBSCRIBE R=sip:phone2@agranig.demo.sipwise.com F=sip:phone2@agranig.demo.sipwise.com T=sip:phone2@agranig.demo.sipwise.com IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1577110477@10.15.20.167
Jun 17 11:49:47 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=7 T start=(nil)
Jun 17 11:49:47 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=11193, isACK=0
Jun 17 11:49:47 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:47 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:47 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=8 T end=(nil)
Jun 17 11:49:47 sp2 proxy[12701]: NOTICE: <script>: Handling subscribe request for event 'call-info' - R=sip:phone2@agranig.demo.sipwise.com ID=1577110477@10.15.20.167
Jun 17 11:49:47 sp2 proxy[12701]: DEBUG: tm [uac.c:284]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<sip:127.0.0.1;r2=on;lr=on;ftag=1348576402;nat=yes;ngcplb=yes;socket=udp:92.42.136.48:5060>
Jun 17 11:49:47 sp2 proxy[12701]: DEBUG: tm [uac.c:185]: dlg2hash(): DEBUG: dlg2hash: 39332
Jun 17 11:49:47 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=8 T start=(nil)
Jun 17 11:49:47 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1147]: t_check_msg(): DEBUG: t_check_msg: T previously sought and not found
Jun 17 11:49:47 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=7 T start=0xffffffffffffffff
Jun 17 11:49:47 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 39332 label 0 branch 0
Jun 17 11:49:47 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c910988)!
Jun 17 11:49:47 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=8 T end=0x7f421c910988
Jun 17 11:49:47 sp2 proxy[12699]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jun 17 11:49:47 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:47 sp2 proxy[12699]: DEBUG: tm [t_reply.c:2076]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0
Jun 17 11:49:47 sp2 proxy[12699]: DEBUG: tm [t_reply.c:2113]: local_reply(): DEBUG: local transaction completed
Jun 17 11:49:47 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c910988, callback type 1024, id 0 entered
Jun 17 11:49:47 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:47 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=7 T start=(nil)
Jun 17 11:49:47 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1046]: t_reply_matching(): DEBUG: t_reply_matching: failure to match a transaction
Jun 17 11:49:47 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=8 global id=8 T end=(nil)
Jun 17 11:49:49 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=8 T start=0xffffffffffffffff
Jun 17 11:49:49 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1046]: t_reply_matching(): DEBUG: t_reply_matching: failure to match a transaction
Jun 17 11:49:49 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=9 T end=(nil)
Jun 17 11:49:50 sp2 proxy[12696]: NOTICE: <script>: New request on proxy - M=NOTIFY R=sip:92.42.136.48 F=sip:test1@demo.sipwise.com T=sip:92.42.136.48 IP=77.244.249.126:6774 (127.0.0.1:5060) ID=b23c1351-c0b54bc@10.15.20.112
Jun 17 11:49:51 sp2 proxy[12698]: NOTICE: <script>: New request on proxy - M=SUBSCRIBE R=sip:phone2@agranig.demo.sipwise.com F=sip:phone2@agranig.demo.sipwise.com T=sip:phone2@agranig.demo.sipwise.com IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1577110477@10.15.20.167
Jun 17 11:49:51 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=8 T start=0xffffffffffffffff
Jun 17 11:49:51 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=11193, isACK=0
Jun 17 11:49:51 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:51 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:51 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=9 T end=(nil)
Jun 17 11:49:51 sp2 proxy[12698]: NOTICE: <script>: Handling subscribe request for event 'call-info' - R=sip:phone2@agranig.demo.sipwise.com ID=1577110477@10.15.20.167
Jun 17 11:49:51 sp2 proxy[12698]: DEBUG: tm [uac.c:284]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<sip:127.0.0.1;r2=on;lr=on;ftag=1348576402;nat=yes;ngcplb=yes;socket=udp:92.42.136.48:5060>
Jun 17 11:49:51 sp2 proxy[12698]: DEBUG: tm [uac.c:185]: dlg2hash(): DEBUG: dlg2hash: 39346
Jun 17 11:49:51 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=9 T start=(nil)
Jun 17 11:49:51 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1147]: t_check_msg(): DEBUG: t_check_msg: T previously sought and not found
Jun 17 11:49:51 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=8 T start=(nil)
Jun 17 11:49:51 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 39346 label 0 branch 0
Jun 17 11:49:51 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c90c238)!
Jun 17 11:49:51 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=9 T end=0x7f421c90c238
Jun 17 11:49:51 sp2 proxy[12700]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jun 17 11:49:51 sp2 proxy[12700]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:51 sp2 proxy[12700]: DEBUG: tm [t_reply.c:2076]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0
Jun 17 11:49:51 sp2 proxy[12700]: DEBUG: tm [t_reply.c:2113]: local_reply(): DEBUG: local transaction completed
Jun 17 11:49:51 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c90c238, callback type 1024, id 0 entered
Jun 17 11:49:51 sp2 proxy[12700]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12697]: NOTICE: <script>: New request on proxy - M=BYE R=sip:127.0.0.1:5085;prxroute=1 F=sip:phone2@agranig.demo.sipwise.com T=sip:0004399111111@agranig.demo.sipwise.com IP=77.244.249.126:46637 (127.0.0.1:5060) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:52 sp2 proxy[12697]: INFO: <script>: removed redis counters - R=sip:127.0.0.1:5085;prxroute=1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:52 sp2 proxy[12697]: INFO: <script>: Stop mediaproxy for all branches, caller did is '50' and callee did is '50' - R=sip:127.0.0.1:5085;prxroute=1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:52 sp2 proxy[12697]: ERROR: sca [sca_call_info.c:1582]: sca_call_info_bye_handler(): sca_call_info_bye_handler: sip:phone2@agranig.demo.sipwise.com dialog leg rOemTINsCbQspe1Vlje9nAK15SNy0DdV;.gX8uom0bP5ROJMaEt1lxZbQpmknoGxP is not active
Jun 17 11:49:52 sp2 proxy[12697]: ERROR: sca [sca_call_info.c:2006]: sca_call_info_update(): Failed to update Call-Info state for 
Jun 17 11:49:52 sp2 proxy[12697]: INFO: <script>: Relaying request, du='<null>' - R=sip:127.0.0.1:5085;prxroute=1 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:52 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=9 , global msg id=8 , T on entrance=(nil)
Jun 17 11:49:52 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=42412, isACK=0
Jun 17 11:49:52 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:52 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:52 sp2 proxy[12697]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8ce000, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12697]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8ce000, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12697]: DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed
Jun 17 11:49:52 sp2 proxy[12701]: NOTICE: <script>: New request on proxy - M=BYE R=sip:25704386@127.0.0.1:5080 F=sip:phone2@agranig.demo.sipwise.com T=sip:test1@agranig.demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:52 sp2 proxy[12701]: INFO: <script>: removed redis counters - R=sip:25704386@127.0.0.1:5080 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:52 sp2 proxy[12701]: INFO: <script>: Stop mediaproxy for all branches, caller did is '50' and callee did is '50' - R=sip:25704386@127.0.0.1:5080 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:52 sp2 proxy[12701]: INFO: <script>: Relaying request, du='<null>' - R=sip:25704386@127.0.0.1:5080 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:52 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=9 , global msg id=8 , T on entrance=(nil)
Jun 17 11:49:52 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=26161, isACK=0
Jun 17 11:49:52 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:52 sp2 proxy[12701]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:52 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8d2998, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12701]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8d2998, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12701]: DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=8 T start=0xffffffffffffffff
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 26161 label 0 branch 0
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8d2998)!
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8d2998, callback type 2, id 0 entered
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback called for t(0x7f421c8d2998) event type 2, reply code 200
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8d2998, callback type 2, id 0 entered
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8d2998, callback type 2, id 0 entered
Jun 17 11:49:52 sp2 proxy[12702]: NOTICE: <script>: New request on proxy - M=PUBLISH R=sip:phone2@agranig.demo.sipwise.com F=sip:pbx@app.local T=sip:phone2@agranig.demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=sip:phone2@agranig.demo.sipwise.com
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=9 T end=0x7f421c8d2998
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=8 T start=(nil)
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=14871, isACK=0
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:52 sp2 proxy[12699]: NOTICE: <script>: NAT-Reply - S=200 - OK M=BYE IP=127.0.0.1:5085 (127.0.0.1:5080) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=9 T end=(nil)
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=9 , global msg id=9 , T on entrance=(nil)
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=14871, isACK=0
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8edc90, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8d2998, callback type 512, id 0 entered
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8edc90, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback called for t(0x7f421c8d2998) event type 512, reply code 200
Jun 17 11:49:52 sp2 proxy[12702]: NOTICE: <script>: Handling publish request - R=sip:phone2@agranig.demo.sipwise.com ID=sip:phone2@agranig.demo.sipwise.com
Jun 17 11:49:52 sp2 proxy[12695]: NOTICE: <script>: New request on proxy - M=PUBLISH R=sip:test1@demo.sipwise.com F=sip:pbx@app.local T=sip:test1@demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=sip:test1@demo.sipwise.com
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=9 T start=(nil)
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=52212, isACK=0
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T end=(nil)
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=10 , global msg id=10 , T on entrance=(nil)
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=52212, isACK=0
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8f0b00, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8f0b00, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12695]: NOTICE: <script>: Handling publish request - R=sip:test1@demo.sipwise.com ID=sip:test1@demo.sipwise.com
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8d2998, callback type 512, id 0 entered
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=9 T start=0x7f421c8edc90
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f4237d3ca18: SIP/2.0 200 OK#015#012Via:..., shmem=0x7f421c8f3538: SIP/2.0 200 OK#015#012Via:
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=9 T start=0x7f421c8edc90
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12702]: DEBUG: tm [t_funcs.c:180]: put_on_wait(): tm: put_on_wait: transaction 0x7f421c8edc90 already on wait
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T start=0x7f421c8f0b00
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f4237cf0420: SIP/2.0 200 OK#015#012Via:..., shmem=0x7f421c8f37c0: SIP/2.0 200 OK#015#012Via:
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T start=0x7f421c8f0b00
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12695]: DEBUG: tm [t_funcs.c:180]: put_on_wait(): tm: put_on_wait: transaction 0x7f421c8f0b00 already on wait
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=8 T start=(nil)
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 42412 label 0 branch 0
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f421c8ce000)!
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8ce000, callback type 2, id 0 entered
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback called for t(0x7f421c8ce000) event type 2, reply code 200
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8ce000, callback type 2, id 0 entered
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T end=0x7f421c8ce000
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_reply.c:2196]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Jun 17 11:49:52 sp2 proxy[12696]: NOTICE: <script>: NAT-Reply - S=200 - OK M=BYE IP=77.244.249.126:46637 (127.0.0.1:5085) ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_reply.c:1812]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8ce000, callback type 512, id 0 entered
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback called for t(0x7f421c8ce000) event type 512, reply code 200
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f421c8ce000, callback type 512, id 0 entered
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12698]: NOTICE: <script>: New request on proxy - M=PUBLISH R=sip:test1@demo.sipwise.com F=sip:pbx@app.local T=sip:test1@demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=sip:test1@demo.sipwise.com
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=9 T start=(nil)
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=52213, isACK=0
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T end=(nil)
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=10 , global msg id=10 , T on entrance=(nil)
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=52213, isACK=0
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8e2e40, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8e2e40, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12698]: NOTICE: <script>: Handling publish request - R=sip:test1@demo.sipwise.com ID=sip:test1@demo.sipwise.com
Jun 17 11:49:52 sp2 proxy[12700]: NOTICE: <script>: New request on proxy - M=PUBLISH R=sip:phone2@agranig.demo.sipwise.com F=sip:pbx@app.local T=sip:phone2@agranig.demo.sipwise.com IP=127.0.0.1:5085 (127.0.0.1:5085) ID=sip:phone2@agranig.demo.sipwise.com
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=9 T start=0xffffffffffffffff
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=14868, isACK=0
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T end=(nil)
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=10 , global msg id=10 , T on entrance=(nil)
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=14868, isACK=0
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8e5688, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f421c8e5688, callback type 1, id 0 entered
Jun 17 11:49:52 sp2 proxy[12700]: NOTICE: <script>: Handling publish request - R=sip:phone2@agranig.demo.sipwise.com ID=sip:phone2@agranig.demo.sipwise.com
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T start=0x7f421c8e2e40
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T start=0x7f421c8e5688
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f4237d39ff8: SIP/2.0 200 OK#015#012Via:..., shmem=0x7f421c8f4658: SIP/2.0 200 OK#015#012Via:
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T start=0x7f421c8e2e40
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12698]: DEBUG: tm [t_funcs.c:180]: put_on_wait(): tm: put_on_wait: transaction 0x7f421c8e2e40 already on wait
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f4237cd1c40: SIP/2.0 200 OK#015#012Via:..., shmem=0x7f421c8f48d0: SIP/2.0 200 OK#015#012Via:
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T start=0x7f421c8e5688
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_lookup.c:1144]: t_check_msg(): DEBUG: t_check_msg: T already found!
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jun 17 11:49:52 sp2 proxy[12700]: DEBUG: tm [t_funcs.c:180]: put_on_wait(): tm: put_on_wait: transaction 0x7f421c8e5688 already on wait
Jun 17 11:49:52 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=9 T start=0xffffffffffffffff
Jun 17 11:49:52 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1046]: t_reply_matching(): DEBUG: t_reply_matching: failure to match a transaction
Jun 17 11:49:52 sp2 proxy[12697]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=10 global id=10 T end=(nil)