[Home]

Summary:ASTERISK-29844: res_pjsip_logger: Logger output can show multiple packets on connection oriented transports
Reporter:Tony Wooster (twooster)Labels:
Date Opened:2022-01-07 09:41:27.000-0600Date Closed:2022-02-17 12:00:01.000-0600
Priority:MinorRegression?
Status:Closed/CompleteComponents:Resources/res_pjsip_logger
Versions:18.8.0 Frequency of
Occurrence		Occasional
Related
Issues:
Environment:Attachments:
Description: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@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@10.18.5.64
From: "xxxxxxxxx"<sip:xxxxxxxxx@10.150.16.68;transport=udp;user=phone>;tag=b33r3b6v-CC-1052-OFC-215
To: "xxxxxxxxx"<sip:xxxxxxxxx@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@10.18.5.64
From: "xxxxxxxxx"<sip:xxxxxxxxx@10.150.16.68;transport=udp;user=phone>;tag=iww23a8b-CC-1035-OFC-215
To: "xxxxxxxxx"<sip:xxxxxxxxx@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@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:

<inline patch removed>

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.
Comments:By: Asterisk Team (asteriskteam) 2022-01-07 09:41:28.862-0600

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/].
By: Joshua C. Colp (jcolp) 2022-01-07 09:44:58.621-0600

Things have to be attached after creation, as you need to specify whether something is code or not.
By: Joshua C. Colp (jcolp) 2022-01-07 09:55:06.204-0600

Marking waiting for feedback until license agreement is accepted and patch attached.
By: Tony Wooster (twooster) 2022-01-07 10:09:42.472-0600

No worries, I'll wait until legal approves before re-attaching the patch. I assume I'll receive an email once that has been approved? Visiting the "sign a license agreement page" just says I  "already have a license that is approved or pending review."
By: Joshua C. Colp (jcolp) 2022-01-07 10:17:55.968-0600

Correct, you should.
By: Asterisk Team (asteriskteam) 2022-01-21 12:00:00.471-0600

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines
By: Tony Wooster (twooster) 2022-01-21 12:04:24.132-0600

This is still an issue and should not be closed. I haven't heard back from your legal team. The patch I supplied is running in production for us (built on top of 18.8.0 because 18.9.0 deadlocks) and working fine.
By: Asterisk Team (asteriskteam) 2022-01-21 12:04:24.263-0600

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Joshua C. Colp (jcolp) 2022-01-25 08:15:20.751-0600

Your license has been accepted and you can now attach it and put it up for review.
By: Asterisk Team (asteriskteam) 2022-02-17 12:00:00.982-0600

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines