Nodes locking up

[keyneston]

I just upgraded to commit 6d43b8c and am now seeing a small percentage of nodes constantly failing their serf checks. There is no consistency between which nodes fail out. Restarting consul will resolve the issue, temporarily.

Consul is running:

nobody   14838  0.3  0.0 160016 13604 ?        Ssl  15:43   0:01 /usr/bin/consul agent -config-dir /etc/consul.d/

But consul members and other api requests hang, not responding.

There is nothing in the logs beyond messages like:

Jun 11 15:47:31 bar21 consul[14838]: serf: messageJoinType: foo52
Jun 11 15:47:31 bar21 consul[14838]: serf: messageJoinType: foo52
Jun 11 15:47:31 bar21 consul[14838]: serf: messageJoinType: foo52
Jun 11 15:47:31 bar21 consul[14838]: serf: messageJoinType: foo52
Jun 11 15:47:31 bar21 consul[14838]: serf: messageJoinType: foo52
Jun 11 15:47:32 bar21 consul[14838]: serf: messageJoinType: foo52
Jun 11 15:47:32 bar21 consul[14838]: serf: messageJoinType: foo52
Jun 11 15:47:33 bar21 consul[14838]: serf: EventMemberFailed: foo29 1.1.1.5
Jun 11 15:47:33 bar21 consul[14838]: serf: EventMemberFailed: zxy1 1.1.1.10
Jun 11 15:47:35 bar21 consul[14838]: serf: EventMemberFailed: baz1 1.1.1.15
Jun 11 15:47:36 bar21 consul[14838]: serf: messageJoinType: foo40
Jun 11 15:47:36 bar21 consul[14838]: serf: messageJoinType: foo40
Jun 11 15:47:36 bar21 consul[14838]: serf: messageJoinType: foo40
Jun 11 15:47:36 bar21 consul[14838]: serf: messageJoinType: foo40
Jun 11 15:47:36 bar21 consul[14838]: serf: messageJoinType: foo40
Jun 11 15:47:36 bar21 consul[14838]: serf: messageJoinType: foo40

[keyneston]

Config:

{
    "bind_addr": "<scrubbed>",
    "data_dir": "/var/lib/consul",
    "datacenter": "dc01",
    "enable_syslog": true,
    "server": false,
    "start_join": [
        "<scrubbed>",
        "<scrubbed>",
        "<scrubbed>",
        "<scrubbed>"
    ],
    "syslog_facility": "local3"
}

[armon]

Do you know what build you were running previously?

[keyneston]

2877124

[armon]

Are the nodes that lock-up totally inoperable? It would be great if you could try to capture the output of sending a SIGUSR1 to get the metrics, followed by a SIGABRT to get a stack trace once they are hung.

[keyneston]

Btw these only print to stdout and not syslog which luckily isn't too bad of a problem since upstart on precise logs stdout automatically. Sadly upstart on lucid doesn't so I have to use syslog for consistent logging.

Metrics and stracktrace: https://gist.github.com/tarrant/4d62bd6db4d9434ed8f4

[armon]

Yeah they are super debug only, directly to stderr. The SIGABRT is built into the runtime.

[armon]

Do you have something fancy going on with syslog? It seems that Consul is blocked writing to syslog. One goroutine is waiting to write to syslog, while holding a lock inside the Logger, so any goroutine that tries to log anything ends up deadlocking.

[keyneston]

As far as I can tell no nothing fancy. But it makes sense that the issue is in syslog since that is the reason I upgraded and the only config that I've changed when upgrading.

I'll poke around our syslog settings and see if I can discover anything.

[armon]

Let me know what you find. Otherwise, our only other choices are to either buffer logs indefinitely (bad) or just drop logs (worse).

[keyneston]

I can't find anything odd in our syslog setup. I'm attempting to replicate the issue with a small go program and the go-syslog library.

[armon]

I'll be trying to replicate tomorrow as well. Hammered a perf cluster for a bit, but never saw this. I wasn't using syslog however.

[keyneston]

We only see this issue in our main cluster, our smaller clusters seem to be happy. This makes me believe it is a locking issue triggered by serf messages about nodes joining/leaving/etc as this cluster sees significantly more of these messages.

[armon]

Did you see the same number of serf messages before the update? Or has there been an uptick in the new build?

[armon]

@tarrant On thinking about this more, I think a few more pieces are clear:

1. There is increased Serf traffic because we now send the "build" tag with the version (e.g. 0.3rc). Since you are doing a rolling upgrade, all the clients are sending new "alive" messages to update the tags. This will cause some temporary congestion on a very large cluster like yours, since effective throughput is only about 40-80 updates/sec with Serf. This is not an issue, since Serf is designed to be eventually consistent.

2. The increased activity causes increased logging, and for some reason the syslog write is blocking.

3. Once the process locks up in the write, other nodes detect a failure (since the agent is not responding to ping messages).

So, I think the root issue here is the blocking syslog. The other pieces of this make sense.

[armon]

As followup, seems we are not alone in this. Golang bug with syslog:
https://groups.google.com/forum/#!topic/Golang-Nuts/PMm8nH0yaoA
https://code.google.com/p/go/issues/detail?id=5932

[armon]

Just updated this: hashicorp/go-syslog@ac3963b

When you get a chance, can you see if this has fixed the issue?

[keyneston]

So far that seems to have fixed the issue.

[armon]

Super annoying that this issue exists, but glad its fixed!