1465253 - rtplogger MOZ_LOG setting truncates lines

Status: RESOLVED FIXED

(Core :: WebRTC, defect, P2)

Description

[Tim Haloun]

User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.139 Safari/537.36

Steps to reproduce:

Turn up webrtc logging as instructed in https://blog.mozilla.org/webrtc/debugging-encrypted-rtp-is-more-fun-than-it-used-to-be/ and make a call on hangouts or similar service. Examine log file.


Actual results:

The logfile contains packet headers with scrubbed contents, plus metadata indicating rtp versus rtcp.  Except, for larger packets, the text is cut off, critically leaving off the metadata, making it impossible to attribute the packet to one media stream or another.

Example:
2018-05-24 20:20:40.603572 UTC - [51016:Socket Thread]: D/signaling [Socket Thread|SrtpFlow] SrtpFlow.cpp:198: Successfully protected an SRTCP packet of len 94
2018-05-24 20:20:40.603574 UTC - [51016:Socket Thread]: D/signaling [Socket Thread|MediaPipeline] MediaPipeline.cpp:1878: ae5575fa75870621| Receive video sending RTCP packet
2018-05-24 20:20:40.608196 UTC - [51016:Unnamed thread 0x7fb102af1b80]: V/signaling [|WebrtcVideoSessionConduit] VideoConduit.cpp:2179: SendRtp Sent RTP Packet seq 9943, len 1193, SSRC 453575858 (0x1b0904b2)
2018-05-24 20:20:40.608376 UTC - [51016:Socket Thread]: D/signaling [Socket Thread|RtpLogger] RtpLogger.cpp:76: O 13:20:40.608328  000000 90 78 26 d7 12 4d e0 78 1b 09 04 b2 be de 00 03 12 1c b8 52 40 71 34 6d 69 64 5f 30 90 e0 9c fd 06 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0
2018-05-24 20:20:40.608423 UTC - [51016:Socket Thread]: D/signaling [Socket Thread|SrtpFlow] SrtpFlow.cpp:152: Successfully protected an SRTP packet of len 1203
2018-05-24 20:20:40.608425 UTC - [51016:Socket Thread]: D/signaling [Socket Thread|MediaPipeline] MediaPipeline.cpp:1878: ae5575fa75870621| Transmit video[{02e9ccc8-40cd-4363-a379-bc9c78203187}] sending RTP packet




Expected results:

All the packet should have been written.  Or in lieu, some of the redundant 00 data should have been elided.  In that case the packet sizes from any reconstructed pcaps would be wrong but the number and the important header parts would be correct.

Comment 1

[u554753]

Per Bug 1431543, triaging this as a Core: WebRTC issue.

Comment 2

[Paul Adenot (:padenot)]

Nils, who should have a look at this one ?

Comment 3

[Nils Ohlmeier [:drno]]

Attachment: Bug 1465253: use postfix as prefix when logging and log in clear.

Review commit: https://reviewboard.mozilla.org/r/251554/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/251554/

Comment 4

[Byron Campen [:bwc]]

Comment on attachment 8986096 [details]
Bug 1465253: use postfix as prefix when logging and log in clear.

https://reviewboard.mozilla.org/r/251554/#review257928

Hmm. This is probably ok from a security perspective.

::: media/webrtc/signaling/src/mediapipeline/RtpLogger.cpp:37
(Diff revision 1)
>  bool RtpLogger::IsPacketLoggingOn() {
>    return CSFLogTestLevel(CSF_LOG_DEBUG);
>  }
>  
>  void RtpLogger::LogPacket(const MediaPacket& packet, bool input,
>                            size_t headerLength, std::string desc) {

It seems that |headerLength| is no longer used.

Comment 5

[Nils Ohlmeier [:drno]]

Comment on attachment 8986096 [details]
Bug 1465253: use postfix as prefix when logging and log in clear.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/251554/diff/1-2/

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3c53e83acb19
use postfix as prefix when logging and log in clear. r=bwc

Comment 7

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/3c53e83acb19