Intermittent Method Not Allowed (405) error while using req-modifier plugin

[tusharsdesai]

Krakend intermittently returns Method Not Allowed (405) error. The error started showing up (about 1 in 5 tries) after I moved the computation of the authorization header out of the critical path in the request modifier plugin (code below).

appserver_1   | 04/07 04:02:02.529 INF --> GET:/movies/ user=anymouse@example.com
appserver_1   | 04/07 04:02:02.530 INF      | AUT |    0.816072ms | user=anymouse@example.com
appserver_1   | 04/07 04:02:02.531 INF      | SL* |    0.946239ms | user=anymouse@example.com
appserver_1   | 04/07 04:02:02.531 INF <--  | 200 |    1.910660ms | GET /movies/ user=anymouse@example.com
apigateway_1  | [GIN] 2022/04/07 - 04:02:02 | 200 |    13.63775ms |      172.21.0.1 | GET      "/v1/movies/?pagesz=5"
appserver_1   | 04/07 04:02:02.536 INF --> POST:/movies/ user=anymouse@example.com
appserver_1   | 04/07 04:02:02.537 INF      | AUT |    0.849827ms | user=anymouse@example.com
appserver_1   | 04/07 04:02:02.546 INF      | INS |    9.420401ms | user=anymouse@example.com
appserver_1   | 04/07 04:02:02.546 INF <--  | 201 |   10.432124ms | POST /movies/ user=anymouse@example.com
apigateway_1  | [GIN] 2022/04/07 - 04:02:02 | 201 |   14.520487ms |      172.21.0.1 | POST     "/v1/movies/"
apigateway_1  | [GIN] 2022/04/07 - 04:02:02 | 405 |        2.74µs |      172.21.0.1 | GET      "/v1/movies/2c256928-8b62-446a-a1a4-23b34049bc9d"

Setup: req-modifier plugin (similar to the sample) and KeyCloak, running in docker-compose on Ubuntu 20.04

Request modifier plugin code:

package main

import (
    "errors"
    "fmt"
    "io"
    "net/url"
    "encoding/base64"
    "os"
)

type registerer string

type RequestWrapper interface {
    Method()    string
    URL()       *url.URL
    Query()     url.Values
    Path()      string
    Body()      io.ReadCloser
    Params()    map[string]string
    Headers()   map[string][]string
}

type reqWrap struct {
    method      string
    url         *url.URL
    query       url.Values
    path        string
    body        io.ReadCloser
    params      map[string]string
    headers     map[string][]string
}

func (r reqWrap) Method() string                {return r.method}
func (r reqWrap) URL() *url.URL                 {return r.url}
func (r reqWrap) Query() url.Values             {return r.query}
func (r reqWrap) Path() string                  {return r.path}
func (r reqWrap) Body() io.ReadCloser           {return r.body}
func (r reqWrap) Params() map[string]string     {return r.params}
func (r reqWrap) Headers() map[string][]string  {return r.headers}

type Logger interface {
    Debug(v ...interface{})
    Info(v ...interface{})
    Warning(v ...interface{})
    Error(v ...interface{})
    Critical(v ...interface{})
    Fatal(v ...interface{})
}

var ModifierRegisterer = registerer("req-modifier")
var logger Logger = nil

func (r registerer) RegisterModifiers(
    f func(name string,
           factory func(map[string]interface{}) func(interface{}) (interface{}, error),
           reqModifier bool,
           rspModifier bool)) {

    f(string(r), r.factory, true, false)
}

func (r registerer) RegisterLogger(in interface{}) {

    l, ok := in.(Logger)
    if !ok {
        return
    }

    logger = l
    logger.Debug(fmt.Sprintf("[PLUGIN: %s] Logger loaded", ModifierRegisterer))
}

