[asterisk-bugs] [JIRA] (ASTERISK-29844) res_pjsip_logger: Logger output can show multiple packets on connection oriented transports

[Kevin Harwell (JIRA)]

     [ https://issues.asterisk.org/jira/browse/ASTERISK-29844?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Kevin Harwell updated ASTERISK-29844:
-------------------------------------

    Assignee: Tony Wooster
      Status: Waiting for Feedback  (was: Triage)

> res_pjsip_logger: Logger output can show multiple packets on connection oriented transports
> -------------------------------------------------------------------------------------------
>
>                 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
>            Assignee: 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:
> <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.



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