Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

@aws-sdk/client-s3 Converting circular structure to JSON warning when using custom logger #4339

Closed
3 tasks done
micchickenburger opened this issue Jan 16, 2023 · 15 comments
Closed
3 tasks done
Assignees
Labels
guidance General information and guidance, answers to FAQs, or recommended best practices/resources.

Comments

@micchickenburger
Copy link

micchickenburger commented Jan 16, 2023

Checkboxes for prior research

Describe the bug

When using a custom logger (Winston, in my case) the S3 GetObjectCommand results in a bunch of these outputs:

2023-01-16 16:34:57 [debug] endpoints

Then, finishes with:

2023-01-16 16:34:57 [warn] Converting circular structure to JSON
2023-01-16 16:34:57     --> starting at object with constructor 'Socket'
2023-01-16 16:34:57     |     property 'parser' -> object with constructor 'HTTPParser'
2023-01-16 16:34:57     --- property 'socket' closes the circle

I didn't test any other commands.

The warning happens because my logger implementation tries to stringify messages passed to it. However, the S3 client library tries to send output with circular references to a logger, which I think is erroneous behavior.

SDK version number

@aws-sdk/[email protected]

Which JavaScript Runtime is this issue in?

Node.js

Details of the browser/Node.js/ReactNative version

v16.19.0

Reproduction Steps

Configuration:

import { GetObjectCommand, S3Client } from '@aws-sdk/client-s3';
import logger from '../logger';

const region = process.env.AWS_REGION || process.env.AWS_DEFAULT_REGION;
const endpoint = 'http://aws:4566'; // localstack
const client = new S3Client({
  region,
  endpoint,
  logger, // removing this line resolves the issue
  forcePathStyle: true, // required for localstack due to lack of dns resolution in app container
});
const command = new GetObjectCommand({
  Bucket: 'bucket',
  Key: 'test.json',
});
const response = await client.send(command); // debug and warn messages occur here
const body = await response.Body?.transformToString();
// ...

This is the logging pattern I use for all the rest of the AWS libraries with no issue.

Here is my Winston configuration:

import winston from 'winston';

const formatter = () => (info: winston.Logform.TransformableInfo) => {
  const { level } = info;
  let { message } = info;

  // By default JSON is not properly stringified
  if (typeof info.message === 'object') {
    message = JSON.stringify(message, null, 2);
  }

  // Color levels
  let color;
  switch (level) {
    case 'error': color = '\x1B[31m'; break;
    case 'warn': color = '\x1B[38;5;214m'; break;
    case 'debug': color = '\x1B[34m'; break;
    default: color = '\x1B[90m';
  }
  return `${color}[${level}] \x1B[39m${message}`;
};

export default logger = winston.createLogger({
  level: 'debug',
  format: winston.format.printf(formatter()),
  transports: [
    new winston.transports.Console(),
  ],
});

Observed Behavior

When using a custom logger (Winston, in my case) the S3 GetObjectCommand results in this output:

2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [debug] endpoints
2023-01-16 16:34:57 [warn] Converting circular structure to JSON
2023-01-16 16:34:57     --> starting at object with constructor 'Socket'
2023-01-16 16:34:57     |     property 'parser' -> object with constructor 'HTTPParser'
2023-01-16 16:34:57     --- property 'socket' closes the circle

This actually breaks the flow; further s3 object processing does not occur.

Expected Behavior

I expect there to be no useless debug messages, and for there to not be a circular reference error during object stringification.

Possible Solution

Not using a custom logger eliminates the issue, as does not stringifying output, but this is the logging pattern I use for all of the aws client libraries without issue. Of course, not stringifying is also not very useful:

[info] [object Object]

EDIT: Using node's util.inspect can be used to remove circular references:

import { inspect } from 'util';

if (typeof info.message === 'object') {
  message = inspect(message, { colors: true });
}

image

Additional Information/Context

No response

@micchickenburger micchickenburger added bug This issue is a bug. needs-triage This issue or PR still needs to be triaged. labels Jan 16, 2023
@yenfryherrerafeliz yenfryherrerafeliz self-assigned this Jan 17, 2023
@yenfryherrerafeliz yenfryherrerafeliz added investigating Issue is being investigated and/or work is in progress to resolve the issue. and removed needs-triage This issue or PR still needs to be triaged. labels Jan 17, 2023
@yenfryherrerafeliz
Copy link
Contributor

Hi @micchickenburger, thanks for opening this issue. I can confirm this bug. I will mark this issue to be reviewed so we can further address it.

Steps to reproduce:

  • Create a empty node project: npm init
  • Install the s3 client denendencies: npm i @aws-sdk/client-s3
  • copy and paste the following code in a js file:
