ASTERISK-28181: ari: Originating overwrites channel start time

[Home]

Summary: ASTERISK-28181: ari: Originating overwrites channel start time

Reporter: sungtae kim (pchero) Labels: pjsip

Date Opened: 2018-11-26 03:10:38.000-0600 Date Closed: 2019-02-06 07:13:46.000-0600

Priority: Major Regression?

Status: Closed/Complete Components: Resources/res_ari_channels

Versions: 15.6.1 16.0.0 Frequency of
Occurrence

Related
Issues:
is related to ASTERISK-28152 mysql two record

Environment: debian-9 Attachments: ( 0) ari_test.sh
( 1) cli.log
( 2) extensions.conf
( 3) full.log
( 4) pjsip.conf

Description: 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@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@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@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@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@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@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@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}

Comments: By: Asterisk Team (asteriskteam) 2018-11-26 03:10:41.762-0600

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Joshua C. Colp (jcolp) 2018-11-26 07:18:09.650-0600

Please attach logs and such in the future. As well please provide an example ARI application, dialplan, and configuration which shows this problem. Does it also occur in earlier versions?
By: sungtae kim (pchero) 2018-11-26 08:06:04.732-0600

I've tested only Asterisk-15.5.0 and Asterisk-master version. Couldn't test it with earlier versions.
By: sungtae kim (pchero) 2018-11-26 08:17:25.264-0600

Tested again. I think the `continue` ARI operation rewrites the channel's start time.

Problem case
{noformat}
[2018-11-26 13:41:36] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325
[2018-11-26 13:41:46] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325/play/a33bbb49-80fa-423f-9657-62c8320229a4:6d2b0466-ae5b-4c97-a7ea-0e3e23e46e13
[2018-11-26 13:41:47] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325/variable
[2018-11-26 13:41:47] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325/continue
[2018-11-26 13:41:55] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325/play/a33bbb49-80fa-423f-9657-62c8320229a4:da10af4a-fbbe-4773-9c5e-431ae1bacee3
[2018-11-26 13:41:55] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325/variable
{noformat}

Normal case
{noformat}
[2018-11-26 14:14:30] DEBUG[18752] http.c: HTTP Request URI is /ari/channels/mbout-520339.531067
[2018-11-26 14:14:41] DEBUG[18752] http.c: HTTP Request URI is /ari/channels/mbout-520339.531067/play/c7693735-35ab-4b64-80ad-01f0a591a787:ba4926ca-932b-45cc-a791-9a4c57f6851d
[2018-11-26 14:14:48] DEBUG[18752] http.c: HTTP Request URI is /ari/channels/mbout-520339.531067/variable
[2018-11-26 14:14:48] DEBUG[18752] http.c: HTTP Request URI is /ari/channels/mbout-520339.531067/variable
{noformat}
By: Benjamin Keith Ford (bford) 2018-11-26 15:28:09.861-0600

As Josh mentioned, we'll need some configuration, dialplan, and an ARI application that produces the problem. As of right now, we don't have enough information to move forward with the issue.
By: sungtae kim (pchero) 2018-11-27 09:34:10.887-0600

Hi, I've uploaded extension.conf file. I've modified some of credential stuffs. But it doesn't affect to the call flows.

And here's ARI application flows. Our ARI application sent below commands.
{noformat}
[2018-11-26 13:41:36] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325
[2018-11-26 13:41:46] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325/play/a33bbb49-80fa-423f-9657-62c8320229a4:6d2b0466-ae5b-4c97-a7ea-0e3e23e46e13
[2018-11-26 13:41:47] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325/variable
[2018-11-26 13:41:47] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325/continue
[2018-11-26 13:41:55] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325/play/a33bbb49-80fa-423f-9657-62c8320229a4:da10af4a-fbbe-4773-9c5e-431ae1bacee3
[2018-11-26 13:41:55] DEBUG[18272] http.c: HTTP Request URI is /ari/channels/testout-777672.221325/variable
{noformat}
By: Joshua C. Colp (jcolp) 2018-11-28 07:29:48.121-0600

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.
By: sungtae kim (pchero) 2018-12-03 06:46:09.363-0600

Hi Joshua,

Sorry to late reply. Here's some test application. I'm not sure this is what you said it. So please comment it if this is not.. :)

