ARSN-531: record server access log fields in s3routes

lib/auth/AuthInfo.ts

@@ -57,8 +57,16 @@ export default class AuthInfo {
     email: string;
     accountDisplayName: string;
     IAMdisplayName: string;
+    authVersion?: string;
+    authType?: string;
+    accessKey?: string;
 
-    constructor(objectFromVault: any) {
+    constructor(
+        objectFromVault: any,
+        authVersion?: string,
+        authType?: string,
+        accessKey?: string,
+    ) {
         // amazon resource name for IAM user (if applicable)
         this.arn = objectFromVault.arn;
         // account canonicalID
@@ -71,6 +79,27 @@ export default class AuthInfo {
         this.accountDisplayName = objectFromVault.accountDisplayName;
         // display name for user (if applicable)
         this.IAMdisplayName = objectFromVault.IAMdisplayName;
+        // SigV4 or SigV2
+        this.authVersion = authVersion;
+        // QueryString or AuthHeader
+        switch (authType) {
+        case 'REST-QUERY-STRING':
+            this.authType = 'QueryString';
+            break;
+        case 'query':
+            this.authType = 'QueryString';
+            break;
+        case 'REST-HEADER':
+            this.authType = 'AuthHeader';
+            break;
+        case 'header':
+            this.authType = 'AuthHeader';
+            break;
+        default:
+            this.authType = authType;
+            break;
+        }
+        this.accessKey = accessKey;
     }
     getArn() {
         return this.arn;
@@ -90,6 +119,15 @@ export default class AuthInfo {
     getIAMdisplayName() {
         return this.IAMdisplayName;
     }
+    getAuthVersion() {
+        return this.authVersion;
+    }
+    getAuthType() {
+        return this.authType;
+    }
+    getAccessKey() {
+        return this.accessKey;
+    }
     // Check whether requester is an IAM user versus an account
     isRequesterAnIAMUser() {
         return !!this.IAMdisplayName;

lib/auth/Vault.ts

@@ -29,7 +29,9 @@ export function vaultSignatureCb(
         params?: any,
         infos?: AccountInfos,
     ) => void,
-    streamingV4Params?: any
+    streamingV4Params?: any,
+    authType?: string,
+    accessKey?: string,
 ) {
     // vaultclient API guarantees that it returns:
     // - either `err`, an Error object with `code` and `message` properties set
@@ -51,7 +53,8 @@ export function vaultSignatureCb(
     });
 
     const info = authInfo.message.body as AuthV4Results;
-    const userInfo = new AuthInfo(info.userInfo);
+    const userInfo = new AuthInfo(info.userInfo,
+        streamingV4Params ? 'SigV4' : 'SigV2', authType, accessKey);
     const authorizationResults = info.authorizationResults;
     const auditLog: { accountDisplayName: string, IAMdisplayName?: string } =
         { accountDisplayName: userInfo.getAccountDisplayName() };
@@ -172,8 +175,9 @@ export default class Vault {
                 securityToken: params.data.securityToken,
                 requestContext: serializedRCsArr,
             },
-            (err: Error | null, userInfo?: any) => vaultSignatureCb(err, userInfo,
-                params.log, callback),
+            (err: Error | null, userInfo?: any) => vaultSignatureCb(err,
+                userInfo, params.log, callback, undefined,
+                params.data.authType, params.data.accessKey),
         );
     }
 
@@ -234,8 +238,10 @@ export default class Vault {
                 securityToken: params.data.securityToken,
                 requestContext: serializedRCs,
             },
-            (err: Error | null, userInfo?: any) => vaultSignatureCb(err, userInfo,
-                params.log, callback, streamingV4Params),
+            (err: Error | null, userInfo?: any) => vaultSignatureCb(err,
+                userInfo, params.log, callback,
+                streamingV4Params,
+                params.data.authType, params.data.accessKey),
         );
     }
 

lib/s3routes/routes.ts

@@ -231,6 +231,13 @@ export default function routes(
         // @ts-ignore
         logger.newRequestLogger());
 
+
+    // @ts-expect-error
+    if (res.serverAccessLog) {
+        // @ts-expect-error
+        res.serverAccessLog.requestID = log.getSerializedUids();
+    }
+
     if (!req.url!.startsWith('/_/healthcheck') &&
         !req.url!.startsWith('/_/report')) {
         log.debug('received request', clientInfo);

lib/s3routes/routesUtils.ts

@@ -14,6 +14,23 @@ const jsutil = require('../jsutil');
 
 const ALLOW_INVALID_META_HEADERS = !!process.env.ALLOW_INVALID_META_HEADERS;
 
+function storeServerAccessLogFields(
+    res: http.ServerResponse,
+    endTurnAroundTime: bigint,
+    errorCode?: string,
+    bytesSent?: number,
+) {
+    // @ts-expect-error
+    if (res.serverAccessLog) {
+        // @ts-expect-error
+        res.serverAccessLog.errorCode = errorCode;
+        // @ts-expect-error
+        res.serverAccessLog.endTurnAroundTime = endTurnAroundTime;
+        // @ts-expect-error
+        res.serverAccessLog.bytesSent = bytesSent;
+    }
+}
+
 export type CallApiMethod = (
     methodName: string,
     request: http.IncomingMessage,
@@ -97,6 +114,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 +147,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(), undefined, bytesSent);
         return response.end(xml, 'utf8', () => {
             log.end().info('responded with XML', {
                 httpCode: response.statusCode,
@@ -148,6 +167,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 +211,7 @@ export const XMLResponseBackend = {
             'Content-Type': 'application/xml',
             'Content-Length': bytesSent,
         });
+        storeServerAccessLogFields(response, process.hrtime.bigint(), error.message, bytesSent);
         return response.end(xmlStr, 'utf8', () => {
             log.end().info('responded with error XML', {
                 httpCode: response.statusCode,
@@ -221,6 +242,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(), undefined, bytesSent);
         return response.end(json, 'utf8', () => {
             log.end().info('responded with JSON', {
                 httpCode: response.statusCode,
@@ -267,6 +289,7 @@ export const JSONResponseBackend = {
             'Content-Type': 'application/json',
             'Content-Length': bytesSent,
         });
+        storeServerAccessLogFields(response, process.hrtime.bigint(), error.message, bytesSent);
         return response.end(data, 'utf8', () => {
             log.end().info('responded with error JSON', {
                 httpCode: response.statusCode,
@@ -388,6 +411,7 @@ export function retrieveData(
     log: RequestLogger,
 ) {
     if (locations.length === 0) {
+        storeServerAccessLogFields(response, process.hrtime.bigint());
         return response.end();
     }
     if (locations[0].azureStreamingOptions) {
@@ -480,6 +504,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 +667,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 +714,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 +728,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,7 +829,9 @@ export function errorHtmlResponse(
         '</html>',
     );
 
-    return response.end(html.join(''), 'utf8', () => {
+    const body = html.join('');
+    storeServerAccessLogFields(response, process.hrtime.bigint(), error.message, body.length);
+    return response.end(body, 'utf8', () => {
         log.end().info('responded with error html', {
             httpCode: response.statusCode,
         });
@@ -824,6 +856,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 +948,7 @@ export function redirectRequest(
     response.writeHead(redirectCode, {
         Location: redirectLocation,
     });
+    storeServerAccessLogFields(response, process.hrtime.bigint());
     response.end();
     return undefined;
 }
@@ -1140,7 +1174,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);