search

motiv-labs / janus

An API Gateway written in Go
https://hellofresh.gitbooks.io/janus
MIT License
2.78k stars 318 forks source link

Retry plugin doesn't work correctly #372

Open Levchks opened 5 years ago

Levchks commented 5 years ago

Hello, trying to add retry plugin to the configuration My Config - 

{
    "name" : "test",
    "active" : true,
    "proxy" : {
        "listen_path" : "/test",
        "upstreams" : {
            "balancing": "roundrobin",
            "targets": [
                {"target": "http://service1"},
                 {"target": "http://service2"}
            ]
        },
        "methods" : ["GET"]
    },
    "plugins": [
        {
            "name" : "retry",
            "enabled" : true,
            "config" : {
                "attempts" : 3,
                "backoff": "10ms"
            }
        }
]
}

I have two services and one of them is off. I expect that after receiving 502 errors from the disabled service, janus will repeat the request and get a response from the working service.

But it returns nothing due to an error: 

janus_1          | {"level":"debug","msg":"Starting Stats middleware","path":"/test","time":"2018-12-10T12:06:36Z"}
janus_1          | {"level":"debug","method":"GET","msg":"Started request","path":"/test","time":"2018-12-10T12:06:36Z"}
janus_1          | {"attempts":3,"backoff":10000000,"level":"debug","msg":"Starting retry middleware","time":"2018-12-10T12:06:36Z"}
janus_1          | {"level":"debug","msg":"Target upstream elected","target":"http://service1","time":"2018-12-10T12:06:36Z"}
janus_1          | {"level":"debug","msg":"Upstream Path","path":"","time":"2018-12-10T12:06:36Z"}
janus_1          | {"level":"info","msg":"Proxying request to the following upstream","request":"/test","request-id":"70adcfa7-3beb-4316-8724-b54c07e1706a","time":"2018-12-10T12:06:36Z","upstream-host":"service1","upstream-request":"/"}
janus_1          | [StatsGo] 2018/12/10 12:06:36 Stats counter incremented  metric=upstream.service1.-.-
janus_1          | [StatsGo] 2018/12/10 12:06:36 Stats counter incremented  metric=total.upstream
janus_1          | 2018/12/10 12:06:45 http: proxy error: context canceled
janus_1          | {"level":"debug","msg":"Target upstream elected","target":"http://service2","time":"2018-12-10T12:06:45Z"}
janus_1          | {"level":"debug","msg":"Upstream Path","path":"","time":"2018-12-10T12:06:45Z"}
janus_1          | {"level":"info","msg":"Proxying request to the following upstream","request":"/test","request-id":"70adcfa7-3beb-4316-8724-b54c07e1706a","time":"2018-12-10T12:06:45Z","upstream-host":"service2","upstream-request":"/"}
janus_1          | [StatsGo] 2018/12/10 12:06:45 Stats counter incremented  metric=upstream.service2.-.-
janus_1          | [StatsGo] 2018/12/10 12:06:45 Stats counter incremented  metric=total.upstream
janus_1          | 2018/12/10 12:06:45 http: proxy error: context canceled
janus_1          | 2018/12/10 12:06:45 http: multiple response.WriteHeader calls

After all attempts getting an error "request failed too many times" (Also if you set non-zero "forwarding_time" - you can get right response from alive service but with 502 in header)

Levchks commented 5 years ago

