[Firestore] Error: 4 DEADLINE_EXCEEDED: Deadline exceeded

[tiagomendonc]

[REQUIRED] Version info

node: 18

firebase-functions: 4.4.0

firebase-tools: not used

firebase-admin: 11.8.0

[REQUIRED] Test case

We use a firestore function as a trigger, every time a doc is updated with some item, the function should update a field value.

exports.onUpdateOrderItem = functions.firestore
  .document('/orders/{orderId}/items/{orderItemId}')
  .onWrite(onUpdateOrderItem);

exports.onUpdateOrdertItem = async (snap, context) => {
  const { incrementOrderTotal } = require('./actions');
  const {
    AdministrativeOrderItemType,
  } = require('../constants/administrativeOrders');

  const orderId = context.params.orderId;
  let incrementValue = 0;

  // OnCreate
  if (!snap.before.exists) {
    const orderItem = snap.after.data();

    if (orderItem.type === AdministrativeOrderItemType) return true;

    if (orderItem.name) {
      incrementValue = parseFloat(orderItem.fare.total);
    }
  }

  // onUpdate
  else if (snap.after.exists) {
    const after = snap.after.data();
    const before = snap.before.data();

    if (after.type === AdministrativeOrderItemType) return true;

    if (after.name) {
      if (!before.name) {
        incrementValue = after.fare ? parseFloat(after.fare.total) : 0;
      } else {
        const afterTotal = after.fare ? parseFloat(after.fare.total) : 0;
        const beforeTotal = before.fare ? parseFloat(before.fare.total) : 0;

        if (afterTotal !== beforeTotal)
          incrementValue = afterTotal - beforeTotal;

        // Handle refund
        if (after.refunded) {
          // If both before and after are refunded, do not increment anything
          if (before.refunded) {
            incrementValue = 0;
          } else incrementValue -= afterTotal;

          // If was refunded, but is not anymore
        } else if (before.refunded) {
          incrementValue = afterTotal;
        }
      }
    }
  }

  // onDelete
  else {
    const orderItem = snap.before.data();

    if (orderItem.type === AdministrativeOrderItemType) return true;

    if (orderItem.name && !orderItem.refunded) {
      incrementValue = -parseFloat(orderItem.fare.total);
    }
  }

  if (incrementValue) incrementOrderTotal(orderId, incrementValue);

  return {};
};

exports.incrementOrerTotal = async (orderId, value, retries = 1) => {
  const { updateDocumentFromFirebase } = require('../utils/firebase');
  const { FieldValue } = require('firebase-admin/firestore');
  const { logger } = require('../utils/bunyan');
  const { incrementErrorHandling } = require('./utils');

  try {
    if (!value || isNaN(value)) return true;

    await updateDocumentFromFirebase(`orders`, ordertId, {
      'fare.total': FieldValue.increment(Number(value)),
    });

    return true;
  } catch (err) {
    logger.error(
      {
        message: 'Unable to increment order total',
        orderId,
        value,
      },
      err
    );
  }
};

exports.updateDocumentFromFirebase = async (
  collection,
  docId,
  payload,
  usingSet
) => {
  try {
    const db = this.app.firestore();
    let query;

    if (usingSet) {
      query = await db
        .collection(collection)
        .doc(docId)
        .set(payload, { merge: true });
    } else {
      query = await db.collection(collection).doc(docId).update(payload);
    }

    return query;
  } catch (err) {
    logger.error({ message: 'Unable to get document', collection, docId }, err);
    return null;
  }
};

[REQUIRED] Expected behavior

It was expected to the document be updated.

[REQUIRED] Actual behavior

Error: 4 DEADLINE_EXCEEDED: Deadline exceeded
    at callErrorFromStatus (/workspace/node_modules/@grpc/grpc-js/build/src/call.js:31:19)
    at Object.onReceiveStatus (/workspace/node_modules/@grpc/grpc-js/build/src/client.js:192:76)
    at Object.onReceiveStatus (/workspace/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:360:141)
    at Object.onReceiveStatus (/workspace/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:323:181)
    at /workspace/node_modules/@grpc/grpc-js/build/src/resolving-call.js:94:78
    at process.processTicksAndRejections (node:internal/process/task_queues:77:11)
for call at
    at ServiceClientImpl.makeUnaryRequest (/workspace/node_modules/@grpc/grpc-js/build/src/client.js:160:32)
    at ServiceClientImpl.<anonymous> (/workspace/node_modules/@grpc/grpc-js/build/src/make-client.js:105:19)
    at /workspace/node_modules/@google-cloud/firestore/build/src/v1/firestore_client.js:227:29
    at /workspace/node_modules/google-gax/build/src/normalCalls/timeout.js:44:16
    at repeat (/workspace/node_modules/google-gax/build/src/normalCalls/retries.js:80:25)
    at /workspace/node_modules/google-gax/build/src/normalCalls/retries.js:118:13
    at OngoingCallPromise.call (/workspace/node_modules/google-gax/build/src/call.js:67:27)
    at NormalApiCaller.call (/workspace/node_modules/google-gax/build/src/normalCalls/normalApiCaller.js:34:19)
    at /workspace/node_modules/google-gax/build/src/createApiCall.js:84:30
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
Caused by: Error
    at WriteBatch.commit (/workspace/node_modules/@google-cloud/firestore/build/src/write-batch.js:433:23)
    at DocumentReference.update (/workspace/node_modules/@google-cloud/firestore/build/src/reference.js:435:14)
    at Object.<anonymous> (/workspace/lib/utils/firebase.js:118:64)
    at Generator.next (<anonymous>)
    at /workspace/lib/utils/firebase.js:7:71
    at new Promise (<anonymous>)
    at __awaiter (/workspace/lib/utils/firebase.js:3:12)
    at exports.updateDocumentFromFirebase (/workspace/lib/utils/firebase.js:107:80)
    at Object.<anonymous> (/workspace/lib/budgets/actions.js:274:15)
    at Generator.next (<anonymous>) {
  code: 4,
  details: 'Deadline exceeded',
  metadata: Metadata { internalRepr: Map(0) {}, options: {} },
  note: 'Exception occurred in retry method that was not classified as transient'
}

Were you able to successfully deploy your functions?

Yes

[inlined]

In the future, please provide a minimal repro rather than you full application. From what I can tell, you've missed an await on your call to incrementOrderTotal in your main function, which means the write to Firestore is happening after your function has completed. When there is no function running, the VM is severely throttled, which is most easily observed by network requests timing out. Adding an await to keep your function executing while you still have outstanding work should fix this.