[Home]

Summary:ASTERISK-29063: PJSIP leaves endpoint in Unavail state when successful qualification happens right after Unavail state change
Reporter:Speed Dial Dave (speeddialdave)Labels:
Date Opened:2020-09-02 08:14:59Date Closed:2020-09-02 09:30:20
Priority:MinorRegression?
Status:Closed/CompleteComponents:pjproject/pjsip
Versions:16.11.0 Frequency of
Occurrence
Related
Issues:
Environment:CentOS Linux 7.8.2003 x86_64Attachments:
Description:{noformat}[2020-08-28T14:07:11.295+0200] VERBOSE[14237] res_pjsip_logger.c: <--- Transmitting SIP request (417 bytes) to UDP:1.2.3.4:5060 --->
OPTIONS sip:1.2.3.4 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;rport;branch=z9hG4bKPj2cce2a99-8f1c-443c-8435-d5347147a76f
From: <sip:trunkname@5.5.5.5>;tag=b856990b-9ef9-45e7-92aa-573924e0bb4c
To: <sip:1.2.3.4>
Contact: <sip:trunkname@5.5.5.5:5060>
Call-ID: 254a56ce-1b12-4fd7-b5ff-2e7684341af4
CSeq: 63071 OPTIONS
Max-Forwards: 70
User-Agent: Asterisk PBX 16.11.0
Content-Length:  0


[2020-08-28T14:07:11.795+0200] VERBOSE[2019] res_pjsip_logger.c: <--- Transmitting SIP request (417 bytes) to UDP:1.2.3.4:5060 --->
OPTIONS sip:1.2.3.4 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;rport;branch=z9hG4bKPj2cce2a99-8f1c-443c-8435-d5347147a76f
From: <sip:trunkname@5.5.5.5>;tag=b856990b-9ef9-45e7-92aa-573924e0bb4c
To: <sip:1.2.3.4>
Contact: <sip:trunkname@5.5.5.5:5060>
Call-ID: 254a56ce-1b12-4fd7-b5ff-2e7684341af4
CSeq: 63071 OPTIONS
Max-Forwards: 70
User-Agent: Asterisk PBX 16.11.0
Content-Length:  0


[2020-08-28T14:07:12.795+0200] VERBOSE[2019] res_pjsip_logger.c: <--- Transmitting SIP request (417 bytes) to UDP:1.2.3.4:5060 --->
OPTIONS sip:1.2.3.4 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;rport;branch=z9hG4bKPj2cce2a99-8f1c-443c-8435-d5347147a76f
From: <sip:trunkname@5.5.5.5>;tag=b856990b-9ef9-45e7-92aa-573924e0bb4c
To: <sip:1.2.3.4>
Contact: <sip:trunkname@5.5.5.5:5060>
Call-ID: 254a56ce-1b12-4fd7-b5ff-2e7684341af4
CSeq: 63071 OPTIONS
Max-Forwards: 70
User-Agent: Asterisk PBX 16.11.0
Content-Length:  0


[2020-08-28T14:07:14.295+0200] DEBUG[2019] res_pjsip.c: 0x7f0ea800c440: Internal tsx timer expired after 3000 msec
[2020-08-28T14:07:14.295+0200] DEBUG[2019] res_pjsip.c: 0x7f0ea800c440: Timer handled here
[2020-08-28T14:07:14.295+0200] DEBUG[2019] res_pjsip.c: 0x7f0ea800c440: Callbacks executed
[2020-08-28T14:07:14.295+0200] VERBOSE[14237] res_pjsip/pjsip_configuration.c: Endpoint trunkname is now Unreachable
[2020-08-28T14:07:14.295+0200] VERBOSE[14237] res_pjsip/pjsip_options.c: Contact trunkname/sip:1.2.3.4 is now Unreachable.  RTT: 0.000 msec
[2020-08-28T14:07:14.295+0200] DEBUG[1991] devicestate.c: No provider found, checking channel drivers for PJSIP - trunkname
[2020-08-28T14:07:14.295+0200] DEBUG[14237] res_pjsip/pjsip_options.c: AOR 'trunkname' now has 0 available contacts
[2020-08-28T14:07:14.295+0200] DEBUG[1991] devicestate.c: Changing state for PJSIP/trunkname - state 5 (Unavailable)
[2020-08-28T14:07:14.295+0200] DEBUG[2050] app_queue.c: Device 'PJSIP/trunkname' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.{noformat}


