[Traefik plugin] panic after deploy (docker service update) and when doing Apache AB test

frobert commented 1 year ago

After running docker service update I would expect zero down time but getting a panic error from souin/trafeik and Traefik container crashes...

Error:

time="2023-10-16T11:12:56Z" level=error msg="plugins-storage/sources/gop-1954682551/src/github.com/darkweak/souin/plugins/traefik/vendor/github.com/darkweak/souin/pkg/middleware/middleware.go:533:19: panic" module=github.com/darkweak/souin plugin=plugin-souin time="2023-10-16T11:12:56Z" level=error msg="plugins-storage/sources/gop-1954682551/src/github.com/darkweak/souin/plugins/traefik/vendor/github.com/darkweak/souin/pkg/middleware/middleware.go:250:12: panic" plugin=plugin-souin module=github.com/darkweak/souin

Anyone had the same issue?

darkweak commented 1 year ago

Hello @frobert How do you run the container ? What's your config ?

frobert commented 1 year ago

Hello @frobert How do you run the container ? What's your config ?

Hey, I'm running a Django app in docker swarm mode...

Traefik Dynamic config:

mb24-souin:
  plugin:
    souin:
      api:
        prometheus: ""
        souin: ""
      default_cache:
        headers:
          - Authorization
          - Content-Type
        regex:
          exclude: '/urednik'
        ttl: 60s
        allowed_http_verbs: [GET, HEAD, POST]
        default_cache_control: public
      log_level: debug

Added middleware in my app docker compose (traefik shows no errors, all good):
traefik.http.routers.mb24-test.middlewares=mb24-souin@file
then i run: - docker service update --image registry.xxxdomain.com/xxxuser/mb24:latest-test mb24-test_app --with-registry-auth --update-parallelism 1 --update-delay 60s --replicas 1 And the trafik crashes the container and rebuilds a new one ....

Otherwise, the cacheing works as expected, we just need to make sure we have zero downtime on deploy...

darkweak commented 1 year ago

Does it happens only on the service update ?

frobert commented 1 year ago

Does it happens only on the service update ?

yes... And if I click "Update the stack" button inside portainer stack, everything seems to be OK...

I'm running docker service update in Drone CI... and it fails when updating

darkweak commented 1 year ago

I will try to reproduce on my swarm cluster

frobert commented 1 year ago

I will try to reproduce on my swarm cluster

Perfect, thanks...

darkweak commented 1 year ago

Hey 👋 Which version of træfik are you using ? Are you using the souin-traefik container or the Traefik default container with souin as plugin in it ?

darkweak commented 1 year ago

Here is the panic I reached but unfortunately that's not a Souin issue.

github.com/traefik/traefik/v3/pkg/server.(*httpForwarder).Accept(0x3c11d20?)
    github.com/traefik/traefik/v3/pkg/server/server_entrypoint_tcp.go:60 +0x68 fp=0x4000089630 sp=0x40000895a0 pc=0x35b55c8
net/http.(*onceCloseListener).Accept(0x5647580?)
    <autogenerated>:1 +0x30 fp=0x4000089650 sp=0x4000089630 pc=0x375800
net/http.(*Server).Serve(0x400015a4b0, {0x5632cf0, 0x40006b4a40})
    net/http/server.go:3056 +0x2b8 fp=0x4000089780 sp=0x4000089650 pc=0x351ff8
github.com/traefik/traefik/v3/pkg/server.createHTTPServer.func2()
    github.com/traefik/traefik/v3/pkg/server/server_entrypoint_tcp.go:594 +0x3c fp=0x40000897d0 sp=0x4000089780 pc=0x35b917c
runtime.goexit()
    runtime/asm_arm64.s:1197 +0x4 fp=0x40000897d0 sp=0x40000897d0 pc=0x85c04
created by github.com/traefik/traefik/v3/pkg/server.createHTTPServer in goroutine 1
    github.com/traefik/traefik/v3/pkg/server/server_entrypoint_tcp.go:593 +0x624
