[Jan 22 01:02:32] VERBOSE[17499] res_pjsip_logger.c: <--- Received SIP request (1354 bytes) from UDP:196.216.192.5:5060 --->
INVITE sip:0114551322@vpbx4.switchtel.co.za;transport=udp SIP/2.0
Via: SIP/2.0/UDP 196.216.192.5:5060;branch=z9hG4bK720d.ec6eb4f1.0
From: Greg <sip:swt11@vpbx2.switchtel.co.za>;tag=56656018
To: <sip:0114551322@vpbx2.switchtel.co.za>
Call-ID: 1441272955-5060-3024@BJC.BGI.B.BF
CSeq: 291 INVITE
Contact: <sip:196.216.192.5;did=cd9.a7c6cc57>
X-Grandstream-PBX: true
Max-Forwards: 69
User-Agent: Grandstream GXP2170 1.0.11.10
Privacy: none
P-Preferred-Identity: "Greg #11" <sip:swt11@vpbx2.switchtel.co.za>
P-Access-Network-Info: IEEE-EUI-48;eui-48-addr=D4-CA-6D-2A-BD-BB
P-Emergency-Info: IEEE-EUI-48;eui-48-addr=00-0B-82-AD-66-F7
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length: 451
X-VPBX-Vars: 4;509;swt;11;swt11

v=0
o=swt11 8000 8000 IN IP4 196.216.192.5
s=SIP Call
c=IN IP4 196.216.192.5
t=0 0
m=audio 34342 RTP/AVP 8 0 18 4 9 97 2 125 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=rtpmap:4 G723/8000
a=rtpmap:9 G722/8000
a=rtpmap:97 iLBC/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:125 opus/48000/2
a=rtpmap:101 telephone-event/8000
a=fmtp:18 annexb=no
a=fmtp:97 mode=30
a=fmtp:101 0-15
a=sendrecv
a=rtcp:34343
a=ptime:20

