[Mar 16 10:44:15] Asterisk 18.10.1 built by root @ asterisk on a x86_64 running Linux on 2022-03-15 13:07:28 UTC [Mar 16 10:44:15] NOTICE[10809] cdr.c: CDR simple logging enabled. [Mar 16 10:44:16] NOTICE[10662] sorcery.c: Type 'system' is not reloadable, maintaining previous values [Mar 16 10:44:16] WARNING[10809] res_phoneprov.c: Unable to find a valid server address or name. [Mar 16 10:44:16] NOTICE[10809] cel_custom.c: No mappings found in cel_custom.conf. Not logging CEL to custom CSVs. [Mar 16 10:44:16] NOTICE[10809] app_queue.c: queuerules.conf has not changed since it was last loaded. Not taking any action. [Mar 16 10:44:35] Asterisk 18.10.1 built by root @ asterisk on a x86_64 running Linux on 2022-03-15 13:07:28 UTC [Mar 16 10:44:35] VERBOSE[10809] loader.c: Reloading module 'logger' (Logger) [Mar 16 10:44:35] DEBUG[10809] config.c: Parsing /etc/asterisk/logger.conf [Mar 16 10:44:35] VERBOSE[10809] logger.c: Asterisk Queue Logger restarted [Mar 16 10:44:35] DEBUG[10679] manager.c: Examining AMI event: Event: Reload Privilege: system,all Timestamp: 1647423875.604179 Module: logger Status: 0 [Mar 16 10:44:44] DEBUG[10662] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000008e to use for Request msg INVITE/cseq=28531 (rdata0x7fae84023268) [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: 742 [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: Direct media no glare mitigation [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Call (UDP:10.0.1.199:5060) to extension '666' sending 100 Trying [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Method is INVITE, Response is 100 Trying [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742 Event: TSX_STATE Inv State: INCOMING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '742()' [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef401b5d8) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The current inv state is INCOMING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Source of transaction state change is TX_MSG [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742 TSX State: Proceeding Inv State: INCOMING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '742()' [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef401b5d8) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7faef401b5d8 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The current transaction state is Proceeding [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The transaction state change event is TX_MSG [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The current inv state is INCOMING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742 TSX State: Proceeding Inv State: INCOMING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: (null topology) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Media count: 1 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Processing stream 0 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Using audio-0 for new stream name [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Using new stream 0:audio-0:audio:sendrecv (nothing) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742 Adding position 0 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Creating new media session [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Setting media session as default for audio [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Done [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: 742 [Mar 16 10:44:44] DEBUG[10662] netsock2.c: Splitting '10.0.1.199' into... [Mar 16 10:44:44] DEBUG[10662] netsock2.c: ...host '10.0.1.199' and port ''. [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7faf5818a190' [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) RTP allocated port 16726 [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) ICE creating session [::]:16726 (16726) [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) ICE create [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) ICE add system candidates [Mar 16 10:44:44] DEBUG[10662] netsock2.c: Splitting '10.0.66.60' into... [Mar 16 10:44:44] DEBUG[10662] netsock2.c: ...host '10.0.66.60' and port ''. [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) ICE add candidate: 10.0.66.60:16726, 2130706431 [Mar 16 10:44:44] DEBUG[10662] netsock2.c: Splitting 'fe80::685c:eaff:fe0d:4830' into... [Mar 16 10:44:44] DEBUG[10662] netsock2.c: ...host 'fe80::685c:eaff:fe0d:4830' and port ''. [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) ICE add candidate: [fe80::685c:eaff:fe0d:4830]:16726, 2130706431 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: RTP instance '0x7faf5818a190' is setup and ready to go [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) ICE stopped [Mar 16 10:44:44] DEBUG[10662] netsock2.c: Splitting 'asterisk' into... [Mar 16 10:44:44] DEBUG[10662] netsock2.c: ...host 'asterisk' and port ''. [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) RTCP setup on RTP instance [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: 742 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: 742 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7faf77597250 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7faf77597250 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7faf77597250 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7faf77597250 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session/pjsip_session_caps.c: '742' Caps for incoming audio call with pref 'local' - remote: (ulaw|alaw|g722|g726|g729) local: (g722|alaw|ulaw|gsm) joint: (g722|alaw|ulaw) [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7faf58001848) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7faf58181ac8) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 9 (0x7faf58181f28) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7faf5818c4a8) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 96 (0x7faf5800b7e8) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 111 (0x7faf58181f78) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 0 (0x7faf58001848) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 8 (0x7faf58181ac8) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 9 (0x7faf58181f28) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 18 (0x7faf5818c4a8) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 96 (0x7faf5800b7e8) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 111 (0x7faf58181f78) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 0 (0x7faf58001848) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 8 (0x7faf58181ac8) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 9 (0x7faf58181f28) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 18 (0x7faf5818c4a8) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 96 (0x7faf5800b7e8) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 111 (0x7faf58181f78) from 0x7faf77597250 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Media stream 0:audio-0:audio:sendrecv (g722|alaw|ulaw) handled by audio [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Done with stream 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Handled? yes [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Processing streams [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Processing stream 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742 Adding position 0 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Using existing media_session [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742 Stream: 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: 742 Type: audio 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) RTCP ignoring duplicate property [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: RC: 1 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Had handler [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Stream 0:audio-0:audio:sendrecv (g722|alaw|ulaw) added [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Done with 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Adding bundle groups (if available) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Copying connection details [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Processing media 0 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Media 0 reset [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: 742: Method is INVITE [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: 742 [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: 742 [Mar 16 10:44:44] DEBUG[10662] channel_internal_api.c: : Formats: (none) [Mar 16 10:44:44] DEBUG[10662] channel_internal_api.c: Channel is being initialized or destroyed [Mar 16 10:44:44] DEBUG[10662] stasis.c: Creating topic. name: channel:1647423884.43, detail: [Mar 16 10:44:44] DEBUG[10662] stasis.c: Topic 'channel:1647423884.43': 0x7faf581727b0 created [Mar 16 10:44:44] DEBUG[10662] channel.c: Channel 0x7faf581733b0 'PJSIP/742-0000001a' allocated [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: Topology: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> Formats: (g722|alaw|ulaw|gsm) [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: Compatible? yes [Mar 16 10:44:44] DEBUG[10662] channel_internal_api.c: PJSIP/742-0000001a: MultistreamFormats: (g722|alaw|ulaw) [Mar 16 10:44:44] DEBUG[10662] channel_internal_api.c: Set native formats but not topology [Mar 16 10:44:44] DEBUG[10662] channel_internal_api.c: PJSIP/742-0000001a: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:44:44] DEBUG[10662] channel_internal_api.c: Used provided topology [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: [Mar 16 10:44:44] DEBUG[10431] threadpool.c: Increasing threadpool stasis/pool's size by 1 [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Timestamp: 1647423884.158717 Channel: PJSIP/742-0000001a ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 1 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: RC: 0 [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Timestamp: 1647423884.158770 Channel: PJSIP/742-0000001a ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 1 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Variable: SIPDOMAIN Value: 10.0.66.60 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Request: Session: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: (null session) Handled request INVITE ? yes [Mar 16 10:44:44] DEBUG[10828][C-0000000e] pbx.c: Launching 'Answer' [Mar 16 10:44:44] VERBOSE[10828][C-0000000e] pbx.c: Executing [666@default:1] Answer("PJSIP/742-0000001a", "") in new stack [Mar 16 10:44:44] DEBUG[10828][C-0000000e] chan_pjsip.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Timestamp: 1647423884.159104 Channel: PJSIP/742-0000001a ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 1 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Extension: 666 Application: Answer AppData: [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Timestamp: 1647423884.159143 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 1 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 [Mar 16 10:44:44] DEBUG[10443] devicestate.c: No provider found, checking channel drivers for PJSIP - 742 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10443] devicestate.c: Changing state for PJSIP/742 - state 2 (In use) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a: Applying negotiated SDP media stream 'audio' using audio SDP handler [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: PJSIP/742-0000001a Stream: 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) RTCP ignoring duplicate property [Mar 16 10:44:44] DEBUG[10662] netsock2.c: Splitting '10.0.1.199' into... [Mar 16 10:44:44] DEBUG[10662] netsock2.c: ...host '10.0.1.199' and port ''. [Mar 16 10:44:44] DEBUG[10662] acl.c: For destination '10.0.1.199', our source address is '10.0.66.60'. [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) RTCP setting address on RTP instance [Mar 16 10:44:44] VERBOSE[10662] res_rtp_asterisk.c: 0x7faf5816dae0 -- Strict RTP learning after remote address set to: 10.0.1.199:4038 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: PJSIP/742-0000001a ANSWER [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7faf77597100 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7faf77597100 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7faf77597100 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7faf77597100 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 0 (0x7faf581a6e48) from 0x7faf77597100 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 8 (0x7faf581a3ca8) from 0x7faf77597100 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 9 (0x7faf580082d8) from 0x7faf77597100 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 18 (0x7faf581a40d8) from 0x7faf77597100 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10497] app_queue.c: Device 'PJSIP/742' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 96 (0x7faf5817ee88) from 0x7faf77597100 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 111 (0x7faf58008328) from 0x7faf77597100 to 0x7faf5818a368 [Mar 16 10:44:44] DEBUG[10662] channel_internal_api.c: PJSIP/742-0000001a: MultistreamFormats: (g722) [Mar 16 10:44:44] DEBUG[10662] channel_internal_api.c: Set native formats but not topology [Mar 16 10:44:44] DEBUG[10662] channel.c: Channel PJSIP/742-0000001a setting read format path: g722 -> g722 [Mar 16 10:44:44] DEBUG[10662] channel.c: Channel PJSIP/742-0000001a setting write format path: g722 -> g722 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) DTLS - ast_rtp_activate rtp=0x7faf5816dae0 - setup and perform DTLS' [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5816dae0) DTLS perform handshake - ssl = (nil), setup = 0 [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1647423884.159515 Device: PJSIP/742 State: INUSE [Mar 16 10:44:44] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5816dae0) DTLS perform handshake - ssl = (nil), setup = 0 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_sdp_rtp.c: Handled [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 16 10:44:44] DEBUG[10662] channel_internal_api.c: PJSIP/742-0000001a: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:44:44] DEBUG[10662] channel_internal_api.c: Used provided topology [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: ExtensionStatus Privilege: call,all Timestamp: 1647423884.159541 Exten: auto_hint_742 Context: default Hint: PJSIP/742,CustomPresence:742 Status: 1 StatusText: InUse [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a: Method is INVITE, Response is 200 OK [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.0.66.60:5060 (this may be re-written again later) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a Event: TSX_STATE Inv State: CONNECTING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '742(PJSIP/742-0000001a)' [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef401b5d8) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The current inv state is CONNECTING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a: Source of transaction state change is TX_MSG [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a TSX State: Completed Inv State: CONNECTING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '742(PJSIP/742-0000001a)' [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef401b5d8) [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7faef401b5d8 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The current transaction state is Completed [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The transaction state change event is TX_MSG [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The current inv state is CONNECTING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a TSX State: Completed Inv State: CONNECTING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: [Mar 16 10:44:44] DEBUG[10828][C-0000000e] chan_pjsip.c: [Mar 16 10:44:44] DEBUG[10828][C-0000000e] chan_pjsip.c: PJSIP/742-0000001a: Indicated Stop generators [Mar 16 10:44:44] DEBUG[10828][C-0000000e] chan_pjsip.c: PJSIP/742-0000001a [Mar 16 10:44:44] VERBOSE[10828][C-0000000e] res_rtp_asterisk.c: 0x7faf5816dae0 -- Strict RTP switching to RTP target address 10.0.1.199:4038 as source [Mar 16 10:44:44] DEBUG[10828][C-0000000e] pbx.c: Launching 'Set' [Mar 16 10:44:44] VERBOSE[10828][C-0000000e] pbx.c: Executing [666@default:2] Set("PJSIP/742-0000001a", "QUEUE_MIN_PENALTY=0") in new stack [Mar 16 10:44:44] DEBUG[10828][C-0000000e] pbx.c: Launching 'Set' [Mar 16 10:44:44] VERBOSE[10828][C-0000000e] pbx.c: Executing [666@default:3] Set("PJSIP/742-0000001a", "QUEUE_MAX_PENALTY=50") in new stack [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Timestamp: 1647423884.464333 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 2 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Extension: 666 Application: Set AppData: QUEUE_MIN_PENALTY=0 [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Timestamp: 1647423884.464360 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 2 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Variable: QUEUE_MIN_PENALTY Value: 0 [Mar 16 10:44:44] DEBUG[10828][C-0000000e] pbx.c: Launching 'Queue' [Mar 16 10:44:44] VERBOSE[10828][C-0000000e] pbx.c: Executing [666@default:4] Queue("PJSIP/742-0000001a", "666") in new stack [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Timestamp: 1647423884.464416 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 3 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Extension: 666 Application: Set AppData: QUEUE_MAX_PENALTY=50 [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: queue: 666, options: , url: , announce: , timeout: , agi: , macro: , gosub: , rule: , position: [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: NO QUEUE_PRIO variable found. Using default. [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Timestamp: 1647423884.464490 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 3 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Variable: QUEUE_MAX_PENALTY Value: 50 [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: PJSIP/742-0000001a: Got max penalty 50 from ${QUEUE_MAX_PENALTY}. [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: PJSIP/742-0000001a: Got min penalty 0 from ${QUEUE_MIN_PENALTY}. [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: queue: 666, expires: 0, priority: 0 [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: Queue 666 has no realtime members defined. No need for update [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Timestamp: 1647423884.464567 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Extension: 666 Application: Queue AppData: 666 [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1647423884.464775 Device: Queue:666 State: RINGING [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: Queue '666' Join, Channel 'PJSIP/742-0000001a', Position '1' [Mar 16 10:44:44] DEBUG[10497] app_queue.c: Device 'Queue:666' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: QueueCallerJoin Privilege: agent,all Timestamp: 1647423884.464824 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Queue: 666 Position: 1 Count: 1 [Mar 16 10:44:44] VERBOSE[10828][C-0000000e] res_musiconhold.c: Started music on hold, class 'default', on channel 'PJSIP/742-0000001a' [Mar 16 10:44:44] DEBUG[10828][C-0000000e] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Mar 16 10:44:44] DEBUG[10679] manager.c: Examining AMI event: Event: MusicOnHoldStart Privilege: call,all Timestamp: 1647423884.464957 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Class: default [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: There is 1 available member. [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: It's our turn (PJSIP/742-0000001a). [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: PJSIP/742-0000001a is trying to call a queue member. [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: Nobody left to try ringing in queue [Mar 16 10:44:44] DEBUG[10828][C-0000000e] app_queue.c: Everyone is busy at this time [Mar 16 10:44:44] DEBUG[10828][C-0000000e] channel.c: Channel PJSIP/742-0000001a setting write format path: ulaw -> g722 [Mar 16 10:44:44] DEBUG[10828][C-0000000e] res_musiconhold.c: PJSIP/742-0000001a Opened file 0 '/var/lib/asterisk/sounds/custom/_onhold/_onhold' [Mar 16 10:44:44] DEBUG[10828][C-0000000e] res_rtp_asterisk.c: (0x7faf5818a190) RTP ooh, format changed from none to g722 [Mar 16 10:44:44] DEBUG[10458] netsock2.c: Splitting '10.0.1.199' into... [Mar 16 10:44:44] DEBUG[10458] netsock2.c: ...host '10.0.1.199' and port ''. [Mar 16 10:44:44] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7faef004f158 for Request msg ACK/cseq=28531 (rdata0x7fae840128b8) [Mar 16 10:44:44] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000008e associated with dialog dlg0x7faef004f158 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a TSX State: Terminated Inv State: CONNECTING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '742(PJSIP/742-0000001a)' [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7faef401b5d8 [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The current transaction state is Terminated [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The transaction state change event is USER [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The current inv state is CONNECTING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a TSX State: Terminated Inv State: CONNECTING [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a Event: RX_MSG Inv State: CONFIRMED [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '742(PJSIP/742-0000001a)' [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: The current inv state is CONFIRMED [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a: Received request [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a: Method is ACK [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: PJSIP/742-0000001a: Queueing SRCCHANGE [Mar 16 10:44:44] DEBUG[10662] chan_pjsip.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a Request: ACK [Mar 16 10:44:44] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a Handled request ACK ? yes [Mar 16 10:44:48] DEBUG[10458] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10458] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10458] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=7423 (rdata0x7fae840128b8) [Mar 16 10:44:48] DEBUG[10458] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000092 to use for Request msg INVITE/cseq=7423 (rdata0x7fae840128b8) [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10662] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '741' domain '10.0.66.60' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_endpoint_identifier_user.c: Identified by From username '741' domain '10.0.66.60' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '741'. [Mar 16 10:44:48] DEBUG[10662] res_pjsip_authenticator_digest.c: Realm: asterisk Username: 741 Result: NOAUTH [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting '10.0.66.60' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host '10.0.66.60' and port ''. [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: ChallengeSent Privilege: security,all Timestamp: 1647423888.303021 EventTV: 2022-03-16T10:44:48.302+0100 Severity: Informational Service: PJSIP EventVersion: 1 AccountID: 741 SessionID: Kb6y633.7aIjLQJLsOIICxUlOWe2B42A LocalAddress: IPV4/UDP/10.0.66.60/5060 RemoteAddress: IPV4/UDP/10.0.1.224/5060 Challenge: [Mar 16 10:44:48] DEBUG[10458] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10458] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10458] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg ACK/cseq=7423 (rdata0x7fae840128b8) [Mar 16 10:44:48] DEBUG[10458] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000092 to use for Request msg ACK/cseq=7423 (rdata0x7fae840128b8) [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10662] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '741' domain '10.0.66.60' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_endpoint_identifier_user.c: Identified by From username '741' domain '10.0.66.60' [Mar 16 10:44:48] DEBUG[10458] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10458] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10458] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=7424 (rdata0x7fae840128b8) [Mar 16 10:44:48] DEBUG[10458] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000092 to use for Request msg INVITE/cseq=7424 (rdata0x7fae840128b8) [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10662] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '741' domain '10.0.66.60' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_endpoint_identifier_user.c: Identified by From username '741' domain '10.0.66.60' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '741'. [Mar 16 10:44:48] DEBUG[10662] res_pjsip_authenticator_digest.c: Calculated nonce 1647423888/450ce42d25fe5620f0d07b2a8ae3f3f4. Actual nonce is 1647423888/450ce42d25fe5620f0d07b2a8ae3f3f4 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_authenticator_digest.c: Realm: asterisk Username: 741 Result: SUCCESS [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting '10.0.66.60' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host '10.0.66.60' and port ''. [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: (null session) Request: INVITE [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Request: [Mar 16 10:44:48] DEBUG[10662] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000092 to use for Request msg INVITE/cseq=7424 (rdata0x7fae84023268) [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: 741 [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: SuccessfulAuth Privilege: security,all Timestamp: 1647423888.396598 EventTV: 2022-03-16T10:44:48.396+0100 Severity: Informational Service: PJSIP EventVersion: 1 AccountID: 741 SessionID: Kb6y633.7aIjLQJLsOIICxUlOWe2B42A LocalAddress: IPV4/UDP/10.0.66.60/5060 RemoteAddress: IPV4/UDP/10.0.1.224/5060 UsingPassword: 1 [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: Direct media no glare mitigation [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Call (UDP:10.0.1.224:5060) to extension '667' sending 100 Trying [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Method is INVITE, Response is 100 Trying [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741 Event: TSX_STATE Inv State: INCOMING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '741()' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef4045f18) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The current inv state is INCOMING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Source of transaction state change is TX_MSG [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741 TSX State: Proceeding Inv State: INCOMING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '741()' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef4045f18) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7faef4045f18 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The current transaction state is Proceeding [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The transaction state change event is TX_MSG [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The current inv state is INCOMING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741 TSX State: Proceeding Inv State: INCOMING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: (null topology) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Media count: 1 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Processing stream 0 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Using audio-0 for new stream name [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Using new stream 0:audio-0:audio:sendrecv (nothing) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741 Adding position 0 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Creating new media session [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Setting media session as default for audio [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Done [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: 741 [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7faf58175a90' [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) RTP allocated port 18242 [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) ICE creating session [::]:18242 (18242) [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) ICE create [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) ICE add system candidates [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting '10.0.66.60' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host '10.0.66.60' and port ''. [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) ICE add candidate: 10.0.66.60:18242, 2130706431 [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting 'fe80::685c:eaff:fe0d:4830' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host 'fe80::685c:eaff:fe0d:4830' and port ''. [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) ICE add candidate: [fe80::685c:eaff:fe0d:4830]:18242, 2130706431 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: RTP instance '0x7faf58175a90' is setup and ready to go [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) ICE stopped [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting 'asterisk' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host 'asterisk' and port ''. [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) RTCP setup on RTP instance [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: 741 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: 741 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7faf77597250 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7faf77597250 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7faf77597250 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7faf77597250 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session/pjsip_session_caps.c: '741' Caps for incoming audio call with pref 'local' - remote: (ulaw|alaw|g722|g726|g729) local: (g722|alaw|ulaw|gsm) joint: (g722|alaw|ulaw) [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7faf58008178) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7faf5817ae38) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 9 (0x7faf581a3ad8) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7faf581a3f08) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 96 (0x7faf581a3f58) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Crossover copying tx to rx payload mapping 111 (0x7faf581a3b28) from 0x7faf77597250 to 0x7faf77597250 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 0 (0x7faf58008178) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 8 (0x7faf5817ae38) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 9 (0x7faf581a3ad8) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 18 (0x7faf581a3f08) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 96 (0x7faf581a3f58) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying rx payload mapping 111 (0x7faf581a3b28) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 0 (0x7faf58008178) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 8 (0x7faf5817ae38) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 9 (0x7faf581a3ad8) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 18 (0x7faf581a3f08) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 96 (0x7faf581a3f58) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 111 (0x7faf581a3b28) from 0x7faf77597250 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Media stream 0:audio-0:audio:sendrecv (g722|alaw|ulaw) handled by audio [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Done with stream 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Handled? yes [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Processing streams [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Processing stream 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741 Adding position 0 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Using existing media_session [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741 Stream: 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: 741 Type: audio 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) RTCP ignoring duplicate property [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: RC: 1 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Had handler [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Stream 0:audio-0:audio:sendrecv (g722|alaw|ulaw) added [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Done with 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Adding bundle groups (if available) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Copying connection details [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Processing media 0 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Media 0 reset [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: 741: Method is INVITE [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: 741 [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: 741 [Mar 16 10:44:48] DEBUG[10662] channel_internal_api.c: : Formats: (none) [Mar 16 10:44:48] DEBUG[10662] channel_internal_api.c: Channel is being initialized or destroyed [Mar 16 10:44:48] DEBUG[10662] stasis.c: Creating topic. name: channel:1647423888.44, detail: [Mar 16 10:44:48] DEBUG[10662] stasis.c: Topic 'channel:1647423888.44': 0x7faf58189b50 created [Mar 16 10:44:48] DEBUG[10662] channel.c: Channel 0x7faf5803c0c0 'PJSIP/741-0000001b' allocated [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: Topology: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> Formats: (g722|alaw|ulaw|gsm) [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: Compatible? yes [Mar 16 10:44:48] DEBUG[10662] channel_internal_api.c: PJSIP/741-0000001b: MultistreamFormats: (g722|alaw|ulaw) [Mar 16 10:44:48] DEBUG[10662] channel_internal_api.c: Set native formats but not topology [Mar 16 10:44:48] DEBUG[10662] channel_internal_api.c: PJSIP/741-0000001b: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:44:48] DEBUG[10662] channel_internal_api.c: Used provided topology [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Timestamp: 1647423888.397859 Channel: PJSIP/741-0000001b ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 1 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: RC: 0 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Request: Session: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: (null session) Handled request INVITE ? yes [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Timestamp: 1647423888.398024 Channel: PJSIP/741-0000001b ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 1 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Variable: SIPDOMAIN Value: 10.0.66.60 [Mar 16 10:44:48] DEBUG[10829][C-0000000f] pbx.c: Launching 'Answer' [Mar 16 10:44:48] VERBOSE[10829][C-0000000f] pbx.c: Executing [667@default:1] Answer("PJSIP/741-0000001b", "") in new stack [Mar 16 10:44:48] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Timestamp: 1647423888.398268 Channel: PJSIP/741-0000001b ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 1 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Extension: 667 Application: Answer AppData: [Mar 16 10:44:48] DEBUG[10443] devicestate.c: No provider found, checking channel drivers for PJSIP - 741 [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10443] devicestate.c: Changing state for PJSIP/741 - state 2 (In use) [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Timestamp: 1647423888.398297 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 1 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b: Applying negotiated SDP media stream 'audio' using audio SDP handler [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: PJSIP/741-0000001b Stream: 0:audio-0:audio:sendrecv (g722|alaw|ulaw) [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) RTCP ignoring duplicate property [Mar 16 10:44:48] DEBUG[10662] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10662] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10662] acl.c: For destination '10.0.1.224', our source address is '10.0.66.60'. [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) RTCP setting address on RTP instance [Mar 16 10:44:48] VERBOSE[10662] res_rtp_asterisk.c: 0x7faf58183ff0 -- Strict RTP learning after remote address set to: 10.0.1.224:4022 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: PJSIP/741-0000001b ANSWER [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7faf77597100 [Mar 16 10:44:48] DEBUG[10497] app_queue.c: Device 'PJSIP/741' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7faf77597100 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7faf77597100 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7faf77597100 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 0 (0x7faf5803d868) from 0x7faf77597100 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 8 (0x7faf58189998) from 0x7faf77597100 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 9 (0x7faf581897d8) from 0x7faf77597100 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 18 (0x7faf58041178) from 0x7faf77597100 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 96 (0x7faf580412d8) from 0x7faf77597100 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] rtp_engine.c: Copying tx payload mapping 111 (0x7faf58189828) from 0x7faf77597100 to 0x7faf58175c68 [Mar 16 10:44:48] DEBUG[10662] channel_internal_api.c: PJSIP/741-0000001b: MultistreamFormats: (g722) [Mar 16 10:44:48] DEBUG[10662] channel_internal_api.c: Set native formats but not topology [Mar 16 10:44:48] DEBUG[10662] channel.c: Channel PJSIP/741-0000001b setting read format path: g722 -> g722 [Mar 16 10:44:48] DEBUG[10662] channel.c: Channel PJSIP/741-0000001b setting write format path: g722 -> g722 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) DTLS - ast_rtp_activate rtp=0x7faf58183ff0 - setup and perform DTLS' [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58183ff0) DTLS perform handshake - ssl = (nil), setup = 0 [Mar 16 10:44:48] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58183ff0) DTLS perform handshake - ssl = (nil), setup = 0 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_sdp_rtp.c: Handled [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: ExtensionStatus Privilege: call,all Timestamp: 1647423888.398587 Exten: auto_hint_741 Context: default Hint: PJSIP/741,CustomPresence:741 Status: 1 StatusText: InUse [Mar 16 10:44:48] DEBUG[10662] channel_internal_api.c: PJSIP/741-0000001b: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:44:48] DEBUG[10662] channel_internal_api.c: Used provided topology [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b: Method is INVITE, Response is 200 OK [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1647423888.398728 Device: PJSIP/741 State: INUSE [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.0.66.60:5060 (this may be re-written again later) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b Event: TSX_STATE Inv State: CONNECTING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '741(PJSIP/741-0000001b)' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef4045f18) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The current inv state is CONNECTING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b: Source of transaction state change is TX_MSG [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b TSX State: Completed Inv State: CONNECTING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '741(PJSIP/741-0000001b)' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef4045f18) [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7faef4045f18 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The current transaction state is Completed [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The transaction state change event is TX_MSG [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The current inv state is CONNECTING [Mar 16 10:44:48] DEBUG[10801] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.0.66.234' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:44:48] DEBUG[10801] res_pjsip/pjsip_resolver.c: Transport type for target '10.0.66.234' is 'UDP transport' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b TSX State: Completed Inv State: CONNECTING [Mar 16 10:44:48] DEBUG[10801] res_pjsip/pjsip_resolver.c: Target '10.0.66.234' is an IP address, skipping resolution [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: [Mar 16 10:44:48] DEBUG[10801] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.0.66.60:5060 (this may be re-written again later) [Mar 16 10:44:48] DEBUG[10829][C-0000000f] chan_pjsip.c: [Mar 16 10:44:48] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/741-0000001b: Indicated Stop generators [Mar 16 10:44:48] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10801] res_pjsip_pubsub.c: evsub 0x7faef40c6be8 state ACTIVE event USER sub_tree 0x7faef40c4cb0 sub_tree state Normal [Mar 16 10:44:48] DEBUG[10801] res_pjsip_pubsub.c: Updating persistence for '301->auto_hint_741' prune on boot: no [Mar 16 10:44:48] DEBUG[10801] sorcery.c: Skipping field 'generator_data' for object type 'subscription_persistence' [Mar 16 10:44:48] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7faef40c4dd8 for Response msg 200/NOTIFY/cseq=27371 (rdata0x7fae840128b8) [Mar 16 10:44:48] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000090 associated with dialog dlg0x7faef40c4dd8 [Mar 16 10:44:48] DEBUG[10828][C-0000000e] res_rtp_asterisk.c: (0x7faf5818a190) RTCP got report of 64 bytes from 10.0.1.199:4039 [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423888.475520 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 To: 10.0.66.60:16727 From: 10.0.1.199:4039 RTT: 0.0000 SSRC: 0x001d98d7 PT: 200(SR) ReportCount: 1 SentNTP: 2087918167.190001 SentRTP: 2812880778 SentPackets: 201 SentOctets: 32160 Report0SourceSSRC: 0x7ccea15c Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 27476 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 0.0000 [Mar 16 10:44:48] VERBOSE[10829][C-0000000f] res_rtp_asterisk.c: 0x7faf58183ff0 -- Strict RTP switching to RTP target address 10.0.1.224:4022 as source [Mar 16 10:44:48] DEBUG[10829][C-0000000f] pbx.c: Launching 'Queue' [Mar 16 10:44:48] VERBOSE[10829][C-0000000f] pbx.c: Executing [667@default:2] Queue("PJSIP/741-0000001b", "667") in new stack [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: queue: 667, options: , url: , announce: , timeout: , agi: , macro: , gosub: , rule: , position: [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: NO QUEUE_PRIO variable found. Using default. [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: queue: 667, expires: 0, priority: 0 [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: Queue 667 has no realtime members defined. No need for update [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Timestamp: 1647423888.555979 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Extension: 667 Application: Queue AppData: 667 [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: Queue '667' Join, Channel 'PJSIP/741-0000001b', Position '1' [Mar 16 10:44:48] VERBOSE[10829][C-0000000f] res_musiconhold.c: Started music on hold, class 'default', on channel 'PJSIP/741-0000001b' [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1647423888.556034 Device: Queue:667 State: RINGING [Mar 16 10:44:48] DEBUG[10497] app_queue.c: Device 'Queue:667' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 16 10:44:48] DEBUG[10829][C-0000000f] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: There is 1 available member. [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: It's our turn (PJSIP/741-0000001b). [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: PJSIP/741-0000001b is trying to call a queue member. [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: (Parallel) Trying 'PJSIP/744' with metric 60000000 [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: QueueCallerJoin Privilege: agent,all Timestamp: 1647423888.556068 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Queue: 667 Position: 1 Count: 1 [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: Found matching member PJSIP/744 in queue '666' [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: Queue '666' (weight 66, calls 1) is preferred over '667' (weight 65, calls 1) [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: Priority queue delaying call to 667:PJSIP/744 [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: Nobody left to try ringing in queue [Mar 16 10:44:48] DEBUG[10829][C-0000000f] app_queue.c: Everyone is busy at this time [Mar 16 10:44:48] DEBUG[10679] manager.c: Examining AMI event: Event: MusicOnHoldStart Privilege: call,all Timestamp: 1647423888.556134 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Class: default [Mar 16 10:44:48] DEBUG[10829][C-0000000f] channel.c: Channel PJSIP/741-0000001b setting write format path: ulaw -> g722 [Mar 16 10:44:48] DEBUG[10829][C-0000000f] res_musiconhold.c: PJSIP/741-0000001b Opened file 0 '/var/lib/asterisk/sounds/custom/_onhold/_onhold' [Mar 16 10:44:48] DEBUG[10829][C-0000000f] res_rtp_asterisk.c: (0x7faf58175a90) RTP ooh, format changed from none to g722 [Mar 16 10:44:48] DEBUG[10458] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:44:48] DEBUG[10458] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:44:48] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7faef401b5d8 for Request msg ACK/cseq=7424 (rdata0x7fae840128b8) [Mar 16 10:44:48] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000092 associated with dialog dlg0x7faef401b5d8 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b TSX State: Terminated Inv State: CONNECTING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '741(PJSIP/741-0000001b)' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7faef4045f18 [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The current transaction state is Terminated [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The transaction state change event is USER [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The current inv state is CONNECTING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b TSX State: Terminated Inv State: CONNECTING [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b Event: RX_MSG Inv State: CONFIRMED [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '741(PJSIP/741-0000001b)' [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: The current inv state is CONFIRMED [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b: Received request [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b: Method is ACK [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: PJSIP/741-0000001b: Queueing SRCCHANGE [Mar 16 10:44:48] DEBUG[10662] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b Request: ACK [Mar 16 10:44:48] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b Handled request ACK ? yes [Mar 16 10:44:49] VERBOSE[10828][C-0000000e] res_rtp_asterisk.c: 0x7faf5816dae0 -- Strict RTP learning complete - Locking on source address 10.0.1.199:4038 [Mar 16 10:44:49] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Timestamp: 1647423889.464085 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 To: 10.0.1.199:4039 From: 10.0.66.60:16727 SSRC: 0x7ccea15c PT: 200(SR) ReportCount: 1 SentNTP: 1647423889.463996 SentRTP: 40000 SentPackets: 250 SentOctets: 40000 Report0SourceSSRC: 0xe15a8d14 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 14008 Report0SequenceNumberCycles: 0 Report0IAJitter: 2 Report0LSR: 2564239523 Report0DLSR: 0.9880 [Mar 16 10:44:49] DEBUG[10828][C-0000000e] app_queue.c: Queue 666 has no realtime members defined. No need for update [Mar 16 10:44:49] DEBUG[10828][C-0000000e] app_queue.c: There is 1 available member. [Mar 16 10:44:49] DEBUG[10828][C-0000000e] app_queue.c: It's our turn (PJSIP/742-0000001a). [Mar 16 10:44:49] DEBUG[10828][C-0000000e] app_queue.c: PJSIP/742-0000001a is trying to call a queue member. [Mar 16 10:44:49] DEBUG[10828][C-0000000e] app_queue.c: Nobody left to try ringing in queue [Mar 16 10:44:49] DEBUG[10828][C-0000000e] app_queue.c: Everyone is busy at this time [Mar 16 10:44:52] DEBUG[10829][C-0000000f] res_rtp_asterisk.c: (0x7faf58175a90) RTCP got report of 64 bytes from 10.0.1.224:4023 [Mar 16 10:44:52] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423892.966427 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.66.60:18243 From: 10.0.1.224:4023 RTT: 0.0000 SSRC: 0x001b7661 PT: 200(SR) ReportCount: 1 SentNTP: 2087778273.200001 SentRTP: 3318541001 SentPackets: 221 SentOctets: 35360 Report0SourceSSRC: 0x47eb1a38 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 18400 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 0.0000 [Mar 16 10:44:53] VERBOSE[10829][C-0000000f] res_rtp_asterisk.c: 0x7faf58183ff0 -- Strict RTP learning complete - Locking on source address 10.0.1.224:4022 [Mar 16 10:44:53] DEBUG[10828][C-0000000e] res_rtp_asterisk.c: (0x7faf5818a190) RTCP got report of 64 bytes from 10.0.1.199:4039 [Mar 16 10:44:53] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423893.475334 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 To: 10.0.66.60:16727 From: 10.0.1.199:4039 RTT: 0.0112 SSRC: 0x001d98dc PT: 200(SR) ReportCount: 1 SentNTP: 2087918172.190001 SentRTP: 3880069258 SentPackets: 451 SentOctets: 72160 Report0SourceSSRC: 0x7ccea15c Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 27726 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 806450888 Report0DLSR: 4.0000 [Mar 16 10:44:53] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Timestamp: 1647423893.555357 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.1.224:4023 From: 10.0.66.60:18243 SSRC: 0x47eb1a38 PT: 200(SR) ReportCount: 1 SentNTP: 1647423893.555254 SentRTP: 40000 SentPackets: 250 SentOctets: 40000 Report0SourceSSRC: 0xe9e80fca Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 39081 Report0SequenceNumberCycles: 0 Report0IAJitter: 1 Report0LSR: 1986081587 Report0DLSR: 0.5880 [Mar 16 10:44:53] DEBUG[10829][C-0000000f] app_queue.c: Queue 667 has no realtime members defined. No need for update [Mar 16 10:44:53] DEBUG[10829][C-0000000f] app_queue.c: There is 1 available member. [Mar 16 10:44:53] DEBUG[10829][C-0000000f] app_queue.c: It's our turn (PJSIP/741-0000001b). [Mar 16 10:44:53] DEBUG[10829][C-0000000f] app_queue.c: PJSIP/741-0000001b is trying to call a queue member. [Mar 16 10:44:53] DEBUG[10829][C-0000000f] app_queue.c: (Parallel) Trying 'PJSIP/744' with metric 60000000 [Mar 16 10:44:53] DEBUG[10829][C-0000000f] app_queue.c: Found matching member PJSIP/744 in queue '666' [Mar 16 10:44:53] DEBUG[10829][C-0000000f] app_queue.c: Queue '666' (weight 66, calls 1) is preferred over '667' (weight 65, calls 1) [Mar 16 10:44:53] DEBUG[10829][C-0000000f] app_queue.c: Priority queue delaying call to 667:PJSIP/744 [Mar 16 10:44:53] DEBUG[10829][C-0000000f] app_queue.c: Nobody left to try ringing in queue [Mar 16 10:44:53] DEBUG[10829][C-0000000f] app_queue.c: Everyone is busy at this time [Mar 16 10:44:54] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Timestamp: 1647423894.463517 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 To: 10.0.1.199:4039 From: 10.0.66.60:16727 SSRC: 0x7ccea15c PT: 200(SR) ReportCount: 1 SentNTP: 1647423894.463443 SentRTP: 80000 SentPackets: 500 SentOctets: 80000 Report0SourceSSRC: 0xe15a8d14 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 14258 Report0SequenceNumberCycles: 0 Report0IAJitter: 3 Report0LSR: 2564567203 Report0DLSR: 0.9880 [Mar 16 10:44:54] DEBUG[10828][C-0000000e] app_queue.c: Queue 666 has no realtime members defined. No need for update [Mar 16 10:44:54] DEBUG[10828][C-0000000e] app_queue.c: There is 1 available member. [Mar 16 10:44:54] DEBUG[10828][C-0000000e] app_queue.c: It's our turn (PJSIP/742-0000001a). [Mar 16 10:44:54] DEBUG[10828][C-0000000e] app_queue.c: PJSIP/742-0000001a is trying to call a queue member. [Mar 16 10:44:54] DEBUG[10828][C-0000000e] app_queue.c: Nobody left to try ringing in queue [Mar 16 10:44:54] DEBUG[10828][C-0000000e] app_queue.c: Everyone is busy at this time [Mar 16 10:44:57] DEBUG[10829][C-0000000f] res_rtp_asterisk.c: (0x7faf58175a90) RTCP got report of 64 bytes from 10.0.1.224:4023 [Mar 16 10:44:57] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423897.966594 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.66.60:18243 From: 10.0.1.224:4023 RTT: 0.0112 SSRC: 0x001b7666 PT: 200(SR) ReportCount: 1 SentNTP: 2087778278.200001 SentRTP: 90827721 SentPackets: 471 SentOctets: 75360 Report0SourceSSRC: 0x47eb1a38 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 18650 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 806719013 Report0DLSR: 4.4000 [Mar 16 10:44:58] DEBUG[10828][C-0000000e] res_rtp_asterisk.c: (0x7faf5818a190) RTCP got report of 64 bytes from 10.0.1.199:4039 [Mar 16 10:44:58] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423898.475361 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 To: 10.0.66.60:16727 From: 10.0.1.199:4039 RTT: 0.0118 SSRC: 0x001d98e1 PT: 200(SR) ReportCount: 1 SentNTP: 2087918177.190001 SentRTP: 669132938 SentPackets: 701 SentOctets: 112160 Report0SourceSSRC: 0x7ccea15c Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 27976 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 806778532 Report0DLSR: 4.0000 [Mar 16 10:44:58] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Timestamp: 1647423898.555706 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.1.224:4023 From: 10.0.66.60:18243 SSRC: 0x47eb1a38 PT: 200(SR) ReportCount: 1 SentNTP: 1647423898.555633 SentRTP: 80000 SentPackets: 500 SentOctets: 80000 Report0SourceSSRC: 0xe9e80fca Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 39331 Report0SequenceNumberCycles: 0 Report0IAJitter: 1 Report0LSR: 1986409267 Report0DLSR: 0.5890 [Mar 16 10:44:58] DEBUG[10829][C-0000000f] app_queue.c: Queue 667 has no realtime members defined. No need for update [Mar 16 10:44:58] DEBUG[10829][C-0000000f] app_queue.c: There is 1 available member. [Mar 16 10:44:58] DEBUG[10829][C-0000000f] app_queue.c: It's our turn (PJSIP/741-0000001b). [Mar 16 10:44:58] DEBUG[10829][C-0000000f] app_queue.c: PJSIP/741-0000001b is trying to call a queue member. [Mar 16 10:44:58] DEBUG[10829][C-0000000f] app_queue.c: (Parallel) Trying 'PJSIP/744' with metric 60000000 [Mar 16 10:44:58] DEBUG[10829][C-0000000f] app_queue.c: Found matching member PJSIP/744 in queue '666' [Mar 16 10:44:58] DEBUG[10829][C-0000000f] app_queue.c: Queue '666' (weight 66, calls 1) is preferred over '667' (weight 65, calls 1) [Mar 16 10:44:58] DEBUG[10829][C-0000000f] app_queue.c: Priority queue delaying call to 667:PJSIP/744 [Mar 16 10:44:58] DEBUG[10829][C-0000000f] app_queue.c: Nobody left to try ringing in queue [Mar 16 10:44:58] DEBUG[10829][C-0000000f] app_queue.c: Everyone is busy at this time [Mar 16 10:44:59] DEBUG[10470] res_pjsip_registrar.c: Woke up at 1647423899 Interval: 30 [Mar 16 10:44:59] DEBUG[10470] res_pjsip_registrar.c: Expiring 0 contacts [Mar 16 10:44:59] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Timestamp: 1647423899.463925 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 To: 10.0.1.199:4039 From: 10.0.66.60:16727 SSRC: 0x7ccea15c PT: 200(SR) ReportCount: 1 SentNTP: 1647423899.463825 SentRTP: 120000 SentPackets: 750 SentOctets: 120000 Report0SourceSSRC: 0xe15a8d14 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 14508 Report0SequenceNumberCycles: 0 Report0IAJitter: 1 Report0LSR: 2564894883 Report0DLSR: 0.9880 [Mar 16 10:44:59] DEBUG[10828][C-0000000e] app_queue.c: Queue 666 has no realtime members defined. No need for update [Mar 16 10:44:59] DEBUG[10828][C-0000000e] app_queue.c: There is 1 available member. [Mar 16 10:44:59] DEBUG[10828][C-0000000e] app_queue.c: It's our turn (PJSIP/742-0000001a). [Mar 16 10:44:59] DEBUG[10828][C-0000000e] app_queue.c: PJSIP/742-0000001a is trying to call a queue member. [Mar 16 10:44:59] DEBUG[10828][C-0000000e] app_queue.c: Nobody left to try ringing in queue [Mar 16 10:44:59] DEBUG[10828][C-0000000e] app_queue.c: Everyone is busy at this time [Mar 16 10:45:02] DEBUG[10829][C-0000000f] res_rtp_asterisk.c: (0x7faf58175a90) RTCP got report of 64 bytes from 10.0.1.224:4023 [Mar 16 10:45:02] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423902.966708 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.66.60:18243 From: 10.0.1.224:4023 RTT: 0.0109 SSRC: 0x001b766b PT: 200(SR) ReportCount: 1 SentNTP: 2087778283.200001 SentRTP: 1158016201 SentPackets: 721 SentOctets: 115360 Report0SourceSSRC: 0x47eb1a38 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 18900 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 807046717 Report0DLSR: 4.4000 [Mar 16 10:45:03] DEBUG[10828][C-0000000e] res_rtp_asterisk.c: (0x7faf5818a190) RTCP got report of 64 bytes from 10.0.1.199:4039 [Mar 16 10:45:03] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423903.475363 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 To: 10.0.66.60:16727 From: 10.0.1.199:4039 RTT: 0.0114 SSRC: 0x001d98e6 PT: 200(SR) ReportCount: 1 SentNTP: 2087918182.190001 SentRTP: 1736321418 SentPackets: 951 SentOctets: 152160 Report0SourceSSRC: 0x7ccea15c Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 28226 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 807106237 Report0DLSR: 4.0000 [Mar 16 10:45:03] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Timestamp: 1647423903.555100 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.1.224:4023 From: 10.0.66.60:18243 SSRC: 0x47eb1a38 PT: 200(SR) ReportCount: 1 SentNTP: 1647423903.555016 SentRTP: 120000 SentPackets: 750 SentOctets: 120000 Report0SourceSSRC: 0xe9e80fca Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 39581 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 1986736947 Report0DLSR: 0.5880 [Mar 16 10:45:03] DEBUG[10829][C-0000000f] app_queue.c: Queue 667 has no realtime members defined. No need for update [Mar 16 10:45:03] DEBUG[10829][C-0000000f] app_queue.c: There is 1 available member. [Mar 16 10:45:03] DEBUG[10829][C-0000000f] app_queue.c: It's our turn (PJSIP/741-0000001b). [Mar 16 10:45:03] DEBUG[10829][C-0000000f] app_queue.c: PJSIP/741-0000001b is trying to call a queue member. [Mar 16 10:45:03] DEBUG[10829][C-0000000f] app_queue.c: (Parallel) Trying 'PJSIP/744' with metric 60000000 [Mar 16 10:45:03] DEBUG[10829][C-0000000f] app_queue.c: Found matching member PJSIP/744 in queue '666' [Mar 16 10:45:03] DEBUG[10829][C-0000000f] app_queue.c: Queue '666' (weight 66, calls 1) is preferred over '667' (weight 65, calls 1) [Mar 16 10:45:03] DEBUG[10829][C-0000000f] app_queue.c: Priority queue delaying call to 667:PJSIP/744 [Mar 16 10:45:03] DEBUG[10829][C-0000000f] app_queue.c: Nobody left to try ringing in queue [Mar 16 10:45:03] DEBUG[10829][C-0000000f] app_queue.c: Everyone is busy at this time [Mar 16 10:45:04] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Timestamp: 1647423904.463282 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 To: 10.0.1.199:4039 From: 10.0.66.60:16727 SSRC: 0x7ccea15c PT: 200(SR) ReportCount: 1 SentNTP: 1647423904.463207 SentRTP: 160000 SentPackets: 1000 SentOctets: 160000 Report0SourceSSRC: 0xe15a8d14 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 14758 Report0SequenceNumberCycles: 0 Report0IAJitter: 1 Report0LSR: 2565222563 Report0DLSR: 0.9870 [Mar 16 10:45:04] DEBUG[10828][C-0000000e] app_queue.c: Queue 666 has no realtime members defined. No need for update [Mar 16 10:45:04] DEBUG[10828][C-0000000e] app_queue.c: There is 1 available member. [Mar 16 10:45:04] DEBUG[10828][C-0000000e] app_queue.c: It's our turn (PJSIP/742-0000001a). [Mar 16 10:45:04] DEBUG[10828][C-0000000e] app_queue.c: PJSIP/742-0000001a is trying to call a queue member. [Mar 16 10:45:04] DEBUG[10828][C-0000000e] app_queue.c: Nobody left to try ringing in queue [Mar 16 10:45:04] DEBUG[10828][C-0000000e] app_queue.c: Everyone is busy at this time [Mar 16 10:45:06] DEBUG[10828][C-0000000e] res_rtp_asterisk.c: (0x7faf5818a190) RTCP got report of 72 bytes from 10.0.1.199:4039 [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423906.405060 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 To: 10.0.66.60:16727 From: 10.0.1.199:4039 RTT: 0.0117 SSRC: 0x001d98e9 PT: 200(SR) ReportCount: 1 SentNTP: 2087918185.120000 SentRTP: 4158204298 SentPackets: 1097 SentOctets: 175520 Report0SourceSSRC: 0x7ccea15c Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 28372 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 807433876 Report0DLSR: 1.9300 [Mar 16 10:45:06] DEBUG[10458] netsock2.c: Splitting '10.0.1.199' into... [Mar 16 10:45:06] DEBUG[10458] netsock2.c: ...host '10.0.1.199' and port ''. [Mar 16 10:45:06] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7faef004f158 for Request msg BYE/cseq=28532 (rdata0x7fae840128b8) [Mar 16 10:45:06] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000008e associated with dialog dlg0x7faef004f158 [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a TSX State: Completed Inv State: CONFIRMED [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '742(PJSIP/742-0000001a)' [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7faee8006a98 [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The current transaction state is Completed [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The transaction state change event is TX_MSG [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The current inv state is CONFIRMED [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a TSX State: Completed Inv State: CONFIRMED [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a Event: TSX_STATE Inv State: DISCONNCTD [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '742(PJSIP/742-0000001a)' [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The current inv state is DISCONNCTD [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a: Source of transaction state change is RX_MSG [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a: Received request [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a: Method is BYE [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a TSX State: Completed Inv State: DISCONNCTD [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '742(PJSIP/742-0000001a)' [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7faee8006a98 [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The current transaction state is Completed [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The transaction state change event is RX_MSG [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: The current inv state is DISCONNCTD [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a TSX State: Completed Inv State: DISCONNCTD [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:06] DEBUG[10662] chan_pjsip.c: PJSIP/742-0000001a [Mar 16 10:45:06] DEBUG[10662] chan_pjsip.c: [Mar 16 10:45:06] VERBOSE[10828][C-0000000e] res_musiconhold.c: Stopped music on hold on PJSIP/742-0000001a [Mar 16 10:45:06] DEBUG[10828][C-0000000e] channel.c: Channel PJSIP/742-0000001a setting write format path: g722 -> g722 [Mar 16 10:45:06] DEBUG[10828][C-0000000e] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Timestamp: 1647423906.569045 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Cause: 16 [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: MusicOnHoldStop Privilege: call,all Timestamp: 1647423906.569070 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 [Mar 16 10:45:06] DEBUG[10828][C-0000000e] app_queue.c: Queue '666' Leave, Channel 'PJSIP/742-0000001a' [Mar 16 10:45:06] DEBUG[10828][C-0000000e] pbx.c: Spawn extension (default,666,4) exited non-zero on 'PJSIP/742-0000001a' [Mar 16 10:45:06] VERBOSE[10828][C-0000000e] pbx.c: Spawn extension (default, 666, 4) exited non-zero on 'PJSIP/742-0000001a' [Mar 16 10:45:06] DEBUG[10828][C-0000000e] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/742-0000001a' [Mar 16 10:45:06] DEBUG[10828][C-0000000e] channel.c: Channel 0x7faf581733b0 'PJSIP/742-0000001a' hanging up. Refs: 2 [Mar 16 10:45:06] DEBUG[10497] app_queue.c: Device 'Queue:666' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 16 10:45:06] DEBUG[10828][C-0000000e] chan_pjsip.c: PJSIP/742-0000001a [Mar 16 10:45:06] DEBUG[10828][C-0000000e] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Mar 16 10:45:06] DEBUG[10828][C-0000000e] chan_pjsip.c: Cause: 0 [Mar 16 10:45:06] DEBUG[10662] chan_pjsip.c: PJSIP/742-0000001a [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: PJSIP/742-0000001a Response 0 [Mar 16 10:45:06] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) DTLS srtp - stopped timeout timer' [Mar 16 10:45:06] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) DTLS srtp - stopped timeout timer' [Mar 16 10:45:06] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) DTLS stop [Mar 16 10:45:06] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) DTLS srtp - stopped timeout timer' [Mar 16 10:45:06] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) DTLS srtp - stopped timeout timer' [Mar 16 10:45:06] DEBUG[10662] res_rtp_asterisk.c: (0x7faf5818a190) ICE RTP transport deallocating [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Timestamp: 1647423906.569294 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Variable: ABANDONED Value: TRUE [Mar 16 10:45:06] DEBUG[10662] rtp_engine.c: Destroyed RTP instance '0x7faf5818a190' [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: QueueCallerAbandon Privilege: agent,all Timestamp: 1647423906.569319 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Queue: 666 Position: 1 OriginalPosition: 1 HoldTime: 22 [Mar 16 10:45:06] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1647423906.569329 Device: Queue:666 State: NOT_INUSE [Mar 16 10:45:06] DEBUG[10662] channel.c: Channel 0x7faf581733b0 'PJSIP/742-0000001a' destroying [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: QueueCallerLeave Privilege: agent,all Timestamp: 1647423906.569354 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Queue: 666 Position: 1 Count: 0 [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Timestamp: 1647423906.569367 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Variable: QUEUEPOSITION Value: 1 [Mar 16 10:45:06] DEBUG[10451] cdr.c: Finalized CDR for PJSIP/742-0000001a - start 1647423884.158559 answer 1647423884.159097 end 1647423906.569889 dur 22.411 bill 22.410 dispo ANSWERED [Mar 16 10:45:06] DEBUG[10662] stasis.c: Destroying topic. name: channel:1647423884.43, detail: [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Timestamp: 1647423906.569632 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Cause: 16 [Mar 16 10:45:06] DEBUG[10662] stasis.c: Topic 'channel:1647423884.43': 0x7faf581727b0 destroyed [Mar 16 10:45:06] DEBUG[10662] channel_internal_api.c: : MultistreamFormats: (nothing) [Mar 16 10:45:06] DEBUG[10662] channel_internal_api.c: Channel is being initialized or destroyed [Mar 16 10:45:06] DEBUG[10662] chan_pjsip.c: [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Timestamp: 1647423906.569962 Channel: PJSIP/742-0000001a ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 742 CallerIDName: Test 742 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 666 Priority: 4 Uniqueid: 1647423884.43 Linkedid: 1647423884.43 Cause: 16 Cause-txt: Normal Clearing [Mar 16 10:45:06] DEBUG[10451] stasis.c: Creating topic. name: channel:1647423906.45, detail: [Mar 16 10:45:06] DEBUG[10451] stasis.c: Topic 'channel:1647423906.45': 0x7faf1c00b730 created [Mar 16 10:45:06] DEBUG[10451] stasis.c: Destroying topic. name: channel:1647423906.45, detail: [Mar 16 10:45:06] DEBUG[10451] stasis.c: Topic 'channel:1647423906.45': 0x7faf1c00b730 destroyed [Mar 16 10:45:06] DEBUG[10443] devicestate.c: No provider found, checking channel drivers for PJSIP - 742 [Mar 16 10:45:06] DEBUG[10443] devicestate.c: Changing state for PJSIP/742 - state 1 (Not in use) [Mar 16 10:45:06] DEBUG[10497] app_queue.c: Device 'PJSIP/742' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1647423906.570271 Device: PJSIP/742 State: NOT_INUSE [Mar 16 10:45:06] DEBUG[10679] manager.c: Examining AMI event: Event: ExtensionStatus Privilege: call,all Timestamp: 1647423906.570318 Exten: auto_hint_742 Context: default Hint: PJSIP/742,CustomPresence:742 Status: 0 StatusText: Idle [Mar 16 10:45:07] DEBUG[10829][C-0000000f] res_rtp_asterisk.c: (0x7faf58175a90) RTCP got report of 64 bytes from 10.0.1.224:4023 [Mar 16 10:45:07] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423907.966123 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.66.60:18243 From: 10.0.1.224:4023 RTT: 0.0110 SSRC: 0x001b7670 PT: 200(SR) ReportCount: 1 SentNTP: 2087778288.200001 SentRTP: 2241981641 SentPackets: 971 SentOctets: 155360 Report0SourceSSRC: 0x47eb1a38 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 19150 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 807374357 Report0DLSR: 4.4000 [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Timestamp: 1647423908.555856 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.1.224:4023 From: 10.0.66.60:18243 SSRC: 0x47eb1a38 PT: 200(SR) ReportCount: 1 SentNTP: 1647423908.555731 SentRTP: 160000 SentPackets: 1000 SentOctets: 160000 Report0SourceSSRC: 0xe9e80fca Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 39831 Report0SequenceNumberCycles: 0 Report0IAJitter: 2 Report0LSR: 1987064627 Report0DLSR: 0.5890 [Mar 16 10:45:08] DEBUG[10829][C-0000000f] app_queue.c: Queue 667 has no realtime members defined. No need for update [Mar 16 10:45:08] DEBUG[10829][C-0000000f] app_queue.c: There is 1 available member. [Mar 16 10:45:08] DEBUG[10829][C-0000000f] app_queue.c: It's our turn (PJSIP/741-0000001b). [Mar 16 10:45:08] DEBUG[10829][C-0000000f] app_queue.c: PJSIP/741-0000001b is trying to call a queue member. [Mar 16 10:45:08] DEBUG[10829][C-0000000f] app_queue.c: (Parallel) Trying 'PJSIP/744' with metric 60000000 [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: 744 Topology: <0:audio-0:audio:sendrecv (g722)> [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: 744 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: 744 (null) Topology: <0:audio-0:audio:sendrecv (g722)> [Mar 16 10:45:08] DEBUG[10662] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Mar 16 10:45:08] DEBUG[10662] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Mar 16 10:45:08] DEBUG[10662] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Mar 16 10:45:08] DEBUG[10662] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0) [Mar 16 10:45:08] DEBUG[10662] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: 744 [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: Direct media no glare mitigation [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session/pjsip_session_caps.c: '744' Caps for outgoing audio call with pref 'remote_merge' - remote: (g722) local: (g722|alaw|ulaw|gsm) joint: (g722|alaw|ulaw|gsm) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: 744 [Mar 16 10:45:08] DEBUG[10829][C-0000000f] channel_internal_api.c: : Formats: (none) [Mar 16 10:45:08] DEBUG[10829][C-0000000f] channel_internal_api.c: Channel is being initialized or destroyed [Mar 16 10:45:08] DEBUG[10829][C-0000000f] stasis.c: Creating topic. name: channel:1647423908.46, detail: [Mar 16 10:45:08] DEBUG[10829][C-0000000f] stasis.c: Topic 'channel:1647423908.46': 0x7faef00d68f0 created [Mar 16 10:45:08] DEBUG[10829][C-0000000f] channel.c: Channel 0x7faef0003520 'PJSIP/744-0000001c' allocated [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: Topology: <0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm)> Formats: (g722|alaw|ulaw|gsm) [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: Compatible? yes [Mar 16 10:45:08] DEBUG[10829][C-0000000f] channel_internal_api.c: PJSIP/744-0000001c: MultistreamFormats: (g722|alaw|ulaw|gsm) [Mar 16 10:45:08] DEBUG[10829][C-0000000f] channel_internal_api.c: Set native formats but not topology [Mar 16 10:45:08] DEBUG[10829][C-0000000f] channel_internal_api.c: PJSIP/744-0000001c: <0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm)> [Mar 16 10:45:08] DEBUG[10829][C-0000000f] channel_internal_api.c: Used provided topology [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Timestamp: 1647423908.560273 Channel: PJSIP/744-0000001c ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: testagent ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1647423908.46 Linkedid: 1647423888.44 [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: Channel: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Timestamp: 1647423908.560406 Channel: PJSIP/744-0000001c ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 667 CallerIDName: testagent ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1647423908.46 Linkedid: 1647423888.44 Extension: s Application: AppQueue AppData: (Outgoing Line) [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Timestamp: 1647423908.560440 Channel: PJSIP/744-0000001c ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 667 CallerIDName: testagent ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1647423908.46 Linkedid: 1647423888.44 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/744-0000001c Topology: <0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm)> [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: 'call' task pushed [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Timestamp: 1647423908.560488 Channel: PJSIP/744-0000001c ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 667 CallerIDName: testagent ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1647423908.46 Linkedid: 1647423888.44 Variable: DIALEDPEERNUMBER Value: 744 [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c Topology: <0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm)> [Mar 16 10:45:08] VERBOSE[10829][C-0000000f] app_queue.c: Called PJSIP/744 [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: AgentCalled Privilege: agent,all Timestamp: 1647423908.560609 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 DestChannel: PJSIP/744-0000001c DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 667 DestCallerIDName: testagent DestConnectedLineNum: 741 DestConnectedLineName: Test 741 DestLanguage: de DestAccountCode: DestContext: default DestExten: 667 DestPriority: 1 DestUniqueid: 1647423908.46 DestLinkedid: 1647423888.44 Queue: 667 Interface: PJSIP/744 MemberName: testagent [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all Timestamp: 1647423908.560657 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 DestChannel: PJSIP/744-0000001c DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 667 DestCallerIDName: testagent DestConnectedLineNum: DestConnectedLineName: DestLanguage: de DestAccountCode: DestContext: default DestExten: s DestPriority: 1 DestUniqueid: 1647423908.46 DestLinkedid: 1647423888.44 DialString: PJSIP/744 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Processing streams [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Processing stream 0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c Adding position 0 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Creating new media session [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Setting media session as default for audio [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Done [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c Stream: 0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_sdp_rtp.c: PJSIP/744-0000001c Type: audio 0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm) [Mar 16 10:45:08] DEBUG[10662] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7faf58175e50' [Mar 16 10:45:08] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) RTP allocated port 10642 [Mar 16 10:45:08] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) ICE creating session [::]:10642 (10642) [Mar 16 10:45:08] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) ICE create [Mar 16 10:45:08] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) ICE add system candidates [Mar 16 10:45:08] DEBUG[10662] netsock2.c: Splitting '10.0.66.60' into... [Mar 16 10:45:08] DEBUG[10662] netsock2.c: ...host '10.0.66.60' and port ''. [Mar 16 10:45:08] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) ICE add candidate: 10.0.66.60:10642, 2130706431 [Mar 16 10:45:08] DEBUG[10662] netsock2.c: Splitting 'fe80::685c:eaff:fe0d:4830' into... [Mar 16 10:45:08] DEBUG[10662] netsock2.c: ...host 'fe80::685c:eaff:fe0d:4830' and port ''. [Mar 16 10:45:08] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) ICE add candidate: [fe80::685c:eaff:fe0d:4830]:10642, 2130706431 [Mar 16 10:45:08] DEBUG[10662] rtp_engine.c: RTP instance '0x7faf58175e50' is setup and ready to go [Mar 16 10:45:08] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) ICE stopped [Mar 16 10:45:08] DEBUG[10662] netsock2.c: Splitting 'asterisk' into... [Mar 16 10:45:08] DEBUG[10662] netsock2.c: ...host 'asterisk' and port ''. [Mar 16 10:45:08] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) RTCP setup on RTP instance [Mar 16 10:45:08] DEBUG[10662] res_pjsip_sdp_rtp.c: RC: 1 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Handled [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Stream 0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm) added [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Done with 0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Adding bundle groups (if available) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Copying connection details [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Processing media 0 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Media 0 reset [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Method is INVITE [Mar 16 10:45:08] VERBOSE[10829][C-0000000f] app_queue.c: PJSIP/744-0000001c connected line has changed. Saving it until answer for PJSIP/741-0000001b [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.0.1.243' [Mar 16 10:45:08] DEBUG[10662] res_pjsip/pjsip_resolver.c: Transport type for target '10.0.1.243' is 'UDP transport' [Mar 16 10:45:08] DEBUG[10662] res_pjsip/pjsip_resolver.c: Target '10.0.1.243' is an IP address, skipping resolution [Mar 16 10:45:08] DEBUG[10662] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.0.66.60:5060 (this may be re-written again later) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c Event: TSX_STATE Inv State: CALLING [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '744(PJSIP/744-0000001c)' [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef0035b58) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The current inv state is CALLING [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Source of transaction state change is TX_MSG [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c TSX State: Calling Inv State: CALLING [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '744(PJSIP/744-0000001c)' [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef0035b58) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7faef0035b58 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The current transaction state is Calling [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The transaction state change event is TX_MSG [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The current inv state is CALLING [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c TSX State: Calling Inv State: CALLING [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Topology: Pending: <0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm)> Active: (null topology) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: RC: 0 [Mar 16 10:45:08] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7faef4091a88 for Response msg 100/INVITE/cseq=14059 (rdata0x7fae840128b8) [Mar 16 10:45:08] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/744-00000205 associated with dialog dlg0x7faef4091a88 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c Method: INVITE Status: 100 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c TSX State: Proceeding Inv State: CALLING [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '744(PJSIP/744-0000001c)' [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef0035b58) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7faef0035b58 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The current transaction state is Proceeding [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The transaction state change event is RX_MSG [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The current inv state is CALLING [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Response is 100 Trying [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c: Status: 100 [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c: Not queueing anything [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c: Status: 100 [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/741-0000001b: Indicated Private Cause Code [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c TSX State: Proceeding Inv State: CALLING [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Topology: Pending: <0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm)> Active: (null topology) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:08] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7faef4091a88 for Response msg 180/INVITE/cseq=14059 (rdata0x7fae840128b8) [Mar 16 10:45:08] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/744-00000205 associated with dialog dlg0x7faef4091a88 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c Method: INVITE Status: 180 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c Event: TSX_STATE Inv State: EARLY [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '744(PJSIP/744-0000001c)' [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef0035b58) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The current inv state is EARLY [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Source of transaction state change is RX_MSG [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Received response [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Response is 180 ringing [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c: Status: 180 [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c TSX State: Proceeding Inv State: EARLY [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '744(PJSIP/744-0000001c)' [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef0035b58) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7faef0035b58 [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The current transaction state is Proceeding [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The transaction state change event is RX_MSG [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: The current inv state is EARLY [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Response is 180 ringing [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c: Status: 180 [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c: Queueing RINGING [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c: Status: 180 [Mar 16 10:45:08] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c TSX State: Proceeding Inv State: EARLY [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: Topology: Pending: <0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm)> Active: (null topology) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Timestamp: 1647423908.622058 Channel: PJSIP/744-0000001c ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 667 CallerIDName: testagent ConnectedLineNum: 741 ConnectedLineName: Test 741 Language: de AccountCode: Context: default Exten: 667 Priority: 1 Uniqueid: 1647423908.46 Linkedid: 1647423888.44 [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/741-0000001b: Indicated Private Cause Code [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:45:08] DEBUG[10443] devicestate.c: No provider found, checking channel drivers for PJSIP - 744 [Mar 16 10:45:08] VERBOSE[10829][C-0000000f] app_queue.c: PJSIP/744-0000001c is ringing [Mar 16 10:45:08] DEBUG[10443] devicestate.c: Changing state for PJSIP/744 - state 6 (Ringing) [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Timestamp: 1647423908.622076 Channel: PJSIP/744-0000001c ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 667 CallerIDName: testagent ConnectedLineNum: 741 ConnectedLineName: Test 741 Language: de AccountCode: Context: default Exten: 667 Priority: 1 Uniqueid: 1647423908.46 Linkedid: 1647423888.44 Extension: 667 Application: AppQueue AppData: (Outgoing Line) [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/741-0000001b: Indicated Private Cause Code [Mar 16 10:45:08] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Timestamp: 1647423908.622084 Channel: PJSIP/744-0000001c ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 667 CallerIDName: testagent ConnectedLineNum: 741 ConnectedLineName: Test 741 Language: de AccountCode: Context: default Exten: 667 Priority: 1 Uniqueid: 1647423908.46 Linkedid: 1647423888.44 [Mar 16 10:45:08] DEBUG[10497] app_queue.c: Removed testagent from pending_members [Mar 16 10:45:08] DEBUG[10497] app_queue.c: Removed testagent from pending_members [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: DialState Privilege: call,all Timestamp: 1647423908.622323 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 DestChannel: PJSIP/744-0000001c DestChannelState: 5 DestChannelStateDesc: Ringing DestCallerIDNum: 667 DestCallerIDName: testagent DestConnectedLineNum: 741 DestConnectedLineName: Test 741 DestLanguage: de DestAccountCode: DestContext: default DestExten: 667 DestPriority: 1 DestUniqueid: 1647423908.46 DestLinkedid: 1647423888.44 DialStatus: RINGING [Mar 16 10:45:08] DEBUG[10497] app_queue.c: Device 'PJSIP/744' changed to state '6' (Ringing) [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: ExtensionStatus Privilege: call,all Timestamp: 1647423908.622336 Exten: auto_hint_744 Context: default Hint: PJSIP/744,CustomPresence:744 Status: 8 StatusText: Ringing [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1647423908.622343 Device: PJSIP/744 State: RINGING [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Timestamp: 1647423908.622360 Queue: 667 MemberName: testagent Interface: PJSIP/744 StateInterface: PJSIP/744 Membership: static Penalty: 60 CallsTaken: 0 LastCall: 0 LastPause: 0 LoginTime: 1647423586 InCall: 0 Status: 6 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [Mar 16 10:45:08] DEBUG[10662] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.0.66.234' [Mar 16 10:45:08] DEBUG[10662] res_pjsip/pjsip_resolver.c: Transport type for target '10.0.66.234' is 'UDP transport' [Mar 16 10:45:08] DEBUG[10662] res_pjsip/pjsip_resolver.c: Target '10.0.66.234' is an IP address, skipping resolution [Mar 16 10:45:08] DEBUG[10679] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Timestamp: 1647423908.622468 Queue: 666 MemberName: testagent Interface: PJSIP/744 StateInterface: PJSIP/744 Membership: static Penalty: 60 CallsTaken: 0 LastCall: 0 LastPause: 0 LoginTime: 1647423586 InCall: 0 Status: 6 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [Mar 16 10:45:08] DEBUG[10662] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.0.66.60:5060 (this may be re-written again later) [Mar 16 10:45:08] DEBUG[10662] res_pjsip_pubsub.c: evsub 0x7fae70003a98 state ACTIVE event USER sub_tree 0x7fae70001130 sub_tree state Normal [Mar 16 10:45:08] DEBUG[10662] res_pjsip_pubsub.c: Updating persistence for '301->auto_hint_744' prune on boot: no [Mar 16 10:45:08] DEBUG[10662] sorcery.c: Skipping field 'generator_data' for object type 'subscription_persistence' [Mar 16 10:45:08] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fae70001258 for Response msg 200/NOTIFY/cseq=16690 (rdata0x7fae840128b8) [Mar 16 10:45:08] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000095 associated with dialog dlg0x7fae70001258 [Mar 16 10:45:12] DEBUG[10829][C-0000000f] res_rtp_asterisk.c: (0x7faf58175a90) RTCP got report of 64 bytes from 10.0.1.224:4023 [Mar 16 10:45:12] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423912.966375 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.66.60:18243 From: 10.0.1.224:4023 RTT: 0.0105 SSRC: 0x001b7675 PT: 200(SR) ReportCount: 1 SentNTP: 2087778293.200001 SentRTP: 3309170121 SentPackets: 1221 SentOctets: 195360 Report0SourceSSRC: 0x47eb1a38 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 19400 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 807702084 Report0DLSR: 4.4000 [Mar 16 10:45:13] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Timestamp: 1647423913.556098 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.1.224:4023 From: 10.0.66.60:18243 SSRC: 0x47eb1a38 PT: 200(SR) ReportCount: 1 SentNTP: 1647423913.555917 SentRTP: 200000 SentPackets: 1250 SentOctets: 200000 Report0SourceSSRC: 0xe9e80fca Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 40081 Report0SequenceNumberCycles: 0 Report0IAJitter: 1 Report0LSR: 1987392307 Report0DLSR: 0.5890 [Mar 16 10:45:15] DEBUG[10813] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 16 10:45:15] DEBUG[10814] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 16 10:45:15] DEBUG[10432] threadpool.c: Destroying worker thread 142 [Mar 16 10:45:15] DEBUG[10432] threadpool.c: Destroying worker thread 143 [Mar 16 10:45:16] DEBUG[10812] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 16 10:45:16] DEBUG[10432] threadpool.c: Destroying worker thread 141 [Mar 16 10:45:16] DEBUG[10802] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 16 10:45:16] DEBUG[10456] threadpool.c: Destroying worker thread 137 [Mar 16 10:45:16] DEBUG[10799] threadpool.c: Worker thread idle timeout reached. Dying. [Mar 16 10:45:16] DEBUG[10432] threadpool.c: Destroying worker thread 135 [Mar 16 10:45:17] DEBUG[10829][C-0000000f] res_rtp_asterisk.c: (0x7faf58175a90) RTCP got report of 64 bytes from 10.0.1.224:4023 [Mar 16 10:45:17] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423917.967065 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.66.60:18243 From: 10.0.1.224:4023 RTT: 0.0110 SSRC: 0x001b767a PT: 200(SR) ReportCount: 1 SentNTP: 2087778298.200001 SentRTP: 98233801 SentPackets: 1471 SentOctets: 235360 Report0SourceSSRC: 0x47eb1a38 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 19650 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 808029776 Report0DLSR: 4.4000 [Mar 16 10:45:18] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Timestamp: 1647423918.555279 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.1.224:4023 From: 10.0.66.60:18243 SSRC: 0x47eb1a38 PT: 200(SR) ReportCount: 1 SentNTP: 1647423918.555152 SentRTP: 240000 SentPackets: 1500 SentOctets: 240000 Report0SourceSSRC: 0xe9e80fca Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 40331 Report0SequenceNumberCycles: 0 Report0IAJitter: 9 Report0LSR: 1987719987 Report0DLSR: 0.5880 [Mar 16 10:45:19] DEBUG[10829][C-0000000f] res_rtp_asterisk.c: (0x7faf58175a90) RTCP got report of 72 bytes from 10.0.1.224:4023 [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1647423919.546542 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 To: 10.0.66.60:18243 From: 10.0.1.224:4023 RTT: 0.0113 SSRC: 0x001b767b PT: 200(SR) ReportCount: 1 SentNTP: 2087778299.780005 SentRTP: 1695280841 SentPackets: 1550 SentOctets: 248000 Report0SourceSSRC: 0x47eb1a38 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 19729 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 808357406 Report0DLSR: 0.9800 [Mar 16 10:45:19] DEBUG[10458] netsock2.c: Splitting '10.0.1.224' into... [Mar 16 10:45:19] DEBUG[10458] netsock2.c: ...host '10.0.1.224' and port ''. [Mar 16 10:45:19] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7faef401b5d8 for Request msg BYE/cseq=7425 (rdata0x7fae840128b8) [Mar 16 10:45:19] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000092 associated with dialog dlg0x7faef401b5d8 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b TSX State: Completed Inv State: CONFIRMED [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '741(PJSIP/741-0000001b)' [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7faef011c3c8 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The current transaction state is Completed [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The transaction state change event is TX_MSG [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The current inv state is CONFIRMED [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b TSX State: Completed Inv State: CONFIRMED [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b Event: TSX_STATE Inv State: DISCONNCTD [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '741(PJSIP/741-0000001b)' [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The current inv state is DISCONNCTD [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b: Source of transaction state change is RX_MSG [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b: Received request [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b: Method is BYE [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b TSX State: Completed Inv State: DISCONNCTD [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '741(PJSIP/741-0000001b)' [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7faef011c3c8 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The current transaction state is Completed [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The transaction state change event is RX_MSG [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The current inv state is DISCONNCTD [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b TSX State: Completed Inv State: DISCONNCTD [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|alaw|ulaw)> [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10662] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:45:19] DEBUG[10662] chan_pjsip.c: [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Timestamp: 1647423919.712903 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Cause: 16 [Mar 16 10:45:19] VERBOSE[10829][C-0000000f] res_musiconhold.c: Stopped music on hold on PJSIP/741-0000001b [Mar 16 10:45:19] DEBUG[10829][C-0000000f] channel.c: Channel PJSIP/741-0000001b setting write format path: g722 -> g722 [Mar 16 10:45:19] DEBUG[10829][C-0000000f] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: MusicOnHoldStop Privilege: call,all Timestamp: 1647423919.713027 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 [Mar 16 10:45:19] DEBUG[10451] cdr.c: Finalized CDR for PJSIP/741-0000001b - start 1647423888.397778 answer 1647423888.398259 end 1647423919.713029 dur 31.315 bill 31.314 dispo NO ANSWER [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all Timestamp: 1647423919.713100 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 DestChannel: PJSIP/744-0000001c DestChannelState: 5 DestChannelStateDesc: Ringing DestCallerIDNum: 667 DestCallerIDName: testagent DestConnectedLineNum: 741 DestConnectedLineName: Test 741 DestLanguage: de DestAccountCode: DestContext: default DestExten: 667 DestPriority: 1 DestUniqueid: 1647423908.46 DestLinkedid: 1647423888.44 DialStatus: CANCEL [Mar 16 10:45:19] DEBUG[10829][C-0000000f] app_queue.c: PJSIP/741-0000001b: Nobody answered. [Mar 16 10:45:19] DEBUG[10829][C-0000000f] channel.c: Channel 0x7faef0003520 'PJSIP/744-0000001c' hanging up. Refs: 2 [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all Timestamp: 1647423919.713259 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 DestChannel: PJSIP/744-0000001c DestChannelState: 5 DestChannelStateDesc: Ringing DestCallerIDNum: 667 DestCallerIDName: testagent DestConnectedLineNum: 741 DestConnectedLineName: Test 741 DestLanguage: de DestAccountCode: DestContext: default DestExten: 667 DestPriority: 1 DestUniqueid: 1647423908.46 DestLinkedid: 1647423888.44 DialStatus: CANCEL [Mar 16 10:45:19] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/744-0000001c [Mar 16 10:45:19] DEBUG[10829][C-0000000f] chan_pjsip.c: AST hangup cause 0 (no match found in PJSIP) [Mar 16 10:45:19] DEBUG[10829][C-0000000f] chan_pjsip.c: Cause: 0 [Mar 16 10:45:19] DEBUG[10662] chan_pjsip.c: PJSIP/744-0000001c [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c Response 0 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c: Method is CANCEL [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Timestamp: 1647423919.713444 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Variable: ABANDONED Value: TRUE [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: QueueCallerAbandon Privilege: agent,all Timestamp: 1647423919.713499 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Queue: 667 Position: 1 OriginalPosition: 1 HoldTime: 31 [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1647423919.713597 Device: Queue:667 State: NOT_INUSE [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c TSX State: Calling Inv State: EARLY [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '744(PJSIP/744-0000001c)' [Mar 16 10:45:19] DEBUG[10829][C-0000000f] app_queue.c: Queue '667' Leave, Channel 'PJSIP/741-0000001b' [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef0035b58) [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x7faef000b8c8 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The current transaction state is Calling [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The transaction state change event is TX_MSG [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The current inv state is EARLY [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Nothing delayed [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/744-0000001c TSX State: Calling Inv State: EARLY [Mar 16 10:45:19] DEBUG[10829][C-0000000f] pbx.c: Spawn extension (default,667,2) exited non-zero on 'PJSIP/741-0000001b' [Mar 16 10:45:19] VERBOSE[10829][C-0000000f] pbx.c: Spawn extension (default, 667, 2) exited non-zero on 'PJSIP/741-0000001b' [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm)> [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10829][C-0000000f] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/741-0000001b' [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10662] channel.c: Channel 0x7faef0003520 'PJSIP/744-0000001c' destroying [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: QueueCallerLeave Privilege: agent,all Timestamp: 1647423919.713709 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Queue: 667 Position: 1 Count: 0 [Mar 16 10:45:19] DEBUG[10829][C-0000000f] channel.c: Channel 0x7faf5803c0c0 'PJSIP/741-0000001b' hanging up. Refs: 2 [Mar 16 10:45:19] DEBUG[10662] stasis.c: Destroying topic. name: channel:1647423908.46, detail: [Mar 16 10:45:19] DEBUG[10662] stasis.c: Topic 'channel:1647423908.46': 0x7faef00d68f0 destroyed [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Timestamp: 1647423919.713752 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Variable: QUEUEPOSITION Value: 1 [Mar 16 10:45:19] DEBUG[10829][C-0000000f] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:45:19] DEBUG[10829][C-0000000f] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Mar 16 10:45:19] DEBUG[10451] cdr.c: Finalized CDR for PJSIP/744-0000001c - start 1647423908.560158 answer 0.000000 end 1647423919.713761 dur 11.153 bill 1647423919.713 dispo FAILED [Mar 16 10:45:19] DEBUG[10662] channel_internal_api.c: : MultistreamFormats: (nothing) [Mar 16 10:45:19] DEBUG[10451] cdr.c: CDR for PJSIP/744-0000001c is dialed and has no Party B; discarding [Mar 16 10:45:19] DEBUG[10662] channel_internal_api.c: Channel is being initialized or destroyed [Mar 16 10:45:19] DEBUG[10662] chan_pjsip.c: [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Timestamp: 1647423919.713781 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Cause: 16 [Mar 16 10:45:19] DEBUG[10829][C-0000000f] chan_pjsip.c: Cause: 0 [Mar 16 10:45:19] DEBUG[10443] devicestate.c: No provider found, checking channel drivers for PJSIP - 744 [Mar 16 10:45:19] DEBUG[10662] chan_pjsip.c: PJSIP/741-0000001b [Mar 16 10:45:19] DEBUG[10443] devicestate.c: Changing state for PJSIP/744 - state 1 (Not in use) [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: PJSIP/741-0000001b Response 0 [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Timestamp: 1647423919.713806 Channel: PJSIP/744-0000001c ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 667 CallerIDName: testagent ConnectedLineNum: 741 ConnectedLineName: Test 741 Language: de AccountCode: Context: default Exten: 667 Priority: 1 Uniqueid: 1647423908.46 Linkedid: 1647423888.44 Cause: 0 Cause-txt: Unknown [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) DTLS srtp - stopped timeout timer' [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) DTLS srtp - stopped timeout timer' [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) DTLS stop [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) DTLS srtp - stopped timeout timer' [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) DTLS srtp - stopped timeout timer' [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175a90) ICE RTP transport deallocating [Mar 16 10:45:19] DEBUG[10662] rtp_engine.c: Destroyed RTP instance '0x7faf58175a90' [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10662] channel.c: Channel 0x7faf5803c0c0 'PJSIP/741-0000001b' destroying [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: ExtensionStatus Privilege: call,all Timestamp: 1647423919.714079 Exten: auto_hint_744 Context: default Hint: PJSIP/744,CustomPresence:744 Status: 0 StatusText: Idle [Mar 16 10:45:19] DEBUG[10451] stasis.c: Creating topic. name: channel:1647423919.47, detail: [Mar 16 10:45:19] DEBUG[10451] stasis.c: Topic 'channel:1647423919.47': 0x7faf1c00aa60 created [Mar 16 10:45:19] DEBUG[10451] stasis.c: Destroying topic. name: channel:1647423919.47, detail: [Mar 16 10:45:19] DEBUG[10451] stasis.c: Topic 'channel:1647423919.47': 0x7faf1c00aa60 destroyed [Mar 16 10:45:19] DEBUG[10662] stasis.c: Destroying topic. name: channel:1647423888.44, detail: [Mar 16 10:45:19] DEBUG[10662] stasis.c: Topic 'channel:1647423888.44': 0x7faf58189b50 destroyed [Mar 16 10:45:19] DEBUG[10662] channel_internal_api.c: : MultistreamFormats: (nothing) [Mar 16 10:45:19] DEBUG[10801] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.0.66.234' [Mar 16 10:45:19] DEBUG[10662] channel_internal_api.c: Channel is being initialized or destroyed [Mar 16 10:45:19] DEBUG[10801] res_pjsip/pjsip_resolver.c: Transport type for target '10.0.66.234' is 'UDP transport' [Mar 16 10:45:19] DEBUG[10662] chan_pjsip.c: [Mar 16 10:45:19] DEBUG[10801] res_pjsip/pjsip_resolver.c: Target '10.0.66.234' is an IP address, skipping resolution [Mar 16 10:45:19] DEBUG[10443] devicestate.c: No provider found, checking channel drivers for PJSIP - 741 [Mar 16 10:45:19] DEBUG[10801] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.0.66.60:5060 (this may be re-written again later) [Mar 16 10:45:19] DEBUG[10443] devicestate.c: Changing state for PJSIP/741 - state 1 (Not in use) [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1647423919.714363 Device: PJSIP/744 State: NOT_INUSE [Mar 16 10:45:19] DEBUG[10497] app_queue.c: Device 'Queue:667' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Timestamp: 1647423919.714390 Channel: PJSIP/741-0000001b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 741 CallerIDName: Test 741 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: default Exten: 667 Priority: 2 Uniqueid: 1647423888.44 Linkedid: 1647423888.44 Cause: 16 Cause-txt: Normal Clearing [Mar 16 10:45:19] DEBUG[10801] res_pjsip_pubsub.c: evsub 0x7fae70003a98 state ACTIVE event USER sub_tree 0x7fae70001130 sub_tree state Normal [Mar 16 10:45:19] DEBUG[10497] app_queue.c: Removed testagent from pending_members [Mar 16 10:45:19] DEBUG[10801] res_pjsip_pubsub.c: Updating persistence for '301->auto_hint_744' prune on boot: no [Mar 16 10:45:19] DEBUG[10497] app_queue.c: Removed testagent from pending_members [Mar 16 10:45:19] DEBUG[10497] app_queue.c: Device 'PJSIP/744' changed to state '1' (Not in use) [Mar 16 10:45:19] DEBUG[10497] app_queue.c: Device 'PJSIP/741' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 16 10:45:19] DEBUG[10801] sorcery.c: Skipping field 'generator_data' for object type 'subscription_persistence' [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1647423919.714607 Device: PJSIP/741 State: NOT_INUSE [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Timestamp: 1647423919.714648 Queue: 667 MemberName: testagent Interface: PJSIP/744 StateInterface: PJSIP/744 Membership: static Penalty: 60 CallsTaken: 0 LastCall: 0 LastPause: 0 LoginTime: 1647423586 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Timestamp: 1647423919.714666 Queue: 666 MemberName: testagent Interface: PJSIP/744 StateInterface: PJSIP/744 Membership: static Penalty: 60 CallsTaken: 0 LastCall: 0 LastPause: 0 LoginTime: 1647423586 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [Mar 16 10:45:19] DEBUG[10679] manager.c: Examining AMI event: Event: ExtensionStatus Privilege: call,all Timestamp: 1647423919.714726 Exten: auto_hint_741 Context: default Hint: PJSIP/741,CustomPresence:741 Status: 0 StatusText: Idle [Mar 16 10:45:19] DEBUG[10801] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.0.66.234' [Mar 16 10:45:19] DEBUG[10801] res_pjsip/pjsip_resolver.c: Transport type for target '10.0.66.234' is 'UDP transport' [Mar 16 10:45:19] DEBUG[10801] res_pjsip/pjsip_resolver.c: Target '10.0.66.234' is an IP address, skipping resolution [Mar 16 10:45:19] DEBUG[10801] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.0.66.60:5060 (this may be re-written again later) [Mar 16 10:45:19] DEBUG[10801] res_pjsip_pubsub.c: evsub 0x7faef40c6be8 state ACTIVE event USER sub_tree 0x7faef40c4cb0 sub_tree state Normal [Mar 16 10:45:19] DEBUG[10801] res_pjsip_pubsub.c: Updating persistence for '301->auto_hint_741' prune on boot: no [Mar 16 10:45:19] DEBUG[10801] sorcery.c: Skipping field 'generator_data' for object type 'subscription_persistence' [Mar 16 10:45:19] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fae70001258 for Response msg 200/NOTIFY/cseq=16691 (rdata0x7fae840128b8) [Mar 16 10:45:19] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000095 associated with dialog dlg0x7fae70001258 [Mar 16 10:45:19] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7faef4091a88 for Response msg 200/CANCEL/cseq=14059 (rdata0x7fae840128b8) [Mar 16 10:45:19] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/744-00000205 associated with dialog dlg0x7faef4091a88 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: 744 Method: CANCEL Status: 200 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: 744 TSX State: Completed Inv State: EARLY [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (g722|alaw|ulaw|gsm)> [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7faef4091a88 for Response msg 487/INVITE/cseq=14059 (rdata0x7fae840128b8) [Mar 16 10:45:19] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/744-00000205 associated with dialog dlg0x7faef4091a88 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: 744 Method: INVITE Status: 487 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: 744 Event: TSX_STATE Inv State: DISCONNCTD [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '744()' [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef0035b58) [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: There is no transaction involved in this state change [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The current inv state is DISCONNCTD [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: 744: Source of transaction state change is RX_MSG [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: 744: Received response [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: 744: Response is 487 Request Terminated [Mar 16 10:45:19] DEBUG[10662] chan_pjsip.c: 744: Status: 487 [Mar 16 10:45:19] DEBUG[10662] chan_pjsip.c: 744: No channel [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: 744 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: 744 TSX State: Completed Inv State: DISCONNCTD [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The state change pertains to the endpoint '744()' [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The inv session still has an invite_tsx (0x7faef0035b58) [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7faef0035b58 [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The current transaction state is Completed [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The transaction state change event is RX_MSG [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: The current inv state is DISCONNCTD [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: Disconnected [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: (null session) TSX State: Completed Inv State: DISCONNCTD [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: [Mar 16 10:45:19] DEBUG[10662] chan_pjsip.c: 744 [Mar 16 10:45:19] DEBUG[10662] chan_pjsip.c: No channel [Mar 16 10:45:19] DEBUG[10662] res_pjsip_session.c: 744: Destroying SIP session [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) DTLS srtp - stopped timeout timer' [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) DTLS srtp - stopped timeout timer' [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) DTLS stop [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) DTLS srtp - stopped timeout timer' [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) DTLS srtp - stopped timeout timer' [Mar 16 10:45:19] DEBUG[10662] res_rtp_asterisk.c: (0x7faf58175e50) ICE RTP transport deallocating [Mar 16 10:45:19] DEBUG[10662] rtp_engine.c: Destroyed RTP instance '0x7faf58175e50' [Mar 16 10:45:19] DEBUG[10458] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7faef40c4dd8 for Response msg 200/NOTIFY/cseq=27372 (rdata0x7fae840128b8) [Mar 16 10:45:19] DEBUG[10458] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000090 associated with dialog dlg0x7faef40c4dd8 [Mar 16 10:45:25] VERBOSE[10830] res_pjsip_endpoint_identifier_dpma.c: Updating DPMA user '301' uri='pjsip:10.0.66.234:5060;transport=' ua='Digium D60 2_9_18'