func (r registerer) factory(map[string]interface{}) func(interface{}) (interface{}, error) {

    raw := os.Getenv("USER_APIGW") + ":" + os.Getenv("PSWD_APIGW")
    encoded := base64.StdEncoding.EncodeToString([]byte(raw))
    authHeader := "Basic " + encoded

    return func(input interface{}) (interface{}, error) {
        req, ok := input.(RequestWrapper)
        if !ok {
            return nil, errors.New("Unknown request type")
        }

        r := modifier(authHeader, req)

        if nil != logger {
            s := fmt.Sprintf("%s %v %v %s %v %v",
                             r.Method(), r.URL(), r.Query(), r.Path(), r.Params(), r.Headers())
            logger.Debug(s)
        }

        return r, nil
    }
}

func modifier(authorizationHeader string, req RequestWrapper) reqWrap {

    headers := req.Headers()
    headers["Authorization"] = []string{authorizationHeader}

    return reqWrap {
        method:     req.Method(),
        url:        req.URL(),
        query:      req.Query(),
        path:       req.Path(),
        body:       req.Body(),
        params:     req.Params(),
        headers:    headers,
    }
}

func init() {
    fmt.Printf("%s plugin loaded\n", ModifierRegisterer)
}

func main(){

}

krakend.json
{
  "$schema": "https://www.krakend.io/schema/v3.json",
  "version": 3,
  "plugin": {
      "pattern":".so",
      "folder": "/opt/krakend/plugins/"
  },
  "extra_config": {
    "telemetry/logging": {
      "level": "INFO",
      "prefix": "[KRAKEND]",
      "syslog": false,
      "stdout": true,
      "format": "default"
    }
  },
  "timeout": "3000ms",
  "cache_ttl": "300s",
  "output_encoding": "json",
  "name": "api-gw",
  "endpoints": [
    {
      "endpoint": "/v1/movies/",
      "method": "POST",
      "output_encoding": "no-op",
      "extra_config": {
        "plugin/req-resp-modifier": {
          "name": ["req-modifier"]
        },
        "auth/validator": {
          "operation_debug": true,
          "alg": "RS256",
          "jwk_url": "http://authserver:8080/auth/realms/movies/protocol/openid-connect/certs",
          "disable_jwk_security": true,
          "cache": true,
          "cache_duration": 10,
          "propagate_claims": [
              ["email", "X-UserEmail"]
          ]
        }
      },
      "input_headers": [
        null,
        "Content-Type",
        "Authorization",
        "X-UserEmail"
      ],
      "backend": [
        {
          "url_pattern": "/movies/",
          "encoding": "no-op",
          "sd": "static",
          "method": "POST",
          "host": [
            "http://appserver:8080"
          ],
          "disable_host_sanitize": false
        }
      ]
    },
    {
      "endpoint": "/v1/movies/{id}",
      "method": "GET",
      "output_encoding": "no-op",
      "extra_config": {
        "plugin/req-resp-modifier": {
          "name": ["req-modifier"]
        },
        "auth/validator": {
          "operation_debug": true,
          "alg": "RS256",
          "jwk_url": "http://authserver:8080/auth/realms/movies/protocol/openid-connect/certs",
          "disable_jwk_security": true,
          "cache": true,
          "cache_duration": 10,
          "propagate_claims": [
              ["email", "X-UserEmail"]
          ]
        }
      },
      "input_headers": [
        "Authorization",
        "X-UserEmail"
      ],
      "backend": [
        {
          "url_pattern": "/movies/{id}",
          "encoding": "no-op",
          "sd": "static",
          "method": "GET",
          "host": [
            "http://appserver:8080"
          ],
          "disable_host_sanitize": false
        }
      ]
    },
    {
      "endpoint": "/v1/movies/{id}",
      "method": "PUT",
      "output_encoding": "no-op",
      "extra_config": {
        "plugin/req-resp-modifier": {
          "name": ["req-modifier"]
        },
        "auth/validator": {
          "operation_debug": true,
          "alg": "RS256",
          "jwk_url": "http://authserver:8080/auth/realms/movies/protocol/openid-connect/certs",
          "disable_jwk_security": true,
          "cache": true,
          "cache_duration": 10,
          "propagate_claims": [
              ["email", "X-UserEmail"]
          ]
        }
      },
      "input_headers": [
        "Content-Type",
        "Authorization",
        "X-UserEmail"
      ],
      "backend": [
        {
          "url_pattern": "/movies/{id}",
          "encoding": "no-op",
          "sd": "static",
          "method": "PUT",
          "host": [
            "http://appserver:8080"
          ],
          "disable_host_sanitize": false
        }
      ]
    },
    {
      "endpoint": "/v1/movies/{id}",
      "method": "DELETE",
      "output_encoding": "no-op",
      "extra_config": {
        "plugin/req-resp-modifier": {
          "name": ["req-modifier"]
        },
        "auth/validator": {
          "operation_debug": true,
          "alg": "RS256",
          "jwk_url": "http://authserver:8080/auth/realms/movies/protocol/openid-connect/certs",
          "disable_jwk_security": true,
          "cache": true,
          "cache_duration": 10,
          "propagate_claims": [
              ["email", "X-UserEmail"]
          ]
        }
      },
      "backend": [
        {
          "url_pattern": "/movies/{id}",
          "encoding": "no-op",
          "sd": "static",
          "method": "DELETE",
          "host": [
            "http://appserver:8080"
          ],
          "disable_host_sanitize": false
        }
      ],
      "input_headers": [
        "Authorization",
        "X-UserEmail"
      ]
    },
    {
      "endpoint": "/v1/movies/",
      "method": "GET",
      "output_encoding": "no-op",
      "extra_config": {
        "qos/ratelimit/router": {
          "max_rate": 50
        },
        "plugin/req-resp-modifier": {
          "name": ["req-modifier"]
        },
        "auth/validator": {
          "operation_debug": true,
          "alg": "RS256",
          "jwk_url": "http://authserver:8080/auth/realms/movies/protocol/openid-connect/certs",
          "disable_jwk_security": true,
          "cache": true,
          "cache_duration": 10,
          "propagate_claims": [
              ["email", "X-UserEmail"]
          ]
        }
      },
      "backend": [
        {
          "url_pattern": "/movies/",
          "encoding": "no-op",
          "sd": "static",
          "method": "GET",
          "host": [
            "http://appserver:8080"
          ],
          "disable_host_sanitize": false
        }
      ],
      "input_headers": [
        "Authorization",
        "X-UserEmail"
      ],
      "input_query_strings": [
        "pagesz",
        "offset",
        "sortby",
        "title",
        "year",
        "director"
      ]
    }
  ]
}

