[asterisk-bugs] [JIRA] (ASTERISK-28181) ari: Originating overwrites channel start time
Joshua C. Colp (JIRA)
noreply at issues.asterisk.org
Wed Nov 28 07:31:47 CST 2018
[ https://issues.asterisk.org/jira/browse/ASTERISK-28181?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Joshua C. Colp updated ASTERISK-28181:
--------------------------------------
Assignee: sungtae kim (was: Unassigned)
Status: Waiting for Feedback (was: Triage)
As previously requested - please provide an ARI application that demonstrates the problem with the accompanying configuration. If we have to piece together things then the variables can change, and the result may not be the same thus wasting time.
> 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: cli.log, extensions.conf, full.log
>
>
> 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