Order of execution in Golang involving defer and goroutine

I have an easy-to-follow logging situation that seems to be occurring in the wrong order.

As you can see, the start time of the first row occurs before the start time of the second row. Yet the execution of the second row fully encapsulates the execution represented by the first row, so this doesn't seem possible.

This code executes first:

	defer func(begin time.Time) {
	    p.logger.InfoV(ctx, "Properties Listsearch "+method,
		    zap.Any("searchRequest", ctx.Request.URL.Query()),
		    zap.Float64("elapsed", time.Now().Sub(begin).Round(time.Millisecond).Seconds()),
	    )
    }(time.Now())

Then, about 40 lines later, a function is called which contains this code:

	go func() {
	    companyFacetsStartTime := time.Now()
        // actual work occurs here
		p.logger.DebugV(ctx, "company facets query complete", zap.Float64("elapsed", time.Now().Sub(companyFacetsStartTime).Round(time.Millisecond).Seconds()))
	}()

I am looking at logs that contain the same transactionID's, so these two calls have to be related.

It doesn't seem possible for row 1's Start to come before row 2's Start. Is there something about the way the defer in the first code block is executed that makes its time.Now() execute later than the time.Now() in the second code block? If not, is there any other explanation?

From your comment Shouldn't time.Now() in the parameter list be set when the defer is executed - the answers is no.

defer function parameters are evaluated when the defer statement is encountered - even though the defer function won't be executed until the container function's completion.

Quoting from the go language spec

> Each time a "defer" statement executes, the function value and
> parameters to the call are evaluated as usual and saved anew but the
> actual function is not invoked.

so in your example:

defer func(begin time.Time) {
    p.logger.InfoV(ctx, "Properties Listsearch "+method,
        zap.Any("searchRequest", ctx.Request.URL.Query()),
        zap.Float64("elapsed", time.Now().Sub(begin).Round(time.Millisecond).Seconds()),
    )
}(time.Now()) // time.Now() is collected when this defer statement is processed ... 
// ... even though execution is later.

Since you want to capture elapsed time of the container function, this is actually the correct time.Now() you want to capture.

If you evaluated begin from within the defer code, the duration reported would simply just record the elapsed time to evaluate the zap log's parameters.

I confused the situation by copying the logging timestamp and labeling it as Start time. That led to my misinterpreting the order of things, which is why I posted this question.

This whole question is a confusing mess that probably should be deleted, rather than waste other peoples' time on SO. Is that the right thing to do?

I apologize for this whole mess.