goroutine 11 [select]:
runtime.gopark(0x4000089e08?, 0x2?, 0x0?, 0x0?, 0x4000089de4?)
    runtime/proc.go:398 +0xc8 fp=0x4000089c90 sp=0x4000089c70 pc=0x50488
runtime.selectgo(0x4000089e08, 0x4000089de0, 0x4000d681b0?, 0x0, 0x4000089df8?, 0x1)
    runtime/select.go:327 +0x608 fp=0x4000089da0 sp=0x4000089c90 pc=0x61838
github.com/traefik/traefik/v3/pkg/server.(*httpForwarder).Accept(0x3c11d20?)
    github.com/traefik/traefik/v3/pkg/server/server_entrypoint_tcp.go:60 +0x68 fp=0x4000089e30 sp=0x4000089da0 pc=0x35b55c8
net/http.(*onceCloseListener).Accept(0x5647580?)
    <autogenerated>:1 +0x30 fp=0x4000089e50 sp=0x4000089e30 pc=0x375800
net/http.(*Server).Serve(0x400015a5a0, {0x5632cf0, 0x40006b4b60})
    net/http/server.go:3056 +0x2b8 fp=0x4000089f80 sp=0x4000089e50 pc=0x351ff8
github.com/traefik/traefik/v3/pkg/server.createHTTPServer.func2()
    github.com/traefik/traefik/v3/pkg/server/server_entrypoint_tcp.go:594 +0x3c fp=0x4000089fd0 sp=0x4000089f80 pc=0x35b917c
runtime.goexit()
    runtime/asm_arm64.s:1197 +0x4 fp=0x4000089fd0 sp=0x4000089fd0 pc=0x85c04
created by github.com/traefik/traefik/v3/pkg/server.createHTTPServer in goroutine 1
    github.com/traefik/traefik/v3/pkg/server/server_entrypoint_tcp.go:593 +0x624
goroutine 12 [select]:
runtime.gopark(0x400008c608?, 0x2?, 0x0?, 0x0?, 0x400008c5e4?)
    runtime/proc.go:398 +0xc8 fp=0x400008c490 sp=0x400008c470 pc=0x50488
runtime.selectgo(0x400008c608, 0x400008c5e0, 0x4000d68240?, 0x0, 0x400008c5f8?, 0x1)
    runtime/select.go:327 +0x608 fp=0x400008c5a0 sp=0x400008c490 pc=0x61838
github.com/traefik/traefik/v3/pkg/server.(*httpForwarder).Accept(0x3c11d20?)
    github.com/traefik/traefik/v3/pkg/server/server_entrypoint_tcp.go:60 +0x68 fp=0x400008c630 sp=0x400008c5a0 pc=0x35b55c8
net/http.(*onceCloseListener).Accept(0x5647580?)
    <autogenerated>:1 +0x30 fp=0x400008c650 sp=0x400008c630 pc=0x375800
net/http.(*Server).Serve(0x400015a690, {0x5632cf0, 0x40006b4be0})
    net/http/server.go:3056 +0x2b8 fp=0x400008c780 sp=0x400008c650 pc=0x351ff8
github.com/traefik/traefik/v3/pkg/server.createHTTPServer.func2()
    github.com/traefik/traefik/v3/pkg/server/server_entrypoint_tcp.go:594 +0x3c fp=0x400008c7d0 sp=0x400008c780 pc=0x35b917c
runtime.goexit()
    runtime/asm_arm64.s:1197 +0x4 fp=0x400008c7d0 sp=0x400008c7d0 pc=0x85c04
created by github.com/traefik/traefik/v3/pkg/server.createHTTPServer in goroutine 1
    github.com/traefik/traefik/v3/pkg/server/server_entrypoint_tcp.go:593 +0x624
