Advanced Debugging Assistant

Summary: A non-atomic check-then-act across 4 replicas (read → 50 ms sleep → read-modify-write), with no enforcement in Postgres, lets many requests pass the stock check. A missing error path turns every "out of stock" into a hung request and a process crash.

Before the issues, one caveat. The code shown is not exactly the code producing your logs:

• orders.js calls redisClient.get(...) but never imports redisClient. As pasted, getStock would throw ReferenceError on every request, and no order could ever succeed.
• The stack trace references inventoryService.js:29 and :34 and a WATCH/MULTI transaction. The pasted file is about 14 lines long and contains no WATCH.

The root-cause analysis below holds for both versions, because the race exists whether or not WATCH is used this way. Still, please confirm what is actually deployed, for example with git log on the image tag. I'm also assuming a schema (products(sku, stock_units), orders(...)) and a pg Pool at src/lib/db, because orderService.js wasn't provided. Send it if my assumptions are wrong.

Mental reproduction (50 concurrent requests, stock = 1, 4 replicas)

t=0ms    Req A..Z (spread across 4 tasks) → GET stock:SKU-4471 → all read "1"
         all pass `1 < 1 === false` check
t=0-50ms everyone sleeps 50 ms (the "fraud check")  ← window is now huge
t=50ms   Req A: GET → 1, SET 0      → createOrder ✅
         Req B: GET → 0, SET -1     → createOrder ✅
         Req C: GET → -1, SET -2    → createOrder ✅
         Req D, E: GET → -2 (both), SET -3 (both)  ← lost update, both ✅
         ...
later    Req that read stock after the first SET sees 0 → throw 'out of stock'
         → unhandled rejection → Node 20 kills the task → pm2 restarts

Every request whose initial GET landed before the first SET believes stock exists. That is why you get 6–9 successes instead of 1. The exact number depends on how many requests arrive within the check window. Postgres has no CHECK constraint (migration 0032 dropped it), so nothing downstream stops them either.

Things only go "correctly" out of stock for requests arriving late. Those throw, get no response, and crash the replica.

Issue #1: Race condition (TOCTOU / non-atomic check-and-decrement)

• Location: processOrder (the getStock check, the sleep, then decrementStock) and all of decrementStock
• Severity: High (this is the bug that causes overselling)
• Root cause:
  1. Check and act are separate operations. The stock check (getStock) and the decrement happen at different times, with at least 50 ms and several network round-trips between them. Any number of other requests can pass the same check in that window.
  2. decrementStock is itself a read-modify-write. It does GET, subtracts in JavaScript, then SETs an absolute value. Wrapping only the SET in MULTI provides zero protection. MULTI makes the queued commands atomic, but the GET happened outside the transaction.
     • Even with WATCH, you'd need to check exec() returning null (transaction aborted) and retry. The code doesn't do this.
     • ioredis's exec() also doesn't throw on per-command errors. It returns [[err, result], ...].
  3. In-process locks can't help. With 4 ECS replicas, a Node mutex or queue only serializes within one task. The atomicity has to live in Redis and/or Postgres.
• Fix: Perform check + decrement as one atomic server-side operation. A Lua script executes atomically in Redis, so no other command interleaves:

// src/services/inventoryService.js
const redisClient = require('../lib/redisClient');

class OutOfStockError extends Error {
  constructor(sku) { super(`out of stock: ${sku}`); this.name = 'OutOfStockError'; this.sku = sku; }
}
class StockNotInitializedError extends Error {
  constructor(sku) { super(`stock key missing for ${sku}`); this.name = 'StockNotInitializedError'; this.sku = sku; }
}

// Atomic: returns new stock on success, -1 if insufficient, -2 if key missing.
redisClient.defineCommand('reserveStock', {
  numberOfKeys: 1,
  lua: `
    local raw = redis.call('GET', KEYS[1])
    if not raw then return -2 end
    local stock = tonumber(raw)
    local qty = tonumber(ARGV[1])
    if stock < qty then return -1 end
    return redis.call('DECRBY', KEYS[1], qty)
  `,
});

async function reserveStock(sku, quantity) {
  const result = await redisClient.reserveStock(`stock:${sku}`, quantity);
  if (result === -2) throw new StockNotInitializedError(sku);
  if (result === -1) throw new OutOfStockError(sku);
  return result;
}

async function releaseStock(sku, quantity) {
  return redisClient.incrby(`stock:${sku}`, quantity);
}

