Skip to content

Commit

Permalink
Add more info to logs (#1606)
Browse files Browse the repository at this point in the history
  • Loading branch information
@jcague
jcague authored Jul 1, 2020
1 parent f554a95 commit fea9fd3
Show file tree
Hide file tree
Showing 14 changed files with 180 additions and 108 deletions.
2 changes: 1 addition & 1 deletion erizo/src/erizo/MediaStream.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -647,7 +647,7 @@ void MediaStream::sendPLIToFeedback() {
}

void MediaStream::setPeriodicKeyframeRequests(bool activate, uint32_t interval) {
ELOG_DEBUG("%s message: settingPeriodicKeyframes, activate: %u, interval, %u", activate, interval);
ELOG_DEBUG("%s message: settingPeriodicKeyframes, activate: %u, interval, %u", toLog(), activate, interval);
periodic_keyframes_requested_ = activate;
periodic_keyframe_interval_ = interval;
notifyUpdateToHandlers();
Expand Down
7 changes: 5 additions & 2 deletions erizo_controller/common/logger.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,10 @@ const logFile = global.config.logger.configFile || '../log4js_configuration.json
const logJsonReplacer = (key, value) => {
if (key) {
if (typeof (value) === 'object') {
return '[Object]';
const log = exports.logger.objectToLog(value);
if (log.length === 0) {
return '{},';
}
}
return value;
}
Expand All @@ -24,7 +27,7 @@ log4js.configure(logFile);
exports.logger = log4js;

exports.logger.objectToLog = (jsonInput) => {
if (jsonInput === undefined) {
if (jsonInput === undefined || jsonInput === null) {
return '';
}
if (typeof (jsonInput) !== 'object') {
Expand Down
6 changes: 4 additions & 2 deletions erizo_controller/erizoController/erizoController.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -312,7 +312,8 @@ const listen = () => {
options.singlePC = getSinglePCConfig(options.singlePC);
const client = room.createClient(channel, token, options);
log.info(`message: client connected, clientId: ${client.id}, ` +
`singlePC: ${options.singlePC}`);
`socketId: ${socket.id}, singlePC: ${options.singlePC},`,
logger.objectToLog(options), logger.objectToLog(options.metadata));
if (!room.p2p && global.config.erizoController.report.session_events) {
const timeStamp = new Date();
amqper.broadcast('event', { room: room.id,
Expand All @@ -336,7 +337,8 @@ const listen = () => {
maxVideoBW: global.config.erizoController.maxVideoBW,
iceServers: global.config.erizoController.iceServers });
} catch (e) {
log.warn('message: error creating Room or Client, error:', e);
log.warn('message: error creating Room or Client, error:', e,
logger.objectToLog(options), logger.objectToLog(options.metadata));
}
});

Expand Down
9 changes: 5 additions & 4 deletions erizo_controller/erizoController/models/Client.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -287,7 +287,7 @@ class Client extends events.EventEmitter {
const stream = this.room.streamManager.getPublishedStreamById(message.id);
if (stream === undefined) {
log.warn('message: Trying to send Data from a non-initialized stream, ' +
`clientId: ${this.id}`, logger.objectToLog(message));
`clientId: ${this.id},`, logger.objectToLog(message));
return;
}
stream.forEachDataSubscriber((index, dataSubscriber) => {
Expand Down Expand Up @@ -374,7 +374,7 @@ class Client extends events.EventEmitter {
onUpdateStreamAttributes(message) {
const stream = this.room.streamManager.getPublishedStreamById(message.id);
if (stream === undefined) {
log.warn('message: Update attributes to a uninitialized stream ',
log.warn('message: Update attributes to a uninitialized stream,',
logger.objectToLog(message));
return;
}
Expand Down Expand Up @@ -426,9 +426,10 @@ class Client extends events.EventEmitter {
options.mediaConfiguration = this.token.mediaConfiguration;
options.singlePC = this.options.singlePC || false;
log.info('message: addPublisher requested, ',
`streamId: ${id}, clientId: ${this.id}`,
`streamId: ${id}, clientId: ${this.id},`,
logger.objectToLog(options),
logger.objectToLog(options.attributes));
logger.objectToLog(options.metadata),
);
const st = new PublishedStream({ id,
client: this.id,
audio: options.audio,
Expand Down
2 changes: 2 additions & 0 deletions erizo_controller/erizoController/models/Room.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -91,6 +91,8 @@ class Room extends events.EventEmitter {
log.debug('message: sendMsgToRoom,',
'clientId:', client.id, ',',
'roomId:', this.id, ', ',
logger.objectToLog(client.options),
logger.objectToLog(client.options.metadata),
logger.objectToLog(method));
client.sendMessage(method, args);
});
Expand Down
16 changes: 9 additions & 7 deletions erizo_controller/erizoController/roomController.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -155,7 +155,7 @@ exports.RoomController = (spec) => {
amqper.callRpc(getErizoQueueFromStreamId(publisherId), 'addExternalOutput', args, undefined);
callback(true);
} else {
log.warn(`message: addExternalOutput already in progress, publisherId: ${publisherId}, url: ${url} `,
log.warn(`message: addExternalOutput already in progress, publisherId: ${publisherId}, url: ${url},`,
logger.objectToLog(options.metadata));
}
};
Expand Down Expand Up @@ -190,21 +190,21 @@ exports.RoomController = (spec) => {

if (streamManager.getPublishedStreamState(streamId) === StreamStates.PUBLISHER_CREATED) {
log.info('message: addPublisher, ',
`clientId ${clientId}, `,
`streamId: ${streamId}`,
`clientId ${clientId},`,
`streamId: ${streamId},`,
logger.objectToLog(options),
logger.objectToLog(options.metadata));

// We create a new ErizoJS with the streamId.
getErizoJS((erizoId, agentId) => {
if (erizoId === 'timeout') {
log.error(`message: addPublisher ErizoAgent timeout, streamId: ${streamId}`,
log.error(`message: addPublisher ErizoAgent timeout, streamId: ${streamId},`,
logger.objectToLog(options.metadata));
callback('timeout-agent');
return;
}
log.info('message: addPublisher erizoJs assigned, ',
`erizoId: ${erizoId}, streamId: ${streamId}`,
`erizoId: ${erizoId}, streamId: ${streamId},`,
logger.objectToLog(options.metadata));
// Track publisher locally
// then we call its addPublisher method.
Expand Down Expand Up @@ -243,7 +243,7 @@ exports.RoomController = (spec) => {
} });
});
} else {
log.warn(`message: addPublisher already in progress, clientId: ${clientId}, streamId: ${streamId} `,
log.warn(`message: addPublisher already in progress, clientId: ${clientId}, streamId: ${streamId},`,
logger.objectToLog(options.metadata));
}
};
Expand All @@ -258,6 +258,7 @@ exports.RoomController = (spec) => {
log.warn('message: addSubscriber null clientId, ',
`streamId: ${streamId}, `,
`clientId: ${clientId},`,
logger.objectToLog(options),
logger.objectToLog(options.metadata));
callback('Error: null clientId');
return;
Expand Down Expand Up @@ -318,7 +319,7 @@ exports.RoomController = (spec) => {
callback(data);
} });
} else {
log.warn(`message: addSubscriber already in progress, clientId: ${clientId}, streamId: ${streamId} `,
log.warn(`message: addSubscriber already in progress, clientId: ${clientId}, streamId: ${streamId},`,
logger.objectToLog(options.metadata));
}
};
Expand All @@ -328,6 +329,7 @@ exports.RoomController = (spec) => {
log.warn('message: addMultipleSubscribers null clientId, ',
`streams: ${streamIds.length}, `,
`clientId: ${clientId},`,
logger.objectToLog(options),
logger.objectToLog(options.metadata));
callback('Error: null clientId');
return;
Expand Down
53 changes: 31 additions & 22 deletions erizo_controller/erizoJS/erizoJSController.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -94,11 +94,12 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
}
};

const getOrCreateClient = (erizoControllerId, clientId, singlePC = false) => {
const getOrCreateClient = (erizoControllerId, clientId, options = {}) => {
let client = clients.get(clientId);
const singlePC = options.singlePC || false;
if (client === undefined) {
client = new Client(erizoControllerId, erizoJSId, clientId,
threadPool, ioThreadPool, !!singlePC);
threadPool, ioThreadPool, !!singlePC, options);
client.on('status_event', onConnectionStatusEvent.bind(this));
clients.set(clientId, client);
}
Expand Down Expand Up @@ -137,7 +138,7 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
return;
}

log.info(`message: removeClient = closing all connections on, clientId: ${clientId}`);
log.info(`message: removeClient - closing all connections on, clientId: ${clientId}`);
client.closeAllConnections();
clients.delete(client.id);
callback('callback', true);
Expand Down Expand Up @@ -186,8 +187,6 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {

that.processConnectionMessage = (erizoControllerId, clientId, connectionId, msg,
callbackRpc = () => {}) => {
log.info('message: Process Connection message, ' +
`clientId: ${clientId}, connectionId: ${connectionId}`);
let error;
const client = clients.get(clientId);
if (!client) {
Expand All @@ -208,6 +207,9 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
return Promise.resolve();
}

log.info('message: Process Connection message, ' +
`clientId: ${clientId}, connectionId: ${connectionId},`,
logger.objectToLog(client.options), logger.objectToLog(client.options.metadata));
if (msg.type === 'failed') {
client.forceCloseConnection(connectionId);
}
Expand All @@ -218,9 +220,6 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
};

that.processStreamMessage = (erizoControllerId, clientId, streamId, msg) => {
log.info('message: Process Stream message, ' +
`clientId: ${clientId}, streamId: ${streamId}`);

let node;
const publisher = publishers[streamId];
if (!publisher) {
Expand All @@ -238,6 +237,10 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
`clientId: ${clientId}, streamId: ${streamId}`);
return;
}
log.info('message: Process Stream message, ' +
`clientId: ${clientId}, streamId: ${streamId},`,
logger.objectToLog(node.options), logger.objectToLog(node.options.metadata));

node.onStreamMessage(msg);
};

Expand All @@ -250,7 +253,7 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
updateUptimeInfo();
let publisher;
log.info('addPublisher, clientId', clientId, 'streamId', streamId);
const client = getOrCreateClient(erizoControllerId, clientId, options.singlePC);
const client = getOrCreateClient(erizoControllerId, clientId, options);

if (publishers[streamId] === undefined) {
// eslint-disable-next-line no-param-reassign
Expand All @@ -260,7 +263,7 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
const connection = client.getOrCreateConnection(options);
log.info('message: Adding publisher, ',
`clientId: ${clientId}, `,
`streamId: ${streamId}`,
`streamId: ${streamId},`,
logger.objectToLog(options),
logger.objectToLog(options.metadata));
publisher = new Publisher(clientId, streamId, connection, options);
Expand Down Expand Up @@ -295,7 +298,7 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
publisher = publishers[streamId];
if (publisher.numSubscribers === 0) {
log.warn('message: publisher already set but no subscribers will ignore, ',
`code: ${WARN_CONFLICT}, streamId: ${streamId}`,
`code: ${WARN_CONFLICT}, streamId: ${streamId},`,
logger.objectToLog(options.metadata));
} else {
log.warn('message: publisher already set has subscribers will ignore, ' +
Expand All @@ -315,17 +318,18 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
if (publisher === undefined) {
log.warn('message: addSubscriber to unknown publisher, ',
`code: ${WARN_NOT_FOUND}, streamId: ${streamId}, `,
`clientId: ${clientId}`,
`clientId: ${clientId},`,
logger.objectToLog(options),
logger.objectToLog(options.metadata));
// We may need to notify the clients
return;
}
let subscriber = publisher.getSubscriber(clientId);
const client = getOrCreateClient(erizoControllerId, clientId, options.singlePC);
const client = getOrCreateClient(erizoControllerId, clientId, options);
if (subscriber !== undefined) {
log.warn('message: Duplicated subscription will resubscribe, ' +
`code: ${WARN_CONFLICT}, streamId: ${streamId}, ` +
`clientId: ${clientId}`, logger.objectToLog(options.metadata));
`clientId: ${clientId},`, logger.objectToLog(options.metadata));
that.removeSubscriber(clientId, streamId);
}
// eslint-disable-next-line no-param-reassign
Expand Down Expand Up @@ -394,18 +398,18 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
if (knownPublishers.length === 0) {
log.warn('message: addMultipleSubscribers to unknown publisher, ',
`code: ${WARN_NOT_FOUND}, streamIds: ${streamIds}, `,
`clientId: ${clientId}`,
`clientId: ${clientId},`,
logger.objectToLog(options.metadata));
callbackRpc('callback', { type: 'error' });
return;
}

log.debug('message: addMultipleSubscribers to publishers, ',
`streamIds: ${knownPublishers}, `,
`clientId: ${clientId}`,
`clientId: ${clientId},`,
logger.objectToLog(options.metadata));

const client = getOrCreateClient(erizoControllerId, clientId, options.singlePC);
const client = getOrCreateClient(erizoControllerId, clientId, options);
// eslint-disable-next-line no-param-reassign
options.publicIP = that.publicIP;
// eslint-disable-next-line no-param-reassign
Expand Down Expand Up @@ -503,9 +507,12 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
new Promise((resolve) => {
const publisher = publishers[streamId];
if (publisher !== undefined) {
log.info(`message: Removing publisher, id: ${clientId}, streamId: ${streamId}`);
log.info(`message: Removing publisher, id: ${clientId}, streamId: ${streamId},`,
logger.objectToLog(publisher.options), logger.objectToLog(publisher.options.metadata));
publisher.forEachSubscriber((subscriberId, subscriber) => {
log.info(`message: Removing subscriber, id: ${subscriberId}`);
log.info(`message: Removing subscriber, id: ${subscriberId},`,
logger.objectToLog(subscriber.options),
logger.objectToLog(subscriber.options.metadata));
closeNode(subscriber);
publisher.removeSubscriber(subscriberId);
});
Expand All @@ -514,7 +521,7 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
closeNode(publisher).then(() => {
publisher.muxer.close((message) => {
log.info('message: muxer closed succesfully, ',
`id: ${streamId}`,
`id: ${streamId},`,
logger.objectToLog(message));
const count = Object.keys(publishers).length;
log.debug(`message: remaining publishers, publisherCount: ${count}`);
Expand Down Expand Up @@ -542,7 +549,8 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
if (publisher && publisher.hasSubscriber(clientId)) {
const subscriber = publisher.getSubscriber(clientId);
log.info(`message: removing subscriber, streamId: ${subscriber.streamId}, ` +
`clientId: ${clientId}`);
`clientId: ${clientId},`,
logger.objectToLog(subscriber.options), logger.objectToLog(subscriber.options.metadata));
return closeNode(subscriber).then(() => {
publisher.removeSubscriber(clientId);
log.info(`message: subscriber node Closed, streamId: ${subscriber.streamId}`);
Expand All @@ -565,7 +573,8 @@ exports.ErizoJSController = (erizoJSId, threadPool, ioThreadPool) => {
const subscriber = publisher.getSubscriber(clientId);
if (subscriber) {
log.debug('message: removing subscription, ' +
'id:', subscriber.clientId);
'id:', subscriber.clientId, ',',
logger.objectToLog(subscriber.options), logger.objectToLog(subscriber.options.metadata));
closePromises.push(closeNode(subscriber));
publisher.removeSubscriber(clientId);
}
Expand Down
Loading

0 comments on commit fea9fd3

Please sign in to comment.