goroutine 68 [IO wait]:
runtime.gopark(0x4999f73e1ecd11c0?, 0xb3728ce3b4a8c1dc?, 0xf7?, 0x5c?, 0xc97700716046158f?)
    runtime/proc.go:398 +0xc8 fp=0x40009bb530 sp=0x40009bb510 pc=0x50488
runtime.netpollblock(0x0?, 0xffffffff?, 0xff?)
    runtime/netpoll.go:564 +0x158 fp=0x40009bb570 sp=0x40009bb530 pc=0x48f88
internal/poll.runtime_pollWait(0x7f519b7548, 0x72)
    runtime/netpoll.go:343 +0xa0 fp=0x40009bb5a0 sp=0x40009bb570 pc=0x7f050
internal/poll.(*pollDesc).wait(0x40001de680?, 0x40009bc000?, 0x0)

darkweak commented 1 year ago

With the given config using image: traefik:v3.0:

# traefik.yml
providers:
  file:
    filename: /souin-configuration.yml
    watch: true

api:
  dashboard: true
  debug: true
  insecure: true

pilot:
  token: #TOKEN

experimental:
  plugins:
    souin:
      moduleName: github.com/darkweak/souin
      version: v1.6.41

log:
  level: DEBUG

accessLog: {}

# /souin-configuration
http:
  routers:
    whoami:
      middlewares:
        - souin
      entrypoints:
        - http
      service: whoami
      rule: Host(`traefik.cheatuniverse.me`)

  services:
    whoami:
      loadBalancer:
        servers:
          - url: http://whoami:80
        passHostHeader: false

  middlewares:
    souin:
      plugin:
        souin:
          api:
            prometheus: ""
            souin: ""
          default_cache:
            headers:
              - Authorization
              - Content-Type
            ttl: 60s
            allowed_http_verbs: [GET, HEAD, POST]
            default_cache_control: public
            cache_name: With-Traefik
          log_level: debug

frobert commented 1 year ago

Hey 👋 Which version of træfik are you using ? Are you using the souin-traefik container or the Traefik default container with souin as plugin in it ?

Hey, im using "image: traefik:v2.10.5" with "souin v1.6.41" plugin.

darkweak commented 1 year ago

Okay I'll retry with this version.

kraoc commented 1 year ago

Hello (back) :p

Traefik 3 beta 4 + Souin plugin v1.6.43

middleware

    cache:
      plugin:
        souin:
          api:
            prometheus: {}
            souin: {}
          default_cache:
            log_level: debug
            allowed_http_verbs:
              - GET
              - HEAD
            ttl: 60s
            headers:
              - Content-Type
              - Authorization
            default_cache_control: public, max-age=86400

Short log

{"plugin":"plugin-souin","module":"github.com/darkweak/souin","time":"2023-11-01T21:01:26+01:00","level":"error","message":"plugins-storage/sources/gop-1008052221/src/github.com/darkweak/souin/plugins/traefik/vendor/github.com/darkweak/souin/pkg/middleware/middleware.go:533:19: panic"}

Long log

goroutine 1153 [running]:
github.com/traefik/yaegi/interp.runCfg.func1()
    github.com/traefik/yaegi@v0.15.1/interp/run.go:205 +0x185
panic({0x414e260?, 0xc0066422f0?})
    runtime/panic.go:914 +0x21f
github.com/traefik/yaegi/interp.runCfg.func1()
    github.com/traefik/yaegi@v0.15.1/interp/run.go:205 +0x185
panic({0x414e260?, 0xc0066422f0?})
    runtime/panic.go:914 +0x21f
reflect.Value.assignTo({0x409faa0?, 0x8e93f60?, 0xc00683e0a8?}, {0x5054d0f, 0xb}, 0x450c900, 0xc00682a330)
    reflect/value.go:3307 +0x289
reflect.Value.Set({0x450c900?, 0xc00682a330?, 0x414e3e0?}, {0x409faa0?, 0x8e93f60?, 0xc0052f29f8?})
    reflect/value.go:2260 +0xe6
