ARSN-531: record server access log fields in s3routes

Author: leif-scality

lib/s3routes/routesUtils.ts

@@ -14,6 +14,16 @@ const jsutil = require('../jsutil');
 
 const ALLOW_INVALID_META_HEADERS = !!process.env.ALLOW_INVALID_META_HEADERS;
 
+function storeServerAccessLogFields(res: http.ServerResponse, endTurnAroundTime: bigint, errorCode?: string) {
+    // @ts-expect-error
+    if (res.serverAccessLog) {
+        // @ts-expect-error
+        res.serverAccessLog.errorCode = errorCode;
+        // @ts-expect-error
+        res.serverAccessLog.endTurnAroundTime = endTurnAroundTime;
+    }
+}
+
 export type CallApiMethod = (
     methodName: string,
     request: http.IncomingMessage,
@@ -97,6 +107,7 @@ export function okHeaderResponse(
     setCommonResponseHeaders(headers, response, log);
     log.debug('response http code', { httpCode });
     response.writeHead(httpCode);
+    storeServerAccessLogFields(response, process.hrtime.bigint());
     return response.end(() => {
         log.end().info('responded to request', {
             httpCode: response.statusCode,
@@ -129,6 +140,7 @@ export const XMLResponseBackend = {
         setCommonResponseHeaders(additionalHeaders, response, log);
         response.writeHead(200, { 'Content-type': 'application/xml' });
         log.trace('xml response', { xml });
+        storeServerAccessLogFields(response, process.hrtime.bigint());
         return response.end(xml, 'utf8', () => {
             log.end().info('responded with XML', {
                 httpCode: response.statusCode,
@@ -148,6 +160,7 @@ export const XMLResponseBackend = {
         // early return to avoid extra headers and XML data
         if (error.code === 304) {
             response.writeHead(error.code);
+            storeServerAccessLogFields(response, process.hrtime.bigint(), error.message);
             return response.end('', 'utf8', () => {
                 log.end().info('responded with empty body', {
                     httpCode: response.statusCode,
@@ -191,6 +204,7 @@ export const XMLResponseBackend = {
             'Content-Type': 'application/xml',
             'Content-Length': bytesSent,
         });
+        storeServerAccessLogFields(response, process.hrtime.bigint(), error.message);
         return response.end(xmlStr, 'utf8', () => {
             log.end().info('responded with error XML', {
                 httpCode: response.statusCode,
@@ -221,6 +235,7 @@ export const JSONResponseBackend = {
         setCommonResponseHeaders(additionalHeaders, response, log);
         response.writeHead(200, { 'Content-type': 'application/json' });
         log.trace('sending success json response', { json });
+        storeServerAccessLogFields(response, process.hrtime.bigint());
         return response.end(json, 'utf8', () => {
             log.end().info('responded with JSON', {
                 httpCode: response.statusCode,
@@ -267,6 +282,7 @@ export const JSONResponseBackend = {
             'Content-Type': 'application/json',
             'Content-Length': bytesSent,
         });
+        storeServerAccessLogFields(response, process.hrtime.bigint(), error.message);
         return response.end(data, 'utf8', () => {
             log.end().info('responded with error JSON', {
                 httpCode: response.statusCode,
@@ -388,6 +404,7 @@ export function retrieveData(
     log: RequestLogger,
 ) {
     if (locations.length === 0) {
+        storeServerAccessLogFields(response, process.hrtime.bigint());
         return response.end();
     }
     if (locations[0].azureStreamingOptions) {
@@ -480,6 +497,8 @@ export function retrieveData(
                 // in the callback of data.get()? The 'close' event is not
                 // called if 'end' is.
                 currentStream = readable;
+
+                storeServerAccessLogFields(response, process.hrtime.bigint());
                 return readable.pipe(response, { end: false });
             }
         ), err => {
@@ -641,6 +660,8 @@ export function responseContentHeaders(
         log.debug('response http code', { httpCode: 200 });
         response.writeHead(200);
     }
+
+    storeServerAccessLogFields(response, process.hrtime.bigint());
     return response.end(() => {
         log.end().info('responded with content headers', {
             httpCode: response.statusCode,
@@ -686,7 +707,7 @@ export function responseStreamData(
                 dataLocations)) {
             log.error(
                 'logic error: total length of fetched data ' +
-                    'locations does not match returned content-length',
+                'locations does not match returned content-length',
                 { contentLength, dataLocations });
             return XMLResponseBackend.errorResponse(errors.InternalError,
                 response, log,
@@ -700,6 +721,8 @@ export function responseStreamData(
             range, log);
     }
     if (dataLocations === null || _computeContentLengthFromLocation(dataLocations) === 0) {
+
+        storeServerAccessLogFields(response, process.hrtime.bigint());
         return response.end(() => {
             log.end().info('responded with only metadata', {
                 httpCode: response.statusCode,
@@ -799,6 +822,7 @@ export function errorHtmlResponse(
         '</html>',
     );
 
+    storeServerAccessLogFields(response, process.hrtime.bigint(), error.message);
     return response.end(html.join(''), 'utf8', () => {
         log.end().info('responded with error html', {
             httpCode: response.statusCode,
@@ -824,6 +848,7 @@ export function errorHeaderResponse(
     response.setHeader('x-amz-error-code', error.message);
     response.setHeader('x-amz-error-message', error.description);
     response.writeHead(error.code);
+    storeServerAccessLogFields(response, process.hrtime.bigint(), error.message);
     return response.end(() => {
         log.end().info('responded with error headers', {
             httpCode: response.statusCode,
@@ -915,6 +940,7 @@ export function redirectRequest(
     response.writeHead(redirectCode, {
         Location: redirectLocation,
     });
+    storeServerAccessLogFields(response, process.hrtime.bigint());
     response.end();
     return undefined;
 }
@@ -1140,7 +1166,7 @@ export function normalizeRequest(
     // the x-amz-decoded-content-length
     const contentLength = request.headers['x-amz-decoded-content-length'] ?
         request.headers['x-amz-decoded-content-length'] :
-        request.headers['content-length'];
+        request.headers['content-length']; // here
     // @ts-expect-error
     request.parsedContentLength =
         Number.parseInt(contentLength?.toString() ?? '', 10);