extensions.conf - Simple dialplan to reproduce the bug.
pjsip.conf - simple pjsip configuration
ari_test - shell script to reproduce the bug.
- It assume that there's ARI application already exist. name: test
- ws://127.0.0.1:8088/ari/events?api_key=asterisk:asterisk&app=test
- It uses sipp for dummy UAS, and curl command to send an ARI request.
By: sungtae kim (pchero) 2018-12-03 17:08:14.728-0600

Hi, If you don't mind it, I would like to take a this ticket. :)

May I know where should I look?
I was trying to find where the start time set, but couldn't find it yet.
By: Joshua C. Colp (jcolp) 2018-12-03 17:30:40.123-0600

All CDR logic is contained in main/cdr.c
By: sungtae kim (pchero) 2019-01-16 17:11:42.838-0600

Dev note.

{noformat}
[Jan 17 00:08:33] DEBUG[108609] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7f0fa4011708)
[Jan 17 00:08:33] DEBUG[108609] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000034 to use for Request msg INVITE/cseq=1 (rdata0x7f0fa4011708)
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '127.0.0.1' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '127.0.0.1' and port ''.
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_endpoint_identifier_ip.c: Source address 127.0.0.1:5061 matches identify 'sipp-uac'
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_endpoint_identifier_ip.c: Identify 'sipp-uac' SIP message matched to endpoint sipp-uac
[Jan 17 00:08:33] DEBUG[108610] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000034 to use for Request msg INVITE/cseq=1 (rdata0x7f0fa4008a58)
[Jan 17 00:08:33] VERBOSE[108610] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '127.0.0.1'
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac()'
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f0fa401ac68)
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The current inv state is INCOMING
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac()'
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f0fa401ac68)
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The current transaction state is Proceeding
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: The current inv state is INCOMING
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '127.0.0.1' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '127.0.0.1' and port ''.
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:33] DEBUG[108610] res_rtp_asterisk.c: Allocated port 19058 for RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:33] DEBUG[108610] res_rtp_asterisk.c: Creating ICE session [::]:19058 (19058) for RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting 'fe80::20c:29ff:fe4b:95b1' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host 'fe80::20c:29ff:fe4b:95b1' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting 'fe80::20c:29ff:fe4b:95b1' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host 'fe80::20c:29ff:fe4b:95b1' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting 'fe80::20c:29ff:fe4b:95bb' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host 'fe80::20c:29ff:fe4b:95bb' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting 'fe80::20c:29ff:fe4b:95bb' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host 'fe80::20c:29ff:fe4b:95bb' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '172.16.78.131' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '172.16.78.131' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '172.16.78.131' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '172.16.78.131' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '192.168.30.10' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '192.168.30.10' and port ''.
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting '192.168.30.10' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host '192.168.30.10' and port ''.
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: RTP instance '0x7f0fa4039fd0' is setup and ready to go
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: Splitting 'debian' into...
[Jan 17 00:08:33] DEBUG[108610] netsock2.c: ...host 'debian' and port ''.
[Jan 17 00:08:33] DEBUG[108610] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f0fafc9a440
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7f0fa4041cd8) from 0x7f0fafc9a440 to 0x7f0fafc9a440
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: Copying rx payload mapping 0 (0x7f0fa4041cd8) from 0x7f0fafc9a440 to 0x7f0fa403a1a8
[Jan 17 00:08:33] DEBUG[108610] rtp_engine.c: Copying tx payload mapping 0 (0x7f0fa4041cd8) from 0x7f0fafc9a440 to 0x7f0fa403a1a8
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Media stream 'audio' handled by audio
[Jan 17 00:08:33] DEBUG[108610] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:33] DEBUG[108610] res_pjsip_session.c: Method is INVITE
[Jan 17 00:08:33] DEBUG[108610] channel.c: Channel 0x7f0fa4031290 'PJSIP/sipp-uac-00000003' allocated
[Jan 17 00:08:33] DEBUG[108610] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/sipp-uac-00000003
[Jan 17 00:08:33] DEBUG[108666] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: none
Uniqueid: none
Variable: SIPDOMAIN
Value: 127.0.0.1

