May someone help me in finding where I’m wrong? I’m getting this whenever I make a call from external:
[2016-06-27 19:43:37] VERBOSE[1925] res_pjsip_logger.c: <— Received SIP request (521 bytes) from UDP:XX.XX.XX.XX:64552 —>
CANCEL sip:[email protected]:5060;transport=UDP;user=phone SIP/2.0
From: sip:[email protected];user=phone;tag=1be0590-7f000001-13e2-50029-84342-42bf2fab-84342
To: sip:**[email protected];user=phone
Call-ID: 1bf37d8-7f000001-13e2-50029-84342-65d16b3d-84342
CSeq: 1 CANCEL
Via: SIP/2.0/UDP 192.168.1.3:5065;branch=z9hG4bK-84342-2046ba8a-1612a521
Max-Forwards: 59
Reason: Q.850;cause=16;text="10"
User-Agent: Technicolor / VDNT-S / AGVTF_5.3.1 / AGVTF_5.3.1
Content-Length: 0
It means that the remote side is giving up on the call to you; he is CANCELing his attempt to call you. The SIP CANCEL is used to hang up a call that has been INVITEd before it is accepted with OK.
Thank you Bill,
haw can avoid this? I cannot receive any calls from outside, it rings with no answer.
This is last complete log:
[2016-06-28 09:03:20] DEBUG[8000] pjproject: tsx0x7f060c02b .State changed from Null to Calling, event=TX_MSG
[2016-06-28 09:03:20] DEBUG[1925] pjproject: sip_endpoint.c Processing incoming message: Response msg 486/OPTIONS/cseq=28507 (rdata0x7f05f88b7978)
[2016-06-28 09:03:20] VERBOSE[1925] res_pjsip_logger.c: <— Received SIP response (400 bytes) from UDP:192.168.1.3:5065 —>
SIP/2.0 486 Rejected
From: sip:**[email protected];user=phone;tag=cnv5kW0llc5.laa279ZCp5OB8uyN7MXI
To: sip:**[email protected];user=phone;tag=1bde850-7f000001-13e2-50029-8feb8-440e9992-8feb8
Call-ID: nlx-Gx.WpHQZA-XkOYVVshigE-pqa.5Q
CSeq: 28507 OPTIONS
Via: SIP/2.0/UDP ex.ter.nal.ip:5060;received=192.168.1.21;rport=65486;branch=z9hG4bKPjOsoTfO3O3fyubvfviIcRcFPPSv6isRqm
Content-Length: 0
[2016-06-28 09:03:20] DEBUG[1925] netsock2.c: Splitting ‘192.168.1.3:5065’ into…
[2016-06-28 09:03:20] DEBUG[1925] netsock2.c: …host ‘192.168.1.3’ and port ‘5065’.
[2016-06-28 09:03:20] DEBUG[1925] netsock2.c: Splitting ‘0.0.0.0:5060’ into…
[2016-06-28 09:03:20] DEBUG[1925] netsock2.c: …host ‘0.0.0.0’ and port ‘5060’.
[2016-06-28 09:03:20] DEBUG[1925] res_pjsip/pjsip_distributor.c: No dialog serializer for response Response msg 486/OPTIONS/cseq=28507 (rdata0x7f05f88b7978). Using request transaction as basis
[2016-06-28 09:03:20] DEBUG[1925] res_pjsip/pjsip_distributor.c: Found serializer pjsip/default-00000010 on transaction tsx0x7f060c02b028
[2016-06-28 09:03:20] DEBUG[627] pjproject: sip_endpoint.c Distributing rdata to modules: Response msg 486/OPTIONS/cseq=28507 (rdata0x7f05f88ba1f8)
[2016-06-28 09:03:20] DEBUG[627] pjproject: tsx0x7f060c02b .Incoming Response msg 486/OPTIONS/cseq=28507 (rdata0x7f05f88ba1f8) in state Calling
[2016-06-28 09:03:20] DEBUG[627] pjproject: tsx0x7f060c02b …State changed from Calling to Completed, event=RX_MSG
[2016-06-28 09:03:20] DEBUG[627] res_pjsip.c: 0x7f0612dff138: PJSIP tsx response received
[2016-06-28 09:03:20] DEBUG[627] res_pjsip.c: 0x7f0612dff138: Cancelling timer
[2016-06-28 09:03:20] DEBUG[627] res_pjsip.c: 0x7f0612dff138: Timer cancelled
[2016-06-28 09:03:20] DEBUG[627] config.c: extract uint from [3] in [0, 4294967295] gives 3
[2016-06-28 09:03:20] DEBUG[627] config.c: extract uint from [0] in [0, 4294967295] gives 0
[2016-06-28 09:03:20] DEBUG[627] config.c: extract uint from [2] in [0, 4294967295] gives 2
[2016-06-28 09:03:20] DEBUG[627] res_pjsip.c: 0x7f0612dff138: Callbacks executed
[2016-06-28 09:03:20] DEBUG[627] res_pjsip.c: 0x7f0612dff138: wrapper destroyed
[2016-06-28 09:03:20] DEBUG[28333] res_pjsip/pjsip_configuration.c: Contact TIMFIBRA/sip:**[email protected]:5065 status didn’t change: Reachable, RTT: 9.449 msec
[2016-06-28 09:03:22] DEBUG[1925] pjproject: sip_endpoint.c Processing incoming message: Request msg CANCEL/cseq=1 (rdata0x7f05f88b7978)
[2016-06-28 09:03:22] VERBOSE[1925] res_pjsip_logger.c: <— Received SIP request (520 bytes) from UDP:ex.ter.nal.ip:50306 —>
CANCEL sip:[email protected]:5060;transport=UDP;user=phone SIP/2.0
From: sip:[email protected];user=phone;tag=1be7270-7f000001-13e2-50029-8feac-6218259-8feac
To: sip:**[email protected];user=phone
Call-ID: 1bf5f08-7f000001-13e2-50029-8feac-7cf57803-8feac
CSeq: 1 CANCEL
Via: SIP/2.0/UDP 192.168.1.3:5065;branch=z9hG4bK-8feac-2322d26d-7d98046e
Max-Forwards: 59
Reason: Q.850;cause=16;text="10"
User-Agent: Technicolor / VDNT-S / AGVTF_5.3.1 / AGVTF_5.3.1
Content-Length: 0
[2016-06-28 09:03:22] DEBUG[1925] netsock2.c: Splitting ‘ex.ter.nal.ip:50306’ into…
[2016-06-28 09:03:22] DEBUG[1925] netsock2.c: …host ‘ex.ter.nal.ip’ and port ‘50306’.
[2016-06-28 09:03:22] DEBUG[1925] netsock2.c: Splitting ‘0.0.0.0:5060’ into…
[2016-06-28 09:03:22] DEBUG[1925] netsock2.c: …host ‘0.0.0.0’ and port ‘5060’.
[2016-06-28 09:03:22] ERROR[1925] res_pjsip/pjsip_distributor.c: Could not find matching INVITE transaction for CANCEL request
[2016-06-28 09:03:22] DEBUG[1925] pjproject: endpoint .Response msg 481/CANCEL/cseq=1 (tdta0x7f06107dda30) created
[2016-06-28 09:03:22] DEBUG[1925] pjproject: sip_resolve.c .Target ‘ex.ter.nal.ip:5065’ type=UDP resolved to ‘ex.ter.nal.ip:5065’ type=UDP (UDP transport)
[2016-06-28 09:03:22] DEBUG[1925] netsock2.c: Splitting ‘ex.ter.nal.ip’ into…
[2016-06-28 09:03:22] DEBUG[1925] netsock2.c: …host ‘ex.ter.nal.ip’ and port ‘’.
[2016-06-28 09:03:22] DEBUG[1925] netsock2.c: Splitting ‘0.0.0.0:5060’ into…
[2016-06-28 09:03:22] DEBUG[1925] netsock2.c: …host ‘0.0.0.0’ and port ‘5060’.
[2016-06-28 09:03:22] DEBUG[1925] netsock2.c: Splitting ‘ex.ter.nal.ip:5065’ into…
[2016-06-28 09:03:22] DEBUG[1925] netsock2.c: …host ‘ex.ter.nal.ip’ and port ‘5065’.
[2016-06-28 09:03:22] VERBOSE[1925] res_pjsip_logger.c: <— Transmitting SIP response (476 bytes) to UDP:ex.ter.nal.ip:5065 —>
SIP/2.0 481 Call/Transaction Does Not Exist
Via: SIP/2.0/UDP 192.168.1.3:5065;received=ex.ter.nal.ip;branch=z9hG4bK-8feac-2322d26d-7d98046e
Call-ID: 1bf5f08-7f000001-13e2-50029-8feac-7cf57803-8feac
From: sip:[email protected];user=phone;tag=1be7270-7f000001-13e2-50029-8feac-6218259-8feac
To: sip:**[email protected];user=phone;tag=z9hG4bK-8feac-2322d26d-7d98046e
CSeq: 1 CANCEL
Server: FPBX-13.0.143(13.9.1)
Content-Length: 0
This one shows your internal phone rejecting the incoming call with 486. You need to look at the whole transaction, end to end, to figure out the problem.
Ok,
the problem is that I cannot find any INVITE. Look here, during options request, the response is “486 rejected” that does not exists (486 should be BUSY). I’m using FreePBX 13.0.143 :