Repository: labstack/echo
Pull request #1991 (2021-09-21 05:59:28)

Add start time to request logger middleware values
Add start time to request logger middleware values to get time value just before next middleware/handler was called. Logger middlewares timestamps are for instants after handler `next(c)` has returned back to request logger scope. `v.StartTime` gives you time before. 

See https://github.com/labstack/echo/issues/1989#issuecomment-923493225

codecov[bot]: # [Codecov](https://codecov.io/gh/labstack/echo/pull/1991?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack) Report
> Merging [#1991](https://codecov.io/gh/labstack/echo/pull/1991?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack) (845ad5d) into [master](https://codecov.io/gh/labstack/echo/commit/4651c7aafe8e37cfcd78d93e580cd501dc40107b?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack) (4651c7a) will **increase** coverage by `0.00%`.
> The diff coverage is `100.00%`.

[![Impacted file tree graph](https://codecov.io/gh/labstack/echo/pull/1991/graphs/tree.svg?width=650&height=150&src=pr&token=vqnT76l79i&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack)](https://codecov.io/gh/labstack/echo/pull/1991?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack)

```diff
@@           Coverage Diff           @@
##           master    #1991   +/-   ##
=======================================
  Coverage   91.23%   91.23%           
=======================================
  Files          33       33           
  Lines        2886     2887    +1     
=======================================
+ Hits         2633     2634    +1     
  Misses        161      161           
  Partials       92       92           
```


| [Impacted Files](https://codecov.io/gh/labstack/echo/pull/1991?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack) | Coverage Δ | |
|---|---|---|
| [middleware/request\_logger.go](https://codecov.io/gh/labstack/echo/pull/1991/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack#diff-bWlkZGxld2FyZS9yZXF1ZXN0X2xvZ2dlci5nbw==) | `97.59% <100.00%> (+0.02%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/labstack/echo/pull/1991?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/labstack/echo/pull/1991?src=pr&el=footer&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack). Last update [4651c7a...845ad5d](https://codecov.io/gh/labstack/echo/pull/1991?src=pr&el=lastupdated&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack).

aldas: @pafuent  please review

Patch:
diff --git a/middleware/request_logger.go b/middleware/request_logger.go
index 7829a1f..1b3e3ea 100644
--- a/middleware/request_logger.go
+++ b/middleware/request_logger.go
@@ -124,6 +124,8 @@ type RequestLoggerConfig struct {
 
 // RequestLoggerValues contains extracted values from logger.
 type RequestLoggerValues struct {
+	// StartTime is time recorded before next middleware/handler is executed.
+	StartTime time.Time
 	// Latency is duration it took to execute rest of the handler chain (next(c) call).
 	Latency time.Duration
 	// Protocol is request protocol (i.e. `HTTP/1.1` or `HTTP/2`)
@@ -215,7 +217,9 @@ func (config RequestLoggerConfig) ToMiddleware() (echo.MiddlewareFunc, error) {
 			}
 			err := next(c)
 
-			v := RequestLoggerValues{}
+			v := RequestLoggerValues{
+				StartTime: start,
+			}
 			if config.LogLatency {
 				v.Latency = now().Sub(start)
 			}


Test patch:
diff --git a/middleware/request_logger_test.go b/middleware/request_logger_test.go
index d5d9be0..5118b12 100644
--- a/middleware/request_logger_test.go
+++ b/middleware/request_logger_test.go
@@ -296,6 +296,7 @@ func TestRequestLogger_allFields(t *testing.T) {
 	err := mw(c)
 
 	assert.NoError(t, err)
+	assert.Equal(t, time.Unix(1631045377, 0), expect.StartTime)
 	assert.Equal(t, 10*time.Second, expect.Latency)
 	assert.Equal(t, "HTTP/1.1", expect.Protocol)
 	assert.Equal(t, "8.8.8.8", expect.RemoteIP)