190715670 Add logger for identifying cause of API failing post reload

Added logger in the pluginhook event flow and sourceRequest flow for debugging issue in the request during and after reload
apigee · Jul 2, 2021 · 21dd609 · 21dd609
1 parent 8f2ec8e
commit 21dd609
Showing 1 changed file with 11 additions and 1 deletion.
diff --git a/lib/plugins-middleware.js b/lib/plugins-middleware.js
@@ -77,10 +77,12 @@ module.exports = function(pluginsSeqManager) {
                 }),
                 function(err) {
                     if (_.isBoolean(err) && err) {
+                        logger.eventLog({ level: 'error', req: sourceRequest, res: sourceResponse, err: err, component: 'plugins-middleware' }, `source request stucked! error : ${JSON.stringify(err)}`);
                         return next(false);
                     }
                     if (err) {
                         // on request failed, sending metrics data to master node. 
+                        logger.eventLog({ level: 'error', req: sourceRequest, res: sourceResponse, err: err, component: 'plugins-middleware' }, 'source request failed.');
                         if(sourceRequest.headers['metrics_record']){
                             sourceRequest.headers['metrics_record']['proxy_status_code'] = sourceResponse.statusCode;
                             sendMetricsData(sourceRequest.headers['metrics_record']);
@@ -90,7 +92,8 @@ module.exports = function(pluginsSeqManager) {
                     //opentrace
                     traceHelper.startTargetSpan(correlation_id, sourceRequest.targetHostname);
                     //closetrace
-
+                    logger.debug({}, 'Request ID: ' + correlation_id +  ', sourceRequest success');
+
                     //create target request
                     const targetStartTime = Date.now();
                     const targetRequest = getTargetRequest(sourceRequest, sourceResponse, plugins, targetStartTime, correlation_id,
@@ -146,6 +149,7 @@ module.exports = function(pluginsSeqManager) {
                         });
 
                     //initiate request piping
+                    logger.debug({}, 'Request ID: ' + correlation_id  + ', Initiate request piping'); 
                     subscribeToSourceRequestEvents(plugins, sourceRequest, sourceResponse, targetRequest);
                     targetRequest.on('close', function() {
                         debug('sourceRequest close');
@@ -635,13 +639,16 @@ function _subscribeToResponseEvents(plugins, sourceRequest, sourceResponse, targ
 
 const getPluginHooksForEvent = function(type, options) {
     const plugins = options.plugins;
+    const logger = logging.getLogger();
+    logger.debug({}, 'Request ID: ' + options.sourceRequest['correlationId']  + `, preparing plugin map for type '${type}' & length -  '${plugins.length}'`);
     const pluginMap = plugins.map((plugin) => getPluginHookForEvent(plugin, type, options));
     return pluginMap;
 };
 
 function getPluginHookForEvent(plugin, type, options) {
     const isRequest = !options.targetRequest;
     const logger = logging.getLogger();
+
     //return handler
     return (data, cb) => {
         cb = _.isFunction(data) ? data : cb;
@@ -653,6 +660,7 @@ function getPluginHookForEvent(plugin, type, options) {
                 const fx = function(e) {  // }, newData) {  // jshint but allowing arg to be passed without access to it
                     //a small fix introduced to fix issues with plugin API being inconsistent with documentation.
                     //Pass a second null to ondata_response event callback then you are able to override the response body
+                    logger.debug({}, 'Request ID: ' + options.sourceRequest['correlationId']  + `, callback executed successfully for handler '${'on' + handler}' of plugin '${plugin.id}'`);
                     var args = Array.prototype.slice.call(arguments);
                     if (args.length === 2) {
                         cb(e, args[1]);
@@ -677,8 +685,10 @@ function getPluginHookForEvent(plugin, type, options) {
                     args = [options.sourceRequest, options.sourceResponse, options.targetResponse, data, fx];
                 }
 
+                logger.debug({}, 'Request ID: ' + options.sourceRequest['correlationId'] + `, executing plugin handler '${'on' + handler}' of plugin '${plugin.id}'`);
                 pluginHandler.apply(null, args);
             } else {
+                logger.debug({}, 'Request ID: ' + options.sourceRequest['correlationId']  + `, plugin '${plugin.id}' does not provide handler function for '${'on' + handler}'`);
                 debug("plugin " + plugin.id + " does not provide handler function for " + handler);
                 cb(null, data); // plugin does not provide onerror_request, carry on
             }