Netlify function runs into timeout being idle for 10+ seconds between last log statement and sending response

Site name: bcup-members.netlify.app

Hi,

I have a problem with a Netlify function which runs into a timeout, but I don’t know why. From the other functions I have tested in my app so far, this is the only one which runs into a timeout.

Because of that timeout I added logging statements to that function to see the timestamps when the function is at what point in the code. As follows is the log of one call. As seen all logging statements including the last occur in the same second the function get invoked.

And then 10 seconds after the last log the timeout log comes.

7:30:48 PM: e68fd74c INFO   [request] /api/member/card
7:30:48 PM: e68fd74c INFO   user:  auth0|5ee294........
7:30:48 PM: e68fd74c INFO   member id:  29431890......
7:30:48 PM: e68fd74c INFO   before fauna request
7:30:48 PM: e68fd74c INFO   after fauna request
7:30:48 PM: e68fd74c INFO   id 1617811......
7:30:48 PM: e68fd74c INFO   member {
    firstname: 'yxyxyxyyx',
    lastname: 'yxyxyyyxyx',
    email: 'yxyxyxyx@yxyxyxy.yyx',
    joinedDate: '2009-05-21T00:00:00.000Z',
    registered: false,
    invited: true
}
7:30:58 PM: e68fd74c Duration: 10010.55 ms	Memory Usage: 46 MB
7:30:58 PM: e68fd74c ERROR  Task timed out after 10.01 seconds

As follows is my function code in Typescript. As you can see right after the last logging statement there is only one call left to return the respone res.status(200).json(member);

I have no idea what could possibly be wrong here. That function runs flawlessly on localhost in <1 second.

import { getSession, withApiAuthRequired } from '@auth0/nextjs-auth0';
import { query } from 'faunadb';

import { IUserProfile } from '@utilities/auth0/types';
import { faunaApiClient } from '@utilities/fauna/faunaClient';
import { IClubMember } from '@utilities/types/club';

type IFaunaClubMember = IClubMember & {
  joinedDate: {
    date: Date;
  };
};

export default withApiAuthRequired(async function card(req, res) {
  const { user } = getSession(req, res);

  // LOGGING - START
  console.log('user: ', user.sub);
  console.log(
    'member id: ',
    (user as IUserProfile).app_metadata.club_member_id
  );
  // LOGGING - END

  try {
    // LOGGING - START
    console.log('before fauna request');
    // LOGGING - END

    const response = await faunaApiClient.query<{
      ts: number;
      data: IFaunaClubMember;
    }>(
      query.Get(
        query.Ref(
          query.Collection('ClubMember'),
          (user as IUserProfile).app_metadata.club_member_id
        )
      )
    );

    // LOGGING - START
    console.log('after fauna request');
    console.log('id', response.ts);
    // LOGGING - END

    const member = {
      ...response.data,
      joinedDate: response.data.joinedDate.date.toISOString(),
    };

    // LOGGING - START
    console.log('member', member);
    // LOGGING - END

    res.status(200).json(member);
  } catch (error) {
    console.error(error);
    res.status(error.status || 500).json({
      code: error.code,
      error: error.message,
    });
  }
});

I hope somebody has a clue what’s wrong here or what I’m missing.

Best regards,
tpinne

Hi tpinne,

I had to use async instead of a callback to make it work in production for me. See post

Maybe in your case it helps to decouple the status and json functions and use await for these promises too?

1 Like

that’s a great idea @pa-nic. thanks for contributing!

Thx, for the response. But it maybe needs further context from my side. My bad that I left that out in my initial post.

This is a NextJS project and this is a NextJS API route protected by Auth0. So res here is of type NextApiResponse and the status() and json() methods of res.status(200).json(member); do not return Promises. status is chained and returns a modified NextApiResponse and json sends everything to the browser.

So there isn’t a callback which can be switched to async

I have other API routes that work fine following the exact same pattern. I found another function which runs into timeouts and compared it one that doesn’t.
And the only real difference is that in the one that runs into timeouts fetches data from Fauna via the JS API and the other one does it via GraphQL (also from Fauna).

Working API route using Fauna GQL:

import { getSession, withApiAuthRequired } from '@auth0/nextjs-auth0';
import { gql } from 'graphql-request';

import {
  createUserPermissionsFromAccessToken,
  UserPermission,
} from '@utilities/auth0/userPermission';
import { faunaGraphQLClient } from '@utilities/fauna/faunaClient';
import { IClubMember } from '@utilities/types/club';

interface IResponse {
  allClubMembers: { data: IClubMember[] };
}

export default withApiAuthRequired(async function list(req, res) {
  const { accessToken } = getSession(req, res);
  const userPermissions = createUserPermissionsFromAccessToken(accessToken);

  if (!userPermissions.has(UserPermission.MEMBER_READ)) {
    res.status(403);
  }

  try {
    const query = gql`
      {
        allClubMembers {
          data {
            _id
            firstname
            lastname
            email
            joinedDate
            validUntil
            registered
            invited
          }
        }
      }
    `;

    const response = await faunaGraphQLClient.request<IResponse>(query);

    res.status(200).json(response.allClubMembers.data);
  } catch (error) {
    console.error(error);
    res.status(error.status || 500).json({
      code: error.code,
      error: error.message,
    });
  }
});

