Having Issues with ACL on 0.8.0+

[Byron Kim]

I'm trying to enable ACL's for the first time in Consul.  I have a 3 node cluster and upgraded to version 0.8.1 first.  I'm now trying to enable a basic ACL but getting 100's of these lines in the logs.

2017/05/31 15:22:58 [ERR] http: Request PUT /v1/session/create?dc=us-east-1&token=%22%22, error: ACL not found from=127.0.0.1:50666
2017/05/31 15:22:58 [ERR] http: Request PUT /v1/session/create?dc=us-east-1&token=%22%22, error: ACL not found from=127.0.0.1:50666

I would estimate about 30+ of these are being generated every second and causing the CPU to spike.  When I go to the UI, I can see the master and agent token set.  I'm using the most basic ACL config.  I have the consul configs set in 2 json files:

main.json

{
    "advertise_addr": "10.0.0.1",
    "bind_addr": "10.0.0.1",
    "client_addr": "10.0.0.1",
    "bootstrap_expect": 3,
    "ui": true,
    "client_addr": "0.0.0.0",
    "datacenter": "us-east-1",
    "data_dir": "/opt/consul",
    "log_level": "INFO",
    "node_name": "integration-consul-ip-10-0-0-1",
    "retry_join_ec2": {
        "tag_key": "Consul",
        "tag_value": "dev"
    },
    "server": true
}

acl.json

{
    "acl_datacenter": "us-east-1",
    "acl_master_token": "dd8b7168-f47d-4ba6-8725-872a711111aa",
    "acl_token": "dd8b7168-f47d-4ba6-8725-872a711111aa",
    "acl_default_policy": "deny",
    "acl_down_policy": "deny"
}

I copy the acl.json to the config directory and restart the non-leader nodes.  Once I restart the leader node, it goes haywire with the error message above.  I think ACL is in place because the tokens are showing in the UI but I need to figure out how to get rid of the error message since that is most likely causing the CPU to spike.

[Sylvain Boily]

Hello,

Check this doc https://gist.github.com/slackpad/d89ce0e1cc0802c3c4f2d84932fa3234 from https://github.com/hashicorp/consul/issues/3054

 

[Byron Kim]

Hi,

My issue seems to be slightly different.  I'm not getting a permission denied error as indicated in the links.  Here is a snippet of the log:

2017/05/31 15:22:51 [INFO] serf: Re-joined to previously known node: 172-16-12-83: 172.16.12.83:8301
2017/05/31 15:22:51 [INFO] consul: Adding LAN server 172-16-80-228 (Addr: tcp/172.16.80.228:8300) (DC: us-east-1)
2017/05/31 15:22:51 [INFO] consul: Adding LAN server 172-16-0-152 (Addr: tcp/172.16.0.152:8300) (DC: us-east-1)
2017/05/31 15:22:51 [INFO] serf: EventMemberJoin: 172-16-5-58.us-east-1 172.16.5.58
2017/05/31 15:22:51 [INFO] serf: Attempting re-join to previously known node: 172.16.5.58:8302
2017/05/31 15:22:51 [INFO] consul: Handled member-join event for server "172-16-5-58.us-east-1" in area "wan"
2017/05/31 15:22:51 [INFO] agent: Joining cluster...
2017/05/31 15:22:51 [INFO] agent: No EC2 region provided, querying instance metadata endpoint...
2017/05/31 15:22:51 [INFO] serf: Re-joined to previously known node: 172.16.5.58:8302
2017/05/31 15:22:51 [INFO] agent: Discovered 13 servers from EC2
2017/05/31 15:22:51 [INFO] agent: (LAN) joining: [redacted IPs]
2017/05/31 15:22:51 [INFO] agent: (LAN) joined: 10 Err: <nil>
2017/05/31 15:22:51 [INFO] agent: Join completed. Synced with 10 initial agents
2017/05/31 15:22:57 [WARN] raft: Heartbeat timeout from "" reached, starting election
2017/05/31 15:22:57 [INFO] raft: Node at 172.16.5.58:8300 [Candidate] entering Candidate state in term 224
2017/05/31 15:22:58 [INFO] raft: Election won. Tally: 2
2017/05/31 15:22:58 [INFO] raft: Node at 172.16.5.58:8300 [Leader] entering Leader state
2017/05/31 15:22:58 [INFO] raft: Added peer 172.16.80.228:8300, starting replication
2017/05/31 15:22:58 [INFO] raft: Added peer 172.16.0.152:8300, starting replication
2017/05/31 15:22:58 [INFO] consul: cluster leadership acquired
2017/05/31 15:22:58 [INFO] consul: New leader elected: 172-16-5-58
2017/05/31 15:22:58 [INFO] raft: pipelining replication to peer {Voter 172.16.0.152:8300 172.16.0.152:8300}
2017/05/31 15:22:58 [INFO] raft: pipelining replication to peer {Voter 172.16.80.228:8300 172.16.80.228:8300}