janus_1 | {"error":"request failed too many times: GET /test request failed","level":"error","msg":"Internal server error handled","stack":"goroutine 148 [running]:\nruntime/debug.Stack(0xce2ba0, 0xc420629d40, 0xc420345d10)\n\t/usr/local/go/src/runtime/debug/stack.go:24 +0xa7\ngithub.com/hellofresh/janus/pkg/errors.Handler(0xce8120, 0xc4206287e0, 0xb7a9a0, 0xc420629d40)\n\t/go/src/github.com/hellofresh/janus/pkg/errors/error.go:64 +0x331\ngithub.com/hellofresh/janus/pkg/plugin/retry.NewRetryMiddleware.func1.1(0xce8120, 0xc4206287e0, 0xc420572d00)\n\t/go/src/github.com/hellofresh/janus/pkg/plugin/retry/middleware.go:61 +0x44d\nnet/http.HandlerFunc.ServeHTTP(0xc420453880, 0xce8120, 0xc4206287e0, 0xc420572d00)\n\t/usr/local/go/src/net/http/server.go:1947 +0x44\ngithub.com/hellofresh/janus/vendor/github.com/go-chi/chi.(ChainHandler).ServeHTTP(0xc4200b27c0, 0xce8120, 0xc4206287e0, 0xc420572d00)\n\t/go/src/github.com/hellofresh/janus/vendor/github.com/go-chi/chi/chain.go:31 +0x52\ngithub.com/hellofresh/janus/vendor/github.com/go-chi/chi.(Mux).routeHTTP(0xc420070240, 0xce8120, 0xc4206287e0, 0xc420572d00)\n\t/go/src/github.com/hellofresh/janus/vendor/github.com/go-chi/chi/mux.go:424 +0x289\ngithub.com/hellofresh/janus/vendor/github.com/go-chi/chi.(Mux).(github.com/hellofresh/janus/vendor/github.com/go-chi/chi.routeHTTP)-fm(0xce8120, 0xc4206287e0, 0xc420572d00)\n\t/go/src/github.com/hellofresh/janus/vendor/github.com/go-chi/chi/mux.go:368 +0x48\nnet/http.HandlerFunc.ServeHTTP(0xc42056c110, 0xce8120, 0xc4206287e0, 0xc420572d00)\n\t/usr/local/go/src/net/http/server.go:1947 +0x44\ngithub.com/hellofresh/janus/pkg/middleware.(OpenTracing).Handler.func1(0xce9c60, 0xc420344e10, 0xc420572c00)\n\t/go/src/github.com/hellofresh/janus/pkg/middleware/opentracing.go:108 +0xa07\nnet/http.HandlerFunc.ServeHTTP(0xc420453440, 0xce9c60, 0xc420344e10, 0xc420572c00)\n\t/usr/local/go/src/net/http/server.go:1947 +0x44\ngithub.com/hellofresh/janus/pkg/middleware.NewRecovery.func1.1(0xce9c60, 0xc420344e10, 0xc420572c00)\n\t/go/src/github.com/hellofresh/janus/pkg/middleware/recovery.go:15 +0xa8\nnet/http.HandlerFunc.ServeHTTP(0xc420453460, 0xce9c60, 0xc420344e10, 0xc420572c00)\n\t/usr/local/go/src/net/http/server.go:1947 +0x44\ngithub.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop.CaptureMetrics.func1(0xce9c60, 0xc420344e10)\n\t/go/src/github.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop/capture_metrics.go:30 +0x4c\ngithub.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop.CaptureMetricsFn(0xce9c60, 0xc420344c80, 0xc4204b9600, 0xc4204b9620, 0x24be955e3fe399cd, 0x40dfda)\n\t/go/src/github.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop/capture_metrics.go:81 +0x25a\ngithub.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop.CaptureMetrics(0xce4140, 0xc420453460, 0xce9c60, 0xc420344c80, 0xc420572c00, 0x70a2dd, 0xc, 0xc4204296c8)\n\t/go/src/github.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop/capture_metrics.go:29 +0x79\ngithub.com/hellofresh/janus/pkg/middleware.(Logger).Handler.func1(0xce9c60, 0xc420344c80, 0xc420572c00)\n\t/go/src/github.com/hellofresh/janus/pkg/middleware/logger.go:34 +0x73d\nnet/http.HandlerFunc.ServeHTTP(0xc420453480, 0xce9c60, 0xc420344c80, 0xc420572c00)\n\t/usr/local/go/src/net/http/server.go:1947 +0x44\ngithub.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop.CaptureMetrics.func1(0xce9c60, 0xc420344c80)\n\t/go/src/github.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop/capture_metrics.go:30 +0x4c\ngithub.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop.CaptureMetricsFn(0xce9120, 0xc420474540, 0xc4204b9b08, 0x70b88b, 0xc07b00, 0xc4203ea680)\n\t/go/src/github.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop/capture_metrics.go:81 +0x25a\ngithub.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop.CaptureMetrics(0xce4140, 0xc420453480, 0xce9120, 0xc420474540, 0xc420572c00, 0xc42052d050, 0x7f532653e8b0, 0x0)\n\t/go/src/github.com/hellofresh/janus/vendor/github.com/felixge/httpsnoop/capture_metrics.go:29 +0x79\ngithub.com/hellofresh/janus/pkg/middleware.(Stats).Handler.func1(0xce9120, 0xc420474540, 0xc420572c00)\n\t/go/src/github.com/hellofresh/janus/pkg/middleware/stats.go:34 +0x18c\nnet/http.HandlerFunc.ServeHTTP(0xc4204534a0, 0xce9120, 0xc420474540, 0xc420572b00)\n\t/usr/local/go/src/net/http/server.go:1947 +0x44\ngithub.com/hellofresh/janus/pkg/middleware.RequestID.func1(0xce9120, 0xc420474540, 0xc420572a00)\n\t/go/src/github.com/hellofresh/janus/pkg/middleware/request_id.go:31 +0x204\nnet/http.HandlerFunc.ServeHTTP(0xc4204534c0, 0xce9120, 0xc420474540, 0xc420572a00)\n\t/usr/local/go/src/net/http/server.go:1947 +0x44\ngithub.com/hellofresh/janus/vendor/github.com/go-chi/chi.(Mux).ServeHTTP(0xc420070240, 0xce9120, 0xc420474540, 0xc420572900)\n\t/go/src/github.com/hellofresh/janus/vendor/github.com/go-chi/chi/mux.go:81 +0x221\ngithub.com/hellofresh/janus/pkg/router.(ChiRouter).ServeHTTP(0xc42056c0a0, 0xce9120, 0xc420474540, 0xc420572900)\n\t/go/src/github.com/hellofresh/janus/pkg/router/chi.go:32 +0x54\nnet/http.serverHandler.ServeHTTP(0xc4204e6680, 0xce9120, 0xc420474540, 0xc420572900)\n\t/usr/local/go/src/net/http/server.go:2697 +0xbc\nnet/http.(conn).serve(0xc42047d2c0, 0xcea120, 0xc42034c400)\n\t/usr/local/go/src/net/http/server.go:1830 +0x651\ncreated by net/http.(Server).Serve\n\t/usr/local/go/src/net/http/server.go:2798 +0x27b\n","time":"2018-12-10T12:06:45Z"} janus_1 | 2018/12/10 12:06:45 http: multiple response.WriteHeader calls janus_1 | {"code":502,"duration":9530,"duration-fmt":"9.530165386s","host":"localhost:8666","level":"info","method":"GET","msg":"Completed handling request","referer":"","remote-addr":"172.20.0.1:60392","request":"/test","request-id":"70adcfa7-3beb-4316-8724-b54c07e1706a","time":"2018-12-10T12:06:45Z","user-agent":"Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:61.0) Gecko/20100101 Firefox/61.0"} janus_1 | [StatsGo] 2018/12/10 12:06:45 Stats timer finished bucket=request.get.test.- elapsed=9.530260837s janus_1 | [StatsGo] 2018/12/10 12:06:45 Stats counter incremented metric=request.get.test.- janus_1 | [StatsGo] 2018/12/10 12:06:45 Stats counter incremented metric=request-fail.get.test.- janus_1 | [StatsGo] 2018/12/10 12:06:45 Stats counter incremented metric=total.request janus_1 | [StatsGo] 2018/12/10 12:06:45 Stats counter incremented metric=total.request-fail janus_1 | [StatsGo] 2018/12/10 12:06:45 Stats timer finished elapsed=9.530260837s bucket=round.get.test.- janus_1 | [StatsGo] 2018/12/10 12:06:45 Stats counter incremented metric=round.get.test.- janus_1 | [StatsGo] 2018/12/10 12:06:45 Stats counter incremented metric=round-fail.get.test.- janus_1 | [StatsGo] 2018/12/10 12:06:45 Stats counter incremented metric=total.round janus_1 | [StatsGo] 2018/12/10 12:06:45 Stats counter incremented metric=total.round-fail