module.exports = { reserveStock, releaseStock, OutOfStockError, StockNotInitializedError };

• Verification: Set stock:SKU-4471 = 1, then fire 50 parallel reserveStock('SKU-4471', 1) calls with Promise.allSettled. Exactly 1 should be fulfilled, 49 rejected with OutOfStockError, and the final value should be 0. Repeat with 4 separate Node processes hitting the same Redis.
• Prevention: Treat any "read, decide in app code, write" sequence against shared state as a bug unless it is guarded by an atomic primitive: a Lua script, WATCH + retry on a null exec(), SELECT ... FOR UPDATE, or a conditional UPDATE ... WHERE.

Issue #2: Postgres (the source of truth) doesn't enforce the invariant

• Location: createOrder / orderService.js, and migration 0032_drop_stock_check.sql
• Severity: High
• Root cause:
  • Your spec says Postgres is the source of truth, yet it accepts stock_units = -8 because the CHECK constraint was dropped. Redis is a cache and can be flushed, evicted, restarted, or drift.
  • So Redis cannot be the only thing standing between you and overselling.
  • Also, Redis is decremented and then the order is inserted as a separate step. If createOrder fails, Redis is permanently off by quantity. This is the dual-write problem.
• Fix: Put the authoritative check in a single Postgres transaction, using a conditional update. Restore the constraint as a backstop.

// src/services/orderService.js  (assumes pg Pool at ../lib/db; adjust to your schema)
const pool = require('../lib/db');
const { OutOfStockError } = require('./inventoryService');

async function placeOrder({ sku, quantity, customerId }) {
  const client = await pool.connect();
  try {
    await client.query('BEGIN');

    // Atomic check-and-decrement: the row lock serializes concurrent writers.
    const upd = await client.query(
      `UPDATE products
          SET stock_units = stock_units - $1
        WHERE sku = $2 AND stock_units >= $1
        RETURNING stock_units`,
      [quantity, sku]
    );
    if (upd.rowCount === 0) throw new OutOfStockError(sku);

    const ins = await client.query(
      `INSERT INTO orders (sku, quantity, customer_id, status)
       VALUES ($1, $2, $3, 'confirmed')
       RETURNING *`,
      [sku, quantity, customerId]
    );

    await client.query('COMMIT');
    return ins.rows[0];
  } catch (err) {
    await client.query('ROLLBACK').catch(() => {});
    throw err;
  } finally {
    client.release();
  }
}

module.exports = { placeOrder };

-- migrations/0045_restore_stock_check.sql
-- NOT VALID lets you add it while bad rows (-8) exist; fix data, then validate.
ALTER TABLE products
  ADD CONSTRAINT products_stock_units_nonnegative CHECK (stock_units >= 0) NOT VALID;
-- after reconciling oversold rows:
-- ALTER TABLE products VALIDATE CONSTRAINT products_stock_units_nonnegative;

• Verification: Run 50 concurrent placeOrder calls directly against Postgres, bypassing Redis entirely, with stock_units = 1. Expect exactly 1 order row and stock_units = 0. A manual UPDATE products SET stock_units = -1 should now fail with a check violation.
• Prevention:
  • Invariants like "never negative" belong in the database as constraints, not only in app code.
  • Any migration that drops a constraint should need an explicit justification in review.
  • Use Redis as a fast-path gate, not the authority.

Issue #3: Unhandled rejection crashes the process; failed requests never get a response

• Location: the route handler in orders.js (processOrder(...).then(...) with no .catch, and no await)
• Severity: High
• Root cause:
  • Since Node 15, the default is --unhandled-rejections=throw. Any rejected promise with no handler terminates the process.
  • In this handler, processOrder rejects on every "out of stock" and on every Redis or Postgres error, and nobody catches it.
  • Consequences:
    1. The client never gets a 409. The socket hangs until ALB or k6 times out.
    2. The whole ECS task dies. It takes all other in-flight requests with it, which is the "exited with code 1" you see.
  • Express 4 does not catch async errors on its own (Express 5 does). You must try/catch and respond or call next(err).
  • The "Redis connection lost" error in your trace is just one of many errors that follow this same crash path.
• Fix:

router.post('/api/orders', async (req, res, next) => {
  try {
    // ...validate, then:
    const order = await processOrder(sku, quantity, customerId);
    return res.status(201).json(order);
  } catch (err) {
    if (err instanceof OutOfStockError) {
      return res.status(409).json({ error: 'out_of_stock', sku: err.sku });
    }
    return next(err); // central error handler → 500, logged
  }
});

