Getting a timeout error when using LoggingBunyan

[Kylar13]

No matter what I try, I'm getting the following error when logging to GCP using Bunyan and this library

GoogleError: Total timeout of API google.logging.v2.LoggingServiceV2 exceeded 60000 milliseconds before any response was received.
    at repeat (/Users/ramonpans/Developer/Bankflip/core/node_modules/google-gax/src/normalCalls/retries.ts:84:23)
    at Timeout._onTimeout (/Users/ramonpans/Developer/Bankflip/core/node_modules/google-gax/src/normalCalls/retries.ts:125:13)
    at listOnTimeout (node:internal/timers:557:17)
    at processTimers (node:internal/timers:500:7) {
  code: 4
}

Providing a minimal reproduction. Unsure if it's a bug or just something that I'm doing wrong

const gcpTransport = new LoggingBunyan({
    credentials: JSON.parse(credentialString),
    projectId,
});
const logger = bunyan.createLogger({
    name: 'core',
    serializers: { err: bunyan.stdSerializers.err },
    streams: [gcpTransport.stream('info')],
});
const httpRequestSerializer = (res: Response) => {
    return {
        requestMethod: res.req.method,
        requestUrl: res.req.url,
        requestSize: res.req.socket.bytesRead,
        status: res.statusCode,
        responseSize: res.req.socket.bytesWritten ?? 0,
        userAgent: res.req.get('user-agent'),
        latency: `${(Number(res.get('x-response-time') ?? 0) / 1000).toFixed(6)}s`,
        protocol: `HTTP/${res.req.httpVersion}`,
    };
};
logger.addSerializers({ httpRequest: httpRequestSerializer });

const app = express();

app.use(responseTime({ digits: 3, suffix: false }));
app.use(requestId());
app.use((req, res, next) => {
    onFinished(res, (err, res) => {
        const log = logger.child({ id: res.req.id }, true);
        log.info({
            httpRequest: res,
            err: err ?? undefined,
        });
    });
    next();
});

app.use('/', (req, res, next) => {
    res.json({ all: 'good' });
});

app.listen(3002);

I get nothing on stdout or GCP until a minute passes and then the error shows and the app crashes.

Thanks in advance for the help!!

[Kylar13]

I'm guessing it is somehow related to this: https://github.com/googleapis/nodejs-logging/issues/1185

[Taaanos]

@Kylar13 it is known, these are relevant too: https://github.com/googleapis/nodejs-logging-bunyan/issues/595, https://github.com/googleapis/nodejs-logging-bunyan/pull/601

[losalex]

@Kylar13 , thanks for opening the issue! Can you please upgrade to latest 3.2.2 package and follow instructions suggested in error-handling-with-a-default-callback to handle timeout errors? Also, can you tell me if timeouts you experience somehow related to a nodejs-logging-bunyan library upgrade or it is temporary situation?

[Kylar13]

As far as I can tell, it's due to logging on the "onFinished" callback, since I log a "Logger ready" after initialization, and it logs normally. The problem is that when I try to await it, it makes no difference since I'm using bunyan and not the base logging library. The error handling will help in the app not crashing, but I still won't get logs, right?

[Kylar13]

Any updates on this?

[losalex]

Sorry @Kylar13 for late reply - you right, while crashing can be prevented, still logs might not be written due to a lack of await capabilities. I believe that one of the possible solutions here is to use console logging with Google Logging Agent (which should be available in GCP) - the nodejs-logging library introduced LogSync class which supports structured logging output into console. From the console log records are picked by the agents running in GCP nodes and delivered to Cloud Logging. However, LogSync class is not integrated with nodejs-logging-bunyan and requires a code change. Please let me know if you think this could be acceptable solution.

[losalex]

Thanks a lot for your patience - I believe this issue is addressed by 605. Feel free to reactivate or comment if you have more concerns.

[pmwisdom]

I can confirm this fixed my issues in Cloud Functions.

[losalex]

Thank you @pmwisdom for confirmation!