[Feature] Add middleware callback with step info before each step is ran

[mcky]

Is your feature request related to a problem? Please describe.
I'm frustrated when I'm trying to debug my inngest functions, because I have to manually add logs before each step.run call to get an overview of the progress (when not using the inngest devtools)

Describe the solution you'd like
The middleware gives me information about the function run, but not which step is currently being ran. I would like to be able to log each step run from my own middleware, e.g.

beforeExecution({ step }) {
  ctx.logger.info(`Running step ${step.name}`)
} 

Where the logger is the same proxy logger instance

Describe alternatives you've considered

• Using transformOutput, which has the context of the step. This runs after, ideally I'd be able to log before and after (then I could also measure run timings)

I'm concious I may be misunderstanding part of the execution flow, but I wasn't able to find the step name that's about to be executed in all the middleware callbacks/context

Additional context
Given a function run with a body like the below:

    await step.run("FIRST STEP", async () => {
      logger.info("--> FIRST STEP");
      return new Promise((resolve) => {
        logger.info("Waiting 1s");
        setTimeout(() => {
          logger.info("<-- FIRST STEP");
          resolve(null);
        }, 300);
      });
    });

    logger.info("Between steps");

    await step.run("SECOND STEP", async () => {
      // same as above
    });

I get roughly these logs

myapp:dev: steps []
myapp:dev: [17:41:23.147] INFO (19703): --> FIRST STEP
myapp:dev: [17:41:23.147] INFO (19703): Waiting 1s
myapp:dev: [17:41:23.449] INFO (19703): <-- FIRST STEP
myapp:dev: step {
myapp:dev:   name: 'FIRST STEP',
myapp:dev: }
myapp:dev: steps [ { id: 'c4dff821e3b2828e75decb728e9b96e3cdece1ac', data: null } ]
myapp:dev: beforeExecution
myapp:dev: [17:41:24.773] INFO (19703): Between steps
myapp:dev: [17:41:24.773] INFO (19703): --> SECOND STEP
myapp:dev: [17:41:24.773] INFO (19703): Waiting 1s
myapp:dev: [17:41:25.074] INFO (19703): <-- SECOND STEP
myapp:dev: step {
myapp:dev:   name: 'SECOND STEP',
myapp:dev: }

p.s. Some of your diagrams about execution are great, I think the middleware docs could really do with a diagram showing when they run in relation to each stage of a function/step

[mcky]

I just came across #217 too, which would scratch the same itch - but I'd still like to have control over it with middleware ideally

[jpwilliams]

Hi @mcky! 👋

Ah - this is a perfect use case and something we want to get right for middleware to make sure it's not restrictive. The debugging middleware in #217 is actually entirely middleware (no internals at all), but it's still lacking the accuracy you're wanting here.

The technical detail here is that beforeExecution() tracks when we're about to begin executing new code in the function as a whole - not necessarily a new step. In addition, it may be the case that we call the hook, execute the function as a whole, and then decide to run a step in the same execution. Calling the same hook twice would be a bit confusing, I think.

It sounds to me like this might warrant a new hook that clearly marks when we're running a step, like beforeStepExcecution() and afterStepExecution().

• Function hooks
  • beforeExecution() - starting to execute new code in the function
  • afterExecution() - finished executing the function
• Step hooks
  • NEW beforeStepExecution() - starting to execute a step (includes that step info)
  • NEW afterStepExecution() - finished executing the step (includes result, similar to transformOutput())

We've seen this requirement pop up before - I think it may be a missing piece in our hooks right now.

re: p.s. - Yes! 🙌 Diagrams of when these hooks run would be great. I'm thinking a controllable animation that steps over code on one side and hooks on the other might be good. 🤔