Rule mutator template changes not reloaded after file update

[claudio-benfatto]

Hi,

Describe the bug

After modifying some configuration in the mutators stanza, for example the content of the headers the new behaviour is not applied accordingly (ie. I still see the old headers in the Oathkeeper responses). This seems to happen especially when the changes are affecting a go template.

Reproducing the bug

Steps to reproduce the behavior:

1. Create a new rule ie. including the following simple mutators:

   mutators:
   - handler: header
     config:
       headers:
         X-Auth-User: "{{ print .Subject }}"

2. Change the mutator go template to populate the header with a different value:

   mutators:
   - handler: header
     config:
       headers:
         X-Auth-User: "{{ print .Extra.groups}}"

3. The responses will not contain the updated header, however the api /rules endpoint shows the updated rules and template
4. After a restart of oathkeeper the rule changes are applied as expected and reflected on the content of the header

Server logs

These are the debug logs following the change in the rules:

oathkeeper_1        | {"event":"fsnotify","file":"/data/rules.yaml","level":"debug","msg":"Detected file change in directory containing access rules. Triggering a reload.","op":"CHMOD","time":"2019-10-07T15:20:03Z"}
oathkeeper_1        | {"event":"config_change","level":"debug","msg":"Access rule watcher received an update.","source":"fsnotify","time":"2019-10-07T15:20:03Z"}
oathkeeper_1        | {"event":"repository_change","file":"file:///data/rules.yaml","level":"debug","msg":"Access rule watcher received an update.","source":"config_update","time":"2019-10-07T15:20:03Z"}
oathkeeper_1        | {"level":"debug","location":"file:///data/rules.yaml","msg":"Fetching access rules from given location because something changed.","time":"2019-10-07T15:20:03Z"}
oathkeeper_1        | {"event":"fsnotify","file":"/data/rules.yaml","level":"debug","msg":"Detected file change in directory containing access rules. Triggering a reload.","op":"WRITE","time":"2019-10-07T15:20:03Z"}
oathkeeper_1        | {"event":"config_change","level":"debug","msg":"Access rule watcher received an update.","source":"fsnotify","time":"2019-10-07T15:20:03Z"}
oathkeeper_1        | {"event":"repository_change","file":"file:///data/rules.yaml","level":"debug","msg":"Access rule watcher received an update.","source":"config_update","time":"2019-10-07T15:20:03Z"}
oathkeeper_1        | {"level":"debug","location":"file:///data/rules.yaml","msg":"Fetching access rules from given location because something changed.","time":"2019-10-07T15:20:03Z"}

Server configuration

serve:
  proxy:
    port: 4455
    tls:
      key:
        path: /ssl/key.pem
      cert:
        path: /ssl/cert.pem
  api:
    port: 4456
    tls:
      key:
        path: /ssl/key.pem
      cert:
        path: /ssl/cert.pem

log:
  level: debug
  format: json

access_rules:
  repositories:
    - file:///data/rules.yaml

mutators:
  header:
    enabled: true
  noop:
    enabled: true
  cookie:
    enabled: true

authorizers:
  allow:
    enabled: true
  deny:
    enabled: true
  keto_engine_acp_ory:
    enabled: true
    base_url: http://keto:4444/

authenticators:
  anonymous:
    enabled: true
    subject: guest
  jwt:
    enabled: true
    jwks_urls:
      - http://keycloak:8080/auth/realms/<realm>/protocol/openid-connect/certs
    scope_strategy: wildcard
  oauth2_client_credentials:
    enabled: true
    token_url: "http://keycloak:8080/auth/realms/<realm>/protocol/openid-connect/token"

Expected behavior

The new configuration should be applied after the rule change is observed and the header should be populated with the right value

Environment

• Docker

Thank you for your help!

[claudio-benfatto]

I realised that it actually happens even in much simpler cases, ie.

oathkeeper.yaml

serve:
  proxy:
    port: 4455
  api:
    port: 4456
log:
  level: debug