import {GetObjectCommand, ListBucketsCommand, S3Client} from "@aws-sdk/client-s3";

const client = new S3Client({
    region: 'us-east-2',
    logger: {
        info: content => {
            console.log('INFO: ', JSON.stringify(content))
        }
    }
});
const response = await client.send(new GetObjectCommand({
    Bucket: process.env.TEST_BUCKET,
    Key: process.env.TEST_KEY
}));
console.log(response)
  • Run the code.

Thanks!

@yenfryherrerafeliz yenfryherrerafeliz added needs-review This issue/pr needs review from an internal developer. p2 This is a standard priority issue and removed investigating Issue is being investigated and/or work is in progress to resolve the issue. labels Jan 18, 2023
@JasonGloverNZ
Copy link

I am having essentially this same issue and it is confounding me.

Versions

Error stack trace

TypeError: Converting circular structure to JSON
--> starting at object with constructor 'TLSSocket'
|     property 'parser' -> object with constructor 'HTTPParser'
--- property 'socket' closes the circle


at JSON.stringify (<anonymous>)

at /opt/sls-sdk-node/index.js:2950:41

at processTicksAndRejections (node:internal/process/task_queues:96:5)

at async /var/task/node_modules/@aws-sdk/middleware-logger/dist-cjs/loggerMiddleware.js:5:22

at async Object.getDocument (/var/task/bucket/documents.js:30:25)

at async Object.getDocument (/var/task/manager/documents.js:41:24)

at async /var/task/controller/documents.js:17:20

/bucket/documents.js.getDocument

    getDocument: async (path) => {
        try{
            console.log(`bucket.documents.getDocument(${path})`);
            const s3cmd = new AWS.GetObjectCommand({ Bucket: process.env.S3_DOCUMENTS_BUCKET, Key: path });
            const doc = await client.send(s3cmd);
            return doc;
        }
        catch(err){
            console.error(`path=${path}
            `, err);
            return undefined;
        }
    },

/manager/documents.js.getDocument

    getDocument: async(path) => {
        let document = await documentsRepo.getDocument(path);
        if(document){
            let stream = document.Body;
            return new Promise((resolve, reject) => {
                const chunks = []
                stream.on('data', chunk => chunks.push(chunk))
                stream.once('end', () => resolve(Buffer.concat(chunks)))
                stream.once('error', reject)
            });
        }
        return undefined;
    },

/controller/documents.js calling code

router.get("/*", async (req, res) => {
    let documentKey = decodeURI(req.path.substring(1));
    let document = await documentsManager.getDocument(documentKey);
    if(!document){
        res.status(400).json({ msg: "Requested file does not exist" });
        return;
    }
    res.write(document);
    res.end();
});

This error is being thrown from this line:

const s3cmd = new AWS.GetObjectCommand({ Bucket: process.env.S3_DOCUMENTS_BUCKET, Key: path });

This code doesn't always error - it depends on the environment.

  • Locally the code is executed by npm - eg. npm run start
  • On Prod the code is executed by pm2, the code is deployed manually and then npm ci is executed on the server to install the node_modules. Just like on dev.
  • On QA the code is deployed by a GitHub action to an AWS Lambda using the serverless framework.

The error only happens on QA so I am looking for a difference there but all I can find is serverless and GitHub actions. But I downloaded the GitHub built code and ran it locally using npm and it works fine.

@JasonGloverNZ
Copy link

What is the SDK trying to log? I haven't told it to log anything.

I event started looking at how to disable the built-in logging ... https://stackoverflow.com/questions/68066813/how-to-disable-aws-sdk-logging/75189203#75189203

@samzi123
Copy link

I'm experiencing the exact same issue. Did you find any solution?

@JasonGloverNZ
Copy link

JasonGloverNZ commented Jan 25, 2023 via email

@micchickenburger
Copy link
Author

@samzi123 @JasonGloverNZ If you have control over your logger functions you can use node’s util.inspect instead of JSON.stringify. See the bottom of the original post for an example.

@JasonGloverNZ
Copy link

JasonGloverNZ commented Jan 26, 2023 via email

@micchickenburger
Copy link
Author

Sure, I can see that. When you instantiate your S3 client, you can pass a custom logger that uses util.inspect as a workaround in the meantime. That function removes circular references and allows the S3 SDK to log without error. I agree that the library should not log at all unless a logger is passed to it.

@JasonGloverNZ
Copy link

JasonGloverNZ commented Jan 26, 2023 via email

@samzi123
Copy link