[Jan 17 00:08:33] DEBUG[108666] manager.c: Examining AMI event:
Event: Newchannel
Privilege: call,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 1
Uniqueid: 1547680113.3
Linkedid: 1547680113.3

[Jan 17 00:08:33] DEBUG[108674][C-00000004] pbx.c: Launching 'NoOp'
[Jan 17 00:08:33] VERBOSE[108674][C-00000004] pbx.c: Executing [agi_test@sipp-uac:1] NoOp("PJSIP/sipp-uac-00000003", "agi_test") in new stack
[Jan 17 00:08:33] DEBUG[108666] manager.c: Examining AMI event:
Event: Newexten
Privilege: dialplan,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 1
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Extension: agi_test
Application: NoOp
AppData: agi_test

[Jan 17 00:08:33] DEBUG[108674][C-00000004] pbx.c: Launching 'AGI'
[Jan 17 00:08:33] VERBOSE[108674][C-00000004] pbx.c: Executing [agi_test@sipp-uac:2] AGI("PJSIP/sipp-uac-00000003", "agi:async,agi_test") in new stack
[Jan 17 00:08:33] DEBUG[108666] manager.c: Examining AMI event:
Event: Newexten
Privilege: dialplan,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Extension: agi_test
Application: AGI
AppData: agi:async,agi_test

[Jan 17 00:08:33] DEBUG[108666] manager.c: Examining AMI event:
Event: AsyncAGIStart
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Env: agi_request%3A%20async%0Aagi_channel%3A%20PJSIP%2Fsipp-uac-00000003%0Aagi_language%3A%20en%0Aagi_type%3A%20PJSIP%0Aagi_uniqueid%3A%201547680113.3%0Aagi_version%3A%20GIT-master-d35873644c%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20agi_test%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20sipp-uac%0Aagi_extension%3A%20agi_test%0Aagi_priority%3A%202%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139704269924096%0Aagi_arg_1%3A%20agi_test%0A%0A

[Jan 17 00:08:44] DEBUG[108666] manager.c: Running action 'AGI'
[Jan 17 00:08:44] DEBUG[108589] devicestate.c: No provider found, checking channel drivers for PJSIP - sipp-uac
[Jan 17 00:08:44] DEBUG[108589] devicestate.c: Changing state for PJSIP/sipp-uac - state 2 (In use)
[Jan 17 00:08:44] DEBUG[108655] app_queue.c: Device 'PJSIP/sipp-uac' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Jan 17 00:08:44] DEBUG[108610] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:44] DEBUG[108610] netsock2.c: Splitting '127.0.0.1' into...
[Jan 17 00:08:44] DEBUG[108610] netsock2.c: ...host '127.0.0.1' and port ''.
[Jan 17 00:08:44] DEBUG[108610] acl.c: For destination '127.0.0.1', our source address is '127.0.0.1'.
[Jan 17 00:08:44] DEBUG[108610] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f0fa4039fd0'
[Jan 17 00:08:44] VERBOSE[108610] res_rtp_asterisk.c: 0x7f0fa403d630 -- Strict RTP learning after remote address set to: 127.0.0.1:6000
[Jan 17 00:08:44] DEBUG[108610] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f0fafc9a070
[Jan 17 00:08:44] DEBUG[108610] rtp_engine.c: Copying tx payload mapping 0 (0x7f0fa4000f18) from 0x7f0fafc9a070 to 0x7f0fa403a1a8
[Jan 17 00:08:44] DEBUG[108610] channel.c: Channel PJSIP/sipp-uac-00000003 setting read format path: ulaw -> ulaw
[Jan 17 00:08:44] DEBUG[108610] channel.c: Channel PJSIP/sipp-uac-00000003 setting write format path: ulaw -> ulaw
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Method is INVITE, Response is 200 OK
[Jan 17 00:08:44] DEBUG[108610] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 127.0.0.1:5060 (this may be re-written again later)
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac(PJSIP/sipp-uac-00000003)'
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f0fa401ac68)
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current inv state is CONNECTING
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac(PJSIP/sipp-uac-00000003)'
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f0fa401ac68)
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current transaction state is Completed
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current inv state is CONNECTING
[Jan 17 00:08:44] DEBUG[108666] manager.c: Examining AMI event:
Event: AGIExecStart
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
CommandId: 1501975288
Command: Answer