The trunk is now marked Unavailable as it failed to respond within 3 seconds. Just half a second later a successful qualification attempt happens:


{noformat}[2020-08-28T14:07:14.795+0200] VERBOSE[2019] res_pjsip_logger.c: <--- Transmitting SIP request (417 bytes) to UDP:1.2.3.4:5060 --->
OPTIONS sip:1.2.3.4 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;rport;branch=z9hG4bKPj2cce2a99-8f1c-443c-8435-d5347147a76f
From: <sip:trunkname@5.5.5.5>;tag=b856990b-9ef9-45e7-92aa-573924e0bb4c
To: <sip:1.2.3.4>
Contact: <sip:trunkname@5.5.5.5:5060>
Call-ID: 254a56ce-1b12-4fd7-b5ff-2e7684341af4
CSeq: 63071 OPTIONS
Max-Forwards: 70
User-Agent: Asterisk PBX 16.11.0
Content-Length:  0


[2020-08-28T14:07:14.797+0200] VERBOSE[2019] res_pjsip_logger.c: <--- Received SIP response (351 bytes) from UDP:1.2.3.4:5060 --->
SIP/2.0 480 No Routes Found
Via: SIP/2.0/UDP 5.5.5.5:5060;received=5.5.5.5;branch=z9hG4bKPj2cce2a99-8f1c-443c-8435-d5347147a76f;rport=5060
From: <sip:999999@5.5.5.5>;tag=b856990b-9ef9-45e7-92aa-573924e0bb4c
To: <sip:1.2.3.4>;tag=aprqngfrt-f7hrai000gtv5
Call-ID: 254a56ce-1b12-4fd7-b5ff-2e7684341af4
CSeq: 63071 OPTIONS


[2020-08-28T14:07:14.797+0200] DEBUG[2019] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 480/OPTIONS/cseq=63071 (rdata0x7f0eec004368).  Using request transaction as basis.
[2020-08-28T14:07:14.797+0200] DEBUG[2019] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7f0ea8018a38 for Response msg 480/OPTIONS/cseq=63071 (rdata0x7f0eec004368).
[2020-08-28T14:07:14.797+0200] DEBUG[2019] res_pjsip/pjsip_distributor.c: Found serializer pjsip/options/trunkname-00000042 on transaction tsx0x7f0ea8018a38
[2020-08-28T14:07:14.797+0200] DEBUG[14237] res_pjsip.c: 0x7f0ea800c440: PJSIP tsx response received
[2020-08-28T14:07:14.797+0200] DEBUG[14237] res_pjsip.c: 0x7f0ea800c440: wrapper destroyed{noformat}


At this point I would expect the trunk to immediately be brought back to Reachable/Avail state, but it stays Unavailable until the next qualification attempt ~27 seconds later:


{noformat}[2020-08-28T14:07:41.295+0200] VERBOSE[30519] res_pjsip_logger.c: <--- Transmitting SIP request (417 bytes) to UDP:1.2.3.4:5060 --->
OPTIONS sip:1.2.3.4 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;rport;branch=z9hG4bKPjf7f88631-d669-44b4-8403-580006ad239d
From: <sip:trunkname@5.5.5.5>;tag=ab0b0636-9b7c-4a40-a38c-1c892ca68c08
To: <sip:1.2.3.4>
Contact: <sip:trunkname@5.5.5.5:5060>
Call-ID: c1d95174-50dd-47e2-bae4-426f8a1f4d63
CSeq: 21729 OPTIONS
Max-Forwards: 70
User-Agent: Asterisk PBX 16.11.0
Content-Length:  0


