CSeq: 1 CANCEL

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

Thank you!
JJ

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.

I see. Exactly what you mean for “whole transaction”?
I set
core set verbose 10
core set debug 10
pjsip set logger on

what i need more to check?

By “whole transaction” I mean we don’t see the INVITE part here. Start with where the INVITE comes in and trace it from there.

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 :

[2016-06-28 15:47:01] VERBOSE[1925] res_pjsip_logger.c: <— Transmitting SIP request (483 bytes) to UDP:192.168.1.3:5065 —>
OPTIONS sip:**[email protected]:5065 SIP/2.0
Via: SIP/2.0/UDP external:5060;rport;branch=z9hG4bKPjtPUziqWbJZNgUjWyvZIem6-QQ-A.1-SU
From: sip:**[email protected];tag=qOOqC0O-3MTGcHKtSbBT.GyduSGIp2cF
To: sip:**[email protected]
Contact: sip:**[email protected]:5060
Call-ID: fNgkyqvhTsR6xFVdYmil8JDoRxLZ8l2O
CSeq: 45318 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-13.0.143(13.9.1)
Content-Length: 0

[2016-06-28 15:47:01] DEBUG[1925] pjproject: sip_endpoint.c Processing incoming message: Response msg 486/OPTIONS/cseq=45318 (rdata0x7f05f8e7e408)
[2016-06-28 15:47:01] VERBOSE[1925] res_pjsip_logger.c: <— Received SIP response (446 bytes) from UDP:192.168.1.3:5065 —>
SIP/2.0 486 Rejected
From: sip:**[email protected];user=phone;tag=qOOqC0O-3MTGcHKtSbBT.GyduSGIp2cF
To: sip:**[email protected];user=phone;tag=1be92f0-7f000001-13e2-50029-95d55-24b74ca7-95d55
Call-ID: fNgkyqvhTsR6xFVdYmil8JDoRxLZ8l2O
CSeq: 45318 OPTIONS
Via: SIP/2.0/UDP external:5060;received=192.168.1.21;rport=5060;branch=z9hG4bKPjtPUziqWbJZNgUjWyvZIem6-QQ-A.1-SU
Content-Length: 0

OK, then these OPTIONS are not relevant, not related to the call you are trying to analyze. Look for the sequence that begins with an INVITE.

I really appreciate your help.
Just made a call from my mobile to the PBX. That’s all I can find about INVITE related to the call:

[2016-06-28 17:08:51] DEBUG[1925] pjproject: sip_resolve.c .Target ‘externalip:5065’ type=UDP resolved to ‘externalip:5065’ type=UDP (UDP transport)
[2016-06-28 17:08:51] DEBUG[1925] netsock2.c: Splitting ‘externalip’ into…
[2016-06-28 17:08:51] DEBUG[1925] netsock2.c: …host ‘externalip’ and port ‘’.
[2016-06-28 17:08:51] DEBUG[1925] netsock2.c: Splitting ‘0.0.0.0:5060’ into…
[2016-06-28 17:08:51] DEBUG[1925] netsock2.c: …host ‘0.0.0.0’ and port ‘5060’.
[2016-06-28 17:08:51] DEBUG[1925] netsock2.c: Splitting ‘externalip:5065’ into…
[2016-06-28 17:08:51] DEBUG[1925] netsock2.c: …host ‘externalip’ and port ‘5065’.
[2016-06-28 17:08:51] VERBOSE[1925] res_pjsip_logger.c: <— Transmitting SIP response (474 bytes) to UDP:externalip:5065 —>
SIP/2.0 481 Call/Transaction Does Not Exist
Via: SIP/2.0/UDP 192.168.1.3:5065;received=externalip;branch=z9hG4bK-9707e-24df6d8f-eebb2d8
Call-ID: 1bfb5a8-7f000001-13e2-50029-9707e-5a5fcb5-9707e
From: sip:[email protected];user=phone;tag=1be9490-7f000001-13e2-50029-9707e-43daa02b-9707e
To: sip:**[email protected];user=phone;tag=z9hG4bK-9707e-24df6d8f-eebb2d8
CSeq: 1 CANCEL
Server: FPBX-13.0.143(13.9.1)
Content-Length: 0

