mediasoup

/ home / Documentation / v3 / mediasoup / Debugging

mediasoup v3 Debugging

Log Levels

mediasoup uses the debug module to log internal information. The JavaScript layer of mediasoup produces its own logs and also collects logs generated by the media worker subprocesses.

There are four log severities:

All the logs generated by mediasoup have a namespace starting with “mediasoup” plus colon, followed by the log severity in upper case plus colon (just if “warn” or “error”), and followed by the internal component name (if any) and the log message.

Log messages generated by media worker subprocesses deserve a special treatment. They are just generated if their severity is equal or higher than the given logLevel, but they are just logged if the value of the DEBUG environment variable matches their namespace.

Logs generated by the media worker subprocesses can have the following namespaces (where NNNNN is the subprocess PID):

Logging example once mediasoup is started:

mediasoup:worker[pid:80653] mediasoup-worker::main() | starting mediasoup-worker process [version:3.0.0-dev] +0ms
mediasoup:worker[pid:80653] mediasoup-worker::main() | little-endian CPU detected +0ms
mediasoup:worker[pid:80653] mediasoup-worker::main() | 64 bits architecture detected +1ms
mediasoup:worker[pid:80653] Settings::PrintConfiguration() | <configuration> +0ms
mediasoup:worker[pid:80653] Settings::PrintConfiguration() |   logLevel            : debug +0ms
mediasoup:worker[pid:80653] Settings::PrintConfiguration() |   logTags             : info,simulcast +0ms
mediasoup:worker[pid:80653] Settings::PrintConfiguration() |   rtcMinPort          : 40000 +0ms
mediasoup:worker[pid:80653] Settings::PrintConfiguration() |   rtcMaxPort          : 49999 +0ms
mediasoup:worker[pid:80653] Settings::PrintConfiguration() | </configuration> +0ms
mediasoup:worker[pid:80653] DepLibUV::PrintVersion() | libuv version: "1.27.0" +0ms
mediasoup:worker[pid:80653] DepOpenSSL::ClassInit() | openssl version: "OpenSSL 1.1.1b  26 Feb 2019" +0ms
mediasoup:worker[pid:80653] DepLibSRTP::ClassInit() | libsrtp version: "libsrtp 2.0.0" +0ms
mediasoup:Worker worker process running [pid:80653] +28ms
mediasoup:Worker createRouter() +1m
mediasoup:Channel[pid:80653] request() [method:worker.createRouter, id:1] +1m
mediasoup:Channel[pid:80653] request succeeded [method:worker.createRouter, id:1] +4ms
mediasoup:Router constructor() +0ms
mediasoup:Channel[pid:80653] request() [method:router.createWebRtcTransport, id:3] +360ms
mediasoup:Channel[pid:80653] request succeeded [method:router.createWebRtcTransport, id:3] +4ms
mediasoup:Transport constructor() +0ms
mediasoup:WebRtcTransport constructor() +0ms
mediasoup:Transport setMaxIncomingBitrate() [bitrate:1500000] +4ms
mediasoup:Channel[pid:80653] request() [method:transport.setMaxIncomingBitrate, id:4] +8ms
mediasoup:Channel[pid:80653] request succeeded [method:transport.setMaxIncomingBitrate, id:4] +2ms

Enable Logging

By default logging is turned off. In order to enable it, the DEBUG environment variable must be set before loading mediasoup.

Check the debug module documentation for further information regarding how to filter specific log messages based on namespace matching rules.

Examples

$ export DEBUG="mediasoup*"
$ node myapp.js

# or:

$ DEBUG="mediasoup*" node myapp.js
process.env.DEBUG = "mediasoup*"

const mediasoup = require("mediasoup");
$ DEBUG="*" node myapp.js
$ DEBUG="mediasoup*" node myapp.js
$ DEBUG="mediasoup:WARN:* mediasoup:ERROR:*" node myapp.js

Log Tags

Certain log categories can be enabled in runtime for debugging purposes by using logTags. Those tags just apply to logs generated by media worker subprocesses.

Remember: These logs are just generated if their severity is equal or higher than the given logLevel, but they are just logged if the value of the DEBUG environment variable matches their namespace.

Examples

$ DEBUG="mediasoup:WARN:* mediasoup:ERROR:*" node myapp.js
const mediasoup = require("mediasoup");

const worker = await mediasoup.createWorker(
  {
    logLevel : "warn",
    logTags  : [ "rtcp" ]
  });
$ DEBUG="mediasoup* *ERROR*" node myapp.js
const mediasoup = require("mediasoup");

const worker = await mediasoup.createWorker(
  {
    logLevel : "debug",
    logTags  : [ "ice", "dtls" ]
  });
worker.updateSettings(
  {
    logLevel : "warn",
    logTags  : [ "ice", "dtls" ]
  });

“trace” Event

Transports, producers and consumers provide a enableTraceEvent() method to enable the “trace” event for RTP/RTCP monitoring purposes:

Based on enabled types, here the information the “trace” event provides with:

Transport

transport.enableTraceEvent([ 'probation' ])

transport.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "out",
    "info": {
      "isKeyFrame": false,
      "marker": "false",
      "payloadSize": 360,
      "payloadType": 127,
      "sequenceNumber": 19244,
      "size": 384,
      "spatialLayer": 0,
      "ssrc": 1234,
      "temporalLayer": 0,
      "timestamp": 239090504,
      "wideSequenceNumber": 166
    },
    "timestamp": 1513191082,
    "type": "probation"
  }
});

transport.enableTraceEvent([ 'bwe' ])

transport.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "out",
    "info": {
      "availableBitrate": 1981250,
      "desiredBitrate": 1483574, 
      "effectiveDesiredBitrate": 1483574, 
      "maxBitrate": 2002824, 
      "maxPaddingBitrate": 1702400, 
      "minBitrate": 30000, 
      "startBitrate": 1981250, 
      "type": 'transport-cc'
    },
    "timestamp": 1513191082,
    "type": "bwe"
  }
});

Producer

producer.enableTraceEvent([ 'rtp' ])

producer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "in",
    "info": {
      "isKeyFrame": false,
      "marker": "true",
      "mid": "6",
      "payloadSize": 914,
      "payloadType": 96,
      "rid": "r1",
      "rrid": "r1",
      "sequenceNumber": 19694,
      "size": 942,
      "spatialLayer": 0,
      "ssrc": 27777256,
      "temporalLayer": 1,
      "timestamp": 1227771600,
      "wideSequenceNumber": 2413
    },
    "timestamp": 1513714260,
    "type": "rtp"
  }
});

producer.enableTraceEvent([ 'keyframe' ])

producer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "in",
    "info": {
      "isKeyFrame": true,
      "marker": "false",
      "mid": "2",
      "payloadSize": 1088,
      "payloadType": 96,
      "rid": "r2",
      "rrid": "r2",
      "sequenceNumber": 14176,
      "size": 1116,
      "spatialLayer": 0,
      "ssrc": 3838709357,
      "temporalLayer": 0,
      "timestamp": 3003475216,
      "wideSequenceNumber": 62
    },
    "timestamp": 1513798049,
    "type": "keyframe"
  }
});

When “keyframe” type is set, there won't be “trace” events with type “rtp” for keyframe packets but just with type “keyframe”.

producer.enableTraceEvent([ 'nack' ])

producer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "out",
    "info": {}
    "timestamp": 1544498146,
    "type": "nack"
  }
});

producer.enableTraceEvent([ 'pli' ])

producer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "out",
    "info": {
      "ssrc": 87654321
    }
    "timestamp": 1544498146,
    "type": "pli"
  }
});

producer.enableTraceEvent([ 'fir' ])

producer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "out",
    "info": {
      "ssrc": 95438003
    }
    "timestamp": 1544498155,
    "type": "fir"
  }
});

producer.enableTraceEvent([ 'sr' ])

producer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "out",
    "info": {
      "ssrc": 15438003,
      "ntp_sec": 768723434,
      "ntp_frac": 87876,
      "rtp_ts": 23768,
      "packet_count": 100,
      "octet_count": 200
    }
    "timestamp": 164498155,
    "type": "sr"
  }
});

Consumer

consumer.enableTraceEvent([ 'rtp' ])

consumer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "out",
    "info": {
      "isKeyFrame": false,
      "marker": "false",
      "payloadSize": 1,
      "payloadType": 100,
      "sequenceNumber": 6,
      "size": 21,
      "spatialLayer": 0,
      "ssrc": 198373608,
      "temporalLayer": 0,
      "timestamp": 54740510
    },
    "timestamp": 1514273430,
    "type": "rtp"
  }
});

consumer.enableTraceEvent([ 'keyframe' ])

consumer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "out",
    "info": {
      "isKeyFrame": true,
      "marker": "true",
      "payloadSize": 437,
      "payloadType": 101,
      "sequenceNumber": 1,
      "size": 465,
      "spatialLayer": 0,
      "ssrc": 185272966,
      "temporalLayer": 0,
      "timestamp": 936997226,
      "wideSequenceNumber": 17
    },
    "timestamp": 1514298020,
    "type": "keyframe"
  }
});

When “keyframe” type is set, there won't be “trace” events with type “rtp” for keyframe packets but just with type “keyframe”.

consumer.enableTraceEvent([ 'nack' ])

consumer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "in",
    "info": {}
    "timestamp": 1546498145,
    "type": "nack"
  }
});

consumer.enableTraceEvent([ 'pli' ])

consumer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "in",
    "info": {
      "ssrc": 5698432
    }
    "timestamp": 1544798444,
    "type": "pli"
  }
});

consumer.enableTraceEvent([ 'fir' ])

consumer.on('trace', (trace) =>
{
  // trace =>
  {
    "direction": "in",
    "info": {
      "ssrc": 776452943
    }
    "timestamp": 1543498101,
    "type": "fir"
  }
});