[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_message_filter.c: Set transport 'transport-udp' on INVITE from 196.216.192.5:0
[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=291 (rdata0x7fd020000dc8)
[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004b to use for Request msg INVITE/cseq=291 (rdata0x7fd020000dc8)
[Jan 22 01:02:32] DEBUG[17489] threadpool.c: Increasing threadpool pjsip/pool's size by 4
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.5' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.5' and port ''.
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'swt11' domain 'vpbx2.switchtel.co.za'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_endpoint_identifier_user.c: Identified by From username 'swt11' domain 'vpbx2.switchtel.co.za'
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.5' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.5' and port ''.
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004b to use for Request msg INVITE/cseq=291 (rdata0x7fd0200231d8)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Call (UDP:196.216.192.5:5060) to extension '0114551322' sending 100 Trying
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Method is INVITE, Response is 100 Trying
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '196.216.192.5'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_resolver.c: Transport type for target '196.216.192.5' is 'UDP transport'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_resolver.c: Target '196.216.192.5' is an IP address, skipping resolution
[Jan 22 01:02:32] VERBOSE[23526] res_pjsip_logger.c: <--- Transmitting SIP response (322 bytes) to UDP:196.216.192.5:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 196.216.192.5:5060;received=196.216.192.5;branch=z9hG4bK720d.ec6eb4f1.0
Call-ID: 1441272955-5060-3024@BJC.BGI.B.BF
From: "Greg" <sip:swt11@vpbx2.switchtel.co.za>;tag=56656018
To: <sip:0114551322@vpbx2.switchtel.co.za>
CSeq: 291 INVITE
Server: SwitchTelecom
Content-Length:  0


[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11()'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd09801c7c8)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is INCOMING
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: swt11: Source of transaction state change is TX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11()'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd09801c7c8)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fd09801c7c8
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is INCOMING
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Media count: 1
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Processing stream 0
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Using audio-0 for new stream name
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Using new stream 0:audio-0:audio:sendrecv (nothing)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11 Adding position 0
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  Creating new media session
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  Setting media session as default for audio
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  Done
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.5' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.5' and port ''.
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.22' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.22' and port ''.
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_sdp_rtp.c: Endpoint swt11: Binding RTP media to 196.216.192.22
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fd07c020430'
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) RTP allocated port 17738
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) ICE creating session 196.216.192.22:17738 (17738)
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) ICE create
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) ICE add system candidates
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.22' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.22' and port ''.
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) ICE add candidate: 196.216.192.22:17738, 2130706431
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.20' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.20' and port ''.
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) ICE add candidate: 196.216.192.20:17738, 2130706431
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.7' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.7' and port ''.
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) ICE add candidate: 196.216.192.7:17738, 2130706431
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: RTP instance '0x7fd07c020430' is setup and ready to go
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) ICE stopped
[Jan 22 01:02:32] DEBUG[23526] acl.c: Attached to given IP address
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) RTCP setup on RTP instance
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 4 based on m type on 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Don't have a default tx payload type 2 format for m type on 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7fd07c0203a8) from 0x7fd0c32f91c0 to 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Crossover copying tx to rx payload mapping 2 (0x7fd07c01ee18) from 0x7fd0c32f91c0 to 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Crossover copying tx to rx payload mapping 4 (0x7fd07c01ec18) from 0x7fd0c32f91c0 to 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7fd07c024688) from 0x7fd0c32f91c0 to 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Crossover copying tx to rx payload mapping 9 (0x7fd07c01ed78) from 0x7fd0c32f91c0 to 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7fd07c01ebc8) from 0x7fd0c32f91c0 to 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Crossover copying tx to rx payload mapping 97 (0x7fd07c01eeb8) from 0x7fd0c32f91c0 to 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x7fd07c025378) from 0x7fd0c32f91c0 to 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Crossover copying tx to rx payload mapping 125 (0x7fd07c01edc8) from 0x7fd0c32f91c0 to 0x7fd0c32f91c0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying rx payload mapping 0 (0x7fd07c0203a8) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying rx payload mapping 2 (0x7fd07c01ee18) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying rx payload mapping 4 (0x7fd07c01ec18) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying rx payload mapping 8 (0x7fd07c024688) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying rx payload mapping 9 (0x7fd07c01ed78) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying rx payload mapping 18 (0x7fd07c01ebc8) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying rx payload mapping 97 (0x7fd07c01eeb8) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying rx payload mapping 101 (0x7fd07c025378) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying rx payload mapping 125 (0x7fd07c01edc8) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 0 (0x7fd07c0203a8) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 2 (0x7fd07c01ee18) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 4 (0x7fd07c01ec18) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 8 (0x7fd07c024688) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 9 (0x7fd07c01ed78) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 18 (0x7fd07c01ebc8) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 97 (0x7fd07c01eeb8) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 101 (0x7fd07c025378) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 125 (0x7fd07c01edc8) from 0x7fd0c32f91c0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Media stream 0:audio-0:audio:sendrecv (alaw|ulaw|g729) handled by audio
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Done with stream 0:audio-0:audio:sendrecv (alaw|ulaw|g729)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Handled? yes
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Processing streams
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Processing stream 0:audio-0:audio:sendrecv (alaw|ulaw|g729)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11 Adding position 0
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  Using existing media_session
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) RTCP ignoring duplicate property
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Stream 0:audio-0:audio:sendrecv (alaw|ulaw|g729) added
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Done with 0:audio-0:audio:sendrecv (alaw|ulaw|g729)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Adding bundle groups (if available)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Copying connection details
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Processing media 0
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Media 0 reset
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  swt11: Method is INVITE
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  swt11
[Jan 22 01:02:32] DEBUG[23526] stasis.c: Creating topic. name: channel:1611270152.0, detail: 
[Jan 22 01:02:32] DEBUG[23526] stasis.c: Topic 'channel:1611270152.0': 0x7fd07c025190 created
[Jan 22 01:02:32] DEBUG[23526] stasis.c: Creating topic. name: cache:32/channel:1611270152.0, detail: 
[Jan 22 01:02:32] DEBUG[23526] stasis.c: Topic 'cache:32/channel:1611270152.0': 0x7fd07c0278a0 created
[Jan 22 01:02:32] DEBUG[23526] channel.c: Channel 0x7fd07c02a770 'PJSIP/swt11-00000000' allocated
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function PJSIP_HEADER(read,"X-VPBX-Vars) result is '4;509;swt;11;swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [0114551322@swvpbx-internal:1] Set("PJSIP/swt11-00000000", "PROXY_VARS=4;509;swt;11;swt11") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CHANNEL(endpoint) result is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [0114551322@swvpbx-internal:2] Set("PJSIP/swt11-00000000", "EXT_USERNAME=swt11") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXTEN' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_strings.c: c1=43, consumed=1, args.allowed=+0-9
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_strings.c: c1=48, c2=57
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_strings.c: Allowed: +0123456789
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function FILTER(+0-9,0114551322) result is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Goto'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [0114551322@swvpbx-internal:3] Goto("PJSIP/swt11-00000000", "swvpbx-dialout-routing,0114551322,1") in new stack
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx_builtins.c: Goto (swvpbx-dialout-routing,0114551322,1)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXTEN' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Gosub'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [0114551322@swvpbx-dialout-routing:1] Gosub("PJSIP/swt11-00000000", "swvpbx-sub-dialout,s,1(0114551322,national)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Channel PJSIP/swt11-00000000 has no datastore, so we're allocating one.
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG2' to 'national'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:1] NoOp("PJSIP/swt11-00000000", "Common processing for all number types") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:2] NoOp("PJSIP/swt11-00000000", "number being processed = 0114551322") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'national'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:3] NoOp("PJSIP/swt11-00000000", "destination = national") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'IGNORE_EXT_CALL_BARRING' is NULL
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:4] NoOp("PJSIP/swt11-00000000", "Ignore Call Barring (1-yes, 0-no): ") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Gosub'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:5] Gosub("PJSIP/swt11-00000000", "swvpbx-set-default-vpbx-trunk,s,1") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG2' to ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-default-vpbx-trunk:1] NoOp("PJSIP/swt11-00000000", "Attempting to set default trunk id and clid on trunk") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CHANNEL(accountcode) result is 'swt'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-default-vpbx-trunk:2] Set("PJSIP/swt11-00000000", "VPBX_NAME=swt") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBX_NAME' is 'swt'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is 'swt'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(swt) result is 'swt'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 7 for column 'vpbx_id' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_VPBX_ID("swt") result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-default-vpbx-trunk:3] ExecIf("PJSIP/swt11-00000000", "["VPBXID"=""]?Set(VPBXID=4)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}' AND `vpbxTrunks_isPrimary` = '1'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 8 for column 'trunk_id' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_VPBX_PRIMARY_TRUNK_ID("4") result is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-default-vpbx-trunk:4] Set("PJSIP/swt11-00000000", "DEFAULT_TRUNK_ID=6") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DEFAULT_TRUNK_ID' is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(6) result is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 4 for column 'clid' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_TRUNK_CLID("6") result is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-default-vpbx-trunk:5] Set("PJSIP/swt11-00000000", "DEFAULT_TRUNKCID=0875500000") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Return'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-default-vpbx-trunk:6] Return("PJSIP/swt11-00000000", "") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DEFAULT_TRUNKCID' is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:6] NoOp("PJSIP/swt11-00000000", "Default trunk cid of the vpbx: 0875500000") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:7] Set("PJSIP/swt11-00000000", "NUMBER_DIALLED=0114551322") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'national'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:8] Set("PJSIP/swt11-00000000", "DESTINATION=national") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:9] NoOp("PJSIP/swt11-00000000", "Check if vpbx suspended or cancelled") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Gosub'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:10] Gosub("PJSIP/swt11-00000000", "swvpbx-sub-check-vpbx-suspended-cancelled,s,1(4)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG2' to ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-check-vpbx-suspended-cancelled:1] Set("PJSIP/swt11-00000000", "VPBX_ID=4") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBX_ID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 9 for column 'suspended' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_VPBX_SUSPENDED("4") result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-check-vpbx-suspended-cancelled:2] Set("PJSIP/swt11-00000000", "VPBX_SUSPENDED=0") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBX_ID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 9 for column 'cancelled' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_VPBX_CANCELLED("4") result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-check-vpbx-suspended-cancelled:3] Set("PJSIP/swt11-00000000", "VPBX_CANCELLED=0") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBX_SUSPENDED' is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBX_CANCELLED' is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-check-vpbx-suspended-cancelled:4] ExecIf("PJSIP/swt11-00000000", "0?Hangup(88)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Return'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-check-vpbx-suspended-cancelled:5] Return("PJSIP/swt11-00000000", "") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:11] NoOp("PJSIP/swt11-00000000", "Check if call recording is activated") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 9 for column 'crec_days' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '184'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '184'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '184'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_CALLRECORDING("4") result is '184'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:12] Set("PJSIP/swt11-00000000", "VPBX_CALL_RECORD_DAYS=184") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBX_CALL_RECORD_DAYS' is '184'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '1'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CHANNEL(accountcode) result is 'swt'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CHANNEL(accountcode) result is 'swt'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CDR(uniqueid) result is '1611270152.0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CDR(sequence) result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:13] ExecIf("PJSIP/swt11-00000000", "1?Set(CALLOPT=U(swvpbx-sub-record-call-outbound^swt/swt-1611270152.0-0))") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:14] NoOp("PJSIP/swt11-00000000", "Check if extension is making the call or directly outbound from DDI") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:15] Set("PJSIP/swt11-00000000", "EXT_MAKING_THE_CALL_USERNAME=swt11") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_MAKING_THE_CALL_USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Gosub'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:16] Gosub("PJSIP/swt11-00000000", "swvpbx-get-extension-id-from-username,s,1(swt11,4)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG2' to '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-get-extension-id-from-username:1] NoOp("PJSIP/swt11-00000000", "Checking if number is an extension") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}` FROM `vpbx_extensions` WHERE `${SQL_ESC(${ARG2})}`='${SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is 'ext_id'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_id) result is 'ext_id'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})}`='${SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'ext_username'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_username) result is 'ext_username'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG3})' (from 'SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG3' (from 'ARG3})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG3' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(swt11) result is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG4})' (from 'SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG4' (from 'ARG4})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG4' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 6 for column 'ext_id' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXTENSION(ext_id,ext_username,swt11,4) result is '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-get-extension-id-from-username:2] Set("PJSIP/swt11-00000000", "EXT_ID=509") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_ID' is '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Return'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-get-extension-id-from-username:3] Return("PJSIP/swt11-00000000", "509") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'GOSUB_RETVAL' is '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:17] Set("PJSIP/swt11-00000000", "EXT_MAKING_THE_CALL_ID=509") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:18] NoOp("PJSIP/swt11-00000000", "Check if matching extension number being dialled") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'NUMBER_DIALLED' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Gosub'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:19] Gosub("PJSIP/swt11-00000000", "swvpbx-get-extension-id-from-number,s,1(0114551322,4)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG2' to '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-get-extension-id-from-number:1] NoOp("PJSIP/swt11-00000000", "Checking if number is an extension") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}` FROM `vpbx_extensions` WHERE `${SQL_ESC(${ARG2})}`='${SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is 'ext_id'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_id) result is 'ext_id'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})}`='${SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'ext_number'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_number) result is 'ext_number'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG3})' (from 'SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG3' (from 'ARG3})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG3' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(0114551322) result is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG4})' (from 'SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG4' (from 'ARG4})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG4' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] func_odbc.c: Found no rows [SELECT `ext_id` FROM `vpbx_extensions` WHERE `ext_number`='0114551322' AND `vpbx_id`='4']
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXTENSION(ext_id,ext_number,0114551322,4) result is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-get-extension-id-from-number:2] Set("PJSIP/swt11-00000000", "EXT_ID=") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_ID' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Return'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-get-extension-id-from-number:3] Return("PJSIP/swt11-00000000", "") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'GOSUB_RETVAL' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:20] Set("PJSIP/swt11-00000000", "EXT_BEING_CALLED_ID=") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:21] NoOp("PJSIP/swt11-00000000", "Check if blind transfer is being made") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'BLINDTRANSFER' is NULL
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '1'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'CUT(BLINDTRANSFER,,1)' (from 'CUT(BLINDTRANSFER,,1)}' len 21)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'BLINDTRANSFER' (from 'BLINDTRANSFER}' len 13)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'BLINDTRANSFER' is NULL
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CUT(BLINDTRANSFER,,1) result is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CUT(CUT(BLINDTRANSFER,,1),/,2) result is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:22] ExecIf("PJSIP/swt11-00000000", "1?Set(EXT_USERNAME_BLIND_TRANSFER=):Set(EXT_USERNAME_BLIND_TRANSFER=)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_USERNAME_BLIND_TRANSFER' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Gosub'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:23] Gosub("PJSIP/swt11-00000000", "swvpbx-get-extension-id-from-username,s,1(,4)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG2' to '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-get-extension-id-from-username:1] NoOp("PJSIP/swt11-00000000", "Checking if number is an extension") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}` FROM `vpbx_extensions` WHERE `${SQL_ESC(${ARG2})}`='${SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is 'ext_id'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_id) result is 'ext_id'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})}`='${SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'ext_username'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_username) result is 'ext_username'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG3})' (from 'SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG3' (from 'ARG3})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG3' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC() result is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG4})' (from 'SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG4' (from 'ARG4})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG4' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] func_odbc.c: Found no rows [SELECT `ext_id` FROM `vpbx_extensions` WHERE `ext_username`='' AND `vpbx_id`='4']
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXTENSION(ext_id,ext_username,,4) result is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-get-extension-id-from-username:2] Set("PJSIP/swt11-00000000", "EXT_ID=") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_ID' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Return'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-get-extension-id-from-username:3] Return("PJSIP/swt11-00000000", "") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'GOSUB_RETVAL' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_USERNAME_BLIND_TRANSFER' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:24] ExecIf("PJSIP/swt11-00000000", "0?Set(EXT_MAKING_THE_CALL_USERNAME=") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_BEING_CALLED_ID' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_BEING_CALLED_ID' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'GosubIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:25] GosubIf("PJSIP/swt11-00000000", "0?swvpbx-sub-extensions,s,1(,4)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:26] NoOp("PJSIP/swt11-00000000", "Check if matching speed dial number") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'NUMBER_DIALLED' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Gosub'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:27] Gosub("PJSIP/swt11-00000000", "swvpbx-sub-speed-dial,s,1(0114551322,4)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG2' to '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-speed-dial:1] Set("PJSIP/swt11-00000000", "NUMBER=0114551322") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-speed-dial:2] Set("PJSIP/swt11-00000000", "VPBX_ID=4") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'NUMBER' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBX_ID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}' AND `vpbx_id`=${SQL_ESC(${ARG2})} AND `speedDial_enabled` != -1' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(0114551322) result is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})} AND `speedDial_enabled` != -1' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] func_odbc.c: Found no rows [SELECT `speedDial_targetType`,`speedDial_target` FROM `vpbx_speedDials` WHERE `speedDial_number`='0114551322' AND `vpbx_id`=4 AND `speedDial_enabled` != -1]
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_SPEED_DIAL("0114551322","4") result is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-speed-dial:3] Set("PJSIP/swt11-00000000", "SPEED_DIAL=") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'SPEED_DIAL' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Return'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-speed-dial:4] Return("PJSIP/swt11-00000000", "") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'GOSUB_RETVAL' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:28] Set("PJSIP/swt11-00000000", "SPEED_DIAL_TARGET_STRING=") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'SPEED_DIAL_TARGET_STRING' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SPEED_DIAL_TARGET_STRING' (from 'SPEED_DIAL_TARGET_STRING}' len 24)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'SPEED_DIAL_TARGET_STRING' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CUT(SPEED_DIAL_TARGET_STRING,\,,1) result is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SPEED_DIAL_TARGET_STRING' (from 'SPEED_DIAL_TARGET_STRING}' len 24)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'SPEED_DIAL_TARGET_STRING' is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CUT(SPEED_DIAL_TARGET_STRING,\,,2) result is ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:29] ExecIf("PJSIP/swt11-00000000", "0?Gosub(swvpbx-sub-target,s,1(,,4,,speed-dial))") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:30] NoOp("PJSIP/swt11-00000000", "Check if call barring for national OR international") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DESTINATION' is 'national'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_MAKING_THE_CALL_USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:31] ExecIf("PJSIP/swt11-00000000", "0?Gosub(swvpbx-check-call-barring-international,s,1(swt11,4))") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DESTINATION' is 'national'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '1'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_MAKING_THE_CALL_USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:32] ExecIf("PJSIP/swt11-00000000", "1?Gosub(swvpbx-check-call-barring-national,s,1(swt11,4))") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG2' to '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-check-call-barring-national:1] NoOp("PJSIP/swt11-00000000", "Checking national outbound call barring") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}` FROM `vpbx_extensions` WHERE `${SQL_ESC(${ARG2})}`='${ARG3}' AND `vpbx_id`=${SQL_ESC(${ARG4})}' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is 'ext_restrictNational'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_restrictNational) result is 'ext_restrictNational'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})}`='${ARG3}' AND `vpbx_id`=${SQL_ESC(${ARG4})}' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'ext_username'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_username) result is 'ext_username'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG3' (from 'ARG3}' AND `vpbx_id`=${SQL_ESC(${ARG4})}' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG3' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG4})' (from 'SQL_ESC(${ARG4})}' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG4' (from 'ARG4})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG4' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 20 for column 'ext_restrictNational' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXT_RESTRICT("ext_restrictNational","ext_username","swt11","4") result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-check-call-barring-national:2] Set("PJSIP/swt11-00000000", "RESTRICT=0") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'RESTRICT' is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Return'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-check-call-barring-national:3] Return("PJSIP/swt11-00000000", "0") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DESTINATION' is 'national'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_MAKING_THE_CALL_USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:33] ExecIf("PJSIP/swt11-00000000", "0?Gosub(swvpbx-check-call-barring-mobile,s,1(swt11,4))") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'GOSUB_RETVAL' is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:34] Set("PJSIP/swt11-00000000", "RESTRICT_OUTBOUND=0") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:35] NoOp("PJSIP/swt11-00000000", "Apply outbound restriction if 1 or 2 is returned") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'RESTRICT_OUTBOUND' is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'RESTRICT_OUTBOUND' is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'RESTRICT_OUTBOUND' is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DESTINATION' is 'national'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'GosubIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:36] GosubIf("PJSIP/swt11-00000000", "0?swvpbx-apply-call-barring,s,1(0,national)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:37] NoOp("PJSIP/swt11-00000000", "Set the department name") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_MAKING_THE_CALL_USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Gosub'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:38] Gosub("PJSIP/swt11-00000000", "swvpbx-sub-get-ext-department-name,s,1(4,swt11)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG2' to 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-get-ext-department-name:1] Set("PJSIP/swt11-00000000", "VPBX_ID=4") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function CHANNEL(endpoint) result is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-get-ext-department-name:2] ExecIf("PJSIP/swt11-00000000", "0?Set(USERNAME=swt11):Set(USERNAME=swt11") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBX_ID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}` FROM `vpbx_extensions` WHERE `${SQL_ESC(${ARG2})}`='${SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is 'ext_id'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_id) result is 'ext_id'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})}`='${SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'ext_username'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_username) result is 'ext_username'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG3})' (from 'SQL_ESC(${ARG3})}' AND `vpbx_id`='${SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG3' (from 'ARG3})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG3' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(swt11) result is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG4})' (from 'SQL_ESC(${ARG4})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG4' (from 'ARG4})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG4' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 6 for column 'ext_id' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXTENSION("ext_id","ext_username","swt11",4) result is '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-get-ext-department-name:3] Set("PJSIP/swt11-00000000", "EXT_ID=509") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-get-ext-department-name:4] Set("PJSIP/swt11-00000000", "DEPARTMENT_NAME=") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_ID' is '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'GotoIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-get-ext-department-name:5] GotoIf("PJSIP/swt11-00000000", "0?return") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_builtins.c: Not taking any branch
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_ID' is '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBX_ID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})} AND `vpbx_id`=${SQL_ESC(${ARG2})} AND `departmentMember_enabled`=1' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(509) result is '509'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})} AND `departmentMember_enabled`=1' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 13 for column 'department_id' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXT_DEPARTMENT_ID("509","4") result is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-get-ext-department-name:6] Set("PJSIP/swt11-00000000", "DEPARTMENT_ID=6") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DEPARTMENT_ID' is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'GotoIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-get-ext-department-name:7] GotoIf("PJSIP/swt11-00000000", "0?return") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_builtins.c: Not taking any branch
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DEPARTMENT_ID' is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})} AND `department_enabled` != -1' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(6) result is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 20 for column 'vpbx_department_name' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of 'Directors'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to 'Directors'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to 'Directors'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXT_DEPARTMENT_NAME("6") result is 'Directors'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-get-ext-department-name:8] Set("PJSIP/swt11-00000000", "DEPARTMENT_NAME=[Directors]") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DEPARTMENT_NAME' is '[Directors]'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Return'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-get-ext-department-name:9] Return("PJSIP/swt11-00000000", "[Directors]") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'GOSUB_RETVAL' is '[Directors]'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:39] Set("PJSIP/swt11-00000000", "EXT_MAKING_CALL_DEPT_NAME=[Directors]") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:40] NoOp("PJSIP/swt11-00000000", "Set TRUNK") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_MAKING_THE_CALL_USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}`='${SQL_ESC(${ARG2})}' AND `vpbx_id`=${SQL_ESC(${ARG3})}' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is 'ext_username'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(ext_username) result is 'ext_username'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})}' AND `vpbx_id`=${SQL_ESC(${ARG3})}' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(swt11) result is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG3})' (from 'SQL_ESC(${ARG3})}' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG3' (from 'ARG3})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG3' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 8 for column 'trunk_id' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXTENSION_TRUNK_ID("ext_username","swt11","4") result is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:41] Set("PJSIP/swt11-00000000", "EXT_TRUNK_ID=6") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_TRUNK_ID' is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DEFAULT_TRUNK_ID' is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:42] ExecIf("PJSIP/swt11-00000000", "0?Set(EXT_TRUNK_ID=6)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_TRUNK_ID' is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '1'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_TRUNK_ID' is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(6) result is '6'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 8 for column 'username' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXTENSION_TRUNK("6") result is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:43] ExecIf("PJSIP/swt11-00000000", "1?Set(TRUNK_USERNAME=0875500000)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'TRUNK_USERNAME' is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:44] ExecIf("PJSIP/swt11-00000000", "0?Hangup(16)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 9 for column 'vpbx_name' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of 'swt'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to 'swt'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to 'swt'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_VPBX_NAME("4") result is 'swt'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:45] Set("PJSIP/swt11-00000000", "VPBX_NAME=swt") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'TRUNK_USERNAME' is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:46] Set("PJSIP/swt11-00000000", "TRUNK=0875500000") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:47] NoOp("PJSIP/swt11-00000000", "Get the outbound caller id") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Gosub'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:48] Gosub("PJSIP/swt11-00000000", "swvpbx-set-caller-id,s,1()") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG2' to ''
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-caller-id:1] NoOp("PJSIP/swt11-00000000", "Check if CALLER_ID is set from using a PIN") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'PIN_CALLER_ID' is NULL
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'PIN_CALLER_ID' is NULL
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-caller-id:2] ExecIf("PJSIP/swt11-00000000", "0?Set(EXT_CALLER_ID_NAME=)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'PIN_CALLER_ID' is NULL
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '1'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_MAKING_THE_CALL_USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}' AND `ext_username`='${SQL_ESC(${ARG2})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(swt11) result is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 15 for column 'ext_displayName' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of 'Greg'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to 'Greg'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to 'Greg'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXTENSION_CALLER_NAME("4","swt11") result is 'Greg'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-caller-id:3] ExecIf("PJSIP/swt11-00000000", "1?Set(EXT_CALLER_ID_NAME=Greg)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_MAKING_THE_CALL_USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})}' AND `ext_username`='${SQL_ESC(${ARG2})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(swt11) result is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 12 for column 'ext_callerId' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXTENSION_CALLER_ID("4","swt11") result is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-caller-id:4] Set("PJSIP/swt11-00000000", "EXT_CALLER_ID_NUM=0875500000") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Return'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-set-caller-id:5] Return("PJSIP/swt11-00000000", "") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_CALLER_ID_NAME' is 'Greg'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DEFAULT_TRUNKCID' is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:49] ExecIf("PJSIP/swt11-00000000", "0?Set(EXT_CALLER_ID_NAME=0875500000") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_CALLER_ID_NUM' is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'DEFAULT_TRUNKCID' is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:50] ExecIf("PJSIP/swt11-00000000", "0?Set(EXT_CALLER_ID_NUM=0875500000") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'NoOp'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:51] NoOp("PJSIP/swt11-00000000", "Dial External") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'GLOBAL_CALLERIDSET' is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '1'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_CALLER_ID_NAME' is 'Greg'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_MAKING_CALL_DEPT_NAME' is '[Directors]'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:52] ExecIf("PJSIP/swt11-00000000", "1?Set(CALLERID(name)=Greg [Directors])") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'GLOBAL_CALLERIDSET' is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '1'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_CALLER_ID_NUM' is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:53] ExecIf("PJSIP/swt11-00000000", "1?Set(CALLERID(num)=0875500000)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'VPBXID' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_MAKING_THE_CALL_USERNAME' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG1})' (from 'SQL_ESC(${ARG1})} AND `ext_username`='${SQL_ESC(${ARG2})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(4) result is '4'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'SQL_ESC(${ARG2})' (from 'SQL_ESC(${ARG2})}'' len 16)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2})' len 4)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG2' is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function SQL_ESC(swt11) result is 'swt11'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Reusing ODBC handle 0x55d85832a970 from class 'clientzone-connector'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got collength of 20 for column 'ext_callerIdRestrict' (offset 0)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: Got coldata of '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] func_odbc.c: buf is now set to '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_odbc.c: Releasing ODBC handle 0x55d85832a970 into pool
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Function ODBC_GET_EXTENSION_CALLER_ID_RESTRICT("4","swt11") result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Set'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:54] Set("PJSIP/swt11-00000000", "EXT_RESTRICT_CALLERID=0") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'EXT_RESTRICT_CALLERID' is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Expression result is '0'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'ExecIf'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:55] ExecIf("PJSIP/swt11-00000000", "0?Set(CALLERID(pres)=unavailable)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'TRUNK' is '0875500000'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'NUMBER_DIALLED' is '0114551322'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'CALLOPT' is 'U(swvpbx-sub-record-call-outbound^swt/swt-1611270152.0-0)'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] pbx.c: Launching 'Dial'
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-dialout:56] Dial("PJSIP/swt11-00000000", "PJSIP/0875500000/sip:0114551322@196.216.192.4:5060,120,U(swvpbx-sub-record-call-outbound^swt/swt-1611270152.0-0)") in new stack
[Jan 22 01:02:32] DEBUG[23530][C-00000001] stasis.c: Creating topic. name: channel:1611270152.1, detail: 
[Jan 22 01:02:32] DEBUG[23530][C-00000001] stasis.c: Topic 'channel:1611270152.1': 0x7fd0800232b0 created
[Jan 22 01:02:32] DEBUG[23530][C-00000001] stasis.c: Creating topic. name: cache:33/channel:1611270152.1, detail: 
[Jan 22 01:02:32] DEBUG[23530][C-00000001] stasis.c: Topic 'cache:33/channel:1611270152.1': 0x7fd0800247b0 created
[Jan 22 01:02:32] DEBUG[23530][C-00000001] channel.c: Channel 0x7fd080026e20 'PJSIP/0875500000-00000001' allocated
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] app_dial.c: Called PJSIP/0875500000/sip:0114551322@196.216.192.4:5060
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/0875500000-00000001 setting read format path: alaw -> alaw
[Jan 22 01:02:32] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/swt11-00000000 setting write format path: alaw -> alaw
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Processing streams
[Jan 22 01:02:32] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/swt11-00000000 setting read format path: alaw -> alaw
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Processing stream 0:audio-0:audio:sendrecv (alaw|ulaw|g729|gsm)
[Jan 22 01:02:32] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/0875500000-00000001 setting write format path: alaw -> alaw
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001 Adding position 0
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  Creating new media session
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  Setting media session as default for audio
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  Done
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.22' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.22' and port ''.
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_sdp_rtp.c: Endpoint 0875500000: Binding RTP media to 196.216.192.22
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fd07c0320d0'
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) RTP allocated port 16902
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) ICE creating session 196.216.192.22:16902 (16902)
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) ICE create
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) ICE add system candidates
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.22' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.22' and port ''.
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) ICE add candidate: 196.216.192.22:16902, 2130706431
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.20' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.20' and port ''.
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) ICE add candidate: 196.216.192.20:16902, 2130706431
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.7' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.7' and port ''.
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) ICE add candidate: 196.216.192.7:16902, 2130706431
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: RTP instance '0x7fd07c0320d0' is setup and ready to go
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) ICE stopped
[Jan 22 01:02:32] DEBUG[23526] acl.c: Attached to given IP address
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) RTCP setup on RTP instance
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Stream 0:audio-0:audio:sendrecv (alaw|ulaw|g729|gsm) added
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Done with 0:audio-0:audio:sendrecv (alaw|ulaw|g729|gsm)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Adding bundle groups (if available)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Copying connection details
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Processing media 0
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Media 0 reset
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Method is INVITE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '196.216.192.4'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_resolver.c: Transport type for target '196.216.192.4' is 'UDP transport'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_resolver.c: Target '196.216.192.4' is an IP address, skipping resolution
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Connected line update
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 196.216.192.22:5060 (this may be re-written again later)
[Jan 22 01:02:32] VERBOSE[23526] res_pjsip_logger.c: <--- Transmitting SIP request (1038 bytes) to UDP:196.216.192.4:5060 --->
INVITE sip:0114551322@196.216.192.4:5060 SIP/2.0
Via: SIP/2.0/UDP 196.216.192.22:5060;rport;branch=z9hG4bKPj16abccf1-953e-4cb4-9b65-79effc2a9faf
From: "Greg [Directors]" <sip:0875500000@196.216.192.22>;tag=536e864b-9b55-48b3-b1ac-01fd7c327b97
To: <sip:0114551322@196.216.192.4>
Contact: <sip:unknown@196.216.192.22:5060>
Call-ID: 4b79a9f3-ea8a-49bb-a057-a68ee1594fef
CSeq: 27239 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub, histinfo
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: SwitchTelecom
Content-Type: application/sdp
Content-Length:   340

v=0
o=- 1217002043 1217002043 IN IP4 196.216.192.22
s=SwitchTelecom
c=IN IP4 196.216.192.22
t=0 0
m=audio 16902 RTP/AVP 8 0 18 3 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd09000e018)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is CALLING
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/0875500000-00000001: Source of transaction state change is TX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd09000e018)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fd09000e018
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current transaction state is Calling
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is CALLING
[Jan 22 01:02:32] VERBOSE[17499] res_pjsip_logger.c: <--- Received SIP response (602 bytes) from UDP:196.216.192.4:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 196.216.192.22:5060;rport=5060;received=196.216.192.22;branch=z9hG4bKPj16abccf1-953e-4cb4-9b65-79effc2a9faf
Call-ID: 4b79a9f3-ea8a-49bb-a057-a68ee1594fef
From: "Greg [Directors]" <sip:0875500000@196.216.192.22>;tag=536e864b-9b55-48b3-b1ac-01fd7c327b97
To: <sip:0114551322@196.216.192.4>;tag=z9hG4bKPj16abccf1-953e-4cb4-9b65-79effc2a9faf
CSeq: 27239 INVITE
WWW-Authenticate: Digest realm="switchtel.co.za",nonce="1611270152/a29fcf701b58d94b5fb394c06e3aaf78",opaque="3bbabf020ff6bfca",algorithm=md5,qop="auth"
Server: SwitchTelecom
Content-Length:  0


[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fd094052c18 for Response msg 401/INVITE/cseq=27239 (rdata0x7fd020000dc8)
[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0875500000-000000a9 associated with dialog dlg0x7fd094052c18
[Jan 22 01:02:32] VERBOSE[23526] res_pjsip_logger.c: <--- Transmitting SIP request (460 bytes) to UDP:196.216.192.4:5060 --->
ACK sip:0114551322@196.216.192.4:5060 SIP/2.0
Via: SIP/2.0/UDP 196.216.192.22:5060;rport;branch=z9hG4bKPj16abccf1-953e-4cb4-9b65-79effc2a9faf
From: "Greg [Directors]" <sip:0875500000@196.216.192.22>;tag=536e864b-9b55-48b3-b1ac-01fd7c327b97
To: <sip:0114551322@196.216.192.4>;tag=z9hG4bKPj16abccf1-953e-4cb4-9b65-79effc2a9faf
Call-ID: 4b79a9f3-ea8a-49bb-a057-a68ee1594fef
CSeq: 27239 ACK
Max-Forwards: 70
User-Agent: SwitchTelecom
Content-Length:  0


[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/0875500000-00000001: Initial INVITE is being challenged.
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Method is INVITE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 196.216.192.22:5060 (this may be re-written again later)
[Jan 22 01:02:32] VERBOSE[23526] res_pjsip_logger.c: <--- Transmitting SIP request (1365 bytes) to UDP:196.216.192.4:5060 --->
INVITE sip:0114551322@196.216.192.4:5060 SIP/2.0
Via: SIP/2.0/UDP 196.216.192.22:5060;rport;branch=z9hG4bKPj8d037bcf-4046-4d8c-8494-b88e19ccf2eb
From: "Greg [Directors]" <sip:0875500000@196.216.192.22>;tag=536e864b-9b55-48b3-b1ac-01fd7c327b97
To: <sip:0114551322@196.216.192.4>
Contact: <sip:unknown@196.216.192.22:5060>
Call-ID: 4b79a9f3-ea8a-49bb-a057-a68ee1594fef
CSeq: 27240 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub, histinfo, histinfo
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: SwitchTelecom
Authorization: Digest username="0875500000", realm="switchtel.co.za", nonce="1611270152/a29fcf701b58d94b5fb394c06e3aaf78", uri="sip:0114551322@196.216.192.4:5060", response="14edf79cfb3d3bb6cc4f96b47eda3325", algorithm=md5, cnonce="8758a10bc4ae4331a95f5c2ada630747", opaque="3bbabf020ff6bfca", qop=auth, nc=00000001
Content-Type: application/sdp
Content-Length:   340

v=0
o=- 1217002043 1217002043 IN IP4 196.216.192.22
s=SwitchTelecom
c=IN IP4 196.216.192.22
t=0 0
m=audio 16902 RTP/AVP 8 0 18 3 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fd098019178
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current transaction state is Calling
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is CALLING
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fd09000e018
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current transaction state is Completed
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is CALLING
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Response is 401 Unauthorized
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 401
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Not queueing anything
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 401
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Private Cause Code
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] VERBOSE[17499] res_pjsip_logger.c: <--- Received SIP response (393 bytes) from UDP:196.216.192.4:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 196.216.192.22:5060;rport=5060;received=196.216.192.22;branch=z9hG4bKPj8d037bcf-4046-4d8c-8494-b88e19ccf2eb
Call-ID: 4b79a9f3-ea8a-49bb-a057-a68ee1594fef
From: "Greg [Directors]" <sip:0875500000@196.216.192.22>;tag=536e864b-9b55-48b3-b1ac-01fd7c327b97
To: <sip:0114551322@196.216.192.4>
CSeq: 27240 INVITE
Server: SwitchTelecom
Content-Length:  0


[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fd094052c18 for Response msg 100/INVITE/cseq=27240 (rdata0x7fd020000dc8)
[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0875500000-000000a9 associated with dialog dlg0x7fd094052c18
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fd098019178
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is CALLING
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Response is 100 Trying
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 100
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Not queueing anything
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 100
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Private Cause Code
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] VERBOSE[17499] res_pjsip_logger.c: <--- Received SIP response (868 bytes) from UDP:196.216.192.4:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 196.216.192.22:5060;rport=5060;received=196.216.192.22;branch=z9hG4bKPj8d037bcf-4046-4d8c-8494-b88e19ccf2eb
Call-ID: 4b79a9f3-ea8a-49bb-a057-a68ee1594fef
From: "Greg [Directors]" <sip:0875500000@196.216.192.22>;tag=536e864b-9b55-48b3-b1ac-01fd7c327b97
To: <sip:0114551322@196.216.192.4>;tag=a01cdb1f-56e9-4c6e-b84d-895deab4f988
CSeq: 27240 INVITE
Server: SwitchTelecom
Contact: <sip:196.216.192.4:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Content-Type: application/sdp
Content-Length:   244

v=0
o=- 1217002043 1217002045 IN IP4 196.216.192.4
s=SwitchTelecom
c=IN IP4 196.216.192.4
t=0 0
m=audio 17358 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fd094052c18 for Response msg 183/INVITE/cseq=27240 (rdata0x7fd020000dc8)
[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0875500000-000000a9 associated with dialog dlg0x7fd094052c18
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is EARLY
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/0875500000-00000001: Source of transaction state change is RX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/0875500000-00000001: Received response
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Response is 183 Session Progress
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 183
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Private Cause Code
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/0875500000-00000001: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) RTCP ignoring duplicate property
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.4' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.4' and port ''.
[Jan 22 01:02:32] DEBUG[23526] acl.c: For destination '196.216.192.4', our source address is '196.216.192.22'.
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) RTCP setting address on RTP instance
[Jan 22 01:02:32] VERBOSE[23526] res_rtp_asterisk.c: 0x7fd07c033050 -- Strict RTP learning after remote address set to: 196.216.192.4:17358
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fd0c32f9100
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 8 (0x7fd07c0311a8) from 0x7fd0c32f9100 to 0x7fd07c0322a8
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 101 (0x7fd07c061148) from 0x7fd0c32f9100 to 0x7fd07c0322a8
[Jan 22 01:02:32] DEBUG[23526] channel.c: Channel PJSIP/0875500000-00000001 setting read format path: alaw -> alaw
[Jan 22 01:02:32] DEBUG[23526] channel.c: Channel PJSIP/0875500000-00000001 setting write format path: alaw -> alaw
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0320d0) DTLS - ast_rtp_activate rtp=0x7fd07c033050 - setup and perform DTLS'
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c033050) DTLS perform handshake - ssl = (nil), setup = 0
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c033050) DTLS perform handshake - ssl = (nil), setup = 0
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/0875500000-00000001: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fd098019178
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is EARLY
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Response is 183 Session Progress
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 183
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Queueing PROGRESS
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 183
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] app_dial.c: PJSIP/0875500000-00000001 is making progress passing it to PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Unknown control '14'
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[17476] devicestate.c: No provider found, checking channel drivers for PJSIP - swt11
[Jan 22 01:02:32] DEBUG[17476] devicestate.c: Changing state for PJSIP/swt11 - state 2 (In use)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/swt11-00000000: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) RTCP ignoring duplicate property
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: Splitting '196.216.192.5' into...
[Jan 22 01:02:32] DEBUG[23526] netsock2.c: ...host '196.216.192.5' and port ''.
[Jan 22 01:02:32] DEBUG[23526] acl.c: For destination '196.216.192.5', our source address is '196.216.192.22'.
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) RTCP setting address on RTP instance
[Jan 22 01:02:32] VERBOSE[23526] res_rtp_asterisk.c: 0x7fd07c0213b0 -- Strict RTP learning after remote address set to: 196.216.192.5:34342
[Jan 22 01:02:32] DEBUG[17537] app_queue.c: Removed PJSIP/swt11 from pending_members
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fd0c32f93e0
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Private Cause Code
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fd0c32f93e0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7fd0c32f93e0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 4 based on m type on 0x7fd0c32f93e0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7fd0c32f93e0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Don't have a default tx payload type 2 format for m type on 0x7fd0c32f93e0
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 0 (0x7fd07c063898) from 0x7fd0c32f93e0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 2 (0x7fd07c09b998) from 0x7fd0c32f93e0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 4 (0x7fd07c0623d8) from 0x7fd0c32f93e0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 8 (0x7fd07c009318) from 0x7fd0c32f93e0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 9 (0x7fd07c062538) from 0x7fd0c32f93e0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[17537] app_queue.c: Removed PJSIP/swt11 from pending_members
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 18 (0x7fd07c0638e8) from 0x7fd0c32f93e0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 97 (0x7fd07c061218) from 0x7fd0c32f93e0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 101 (0x7fd07c0613c8) from 0x7fd0c32f93e0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 125 (0x7fd07c09b948) from 0x7fd0c32f93e0 to 0x7fd07c020608
[Jan 22 01:02:32] DEBUG[23526] channel.c: Channel PJSIP/swt11-00000000 setting read format path: alaw -> alaw
[Jan 22 01:02:32] DEBUG[23526] channel.c: Channel PJSIP/swt11-00000000 setting write format path: alaw -> alaw
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) DTLS - ast_rtp_activate rtp=0x7fd07c0213b0 - setup and perform DTLS'
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0213b0) DTLS perform handshake - ssl = (nil), setup = 0
[Jan 22 01:02:32] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0213b0) DTLS perform handshake - ssl = (nil), setup = 0
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/swt11-00000000: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Jan 22 01:02:32] DEBUG[17537] app_queue.c: Removed PJSIP/swt11 from pending_members
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Method is INVITE, Response is 183 Session Progress
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[17537] app_queue.c: Removed PJSIP/swt11 from pending_members
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 196.216.192.22:5060 (this may be re-written again later)
[Jan 22 01:02:32] DEBUG[17537] app_queue.c: Device 'PJSIP/swt11' changed to state '2' (In use)
[Jan 22 01:02:32] VERBOSE[23526] res_pjsip_logger.c: <--- Transmitting SIP response (859 bytes) to UDP:196.216.192.5:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 196.216.192.5:5060;received=196.216.192.5;branch=z9hG4bK720d.ec6eb4f1.0
Call-ID: 1441272955-5060-3024@BJC.BGI.B.BF
From: "Greg" <sip:swt11@vpbx2.switchtel.co.za>;tag=56656018
To: <sip:0114551322@vpbx2.switchtel.co.za>;tag=3e6c7b22-4ff6-4787-a07d-dbc57f305b0f
CSeq: 291 INVITE
Server: SwitchTelecom
Contact: <sip:196.216.192.22:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE
Content-Type: application/sdp
Content-Length:   305

v=0
o=- 8000 8002 IN IP4 196.216.192.22
s=SwitchTelecom
c=IN IP4 196.216.192.22
t=0 0
m=audio 17738 RTP/AVP 8 0 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd09801c7c8)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is EARLY
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/swt11-00000000: Source of transaction state change is TX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd09801c7c8)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fd09801c7c8
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is EARLY
[Jan 22 01:02:32] DEBUG[17537] app_queue.c: Device 'Queue:swt-technical-queue-4_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 22 01:02:32] DEBUG[17537] app_queue.c: Device 'Queue:swt-sales-3_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 22 01:02:32] DEBUG[17537] app_queue.c: Device 'Queue:swt-operator-4_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 22 01:02:32] DEBUG[17537] app_queue.c: Device 'Queue:swt-emergency_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] res_rtp_asterisk.c: 0x7fd07c033050 -- Strict RTP switching to RTP target address 196.216.192.4:17358 as source
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_rtp_asterisk.c: (0x7fd07c020430) RTP ooh, format changed from none to alaw
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_rtp_asterisk.c: (0x7fd07c020430) RTCP starting transmission
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] res_rtp_asterisk.c: 0x7fd07c0213b0 -- Strict RTP switching to RTP target address 196.216.192.5:34342 as source
[Jan 22 01:02:32] DEBUG[23530][C-00000001] res_rtp_asterisk.c: (0x7fd07c0320d0) RTP ooh, format changed from none to alaw
[Jan 22 01:02:32] VERBOSE[17499] res_pjsip_logger.c: <--- Received SIP response (868 bytes) from UDP:196.216.192.4:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 196.216.192.22:5060;rport=5060;received=196.216.192.22;branch=z9hG4bKPj8d037bcf-4046-4d8c-8494-b88e19ccf2eb
Call-ID: 4b79a9f3-ea8a-49bb-a057-a68ee1594fef
From: "Greg [Directors]" <sip:0875500000@196.216.192.22>;tag=536e864b-9b55-48b3-b1ac-01fd7c327b97
To: <sip:0114551322@196.216.192.4>;tag=a01cdb1f-56e9-4c6e-b84d-895deab4f988
CSeq: 27240 INVITE
Server: SwitchTelecom
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Contact: <sip:196.216.192.4:5060>
Content-Type: application/sdp
Content-Length:   244

v=0
o=- 1217002043 1217002045 IN IP4 196.216.192.4
s=SwitchTelecom
c=IN IP4 196.216.192.4
t=0 0
m=audio 17358 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fd094052c18 for Response msg 183/INVITE/cseq=27240 (rdata0x7fd020000dc8)
[Jan 22 01:02:32] DEBUG[17499] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0875500000-000000a9 associated with dialog dlg0x7fd094052c18
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is EARLY
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/0875500000-00000001: Source of transaction state change is RX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/0875500000-00000001: Received response
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Response is 183 Session Progress
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 183
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Private Cause Code
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fd098019178
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is EARLY
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Response is 183 Session Progress
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 183
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Queueing PROGRESS
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 183
[Jan 22 01:02:32] VERBOSE[23530][C-00000001] app_dial.c: PJSIP/0875500000-00000001 is making progress passing it to PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Unknown control '14'
[Jan 22 01:02:32] DEBUG[17476] devicestate.c: No provider found, checking channel drivers for PJSIP - swt11
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[17476] devicestate.c: Changing state for PJSIP/swt11 - state 2 (In use)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Method is INVITE, Response is 183 Session Progress
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Private Cause Code
[Jan 22 01:02:32] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:32] DEBUG[23526] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 196.216.192.22:5060 (this may be re-written again later)
[Jan 22 01:02:32] VERBOSE[23526] res_pjsip_logger.c: <--- Transmitting SIP response (859 bytes) to UDP:196.216.192.5:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 196.216.192.5:5060;received=196.216.192.5;branch=z9hG4bK720d.ec6eb4f1.0
Call-ID: 1441272955-5060-3024@BJC.BGI.B.BF
From: "Greg" <sip:swt11@vpbx2.switchtel.co.za>;tag=56656018
To: <sip:0114551322@vpbx2.switchtel.co.za>;tag=3e6c7b22-4ff6-4787-a07d-dbc57f305b0f
CSeq: 291 INVITE
Server: SwitchTelecom
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE
Contact: <sip:196.216.192.22:5060>
Content-Type: application/sdp
Content-Length:   305

v=0
o=- 8000 8002 IN IP4 196.216.192.22
s=SwitchTelecom
c=IN IP4 196.216.192.22
t=0 0
m=audio 17738 RTP/AVP 8 0 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd09801c7c8)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is EARLY
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: PJSIP/swt11-00000000: Source of transaction state change is TX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd09801c7c8)
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fd09801c7c8
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 22 01:02:32] DEBUG[23526] res_pjsip_session.c: The current inv state is EARLY
[Jan 22 01:02:33] VERBOSE[17499] res_pjsip_logger.c: <--- Received SIP response (955 bytes) from UDP:196.216.192.4:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 196.216.192.22:5060;rport=5060;received=196.216.192.22;branch=z9hG4bKPj8d037bcf-4046-4d8c-8494-b88e19ccf2eb
Call-ID: 4b79a9f3-ea8a-49bb-a057-a68ee1594fef
From: "Greg [Directors]" <sip:0875500000@196.216.192.22>;tag=536e864b-9b55-48b3-b1ac-01fd7c327b97
To: <sip:0114551322@196.216.192.4>;tag=a01cdb1f-56e9-4c6e-b84d-895deab4f988
CSeq: 27240 INVITE
Server: SwitchTelecom
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Contact: <sip:196.216.192.4:5060>
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   244

v=0
o=- 1217002043 1217002045 IN IP4 196.216.192.4
s=SwitchTelecom
c=IN IP4 196.216.192.4
t=0 0
m=audio 17358 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fd094052c18 for Response msg 200/INVITE/cseq=27240 (rdata0x7fd020000dc8)
[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0875500000-000000a9 associated with dialog dlg0x7fd094052c18
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current inv state is CONNECTING
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: PJSIP/0875500000-00000001: Source of transaction state change is RX_MSG
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: PJSIP/0875500000-00000001: Received response
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Response is 200 OK
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 200
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:33] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Private Cause Code
[Jan 22 01:02:33] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '196.216.192.4'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_resolver.c: Transport type for target '196.216.192.4' is 'UDP transport'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_resolver.c: Target '196.216.192.4' is an IP address, skipping resolution
[Jan 22 01:02:33] VERBOSE[23526] res_pjsip_logger.c: <--- Transmitting SIP request (440 bytes) to UDP:196.216.192.4:5060 --->
ACK sip:196.216.192.4:5060 SIP/2.0
Via: SIP/2.0/UDP 196.216.192.22:5060;rport;branch=z9hG4bKPjaec9b49d-e5bf-4eef-999f-e81f77a4a7e3
From: "Greg [Directors]" <sip:0875500000@196.216.192.22>;tag=536e864b-9b55-48b3-b1ac-01fd7c327b97
To: <sip:0114551322@196.216.192.4>;tag=a01cdb1f-56e9-4c6e-b84d-895deab4f988
Call-ID: 4b79a9f3-ea8a-49bb-a057-a68ee1594fef
CSeq: 27240 ACK
Max-Forwards: 70
User-Agent: SwitchTelecom
Content-Length:  0


[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint '0875500000(PJSIP/0875500000-00000001)'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fd098019178
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current transaction state is Terminated
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001: Response is 200 OK
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 200
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Queueing ANSWER
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001: Status: 200
[Jan 22 01:02:33] VERBOSE[23530][C-00000001] app_dial.c: PJSIP/0875500000-00000001 answered PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[17476] devicestate.c: No provider found, checking channel drivers for PJSIP - 0875500000
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:33] DEBUG[17476] devicestate.c: Changing state for PJSIP/0875500000 - state 2 (In use)
[Jan 22 01:02:33] VERBOSE[23530][C-00000001] app_stack.c: PJSIP/0875500000-00000001 Internal Gosub(swvpbx-sub-record-call-outbound,s,1(swt/swt-1611270152.0-0)) start
[Jan 22 01:02:33] DEBUG[23530][C-00000001] app_stack.c: PJSIP/0875500000-00000001 Original location: swvpbx-incoming,,1
[Jan 22 01:02:33] DEBUG[23530][C-00000001] app_stack.c: Channel PJSIP/0875500000-00000001 has no datastore, so we're allocating one.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] app_stack.c: Setting 'ARG1' to 'swt/swt-1611270152.0-0'
[Jan 22 01:02:33] DEBUG[23530][C-00000001] app_stack.c: Gosub exited with status 0
[Jan 22 01:02:33] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'GLOBAL_CALL_RECORDING_DIR' is '/data/vpbx4.switchtel.co.za/recordings'
[Jan 22 01:02:33] DEBUG[23530][C-00000001] pbx_variables.c: Result of 'ARG1' is 'swt/swt-1611270152.0-0'
[Jan 22 01:02:33] DEBUG[23530][C-00000001] pbx.c: Launching 'MixMonitor'
[Jan 22 01:02:33] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-record-call-outbound:1] MixMonitor("PJSIP/0875500000-00000001", "/data/vpbx4.switchtel.co.za/recordings/swt/swt-1611270152.0-0.gsm,ai(__MIXMONID)") in new stack
[Jan 22 01:02:33] DEBUG[17537] app_queue.c: Device 'PJSIP/0875500000' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] autochan.c: Created autochan 0x7fd080025510 to hold channel PJSIP/0875500000-00000001 (0x7fd080026e20)
[Jan 22 01:02:33] DEBUG[23530][C-00000001] pbx.c: Launching 'Return'
[Jan 22 01:02:33] VERBOSE[23530][C-00000001] pbx.c: Executing [s@swvpbx-sub-record-call-outbound:2] Return("PJSIP/0875500000-00000001", "") in new stack
[Jan 22 01:02:33] DEBUG[23530][C-00000001] app_stack.c: Spawn extension (swvpbx-incoming,,1) exited with -1 on 'PJSIP/0875500000-00000001'
[Jan 22 01:02:33] VERBOSE[23534][C-00000001] app_mixmonitor.c: Begin MixMonitor Recording PJSIP/0875500000-00000001
[Jan 22 01:02:33] VERBOSE[23530][C-00000001] app_stack.c: Spawn extension (swvpbx-incoming, , 1) exited non-zero on 'PJSIP/0875500000-00000001'
[Jan 22 01:02:33] VERBOSE[23530][C-00000001] app_stack.c: PJSIP/0875500000-00000001 Internal Gosub(swvpbx-sub-record-call-outbound,s,1(swt/swt-1611270152.0-0)) complete GOSUB_RETVAL=
[Jan 22 01:02:33] DEBUG[23530][C-00000001] app_stack.c: PJSIP/0875500000-00000001 Ending location: swvpbx-incoming,,1
[Jan 22 01:02:33] DEBUG[23534][C-00000001] audiohook.c: Read factory 0x7fd08000fb18 and write factory 0x7fd080010558 both fail to provide 160 samples
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/0875500000-00000001 setting read format path: alaw -> alaw
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/swt11-00000000 setting write format path: alaw -> alaw
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/swt11-00000000 setting read format path: alaw -> alaw
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/0875500000-00000001 setting write format path: alaw -> alaw
[Jan 22 01:02:33] DEBUG[17476] devicestate.c: No provider found, checking channel drivers for PJSIP - swt11
[Jan 22 01:02:33] DEBUG[17476] devicestate.c: Changing state for PJSIP/swt11 - state 2 (In use)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Method is INVITE, Response is 200 OK
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 196.216.192.22:5060 (this may be re-written again later)
[Jan 22 01:02:33] VERBOSE[23526] res_pjsip_logger.c: <--- Transmitting SIP response (893 bytes) to UDP:196.216.192.5:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 196.216.192.5:5060;received=196.216.192.5;branch=z9hG4bK720d.ec6eb4f1.0
Call-ID: 1441272955-5060-3024@BJC.BGI.B.BF
From: "Greg" <sip:swt11@vpbx2.switchtel.co.za>;tag=56656018
To: <sip:0114551322@vpbx2.switchtel.co.za>;tag=3e6c7b22-4ff6-4787-a07d-dbc57f305b0f
CSeq: 291 INVITE
Server: SwitchTelecom
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE
Contact: <sip:196.216.192.22:5060>
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   305

v=0
o=- 8000 8002 IN IP4 196.216.192.22
s=SwitchTelecom
c=IN IP4 196.216.192.22
t=0 0
m=audio 17738 RTP/AVP 8 0 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd09801c7c8)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current inv state is CONNECTING
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: PJSIP/swt11-00000000: Source of transaction state change is TX_MSG
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd09801c7c8)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fd09801c7c8
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current transaction state is Completed
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current inv state is CONNECTING
[Jan 22 01:02:33] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Stop generators
[Jan 22 01:02:33] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23530][C-00000001] stasis.c: Creating topic. name: bridge:9598ee66-59d8-4797-8b60-53d896b301e1, detail: 
[Jan 22 01:02:33] DEBUG[23530][C-00000001] stasis.c: Topic 'bridge:9598ee66-59d8-4797-8b60-53d896b301e1': 0x7fd08000c2c0 created
[Jan 22 01:02:33] DEBUG[23530][C-00000001] stasis.c: Creating topic. name: cache:34/bridge:9598ee66-59d8-4797-8b60-53d896b301e1, detail: 
[Jan 22 01:02:33] DEBUG[23530][C-00000001] stasis.c: Topic 'cache:34/bridge:9598ee66-59d8-4797-8b60-53d896b301e1': 0x7fd080020610 created
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge_native_rtp.c: Bridge '9598ee66-59d8-4797-8b60-53d896b301e1' can not use native RTP bridge as two channels are required
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Chose bridge technology simple_bridge
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1: calling simple_bridge technology constructor
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1: calling simple_bridge technology start
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge_channel.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1: 0x7fd080026a20(PJSIP/0875500000-00000001) is joining
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge_channel.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1: pushing 0x7fd080026a20(PJSIP/0875500000-00000001)
[Jan 22 01:02:33] VERBOSE[23535][C-00000001] bridge_channel.c: Channel PJSIP/0875500000-00000001 joined 'simple_bridge' basic-bridge <9598ee66-59d8-4797-8b60-53d896b301e1>
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge_native_rtp.c: Bridge '9598ee66-59d8-4797-8b60-53d896b301e1' can not use native RTP bridge as two channels are required
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Chose bridge technology simple_bridge
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1 is already using the new technology.
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1: 0x7fd080026a20(PJSIP/0875500000-00000001) is joining simple_bridge technology
[Jan 22 01:02:33] DEBUG[23535][C-00000001] chan_pjsip.c:  PJSIP/0875500000-00000001: Indicated Media SSRC change
[Jan 22 01:02:33] DEBUG[23535][C-00000001] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge_channel.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1: 0x7fd080026c00(PJSIP/swt11-00000000) is joining
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge_channel.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1: pushing 0x7fd080026c00(PJSIP/swt11-00000000)
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge_channel.c: Setting channel PJSIP/swt11-00000000 peeraccount with channel PJSIP/0875500000-00000001 accountcode 'swt'.
[Jan 22 01:02:33] VERBOSE[23530][C-00000001] bridge_channel.c: Channel PJSIP/swt11-00000000 joined 'simple_bridge' basic-bridge <9598ee66-59d8-4797-8b60-53d896b301e1>
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge_native_rtp.c: Bridge '9598ee66-59d8-4797-8b60-53d896b301e1'.  Checking compatability for channels 'PJSIP/0875500000-00000001' and 'PJSIP/swt11-00000000'
[Jan 22 01:02:33] DEBUG[17484] cdr.c: Finalized CDR for PJSIP/0875500000-00000001 - start 1611270152.249789 answer 1611270153.002371 end 1611270153.004770 dur 0.754 bill 0.002 dispo ANSWERED
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge_native_rtp.c: Bridge '9598ee66-59d8-4797-8b60-53d896b301e1' can not use native RTP bridge as channel 'PJSIP/0875500000-00000001' has features which prevent it
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Chose bridge technology simple_bridge
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1 is already using the new technology.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1: 0x7fd080026c00(PJSIP/swt11-00000000) is joining simple_bridge technology
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/swt11-00000000 setting read format path: alaw -> alaw
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/0875500000-00000001 setting write format path: alaw -> alaw
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/0875500000-00000001 setting read format path: alaw -> alaw
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: Channel PJSIP/swt11-00000000 setting write format path: alaw -> alaw
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: PJSIP/swt11-00000000: Topologies already match. Current:  <0:audio-0:audio:sendrecv (alaw|ulaw|g729)>  Requested:  <0:audio-0:audio:sendrecv (alaw|ulaw|g729)>
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: PJSIP/0875500000-00000001: Topologies already match. Current:  <0:audio-0:audio:sendrecv (alaw)>  Requested:  <0:audio-0:audio:sendrecv (alaw)>
[Jan 22 01:02:33] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Media SSRC change
[Jan 22 01:02:33] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated Private Cause Code
[Jan 22 01:02:33] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23535][C-00000001] audiohook.c: Flushing audiohook 0x7fd08000fa90 so it remains in sync
[Jan 22 01:02:33] DEBUG[23535][C-00000001] audiohook.c: Audiohook 0x7fd08000fa90 has stale audio in its factories. Flushing them both
[Jan 22 01:02:33] DEBUG[23534][C-00000001] audiohook.c: Failed to get 160 samples from read factory 0x7fd08000fb18
[Jan 22 01:02:33] DEBUG[23534][C-00000001] audiohook.c: Failed to get 160 samples from read factory 0x7fd08000fb18
[Jan 22 01:02:33] DEBUG[23534][C-00000001] audiohook.c: Failed to get 160 samples from read factory 0x7fd08000fb18
[Jan 22 01:02:33] DEBUG[23534][C-00000001] audiohook.c: Read factory 0x7fd08000fb18 and write factory 0x7fd080010558 both fail to provide 160 samples
[Jan 22 01:02:33] DEBUG[23534][C-00000001] audiohook.c: Failed to get 160 samples from read factory 0x7fd08000fb18
[Jan 22 01:02:33] DEBUG[23534][C-00000001] audiohook.c: Read factory 0x7fd08000fb18 and write factory 0x7fd080010558 both fail to provide 160 samples
[Jan 22 01:02:33] VERBOSE[17499] res_pjsip_logger.c: <--- Received SIP request (995 bytes) from UDP:196.216.192.4:5060 --->
INVITE sip:unknown@196.216.192.22:5060 SIP/2.0
Via: SIP/2.0/UDP 196.216.192.4:5060;rport;branch=z9hG4bKPjf100b2e0-d5b8-488c-bb33-33e6e429628c
From: <sip:0114551322@196.216.192.4>;tag=a01cdb1f-56e9-4c6e-b84d-895deab4f988
To: "Greg [Directors]" <sip:0875500000@196.216.192.22>;tag=536e864b-9b55-48b3-b1ac-01fd7c327b97
Contact: <sip:196.216.192.4:5060>
Call-ID: 4b79a9f3-ea8a-49bb-a057-a68ee1594fef
CSeq: 23622 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800;refresher=uas
Min-SE: 90
Max-Forwards: 70
User-Agent: SwitchTelecom
Content-Type: application/sdp
Content-Length:   264

v=0
o=- 1217002043 1217002046 IN IP4 196.216.192.4
s=SwitchTelecom
c=IN IP4 196.216.192.4
t=0 0
m=image 18391 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxDatagram:494
a=T38FaxUdpEC:t38UDPRedundancy

[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_message_filter.c: Set transport 'transport-udp' on INVITE from 196.216.192.4:5060
[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fd094052c18 for Request msg INVITE/cseq=23622 (rdata0x7fd020000dc8)
[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0875500000-000000a9 associated with dialog dlg0x7fd094052c18
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/0875500000-00000001 Adding position 0
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Can't reuse existing media session because the types are different. image <> audio
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Creating new media session
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Setting media session as default for image
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Done
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/0875500000-00000001
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_t38.c: T.38 state changed to '2' from '0' on channel 'PJSIP/0875500000-00000001'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_t38.c: Deferring incoming SDP stream on PJSIP/0875500000-00000001 for peer re-invite
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge_native_rtp.c: Bridge '9598ee66-59d8-4797-8b60-53d896b301e1'.  Checking compatability for channels 'PJSIP/0875500000-00000001' and 'PJSIP/swt11-00000000'
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge_native_rtp.c: Bridge '9598ee66-59d8-4797-8b60-53d896b301e1' can not use native RTP bridge as channel 'PJSIP/0875500000-00000001' has features which prevent it
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Chose bridge technology simple_bridge
[Jan 22 01:02:33] DEBUG[23535][C-00000001] bridge.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1 is already using the new technology.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000: Indicated T38_Parameters/Invalid
[Jan 22 01:02:33] DEBUG[23530][C-00000001] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000 Adding position 0
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Can't reuse existing media session because the types are different. image <> audio
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Creating new media session
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Setting media session as default for image
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Done
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_t38.c: T.38 state changed to '1' from '0' on channel 'PJSIP/swt11-00000000'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: New SDP? yes  Queued? no DP:  <0:t38:image:sendrecv (t38)>  DA: none
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge_native_rtp.c: Bridge '9598ee66-59d8-4797-8b60-53d896b301e1'.  Checking compatability for channels 'PJSIP/0875500000-00000001' and 'PJSIP/swt11-00000000'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge_native_rtp.c: Bridge '9598ee66-59d8-4797-8b60-53d896b301e1' can not use native RTP bridge as channel 'PJSIP/0875500000-00000001' has features which prevent it
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Delay sending reinvite because of outstanding transaction
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Chose bridge technology simple_bridge
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1 is already using the new technology.
[Jan 22 01:02:33] DEBUG[23534][C-00000001] audiohook.c: Failed to get 160 samples from read factory 0x7fd08000fb18
[Jan 22 01:02:33] DEBUG[23534][C-00000001] audiohook.c: Read factory 0x7fd08000fb18 and write factory 0x7fd080010558 both fail to provide 160 samples
[Jan 22 01:02:33] DEBUG[23530][C-00000001] res_rtp_asterisk.c: (0x7fd07c020430) RTCP got report of 12 bytes from 196.216.192.5:34343
[Jan 22 01:02:33] DEBUG[23530][C-00000001] res_rtp_asterisk.c: (0x7fd07c020430) RTCP 0x7fd07c0213b0 -- from 196.216.192.5:34343: Failed first packet validity check
[Jan 22 01:02:33] VERBOSE[17499] res_pjsip_logger.c: <--- Received SIP request (831 bytes) from UDP:196.216.192.5:5060 --->
ACK sip:196.216.192.22:5060 SIP/2.0
Via: SIP/2.0/UDP 196.216.192.5:5060;branch=z9hG4bK720d.ec6eb4f1.2
From: "Greg #11" <sip:swt11@vpbx2.switchtel.co.za>;tag=56656018
To: <sip:0114551322@vpbx2.switchtel.co.za>;tag=3e6c7b22-4ff6-4787-a07d-dbc57f305b0f
Call-ID: 1441272955-5060-3024@BJC.BGI.B.BF
CSeq: 291 ACK
Contact: <sip:196.216.192.5;did=cd9.a7c6cc57>
Proxy-Authorization: Digest username="swt11", realm="vpbx2.switchtel.co.za", nonce="600a082600005ecc396622e7454526a3783ac580e9bc2283", uri="sip:0114551322@vpbx2.switchtel.co.za", response="8c5b8b3df60c97a724751e7dda12c31e", algorithm=MD5
X-Grandstream-PBX: true
Max-Forwards: 69
Supported: replaces, path, timer
User-Agent: Grandstream GXP2170 1.0.11.10
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_message_filter.c: Set transport 'transport-udp' on ACK from 196.216.192.5:0
[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fd094055f48 for Request msg ACK/cseq=291 (rdata0x7fd020000dc8)
[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000004b associated with dialog dlg0x7fd094055f48
[Jan 22 01:02:33] DEBUG[23526] netsock2.c: Splitting '196.216.192.5' into...
[Jan 22 01:02:33] DEBUG[23526] netsock2.c: ...host '196.216.192.5' and port ''.
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fd09801c7c8
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current transaction state is Terminated
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The transaction state change event is USER
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current inv state is CONNECTING
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: PJSIP/swt11-00000000: INVITE delay check. tsx-state:Terminated
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: PJSIP/swt11-00000000: Received request
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Method is ACK
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000: Queueing SRCCHANGE
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Sending delayed INVITE request
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: sending delayed INVITE request
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: New SDP? yes  Queued? yes DP:  <0:t38:image:sendrecv (t38)>  DA:  <0:audio-0:audio:sendrecv (alaw|ulaw|g729)>
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Pending media state exists
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Active media state exists and is not equal to pending
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: DP:  <0:t38:image:sendrecv (t38)>
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: DA:  <0:audio-0:audio:sendrecv (alaw|ulaw|g729)>
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: CP: (null topology)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: CA:  <0:audio-0:audio:sendrecv (alaw|ulaw|g729)>
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: DP:  <0:t38:image:sendrecv (t38)>  DA:  <0:audio-0:audio:sendrecv (alaw|ulaw|g729)>  CA:  <0:audio-0:audio:sendrecv (alaw|ulaw|g729)>
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: slot: 0 DP: 0:t38:image:sendrecv (t38)  DA: 0:audio-0:audio:sendrecv (alaw|ulaw|g729)  CA: 0:audio-0:audio:sendrecv (alaw|ulaw|g729)
[Jan 22 01:02:33] DEBUG[23535][C-00000001] chan_pjsip.c:  PJSIP/0875500000-00000001: Indicated Media SSRC change
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Checking if DP is already in NP somewhere
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Checking t38 against audio-0
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Checking if DP is already in DA somewhere
[Jan 22 01:02:33] DEBUG[23535][C-00000001] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Checking t38 against audio-0
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Found NP slot: -1  Found removed NP slot: -1 Found DA slot: -1
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: There was no corresponding DA stream so the request was to add a stream
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: There was no corresponding NP stream
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Checking for open slot
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Appended new stream to slot 1
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Resetting default media states
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Running post-validation
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Topology:  <0:audio-0:audio:sendrecv (alaw|ulaw|g729)> <1:t38:image:sendrecv (t38)>
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Checking stream 0:audio-0:audio:sendrecv (alaw|ulaw|g729)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Done with stream 0:audio-0:audio:sendrecv (alaw|ulaw|g729)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Checking stream 1:t38:image:sendrecv (t38)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: media 1 is null
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Valid
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: NP:  <0:audio-0:audio:sendrecv (alaw|ulaw|g729)> <1:t38:image:sendrecv (t38)>
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: NP:  <0:audio-0:audio:sendrecv (alaw|ulaw|g729)> <1:t38:image:sendrecv (t38)>
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Pruning and checking formats of streams
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Checking stream audio-0
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Found existing stream audio-0
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Checking stream t38
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Processing streams
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Processing stream 0:audio-0:audio:sendrecv (alaw|ulaw|g729)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000 Adding position 0
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Using existing media_session
[Jan 22 01:02:33] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) RTCP ignoring duplicate property
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Stream 0:audio-0:audio:sendrecv (alaw|ulaw|g729) added
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Done with 0:audio-0:audio:sendrecv (alaw|ulaw|g729)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Processing stream 1:t38:image:sendrecv (t38)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000 Adding position 1
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Creating new media session
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Setting media session as default for image
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  Done
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/swt11-00000000
[Jan 22 01:02:33] WARNING[23526] udptl.c: UDPTL (no tag): Cannot calculate local_max_datagram before local_max_ifp has been set.
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Stream 1:t38:image:sendrecv (t38) added
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Done with 1:t38:image:sendrecv (t38)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Adding bundle groups (if available)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Copying connection details
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Processing media 0
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Media 0 reset
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Processing media 1
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Media 1 has good existing connection info
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Method is INVITE
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '196.216.192.5'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_resolver.c: Transport type for target '196.216.192.5' is 'UDP transport'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_resolver.c: Target '196.216.192.5' is an IP address, skipping resolution
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 196.216.192.22:5060 (this may be re-written again later)
[Jan 22 01:02:33] VERBOSE[23526] res_pjsip_logger.c: <--- Transmitting SIP request (1165 bytes) to UDP:196.216.192.5:5060 --->
INVITE sip:196.216.192.5;did=cd9.a7c6cc57 SIP/2.0
Via: SIP/2.0/UDP 196.216.192.22:5060;rport;branch=z9hG4bKPjbbb5758f-f670-4f4b-b1e5-5073e6865c0d
From: <sip:0114551322@vpbx2.switchtel.co.za>;tag=3e6c7b22-4ff6-4787-a07d-dbc57f305b0f
To: "Greg" <sip:swt11@vpbx2.switchtel.co.za>;tag=56656018
Contact: <sip:196.216.192.22:5060>
Call-ID: 1441272955-5060-3024@BJC.BGI.B.BF
CSeq: 26465 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub, histinfo
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: SwitchTelecom
Content-Type: application/sdp
Content-Length:   466

v=0
o=- 8000 8003 IN IP4 196.216.192.22
s=SwitchTelecom
c=IN IP4 196.216.192.22
t=0 0
m=audio 17738 RTP/AVP 8 0 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
m=image 19382 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxDatagram:0
a=T38FaxUdpEC:t38UDPRedundancy

[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fd098019178
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current transaction state is Calling
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Sending session refresh SDP via re-INVITE
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] VERBOSE[17499] res_pjsip_logger.c: <--- Received SIP response (429 bytes) from UDP:196.216.192.5:5060 --->
SIP/2.0 100 Giving it a try
Via: SIP/2.0/UDP 196.216.192.22:5060;received=196.216.192.22;rport=5060;branch=z9hG4bKPjbbb5758f-f670-4f4b-b1e5-5073e6865c0d
From: <sip:0114551322@vpbx2.switchtel.co.za>;tag=3e6c7b22-4ff6-4787-a07d-dbc57f305b0f
To: "Greg" <sip:swt11@vpbx2.switchtel.co.za>;tag=56656018
Call-ID: 1441272955-5060-3024@BJC.BGI.B.BF
CSeq: 26465 INVITE
Server: Switch Telecom Hosted Switchboard
Content-Length: 0


[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fd094055f48 for Response msg 100/INVITE/cseq=26465 (rdata0x7fd020000dc8)
[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000004b associated with dialog dlg0x7fd094055f48
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fd098019178)
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fd098019178
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Response is 100 Giving it a try
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000: Status: 100
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000: Not queueing anything
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000: Status: 100
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23535][C-00000001] chan_pjsip.c:  PJSIP/0875500000-00000001: Indicated Private Cause Code
[Jan 22 01:02:33] DEBUG[23535][C-00000001] chan_pjsip.c:  PJSIP/0875500000-00000001
[Jan 22 01:02:33] VERBOSE[17499] res_pjsip_logger.c: <--- Received SIP response (1131 bytes) from UDP:196.216.192.5:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 196.216.192.22:5060;received=196.216.192.22;rport=5060;branch=z9hG4bKPjbbb5758f-f670-4f4b-b1e5-5073e6865c0d
From: <sip:0114551322@vpbx2.switchtel.co.za>;tag=3e6c7b22-4ff6-4787-a07d-dbc57f305b0f
To: "Greg" <sip:swt11@vpbx2.switchtel.co.za>;tag=56656018
Call-ID: 1441272955-5060-3024@BJC.BGI.B.BF
CSeq: 26465 INVITE
Contact: <sip:196.216.192.5;did=cd9.a7c6cc57>
Supported: replaces, path, timer
User-Agent: Grandstream GXP2170 1.0.11.10
Session-Expires: 1800;refresher=uac
Require: timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Content-Length: 457

v=0
o=swt11 8000 8001 IN IP4 196.216.192.5
s=SIP Call
c=IN IP4 196.216.192.5
t=0 0
m=audio 34342 RTP/AVP 8 0 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:18 annexb=no
a=fmtp:101 0-15
a=sendrecv
a=rtcp:34343
a=ptime:20
m=image 0 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxDatagram:0
a=T38FaxUdpEC:t38UDPRedundancy

[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fd094055f48 for Response msg 200/INVITE/cseq=26465 (rdata0x7fd020000dc8)
[Jan 22 01:02:33] DEBUG[17499] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000004b associated with dialog dlg0x7fd094055f48
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: PJSIP/swt11-00000000: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Jan 22 01:02:33] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) RTCP ignoring duplicate property
[Jan 22 01:02:33] DEBUG[23526] netsock2.c: Splitting '196.216.192.5' into...
[Jan 22 01:02:33] DEBUG[23526] netsock2.c: ...host '196.216.192.5' and port ''.
[Jan 22 01:02:33] DEBUG[23526] acl.c: For destination '196.216.192.5', our source address is '196.216.192.22'.
[Jan 22 01:02:33] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) RTCP setting address on RTP instance
[Jan 22 01:02:33] DEBUG[23526] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fd0c32f90a0
[Jan 22 01:02:33] DEBUG[23526] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fd0c32f90a0
[Jan 22 01:02:33] DEBUG[23526] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7fd0c32f90a0
[Jan 22 01:02:33] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 0 (0x7fd07c08e148) from 0x7fd0c32f90a0 to 0x7fd07c020608
[Jan 22 01:02:33] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 8 (0x7fd07c00ddd8) from 0x7fd0c32f90a0 to 0x7fd07c020608
[Jan 22 01:02:33] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 18 (0x7fd07c066ef8) from 0x7fd0c32f90a0 to 0x7fd07c020608
[Jan 22 01:02:33] DEBUG[23526] rtp_engine.c: Copying tx payload mapping 101 (0x7fd07c066ea8) from 0x7fd0c32f90a0 to 0x7fd07c020608
[Jan 22 01:02:33] DEBUG[23526] channel.c: Channel PJSIP/swt11-00000000 setting read format path: alaw -> alaw
[Jan 22 01:02:33] DEBUG[23526] channel.c: Channel PJSIP/swt11-00000000 setting write format path: alaw -> alaw
[Jan 22 01:02:33] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c020430) DTLS - ast_rtp_activate rtp=0x7fd07c0213b0 - setup and perform DTLS'
[Jan 22 01:02:33] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0213b0) DTLS perform handshake - ssl = (nil), setup = 0
[Jan 22 01:02:33] DEBUG[23526] res_rtp_asterisk.c: (0x7fd07c0213b0) DTLS perform handshake - ssl = (nil), setup = 0
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge_native_rtp.c: Bridge '9598ee66-59d8-4797-8b60-53d896b301e1'.  Checking compatability for channels 'PJSIP/0875500000-00000001' and 'PJSIP/swt11-00000000'
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge_native_rtp.c: Bridge '9598ee66-59d8-4797-8b60-53d896b301e1' can not use native RTP bridge as channel 'PJSIP/0875500000-00000001' has features which prevent it
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: PJSIP/swt11-00000000: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Chose bridge technology simple_bridge
[Jan 22 01:02:33] DEBUG[23530][C-00000001] bridge.c: Bridge 9598ee66-59d8-4797-8b60-53d896b301e1 is already using the new technology.
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '196.216.192.5'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_resolver.c: Transport type for target '196.216.192.5' is 'UDP transport'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip/pjsip_resolver.c: Target '196.216.192.5' is an IP address, skipping resolution
[Jan 22 01:02:33] VERBOSE[23526] res_pjsip_logger.c: <--- Transmitting SIP request (419 bytes) to UDP:196.216.192.5:5060 --->
ACK sip:196.216.192.5;did=cd9.a7c6cc57 SIP/2.0
Via: SIP/2.0/UDP 196.216.192.22:5060;rport;branch=z9hG4bKPj255d3900-5cbd-479b-9b45-980ac3607a7a
From: <sip:0114551322@vpbx2.switchtel.co.za>;tag=3e6c7b22-4ff6-4787-a07d-dbc57f305b0f
To: "Greg" <sip:swt11@vpbx2.switchtel.co.za>;tag=56656018
Call-ID: 1441272955-5060-3024@BJC.BGI.B.BF
CSeq: 26465 ACK
Max-Forwards: 70
User-Agent: SwitchTelecom
Content-Length:  0


[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The state change pertains to the endpoint 'swt11(PJSIP/swt11-00000000)'
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fd098019178
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current transaction state is Terminated
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000: Response is 200 OK
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000: Status: 200
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000: Queueing ANSWER
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000: Status: 200
[Jan 22 01:02:33] DEBUG[23526] chan_pjsip.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_session.c:  PJSIP/swt11-00000000
[Jan 22 01:02:33] DEBUG[23526] res_pjsip_t38.c: T.38 state changed to '3' from '1' on channel 'PJSIP/swt11-00000000'
[Jan 22 01:02:33] DEBUG[23530][C-00000001] channel.c: Dropping duplicate answer!