[asterisk-bugs] [JIRA] (ASTERISK-29063) PJSIP leaves endpoint in Unavail state when successful qualification happens right after Unavail state change

Wed Sep 2 08:16:43 CDT 2020

    [ https://issues.asterisk.org/jira/browse/ASTERISK-29063?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=251900#comment-251900 ] 

Asterisk Team commented on ASTERISK-29063:
------------------------------------------

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.

> PJSIP leaves endpoint in Unavail state when successful qualification happens right after Unavail state change
> -------------------------------------------------------------------------------------------------------------
>
>                 Key: ASTERISK-29063
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-29063
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: pjproject/pjsip
>    Affects Versions: 16.11.0
>         Environment: CentOS Linux 7.8.2003 x86_64
>            Reporter: Speed Dial Dave
>            Severity: Minor
>
> {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 at 5.5.5.5>;tag=b856990b-9ef9-45e7-92aa-573924e0bb4c
> To: <sip:1.2.3.4>
> Contact: <sip:trunkname at 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 at 5.5.5.5>;tag=b856990b-9ef9-45e7-92aa-573924e0bb4c
> To: <sip:1.2.3.4>
> Contact: <sip:trunkname at 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 at 5.5.5.5>;tag=b856990b-9ef9-45e7-92aa-573924e0bb4c
> To: <sip:1.2.3.4>
> Contact: <sip:trunkname at 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 at 5.5.5.5>;tag=b856990b-9ef9-45e7-92aa-573924e0bb4c
> To: <sip:1.2.3.4>
> Contact: <sip:trunkname at 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 at 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 at 5.5.5.5>;tag=ab0b0636-9b7c-4a40-a38c-1c892ca68c08
> To: <sip:1.2.3.4>
> Contact: <sip:trunkname at 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 at 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}

--
This message was sent by Atlassian JIRA
(v6.2#6252)