Another not working API route using Fauna JS API:

import { getSession, withApiAuthRequired } from '@auth0/nextjs-auth0';
import { query } from 'faunadb';

import {
  createUserPermissionsFromAccessToken,
  UserPermission,
} from '@utilities/auth0/userPermission';
import { faunaApiClient } from '@utilities/fauna/faunaClient';
import { IMemberFormData } from '@utilities/types/form/member';

export default withApiAuthRequired(async function create(req, res) {
  const { accessToken } = getSession(req, res);
  const userPermissions = createUserPermissionsFromAccessToken(accessToken);

  if (!userPermissions.has(UserPermission.MEMBER_CREATE)) {
    res.status(403);
  }

  const data: IMemberFormData = JSON.parse(req.body);

  try {
    const response = await faunaApiClient.query(
      query.Create(query.Collection('ClubMember'), {
        data: {
          firstname: data.firstname,
          lastname: data.lastname,
          email: data.email,
          joinedDate: query.Date(data.joinedDate),
        },
      })
    );

    res.status(200).json(true);
  } catch (error) {
    console.error(error);
    res.status(error.status || 500).json({
      code: error.code,
      error: error.message,
    });
  }
});

Hi, @tpinne. I don’t know the specific of your code but 99.9% the root cause of these “timeout after the successful completion” issues with functions is that the external connection (for example, HTTP/2 connections, database connections, etc.) are not being closed manually when the query is complete. The connection being open keeps the code from returning and the function times out.

Looking at this documentation here it might be as simple as disabling the “keep-alive” setting:

Hi @luke,

thx for that suggestion. I tried that option with no success. I created the most simple API route code with a fauna connection to eliminate every possible side effect through other imports or even Auth0. The following code just connects to Fauna with keepAlive: false and generates a new ID. Nothing more than that. And returns the response which is just an integer.

import { Client, query } from 'faunadb';

export default async function faunaCheck(req, res) {
  try {
    const client = new Client({
      secret: process.env.FAUNADB_SERVER_SECRET,
      keepAlive: false,
    });

    const response = await client.query(query.NewId());

    console.log(response);

    res.status(200).json(response);
  } catch (error) {
    console.error(error);
    res.status(error.status || 500).json({
      code: error.code,
      error: error.message,
    });
  }
}

And the result is the same. I also tried to return the response as plain body like res.status(200).send(response); to rule out any problems with converting to json.

1:08:31 PM: 38041abc INFO   [request] /api/fauna-check-json
1:08:31 PM: 38041abc INFO   295301296086319618   <--- this is the console.log(response)
1:08:41 PM: 38041abc Duration: 10010.49 ms	Memory Usage: 78 MB	Init Duration: 295.31 ms
1:08:41 PM: 38041abc ERROR  Task timed out after 10.01 seconds

I tried everything now you guys here and other posts on the internet suggested. Like using keepAlive: false, putting await in front of the client.query call, boiled the code down to a minimum.

So, just to test and rule further things out, I deployed the site to Vercel. I don’t like the platform by any means, but the same code without any modifications runs perfectly fine. So I’m guessing I’m not missing anything codewise.

Maybe there is something that causes this problems in the way the Netlify NextJS Build Plugin produces the functions or anything else? From what I can tell at the moment, that is the most obvious difference between those two services (despite the overall architecture).

But for now I’m totally clueless where to dig deeper on my end :frowning:

@tpinne hey there! i wonder if this is also your issue: getServerSideProps functions times out when connecting to MongoDB · Issue #191 · netlify/next-runtime · GitHub

to test this, you could try to patch-package @netlify/plugin-nextjs (pretty straightforward) and add context.callbackWaitsForEmptyEventLoop = false; in this file: https://github.com/netlify/netlify-plugin-nextjs/blob/main/src/lib/templates/netlifyFunction.js#L13

let me know if that works. per conversation on this issue (Default callbackWaitsForEmptyEventLoop to false? · Issue #190 · netlify/next-runtime · GitHub), we’re hoping to make some changes to help avoid a lot more of these [db-related] timeout issues in next on netlify projects.

keep me updated here or feel free to chime in on the github issues!!!

4 Likes

Yo @lindsaylevine you’re the savior of the day. Works like a charm and really easy to use with patch-package. Hope this gets integrated soon into the package itself.

And thx everybody in this thread who helped to get to this solution so fast.

1 Like

I’m currently running into this issue. Code works fine in Zeit/Vercel, however, in Netlify my API is timing out. Build includes Next.js, Netlify-plugin-nextjs, mongoose.

Was there a permanent solution to toggle callbackWaitsForEmptyEventLoop to false or what solution has been put forward.

Unfortunately, I’m finding it impossible to complete the ‘Solution’ above as the link is not longer active. What is the best solution here?

Thanks.

@Raymond_Ayala hey! yes, there was a permanent solution added :). what version of next.js are you using? and what version of netlify-plugin-nextjs (should say in your build logs)?

we just rewrote our plugin, and i’d love for you to try out our alpha to see if it fixes your issue. it’s not quite ready for production but will be very soon! to try, head to @netlify/plugin-nextjs-experimental - npm and follow the instructions there. let us know!

1 Like

The proposed package worked like a charm! No timeouts as API responds in <1s. Thank you so much.

Cheers!