access_rules:
  repositories:
    - file://./data/rules.yaml
mutators:
  header:
    enabled: true
    config:
      -
  noop:
    enabled: true
  cookie:
    enabled: true
    config:
      -

authorizers:
  allow:
    enabled: true
  deny:
    enabled: true
  keto_engine_acp_ory:
    enabled: true
    config:
      base_url: http://auth-keto:4444/

authenticators:
  anonymous:
    enabled: true
    config:
      subject: guest
  jwt:
    enabled: true
    config:
      jwks_urls:
        - http://auth-keycloak/auth/realms/realm/protocol/openid-connect/certs
      scope_strategy: wildcard

rules.yaml

  - id: example
    match:
      url: "http://www.example.com/<.*>"
      methods:
      - GET
      - HEAD
      - OPTIONS
    authenticators: [{ "handler": "anonymous" }]
    authorizer: { "handler": "allow" }
    mutators:
      - handler: header
        config:
          headers:
            X-Auth-User: first

How to reproduce the issue

1. Start the oathkeeper process

   oathkeeper --config data/oathkeeper.yaml serve

   • Use curl:

     $ curl -I -X GET -H "X-Forwarded-Proto: http" -H "Host: www.example.com" http://localhost:4456/decisions/v2
     HTTP/1.1 200 OK
     X-Auth-User: first
     Date: Tue, 08 Oct 2019 08:28:02 GMT
     Content-Length: 0

2. Change the config to:

   - id: example
   match:
     url: "http://www.example.com/<.*>"
     methods:
     - GET
     - HEAD
     - OPTIONS
   authenticators: [{ "handler": "anonymous" }]
   authorizer: { "handler": "allow" }
   mutators:
     - handler: header
       config:
         headers:
           X-Auth-User: second

3. The configuration is reloaded:

   DEBU[0299] Detected file change in directory containing access rules. Triggering a reload.  event=fsnotify file=data/rules.yaml op=CHMOD
   DEBU[0299] Detected file change in directory containing access rules. Triggering a reload.  event=fsnotify file=data/rules.yaml op=WRITE
   DEBU[0299] Viper detected a configuration change, reloading config.  event=config_change source=fsnotify
   DEBU[0299] Viper detected a configuration change, reloading config.  event=config_change source=fsnotify
   DEBU[0299] One or more access rule repositories changed, reloading access rules.  event=repository_change file="file://./data/rules.yaml" source=config_update
   DEBU[0299] Fetching access rules from given location because something changed.  location="file://data/rules.yaml"
   DEBU[0299] One or more access rule repositories changed, reloading access rules.  event=repository_change file="file://./data/rules.yaml" source=config_update
   DEBU[0299] Fetching access rules from given location because something changed.  location="file://data/rules.yaml"

4. curl again (Does not give us the new header value):

   curl -I -X GET -H "X-Forwarded-Proto: http" -H "Host: www.example.com" http://localhost:4456/decisions/v2
   HTTP/1.1 200 OK
   X-Auth-User: first
   Date: Tue, 08 Oct 2019 08:31:44 GMT
   Content-Length: 0

5. restart oathkeeper and curl again:

   curl -I -X GET -H "X-Forwarded-Proto: http" -H "Host: www.example.com" http://localhost:4456/decisions/v2
   HTTP/1.1 200 OK
   X-Auth-User: second
   Date: Tue, 08 Oct 2019 08:33:08 GMT
   Content-Length: 0

[aeneasr]

Which version of Oathkeeper are you running?

Also, be aware that it might take a couple of seconds before the rules are refreshed in the internal cache.

[claudio-benfatto]

Hi @aeneasr I'm running v0.18.0-beta.1, and I'm waiting much longer than 2 sec ;)

UPDATE I could replicate it with v0.19.0-beta.1 too

[aeneasr]

Hey, sorry for the super long follow-up, I believe that this could be caused by the template caching! It appears that the rules are properly reloaded judging from the debug log.

[aeneasr]

I was able to identify the issue, it is in fact caused by caching!