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

Fri Jan 7 09:42:07 CST 2022

    [ https://issues.asterisk.org/jira/browse/ASTERISK-29844?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=257672#comment-257672 ] 

Asterisk Team commented on ASTERISK-29844:
------------------------------------------

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.

Please note that by submitting data, code, or documentation to Sangoma through JIRA, you accept the Terms of Use present at [https://www.asterisk.org/terms-of-use/|https://www.asterisk.org/terms-of-use/].

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