[2020-08-28T14:07:41.297+0200] VERBOSE[2019] res_pjsip_logger.c: <--- Received SIP response (351 bytes) from UDP:1.2.3.4:5060 --->
SIP/2.0 480 No Routes Found
Via: SIP/2.0/UDP 5.5.5.5:5060;received=5.5.5.5;branch=z9hG4bKPjf7f88631-d669-44b4-8403-580006ad239d;rport=5060
From: <sip:999999@5.5.5.5>;tag=ab0b0636-9b7c-4a40-a38c-1c892ca68c08
To: <sip:1.2.3.4>;tag=aprqngfrt-sknglo2000l2e
Call-ID: c1d95174-50dd-47e2-bae4-426f8a1f4d63
CSeq: 21729 OPTIONS


[2020-08-28T14:07:41.297+0200] DEBUG[2019] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 480/OPTIONS/cseq=21729 (rdata0x7f0eec004368).  Using request transaction as basis.
[2020-08-28T14:07:41.297+0200] DEBUG[2019] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7f0ea8018a38 for Response msg 480/OPTIONS/cseq=21729 (rdata0x7f0eec004368).
[2020-08-28T14:07:41.297+0200] DEBUG[2019] res_pjsip/pjsip_distributor.c: Found serializer pjsip/options/trunkname-00000042 on transaction tsx0x7f0ea8018a38
[2020-08-28T14:07:41.297+0200] DEBUG[14237] res_pjsip.c: 0x7f0ef00015b0: PJSIP tsx response received
[2020-08-28T14:07:41.297+0200] DEBUG[14237] res_pjsip.c: 0x7f0ef00015b0: Cancelling timer
[2020-08-28T14:07:41.297+0200] DEBUG[14237] res_pjsip.c: 0x7f0ef00015b0: Timer cancelled
[2020-08-28T14:07:41.297+0200] DEBUG[14237] res_pjsip.c: 0x7f0ef00015b0: Callbacks executed
[2020-08-28T14:07:41.297+0200] DEBUG[14237] res_pjsip.c: 0x7f0ef00015b0: wrapper destroyed
[2020-08-28T14:07:41.297+0200] DEBUG[14237] res_pjsip/pjsip_options.c: Endpoint state compositor 'trunkname' is online as AOR 'trunkname' is available
[2020-08-28T14:07:41.297+0200] VERBOSE[14237] res_pjsip/pjsip_configuration.c: Endpoint trunkname is now Reachable
[2020-08-28T14:07:41.297+0200] VERBOSE[14237] res_pjsip/pjsip_options.c: Contact trunkname/sip:1.2.3.4 is now Reachable.  RTT: 2.133 msec
[2020-08-28T14:07:41.297+0200] DEBUG[14237] res_pjsip/pjsip_options.c: AOR 'trunkname' now has 1 available contacts
[2020-08-28T14:07:41.297+0200] DEBUG[1991] devicestate.c: No provider found, checking channel drivers for PJSIP - trunkname
[2020-08-28T14:07:41.297+0200] DEBUG[1991] devicestate.c: Changing state for PJSIP/trunkname - state 1 (Not in use)
{noformat}
Comments:By: Asterisk Team (asteriskteam) 2020-09-02 08:15:01.324-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
By: Joshua C. Colp (jcolp) 2020-09-02 08:41:54.531-0500

This is due to the way that the PJSIP stack works. When we send a request we give it a timeout, if that timeout is met then we receive a callback saying no response. The SIP stack continues to attempt the transaction (it should probably stop, but that's within the stack itself) and subsequent responses are ignored (since we were told it already failed).

To try to overcome this is an improvement and would likely require modifications within the PJSIP stack itself with optional behavior changes. I don't think it would be easy to do.

As well, since this would be an improvement we generally don't accept those without a patch. Is it something you're looking into?
By: Speed Dial Dave (speeddialdave) 2020-09-02 09:24:41.093-0500

Nay.
By: Joshua C. Colp (jcolp) 2020-09-02 09:30:20.975-0500

Understood, if that changes you can comment and this issue will reopen. For now though I'm closing this out as not a bug for the reasoning previously given.