github.com/traefik/yaegi/interp._new.func1(0xc0068302c0?)
    github.com/traefik/yaegi@v0.15.1/interp/run.go:3408 +0xba
github.com/traefik/yaegi/interp.runCfg(0xc00171d540, 0xc0068302c0, 0xc?, 0x414e260?)
    github.com/traefik/yaegi@v0.15.1/interp/run.go:213 +0x285
github.com/traefik/yaegi/interp.genFunctionWrapper.func1.1({0xc006f8c000, 0x5, 0x8?})
    github.com/traefik/yaegi@v0.15.1/interp/run.go:1024 +0x7c5
reflect.Value.call({0xc004b3da40?, 0xc001bdc330?, 0xc001bcf620?}, {0x503eb27, 0x4}, {0xc005671f80, 0x5, 0x78?})
    reflect/value.go:596 +0xce7
reflect.Value.Call({0xc004b3da40?, 0xc001bdc330?, 0x193?}, {0xc005671f80?, 0x433a720?, 0xc006830160?})
    reflect/value.go:380 +0xb9
github.com/traefik/yaegi/interp.call.func9.2({0xc005671f80?, 0xc001bdc330?, 0xc00269a928?})
    github.com/traefik/yaegi@v0.15.1/interp/run.go:1293 +0x36
github.com/traefik/yaegi/interp.call.func9(0xc006830160)
    github.com/traefik/yaegi@v0.15.1/interp/run.go:1313 +0xcc5
github.com/traefik/yaegi/interp.runCfg(0xc00365b2c0, 0xc006830160, 0xc0013c9940?, 0x0?)
    github.com/traefik/yaegi@v0.15.1/interp/run.go:213 +0x285
github.com/traefik/yaegi/interp.getFunc.func1.1({0x8e93f60, 0x0, 0x0?})
    github.com/traefik/yaegi@v0.15.1/interp/run.go:1912 +0x56b
reflect.Value.call({0x409fd60?, 0xc001bdc180?, 0x77b2f0?}, {0x503eb27, 0x4}, {0x8e93f60, 0x0, 0xc004eb2340?})
    reflect/value.go:596 +0xce7
reflect.Value.Call({0x409fd60?, 0xc001bdc180?, 0x0?}, {0x8e93f60?, 0xc004baafd0?, 0x44853c?})
    reflect/value.go:380 +0xb9
github.com/traefik/yaegi/interp.call.func9.2({0x8e93f60?, 0xc161c5?, 0xc005de6400?})
    github.com/traefik/yaegi@v0.15.1/interp/run.go:1293 +0x36
created by github.com/traefik/yaegi/interp.call.func9 in goroutine 1134
    github.com/traefik/yaegi@v0.15.1/interp/run.go:1305 +0xf5e
panic: reflect.Set: value of type *struct {} is not assignable to type error [recovered]
    panic: reflect.Set: value of type *struct {} is not assignable to type error [recovered]
    panic: reflect.Set: value of type *struct {} is not assignable to type error

And still no store

Souin; fwd=uri-miss; stored; key=GET-https-infos.zogg.fr-/

Anything I can add for you to review ?

frobert commented 11 months ago

Problem persist on latest stable versions... This time the plugin and traefik crashes as soon as we get web traffic...

darkweak commented 11 months ago

Sorry @kraoc I missed your comment.

@frobert I will investigate on that.

Sorry for the inconvenience.

frobert commented 11 months ago

Sorry @kraoc I missed your comment.

@frobert I will investigate on that.

Sorry for the inconvenience.

Thanks!

One more finding, kind of strange but may be it would help....

If I use "whoami" docker image for backend app, then it seem to be working ok.... But as soon as I switch to my backend app (build in Django with unicorn), traefik with souin cache brakes... There are no errors on Django BE app and if I disable souin cache, app works as expected.... Is there any other way to debug or is souin plugin just not up to expectations for a production app...

darkweak / souin

[Traefik plugin] panic after deploy (docker service update) and when doing Apache AB test #387