Error handling in Cloud functions - Cloud Logging

[mcozzi]

Hello. I have a series of cloud functions and I want to get an alert when errors occur in them. I already have the alert set and it works.
I decided to use the Cloud Logging logs: functions.logger.error(`Error ${error.message}`);
But for example when my function times out and I go to Logs Explorer I see these logs:
"Function execution started"
"Function execution took 4999 ms, finished with status: 'error' " or "Function execution took 4999 ms, finished with status: 'timeout' "
What should I do to handle those errors correctly? I tried to catch them but without good results. I would like to get a log with an ERROR severity (now their severity is DEBUG) in Cloud logging and therefore, get an alert sent to my email.
Thank you for your help.

[anjelisa]

Hi @mcozzi,

Welcome to Google Cloud Community!

There are multiple cases reported with the same error (Function execution took xxx ms, finished with status: 'error' ) and related high latency yesterday, and the cause of this could be from the incident yesterday.

Summary: Google Cloud Networking experiencing elevated latency in multiple regions

See here, https://status.cloud.google.com/incidents/nieR2aLyg1rwFKq1aWZU#2c2sBHWU84yPDJ8y1ar4

On the other hand, you can set the time out duration higher than your expected function execution time using this document.

Furthermore, logs from Cloud function with DEBUG severity are only messages from the internal system like the status of the function execution, the info  for function execution - they are tagged as DEBUG log level and does not automatically mean an error. See documentation. So I would not recommend catching logs with DEBUG log level. However, you can use log-based alerts and configure it to notify you whenever that kind of log_id appears in your logs. Refer to this documentation for guidance.

Let me know if these help.

[mcozzi]

Hello Anjelisa, thanks for your answer.

I'm not using metrics (only alerts), so alerts are triggered by errors log in Cloud Logging.
My main objective is to get  possible errors logged with severity ERROR so as to get alerted of them and don't miss anyone. 

The thing is that I had a timeout in the past and fixed it but I saw it because I went to the cloud function's Register. I did it manually and I could have not seen it, and what I want now is to get notified by the system so as not to miss anything.
Now I'm not getting that error (I'm forcing a timeout now so as to try to catch it ) but maybe in the future I get them and I don't see them.

If I see a log like "Function execution took xxx ms, finished with status: 'error' " or "Function execution took xxx ms, finished with status: 'timeout' ", they are only caused by external problems like the incident you mentioned? Do you know a proper way to get us notified of those kind of errors so as to avoid having to see the cloud function's register? I would like to get an alert whenever a cloud function finishes with a status different from 'ok' or '200'.

[anjelisa]

Hi @mcozzi ,

You can use the link I provided to Create a log-based alert by using the Logs Explorer.

In this way you choose the logs for which you want to receive a notification, and specify whom to notify. You can create a log-based alert that notifies you whenever there's a log with severity 'ERROR' and/or log_id of the  function execution.

For example in the doc, you want find log entries with a severity level of NOTICE in the syslog log that have invalid IP addresses in the JSON payload, you can use the following query:

log_id("syslog")
severity = "NOTICE"
jsonPayload.result !~ "^((25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)(\.|$)){4}$"

After running the query, follow the next steps in the link to create the alerts.

The incident I mentioned is only one of the possible causes of the "Function execution took xxx ms, finished with status: 'timeout' " error which is the kind that should not be seen often.

[mcozzi]

Hello

Thank you for your response. I already created the logs and the alerts. I send you my query, the cloud function I want to get logged and the cloud function that I'm using to get a timeout and see if I can avoid missing a possible error.
My query is:

resource.type="cloud_function"

resource.labels.function_name="createTask"

severity>=ERROR

My cloud function is:

exports.addRubinzalUser = functions.https.onCall(async (data, context) => {
try{
const response = await entities.users.addRubinzalUser(data); 
if (response?.status === 201) {
return { status: 201, message: "User created successfully" };
} else {
const indexOfExecutionId = Object.values(context.rawRequest.rawHeaders).indexOf("Function-Execution-Id")+1;
functions.logger.error(`Error ${response.message}`, {
error: Object.values(response.data),
requestBody: context.rawRequest.body.data,
functionExecutionId: context.rawRequest.rawHeaders[indexOfExecutionId]
});
return { status: 400, message: "Error when creating user" };
}
}catch(error){
console.log("--error-->", error)
functions.logger.error(`Error ${error.message}`, {
error: error.message,
requestBody: context.rawRequest.body.data,
severity: 'ERROR',
});
return { status: 400, message: "Error in function" };
}
});

Cloud function for testing, that results in timeout: 

exports.function = functions.runWith({ timeoutSeconds: 5 }).https.onCall(async (data, context) => {
try{ await new Promise((resolve) => setTimeout(resolve, 10000));
}catch(error){
functions.logger.error(Error ${error.message}); return { status: 400, message: "Error in function" }; } }); 

I have tried several errors to see how and if they get logged and when for some reason the user isn't created successfully I see and error like the following, which is what I intended:

But when I forced  a timeout for example I got the following:

Catching this second kind of error is what I'm missing and what I would like to catch so as to avoid having some trouble in my app.

What I've done goes according to what you were saying? I would really appreciate your help to solve this. If you think there's a better way to fix this please tell me.
Thank you for your help.

Marcela

[mcozzi]

my query is:

resource.type="cloud_function"

resource.labels.function_name="addRubinzalUser"

severity>=ERROR

[aborge]

The second entry in your log is not an error, it is just a log message, the error ocurred in the try {...} part of your function. 

The line in your logs with the text: Function execution took 63 ms, finished with status: 'error'
It is just Google Cloud reporting the execution result:

const functions = require('@google-cloud/functions-framework')


functions.http('helloWorld', async (req, res) => {
    try {
        throw new Error('MY_ERROR'); // This error should be reported on Error Reporting!
        res.status(200).send('OK')
    } catch (error) {
        console.log(error) // MY_ERROR 
       
        // Function execution took 63 ms, finished with status: 'error'
        res.status(500).send('ERROR')
    }
})