[asterisk-bugs] [JIRA] (ASTERISK-29844) pjsip logs, probably pcaps, incorrect packet contents

[Tony Wooster (JIRA)]

Tony Wooster created ASTERISK-29844:
---------------------------------------

             Summary: pjsip logs, probably pcaps, incorrect packet contents
                 Key: ASTERISK-29844
                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-29844
             Project: Asterisk
          Issue Type: Bug
      Security Level: None
          Components: Resources/res_pjsip_logger
    Affects Versions: 18.8.0
            Reporter: Tony Wooster


The pjsip logger logs both textually and can emit pcap-format captures of received SIP messages. On occasion, it appears to output incorrect packet data, showing output of several SIP packets in a single log line.

As an example, take a look at this (somewhat reformatted, and anonymized), log capture:

{noformat}
<--- Received SIP request (611 bytes) from TCP:192.168.125.1:40499 --->
INVITE sip:xxxxxxxxx at 10.241.240.166;user=phone SIP/2.0
Record-Route: <sip:192.168.125.1;transport=tcp;r2=on;lr;nat=yes>
Record-Route: <sip:10.241.240.166;r2=on;lr;nat=yes>
Via: SIP/2.0/TCP 192.168.125.1;branch=z9hG4bKfc48.81e023d5054cfc91973b6cc82985af44.0
Via: SIP/2.0/UDP 10.150.16.68:5071;rport=5071;branch=z9hG4bKrbmvcn6vr4212o2v61x2o1524;X-DispMsg=1406
Call-ID: k4bxn2ov3ov4lvbncb66mkol6oo6xrkl at 10.18.5.64
From: "xxxxxxxxx"<sip:xxxxxxxxx at 10.150.16.68;transport=udp;user=phone>;tag=b33r3b6v-CC-1052-OFC-215
To: "xxxxxxxxx"<sip:xxxxxxxxx at 10.241.240.166;transport=udp;user=phone>
CSeq: 1 INVITE
P-Access-Network-Info: GEN-ACCESS;"area-number=+xxxxxxxxxxxx"
Max-Forwards: 69
Contact: <sip:10.150.16.68:5060;alias=10.150.16.68~5071~1>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,INFO,PRACK,NOTIFY,MESSAGE,UPDATE
P-Asserted-Identity: <tel:xxxxxxxxx>
P-Early-Media: supported
Supported: 100rel,timer,histinfo,precondition
Min-SE: 90
Session-Expires: 1800;refresher=uac
Content-Length: 712
Content-Type: application/sdp

v=0
o=HuaweiSoftx3000 1074236091 1074236092 IN IP4 192.168.125.1
s=SipCall
c=IN IP4 192.168.125.1
t=0 0
m=audio 43494 RTP/AVP 108 105 3 96 106 101 8 116
a=rtpmap:108 AMR/8000
a=fmtp:108 mode-set=0,2,4,7;mode-change-neighbor=1;mode-change-period=2
a=rtpmap:105 GSM-EFR/8000
a=rtpmap:3 GSM/8000
a=rtpmap:96 AMR/8000
a=fmtp:96 mode-set=0,2,4;mode-change-neighbor=1;mode-change-period=2
a=rtpmap:106 GSM-HR/8000
a=rtpmap:101 AMR-WB/8000
a=fmtp:101 mode-set=0,1,2,8
a=rtpmap:8 PCMA/8000
a=rtpmap:116 telephone-event/8000
a=ptime:20
a=maxptime:20
a=curr:qos local sendrecv
a=curr:qos remote none
a=des:qos mandatory local sendrecv
a=des:qos optional remote sendrecv
a=3gOoBTC
a=nortpproxy:yes
BYE sip:192.168.125.10:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.125.1;branch=z9hG4bKe5a1.55acf2e6fb99b7f2fe7faf3019ac39b6.0
Via: SIP/2.0/UDP 10.150.16.68:5071;rport=5071;branch=z9hG4bK1i03bkiiwi82i1bja8k3cphap;X-DispMsg=1406
Call-ID: 3b2krrccij18l3w83k2ibpkjc0hlhal0 at 10.18.5.64
From: "xxxxxxxxx"<sip:xxxxxxxxx at 10.150.16.68;transport=udp;user=phone>;tag=iww23a8b-CC-1035-OFC-215
To: "xxxxxxxxx"<sip:xxxxxxxxx at 10.241.240.166;transport=udp;user=phone>;tag=a82de1b9-196b-416a-98fc-a8b84d97e641
CSeq: 3 BYE
Max-Forwards: 69
Reason: Q.850;cause=16;text="Normal call clearing"
Content-Length: 0

INVITE sip:xxxxxxxxx at 10.241.240.166;user=phone SIP/2.0
Record-Route: <sip:192.168.125.1;transport=tcp;r2=on;lr;nat=yes>
Record-Route: <sip:10.241.240.166;r2=on;lr;nat=yes>
... etc, continues until end of packet buffer ...
{noformat}

As you can see, the received length (611 bytes) definitely doesn't correspond to the overall output, nor does it correspond to the typical length of an `INVITE` (~1700 bytes, from what I've seen). It looks more like it's corresponding to the `BYE` that's crushed right up to the end of the first `INVITE` in the output.

Looking at the code (`res/res_pjsip_logger.c`), I think this is because logging (and pcap both!) have bugs. They reference `pkt_info.packet` -- the start of the packet buffer -- rather than `msg_info.msg_buf` -- the start of the current message -- and textual logging doesn't use the `msg_info.len`.

I don't have Gerrit access yet, still awaiting legal approval, but hey, I think this is the fix I think will work:

{noformat}
diff --git a/res/res_pjsip_logger.c b/res/res_pjsip_logger.c
index 957020f8a0..7641308761 100644
--- a/res/res_pjsip_logger.c
+++ b/res/res_pjsip_logger.c
@@ -309,16 +309,17 @@ static pj_bool_t logging_on_rx_msg(pjsip_rx_data *rdata)
        ao2_unlock(default_logger);

        if (default_logger->log_to_verbose) {
-               ast_verbose("<--- Received SIP %s (%d bytes) from %s:%s --->\n%s\n",
+               ast_verbose("<--- Received SIP %s (%d bytes) from %s:%s --->\n%.*s\n",
                        rdata->msg_info.msg->type == PJSIP_REQUEST_MSG ? "request" : "response",
                        rdata->msg_info.len,
                        rdata->tp_info.transport->type_name,
                        pj_sockaddr_print(&rdata->pkt_info.src_addr, buffer, sizeof(buffer), 3),
-                       rdata->pkt_info.packet);
+                       rdata->msg_info.len,
+                       rdata->msg_info.msg_buf);
        }

        if (default_logger->log_to_pcap) {
-               pjsip_logger_write_to_pcap(default_logger, rdata->pkt_info.packet, rdata->msg_info.len,
+               pjsip_logger_write_to_pcap(default_logger, rdata->msg_info.msg_buf, rdata->msg_info.len,
                        &rdata->pkt_info.src_addr, NULL);
        }
{noformat}

This is the first time I've dug into Asterisk and PJSIP code, and the patch is untested, however, so I could be wrong. Either way, something is wrong with the log output.

P.s.: I'd follow the guidelines and attach log output rather than pasting it in the description, but there's no place to do that while creating an issue.



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