[Jan 17 00:08:44] DEBUG[108666] manager.c: Examining AMI event:
Event: Newstate
Privilege: call,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3

[Jan 17 00:08:44] DEBUG[108666] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: PJSIP/sipp-uac
State: INUSE

[Jan 17 00:08:44] DEBUG[108609] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f0fa4034428 for Request msg ACK/cseq=1 (rdata0x7f0fa4011708)
[Jan 17 00:08:44] DEBUG[108609] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000034 associated with dialog dlg0x7f0fa4034428
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac(PJSIP/sipp-uac-00000003)'
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current transaction state is Terminated
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The transaction state change event is USER
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current inv state is CONNECTING
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac(PJSIP/sipp-uac-00000003)'
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Received request
[Jan 17 00:08:44] DEBUG[108610] res_pjsip_session.c: Method is ACK
[Jan 17 00:08:44] DEBUG[108674][C-00000004] channel.c: Didn't receive a media frame from PJSIP/sipp-uac-00000003 within 500 ms of answering. Continuing anyway
[Jan 17 00:08:44] DEBUG[108666] manager.c: Examining AMI event:
Event: AGIExecEnd
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
CommandId: 1501975288
Command: Answer
ResultCode: 200
Result: Success

[Jan 17 00:08:44] DEBUG[108666] manager.c: Examining AMI event:
Event: AsyncAGIExec
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Result: 200%20result%3D0%0A