• Verification: Set stock to 0 and POST once. You should get a 409 immediately, and the process should stay up. Kill Redis mid-request (docker pause redis). You should get a 500 or 503 response, not a crash.
• Prevention:
  • Never fire-and-forget a promise in a request handler.
  • Add ESLint @typescript-eslint/no-floating-promises or eslint-plugin-promise.
  • Add a central Express error middleware.
  • Log process.on('unhandledRejection') for visibility, but do not use it to swallow errors.

Issue #4: NaN bypasses the stock check; quantity is unvalidated

• Location: getStock (parseInt), and req.body destructuring
• Severity: High (for security and correctness)
• Root cause:
  • Missing key: if the Redis key is missing (eviction, flush, cold start), redisClient.get returns null. Then parseInt(null, 10) is NaN, and NaN < quantity is false, so the check passes. The code then writes NaN - 1, which is stored as the string "NaN" and poisons the key.
  • Bad quantity: it comes straight from the client.
    • quantity: -5 passes the check and increases stock, which lets anyone mint inventory.
    • quantity: 0 creates free orders.
    • quantity: "1e9" or quantity: 1.5 behave unpredictably due to type coercion.
  • Trusted customerId: customerId from the body lets anyone place orders as anyone.
• Fix:

const SKU_RE = /^[A-Z0-9-]{1,64}$/;
const MAX_QTY = 100;

function validateOrderInput(body) {
  const { sku, quantity } = body ?? {};
  if (typeof sku !== 'string' || !SKU_RE.test(sku)) return 'invalid sku';
  if (!Number.isInteger(quantity) || quantity < 1 || quantity > MAX_QTY) return 'invalid quantity';
  return null;
}

The Lua script in Issue #1 also returns -2 for a missing key instead of treating it as available. Derive customerId from the authenticated session (req.user.id), not the body.

• Verification:
  • POST quantity: -5, 0, "1", 1.5: each should return 400.
  • Run DEL stock:SKU-4471 and POST: you should get a 503 or a resync, never a 200.
• Prevention: Use schema validation at the edge (zod, joi, or ajv) on every route. Never trust identity fields sent in the request body.

Issue #5: Redis ↔ Postgres drift (dual write without compensation)

• Location: the sequence decrementStock → createOrder
• Severity: Medium
• Root cause:
  • Two separate stores can't be updated atomically. If the Redis decrement succeeds and Postgres fails, Redis under-reports stock forever. Postgres could fail because of the restored constraint, a timeout, or a crash.
  • The reverse can also happen: Postgres may say out of stock while Redis said OK, because Redis was stale.
• Fix: Reserve in Redis, commit in Postgres, and on any Postgres failure, compensate with releaseStock (shown in the refactor below). Add a periodic reconciliation job that sets Redis from Postgres. This covers the one gap compensation can't: a crash between the two steps.
• Verification: Inject a failure in placeOrder (e.g., throw after BEGIN). The Redis value should return to its original number.
• Prevention: Designate one authority (Postgres) and treat the other store as a derived cache. Reconcile on a schedule and alert on drift.

Issue #6: Artificial latency inside the critical section

