[Apr 3 14:35:24] VERBOSE[20543] netsock.c: == Using SIP RTP CoS mark 5 [Apr 3 14:35:24] DEBUG[20543] chan_sip.c: Setting NAT on RTP to Off [Apr 3 14:35:24] DEBUG[20543] chan_sip.c: Allocating new SIP dialog for a0ba99dc-9148fbe1-5bc42e0a@10.0.2.9 - INVITE (With RTP) [Apr 3 14:35:24] DEBUG[20543] chan_sip.c: Setting NAT on RTP to On [Apr 3 14:35:24] DEBUG[20543] chan_sip.c: Stopping retransmission on 'a0ba99dc-9148fbe1-5bc42e0a@10.0.2.9' of Response 1: Match Found [Apr 3 14:35:24] DEBUG[20543] chan_sip.c: Setting NAT on RTP to On [Apr 3 14:35:24] DEBUG[20543] chan_sip.c: Checking SIP call limits for device 1000 [Apr 3 14:35:24] DEBUG[20553] pbx.c: Launching 'Gosub' [Apr 3 14:35:24] VERBOSE[20553] pbx.c: -- Executing [5130582@kenny:1] Gosub("SIP/1000-00000003", "gv-out,s,1(19895130582)") in new stack [Apr 3 14:35:24] DEBUG[20553] app_stack.c: Channel SIP/1000-00000003 has no datastore, so we're allocating one. [Apr 3 14:35:24] DEBUG[20553] app_stack.c: Setting 'ARG1' to '19895130582' [Apr 3 14:35:24] DEBUG[20553] pbx.c: Launching 'Wait' [Apr 3 14:35:24] VERBOSE[20553] pbx.c: -- Executing [s@gv-out:1] Wait("SIP/1000-00000003", "1") in new stack [Apr 3 14:35:25] DEBUG[20553] pbx.c: Launching 'Set' [Apr 3 14:35:25] VERBOSE[20553] pbx.c: -- Executing [s@gv-out:2] Set("SIP/1000-00000003", "ACCTNAME=henshaw.barnt") in new stack [Apr 3 14:35:25] DEBUG[20553] pbx.c: Launching 'Set' [Apr 3 14:35:25] VERBOSE[20553] pbx.c: -- Executing [s@gv-out:3] Set("SIP/1000-00000003", "ACCTPASS=400babies") in new stack [Apr 3 14:35:25] DEBUG[20553] pbx.c: Launching 'Set' [Apr 3 14:35:25] VERBOSE[20553] pbx.c: -- Executing [s@gv-out:4] Set("SIP/1000-00000003", "RINGBACK=14156513741") in new stack [Apr 3 14:35:25] DEBUG[20553] pbx.c: Launching 'Set' [Apr 3 14:35:25] VERBOSE[20553] pbx.c: -- Executing [s@gv-out:5] Set("SIP/1000-00000003", "CALLPARK=7020") in new stack [Apr 3 14:35:25] DEBUG[20553] pbx.c: Launching 'Playback' [Apr 3 14:35:25] VERBOSE[20553] pbx.c: -- Executing [s@gv-out:6] Playback("SIP/1000-00000003", "pls-wait-connect-call") in new stack [Apr 3 14:35:25] DEBUG[20553] chan_sip.c: SIP answering channel: SIP/1000-00000003 [Apr 3 14:35:25] DEBUG[20553] chan_sip.c: Setting framing from config on incoming call [Apr 3 14:35:25] DEBUG[20553] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Apr 3 14:35:25] DEBUG[20553] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Apr 3 14:35:25] DEBUG[20543] chan_sip.c: Stopping retransmission on 'a0ba99dc-9148fbe1-5bc42e0a@10.0.2.9' of Response 2: Match Found [Apr 3 14:35:25] DEBUG[20553] rtp.c: RTP NAT: Got audio from other end. Now sending to address 71.13.223.53:2222 [Apr 3 14:35:26] DEBUG[20553] rtp.c: Ooh, format changed from unknown to ulaw [Apr 3 14:35:26] DEBUG[20553] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Apr 3 14:35:26] DEBUG[20553] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 3 14:35:26] VERBOSE[20553] file.c: -- Playing 'pls-wait-connect-call.ulaw' (language 'en') [Apr 3 14:35:26] DEBUG[20553] rtp.c: Got RTCP report of 92 bytes [Apr 3 14:35:28] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:28] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:28] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:28] DEBUG[20553] pbx.c: Launching 'System' [Apr 3 14:35:28] VERBOSE[20553] pbx.c: -- Executing [s@gv-out:7] System("SIP/1000-00000003", "gvoice -e henshaw.barnt -p 400babies call 19895130582 14156513741") in new stack [Apr 3 14:35:31] DEBUG[20554] rtp.c: Got RTCP report of 92 bytes [Apr 3 14:35:34] DEBUG[20553] pbx.c: Launching 'Set' [Apr 3 14:35:34] VERBOSE[20553] pbx.c: -- Executing [s@gv-out:8] Set("SIP/1000-00000003", "PARKINGEXTEN=7020") in new stack [Apr 3 14:35:34] DEBUG[20553] pbx.c: Launching 'Park' [Apr 3 14:35:34] VERBOSE[20553] pbx.c: -- Executing [s@gv-out:9] Park("SIP/1000-00000003", "") in new stack [Apr 3 14:35:35] DEBUG[20553] features.c: Parkinglot: default [Apr 3 14:35:35] DEBUG[20553] channel.c: Planning to masquerade channel SIP/1000-00000003 into the structure of Parked/SIP/1000-00000003 [Apr 3 14:35:35] DEBUG[20553] channel.c: Done planning to masquerade channel SIP/1000-00000003 into the structure of Parked/SIP/1000-00000003 [Apr 3 14:35:35] DEBUG[20553] channel.c: Putting channel SIP/1000-00000003 in 4/4 formats [Apr 3 14:35:35] DEBUG[20553] channel.c: Released clone lock on 'Parked/SIP/1000-00000003' [Apr 3 14:35:35] DEBUG[20553] channel.c: Done Masquerading SIP/1000-00000003 (6) [Apr 3 14:35:35] VERBOSE[20553] features.c: == Parked SIP/1000-00000003 on 7020 (lot default). Will timeout back to extension [gv-out] s, 1 in 45 seconds [Apr 3 14:35:35] DEBUG[20553] pbx.c: Added extension '7020' priority 1 to parkedcalls (0x7f19fc114520) [Apr 3 14:35:35] VERBOSE[20553] pbx.c: -- Added extension '7020' priority 1 to parkedcalls (0x7f19fc114520) [Apr 3 14:35:35] DEBUG[20553] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 3 14:35:35] VERBOSE[20553] file.c: -- Playing 'digits/7.ulaw' (language 'en') [Apr 3 14:35:36] DEBUG[20553] channel.c: Scheduling timer at (52 requested / 52 actual) timer ticks per second [Apr 3 14:35:36] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:36] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:36] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:36] DEBUG[20553] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 3 14:35:36] VERBOSE[20553] file.c: -- Playing 'digits/0.ulaw' (language 'en') [Apr 3 14:35:36] DEBUG[20553] rtp.c: Got RTCP report of 92 bytes [Apr 3 14:35:36] DEBUG[20553] channel.c: Scheduling timer at (56 requested / 56 actual) timer ticks per second [Apr 3 14:35:36] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:36] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:36] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:37] DEBUG[20553] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 3 14:35:37] VERBOSE[20553] file.c: -- Playing 'digits/2.ulaw' (language 'en') [Apr 3 14:35:37] DEBUG[20553] channel.c: Scheduling timer at (1000 requested / 100 actual) timer ticks per second [Apr 3 14:35:37] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:37] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:37] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:37] DEBUG[20553] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 3 14:35:37] VERBOSE[20553] file.c: -- Playing 'digits/0.ulaw' (language 'en') [Apr 3 14:35:37] VERBOSE[20543] netsock.c: == Using SIP RTP CoS mark 5 [Apr 3 14:35:37] DEBUG[20543] chan_sip.c: Setting NAT on RTP to Off [Apr 3 14:35:37] DEBUG[20543] chan_sip.c: Allocating new SIP dialog for 49d968207ff821ed090ce0c96e183000@sipgate.com - INVITE (With RTP) [Apr 3 14:35:37] DEBUG[20543] chan_sip.c: Setting NAT on RTP to Off [Apr 3 14:35:37] DEBUG[20543] chan_sip.c: Checking SIP call limits for device 4408404e1 [Apr 3 14:35:37] DEBUG[20566] pbx.c: Launching 'NoOp' [Apr 3 14:35:37] VERBOSE[20566] pbx.c: -- Executing [4408404e1@sipgate-in:1] NoOp("SIP/sipgate-00000004", "Incoming SIP Gate Call from : 9894920536") in new stack [Apr 3 14:35:37] DEBUG[20566] pbx.c: Expression result is '1' [Apr 3 14:35:37] DEBUG[20566] pbx.c: Launching 'GotoIf' [Apr 3 14:35:37] VERBOSE[20566] pbx.c: -- Executing [4408404e1@sipgate-in:2] GotoIf("SIP/sipgate-00000004", "1?gvringback:gvincoming") in new stack [Apr 3 14:35:37] VERBOSE[20566] pbx.c: -- Goto (sipgate-in,4408404e1,4) [Apr 3 14:35:37] DEBUG[20566] pbx.c: Launching 'Answer' [Apr 3 14:35:37] VERBOSE[20566] pbx.c: -- Executing [4408404e1@sipgate-in:4] Answer("SIP/sipgate-00000004", "") in new stack [Apr 3 14:35:37] DEBUG[20566] chan_sip.c: SIP answering channel: SIP/sipgate-00000004 [Apr 3 14:35:37] DEBUG[20566] chan_sip.c: Setting framing from config on incoming call [Apr 3 14:35:37] DEBUG[20566] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Apr 3 14:35:37] DEBUG[20566] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Apr 3 14:35:38] DEBUG[20543] chan_sip.c: Stopping retransmission on '49d968207ff821ed090ce0c96e183000@sipgate.com' of Response 103: Match Found [Apr 3 14:35:38] DEBUG[20566] pbx.c: Launching 'ParkedCall' [Apr 3 14:35:38] VERBOSE[20566] pbx.c: -- Executing [4408404e1@sipgate-in:5] ParkedCall("SIP/sipgate-00000004", "7020") in new stack [Apr 3 14:35:38] VERBOSE[20566] features.c: -- Channel SIP/sipgate-00000004 connected to parked call 7020 [Apr 3 14:35:38] VERBOSE[20566] rtp.c: -- Packet2Packet bridging SIP/sipgate-00000004 and SIP/1000-00000003 [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749114087696 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20553] channel.c: Thread 139749114087696 Blocking 'SIP/1000-00000003', already blocked by thread 139749114087696 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20553] channel.c: Thread 139749114087696 Blocking 'SIP/1000-00000003', already blocked by thread 139749114087696 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749114087696 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20553] channel.c: Scheduling timer at (56 requested / 56 actual) timer ticks per second [Apr 3 14:35:38] DEBUG[20566] channel.c: Thread 139749113071888 Blocking 'SIP/1000-00000003', already blocked by thread 139749113071888 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20553] channel.c: Thread 139749114087696 Blocking 'SIP/1000-00000003', already blocked by thread 139749114087696 in procedure ast_waitfor_nandfds [Apr 3 14:35:38] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:38] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 3 14:35:38] DEBUG[20553] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second