[Apr 18 09:39:23] Asterisk 15.3.0 built by root @ thierry-Satellite-L650 on a x86_64 running Linux on 2018-03-27 09:46:36 UTC
[Apr 18 09:39:23] DEBUG[2736] config.c: Parsing /etc/asterisk/logger.conf
[Apr 18 09:39:23] VERBOSE[2736] logger.c: Asterisk Queue Logger restarted
[Apr 18 09:39:50] DEBUG[2653] res_pjsip_registrar.c: Woke up at 1524037190  Interval: 30
[Apr 18 09:39:50] DEBUG[2653] res_pjsip_registrar.c: Expiring 0 contacts
[Apr 18 09:39:52] DEBUG[2637] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=227 (rdata0x7f75cc000af8)
[Apr 18 09:39:52] DEBUG[2637] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000028 to use for Request msg INVITE/cseq=227 (rdata0x7f75cc000af8)
[Apr 18 09:39:52] DEBUG[2635] threadpool.c: Increasing threadpool SIP's size by 5
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '127.0.0.1' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '127.0.0.1' and port ''.
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '6001' domain '127.0.0.1'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_endpoint_identifier_user.c: Identified by From username '6001' domain '127.0.0.1'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '6001'.
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '192.168.0.22' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '192.168.0.22' and port ''.
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '127.0.0.1' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '127.0.0.1' and port ''.
[Apr 18 09:39:52] DEBUG[2637] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg ACK/cseq=227 (rdata0x7f75cc000af8)
[Apr 18 09:39:52] DEBUG[2637] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000028 to use for Request msg ACK/cseq=227 (rdata0x7f75cc000af8)
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '127.0.0.1' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '127.0.0.1' and port ''.
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '6001' domain '127.0.0.1'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_endpoint_identifier_user.c: Identified by From username '6001' domain '127.0.0.1'
[Apr 18 09:39:52] DEBUG[2637] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=228 (rdata0x7f75cc000af8)
[Apr 18 09:39:52] DEBUG[2637] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000028 to use for Request msg INVITE/cseq=228 (rdata0x7f75cc000af8)
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '127.0.0.1' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '127.0.0.1' and port ''.
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '6001' domain '127.0.0.1'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_endpoint_identifier_user.c: Identified by From username '6001' domain '127.0.0.1'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '6001'.
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_authenticator_digest.c: Calculated nonce 1524037192/6561b674c204ba8167161bccbb24f522. Actual nonce is 1524037192/6561b674c204ba8167161bccbb24f522
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '192.168.0.22' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '192.168.0.22' and port ''.
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '127.0.0.1' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '127.0.0.1' and port ''.
[Apr 18 09:39:52] DEBUG[4778] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000028 to use for Request msg INVITE/cseq=228 (rdata0x7f75cc0097a8)
[Apr 18 09:39:52] VERBOSE[4778] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '127.0.0.1'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The state change pertains to the endpoint '6001()'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f75d8003998)
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: There is no transaction involved in this state change
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The current inv state is INCOMING
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The state change pertains to the endpoint '6001()'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f75d8003998)
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f75d8003998
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The current transaction state is Proceeding
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The transaction state change event is TX_MSG
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The current inv state is INCOMING
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '127.0.0.1' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '127.0.0.1' and port ''.
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f75dc00e9a8'
[Apr 18 09:39:52] DEBUG[4778] res_rtp_asterisk.c: Allocated port 16302 for RTP instance '0x7f75dc00e9a8'
[Apr 18 09:39:52] DEBUG[4778] res_rtp_asterisk.c: Creating ICE session [::]:16302 (16302) for RTP instance '0x7f75dc00e9a8'
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '2a01:e34:ec24:7100:fd91:7e48:b98c:d1b9' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '2a01:e34:ec24:7100:fd91:7e48:b98c:d1b9' and port ''.
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '2a01:e34:ec24:7100:fd91:7e48:b98c:d1b9' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '2a01:e34:ec24:7100:fd91:7e48:b98c:d1b9' and port ''.
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '2a01:e34:ec24:7100:9583:8f6c:cbb5:a60c' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '2a01:e34:ec24:7100:9583:8f6c:cbb5:a60c' and port ''.
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '2a01:e34:ec24:7100:9583:8f6c:cbb5:a60c' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '2a01:e34:ec24:7100:9583:8f6c:cbb5:a60c' and port ''.
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting 'fe80::6526:ccc8:6d79:8eee' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host 'fe80::6526:ccc8:6d79:8eee' and port ''.
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting 'fe80::6526:ccc8:6d79:8eee' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host 'fe80::6526:ccc8:6d79:8eee' and port ''.
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '192.168.0.22' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '192.168.0.22' and port ''.
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '192.168.0.22' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '192.168.0.22' and port ''.
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: RTP instance '0x7f75dc00e9a8' is setup and ready to go
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting 'thierry-Satellite-L650' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host 'thierry-Satellite-L650' and port ''.
[Apr 18 09:39:52] DEBUG[4778] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f75dc00e9a8'
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 98 based on m type on 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 97 based on m type on 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 3 based on m type on 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7f75dc0126c0) from 0x7f758b1e1440 to 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Crossover copying tx to rx payload mapping 3 (0x7f75dc012820) from 0x7f758b1e1440 to 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7f75dc00e920) from 0x7f758b1e1440 to 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Crossover copying tx to rx payload mapping 97 (0x7f75dc012670) from 0x7f758b1e1440 to 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Crossover copying tx to rx payload mapping 98 (0x7f75dc00e7f0) from 0x7f758b1e1440 to 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x1fbf9c0) from 0x7f758b1e1440 to 0x7f758b1e1440
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying rx payload mapping 0 (0x7f75dc0126c0) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying rx payload mapping 3 (0x7f75dc012820) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying rx payload mapping 8 (0x7f75dc00e920) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying rx payload mapping 97 (0x7f75dc012670) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying rx payload mapping 98 (0x7f75dc00e7f0) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying rx payload mapping 101 (0x1fbf9c0) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 0 (0x7f75dc0126c0) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 3 (0x7f75dc012820) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 8 (0x7f75dc00e920) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 97 (0x7f75dc012670) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 98 (0x7f75dc00e7f0) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 101 (0x1fbf9c0) from 0x7f758b1e1440 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Media stream 'audio' handled by audio
[Apr 18 09:39:52] DEBUG[4778] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f75dc00e9a8'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Method is INVITE
[Apr 18 09:39:52] DEBUG[2611] threadpool.c: Increasing threadpool stasis-core's size by 1
[Apr 18 09:39:52] DEBUG[4778] channel.c: Channel 0x7f75dc017028 'PJSIP/6001-00000006' allocated
[Apr 18 09:39:52] DEBUG[4778] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/6001-00000006
[Apr 18 09:39:52] DEBUG[4784][C-00000007] pbx.c: Launching 'Answer'
[Apr 18 09:39:52] VERBOSE[4784][C-00000007] pbx.c: Executing [100@from-internal:1] Answer("PJSIP/6001-00000006", "") in new stack
[Apr 18 09:39:52] DEBUG[2622] devicestate.c: No provider found, checking channel drivers for PJSIP - 6001
[Apr 18 09:39:52] DEBUG[2622] devicestate.c: Changing state for PJSIP/6001 - state 2 (In use)
[Apr 18 09:39:52] DEBUG[2688] app_queue.c: Device 'PJSIP/6001' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Apr 18 09:39:52] DEBUG[4778] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f75dc00e9a8'
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: Splitting '127.0.0.1' into...
[Apr 18 09:39:52] DEBUG[4778] netsock2.c: ...host '127.0.0.1' and port ''.
[Apr 18 09:39:52] DEBUG[4778] acl.c: For destination '127.0.0.1', our source address is '127.0.0.1'.
[Apr 18 09:39:52] DEBUG[4778] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f75dc00e9a8'
[Apr 18 09:39:52] VERBOSE[4778] res_rtp_asterisk.c: 0x7f75dc00f4f0 -- Strict RTP learning after remote address set to: 127.0.0.1:8000
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 98 based on m type on 0x7f758b1e1010
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 97 based on m type on 0x7f758b1e1010
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f758b1e1010
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f758b1e1010
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 3 based on m type on 0x7f758b1e1010
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f758b1e1010
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 0 (0x7f75dc01e260) from 0x7f758b1e1010 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 3 (0x7f75dc01e2b0) from 0x7f758b1e1010 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 8 (0x7f75dc01e100) from 0x7f758b1e1010 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 97 (0x7f75dc01e0b0) from 0x7f758b1e1010 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 98 (0x7f75dc01e060) from 0x7f758b1e1010 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] rtp_engine.c: Copying tx payload mapping 101 (0x1fbf9c0) from 0x7f758b1e1010 to 0x7f75dc00eb70
[Apr 18 09:39:52] DEBUG[4778] channel.c: Channel PJSIP/6001-00000006 setting read format path: ulaw -> ulaw
[Apr 18 09:39:52] DEBUG[4778] channel.c: Channel PJSIP/6001-00000006 setting write format path: ulaw -> ulaw
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Method is INVITE, Response is 200 OK
[Apr 18 09:39:52] DEBUG[4778] 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)
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The state change pertains to the endpoint '6001(PJSIP/6001-00000006)'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f75d8003998)
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: There is no transaction involved in this state change
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The current inv state is CONNECTING
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Source of transaction state change is TX_MSG
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The state change pertains to the endpoint '6001(PJSIP/6001-00000006)'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f75d8003998)
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f75d8003998
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The current transaction state is Completed
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The transaction state change event is TX_MSG
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The current inv state is CONNECTING
[Apr 18 09:39:52] DEBUG[4784][C-00000007] res_rtp_asterisk.c: Got RTCP report of 52 bytes from 127.0.0.1:8001
[Apr 18 09:39:52] DEBUG[2637] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f75d8020928 for Request msg ACK/cseq=228 (rdata0x7f75cc000af8)
[Apr 18 09:39:52] DEBUG[2637] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000028 associated with dialog dlg0x7f75d8020928
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The state change pertains to the endpoint '6001(PJSIP/6001-00000006)'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f75d8003998
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The current transaction state is Terminated
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The transaction state change event is USER
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The current inv state is CONNECTING
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The state change pertains to the endpoint '6001(PJSIP/6001-00000006)'
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: There is no transaction involved in this state change
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: The current inv state is CONFIRMED
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Received request
[Apr 18 09:39:52] DEBUG[4778] res_pjsip_session.c: Method is ACK
[Apr 18 09:39:52] VERBOSE[4784][C-00000007] res_rtp_asterisk.c: 0x7f75dc00f4f0 -- Strict RTP switching to RTP target address 127.0.0.1:8000 as source
[Apr 18 09:39:52] DEBUG[4784][C-00000007] pbx.c: Launching 'Playback'
[Apr 18 09:39:52] VERBOSE[4784][C-00000007] pbx.c: Executing [100@from-internal:2] Playback("PJSIP/6001-00000006", "screen-callee-options") in new stack
[Apr 18 09:39:52] DEBUG[4784][C-00000007] media_cache.c: Failed to obtain media at 'screen-callee-options'
[Apr 18 09:39:52] DEBUG[4784][C-00000007] channel.c: Channel PJSIP/6001-00000006 setting write format path: gsm -> ulaw
[Apr 18 09:39:52] DEBUG[4784][C-00000007] res_rtp_asterisk.c: Ooh, format changed from none to ulaw
[Apr 18 09:39:52] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 18 09:39:52] VERBOSE[4784][C-00000007] file.c: <PJSIP/6001-00000006> Playing 'screen-callee-options.gsm' (language 'en')
[Apr 18 09:39:57] VERBOSE[4784][C-00000007] res_rtp_asterisk.c: 0x7f75dc00f4f0 -- Strict RTP learning complete - Locking on source address 127.0.0.1:8000
[Apr 18 09:39:59] DEBUG[4784][C-00000007] res_rtp_asterisk.c: Got RTCP report of 96 bytes from 127.0.0.1:8001
[Apr 18 09:40:05] DEBUG[4784][C-00000007] res_rtp_asterisk.c: Got RTCP report of 96 bytes from 127.0.0.1:8001
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Channel PJSIP/6001-00000006 setting write format path: ulaw -> ulaw
[Apr 18 09:40:10] DEBUG[4784][C-00000007] pbx.c: Launching 'Record'
[Apr 18 09:40:10] VERBOSE[4784][C-00000007] pbx.c: Executing [100@from-internal:3] Record("PJSIP/6001-00000006", ""/tmp/file_in.wav16",1,5") in new stack
[Apr 18 09:40:10] DEBUG[4784][C-00000007] media_cache.c: Failed to obtain media at 'beep'
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Channel PJSIP/6001-00000006 setting write format path: gsm -> ulaw
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 18 09:40:10] VERBOSE[4784][C-00000007] file.c: <PJSIP/6001-00000006> Playing 'beep.gsm' (language 'en')
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Channel PJSIP/6001-00000006 setting write format path: ulaw -> ulaw
[Apr 18 09:40:10] DEBUG[4784][C-00000007] channel.c: Channel PJSIP/6001-00000006 setting read format path: ulaw -> slin
[Apr 18 09:40:10] DEBUG[4784][C-00000007] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Apr 18 09:40:10] DEBUG[4784][C-00000007] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:10] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:11] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] res_rtp_asterisk.c: Got RTCP report of 96 bytes from 127.0.0.1:8001
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:12] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:13] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:14] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] translate.c: Sample size different 160 vs 320
[Apr 18 09:40:15] DEBUG[4784][C-00000007] channel.c: Channel PJSIP/6001-00000006 setting read format path: ulaw -> ulaw
[Apr 18 09:40:15] DEBUG[4784][C-00000007] pbx.c: Launching 'Playback'
[Apr 18 09:40:15] VERBOSE[4784][C-00000007] pbx.c: Executing [100@from-internal:4] Playback("PJSIP/6001-00000006", "screen-callee-options") in new stack
[Apr 18 09:40:15] DEBUG[4784][C-00000007] media_cache.c: Failed to obtain media at 'screen-callee-options'
[Apr 18 09:40:15] DEBUG[4784][C-00000007] channel.c: Channel PJSIP/6001-00000006 setting write format path: gsm -> ulaw
[Apr 18 09:40:15] DEBUG[4784][C-00000007] res_rtp_asterisk.c: Difference is 40016, ms is 5022
[Apr 18 09:40:15] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 18 09:40:15] VERBOSE[4784][C-00000007] file.c: <PJSIP/6001-00000006> Playing 'screen-callee-options.gsm' (language 'en')
[Apr 18 09:40:19] DEBUG[4784][C-00000007] res_rtp_asterisk.c: Got RTCP report of 96 bytes from 127.0.0.1:8001
[Apr 18 09:40:20] DEBUG[2653] res_pjsip_registrar.c: Woke up at 1524037220  Interval: 30
[Apr 18 09:40:20] DEBUG[2653] res_pjsip_registrar.c: Expiring 0 contacts
[Apr 18 09:40:24] DEBUG[4784][C-00000007] res_rtp_asterisk.c: Got RTCP report of 96 bytes from 127.0.0.1:8001
[Apr 18 09:40:32] DEBUG[4784][C-00000007] res_rtp_asterisk.c: Got RTCP report of 96 bytes from 127.0.0.1:8001
[Apr 18 09:40:33] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 18 09:40:33] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 18 09:40:33] DEBUG[4784][C-00000007] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 18 09:40:33] DEBUG[4784][C-00000007] channel.c: Channel PJSIP/6001-00000006 setting write format path: ulaw -> ulaw
[Apr 18 09:40:33] DEBUG[4784][C-00000007] pbx.c: Launching 'Hangup'
[Apr 18 09:40:33] VERBOSE[4784][C-00000007] pbx.c: Executing [100@from-internal:5] Hangup("PJSIP/6001-00000006", "") in new stack
[Apr 18 09:40:33] DEBUG[4784][C-00000007] channel.c: Soft-Hanging (0x20) up channel 'PJSIP/6001-00000006'
[Apr 18 09:40:33] DEBUG[4784][C-00000007] pbx.c: Spawn extension (from-internal,100,5) exited non-zero on 'PJSIP/6001-00000006'
[Apr 18 09:40:33] VERBOSE[4784][C-00000007] pbx.c: Spawn extension (from-internal, 100, 5) exited non-zero on 'PJSIP/6001-00000006'
[Apr 18 09:40:33] DEBUG[4784][C-00000007] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/6001-00000006'
[Apr 18 09:40:33] DEBUG[4784][C-00000007] channel.c: Channel 0x7f75dc017028 'PJSIP/6001-00000006' hanging up.  Refs: 2
[Apr 18 09:40:33] DEBUG[4784][C-00000007] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[Apr 18 09:40:33] DEBUG[4778] rtp_engine.c: Destroyed RTP instance '0x7f75dc00e9a8'
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: Method is BYE
[Apr 18 09:40:33] DEBUG[4778] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '127.0.0.1'
[Apr 18 09:40:33] DEBUG[4778] res_pjsip/pjsip_resolver.c: Transport type for target '127.0.0.1' is 'UDP'
[Apr 18 09:40:33] DEBUG[4778] res_pjsip/pjsip_resolver.c: Target '127.0.0.1' is an IP address, skipping resolution
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The state change pertains to the endpoint '6001(PJSIP/6001-00000006)'
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f75d8003998
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The current transaction state is Calling
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The transaction state change event is TX_MSG
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The current inv state is CONFIRMED
[Apr 18 09:40:33] DEBUG[4778] channel.c: Channel 0x7f75dc017028 'PJSIP/6001-00000006' destroying
[Apr 18 09:40:33] DEBUG[2626] cdr.c: Finalized CDR for PJSIP/6001-00000006 - start 1524037192.275006 answer 1524037192.275521 end 1524037233.713404 dispo ANSWERED
[Apr 18 09:40:33] DEBUG[2622] devicestate.c: No provider found, checking channel drivers for PJSIP - 6001
[Apr 18 09:40:33] DEBUG[2622] devicestate.c: Changing state for PJSIP/6001 - state 1 (Not in use)
[Apr 18 09:40:33] DEBUG[2688] app_queue.c: Device 'PJSIP/6001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 18 09:40:33] DEBUG[2637] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f75d8020928 for Response msg 200/BYE/cseq=25605 (rdata0x7f75cc000af8)
[Apr 18 09:40:33] DEBUG[2637] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000028 associated with dialog dlg0x7f75d8020928
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The state change pertains to the endpoint '6001()'
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: There is no transaction involved in this state change
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The current inv state is DISCONNCTD
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: Source of transaction state change is RX_MSG
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: Received response
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: Response is 200 OK
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The state change pertains to the endpoint '6001()'
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f75d8003998
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The current transaction state is Completed
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The transaction state change event is RX_MSG
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: The current inv state is DISCONNCTD
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: Received response
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: Response is 200 OK
[Apr 18 09:40:33] DEBUG[4778] res_pjsip_session.c: BYE received final response code 200
[Apr 18 09:40:38] DEBUG[2637] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Apr 18 09:40:38] DEBUG[2637] res_pjsip_session.c: The state change pertains to the endpoint '6001()'
[Apr 18 09:40:38] DEBUG[2637] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Apr 18 09:40:38] DEBUG[2637] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f75d8003998
[Apr 18 09:40:38] DEBUG[2637] res_pjsip_session.c: The current transaction state is Terminated
[Apr 18 09:40:38] DEBUG[2637] res_pjsip_session.c: The transaction state change event is TIMER
[Apr 18 09:40:38] DEBUG[2637] res_pjsip_session.c: The current inv state is DISCONNCTD
[Apr 18 09:40:38] DEBUG[4778] res_pjsip_session.c: Destroying SIP session with endpoint 6001
[Apr 18 09:40:50] DEBUG[2653] res_pjsip_registrar.c: Woke up at 1524037250  Interval: 30
[Apr 18 09:40:50] DEBUG[2653] res_pjsip_registrar.c: Expiring 0 contacts
[Apr 18 09:40:52] DEBUG[4782] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr 18 09:40:52] DEBUG[4780] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr 18 09:40:52] DEBUG[4781] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr 18 09:40:52] DEBUG[2635] threadpool.c: Destroying worker thread 40
[Apr 18 09:40:52] DEBUG[2635] threadpool.c: Destroying worker thread 39
[Apr 18 09:40:52] DEBUG[2635] threadpool.c: Destroying worker thread 38
[Apr 18 09:40:52] DEBUG[4779] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr 18 09:40:52] DEBUG[2635] threadpool.c: Destroying worker thread 37
[Apr 18 09:40:53] DEBUG[4783] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr 18 09:40:53] DEBUG[2611] threadpool.c: Destroying worker thread 41
[Apr 18 09:41:20] DEBUG[2653] res_pjsip_registrar.c: Woke up at 1524037280  Interval: 30
[Apr 18 09:41:20] DEBUG[2653] res_pjsip_registrar.c: Expiring 0 contacts
[Apr 18 09:41:38] DEBUG[4778] threadpool.c: Worker thread idle timeout reached. Dying.
[Apr 18 09:41:38] DEBUG[2635] threadpool.c: Destroying worker thread 36
[Apr 18 09:41:50] DEBUG[2653] res_pjsip_registrar.c: Woke up at 1524037310  Interval: 30
[Apr 18 09:41:50] DEBUG[2653] res_pjsip_registrar.c: Expiring 0 contacts