[asterisk-bugs] [JIRA] (ASTERISK-28181) ari: Originating overwrites channel start time
sungtae kim (JIRA)
noreply at issues.asterisk.org
Wed Jan 16 17:11:47 CST 2019
[ https://issues.asterisk.org/jira/browse/ASTERISK-28181?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=245987#comment-245987 ]
sungtae kim commented on ASTERISK-28181:
----------------------------------------
Dev note.
{noformat}
[Jan 17 00:08:33] DEBUG[108609] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7f0fa4011708)
[Jan 17 00:08:33] DEBUG[108609] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000034 to use for Request msg INVITE/cseq=1 (rdata0x7f0fa4011708)
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '127.0.0.1' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '127.0.0.1' and port ''.
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_endpoint_identifier_ip.c: Source address 127.0.0.1:5061 matches identify 'sipp-uac'
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_endpoint_identifier_ip.c: Identify 'sipp-uac' SIP message matched to endpoint sipp-uac
[Jan 17 00:08:33] DEBUG[108610] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000034 to use for Request msg INVITE/cseq=1 (rdata0x7f0fa4008a58)
[Jan 17 00:08:33] VERBOSE[108610] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '127.0.0.1'
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac()'
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f0fa401ac68)
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The current inv state is INCOMING
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac()'
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f0fa401ac68)
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The current inv state is INCOMING
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '127.0.0.1' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '127.0.0.1' and port ''.
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:33] DEBUG[108610] res_rtp_asterisk.c: Allocated port 19058 for RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:33] DEBUG[108610] res_rtp_asterisk.c: Creating ICE session [::]:19058 (19058) for RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting 'fe80::20c:29ff:fe4b:95b1' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host 'fe80::20c:29ff:fe4b:95b1' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting 'fe80::20c:29ff:fe4b:95b1' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host 'fe80::20c:29ff:fe4b:95b1' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting 'fe80::20c:29ff:fe4b:95bb' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host 'fe80::20c:29ff:fe4b:95bb' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting 'fe80::20c:29ff:fe4b:95bb' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host 'fe80::20c:29ff:fe4b:95bb' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '172.16.78.131' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '172.16.78.131' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '172.16.78.131' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '172.16.78.131' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '192.168.30.10' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '192.168.30.10' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '192.168.30.10' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '192.168.30.10' and port ''.
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: RTP instance '0x7f0fa4039fd0' is setup and ready to go
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting 'debian' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host 'debian' and port ''.
[Jan 17 00:08:33] DEBUG[108610] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f0fafc9a440
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7f0fa4041cd8) from 0x7f0fafc9a440 to 0x7f0fafc9a440
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: Copying rx payload mapping 0 (0x7f0fa4041cd8) from 0x7f0fafc9a440 to 0x7f0fa403a1a8
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: Copying tx payload mapping 0 (0x7f0fa4041cd8) from 0x7f0fafc9a440 to 0x7f0fa403a1a8
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Media stream 'audio' handled by audio
[Jan 17 00:08:33] DEBUG[108610] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Method is INVITE
[Jan 17 00:08:33] DEBUG[108610] channel.c: Channel 0x7f0fa4031290 'PJSIP/sipp-uac-00000003' allocated
[Jan 17 00:08:33] DEBUG[108610] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/sipp-uac-00000003
[Jan 17 00:08:33] DEBUG[108666] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: none
Uniqueid: none
Variable: SIPDOMAIN
Value: 127.0.0.1
[Jan 17 00:08:33] DEBUG[108666] manager.c: Examining AMI event:
Event: Newchannel
Privilege: call,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 1
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
[Jan 17 00:08:33] DEBUG[108674][C-00000004] pbx.c: Launching 'NoOp'
[Jan 17 00:08:33] VERBOSE[108674][C-00000004] pbx.c: Executing [agi_test at sipp-uac:1] NoOp("PJSIP/sipp-uac-00000003", "agi_test") in new stack
[Jan 17 00:08:33] DEBUG[108666] manager.c: Examining AMI event:
Event: Newexten
Privilege: dialplan,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 1
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Extension: agi_test
Application: NoOp
AppData: agi_test
[Jan 17 00:08:33] DEBUG[108674][C-00000004] pbx.c: Launching 'AGI'
[Jan 17 00:08:33] VERBOSE[108674][C-00000004] pbx.c: Executing [agi_test at sipp-uac:2] AGI("PJSIP/sipp-uac-00000003", "agi:async,agi_test") in new stack
[Jan 17 00:08:33] DEBUG[108666] manager.c: Examining AMI event:
Event: Newexten
Privilege: dialplan,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Extension: agi_test
Application: AGI
AppData: agi:async,agi_test
[Jan 17 00:08:33] DEBUG[108666] manager.c: Examining AMI event:
Event: AsyncAGIStart
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Env: agi_request%3A%20async%0Aagi_channel%3A%20PJSIP%2Fsipp-uac-00000003%0Aagi_language%3A%20en%0Aagi_type%3A%20PJSIP%0Aagi_uniqueid%3A%201547680113.3%0Aagi_version%3A%20GIT-master-d35873644c%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20agi_test%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20sipp-uac%0Aagi_extension%3A%20agi_test%0Aagi_priority%3A%202%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139704269924096%0Aagi_arg_1%3A%20agi_test%0A%0A
[Jan 17 00:08:44] DEBUG[108666] manager.c: Running action 'AGI'
[Jan 17 00:08:44] DEBUG[108589] devicestate.c: No provider found, checking channel drivers for PJSIP - sipp-uac
[Jan 17 00:08:44] DEBUG[108589] devicestate.c: Changing state for PJSIP/sipp-uac - state 2 (In use)
[Jan 17 00:08:44] DEBUG[108655] app_queue.c: Device 'PJSIP/sipp-uac' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Jan 17 00:08:44] DEBUG[108610] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:44] DEBUG[108610] netsock2.c: Splitting '127.0.0.1' into...
[Jan 17 00:08:44] DEBUG[108610] netsock2.c: ...host '127.0.0.1' and port ''.
[Jan 17 00:08:44] DEBUG[108610] acl.c: For destination '127.0.0.1', our source address is '127.0.0.1'.
[Jan 17 00:08:44] DEBUG[108610] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:44] VERBOSE[108610] res_rtp_asterisk.c: 0x7f0fa403d630 -- Strict RTP learning after remote address set to: 127.0.0.1:6000
[Jan 17 00:08:44] DEBUG[108610] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f0fafc9a070
[Jan 17 00:08:44] DEBUG[108610] rtp_engine.c: Copying tx payload mapping 0 (0x7f0fa4000f18) from 0x7f0fafc9a070 to 0x7f0fa403a1a8
[Jan 17 00:08:44] DEBUG[108610] channel.c: Channel PJSIP/sipp-uac-00000003 setting read format path: ulaw -> ulaw
[Jan 17 00:08:44] DEBUG[108610] channel.c: Channel PJSIP/sipp-uac-00000003 setting write format path: ulaw -> ulaw
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Method is INVITE, Response is 200 OK
[Jan 17 00:08:44] DEBUG[108610] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 127.0.0.1:5060 (this may be re-written again later)
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac(PJSIP/sipp-uac-00000003)'
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f0fa401ac68)
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current inv state is CONNECTING
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac(PJSIP/sipp-uac-00000003)'
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f0fa401ac68)
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current transaction state is Completed
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current inv state is CONNECTING
[Jan 17 00:08:44] DEBUG[108666] manager.c: Examining AMI event:
Event: AGIExecStart
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
CommandId: 1501975288
Command: Answer
[Jan 17 00:08:44] DEBUG[108666] manager.c: Examining AMI event:
Event: Newstate
Privilege: call,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
[Jan 17 00:08:44] DEBUG[108666] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: PJSIP/sipp-uac
State: INUSE
[Jan 17 00:08:44] DEBUG[108609] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f0fa4034428 for Request msg ACK/cseq=1 (rdata0x7f0fa4011708)
[Jan 17 00:08:44] DEBUG[108609] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000034 associated with dialog dlg0x7f0fa4034428
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac(PJSIP/sipp-uac-00000003)'
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current transaction state is Terminated
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The transaction state change event is USER
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current inv state is CONNECTING
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac(PJSIP/sipp-uac-00000003)'
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Received request
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Method is ACK
[Jan 17 00:08:44] DEBUG[108674][C-00000004] channel.c: Didn't receive a media frame from PJSIP/sipp-uac-00000003 within 500 ms of answering. Continuing anyway
[Jan 17 00:08:44] DEBUG[108666] manager.c: Examining AMI event:
Event: AGIExecEnd
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
CommandId: 1501975288
Command: Answer
ResultCode: 200
Result: Success
[Jan 17 00:08:44] DEBUG[108666] manager.c: Examining AMI event:
Event: AsyncAGIExec
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Result: 200%20result%3D0%0A
[Jan 17 00:08:45] DEBUG[108621] res_pjsip_registrar.c: Woke up at 1547680125 Interval: 30
[Jan 17 00:08:45] DEBUG[108621] res_pjsip_registrar.c: Expiring 0 contacts
[Jan 17 00:08:52] DEBUG[108666] manager.c: Running action 'AGI'
[Jan 17 00:08:53] DEBUG[108674][C-00000004] pbx.c: Launching 'Wait'
[Jan 17 00:08:53] VERBOSE[108674][C-00000004] pbx.c: Executing [agi_test at sipp-uac:3] Wait("PJSIP/sipp-uac-00000003", "10") in new stack
[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: AGIExecStart
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
CommandId: 1858247138
Command: asyncagi break
[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: AGIExecEnd
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
CommandId: 1858247138
Command: asyncagi break
ResultCode: 200
Result: Success
[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: AsyncAGIExec
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Result: 200%20result%3D0%0A
[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: AsyncAGIEnd
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Variable: AGISTATUS
Value: SUCCESS
[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: Newexten
Privilege: dialplan,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 3
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Extension: agi_test
Application: Wait
AppData: 10
[Jan 17 00:09:03] DEBUG[108674][C-00000004] pbx.c: Launching 'Hangup'
[Jan 17 00:09:03] VERBOSE[108674][C-00000004] pbx.c: Executing [agi_test at sipp-uac:4] Hangup("PJSIP/sipp-uac-00000003", "") in new stack
[Jan 17 00:09:03] DEBUG[108674][C-00000004] channel.c: Soft-Hanging (0x20) up channel 'PJSIP/sipp-uac-00000003'
[Jan 17 00:09:03] DEBUG[108674][C-00000004] pbx.c: Spawn extension (sipp-uac,agi_test,4) exited non-zero on 'PJSIP/sipp-uac-00000003'
[Jan 17 00:09:03] VERBOSE[108674][C-00000004] pbx.c: Spawn extension (sipp-uac, agi_test, 4) exited non-zero on 'PJSIP/sipp-uac-00000003'
[Jan 17 00:09:03] DEBUG[108674][C-00000004] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/sipp-uac-00000003'
[Jan 17 00:09:03] DEBUG[108674][C-00000004] channel.c: Channel 0x7f0fa4031290 'PJSIP/sipp-uac-00000003' hanging up. Refs: 2
[Jan 17 00:09:03] DEBUG[108674][C-00000004] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[Jan 17 00:09:03] DEBUG[108666] manager.c: Examining AMI event:
Event: Newexten
Privilege: dialplan,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 4
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Extension: agi_test
Application: Hangup
AppData:
[Jan 17 00:09:03] DEBUG[108666] manager.c: Examining AMI event:
Event: SoftHangupRequest
Privilege: call,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 4
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Cause: 16
[Jan 17 00:09:03] DEBUG[108610] rtp_engine.c: Destroyed RTP instance '0x7f0fa4039fd0'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Method is BYE
[Jan 17 00:09:03] DEBUG[108610] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '127.0.0.1'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip/pjsip_resolver.c: Transport type for target '127.0.0.1' is 'UDP'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip/pjsip_resolver.c: Target '127.0.0.1' is an IP address, skipping resolution
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac(PJSIP/sipp-uac-00000003)'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The current transaction state is Calling
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 17 00:09:03] DEBUG[108610] channel.c: Channel 0x7f0fa4031290 'PJSIP/sipp-uac-00000003' destroying
[Jan 17 00:09:03] DEBUG[108589] devicestate.c: No provider found, checking channel drivers for PJSIP - sipp-uac
[Jan 17 00:09:03] DEBUG[108589] devicestate.c: Changing state for PJSIP/sipp-uac - state 1 (Not in use)
[Jan 17 00:09:03] DEBUG[108655] app_queue.c: Device 'PJSIP/sipp-uac' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 17 00:09:03] DEBUG[108602] cdr.c: Finalized CDR for PJSIP/sipp-uac-00000003 - start 1547680113.060110 answer 1547680124.298005 end 1547680143.028024 dispo ANSWERED
[Jan 17 00:09:03] DEBUG[108666] manager.c: Examining AMI event:
Event: Hangup
Privilege: call,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 4
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Cause: 16
Cause-txt: Normal Clearing
[Jan 17 00:09:03] DEBUG[108666] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: PJSIP/sipp-uac
State: NOT_INUSE
[Jan 17 00:09:03] DEBUG[108609] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f0fa4034428 for Response msg 200/BYE/cseq=24124 (rdata0x7f0fa4011708)
[Jan 17 00:09:03] DEBUG[108609] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000034 associated with dialog dlg0x7f0fa4034428
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac()'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Received response
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Response is 200 OK
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac()'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The current transaction state is Completed
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Received response
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Response is 200 OK
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: BYE received final response code 200
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac()'
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The current transaction state is Terminated
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The transaction state change event is TIMER
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 17 00:09:08] DEBUG[108610] res_pjsip_session.c: Destroying SIP session with endpoint sipp-uac
[Jan 17 00:09:15] DEBUG[108621] res_pjsip_registrar.c: Woke up at 1547680155 Interval: 30
[Jan 17 00:09:15] DEBUG[108621] res_pjsip_registrar.c: Expiring 0 contacts
{noformat}
> ari: Originating overwrites channel start time
> ----------------------------------------------
>
> Key: ASTERISK-28181
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-28181
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Resources/res_ari_channels
> Affects Versions: 15.6.1, 16.0.0
> Environment: debian-9
> Reporter: sungtae kim
> Assignee: sungtae kim
> Labels: pjsip
> Attachments: ari_test.sh, cli.log, extensions.conf, full.log, pjsip.conf
>
>
> Hi, the outbound calling via ARI, it overwrites the channel's start time.
> And it causes wrong CDR time calculation. - It makes shorter duration time than bill seconds.
> If you see the bill sec, it's 8.097032. And call duration is 6.420880.
> {noformat}
> [2018-11-26 08:55:34] DEBUG[15482] res_pjsip_registrar.c: Woke up at 1543222534 Interval: 30
> [2018-11-26 08:55:34] DEBUG[15482] res_pjsip_registrar.c: Expiring 0 contacts
> [2018-11-26 08:55:37] DEBUG[15641] http.c: HTTP opening session. Top level
> [2018-11-26 08:55:37] DEBUG[15641] http.c: HTTP Request URI is /ari/channels/testout-699786.201829
> [2018-11-26 08:55:37] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829] with handler [httpstatus] len 10
> [2018-11-26 08:55:37] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829] with handler [phoneprov] len 9
> [2018-11-26 08:55:37] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829] with handler [static] len 6
> [2018-11-26 08:55:37] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829] with handler [ari] len 3
> [2018-11-26 08:55:37] DEBUG[15641] http.c: Match made with [ari]
> [2018-11-26 08:55:37] DEBUG[15641] http.c: HTTP consuming request body
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Finding handler for channels
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking asterisk
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking endpoints
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking recordings
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking events
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking applications
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking sounds
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking deviceStates
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking bridges
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking playbacks
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking channels
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Finding handler for testout-699786.201829
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking create
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Checking channelId
> [2018-11-26 08:55:37] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:37] DEBUG[15641] channel.c: Channel 0x7fe0e80048b0 'PJSIP/test-voip-00000002' allocated
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_header_funcs.c: Adding header P-Asserted-Identity with value tel:1337
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_header_funcs.c: Adding header X-Leg-ID with value d30c2825-c8fd-4852-8945-ee43de6be34a
> [2018-11-26 08:55:37] DEBUG[15641] res_stasis.c: test_voip: Subscribing to testout-699786.201829
> [2018-11-26 08:55:37] DEBUG[15641] stasis/app.c: Channel 'testout-699786.201829' is 1 interested in test_voip
> [2018-11-26 08:55:37] DEBUG[15473] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fe11400a780'
> [2018-11-26 08:55:37] DEBUG[15473] res_rtp_asterisk.c: Allocated port 14050 for RTP instance '0x7fe11400a780'
> [2018-11-26 08:55:37] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 499
> [2018-11-26 08:55:37] DEBUG[15473] res_rtp_asterisk.c: Creating ICE session [::]:14050 (14050) for RTP instance '0x7fe11400a780'
> [2018-11-26 08:55:37] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 499
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: Splitting 'fe80::4001:aff:fe84:12' into...
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: ...host 'fe80::4001:aff:fe84:12' and port ''.
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: Splitting 'fe80::4001:aff:fe84:12' into...
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: ...host 'fe80::4001:aff:fe84:12' and port ''.
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: Splitting '10.132.0.18' into...
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: ...host '10.132.0.18' and port ''.
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: Splitting '10.132.0.18' into...
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: ...host '10.132.0.18' and port ''.
> [2018-11-26 08:55:37] DEBUG[15473] rtp_engine.c: RTP instance '0x7fe11400a780' is setup and ready to go
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: Splitting 'voice-asterisk-staging-europe-west1-d-01' into...
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: ...host 'voice-asterisk-staging-europe-west1-d-01' and port ''.
> [2018-11-26 08:55:37] DEBUG[15473] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fe11400a780'
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: Method is INVITE
> [2018-11-26 08:55:37] VERBOSE[15642] dial.c: Called test-voip/sip:200031616818985 at 80.252.95.172
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.132.0.21'
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip/pjsip_resolver.c: Transport type for target '10.132.0.21' is 'UDP'
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip/pjsip_resolver.c: Target '10.132.0.21' is an IP address, skipping resolution
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.132.0.18:5080 (this may be re-written again later)
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: Splitting '10.132.0.21' into...
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: ...host '10.132.0.21' and port ''.
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: Splitting '10.132.0.18' into...
> [2018-11-26 08:55:37] DEBUG[15473] netsock2.c: ...host '10.132.0.18' and port ''.
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: Setting external media address to 10.132.0.18
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: There is no transaction involved in this state change
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The current inv state is CALLING
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: Source of transaction state change is TX_MSG
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fe11400aef8
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The current transaction state is Calling
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The transaction state change event is TX_MSG
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The current inv state is CALLING
> [2018-11-26 08:55:37] DEBUG[15641] http.c: HTTP keeping session open. status_code:200
> [2018-11-26 08:55:37] DEBUG[15472] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe11402c8c8 for Response msg 100/INVITE/cseq=4227 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:37] DEBUG[15472] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/test-voip-0000005f associated with dialog dlg0x7fe11402c8c8
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fe11400aef8
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The current transaction state is Proceeding
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The transaction state change event is RX_MSG
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: The current inv state is CALLING
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:37] DEBUG[15473] res_pjsip_session.c: Response is 100 Trying
> [2018-11-26 08:55:42] DEBUG[15472] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe11402c8c8 for Response msg 183/INVITE/cseq=4227 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:42] DEBUG[15472] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/test-voip-0000005f associated with dialog dlg0x7fe11402c8c8
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: There is no transaction involved in this state change
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The current inv state is EARLY
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Source of transaction state change is RX_MSG
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Response is 183 Session Progress
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
> [2018-11-26 08:55:42] DEBUG[15473] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fe11400a780'
> [2018-11-26 08:55:42] DEBUG[15473] netsock2.c: Splitting '10.132.15.220' into...
> [2018-11-26 08:55:42] DEBUG[15473] netsock2.c: ...host '10.132.15.220' and port ''.
> [2018-11-26 08:55:42] DEBUG[15473] acl.c: For destination '10.132.15.220', our source address is '10.132.0.18'.
> [2018-11-26 08:55:42] DEBUG[15473] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fe11400a780'
> [2018-11-26 08:55:42] VERBOSE[15473] res_rtp_asterisk.c: 0x7fe11400cd80 -- Strict RTP learning after remote address set to: 10.132.15.220:36780
> [2018-11-26 08:55:42] DEBUG[15473] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fe0b7215ed0
> [2018-11-26 08:55:42] DEBUG[15473] rtp_engine.c: Copying tx payload mapping 8 (0x7fe1140288e8) from 0x7fe0b7215ed0 to 0x7fe11400a958
> [2018-11-26 08:55:42] DEBUG[15473] rtp_engine.c: Copying tx payload mapping 101 (0x7fe114028938) from 0x7fe0b7215ed0 to 0x7fe11400a958
> [2018-11-26 08:55:42] DEBUG[15473] channel.c: Channel PJSIP/test-voip-00000002 setting read format path: alaw -> ulaw
> [2018-11-26 08:55:42] DEBUG[15473] channel.c: Channel PJSIP/test-voip-00000002 setting write format path: ulaw -> alaw
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fe11400aef8
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The current transaction state is Proceeding
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The transaction state change event is RX_MSG
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The current inv state is EARLY
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Response is 183 Session Progress
> [2018-11-26 08:55:42] VERBOSE[15642] dial.c: PJSIP/test-voip-00000002 is making progress
> [2018-11-26 08:55:42] VERBOSE[15642] dial.c: PJSIP/test-voip-00000002 is making progress
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 507
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 507
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 507
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 507
> [2018-11-26 08:55:42] DEBUG[15472] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe11402c8c8 for Response msg 183/INVITE/cseq=4227 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:42] DEBUG[15472] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/test-voip-0000005f associated with dialog dlg0x7fe11402c8c8
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: There is no transaction involved in this state change
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The current inv state is EARLY
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Source of transaction state change is RX_MSG
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Response is 183 Session Progress
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fe11400aef8
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The current transaction state is Proceeding
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The transaction state change event is RX_MSG
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The current inv state is EARLY
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Response is 183 Session Progress
> [2018-11-26 08:55:42] VERBOSE[15642] dial.c: PJSIP/test-voip-00000002 is making progress
> [2018-11-26 08:55:42] VERBOSE[15642] dial.c: PJSIP/test-voip-00000002 is making progress
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 507
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 507
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 507
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 507
> [2018-11-26 08:55:42] DEBUG[15472] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe11402c8c8 for Response msg 183/INVITE/cseq=4227 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:42] DEBUG[15472] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/test-voip-0000005f associated with dialog dlg0x7fe11402c8c8
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: There is no transaction involved in this state change
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The current inv state is EARLY
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Source of transaction state change is RX_MSG
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Response is 183 Session Progress
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fe11400aef8
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The current transaction state is Proceeding
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The transaction state change event is RX_MSG
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: The current inv state is EARLY
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:42] DEBUG[15473] res_pjsip_session.c: Response is 183 Session Progress
> [2018-11-26 08:55:42] VERBOSE[15642] dial.c: PJSIP/test-voip-00000002 is making progress
> [2018-11-26 08:55:42] VERBOSE[15642] dial.c: PJSIP/test-voip-00000002 is making progress
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 507
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 507
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 507
> [2018-11-26 08:55:42] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 507
> [2018-11-26 08:55:42] VERBOSE[15642] res_rtp_asterisk.c: 0x7fe11400cd80 -- Strict RTP switching to RTP target address 10.132.15.220:36780 as source
> [2018-11-26 08:55:43] DEBUG[15472] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe11402c8c8 for Response msg 180/INVITE/cseq=4227 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:43] DEBUG[15472] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/test-voip-0000005f associated with dialog dlg0x7fe11402c8c8
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: There is no transaction involved in this state change
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: The current inv state is EARLY
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: Source of transaction state change is RX_MSG
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: Response is 180 Ringing
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fe11400aef8
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: The current transaction state is Proceeding
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: The transaction state change event is RX_MSG
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: The current inv state is EARLY
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:43] DEBUG[15473] res_pjsip_session.c: Response is 180 Ringing
> [2018-11-26 08:55:43] DEBUG[15459] devicestate.c: No provider found, checking channel drivers for PJSIP - test-voip
> [2018-11-26 08:55:43] DEBUG[15459] devicestate.c: Changing state for PJSIP/test-voip - state 6 (Ringing)
> [2018-11-26 08:55:43] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 433
> [2018-11-26 08:55:43] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 433
> [2018-11-26 08:55:43] VERBOSE[15642] dial.c: PJSIP/test-voip-00000002 is ringing
> [2018-11-26 08:55:43] VERBOSE[15642] dial.c: PJSIP/test-voip-00000002 is ringing
> [2018-11-26 08:55:43] DEBUG[15519] app_queue.c: Device 'PJSIP/test-voip' changed to state '6' (Ringing) but we don't care because they're not a metester of any queue.
> [2018-11-26 08:55:43] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 509
> [2018-11-26 08:55:43] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 509
> [2018-11-26 08:55:43] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 509
> [2018-11-26 08:55:43] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 509
> [2018-11-26 08:55:44] DEBUG[15472] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:44] DEBUG[15472] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000032 to use for Request msg OPTIONS/cseq=10 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:44] DEBUG[15473] netsock2.c: Splitting '10.132.0.21' into...
> [2018-11-26 08:55:44] DEBUG[15473] netsock2.c: ...host '10.132.0.21' and port ''.
> [2018-11-26 08:55:44] DEBUG[15473] res_pjsip_endpoint_identifier_ip.c: Source address 10.132.0.21:5060 matches identify 'test-voip-1'
> [2018-11-26 08:55:44] DEBUG[15473] res_pjsip_endpoint_identifier_ip.c: Identify 'test-voip-1' SIP message matched to endpoint test-voip
> [2018-11-26 08:55:44] DEBUG[15473] netsock2.c: Splitting '10.132.0.21' into...
> [2018-11-26 08:55:44] DEBUG[15473] netsock2.c: ...host '10.132.0.21' and port ''.
> [2018-11-26 08:55:44] DEBUG[15472] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:44] DEBUG[15472] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000001c to use for Request msg OPTIONS/cseq=10 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:44] DEBUG[15473] netsock2.c: Splitting '10.132.0.21' into...
> [2018-11-26 08:55:44] DEBUG[15473] netsock2.c: ...host '10.132.0.21' and port ''.
> [2018-11-26 08:55:44] DEBUG[15473] res_pjsip_endpoint_identifier_ip.c: Source address 10.132.0.21:5060 matches identify 'test-voip-1'
> [2018-11-26 08:55:44] DEBUG[15473] res_pjsip_endpoint_identifier_ip.c: Identify 'test-voip-1' SIP message matched to endpoint test-voip
> [2018-11-26 08:55:44] DEBUG[15473] netsock2.c: Splitting '10.132.0.21' into...
> [2018-11-26 08:55:44] DEBUG[15473] netsock2.c: ...host '10.132.0.21' and port ''.
> [2018-11-26 08:55:47] DEBUG[15642] res_rtp_asterisk.c: Got RTCP report of 28 bytes from 10.132.15.220:36781
> [2018-11-26 08:55:47] VERBOSE[15642] res_rtp_asterisk.c: 0x7fe11400cd80 -- Strict RTP learning complete - Locking on source address 10.132.15.220:36780
> [2018-11-26 08:55:47] DEBUG[15472] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe11402c8c8 for Response msg 200/INVITE/cseq=4227 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:47] DEBUG[15472] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/test-voip-0000005f associated with dialog dlg0x7fe11402c8c8
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: There is no transaction involved in this state change
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The current inv state is CONNECTING
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: Source of transaction state change is RX_MSG
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: Response is 200 OK
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.132.0.21'
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip/pjsip_resolver.c: Transport type for target '10.132.0.21' is 'UDP'
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip/pjsip_resolver.c: Target '10.132.0.21' is an IP address, skipping resolution
> [2018-11-26 08:55:47] DEBUG[15459] devicestate.c: No provider found, checking channel drivers for PJSIP - test-voip
> [2018-11-26 08:55:47] DEBUG[15459] devicestate.c: Changing state for PJSIP/test-voip - state 2 (In use)
> [2018-11-26 08:55:47] VERBOSE[15642] dial.c: PJSIP/test-voip-00000002 answered
> [2018-11-26 08:55:47] DEBUG[15473] netsock2.c: Splitting '10.132.0.21' into...
> [2018-11-26 08:55:47] DEBUG[15473] netsock2.c: ...host '10.132.0.21' and port ''.
> [2018-11-26 08:55:47] VERBOSE[15642] ari/resource_channels.c: Launching Stasis(test_voip,test_DIALED=1) on PJSIP/test-voip-00000002
> [2018-11-26 08:55:47] DEBUG[15642] stasis/app.c: Channel 'testout-699786.201829' is 2 interested in test_voip
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe11400aef8)
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: There is no transaction involved in this state change
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The current inv state is CONFIRMED
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The inv session does NOT have an invite_tsx
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fe11400aef8
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The current transaction state is Terminated
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The transaction state change event is RX_MSG
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: The current inv state is CONFIRMED
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: Received response
> [2018-11-26 08:55:47] DEBUG[15473] res_pjsip_session.c: Response is 200 OK
> [2018-11-26 08:55:47] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 428
> [2018-11-26 08:55:47] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 428
> [2018-11-26 08:55:47] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 503
> [2018-11-26 08:55:47] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 503
> [2018-11-26 08:55:47] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 460
> [2018-11-26 08:55:47] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 460
> [2018-11-26 08:55:47] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 444
> [2018-11-26 08:55:47] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 444
> [2018-11-26 08:55:47] DEBUG[15519] app_queue.c: Device 'PJSIP/test-voip' changed to state '2' (In use) but we don't care because they're not a metester of any queue.
> [2018-11-26 08:55:47] DEBUG[15641] http.c: HTTP Request URI is /ari/channels/testout-699786.201829/play/14011c25-35e9-4734-b574-065dd4d9f62c:6b6cefc6-dc51-4cbf-b4c0-d878a58d7931
> [2018-11-26 08:55:47] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/play/14011c25-35e9-4734-b574-065dd4d9f62c:6b6cefc6-dc51-4cbf-b4c0-d878a58d7931] with handler [httpstatus] len 10
> [2018-11-26 08:55:47] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/play/14011c25-35e9-4734-b574-065dd4d9f62c:6b6cefc6-dc51-4cbf-b4c0-d878a58d7931] with handler [phoneprov] len 9
> [2018-11-26 08:55:47] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/play/14011c25-35e9-4734-b574-065dd4d9f62c:6b6cefc6-dc51-4cbf-b4c0-d878a58d7931] with handler [static] len 6
> [2018-11-26 08:55:47] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/play/14011c25-35e9-4734-b574-065dd4d9f62c:6b6cefc6-dc51-4cbf-b4c0-d878a58d7931] with handler [ari] len 3
> [2018-11-26 08:55:47] DEBUG[15641] http.c: Match made with [ari]
> [2018-11-26 08:55:47] DEBUG[15641] http.c: HTTP consuming request body
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Finding handler for channels
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking asterisk
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking endpoints
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking recordings
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking events
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking applications
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking sounds
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking deviceStates
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking bridges
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking playbacks
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking channels
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Finding handler for testout-699786.201829
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking create
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking channelId
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Finding handler for play
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking continue
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking redirect
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking answer
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking ring
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking dtmf
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking mute
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking hold
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking moh
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking silence
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking play
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Finding handler for 14011c25-35e9-4734-b574-065dd4d9f62c:6b6cefc6-dc51-4cbf-b4c0-d878a58d7931
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Checking playbackId
> [2018-11-26 08:55:47] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:47] DEBUG[15641] res_stasis_playback.c: testout-699786.201829: Sending play(sound:https://pocket-staging.messagebird.io/1/tts/f60a542334f68a0f33e2cb979b2990372772c2fc66b51ecb48e6ef33e38af9b4ec674e5d59b610960d92de0d966446cf1017e021edae559caff418af6a52e618.wav) command
> [2018-11-26 08:55:47] DEBUG[15641] http.c: HTTP keeping session open. status_code:201
> [2018-11-26 08:55:48] DEBUG[15642] sorcery.c: After calling wizard 'bucket_file', object 'https://pocket-staging.messagebird.io/1/tts/f60a542334f68a0f33e2cb979b2990372772c2fc66b51ecb48e6ef33e38af9b4ec674e5d59b610960d92de0d966446cf1017e021edae559caff418af6a52e618.wav' is stale
> [2018-11-26 08:55:48] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 452
> [2018-11-26 08:55:48] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 452
> [2018-11-26 08:55:48] DEBUG[15642] media_cache.c: Returning media at local file: /tmp/bucket-pBps9u
> [2018-11-26 08:55:48] DEBUG[15642] channel.c: Channel PJSIP/test-voip-00000002 setting write format path: slin -> alaw
> [2018-11-26 08:55:48] DEBUG[15642] res_rtp_asterisk.c: Ooh, format changed from none to alaw
> [2018-11-26 08:55:48] DEBUG[15642] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
> [2018-11-26 08:55:48] VERBOSE[15642] file.c: <PJSIP/test-voip-00000002> Playing 'https://pocket-staging.messagebird.io/1/tts/f60a542334f68a0f33e2cb979b2990372772c2fc66b51ecb48e6ef33e38af9b4ec674e5d59b610960d92de0d966446cf1017e021edae559caff418af6a52e618.wav.slin' (language 'en')
> [2018-11-26 08:55:49] DEBUG[15642] channel.c: Scheduling timer at (151 requested / 151 actual) timer ticks per second
> [2018-11-26 08:55:49] DEBUG[15642] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
> [2018-11-26 08:55:49] DEBUG[15642] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
> [2018-11-26 08:55:49] DEBUG[15642] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
> [2018-11-26 08:55:49] DEBUG[15642] channel.c: Channel PJSIP/test-voip-00000002 setting write format path: ulaw -> alaw
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 450
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 450
> [2018-11-26 08:55:49] DEBUG[15641] http.c: HTTP Request URI is /ari/channels/testout-699786.201829/variable
> [2018-11-26 08:55:49] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/variable] with handler [httpstatus] len 10
> [2018-11-26 08:55:49] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/variable] with handler [phoneprov] len 9
> [2018-11-26 08:55:49] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/variable] with handler [static] len 6
> [2018-11-26 08:55:49] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/variable] with handler [ari] len 3
> [2018-11-26 08:55:49] DEBUG[15641] http.c: Match made with [ari]
> [2018-11-26 08:55:49] DEBUG[15641] http.c: HTTP consuming request body
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Finding handler for channels
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking asterisk
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking endpoints
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking recordings
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking events
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking applications
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking sounds
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking deviceStates
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking bridges
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking playbacks
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking channels
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Finding handler for testout-699786.201829
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking create
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking channelId
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Finding handler for variable
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking continue
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking redirect
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking answer
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking ring
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking dtmf
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking mute
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking hold
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking moh
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking silence
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking play
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking record
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking variable
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:49] DEBUG[15641] http.c: HTTP keeping session open. status_code:204
> [2018-11-26 08:55:49] DEBUG[15641] http.c: HTTP Request URI is /ari/channels/testout-699786.201829/continue
> [2018-11-26 08:55:49] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/continue] with handler [httpstatus] len 10
> [2018-11-26 08:55:49] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/continue] with handler [phoneprov] len 9
> [2018-11-26 08:55:49] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/continue] with handler [static] len 6
> [2018-11-26 08:55:49] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/continue] with handler [ari] len 3
> [2018-11-26 08:55:49] DEBUG[15641] http.c: Match made with [ari]
> [2018-11-26 08:55:49] DEBUG[15641] http.c: HTTP consuming request body
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Finding handler for channels
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking asterisk
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking endpoints
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking recordings
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking events
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking applications
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking sounds
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking deviceStates
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking bridges
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking playbacks
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking channels
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Finding handler for testout-699786.201829
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking create
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking channelId
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Finding handler for continue
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Checking continue
> [2018-11-26 08:55:49] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:49] DEBUG[15641] http.c: HTTP keeping session open. status_code:204
> [2018-11-26 08:55:49] DEBUG[15642] stasis/app.c: channel 'testout-699786.201829': is 1 interested in test_voip
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 558
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 558
> [2018-11-26 08:55:49] DEBUG[15642][C-00000003] pbx.c: Launching 'Verbose'
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 423
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 423
> [2018-11-26 08:55:49] VERBOSE[15642][C-00000003] pbx.c: Executing [s at mp3playback:1] Verbose("PJSIP/test-voip-00000002", "Playing mp3 file.") in new stack
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 494
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 494
> [2018-11-26 08:55:49] VERBOSE[15642][C-00000003] app_verbose.c: Playing mp3 file.
> [2018-11-26 08:55:49] DEBUG[15642][C-00000003] pbx.c: Launching 'Set'
> [2018-11-26 08:55:49] VERBOSE[15642][C-00000003] pbx.c: Executing [s at mp3playback:2] Set("PJSIP/test-voip-00000002", "CHANNEL(hangup_handler_push)=mp3hangup,s,1") in new stack
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 515
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 515
> [2018-11-26 08:55:49] DEBUG[15642][C-00000003] app_stack.c: Gosub args:mp3hangup,s,1 new_args:mp3hangup,s,1
> [2018-11-26 08:55:49] DEBUG[15642][C-00000003] pbx_variables.c: Result of 'MP3FILE' is 'https://serv.polyfloyd.net/files/Music/Whatever/Rick%20Astley%20-%20Never%20Gonna%20Give%20You%20Up.mp3'
> [2018-11-26 08:55:49] DEBUG[15642][C-00000003] pbx.c: Launching 'MP3Player'
> [2018-11-26 08:55:49] VERBOSE[15642][C-00000003] pbx.c: Executing [s at mp3playback:3] MP3Player("PJSIP/test-voip-00000002", "https://serv.polyfloyd.net/files/Music/Whatever/Rick%20Astley%20-%20Never%20Gonna%20Give%20You%20Up.mp3") in new stack
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 582
> [2018-11-26 08:55:49] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 582
> [2018-11-26 08:55:49] DEBUG[15642][C-00000003] channel.c: Channel PJSIP/test-voip-00000002 setting write format path: slin -> alaw
> [2018-11-26 08:55:50] DEBUG[15642][C-00000003] res_rtp_asterisk.c: Difference is 9920, ms is 1260
> [2018-11-26 08:55:51] DEBUG[15642][C-00000003] res_rtp_asterisk.c: Got RTCP report of 52 bytes from 10.132.15.220:36781
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] res_rtp_asterisk.c: Got RTCP report of 8 bytes from 10.132.15.220:36781
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] res_rtp_asterisk.c: 0x7fe11400cd80 -- RTCP from 10.132.15.220:36781: Failed first packet validity check
> [2018-11-26 08:55:55] DEBUG[15472] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe11402c8c8 for Request msg BYE/cseq=74904 (rdata0x7fe0e4000bd8)
> [2018-11-26 08:55:55] DEBUG[15472] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/test-voip-0000005f associated with dialog dlg0x7fe11402c8c8
> [2018-11-26 08:55:55] DEBUG[15473] netsock2.c: Splitting '10.132.0.21' into...
> [2018-11-26 08:55:55] DEBUG[15473] netsock2.c: ...host '10.132.0.21' and port ''.
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The inv session does NOT have an invite_tsx
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fe11400aef8
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The current transaction state is Completed
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The transaction state change event is TX_MSG
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The current inv state is CONFIRMED
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The inv session does NOT have an invite_tsx
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: There is no transaction involved in this state change
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The current inv state is DISCONNCTD
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: Source of transaction state change is RX_MSG
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: Received request
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: Method is BYE
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The state change pertains to the endpoint 'test-voip(PJSIP/test-voip-00000002)'
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The inv session does NOT have an invite_tsx
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fe11400aef8
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The current transaction state is Completed
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The transaction state change event is RX_MSG
> [2018-11-26 08:55:55] DEBUG[15473] res_pjsip_session.c: The current inv state is DISCONNCTD
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 445
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 445
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] app_mp3.c: Null frame == hangup() detected
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] pbx.c: Spawn extension (mp3playback,s,3) exited non-zero on 'PJSIP/test-voip-00000002'
> [2018-11-26 08:55:55] VERBOSE[15642][C-00000003] pbx.c: Spawn extension (mp3playback, s, 3) exited non-zero on 'PJSIP/test-voip-00000002'
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 471
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 471
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] channel.c: Channel 0x7fe0e80048b0 'PJSIP/test-voip-00000002' hanging up. Refs: 2
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] channel.c: Soft-Hanging (0x80) up channel 'PJSIP/test-voip-00000002'
> [2018-11-26 08:55:55] VERBOSE[15642][C-00000003] app_stack.c: PJSIP/test-voip-00000002 Internal Gosub(mp3hangup,s,1) start
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] app_stack.c: PJSIP/test-voip-00000002 Original location: mp3playback,s,3
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] app_stack.c: Channel PJSIP/test-voip-00000002 has no datastore, so we're allocating one.
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 464
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 464
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] app_stack.c: Gosub exited with status 0
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] pbx.c: Launching 'Verbose'
> [2018-11-26 08:55:55] VERBOSE[15642][C-00000003] pbx.c: Executing [s at mp3hangup:1] Verbose("PJSIP/test-voip-00000002", "Hangup during mp3 file.") in new stack
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 498
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 498
> [2018-11-26 08:55:55] DEBUG[15467] cdr.c: Finalized CDR for PJSIP/test-voip-00000002 - start 1543222549.390612 answer 1543222547.714460 end 1543222555.811492 dispo ANSWERED
> [2018-11-26 08:55:55] VERBOSE[15642][C-00000003] app_verbose.c: Hangup during mp3 file.
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] pbx.c: Launching 'Stasis'
> [2018-11-26 08:55:55] VERBOSE[15642][C-00000003] pbx.c: Executing [s at mp3hangup:2] Stasis("PJSIP/test-voip-00000002", "test_voip,test_FROMMP3=1") in new stack
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 494
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 494
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 462
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 462
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] stasis/app.c: Channel 'testout-699786.201829' is 2 interested in test_voip
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 447
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 447
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] stasis/app.c: channel 'testout-699786.201829': is 1 interested in test_voip
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 421
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 421
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 469
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 469
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] pbx.c: Launching 'Return'
> [2018-11-26 08:55:55] VERBOSE[15642][C-00000003] pbx.c: Executing [s at mp3hangup:3] Return("PJSIP/test-voip-00000002", "") in new stack
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 474
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 474
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 454
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 454
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 462
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 462
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] app_stack.c: Spawn extension (mp3playback,s,3) exited with -1 on 'PJSIP/test-voip-00000002'
> [2018-11-26 08:55:55] VERBOSE[15642][C-00000003] app_stack.c: Spawn extension (mp3playback, s, 3) exited non-zero on 'PJSIP/test-voip-00000002'
> [2018-11-26 08:55:55] VERBOSE[15642][C-00000003] app_stack.c: PJSIP/test-voip-00000002 Internal Gosub(mp3hangup,s,1) complete GOSUB_RETVAL=
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] app_stack.c: PJSIP/test-voip-00000002 Ending location: mp3playback,s,3
> [2018-11-26 08:55:55] DEBUG[15642][C-00000003] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
> [2018-11-26 08:55:55] DEBUG[15473] rtp_engine.c: Destroyed RTP instance '0x7fe11400a780'
> [2018-11-26 08:55:55] DEBUG[15473] channel.c: Channel 0x7fe0e80048b0 'PJSIP/test-voip-00000002' destroying
> [2018-11-26 08:55:55] DEBUG[15448] threadpool.c: Increasing threadpool stasis-core's size by 1
> [2018-11-26 08:55:55] DEBUG[15459] devicestate.c: No provider found, checking channel drivers for PJSIP - test-voip
> [2018-11-26 08:55:55] DEBUG[15459] devicestate.c: Changing state for PJSIP/test-voip - state 5 (Unavailable)
> [2018-11-26 08:55:55] DEBUG[15519] app_queue.c: Device 'PJSIP/test-voip' changed to state '5' (Unavailable) but we don't care because they're not a metester of any queue.
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(leg_id)})' (from 'CSV_QUOTE(${CDR(leg_id)})},${CSV_QUOTE(${CDR(clid)})},${CSV_QUOTE(${CDR(src)})},${CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 25)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(leg_id)' (from 'CDR(leg_id)})' len 11)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(leg_id) result is ''
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE() result is '""'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(clid)})' (from 'CSV_QUOTE(${CDR(clid)})},${CSV_QUOTE(${CDR(src)})},${CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 23)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(clid)' (from 'CDR(clid)})' len 9)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(clid) result is '"" <1337>'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE("" <1337>) result is '""""" <1337>"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(src)})' (from 'CSV_QUOTE(${CDR(src)})},${CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 22)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(src)' (from 'CDR(src)})' len 8)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(src) result is '1337'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(1337) result is '"1337"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(dst)})' (from 'CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 22)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(dst)' (from 'CDR(dst)})' len 8)
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 493
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 493
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(dst) result is 's'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(s) result is '"s"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(dcontext)})' (from 'CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 27)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(dcontext)' (from 'CDR(dcontext)})' len 13)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(dcontext) result is 'mp3playback'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(mp3playback) result is '"mp3playback"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(channel)})' (from 'CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 26)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(channel)' (from 'CDR(channel)})' len 12)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(channel) result is 'PJSIP/test-voip-00000002'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(PJSIP/test-voip-00000002) result is '"PJSIP/test-voip-00000002"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(dstchannel)})' (from 'CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 29)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(dstchannel)' (from 'CDR(dstchannel)})' len 15)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(dstchannel) result is ''
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE() result is '""'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(lastapp)})' (from 'CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 26)
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket string of length 471
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(lastapp)' (from 'CDR(lastapp)})' len 12)
> [2018-11-26 08:55:55] DEBUG[15525] res_http_websocket.c: Writing websocket text frame, length 471
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(lastapp) result is 'MP3Player'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(MP3Player) result is '"MP3Player"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(lastdata)})' (from 'CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 27)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(lastdata)' (from 'CDR(lastdata)})' len 13)
> [2018-11-26 08:55:55] DEBUG[15525] stasis/app.c: channel 'testout-699786.201829': is 0 interested in test_voip
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(lastdata) result is 'https://serv.polyfloyd.net/files/Music/Whatever/Rick%20Astley%20-%20Never%20Gon'
> [2018-11-26 08:55:55] DEBUG[15525] stasis/app.c: channel 'testout-699786.201829' unsubscribed from test_voip
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(https://serv.polyfloyd.net/files/Music/Whatever/Rick%20Astley%20-%20Never%20Gon) result is '"https://serv.polyfloyd.net/files/Music/Whatever/Rick%20Astley%20-%20Never%20Gon"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(start)})' (from 'CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 24)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(start)' (from 'CDR(start)})' len 10)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(start) result is '2018-11-26 08:55:49'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(2018-11-26 08:55:49) result is '"2018-11-26 08:55:49"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(answer)})' (from 'CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 25)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(answer)' (from 'CDR(answer)})' len 11)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(answer) result is '2018-11-26 08:55:47'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(2018-11-26 08:55:47) result is '"2018-11-26 08:55:47"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(end)})' (from 'CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 22)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(end)' (from 'CDR(end)})' len 8)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(end) result is '2018-11-26 08:55:55'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(2018-11-26 08:55:55) result is '"2018-11-26 08:55:55"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(duration)})' (from 'CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 27)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(duration)' (from 'CDR(duration)})' len 13)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(duration) result is '6'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(6) result is '"6"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(billsec)})' (from 'CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 26)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(billsec)' (from 'CDR(billsec)})' len 12)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(billsec) result is '8'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(8) result is '"8"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(disposition)})' (from 'CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 30)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(disposition)' (from 'CDR(disposition)})' len 16)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(disposition) result is 'ANSWERED'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(ANSWERED) result is '"ANSWERED"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(amaflags)})' (from 'CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 27)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(amaflags)' (from 'CDR(amaflags)})' len 13)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(amaflags) result is 'DOCUMENTATION'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(DOCUMENTATION) result is '"DOCUMENTATION"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(accountcode)})' (from 'CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 30)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)})' len 16)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(accountcode) result is ''
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE() result is '""'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(uniqueid)})' (from 'CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 27)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(uniqueid)' (from 'CDR(uniqueid)})' len 13)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(uniqueid) result is 'testout-699786.201829'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(testout-699786.201829) result is '"testout-699786.201829"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(userfield)})' (from 'CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 28)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(userfield)' (from 'CDR(userfield)})' len 14)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(userfield) result is ''
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE() result is '""'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(sequence)' (from 'CDR(sequence)},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 13)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(sequence) result is '2'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(duration,f)})' (from 'CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})}
> ' len 29)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(duration,f)' (from 'CDR(duration,f)})' len 15)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(duration,f) result is '6.420880'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(6.420880) result is '"6.420880"'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(billsec,f)})' (from 'CSV_QUOTE(${CDR(billsec,f)})}
> ' len 28)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Evaluating 'CDR(billsec,f)' (from 'CDR(billsec,f)})' len 14)
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CDR(billsec,f) result is '8.097032'
> [2018-11-26 08:55:55] DEBUG[15467] pbx_variables.c: Function CSV_QUOTE(8.097032) result is '"8.097032"'
> [2018-11-26 08:55:55] DEBUG[15641] http.c: HTTP Request URI is /ari/channels/testout-699786.201829/play/14011c25-35e9-4734-b574-065dd4d9f62c:37243ec8-991a-4480-9bf0-064e57616403
> [2018-11-26 08:55:55] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/play/14011c25-35e9-4734-b574-065dd4d9f62c:37243ec8-991a-4480-9bf0-064e57616403] with handler [httpstatus] len 10
> [2018-11-26 08:55:55] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/play/14011c25-35e9-4734-b574-065dd4d9f62c:37243ec8-991a-4480-9bf0-064e57616403] with handler [phoneprov] len 9
> [2018-11-26 08:55:55] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/play/14011c25-35e9-4734-b574-065dd4d9f62c:37243ec8-991a-4480-9bf0-064e57616403] with handler [static] len 6
> [2018-11-26 08:55:55] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/play/14011c25-35e9-4734-b574-065dd4d9f62c:37243ec8-991a-4480-9bf0-064e57616403] with handler [ari] len 3
> [2018-11-26 08:55:55] DEBUG[15641] http.c: Match made with [ari]
> [2018-11-26 08:55:55] DEBUG[15641] http.c: HTTP consuming request body
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Finding handler for channels
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking asterisk
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking endpoints
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking recordings
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking events
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking applications
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking sounds
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking deviceStates
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking bridges
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking playbacks
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking channels
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Finding handler for testout-699786.201829
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking create
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking channelId
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Finding handler for play
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking continue
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking redirect
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking answer
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking ring
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking dtmf
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking mute
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking hold
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking moh
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking silence
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking play
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Finding handler for 14011c25-35e9-4734-b574-065dd4d9f62c:37243ec8-991a-4480-9bf0-064e57616403
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking playbackId
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:55] DEBUG[15641] http.c: HTTP keeping session open. status_code:404
> [2018-11-26 08:55:55] DEBUG[15641] http.c: HTTP Request URI is /ari/channels/testout-699786.201829/variable
> [2018-11-26 08:55:55] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/variable] with handler [httpstatus] len 10
> [2018-11-26 08:55:55] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/variable] with handler [phoneprov] len 9
> [2018-11-26 08:55:55] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/variable] with handler [static] len 6
> [2018-11-26 08:55:55] DEBUG[15641] http.c: match request [ari/channels/testout-699786.201829/variable] with handler [ari] len 3
> [2018-11-26 08:55:55] DEBUG[15641] http.c: Match made with [ari]
> [2018-11-26 08:55:55] DEBUG[15641] http.c: HTTP consuming request body
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Finding handler for channels
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking asterisk
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking endpoints
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking recordings
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking events
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking applications
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking sounds
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking deviceStates
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking bridges
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking playbacks
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking channels
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Finding handler for testout-699786.201829
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking create
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking channelId
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Finding handler for variable
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking continue
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking redirect
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking answer
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking ring
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking dtmf
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking mute
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking hold
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking moh
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking silence
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking play
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking record
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Checking variable
> [2018-11-26 08:55:55] DEBUG[15641] res_ari.c: Got it!
> [2018-11-26 08:55:55] DEBUG[15641] http.c: HTTP keeping session open. status_code:404
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list