[asterisk-users] Asterisk 18.12.1 to 18.15.0 upgrade seems to have introduced a behavior where PJSIP is unable to send a response to OPTIONS (seems to resolve after anywhere a period of time)

Wed Dec 7 09:34:24 CST 2022

On Wed, Dec 7, 2022 at 11:26 AM Dan Cropp <dan at amtelco.com> wrote:

> On two VMs, we encounter a strange behavior when we upgrade from 18.12.1
> to 18.15.0 (also tried 18.15.1 last night).
>
> When we roll the VMs back to 18.12.1, we don’t see the behavior repeat.
>
>
>
> We have a Kamailio VM front ending the asterisk.
>
>
>
> It sends OPTIONS messages periodically.
>
>
>
> After startup (and also after reloading configuration settings), we see
> periods where the response can’t be sent.
>
> After a period of time, it suddenly starts working.
>
>
>
> Here is a sample of it failing, followed by it working for the next
> OPTIONS message received.
>
>
>
>
>
> [12/06 20:40:55.797] VERBOSE[186673] res_pjsip_logger.c: <--- Received SIP
> request (392 bytes) from UDP:192.168.12.10:5060 --->
>
> OPTIONS sip:box_b at 192.168.12.120:5060 SIP/2.0
>
> Via: SIP/2.0/UDP
> 192.168.12.10;branch=z9hG4bK10f.4d4a0332000000000000000000000000.0
>
> To: sip:box_b at 192.168.12.120:5060
>
> From:
> sip:kamailio at 192.168.12.10;tag=f1bcd6806a18022e516c4139c95990f1-92130971
>
> CSeq: 10 OPTIONS
>
> Call-ID: 5ff0944d46b1692c-2858982 at 192.168.12.10
>
> Max-Forwards: 70
>
> Content-Length: 0
>
> User-Agent: Genesis Proxy
>
>
>
>
>
> [12/06 20:40:55.797] DEBUG[186673] res_pjsip/pjsip_distributor.c: Could
> not find matching transaction for Request msg OPTIONS/cseq=10
> (rdata0x7f88380385c8)
>
> [12/06 20:40:55.797] DEBUG[186673] res_pjsip/pjsip_distributor.c:
> Calculated serializer pjsip/distributor-000002f9 to use for Request msg
> OPTIONS/cseq=10 (rdata0x7f88380385c8)
>
> [12/06 20:40:55.797] DEBUG[194583] res_pjsip_endpoint_identifier_ip.c:
> Source address 192.168.12.10:5060 does not match identify 'identify140'
>
> [12/06 20:40:55.797] DEBUG[194583] res_pjsip_endpoint_identifier_ip.c:
> Source address 192.168.12.10:5060 matches identify 'identify158'
>
> [12/06 20:40:55.797] DEBUG[194583] res_pjsip_endpoint_identifier_ip.c:
> Identify 'identify158' SIP message matched to endpoint Kamailio
>
> [12/06 20:40:55.797] DEBUG[194583] res_pjsip/pjsip_resolver.c: Performing
> SIP DNS resolution of target '192.168.12.10'
>
> [12/06 20:40:55.797] DEBUG[194583] res_pjsip/pjsip_resolver.c: Transport
> type for target '192.168.12.10' is 'UDP transport'
>
> [12/06 20:40:55.797] DEBUG[194583] res_pjsip/pjsip_resolver.c: Target
> '192.168.12.10' is an IP address, skipping resolution
>
>
>
> [12/06 20:40:55.797] ERROR[194583] res_pjsip/pjsip_options.c: Unable to
> send response (-1)
>
>
>
>
>
> Four minutes later (and ever since then), it’s been fine responding to the
> OPTIONS.
>
>
>
> [12/06 20:40:59.797] VERBOSE[186673] res_pjsip_logger.c: <--- Received SIP
> request (392 bytes) from UDP:192.168.12.10:5060 --->
>
> OPTIONS sip:box_b at 192.168.12.120:5060 SIP/2.0
>
> Via: SIP/2.0/UDP
> 192.168.12.10;branch=z9hG4bK10f.4d4a0332000000000000000000000000.0
>
> To: sip:box_b at 192.168.12.120:5060
>
> From:
> sip:kamailio at 192.168.12.10;tag=f1bcd6806a18022e516c4139c95990f1-92130971
>
> CSeq: 10 OPTIONS
>
> Call-ID: 5ff0944d46b1692c-2858982 at 192.168.12.10
>
> Max-Forwards: 70
>
> Content-Length: 0
>
> User-Agent: Genesis Proxy
>
>
>
> [12/06 20:40:59.797] DEBUG[186673] res_pjsip/pjsip_distributor.c: Could
> not find matching transaction for Request msg OPTIONS/cseq=10
> (rdata0x7f8838027c18)
>
> [12/06 20:40:59.797] DEBUG[186673] res_pjsip/pjsip_distributor.c:
> Calculated serializer pjsip/distributor-000002f9 to use for Request msg
> OPTIONS/cseq=10 (rdata0x7f8838027c18)
>
> [12/06 20:40:59.797] DEBUG[194583] res_pjsip_endpoint_identifier_ip.c:
> Source address 192.168.12.10:5060 does not match identify 'identify140'
>
> [12/06 20:40:59.797] DEBUG[194583] res_pjsip_endpoint_identifier_ip.c:
> Source address 192.168.12.10:5060 matches identify 'identify158'
>
> [12/06 20:40:59.797] DEBUG[194583] res_pjsip_endpoint_identifier_ip.c:
> Identify 'identify158' SIP message matched to endpoint Kamailio
>
> [12/06 20:40:59.798] DEBUG[194583] res_pjsip/pjsip_resolver.c: Performing
> SIP DNS resolution of target '192.168.12.10'
>
> [12/06 20:40:59.798] DEBUG[194583] res_pjsip/pjsip_resolver.c: Transport
> type for target '192.168.12.10' is 'UDP transport'
>
> [12/06 20:40:59.798] DEBUG[194583] res_pjsip/pjsip_resolver.c: Target
> '192.168.12.10' is an IP address, skipping resolution
>
>
>
> [12/06 20:40:59.798] VERBOSE[194583] res_pjsip_logger.c: <--- Transmitting
> SIP response (896 bytes) to UDP:192.168.12.10:5060 --->
>
> SIP/2.0 200 OK
>
> Via: SIP/2.0/UDP
> 192.168.12.10;received=192.168.12.10;branch=z9hG4bK10f.4d4a0332000000000000000000000000.0
>
> Call-ID: 5ff0944d46b1692c-2858982 at 192.168.12.10
>
> From:
> sip:kamailio at 192.168.12.10;tag=f1bcd6806a18022e516c4139c95990f1-92130971
>
> To:
> sip:box_b at 192.168.12.120;tag=z9hG4bK10f.4d4a0332000000000000000000000000.0
>
> CSeq: 10 OPTIONS
>
> Accept: application/sdp, application/dialog-info+xml,
> application/simple-message-summary, application/xpidf+xml,
> application/cpim-pidf+xml, application/pidf+xml, application/pidf+xml,
> application/dialog-info+xml, application/simple-message-summary,
> message/sipfrag;version=2.0
>
> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE,
> CANCEL, UPDATE, PRACK, MESSAGE, REFER
>
> Supported: 100rel, timer, replaces, norefersub
>
> Accept-Encoding: identity
>
> Accept-Language: en
>
> Server: Asterisk PBX 18.15.1
>
> Content-Length:  0
>
>
>
> Portion of the pjsip.conf settings…
>
>
>
> [Kamailio]
>
> type = aor
>
> authenticate_qualify = yes
>
> contact = sip:192.168.10.235
>
> ;outbound_proxy=sip:192.168.12.10
>
>
>
> [identify158]
>
> type = identify
>
> endpoint = Kamailio
>
> match = 192.168.12.10
>
>
>
> [Kamailio]
>
> type = endpoint
>
> context = IS
>
> transport = transport1
>
> aors = Kamailio
>
> accountcode = 29
>
> dtmf_mode = inband
>
> device_state_busy_at = 48
>
> force_rport = no
>
> moh_passthrough = no
>
> identify_by = username,ip,header
>
> disallow = all
>
> allow = ulaw
>
> asymmetric_rtp_codec = yes
>
> acl = acl6
>
> outbound_proxy=sip:192.168.12.10
>
>
>
> Was there some configuration change introduced after 18.12.1 that I missed?
>

Any such things would be in the upgrade notes, but no.

>
>
> Any thoughts?
>

 I haven't seen this before, and haven't seen any other reports of it so
far. The OPTIONS code itself hasn't changed between the two. There was a
fix for a crash in send_stateful_response so adding log messages to the
error cases is likely needed to see in particular which one is failing.

-- 
Joshua C. Colp
Asterisk Project Lead
Sangoma Technologies
Check us out at www.sangoma.com and www.asterisk.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20221207/5cab23f5/attachment-0001.html>