[2016-06-28 17:08:51] DEBUG[1925] pjproject: tdta0x7f0610e3 .Destroying txdata Response msg 481/CANCEL/cseq=1 (tdta0x7f0610e3fd50)
[2016-06-28 17:08:53] DEBUG[1925] pjproject: sip_endpoint.c Processing incoming message: Request msg CANCEL/cseq=1 (rdata0x7f05f8f34cd8)
[2016-06-28 17:08:53] VERBOSE[1925] res_pjsip_logger.c: <— Received SIP request (519 bytes) from UDP:externalip:63281 —>
CANCEL sip:[email protected]:5060;transport=UDP;user=phone SIP/2.0
From: sip:[email protected];user=phone;tag=1be9490-7f000001-13e2-50029-9707e-43daa02b-9707e
To: sip:**[email protected];user=phone
Call-ID: 1bfb5a8-7f000001-13e2-50029-9707e-5a5fcb5-9707e
CSeq: 1 CANCEL
Via: SIP/2.0/UDP 192.168.1.3:5065;branch=z9hG4bK-9707e-24df6d8f-eebb2d8
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 17:08:53] DEBUG[1925] netsock2.c: Splitting ‘externalip:63281’ into…
[2016-06-28 17:08:53] DEBUG[1925] netsock2.c: …host ‘externalip’ and port ‘63281’.
[2016-06-28 17:08:53] DEBUG[1925] netsock2.c: Splitting ‘0.0.0.0:5060’ into…
[2016-06-28 17:08:53] DEBUG[1925] netsock2.c: …host ‘0.0.0.0’ and port ‘5060’.
[2016-06-28 17:08:53] ERROR[1925] res_pjsip/pjsip_distributor.c: Could not find matching INVITE transaction for CANCEL request
[2016-06-28 17:08:53] DEBUG[1925] pjproject: endpoint .Response msg 481/CANCEL/cseq=1 (tdta0x7f0610e3fd50) created
[2016-06-28 17:08:53] DEBUG[1925] pjproject: sip_resolve.c .Target ‘externalip:5065’ type=UDP resolved to ‘externalip:5065’ type=UDP (UDP transport)
[2016-06-28 17:08:53] DEBUG[1925] netsock2.c: Splitting ‘externalip’ into…
[2016-06-28 17:08:53] DEBUG[1925] netsock2.c: …host ‘externalip’ and port ‘’.
[2016-06-28 17:08:53] DEBUG[1925] netsock2.c: Splitting ‘0.0.0.0:5060’ into…
[2016-06-28 17:08:53] DEBUG[1925] netsock2.c: …host ‘0.0.0.0’ and port ‘5060’.
[2016-06-28 17:08:53] DEBUG[1925] netsock2.c: Splitting ‘externalip:5065’ into…
[2016-06-28 17:08:53] DEBUG[1925] netsock2.c: …host ‘externalip’ and port ‘5065’.
[2016-06-28 17:08:53] VERBOSE[1925] res_pjsip_logger.c: <— Transmitting SIP response (474 bytes) to UDP:externalip:5065 —>
SIP/2.0 481 Call/Transaction Does Not Exist
Via: SIP/2.0/UDP 192.168.1.3:5065;received=externalip;branch=z9hG4bK-9707e-24df6d8f-eebb2d8
Call-ID: 1bfb5a8-7f000001-13e2-50029-9707e-5a5fcb5-9707e
From: sip:[email protected];user=phone;tag=1be9490-7f000001-13e2-50029-9707e-43daa02b-9707e
To: sip:**[email protected];user=phone;tag=z9hG4bK-9707e-24df6d8f-eebb2d8
CSeq: 1 CANCEL
Server: FPBX-13.0.143(13.9.1)
Content-Length: 0

[2016-06-28 17:08:53] DEBUG[1925] pjproject: tdta0x7f0610e3 .Destroying txdata Response msg 481/CANCEL/cseq=1 (tdta0x7f0610e3fd50)
[2016-06-28 17:08:53] DEBUG[2015] res_pjsip_registrar_expire.c: Woke up at 1467126533 Interval: 30
[2016-06-28 17:08:53] DEBUG[2015] res_pjsip_registrar_expire.c: Expiring 0 contacts

[2016-06-28 17:08:55] DEBUG[32674] manager.c: Running action ‘DPMALicenseStatus’