Skip to content

Commit

Permalink
refactor(mediasoup): review log levels and metadata
Browse files Browse the repository at this point in the history 
Some mediasoup adapter log levels are at debug level, but they are useful
for debugging production edge cases. Additionaly, transport-level logs
are missing their mcs-core elementId in metadata, which makes it
difficult to correlate them.

Review the mediasoup adapter logs by:
  - Bumping useful, not to verbose debug logs to warn, error or info
  - Adding correlation info to metadata that were lacking it
  - Adding a new log entry that registers whenever a transport is
    destroyed _before_ being sucessfully negotiated (with connection
    info in its metadata)
  • Loading branch information
@prlanzarin
prlanzarin committed Sep 26, 2024
1 parent abddbf8 commit 24b2d0e
Show file tree
Hide file tree
Showing 5 changed files with 77 additions and 18 deletions.
1 change: 1 addition & 0 deletions CHANGELOG.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ For previous changes, see the [release notes](https://github.com/bigbluebutton/b
### UNRELEASED

* feat(mediasoup): pipe mediasoup logs to the application logger
* refactor(mediasoup): review log levels and metadata

### v2.15.0

Expand Down
42 changes: 31 additions & 11 deletions lib/mcs-core/lib/adapters/mediasoup/base-element.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -61,6 +61,7 @@ module.exports = class BaseMediasoupElement extends EventEmitter {

this._currentMaxIncomingBitrate = DEFAULT_MAX_IN_BW;
this._currentMaxOutgoingBitrate = DEFAULT_MAX_OUT_BW;
this._mediaEstablishedOnce = false;

this._processOptions(options);

Expand Down Expand Up @@ -345,7 +346,12 @@ module.exports = class BaseMediasoupElement extends EventEmitter {

const router = getRouter(this.routerId);
if (router == null) throw (C.ERROR.ROOM_NOT_FOUND);
this.transportSet = new TransportSet(this.type, router.appData.internalAdapterId);
this.transportSet = new TransportSet(
this.type,
router.appData.internalAdapterId, {
elementId: this.id,
}
);
return this.transportSet.createTransportSet(options).then(() => {
this.host = this.transportSet.host;
this.transportSet.setMaxIncomingBitrate(this._currentMaxIncomingBitrate);
Expand Down Expand Up @@ -547,7 +553,7 @@ module.exports = class BaseMediasoupElement extends EventEmitter {
// consumer.changeProducer is only available in a forked version of mediasoup
// If it's unavailable, no-op
if (typeof consumer.changeProducer !== 'function') {
Logger.debug('mediasoup: changeProducer not available');
Logger.warn('mediasoup: changeProducer not available');
return;
}

Expand Down Expand Up @@ -629,7 +635,7 @@ module.exports = class BaseMediasoupElement extends EventEmitter {
}
}
} catch (error) {
Logger.debug('mediasoup: failed to get bitrate for source from spec', {
Logger.warn('mediasoup: failed to get bitrate for source from spec', {
elementId: this.id,
type: this.type,
sourceId: source.id,
Expand Down Expand Up @@ -731,14 +737,10 @@ module.exports = class BaseMediasoupElement extends EventEmitter {
}

_handleTransportIceStateCompleted () {
Logger.info('mediasoup: transport ICE state completed', {
elementId: this.id, type: this.type, routerId: this.routerId,
transportId: this.transportSet.id,
});

const iceSelectedTuple = this.transportSet.transport.iceSelectedTuple;
const iceSelectedTuple = this.transportSet?.transport?.iceSelectedTuple;

Logger.debug('mediasoup: transport ICE tuple selected', {
this._mediaEstablishedOnce = true;
Logger.info('mediasoup: transport ICE state completed', {
elementId: this.id, type: this.type, routerId: this.routerId,
transportId: this.transportSet.id,
iceSelectedTuple,
Expand Down Expand Up @@ -797,6 +799,7 @@ module.exports = class BaseMediasoupElement extends EventEmitter {
}

_handleRTPTupleDiscovered (rtpTuple) {
this._mediaEstablishedOnce = true;
Logger.info('mediasoup: remote origin RTP tuple discovered', {
elementId: this.id, type: this.type, routerId: this.routerId,
transportId: this.transportSet.id, rtpTuple,
Expand All @@ -813,7 +816,7 @@ module.exports = class BaseMediasoupElement extends EventEmitter {
}

_handleIceSelectedTupleChange (iceSelectedTuple) {
Logger.trace('mediasoup: transport ICE selected tuple changed', {
Logger.debug('mediasoup: transport ICE selected tuple changed', {
elementId: this.id,
type: this.type,
routerId: this.routerId,
Expand Down Expand Up @@ -851,6 +854,23 @@ module.exports = class BaseMediasoupElement extends EventEmitter {
}

async stop () {
if (!this._mediaEstablishedOnce) {
const mediaSsrcMap = this.remoteDescriptor?.media?.length > 0
? this.remoteDescriptor.media.map(({ type, mid, msid, iceUfrag, icePwd, ssrcs }) => ({
type, mid, msid, iceUfrag, icePwd, ssrcs,
}))
: [];

Logger.warn('mediasoup: stopping transport before media established', {
elementId: this.id,
type: this.type,
routerId: this.routerId,
transportId: this.transportSet.id,
transportData: this.transportSet.transportOptions,
remoteMedia: mediaSsrcMap,
});
}

if (this.transportSet && typeof this.transportSet.stop === 'function') {
await this.transportSet.stop();
}
Expand Down
21 changes: 18 additions & 3 deletions lib/mcs-core/lib/adapters/mediasoup/mtransport-sdp-element.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,12 @@ module.exports = class MultiTransportSDPElement extends BaseMediasoupElement {
await transportSet.stop();
} catch (error) {
Logger.error('mediasoup: failure cleaning multi-transport transport set', {
errorMessage: error.message, elementId: this.id, mediaType,
errorMessage: error.message,
errorStack: error.stack,
type: this.type,
routerId: this.routerId,
elementId: this.id,
mediaType,
transportId: transportSet.id,
});
} finally {
Expand All @@ -71,7 +76,12 @@ module.exports = class MultiTransportSDPElement extends BaseMediasoupElement {
await internalElement.stop();
} catch (error) {
Logger.error('mediasoup: failure cleaning multi-transport internal element', {
errorMessage: error.message, elementId: this.id, mediaType,
errorMessage: error.message,
errorStack: error.stack,
type: this.type,
routerId: this.routerId,
elementId: this.id,
mediaType,
internalElementId: internalElement.id,
});
} finally {
Expand Down Expand Up @@ -101,7 +111,12 @@ module.exports = class MultiTransportSDPElement extends BaseMediasoupElement {
try {
const router = getRouter(this.routerId);
if (router == null) throw (C.ERROR.ROOM_NOT_FOUND);
const transportSet = new TransportSet(this.type, router.appData.internalAdapterId);
const transportSet = new TransportSet(
this.type,
router.appData.internalAdapterId, {
elementId: this.id,
},
);
return transportSet.createTransportSet(options);
} catch (error) {
throw (handleError(error));
Expand Down
2 changes: 1 addition & 1 deletion lib/mcs-core/lib/adapters/mediasoup/sdp-element.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -432,7 +432,7 @@ module.exports = class MediasoupSDPElement extends BaseMediasoupElement {

_restartIce () {
return this.transportSet.restartIce().then((iceParameters) => {
Logger.debug("mediasoup: ICE restart started", {
Logger.info("mediasoup: ICE restart started", {
elementId: this.id, type: this.type, routerId: this.routerId, iceParameters,
});
this.localDescriptor = SDPTranslator.assembleSDP(this.kindParametersMap, {
Expand Down
29 changes: 26 additions & 3 deletions lib/mcs-core/lib/adapters/mediasoup/transports.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,13 @@ module.exports = class TransportSet {
};
}

constructor(type, routerId) {
_processOptions (options) {
if (typeof options.elementId === 'string') {
this.elementId = options.elementId;
}
}

constructor(type, routerId, options = {}) {
this.type = type;
this._mappedType = getMappedTransportType(type);
this.transportOptions;
Expand All @@ -42,6 +48,8 @@ module.exports = class TransportSet {
this.routerId = routerId;
this.connected = false;

this._processOptions(options);

// Event handlers
this._handleRouterClose = this._handleRouterClose.bind(this);
}
Expand Down Expand Up @@ -140,12 +148,14 @@ module.exports = class TransportSet {

Logger.info("mediasoup: transport created", {
transportId: this.id, type: this.type, routerId: this.routerId,
elementId: this.elementId,
});

return this;
} catch (error) {
Logger.error("mediasoup: transport creation failed", {
errorMessage: error.message, type: this.type, routerId: this.routerId,
elementId: this.elementId,
});
throw error;
}
Expand Down Expand Up @@ -193,12 +203,14 @@ module.exports = class TransportSet {

Logger.info("mediasoup: transport created", {
transportId: this.transport.id, type: this.type, routerId: this.routerId,
elementId: this.elementId,
});

return this;
} catch (error) {
Logger.error("mediasoup: transport creation failed", {
errorMessage: error.message, type: this.type, routerId: this.routerId,
elementId: this.elementId,
});
throw error;
}
Expand Down Expand Up @@ -227,7 +239,12 @@ module.exports = class TransportSet {
&& typeof this.transport.setMaxIncomingBitrate === 'function'
) {
this.transport.setMaxIncomingBitrate(max).catch((error) => {
Logger.error("mediasoup: max incoming bitrate failure", { errorMessage: error.message });
Logger.error("mediasoup: max incoming bitrate failure", {
errorMessage: error.message,
type: this.type,
routerId: this.routerId,
elementId: this.elementId,
});
});
}
}
Expand All @@ -238,7 +255,12 @@ module.exports = class TransportSet {
&& max > 0
) {
this.transport.setMaxOutgoingBitrate(max).catch((error) => {
Logger.error("mediasoup: max outgoing bitrate failure", { errorMessage: error.message });
Logger.error("mediasoup: max outgoing bitrate failure", {
errorMessage: error.message,
type: this.type,
routerId: this.routerId,
elementId: this.elementId,
});
});
}
}
Expand Down Expand Up @@ -274,6 +296,7 @@ module.exports = class TransportSet {
if (reason) {
Logger.info("mediasoup: TransportSet closed", {
transportId: this.id, type: this.type, routerId: this.routerId, reason,
elementId: this.elementId,
});
}

Expand Down

0 comments on commit 24b2d0e

Please sign in to comment.