INVITE from extension being dropped

Asterisk Asterisk SIP
1

I’m trying to debug an extension which cannot make outgoing calls (incoming calls work fine). I did some packet captures and turned on the pjsip logger.

This is the packet flow I am seeing when the problematic extension tries to make an outgoing call:

Screen Shot 2020-11-01 at 5.24.09 PM
Screen Shot 2020-11-01 at 5.24.09 PM876×416 60 KB

When I try from a different extension where outgoing calls work, this is the flow I am seeing:

Screen Shot 2020-11-01 at 5.27.42 PM
Screen Shot 2020-11-01 at 5.27.42 PM860×542 62.5 KB

When I look at the output of the pjsip logger in asterisk, I don’t even see the subsequent INVITE packets (containing authorization info), but I do see them in the tcpdump capture on the host running asterisk. So it almost seems as if asterisk is ignoring/dropping these INVITE packets with authorization from this extension.

Has anyone seen this before or know how to debug further?

2

They are being sent to the wrong place, or you don’t have a sufficient logging level and they are being sent with the wrong CSEQ.

W’e need to see destination addresses, and full headers to understand more.

3

@david551 How do I increase the logging level?
The headers seem to match a different extension that works fine where the 2nd INVITE (with auth) doesn’t get ignored by Asterisk.

I’m taking the packet capture on the Asterisk server, so I know they are making it there.

Here are the full headers for the non-working extension:

1st INVITE from extension (without authorization):

Frame 404: 1433 bytes on wire (11464 bits), 1433 bytes captured (11464 bits)
Ethernet II, Src: xx:xx:xx:xx:xx:xx (xx:xx:xx:xx:xx:xx), Dst: yy:yy:yy:yy:yy:yy (yy:yy:yy:yy:yy:yy)
Internet Protocol Version 4, Src: x.x.x.x, Dst: y.y.y.y
User Datagram Protocol, Src Port: 5060, Dst Port: xx
Session Initiation Protocol (INVITE)
    Request-Line: INVITE sip:xxx@xxxx:xx SIP/2.0
    Message Header
        Via: SIP/2.0/UDP 10.10.0.99:5060;branch=z9hG4bK968240927;rport
        From: "xxx" <sip:1501@xxxx:xx>;tag=407085146
        To: <sip:xxx@xxxx:xx>
        Call-ID: 239187605-5060-4@BA.BA.A.JJ
        [Generated Call-ID: 239187605-5060-4@BA.BA.A.JJ]
        CSeq: 20 INVITE
        Contact: "xxx" <sip:1501@10.10.0.99:5060>
        Max-Forwards: 70
        User-Agent: Grandstream HT801 1.0.19.11
        Privacy: none
        P-Preferred-Identity: "xxx" <sip:1501@xxxx:xx>
        P-Access-Network-Info: IEEE-EUI-48;eui-48-addr=xx-xx-xx-xx-xx-xx
        P-Emergency-Info: IEEE-EUI-48;eui-48-addr=yy-yy-yy-yy-yy-yy
        Supported: replaces, path, timer, eventlist
        Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE
        Content-Type: application/sdp
        Accept: application/sdp, application/dtmf-relay
        Content-Length:   448

Unauthorized response from Asterisk:

Frame 405: 567 bytes on wire (4536 bits), 567 bytes captured (4536 bits)
Ethernet II, Src: xx:xx:xx:xx:xx:xx (xx:xx:xx:xx:xx:xx), Dst: yy:yy:yy:yy:yy:yy (yy:yy:yy:yy:yy:yy)
Internet Protocol Version 4, Src: y.y.y.y, Dst: x.x.x.x
User Datagram Protocol, Src Port: xx, Dst Port: 5060
Session Initiation Protocol (401)
    Status-Line: SIP/2.0 401 Unauthorized
    Message Header
        Via: SIP/2.0/UDP 10.10.0.99:5060;rport=5060;received=x.x.x.x;branch=z9hG4bK968240927
        Call-ID: 239187605-5060-4@BA.BA.A.JJ
        [Generated Call-ID: 239187605-5060-4@BA.BA.A.JJ]
        From: "xxx" <sip:1501@xxxx>;tag=407085146
        To: <sip:13058904001@xxxx>;tag=z9hG4bK968240927
        CSeq: 20 INVITE
        WWW-Authenticate: Digest realm="asterisk",nonce="xxxxx",opaque="yyyyy",algorithm=md5,qop="auth"
        Server: VitalPBX
        Content-Length:  0

ACK from extension:

Frame 407: 408 bytes on wire (3264 bits), 408 bytes captured (3264 bits)
Ethernet II, Src: xx:xx:xx:xx:xx:xx (xx:xx:xx:xx:xx:xx), Dst: yy:yy:yy:yy:yy:yy (yy:yy:yy:yy:yy:yy)
Internet Protocol Version 4, Src: x.x.x.x, Dst: y.y.y.y
User Datagram Protocol, Src Port: 5060, Dst Port: xx
Session Initiation Protocol (ACK)
    Request-Line: ACK sip:xxx@xxxx:xx SIP/2.0
    Message Header
        Via: SIP/2.0/UDP 10.10.0.99:5060;branch=z9hG4bK968240927;rport
        From: "xxx" <sip:1501@xxxx>;tag=407085146
        To: <sip:xxx@xxxx>;tag=z9hG4bK968240927
        Call-ID: 239187605-5060-4@BA.BA.A.JJ
        [Generated Call-ID: 239187605-5060-4@BA.BA.A.JJ]
        CSeq: 20 ACK
        Content-Length: 0

2nd INVITE from extension (with authorization) - ignored by Asterisk:

Frame 408: 1514 bytes on wire (12112 bits), 1514 bytes captured (12112 bits)
Ethernet II, Src: xx:xx:xx:xx:xx:xx (xx:xx:xx:xx:xx:xx), Dst: yy:yy:yy:yy:yy:yy (yy:yy:yy:yy:yy:yy)
Internet Protocol Version 4, Src: x.x.x.x, Dst: y.y.y.y
User Datagram Protocol, Src Port: 5060, Dst Port: xx
Session Initiation Protocol (INVITE)
    Request-Line: INVITE sip:xxx@xxxx:xx SIP/2.0
    Message Header
        Via: SIP/2.0/UDP 10.10.0.99:5060;branch=z9hG4bK1511636959;rport
        From: "xxx" <sip:1501@xxxx:xx>;tag=407085146
        To: <sip:xxx@xxxx:xx>
        Call-ID: 239187605-5060-4@BA.BA.A.JJ
        [Generated Call-ID: 239187605-5060-4@BA.BA.A.JJ]
        CSeq: 21 INVITE
        Contact: "xxx" <sip:1501@10.10.0.99:5060>
         [truncated]Authorization: Digest username="1501", realm="asterisk", nonce="xxxxx", uri="sip:xxx@xxxx:xx", response="xxxxx", algorithm=md5
        Max-Forwards: 70
        User-Agent: Grandstream HT801 1.0.19.11
        Privacy: none
        P-Preferred-Identity: "xxx" <sip:1501@xxxx:xx>
        P-Access-Network-Info: IEEE-EUI-48;eui-48-addr=xx-xx-xx-xx-xx-xx
        P-Emergency-Info: IEEE-EUI-48;eui-48-addr=yy-yy-yy-yy-yy-yy
        Supported: replaces, path, timer, eventlist
        Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE
        Content-Type: application/sdp
        Accept: application/sdp, application/dtmf-relay
        Content-Length:   448
4

The contact header is going to break things, but only later in the call. The source device appears to be behind NAT, but is sending rport to deal with that problem. However, rport only deals with immediate responses, and the private address in the Contact header will break things if Asterisk has to send BYE or re-INVITE.

I can’t see anything that would break the initial handshake.

See https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information re logging levels.

5

@david551
I turned on verbose logs from Asterisk and output to a file. Asterisk does not even process or log the subsequent INVITE packets from the extension containing the authorization info:

[2020-11-02 18:42:47] VERBOSE[1479] res_pjsip_logger.c: <--- Received SIP request (1394 bytes) from UDP:x.x.x.x:5060 --->
INVITE sip:0123@xxxx:12345 SIP/2.0
Via: SIP/2.0/UDP 10.10.0.99:5060;branch=z9hG4bK2034858441;rport
From: "xxx" <sip:1501@xxxx:12345>;tag=1208118057
To: <sip:0123@xxxx:12345>
Call-ID: 45845441-5060-13@BA.BA.A.JJ
CSeq: 110 INVITE
Contact: "xxx" <sip:1501@10.10.0.99:5060>
Max-Forwards: 70
User-Agent: Grandstream HT801 1.0.19.11
Privacy: none
P-Preferred-Identity: "xxx" <sip:1501@xxxx:12345>
P-Access-Network-Info: IEEE-EUI-48;eui-48-addr=xx-xx-xx-xx-xx-xx
P-Emergency-Info: IEEE-EUI-48;eui-48-addr=yy-yy-yy-yy-yy-yy
Supported: replaces, path, timer, eventlist
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length:   448

v=0
o=1501 8000 8000 IN IP4 10.10.0.99
s=SIP Call
c=IN IP4 10.10.0.99
t=0 0
m=audio 5004 RTP/AVP 0 8 4 18 2 97 123 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:8 PCMA/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:2 G726-32/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=20
a=rtpmap:123 opus/48000/2
a=fmtp:123 maxplaybackrate=16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16,32-36,54

[2020-11-02 18:42:47] VERBOSE[22650] res_pjsip_logger.c: <--- Transmitting SIP response (529 bytes) to UDP:x.x.x.x:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.10.0.99:5060;rport=5060;received=x.x.x.x;branch=z9hG4bK2034858441
Call-ID: 45845441-5060-13@BA.BA.A.JJ
From: "xxx" <sip:1501@xxxx>;tag=1208118057
To: <sip:0123@xxxx>;tag=z9hG4bK2034858441
CSeq: 110 INVITE
WWW-Authenticate: Digest realm="asterisk",nonce="xx/xx",opaque="xx",algorithm=md5,qop="auth"
Server: VitalPBX
Content-Length:  0


[2020-11-02 18:42:47] VERBOSE[1479] res_pjsip_logger.c: <--- Received SIP request (370 bytes) from UDP:x.x.x.x:5060 --->
ACK sip:0123@xxxx:12345 SIP/2.0
Via: SIP/2.0/UDP 10.10.0.99:5060;branch=z9hG4bK2034858441;rport
From: "xxx" <sip:1501@xxxx>;tag=1208118057
To: <sip:0123@xxxx>;tag=z9hG4bK2034858441
Call-ID: 45845441-5060-13@BA.BA.A.JJ
CSeq: 110 ACK
Content-Length: 0
6

Anyone know why the SIP INVITE packets would make it to the network interface of the PBX, but not to Asterisk?

7

iptables? IIRC, tcpdump sees before iptables and applications see after.

8

@sedwards I was thinking that, but the odd thing is that only the subsequent INVITE packets after Asterisk sends 401 Unauthorized are being dropped. The ACK to the 401 is not dropped. And no other SIP packets from the extension seem to be dropped.

Is there any way to log if iptables are dropping anything?

9

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.