[tusharsdesai]

I've seen this error happen on endpoints that take an id. e.g. GET, PUT, DELETE on /v1/movies/{id}

[tusharsdesai]

I am seeing this panic (seems to be related to gin). Since this issue is about routing (method not allowed error), I'm reporting the panic here.

01:28:03 $ docker logs moviedb_apigateway_1 
Parsing configuration file: /etc/krakend/krakend.json
req-modifier plugin loaded
[KRAKEND] 2022/04/07 - 07:56:30.192 ▶ INFO [SERVICE: Modifier Plugin] Total plugins loaded: 1
[KRAKEND] 2022/04/07 - 07:56:30.192 ▶ INFO Starting the KrakenD instance
panic: runtime error: index out of range [1] with length 1

goroutine 26 [running]:
github.com/gin-gonic/gin.(*node).addRoute(0xc0001701c0, {0xc0004a1220, 0xb}, {0xc00000e210, 0x3, 0x3})
    /go/pkg/mod/github.com/gin-gonic/gin@v1.7.7/tree.go:186 +0xc77
github.com/gin-gonic/gin.(*Engine).addRoute(0xc0001031e0, {0x2459cb0, 0xc0004a16b0}, {0xc0004a1220, 0xb}, {0xc00000e210, 0x3, 0x3})
    /go/pkg/mod/github.com/gin-gonic/gin@v1.7.7/gin.go:305 +0x1fa