I'm kind of at a loss on this one. This is one of the few results on the internet for this error in this location. This code works in local development, only fails when deployed. Local dev: - node is executing. In QA: - build prepared by GitHub action - executing through serverless.com framework - process hosted by AWS lambda - same node version I'm wondering if somehow the SDK picks up that there is a logger provided to it by either the lambda environment (which I am guessing is some streamlined Linux) or by the serverless framework. I certainly haven't configured one anywhere. 🤷🏼‍♂️🧐
On Thu, Jan 26, 2023 at 11:25 AM, Micah Henning @.> wrote: Sure, I can see that. When you instantiate your S3 client, you can pass a custom logger that uses util.inspect as a workaround in the meantime. That function removes circular references and allows the S3 SDK to log without error. I agree that the library should not log at all unless a logger is passed to it. — Reply to this email directly, view it on GitHub <#4339 (comment)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAU2O3X5GI3WMML5WYPPJJLWUK6QRANCNFSM6AAAAAAT5HKMLE . You are receiving this because you were mentioned.Message ID: @.>
-- Jason Glover 415 530 6975 about.me/jasonglover

I had the same issue and was only getting the issue when deploying the code to Lambda with Serverless. I'm guessing it's due to some problem with Serverless' logging. I ended up using v2 of the aws-sdk to call getObject which resolved the issue.

@JasonGloverNZ
Copy link

I have managed to get past this problem by disabling the SDK's internal logging. I did so by setting logger: undefined

const s3Config = {
    endpoint: process.env.S3_ENDPOINT,
    region: process.env.S3_REGION,
    logger: undefined,
    credentials: {
        accessKeyId: process.env.S3_KEY,
        secretAccessKey: process.env.S3_SECRET
    }
};

@shrihari007
Copy link

shrihari007 commented Apr 3, 2023

Facing the same issue when trying to fetch data from s3. Since the above solution did not work, reverting back to sdk v2

@fxricky
Copy link

fxricky commented Jun 10, 2023

facing the error TypeError: Converting circular structure to JSON here, unable to return the s3 object thru nodejs application

@ajredniwja ajredniwja added queued This issues is on the AWS team's backlog and removed needs-review This issue/pr needs review from an internal developer. labels Sep 12, 2023
@kuhe kuhe added p1 This is a high priority issue p2 This is a standard priority issue and removed p2 This is a standard priority issue p1 This is a high priority issue labels Sep 12, 2023
@kuhe
Copy link
Contributor

kuhe commented Sep 12, 2023

Use import { inspect } from "node:util"; as the serializer instead of JSON.stringify.

Our logger interface has a variable number of arguments like the console logger. Provide a varargs-compatible logging implementation. In the example above, winston only logged the first argument.

const s3 = new S3({
  region: "us-west-2",
  logger: {
    ...logger,
    debug(...args) {
      return logger.debug(args.join(" "));
    },
    info(...args) {
      for (const arg of args) {
        logger.info(arg);
      }
    },
  },
});

example: concat or loop the arguments before passing to winston's single-argument logger.

The endpoints debug output looks like this:

[debug] endpoints evaluateCondition: aws.partition($Region) = {
  "dnsSuffix": "amazonaws.com",
  "dualStackDnsSuffix": "api.aws",
  "name": "aws",
  "supportsDualStack": true,
  "supportsFIPS": true,
  "description": "US West (Oregon)"
}
[debug] endpoints assign: partitionResult := {
  "dnsSuffix": "amazonaws.com",
  "dualStackDnsSuffix": "api.aws",
  "name": "aws",
  "supportsDualStack": true,
  "supportsFIPS": true,
  "description": "US West (Oregon)"
}
[debug] endpoints evaluateCondition: isValidHostLabel($Region, false) = true
[debug] endpoints evaluateCondition: booleanEquals($Accelerate, true) = false
[debug] endpoints evaluateCondition: booleanEquals($UseDualStack, true) = false
[debug] endpoints evaluateCondition: booleanEquals($UseDualStack, true) = false
[debug] endpoints evaluateCondition: booleanEquals($UseDualStack, true) = false
[debug] endpoints evaluateCondition: booleanEquals($UseDualStack, false) = true
[debug] endpoints evaluateCondition: booleanEquals($UseFIPS, true) = false

@kuhe kuhe added guidance General information and guidance, answers to FAQs, or recommended best practices/resources. and removed bug This issue is a bug. p2 This is a standard priority issue queued This issues is on the AWS team's backlog labels Sep 12, 2023
Copy link

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs and link to relevant comments in this thread.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Nov 22, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
guidance General information and guidance, answers to FAQs, or recommended best practices/resources.
Projects
None yet
Development

No branches or pull requests

8 participants