Zookeeper Serverset SD broken on 1.4.1

[jjneely]

What did you do?

Upgraded from 1.2.1 to 1.4.1.

What did you expect to see?

Known working serverset configuration should continue to function.

What did you see instead? Under which circumstances?

The /target page refuses to load. Scraping of all targets does not happen.

Environment

• System information:

  Linux 3.13.0-85-generic x86_64
  Ubuntu Trusty

• Prometheus version:

    # prometheus -version
    prometheus, version 1.4.1 (branch: XXX, revision: 1.4.1-1+JENKINS~trusty.20161202194014)
      build user:       jjneely@42lines.net
      build date:       2016-12-02T19:41:12Z
      go version:       go1.7.4
  

• Prometheus configuration file:

Complete configuration can be made available privately. The following is what my server set looks like. (Yes, JSON.)

    {
      "job_name": "pushgateway",
      "serverset_sd_configs": [
        {
          "servers": [
            "mesos-zk-discovery-001-g6.XXX.com:2181",
            "mesos-zk-discovery-002-g6.XXX.com:2181",
            "mesos-zk-discovery-003-g6.XXX.com:2181"
          ],
          "paths": [
            "/aurora/site-visibility/prod/pushgateway"
          ]
        }
      ],
      "honor_labels": true,
      "relabel_configs": [
        ...
      ]
    }

Removing the serverset_sd_configs section from the configuration makes the Prometheus 1.4.1 instance function normally. Issues return when the serverset section is re-added.

• Logs:

No additional logs produced, even with -log.leve=debug present. I believe the target manager is deadlocked.

[cristifalcas]

We have the same issue. After 1.4.0, zookeepeer scrape_config doesn't work anymore.

[prfalken]

This obviously affects the Nerve Service Discovery as well, as it's based on zookeeper.

[JustinVenus]

Ran into this issue as well. Prometheus-1.3.1 is the last release version that isn't affected by this bug.

[jacobrichard]

Looks like a lot of ZK service discovery changes in 1.4.0. I'd have to pick through what is being done here, but it looks like nerve and serverset got merged into one file. Seems like a lot of locking logic was rewritten or removed, which could contribute to a deadlock.

See the changes in: a1eec44

[Jackey2015]

in this file: util/treecache/treecache.go
tc.events <- ZookeeperTreeCacheEvent{Path: path, Data: node.data}
change to
go func() { tc.events <- ZookeeperTreeCacheEvent{Path: path, Data: node.data} }()

rebuild prometheus after change code, it works OK

[cristifalcas]

Any updates on this?

[juliusv]

I am not familiar with the Zookeeper SD at all and don't have a Zookeper around to try anything out myself, but just from having a quick look at the code I suspect the problem to be this deadlock:

• we create a tree cache, passing in an unbuffered channel for it to send updates:
  https://github.com/prometheus/prometheus/blob/master/discovery/zookeeper/zookeeper.go#L74
• the tree cache constructor synchronously triggers an initial update, which tries to send events over the channel:
  https://github.com/prometheus/prometheus/blob/master/util/treecache/treecache.go#L89
  https://github.com/prometheus/prometheus/blob/master/util/treecache/treecache.go#L191
• ...but the channel is only being read after the construction of the cache is complete, so there's a deadlock, as the sender blocks on the channel

Perhaps it is sufficient to remove the initial synchronous sync by just removing these lines:

prometheus/util/treecache/treecache.go

Lines 89 to 92 in 3730255

	err := tc.recursiveNodeUpdate(path, tc.head)
	if err != nil {
	log.Errorf("Error during initial read of Zookeeper: %s", err)
	}

If someone could try that out, that would be great.

[StephanErb]

@juliusv thanks for doing the code analysis. I will test it out and report back here.

[StephanErb]

Following Julius excellent lead, I was able to assemble a fix. See #2470 for details.

[StephanErb]

Any chance to get this into a bugfix release?

(I can understand if this is too much effort, but maybe you have good automation in place to make this feasible :-). Thanks!)

[jjneely]

I filed #2481 regarding this patch, there seems to be issues after a SIGHUP reload where the Zookeeper code begins consuming a large amount of CPU time.

[beorn7]

The 1.6 release is not too far away. (If I only wouldn't be drawn into production incidents all the time, or had to prepare talks for CloudNativeCon ;).

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.