Azure function restarts midway then never returns (HTTP Trigger)

Question

I have a nodejs app function that is triggered via HTTP. It calls a cosmosdb stored procedure, sets some output bindings for event hub, then returns to the user.

The issue is the function is working properly, but for some reason it ALWAYS restarts before returning to the user, which even after making the stored procedure handle such event, the function then never returns. In postman it always returns a generic azure 502. In the testing UI it eventually seems to timeout and has a response of 500 with no body.

When I run this via the azure function testing, it always seems to restart mid-way through. Almost always it gets to the very end and even calls Context.done(). I know this because the event hub events are being sent and trigger other functions. HOWEVER, instead of returning the HTTP res to the user, it restarts the app, goes through everything, and either throws an error, which is logged in the .catch but NEVER returns from the HTTP call. It eventually just hits the timeout and returns a 500 or 502.

Even more odd, when looking at the entry logs under the 'monitor' tab, only the second run exists but shows it executed successfully! I've tried running the function via Azure function testing and via postman and the result is the same.

The function used to return a promise, which I've had issues with in the past, so I've converted to calling context.done() with no luck. What is causing this?

Here is an example run that eventually returns a 500 (taken from the function testing log stream):

2018-03-27T17:27:57.636 [Info] Function started (Id=b4c64acc-3120-4dbd-b067-034ef7e6b548)
2018-03-27T17:28:00.436 [Info] 1
2018-03-27T17:28:07.167 [Info] Function started (Id=59ef098a-8ce0-43fa-9a98-c2043f40566a)
2018-03-27T17:28:10.452 [Info] 1
2018-03-27T17:28:10.881 [Info] 2
2018-03-27T17:28:10.886 [Info] 3
2018-03-27T17:29:22  No new trace in the past 1 min(s).
2018-03-27T17:30:22  No new trace in the past 2 min(s).
2018-03-27T17:31:22  No new trace in the past 3 min(s).
2018-03-27T17:32:22  No new trace in the past 4 min(s).

And one that gets all the way to context.done():

2018-03-27T17:33:56.887 [Info] Function started (Id=7e0c9d3d-549b-4f7f-905b-454d69e18cca)
2018-03-27T17:34:00.902 [Info] 1
2018-03-27T17:34:01.324 [Info] 2
2018-03-27T17:34:01.339 [Info] 3
2018-03-27T17:34:02.121 [Info] 4
2018-03-27T17:34:02.121 [Info] 5
2018-03-27T17:34:02.121 [Info] 6
2018-03-27T17:34:08.563 [Info] Function started (Id=ffcdf487-d1e6-4422-856f-ed709470605b)
2018-03-27T17:34:12.090 [Info] 1
2018-03-27T17:34:12.530 [Info] 2
2018-03-27T17:34:12.530 [Info] 3
2018-03-27T17:35:22  No new trace in the past 1 min(s).
2018-03-27T17:36:22  No new trace in the past 2 min(s).
2018-03-27T17:37:22  No new trace in the past 3 min(s).
2018-03-27T17:38:22  No new trace in the past 4 min(s).
2018-03-27T17:39:22  No new trace in the past 5 min(s).
2018-03-27T17:40:22  No new trace in the past 6 min(s).

I have tried restarting the function app which didn't seem to help. This is a consumption plan app if it matters.

The function is as follows:

const DB = require('../Shared/DB');
const Errors = require('../Shared/Errors');
const Auth = require("../Shared/Auth");
const Approvals = require("../Shared/Approval");

module.exports = function (context, req) {
  let user; 
  let found;
  let outMessage = 'CheckoutRequested';
  let outMessageObj = {'id': req.params.id};
  return Auth.get_user_from_request(req).then( (u) => {
    context.log(1);
    user = u;
    outMessageObj['user'] = u.raw();

    if (!req.params.id) throw new Errors.BadRequestError("Id is a required parameters.");

    const db = new DB();
    // Call stored procedure;
    return db.check_out(req.params.id, user);
  }).then( (res) => { 
    context.log(2);
    found = res;
    outMessageObj['found'] = found;

    context.log(3);
    return Approvals.get_approvers(user, found);
  }).then(approvers => {
      context.log(4);
    // Determine the type of event hub message to send.
    if (approvers.length == 0){
      outMessage = 'CheckoutApproved';
    }

    outMessageObj['approvers'] = approvers;

    context.bindings[outMessage] = outMessageObj;
    context.log(5);
    context.bindings.res = {
      status: 200,
      body: {
        "found": found, 
        "user": user
      }
    };
    context.bindings.output = context.bindings.res;
    context.log(6);
    context.done();
  }).catch( (error) => {
      context.log('error');
    context.log.error(error);
    if (outMessageObj.user){
      context.bindings['CheckoutFailed'] = outMessageObj;
    }
    context.bindings.res = {
      status: 500,
      body: {
        "error": error.message, 
      }
    };
    context.done();
  });
};

I've got 3 output bindings on 3 different partitions based on the output:

{
  "bindings": [
    {
      "authLevel": "function",
      "type": "httpTrigger",
      "direction": "in",
      "name": "req",
      "route": "checkout/{id}",
      "methods": [
        "put"
      ]
    },
    {
      "type": "http",
      "direction": "out",
      "name": "res"
    },
    {
      "type": "eventHub",
      "name": "CheckoutApproved",
      "connection": "********",
      "path": "CheckoutApproved",
      "direction": "out"
    },
    {
      "type": "eventHub",
      "name": "CheckoutRequested",
      "connection": "********",
      "path": "CheckoutRequested",
      "direction": "out"
    },
    {
      "type": "eventHub",
      "name": "CheckoutFailed",
      "connection": "********",
      "path": "CheckoutFailed",
      "direction": "out"
    }
  ],
  "disabled": false
}

EDIT: To add to this, I've tried setting the output to all the context.res, context.bindings.res, context.done(null, response object), and returning a promise.

matt matt · Accepted Answer · 2018-03-27T17:57:59

Have you tried returning your status code in context.res?

Something like this context.res = { status: 200, body: items };

Azure function restarts midway then never returns (HTTP Trigger)

1 Answers