I have a fresh installation of Asterisk 18, IAXmodem 1.3.2, HylaFAX 6.0.6, running on Ubuntu 20.04 and connected to a SIP provider.
The goal is to have a single phone number that will act as both a voicemail-to-email and a fax-to-email server (the current mailbox provider that I’ve used for over 20 years has suddenly removed support for voicemail, so I need an integrated solution for both).
I have set everything up with the above software so that the voicemail works on its own and the fax works on its own. It took a bit of time to ensure that the alaw codecs are aligned (e.g. alaw module is not loaded by default and all I was getting was a cryptic 488 error) and then to figure out how the extensions work properly (the O’Reilly book was invaluable!), but it has been a fun little project and learning experience.
However, when I try to have fax vs voicemail switching on a single extension, I hit the wall. Based on everything I’ve read on this and other forums, this is meant to be supported out of the box, but I can’t find a howto that shows how this is done exactly (well, I can find some very old tutorials for the old sip library, but not pjsip).
PJSIP has fax_detect option (for CNG tone), but I can’t find any documentation on how to use this option in practice.
Could anyone please help me on how to get this configured correctly in pjsip.conf and extensions.conf? If the limitation is with IAXmodem/HylaFAX and I need to use a different package there, I don’t have a problem with switching (no pun intended).
These are my configuration files - as far as I could get things to work (“xxxx” used to mark sensitive info):
pjsip.conf
[vcontrol]
type=endpoint
transport=transport-udp
context=inbound-calls
disallow=all
outbound_auth=vcontrol
aors=vcontrol
use_avpf=no
allow = !all,alaw
;[endpoint]
;fax_detect=yes
;fax_detect_timeout=5
[vcontrol]
type=registration
transport=transport-udp
outbound_auth=vcontrol
client_uri=sip:xxxx@sip.vcontrol.com.au:5060
server_uri=sip:sip.vcontrol.com.au:5060
[vcontrol]
type=auth
auth_type=userpass
username=xxxx
password=xxxx
[vcontrol]
type=aor
contact=sip:xxxx@sip.vcontrol.com.au
[vcontrol]
type=identify
endpoint=vcontrol
;match=sip.vcontrol.com.au
match=27.131.112.116
[transport-udp]
type=transport
protocol=udp
bind=0.0.0.0
extensions.conf
[inbound-calls]
exten => s,1,Answer()
same => n,NoOp(${CALLERID(num)})
same => n,NoOp(${CONTEXT})
same => n,WaitExten(10)
exten => fax,1,NoOp(“Fax”)
same => n,Dial(IAX2/iaxmodem)
exten => e,1,NoOp(“Exception Catchall”)
same => n,Playback(hello)
same => n,VoiceMail(1001@voicemailcontext)
;[fax-in]
;exten => _X.,1,Dial(IAX2/iaxmodem)
[voicemail-in]
;exten => 1,1,Answer()
;same => n,VoiceMail(1001@voicemailcontext)
And here’s a full log and SIP trace of an incoming fax call. The fax call comes in, it is not detected as a fax and is therefore answered as a voicemail after 10 seconds, as per the dial plan above.
[Jul 26 00:10:50] VERBOSE[1559641] res_pjsip_logger.c: <--- Received SIP request (1009 bytes) from UDP:27.131.112.116:5060 --->
INVITE sip:s@xxxx:5060 SIP/2.0
Record-Route: <sip:27.131.112.116;lr;ftag=as78734d53;did=154.d8e7e697>
Via: SIP/2.0/UDP 27.131.112.116:5060;branch=z9hG4bK223d.3ffe65a5.0
Via: SIP/2.0/UDP 27.131.76.198:5060;received=27.131.76.198;branch=z9hG4bK43513012;rport=5060
Max-Forwards: 69
From: "xxxx" <sip:xxxx@27.131.112.116>;tag=as78734d53
To: <sip:110153102@27.131.112.116>
Contact: <sip:15034367160@27.131.76.198:5060>
Call-ID: 660e6fb46d2fa64d602340ca2fd9818d@27.131.112.116
CSeq: 102 INVITE
User-Agent: Asterisk PBX 13.23.1
Date: Sun, 25 Jul 2021 14:10:50 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces
Content-Type: application/sdp
Content-Length: 254
v=0
o=root 1025995510 1025995510 IN IP4 27.131.76.198
s=Asterisk PBX 13.23.1
c=IN IP4 27.131.76.198
t=0 0
m=audio 11400 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
[Jul 26 00:10:50] DEBUG[1559641] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=102 (rdata0xffff8c002108)
[Jul 26 00:10:50] DEBUG[1559641] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000031 to use for Request msg INVITE/cseq=102 (rdata0xffff8c002108)
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_endpoint_identifier_ip.c: Source address 27.131.112.116:5060 matches identify 'vcontrol'
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_endpoint_identifier_ip.c: Identify 'vcontrol' SIP message matched to endpoint vcontrol
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: (null session) Request: INVITE
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Request:
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000031 to use for Request msg INVITE/cseq=102 (rdata0xffff8c023528)
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: vcontrol
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: Direct media no glare mitigation
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Call (UDP:27.131.112.116:5060) to extension 's' sending 100 Trying
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Method is INVITE, Response is 100 Trying
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol
[Jul 26 00:10:50] VERBOSE[1559642] res_pjsip_logger.c: <--- Transmitting SIP response (532 bytes) to UDP:27.131.112.116:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 27.131.112.116:5060;rport=5060;received=27.131.112.116;branch=z9hG4bK223d.3ffe65a5.0
Via: SIP/2.0/UDP 27.131.76.198:5060;rport=5060;received=27.131.76.198;branch=z9hG4bK43513012
Record-Route: <sip:27.131.112.116;lr;ftag=as78734d53;did=154.d8e7e697>
Call-ID: 660e6fb46d2fa64d602340ca2fd9818d@27.131.112.116
From: "xxxx" <sip:xxxx@27.131.112.116>;tag=as78734d53
To: <sip:xxxx@27.131.112.116>
CSeq: 102 INVITE
Server: Asterisk PBX GIT-18-2c3defc6c6
Content-Length: 0
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol Event: TSX_STATE Inv State: INCOMING
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Source of transaction state change is TX_MSG
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c:
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol TSX State: Proceeding Inv State: INCOMING
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Nothing delayed
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol TSX State: Proceeding Inv State: INCOMING
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Topology: Pending: (null topology) Active: (null topology)
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c:
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Media count: 1
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Processing stream 0
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Using audio-0 for new stream name
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Using new stream 0:audio-0:audio:sendrecv (nothing)
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol Adding position 0
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Creating new media session
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Setting media session as default for audio
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Done
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c: vcontrol
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c: Transport transport-udp bound to 0.0.0.0: Using it for RTP media.
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xffff2c066fb8'
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) RTP allocated port 29704
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) ICE creating session 0.0.0.0:29704 (29704)
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) ICE create
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) ICE add system candidates
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) ICE add candidate: xxxx:29704, 2130706431
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: RTP instance '0xffff2c066fb8' is setup and ready to go
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) ICE stopped
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) RTCP setup on RTP instance
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c: vcontrol
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c: vcontrol
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Setting tx payload type 8 based on m type on 0xffff55ad5bb0
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c:
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session/pjsip_session_caps.c: 'vcontrol' Caps for incoming audio call with pref 'local' - remote: (alaw) local: (alaw) joint: (alaw)
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0xffff2c023d78) from 0xffff55ad5bb0 to 0xffff55ad5bb0
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0xffff2c01d818) from 0xffff55ad5bb0 to 0xffff55ad5bb0
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Copying rx payload mapping 8 (0xffff2c023d78) from 0xffff55ad5bb0 to 0xffff2c067190
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Copying rx payload mapping 101 (0xffff2c01d818) from 0xffff55ad5bb0 to 0xffff2c067190
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Copying tx payload mapping 8 (0xffff2c023d78) from 0xffff55ad5bb0 to 0xffff2c067190
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Copying tx payload mapping 101 (0xffff2c01d818) from 0xffff55ad5bb0 to 0xffff2c067190
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c:
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c:
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Media stream 0:audio-0:audio:sendrecv (alaw) handled by audio
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Done with stream 0:audio-0:audio:sendrecv (alaw)
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Handled? yes
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Processing streams
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Processing stream 0:audio-0:audio:sendrecv (alaw)
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol Adding position 0
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Using existing media_session
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol Stream: 0:audio-0:audio:sendrecv (alaw)
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c: vcontrol Type: audio 0:audio-0:audio:sendrecv (alaw)
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) RTCP ignoring duplicate property
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c: RC: 1
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Had handler
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Stream 0:audio-0:audio:sendrecv (alaw) added
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Done with 0:audio-0:audio:sendrecv (alaw)
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Adding bundle groups (if available)
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Copying connection details
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Processing media 0
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Media 0 reset
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: vcontrol: Method is INVITE
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: vcontrol
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: vcontrol
[Jul 26 00:10:50] DEBUG[1559642] channel_internal_api.c: <initializing>: Formats: (none)
[Jul 26 00:10:50] DEBUG[1559642] channel_internal_api.c: Channel is being initialized or destroyed
[Jul 26 00:10:50] DEBUG[1559642] stasis.c: Creating topic. name: channel:1627222250.55, detail:
[Jul 26 00:10:50] DEBUG[1559642] stasis.c: Topic 'channel:1627222250.55': 0xffff2c08a8d8 created
[Jul 26 00:10:50] DEBUG[1559642] channel.c: Channel 0xffff2c07ade8 'PJSIP/vcontrol-00000012' allocated
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: Topology: <0:audio-0:audio:sendrecv (alaw)> Formats: (alaw)
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: Compatible? yes
[Jul 26 00:10:50] DEBUG[1559642] channel_internal_api.c: PJSIP/vcontrol-00000012: MultistreamFormats: (alaw)
[Jul 26 00:10:50] DEBUG[1559642] channel_internal_api.c: Set native formats but not topology
[Jul 26 00:10:50] DEBUG[1559642] channel_internal_api.c: PJSIP/vcontrol-00000012: <0:audio-0:audio:sendrecv (alaw)>
[Jul 26 00:10:50] DEBUG[1559642] channel_internal_api.c: Used provided topology
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c:
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: RC: 0
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Request: Session: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: (null session) Handled request INVITE ? yes
[Jul 26 00:10:50] DEBUG[1562333][C-00000013] pbx.c: Launching 'Answer'
[Jul 26 00:10:50] VERBOSE[1562333][C-00000013] pbx.c: Executing [s@inbound-calls:1] Answer("PJSIP/vcontrol-00000012", "") in new stack
[Jul 26 00:10:50] DEBUG[1562333][C-00000013] chan_pjsip.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559619] threadpool.c: Increasing threadpool stasis/pool's size by 1
[Jul 26 00:10:50] DEBUG[1559631] devicestate.c: No provider found, checking channel drivers for PJSIP - vcontrol
[Jul 26 00:10:50] DEBUG[1559631] devicestate.c: Changing state for PJSIP/vcontrol - state 2 (In use)
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c: PJSIP/vcontrol-00000012 Stream: 0:audio-0:audio:sendrecv (alaw)
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) RTCP ignoring duplicate property
[Jul 26 00:10:50] DEBUG[1559675] app_queue.c: Device 'PJSIP/vcontrol' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 26 00:10:50] DEBUG[1559642] acl.c: For destination '27.131.76.198', our source address is 'xxxx'.
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) RTCP setting address on RTP instance
[Jul 26 00:10:50] VERBOSE[1559642] res_rtp_asterisk.c: 0xffff2c067f60 -- Strict RTP learning after remote address set to: 27.131.76.198:11400
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c: PJSIP/vcontrol-00000012 ANSWER
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Setting tx payload type 8 based on m type on 0xffff55ad5ab8
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c:
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Copying tx payload mapping 8 (0xffff2c059d58) from 0xffff55ad5ab8 to 0xffff2c067190
[Jul 26 00:10:50] DEBUG[1559642] rtp_engine.c: Copying tx payload mapping 101 (0xffff2c021648) from 0xffff55ad5ab8 to 0xffff2c067190
[Jul 26 00:10:50] DEBUG[1559642] channel_internal_api.c: PJSIP/vcontrol-00000012: MultistreamFormats: (alaw)
[Jul 26 00:10:50] DEBUG[1559642] channel_internal_api.c: Set native formats but not topology
[Jul 26 00:10:50] DEBUG[1559642] channel.c: Channel PJSIP/vcontrol-00000012 setting read format path: alaw -> alaw
[Jul 26 00:10:50] DEBUG[1559642] channel.c: Channel PJSIP/vcontrol-00000012 setting write format path: alaw -> alaw
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c:
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c066fb8) DTLS - ast_rtp_activate rtp=0xffff2c067f60 - setup and perform DTLS'
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c067f60) DTLS perform handshake - ssl = (nil), setup = 0
[Jul 26 00:10:50] DEBUG[1559642] res_rtp_asterisk.c: (0xffff2c067f60) DTLS perform handshake - ssl = (nil), setup = 0
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_sdp_rtp.c: Handled
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Jul 26 00:10:50] DEBUG[1559642] channel_internal_api.c: PJSIP/vcontrol-00000012: <0:audio-0:audio:sendrecv (alaw)>
[Jul 26 00:10:50] DEBUG[1559642] channel_internal_api.c: Used provided topology
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c:
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012: Method is INVITE, Response is 200 OK
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] VERBOSE[1559642] res_pjsip_logger.c: <--- Transmitting SIP response (1024 bytes) to UDP:27.131.112.116:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 27.131.112.116:5060;rport=5060;received=27.131.112.116;branch=z9hG4bK223d.3ffe65a5.0
Via: SIP/2.0/UDP 27.131.76.198:5060;rport=5060;received=27.131.76.198;branch=z9hG4bK43513012
Record-Route: <sip:27.131.112.116;lr;ftag=as78734d53;did=154.d8e7e697>
Call-ID: 660e6fb46d2fa64d602340ca2fd9818d@27.131.112.116
From: "xxxx" <sip:xxxx@27.131.112.116>;tag=as78734d53
To: <sip:xxxx@27.131.112.116>;tag=0ede480a-026c-43ed-858a-4864790937f1
CSeq: 102 INVITE
Server: Asterisk PBX GIT-18-2c3defc6c6
Contact: <sip:xxxx:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length: 231
v=0
o=- 1025995510 1025995512 IN IP4 xxxx
s=Asterisk
c=IN IP4 xxxx
t=0 0
m=audio 29704 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012 Event: TSX_STATE Inv State: CONNECTING
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012: Source of transaction state change is TX_MSG
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c:
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012 TSX State: Completed Inv State: CONNECTING
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Nothing delayed
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012 TSX State: Completed Inv State: CONNECTING
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (alaw)>
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c:
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c:
[Jul 26 00:10:50] DEBUG[1562333][C-00000013] chan_pjsip.c:
[Jul 26 00:10:50] DEBUG[1562333][C-00000013] chan_pjsip.c: PJSIP/vcontrol-00000012: Indicated Stop generators
[Jul 26 00:10:50] DEBUG[1562333][C-00000013] chan_pjsip.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] VERBOSE[1559641] res_pjsip_logger.c: <--- Received SIP request (533 bytes) from UDP:27.131.112.116:5060 --->
ACK sip:xxxx:5060 SIP/2.0
Via: SIP/2.0/UDP 27.131.112.116:5060;branch=z9hG4bK223d.3ffe65a5.2
Via: SIP/2.0/UDP 27.131.76.198:5060;received=27.131.76.198;branch=z9hG4bK55806c23;rport=5060
Max-Forwards: 69
From: "xxxx" <sip:xxxx@27.131.112.116>;tag=as78734d53
To: <sip:xxxx@27.131.112.116>;tag=0ede480a-026c-43ed-858a-4864790937f1
Contact: <sip:15034367160@27.131.76.198:5060>
Call-ID: 660e6fb46d2fa64d602340ca2fd9818d@27.131.112.116
CSeq: 102 ACK
User-Agent: Asterisk PBX 13.23.1
Content-Length: 0
[Jul 26 00:10:50] DEBUG[1559641] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0xffff2c023e58 for Request msg ACK/cseq=102 (rdata0xffff8c002108)
[Jul 26 00:10:50] DEBUG[1559641] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000031 associated with dialog dlg0xffff2c023e58
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012 TSX State: Terminated Inv State: CONNECTING
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Nothing delayed
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012 TSX State: Terminated Inv State: CONNECTING
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (alaw)>
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c:
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012 Event: RX_MSG Inv State: CONFIRMED
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012: Received request
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012: Method is ACK
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: PJSIP/vcontrol-00000012: Queueing SRCCHANGE
[Jul 26 00:10:50] DEBUG[1559642] chan_pjsip.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c:
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012 Request: ACK
[Jul 26 00:10:50] DEBUG[1559642] res_pjsip_session.c: PJSIP/vcontrol-00000012 Handled request ACK ? yes
[Jul 26 00:10:51] DEBUG[1562333][C-00000013] channel.c: Didn't receive a media frame from PJSIP/vcontrol-00000012 within 500 ms of answering. Continuing anyway
[Jul 26 00:10:51] DEBUG[1562333][C-00000013] pbx_variables.c: Function CALLERID(num) result is '15034367160'
[Jul 26 00:10:51] DEBUG[1562333][C-00000013] pbx.c: Launching 'NoOp'
[Jul 26 00:10:51] VERBOSE[1562333][C-00000013] pbx.c: Executing [s@inbound-calls:2] NoOp("PJSIP/vcontrol-00000012", "15034367160") in new stack
[Jul 26 00:10:51] DEBUG[1562333][C-00000013] pbx.c: Launching 'NoOp'
[Jul 26 00:10:51] VERBOSE[1562333][C-00000013] pbx.c: Executing [s@inbound-calls:3] NoOp("PJSIP/vcontrol-00000012", "inbound-calls") in new stack
[Jul 26 00:10:51] DEBUG[1562333][C-00000013] pbx.c: Launching 'WaitExten'
[Jul 26 00:10:51] VERBOSE[1562333][C-00000013] pbx.c: Executing [s@inbound-calls:4] WaitExten("PJSIP/vcontrol-00000012", "10") in new stack
[Jul 26 00:10:52] DEBUG[1559659] chan_iax2.c: Determining if address 127.0.0.1 with username iaxmodem requires calltoken validation. Optional = 0 calltoken_required = 3
[Jul 26 00:10:52] DEBUG[1559659] chan_iax2.c: ip callno count incremented to 2 for 127.0.0.1
[Jul 26 00:10:52] DEBUG[1559631] devicestate.c: No provider found, checking channel drivers for IAX2 - iaxmodem
[Jul 26 00:10:52] DEBUG[1559631] chan_iax2.c: Checking device state for device iaxmodem
[Jul 26 00:10:52] DEBUG[1559631] chan_iax2.c: Found peer. What's device state of iaxmodem? addr=127.0.0.1:4570, defaddr=(null) maxms=0, lastms=0
[Jul 26 00:10:52] DEBUG[1559631] devicestate.c: Changing state for IAX2/iaxmodem - state 0 (Unknown)
[Jul 26 00:10:52] NOTICE[1559662] chan_iax2.c: Restricting registration for peer 'iaxmodem' to 60 seconds (requested 50)
[Jul 26 00:10:52] DEBUG[1559631] devicestate.c: No provider found, checking channel drivers for IAX2 - iaxmodem
[Jul 26 00:10:52] DEBUG[1559631] chan_iax2.c: Checking device state for device iaxmodem
[Jul 26 00:10:52] DEBUG[1559631] chan_iax2.c: Found peer. What's device state of iaxmodem? addr=127.0.0.1:4570, defaddr=(null) maxms=0, lastms=0
[Jul 26 00:10:52] DEBUG[1559631] devicestate.c: Changing state for IAX2/iaxmodem - state 0 (Unknown)
[Jul 26 00:10:52] DEBUG[1559664] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds
[Jul 26 00:10:53] VERBOSE[1559641] res_pjsip_logger.c: <--- Received SIP request (285 bytes) from UDP:27.131.112.116:5060 --->
OPTIONS sip:xxxx:11955 SIP/2.0
Via: SIP/2.0/UDP 27.131.112.116:5060;branch=z9hG4bK928ead08
From: sip:pinger@27.131.112.116;tag=bbabbbd6
To: sip:xxxx:11955
Call-ID: 90771c36-928ead08-20bcf1@27.131.112.116
CSeq: 1 OPTIONS
Max-Forwards: 70
Content-Length: 0
[Jul 26 00:10:53] DEBUG[1559641] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=1 (rdata0xffff8c002108)
[Jul 26 00:10:53] DEBUG[1559641] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000027 to use for Request msg OPTIONS/cseq=1 (rdata0xffff8c002108)
[Jul 26 00:10:53] DEBUG[1559642] res_pjsip_endpoint_identifier_ip.c: Source address 27.131.112.116:5060 matches identify 'vcontrol'
[Jul 26 00:10:53] DEBUG[1559642] res_pjsip_endpoint_identifier_ip.c: Identify 'vcontrol' SIP message matched to endpoint vcontrol
[Jul 26 00:10:53] VERBOSE[1559642] res_pjsip_logger.c: <--- Transmitting SIP response (820 bytes) to UDP:27.131.112.116:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 27.131.112.116:5060;rport=5060;received=27.131.112.116;branch=z9hG4bK928ead08
Call-ID: 90771c36-928ead08-20bcf1@27.131.112.116
From: <sip:pinger@27.131.112.116>;tag=bbabbbd6
To: <sip:xxxx>;tag=z9hG4bK928ead08
CSeq: 1 OPTIONS
Accept: application/xpidf+xml, application/cpim-pidf+xml, application/dialog-info+xml, application/simple-message-summary, application/pidf+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, application/sdp, message/sipfrag;version=2.0
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Accept-Encoding: identity
Accept-Language: en
Server: Asterisk PBX GIT-18-2c3defc6c6
Content-Length: 0
[Jul 26 00:10:57] DEBUG[1559656] chan_iax2.c: ip callno count decremented to 1 for 127.0.0.1
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] pbx.c: Launching 'NoOp'
[Jul 26 00:11:01] VERBOSE[1562333][C-00000013] pbx.c: Executing [e@inbound-calls:1] NoOp("PJSIP/vcontrol-00000012", "“Exception Catchall”") in new stack
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] pbx.c: Launching 'Playback'
[Jul 26 00:11:01] VERBOSE[1562333][C-00000013] pbx.c: Executing [e@inbound-calls:2] Playback("PJSIP/vcontrol-00000012", "hello") in new stack
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] channel.c: Channel PJSIP/vcontrol-00000012 setting write format path: gsm -> alaw
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] res_rtp_asterisk.c: (0xffff2c066fb8) RTP ooh, format changed from none to alaw
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] res_rtp_asterisk.c: (0xffff2c066fb8) RTCP starting transmission
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jul 26 00:11:01] VERBOSE[1562333][C-00000013] file.c: <PJSIP/vcontrol-00000012> Playing 'hello.gsm' (language 'en')
[Jul 26 00:11:01] VERBOSE[1562333][C-00000013] res_rtp_asterisk.c: 0xffff2c067f60 -- Strict RTP switching to RTP target address 27.131.76.198:11400 as source
[Jul 26 00:11:01] VERBOSE[1562333][C-00000013] res_rtp_asterisk.c: 0xffff2c067f60 -- Strict RTP learning complete - Locking on source address 27.131.76.198:11400
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] channel.c: Channel PJSIP/vcontrol-00000012 setting write format path: alaw -> alaw
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] pbx.c: Launching 'VoiceMail'
[Jul 26 00:11:01] VERBOSE[1562333][C-00000013] pbx.c: Executing [e@inbound-calls:3] VoiceMail("PJSIP/vcontrol-00000012", "1001@voicemailcontext") in new stack
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] app_voicemail.c: Before find_user
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] channel.c: Channel PJSIP/vcontrol-00000012 setting write format path: gsm -> alaw
[Jul 26 00:11:01] DEBUG[1562333][C-00000013] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jul 26 00:11:01] VERBOSE[1562333][C-00000013] file.c: <PJSIP/vcontrol-00000012> Playing 'vm-intro.gsm' (language 'en')