[asterisk-bugs] [JIRA] (ASTERISK-28181) ari: Originating overwrites channel start time
Friendly Automation (JIRA)
noreply at issues.asterisk.org
Wed Feb 6 07:13:47 CST 2019
[ https://issues.asterisk.org/jira/browse/ASTERISK-28181?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Friendly Automation closed ASTERISK-28181.
------------------------------------------
Resolution: Fixed
> 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