• Location: the 50 ms setTimeout in processOrder
• Severity: Medium (it amplifies Issue #1)
• Root cause: Doing slow work (a fraud check) between check and act makes the race window 50 ms+ wide instead of microseconds. With the atomic fix, correctness no longer depends on this window. It's still better to run the fraud check before reserving stock, so you don't hold inventory for requests that will be rejected.
• Fix: Move the fraud check before reserveStock, or release the reservation if the fraud check fails after it.
• Prevention: Keep critical sections as short as possible, and don't do I/O while holding a reservation or lock.

Issue #7: Missing import, and code/deployment mismatch

• Location: orders.js (redisClient undefined); the stack trace's line numbers and WATCH/MULTI
• Severity: Low (as pasted it would be fatal; it indicates the deployed build differs)
• Fix: The refactored version removes getStock from the route entirely. Verify that the image deployed to ECS matches the commit you're debugging.

Refactored Version

// src/services/inventoryService.js
const redisClient = require('../lib/redisClient');

class OutOfStockError extends Error {
  constructor(sku) { super(`out of stock: ${sku}`); this.name = 'OutOfStockError'; this.sku = sku; }
}
class StockNotInitializedError extends Error {
  constructor(sku) { super(`stock key missing for ${sku}`); this.name = 'StockNotInitializedError'; this.sku = sku; }
}

const stockKey = (sku) => `stock:${sku}`;

// Runs atomically inside Redis: no other command can interleave.
redisClient.defineCommand('reserveStock', {
  numberOfKeys: 1,
  lua: `
    local raw = redis.call('GET', KEYS[1])
    if not raw then return -2 end
    local stock = tonumber(raw)
    local qty = tonumber(ARGV[1])
    if stock == nil or qty == nil or qty <= 0 then return -3 end
    if stock < qty then return -1 end
    return redis.call('DECRBY', KEYS[1], qty)
  `,
});

async function reserveStock(sku, quantity) {
  const result = await redisClient.reserveStock(stockKey(sku), quantity);
  if (result === -1) throw new OutOfStockError(sku);
  if (result === -2) throw new StockNotInitializedError(sku);
  if (result === -3) throw new Error(`corrupt stock value or bad quantity for ${sku}`);
  return result;
}

async function releaseStock(sku, quantity) {
  return redisClient.incrby(stockKey(sku), quantity);
}

async function setStockFromSource(sku, units) {
  return redisClient.set(stockKey(sku), units);
}

module.exports = {
  reserveStock,
  releaseStock,
  setStockFromSource,
  OutOfStockError,
  StockNotInitializedError,
};

// src/services/orderService.js
const pool = require('../lib/db');
const { OutOfStockError } = require('./inventoryService');

async function placeOrder({ sku, quantity, customerId }) {
  const client = await pool.connect();
  try {
    await client.query('BEGIN');

    const upd = await client.query(
      `UPDATE products
          SET stock_units = stock_units - $1
        WHERE sku = $2 AND stock_units >= $1
        RETURNING stock_units`,
      [quantity, sku]
    );
    if (upd.rowCount === 0) throw new OutOfStockError(sku);

    const ins = await client.query(
      `INSERT INTO orders (sku, quantity, customer_id, status)
       VALUES ($1, $2, $3, 'confirmed')
       RETURNING *`,
      [sku, quantity, customerId]
    );

    await client.query('COMMIT');
    return { order: ins.rows[0], remaining: upd.rows[0].stock_units };
  } catch (err) {
    await client.query('ROLLBACK').catch(() => {});
    throw err;
  } finally {
    client.release();
  }
}

async function getStockUnits(sku) {
  const { rows } = await pool.query('SELECT stock_units FROM products WHERE sku = $1', [sku]);
  return rows[0]?.stock_units ?? null;
}

module.exports = { placeOrder, getStockUnits };

// src/routes/orders.js
const router = require('express').Router();
const {
  reserveStock,
  releaseStock,
  setStockFromSource,
  OutOfStockError,
  StockNotInitializedError,
} = require('../services/inventoryService');
const { placeOrder, getStockUnits } = require('../services/orderService');
const { runFraudCheck } = require('../services/fraudService'); // your existing check
const logger = require('../lib/logger');

const SKU_RE = /^[A-Z0-9-]{1,64}$/;
const MAX_QTY = 100;

function validateOrderInput(body) {
  const { sku, quantity } = body ?? {};
  if (typeof sku !== 'string' || !SKU_RE.test(sku)) return 'invalid sku';
  if (!Number.isInteger(quantity) || quantity < 1 || quantity > MAX_QTY) return 'invalid quantity';
  return null;
}

router.post('/api/orders', async (req, res, next) => {
  const validationError = validateOrderInput(req.body);
  if (validationError) return res.status(400).json({ error: validationError });

  const { sku, quantity } = req.body;
  const customerId = req.user?.id; // from auth middleware, NOT the body
  if (!customerId) return res.status(401).json({ error: 'unauthenticated' });

  try {
    const order = await processOrder(sku, quantity, customerId);
    return res.status(201).json(order);
  } catch (err) {
    if (err instanceof OutOfStockError) {
      return res.status(409).json({ error: 'out_of_stock', sku });
    }
    if (err instanceof StockNotInitializedError) {
      return res.status(503).json({ error: 'inventory_unavailable', sku });
    }
    return next(err);
  }
});

async function processOrder(sku, quantity, customerId) {
  // 1. Slow checks BEFORE touching inventory; keep the critical section short.
  await runFraudCheck({ sku, quantity, customerId });

  // 2. Fast, atomic gate in Redis (rejects the other 49 without hitting Postgres).
  try {
    await reserveStock(sku, quantity);
  } catch (err) {
    if (err instanceof StockNotInitializedError) {
      await resyncFromPostgres(sku); // warm the cache for the next request
    }
    throw err;
  }

  // 3. Authoritative commit in Postgres; compensate Redis on ANY failure.
  try {
    const { order } = await placeOrder({ sku, quantity, customerId });
    return order;
  } catch (err) {
    await releaseStock(sku, quantity).catch((releaseErr) =>
      logger.error('failed to release redis reservation; reconciliation needed', {
        sku, quantity, releaseErr,
      })
    );
    if (err instanceof OutOfStockError) {
      // Redis said yes, Postgres said no → cache drifted; correct it.
      await resyncFromPostgres(sku);
    }
    throw err;
  }
}

async function resyncFromPostgres(sku) {
  try {
    const units = await getStockUnits(sku);
    if (units !== null) await setStockFromSource(sku, units);
  } catch (err) {
    logger.warn('stock resync failed', { sku, err });
  }
}

module.exports = router;

// src/app.js (excerpt): central error handler, registered after all routes
app.use((err, req, res, _next) => {
  req.log?.error({ err }, 'unhandled request error') ?? console.error(err);
  res.status(500).json({ error: 'internal_error' });
});

process.on('unhandledRejection', (reason) => {
  console.error('unhandledRejection', reason); // visibility only; still let it crash
  throw reason;
});

Why this is correct even though it spans two stores:

• Postgres is the single authority. The conditional UPDATE ... WHERE stock_units >= $1 takes a row lock. Concurrent transactions serialize on it, and the loser re-evaluates the WHERE against the committed value and matches 0 rows. Postgres alone guarantees exactly one success. The CHECK constraint is a second backstop.
• Redis is an optimization. It rejects the other 49 requests cheaply without opening 49 Postgres transactions. If Redis drifts, the worst case is a spurious 409 or an extra Postgres round-trip, never an oversell.

Recommendations

1. Concurrency regression test. Use Jest + testcontainers with real Redis and real Postgres, not mocks, because mocks can't reproduce races.

   test('only one of 50 concurrent orders wins the last unit', async () => {
     await seed({ sku: 'SKU-4471', units: 1 });
     const results = await Promise.allSettled(
       Array.from({ length: 50 }, (_, i) =>
         request(app).post('/api/orders').set(authFor(`c${i}`)).send({ sku: 'SKU-4471', quantity: 1 }))
     );
     const codes = results.map((r) => r.value.status);
     expect(codes.filter((c) => c === 201)).toHaveLength(1);
     expect(codes.filter((c) => c === 409)).toHaveLength(49);
     expect(await redis.get('stock:SKU-4471')).toBe('0');
     expect(await pgStock('SKU-4471')).toBe(0);
     expect(await orderCount('SKU-4471')).toBe(1);
   });
   

2. Re-run the k6 test across all 4 replicas.
   • Pass criteria: exactly one 201 and 49 409s. The run should have zero timeouts and zero task restarts, and both stores should end at 0.
   • Chaos variant: add docker pause on Redis mid-run and confirm that you get 503s but no oversell.
3. Clean up the existing damage. Find the oversold orders (orders for SKU-4471 beyond the first stock_units worth), cancel or refund them, and correct stock_units. Then VALIDATE CONSTRAINT and SET stock:SKU-4471 from Postgres.
4. Reconciliation job. Every N minutes, compare Redis vs Postgres for active SKUs, overwrite Redis from Postgres, and emit a inventory.drift metric. Alert if drift is nonzero.
5. Idempotency keys. Require an Idempotency-Key header, stored in a unique column on orders. That way client or ALB retries of a timed-out request don't create duplicate orders.
6. Structured logging. For each order attempt, log {sku, quantity, customerId, redisResult, pgRowCount, outcome, latencyMs}. The current "stock already at -8" warning should become an error-level alert, not a warn.
7. Linting. Enable no-floating-promises and require-await. Add a code-review rule that migrations dropping constraints need sign-off.
8. Process manager. On ECS, running pm2 inside the container hides crashes from ECS health checks and metrics. Prefer node as PID 1, e.g. with --init. Let ECS restart the task so crashes are visible in CloudWatch.