[Jan 17 00:08:45] DEBUG[108621] res_pjsip_registrar.c: Woke up at 1547680125 Interval: 30
[Jan 17 00:08:45] DEBUG[108621] res_pjsip_registrar.c: Expiring 0 contacts
[Jan 17 00:08:52] DEBUG[108666] manager.c: Running action 'AGI'
[Jan 17 00:08:53] DEBUG[108674][C-00000004] pbx.c: Launching 'Wait'
[Jan 17 00:08:53] VERBOSE[108674][C-00000004] pbx.c: Executing [agi_test@sipp-uac:3] Wait("PJSIP/sipp-uac-00000003", "10") in new stack
[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: AGIExecStart
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
CommandId: 1858247138
Command: asyncagi break

[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: AGIExecEnd
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
CommandId: 1858247138
Command: asyncagi break
ResultCode: 200
Result: Success

[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: AsyncAGIExec
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Result: 200%20result%3D0%0A

[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: AsyncAGIEnd
Privilege: agi,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3

[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 2
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Variable: AGISTATUS
Value: SUCCESS

[Jan 17 00:08:53] DEBUG[108666] manager.c: Examining AMI event:
Event: Newexten
Privilege: dialplan,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 3
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Extension: agi_test
Application: Wait
AppData: 10

[Jan 17 00:09:03] DEBUG[108674][C-00000004] pbx.c: Launching 'Hangup'
[Jan 17 00:09:03] VERBOSE[108674][C-00000004] pbx.c: Executing [agi_test@sipp-uac:4] Hangup("PJSIP/sipp-uac-00000003", "") in new stack
[Jan 17 00:09:03] DEBUG[108674][C-00000004] channel.c: Soft-Hanging (0x20) up channel 'PJSIP/sipp-uac-00000003'
[Jan 17 00:09:03] DEBUG[108674][C-00000004] pbx.c: Spawn extension (sipp-uac,agi_test,4) exited non-zero on 'PJSIP/sipp-uac-00000003'
[Jan 17 00:09:03] VERBOSE[108674][C-00000004] pbx.c: Spawn extension (sipp-uac, agi_test, 4) exited non-zero on 'PJSIP/sipp-uac-00000003'
[Jan 17 00:09:03] DEBUG[108674][C-00000004] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/sipp-uac-00000003'
[Jan 17 00:09:03] DEBUG[108674][C-00000004] channel.c: Channel 0x7f0fa4031290 'PJSIP/sipp-uac-00000003' hanging up. Refs: 2
[Jan 17 00:09:03] DEBUG[108674][C-00000004] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[Jan 17 00:09:03] DEBUG[108666] manager.c: Examining AMI event:
Event: Newexten
Privilege: dialplan,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 4
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Extension: agi_test
Application: Hangup
AppData:

[Jan 17 00:09:03] DEBUG[108666] manager.c: Examining AMI event:
Event: SoftHangupRequest
Privilege: call,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 4
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Cause: 16

[Jan 17 00:09:03] DEBUG[108610] rtp_engine.c: Destroyed RTP instance '0x7f0fa4039fd0'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Method is BYE
[Jan 17 00:09:03] DEBUG[108610] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '127.0.0.1'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip/pjsip_resolver.c: Transport type for target '127.0.0.1' is 'UDP'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip/pjsip_resolver.c: Target '127.0.0.1' is an IP address, skipping resolution
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac(PJSIP/sipp-uac-00000003)'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The current transaction state is Calling
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 17 00:09:03] DEBUG[108610] channel.c: Channel 0x7f0fa4031290 'PJSIP/sipp-uac-00000003' destroying
[Jan 17 00:09:03] DEBUG[108589] devicestate.c: No provider found, checking channel drivers for PJSIP - sipp-uac
[Jan 17 00:09:03] DEBUG[108589] devicestate.c: Changing state for PJSIP/sipp-uac - state 1 (Not in use)
[Jan 17 00:09:03] DEBUG[108655] app_queue.c: Device 'PJSIP/sipp-uac' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 17 00:09:03] DEBUG[108602] cdr.c: Finalized CDR for PJSIP/sipp-uac-00000003 - start 1547680113.060110 answer 1547680124.298005 end 1547680143.028024 dispo ANSWERED
[Jan 17 00:09:03] DEBUG[108666] manager.c: Examining AMI event:
Event: Hangup
Privilege: call,all
Channel: PJSIP/sipp-uac-00000003
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: sipp-uac
Exten: agi_test
Priority: 4
Uniqueid: 1547680113.3
Linkedid: 1547680113.3
Cause: 16
Cause-txt: Normal Clearing

[Jan 17 00:09:03] DEBUG[108666] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: PJSIP/sipp-uac
State: NOT_INUSE

[Jan 17 00:09:03] DEBUG[108609] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f0fa4034428 for Response msg 200/BYE/cseq=24124 (rdata0x7f0fa4011708)
[Jan 17 00:09:03] DEBUG[108609] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000034 associated with dialog dlg0x7f0fa4034428
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac()'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Received response
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Response is 200 OK
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac()'
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The current transaction state is Completed
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Received response
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: Response is 200 OK
[Jan 17 00:09:03] DEBUG[108610] res_pjsip_session.c: BYE received final response code 200
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The state change pertains to the endpoint 'sipp-uac()'
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f0fa401ac68
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The current transaction state is Terminated
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The transaction state change event is TIMER
[Jan 17 00:09:08] DEBUG[108609] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 17 00:09:08] DEBUG[108610] res_pjsip_session.c: Destroying SIP session with endpoint sipp-uac
[Jan 17 00:09:15] DEBUG[108621] res_pjsip_registrar.c: Woke up at 1547680155 Interval: 30
[Jan 17 00:09:15] DEBUG[108621] res_pjsip_registrar.c: Expiring 0 contacts
{noformat}
By: Kevin Harwell (kharwell) 2019-01-16 17:55:22.009-0600

I've linked ASTERISK-28152 because there the reporter had an issue with a new CDR being created upon re-entering the dialplan via an AGI call triggered through a queue call. That issue was closed because it was deemed "working as it should".

If the fix here makes it so only one CDR is created then the scenario on ASTERISK-28152 will need to be retested, and that issue updated.
By: Friendly Automation (friendly-automation) 2019-02-06 07:13:47.213-0600

Change 10964 merged by George Joseph:
main/cdr: Fixed cdr start overwriting

[https://gerrit.asterisk.org/10964|https://gerrit.asterisk.org/10964]
By: Friendly Automation (friendly-automation) 2019-02-06 07:13:57.168-0600

Change 10747 merged by George Joseph:
main/cdr: Fixed cdr start overwriting

[https://gerrit.asterisk.org/10747|https://gerrit.asterisk.org/10747]
By: Friendly Automation (friendly-automation) 2019-02-06 07:14:07.653-0600

Change 10963 merged by George Joseph:
main/cdr: Fixed cdr start overwriting

[https://gerrit.asterisk.org/10963|https://gerrit.asterisk.org/10963]