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

Speed Dial Dave (JIRA) noreply at issues.asterisk.org
Wed Sep 2 08:16:43 CDT 2020 

Speed Dial Dave created ASTERISK-29063:
------------------------------------------

             Summary: 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)

More information about the asterisk-bugs mailing list