2017/05/31 15:22:58 [ERR] http: Request PUT /v1/session/create?dc=us-east-1&token=%22%22, error: ACL not found from=127.0.0.1:50666
2017/05/31 15:22:58 [ERR] http: Request PUT /v1/session/create?dc=us-east-1&token=%22%22, error: ACL not found from=127.0.0.1:50666
2017/05/31 15:22:58 [ERR] http: Request PUT /v1/session/create?dc=us-east-1&token=%22%22, error: ACL not found from=127.0.0.1:50666
2017/05/31 15:22:58 [ERR] http: Request PUT /v1/session/create?dc=us-east-1&token=%22%22, error: ACL not found from=127.0.0.1:50666
2017/05/31 15:22:58 [ERR] http: Request PUT /v1/session/create?dc=us-east-1&token=%22%22, error: ACL not found from=127.0.0.1:50666

My question is, why isn't Consul using a token in the PUT request at the end of the log?

[Sylvain Boily]

As i understand, you need to have acl_agent_token now.

check this doc https://www.consul.io/docs/guides/acl.html

and specifically https://www.consul.io/docs/guides/acl.html#version_8_acls

 

[James Phillips]

Hi Byron,

Do you know where those session requests are coming from? It looks
like there's some URL-escaped junk being added by whatever that
process is that's being interpreted as a token. Since this token is
invalid, that returns an error immediately. There previously wasn't
any ACL support for sessions, so this is new behavior in 0.8.x.

-- James

> --
> This mailing list is governed under the HashiCorp Community Guidelines -
> https://www.hashicorp.com/community-guidelines.html. Behavior in violation
> of those guidelines may result in your removal from this mailing list.
>
> GitHub Issues: https://github.com/hashicorp/consul/issues
> IRC: #consul on Freenode
> ---
> You received this message because you are subscribed to the Google Groups
> "Consul" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to consul-tool...@googlegroups.com.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/consul-tool/043b31c3-924f-40d9-ae06-57107c512b2f%40googlegroups.com.
>
> For more options, visit https://groups.google.com/d/optout.

[Byron Kim]

They are showing up on each node in the cluster once the master is restarted.  Going back to Sylvain's comments, I think I'm missing the step of adding the actual ACL policies once I add the ACL configuration.  Gonna test it out

[Byron Kim]

Still getting the error.  I set my default policy's to be "allow"ed and then added this policy:

{
  "agent": {
    "": {
      "policy": "read"
    }
  },
  "key": {
    "": {
      "policy": "read"
    },
    "lock/": {
      "policy": "write"
    }
  },
  "node": {
    "integration": {
      "policy": "read"
    }
  },
  "service": {
    "": {
      "policy": "write"
    }
  },
  "session": {
    "": {
      "policy": "write"
    },
    "integration": {
      "policy": "write"
    }
  }
}

and I'm still getting a ton of these in the logs:

2017/06/01 20:57:15 [ERR] http: Request PUT /v1/session/create?dc=us-east-1&token=%22%22, error: rpc error: ACL not found from=127.0.0.1:47736
2017/06/01 20:57:15 [ERR] http: Request PUT /v1/session/create?dc=us-east-1&token=%22%22, error: rpc error: ACL not found from=127.0.0.1:47736

I'm not sure if `consul monitor` is supposed to show the actual value of the token, but it's always displaying `%22%22`

[James Phillips]

It is supposed to redact the token, but it looks like its regex might
need fixing. Do you know what application is trying to make a session
and generating those requests?

> https://groups.google.com/d/msgid/consul-tool/ebd379ba-63ec-40e8-bbbf-d1efc2dfb16e%40googlegroups.com.

[Byron Kim]

So I had several other nodes connecting so I stopped consul on them and tried to run the ACL update again and with the same problem.  I then disabled nginx (set as a proxy in front of an ELB) and still had the log and finally caught something in the logs.  I have consul-alerts running and disabled it and now the errors went away :)