[asterisk-bugs] [JIRA] (ASTERISK-29063) PJSIP leaves endpoint in Unavail state when successful qualification happens right after Unavail state change
Joshua C. Colp (JIRA)
noreply at issues.asterisk.org
Wed Sep 2 08:40:43 CDT 2020
[ https://issues.asterisk.org/jira/browse/ASTERISK-29063?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Joshua C. Colp updated ASTERISK-29063:
--------------------------------------
Issue Type: Improvement (was: Bug)
> 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: Improvement
> 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