github.com/gin-gonic/gin.(*RouterGroup).handle(0xc00086b7c0, {0x2459cb0, 0x3}, {0xc0004a16b0, 0x0}, {0xc000b48048, 0x1, 0x0})
    /go/pkg/mod/github.com/gin-gonic/gin@v1.7.7/routergroup.go:75 +0x145
github.com/gin-gonic/gin.(*RouterGroup).GET(...)
    /go/pkg/mod/github.com/gin-gonic/gin@v1.7.7/routergroup.go:103
github.com/luraproject/lura/v2/router/gin.ginRouter.registerKrakendEndpoint({{0xc0001031e0, {0x0, 0x0, 0x0}, 0xc00073a280, {0x2a64f00, 0xc0005bfdd0}, {0x2a9bfb0, 0xc0005bf140}, 0xc00073a320}, ...}, ...)
    /go/pkg/mod/github.com/luraproject/lura/v2@v2.0.1/router/gin/router.go:185 +0x265
github.com/luraproject/lura/v2/router/gin.ginRouter.registerKrakendEndpoints.func1()
    /go/pkg/mod/github.com/luraproject/lura/v2@v2.0.1/router/gin/router.go:165 +0x1b0
golang.org/x/sync/errgroup.(*Group).Go.func1()
    /go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57 +0x67
created by golang.org/x/sync/errgroup.(*Group).Go
    /go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:54 +0x92
01:29:48 $ 

[tusharsdesai]

I checked krakend.json and got a linting error for propagate_claims. But, I've specified claims propagation in krakend.json as per the example in the krakend docs. Claims propagation also seems to be working for me.

In any case, one more data point for your reference.

04:38:40 $ ./krakend.exe check -tlc krakend.json
Parsing configuration file: krakend.json
ERROR linting the configuration file:   jsonschema: '/endpoints/0/extra_config/auth~1validator/propagate_claims/0' does not validate with https://www.krakend.io/schema/v3.json#/properties/endpoints/items/$ref/properties/extra_config/$ref/properties/auth~1validator/$ref/properties/propagate_claims/items/type: expected string, but got array

[alombarte]

Hi @tusharsdesai , I'm giving you feedback only about the linting problem you pointed out in your last comment. It is a bug in the JSON schema and has been fixed: https://github.com/krakendio/krakend-schema/commit/1e153fc95e51b402dec9132b58189c9f534a99cd Thanks

[kpacha]

the panic should be fixed by adding the flag "sequential_start":true at the root of your configuration

[tusharsdesai]

Hey guys. I've stopped seeing these issues since upgrading to 2.0.1.

A few suggestions,

1. I don't know what sequential_start is for, but you can consider making it default/optional behavior. I like how GCP defines default (hard-coded, can't be changed), optional (can be changed) and mandatory/required (must be specified) configurations.
2. Please include a log message (at info level) to display the krakend version. It is easier for us to report issues.
3. Please tweet about minor releases as well. Many organizations will not upgrade directly to a major release and will wait for the subsequent minor/bugfix release.

[kpacha]

I don't know what sequential_start is for, but you can consider making it default/optional behavior. I like how GCP defines default (hard-coded, can't be changed), optional (can be changed) and mandatory/required (must be specified) configurations.

that was a great idea and we already included in the latest releases. thanks!

Please include a log message (at info level) to display the krakend version. It is easier for us to report issues.

the help command informs about the version, as the header included in every response the gateway is returning

Please tweet about minor releases as well. Many organizations will not upgrade directly to a major release and will wait for the subsequent minor/bugfix release.

thanks for the suggestion, I'll pass it to the team

[github-actions[bot]]

This issue was marked as resolved a long time ago and now has been automatically locked as there has not been any recent activity after it. You can still open a new issue and reference this link.