Skip to content
Closed
Show file tree
Hide file tree
Changes from 5 commits
Commits
Show all changes
23 commits
Select commit Hold shift + click to select a range
fea6c1b
First commit for replacement for replication test suite. All are curr…
Jul 13, 2015
069b9d7
Fixed soft failure tests.
Jul 14, 2015
0a1efd3
Produce/consume from multiple topics.
Jul 14, 2015
4dd513e
Added one test with acks=1 and one using compression.
Jul 14, 2015
99ae12f
Replaced previous replication_test.py with the new suite of replicati…
Jul 14, 2015
d6294fa
Merged in KAFKA-2276
Jul 20, 2015
77d07a3
Merged in KAFKA-2276
Jul 22, 2015
61b7a2a
Update provisioning so that iptables can be used in creating network …
Jul 23, 2015
a2ad18b
Merged in upstream trunk.
Jul 27, 2015
a62fb6c
fixed checkstyle errors
Jul 27, 2015
1a4d211
Many small changes per review. Also, improved performance by making k…
Jul 28, 2015
5a548e6
Fixed command adding LOG_DIR to env before starting kafka
Jul 28, 2015
57386de
KAFKA-2301: Warn ConsumerOffsetChecker as deprecated; reviewed by Ewe…
Jul 28, 2015
269c240
KAFKA-2381: Fix concurrent modification on assigned partition while l…
Jul 28, 2015
3df46bf
KAFKA-2347: Add setConsumerRebalanceListener method to ZookeeperConsu…
Jul 28, 2015
594b963
KAFKA-2275: Add ListTopics() API to the Java consumer; reviewed by Ja…
Jul 28, 2015
f4101ab
KAFKA-2089: Fix transient MetadataTest failure; reviewed by Jiangjie …
rajinisivaram Jul 28, 2015
86ec39c
Merged in upstream trunk.
Jul 29, 2015
9bb1037
Fixed some of the wait_until conditions which were causing problems w…
Jul 29, 2015
3791086
Merged in final KAFKA-2276
Jul 29, 2015
499ceca
Added unit-test-like sanity checks to help with validating and debugg…
Jul 29, 2015
c9edf92
Added crude network partition test which approximately replicates the…
Jul 29, 2015
b5a44dc
Added check in kafka.stop_node to kill -9 if SIGTERM did not work.
Jul 29, 2015
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -27,11 +27,15 @@
import org.json.simple.JSONObject;

import java.io.IOException;
import java.util.List;
import java.util.Properties;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicBoolean;

import static net.sourceforge.argparse4j.impl.Arguments.store;

import net.sourceforge.argparse4j.ArgumentParsers;
import net.sourceforge.argparse4j.impl.Arguments;
import net.sourceforge.argparse4j.inf.ArgumentParser;
import net.sourceforge.argparse4j.inf.ArgumentParserException;
import net.sourceforge.argparse4j.inf.Namespace;
Expand Down Expand Up @@ -66,14 +70,18 @@ public class VerifiableProducer {
private long throughput;

// Hook to trigger producing thread to stop sending messages
private boolean stopProducing = false;
private AtomicBoolean stopProducing = new AtomicBoolean(false);

// Timeout on producer.close() call
private long closeTimeoutSeconds;

public VerifiableProducer(
Properties producerProps, String topic, int throughput, int maxMessages) {
Properties producerProps, String topic, int throughput, int maxMessages, long closeTimeoutSeconds) {

this.topic = topic;
this.throughput = throughput;
this.maxMessages = maxMessages;
this.closeTimeoutSeconds = closeTimeoutSeconds;
this.producer = new KafkaProducer<String, String>(producerProps);
}

Expand Down Expand Up @@ -124,6 +132,23 @@ private static ArgumentParser argParser() {
.choices(0, 1, -1)
.metavar("ACKS")
.help("Acks required on each produced message. See Kafka docs on request.required.acks for details.");

parser.addArgument("--producer-prop")

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Other tools (at least producer performance, possibly others) just allow a list of prop=value arguments. Any reason not to be consistent with those (or whatever the KIP-4 discussion might have ended up agreeing upon)?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The only place I kinda see this is in kafka-topic.sh, but neither KIP-4 nor KIP-14 make reference to allowing a list of prop=value.

Currently kafka-topic.sh doesn't really have this behavior (should it?...):
This works (one --config per config):

kafka_fork $ bin/kafka-topics.sh --topic abc --zookeeper=localhost:2181 --create --partitions 1 --replication-factor 1 --config max.message.bytes=111 --config flush.ms=222

This silently ignores the second config (flush.ms):

kafka_fork $ bin/kafka-topics.sh --topic abc --zookeeper=localhost:2181 --create --partitions 1 --replication-factor 1 --config max.message.bytes=111 flush.ms=222

From a quick scan of https://reviews.apache.org/r/34554/diff/7#3 it looks like this behavior is unchanged in the KIP-4 patches.

That all said, I changed the name to "--config" to be consistent.

.action(Arguments.append())
.required(false)
.type(String.class)
.dest("userSpecifiedProducerProps")
.metavar("PRODUCER-PROP")
.help("Any custom producer properties of the form key=val.");

parser.addArgument("--close-timeout")
.action(store())
.required(false)
.setDefault(10L)

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Curious about the default here. Should it be significantly higher? For this tool, it's pretty important to report as accurate information as possible. I'm concerned that if you happen to do something like stop this producer when you're also bouncing brokers, are there cases where this default might not be sufficient and cause tests to appear to fail (e.g. it will actually succeed, slowly, but because of this timeout we log it as failed).

Perhaps an important related question is what types of situations might we get stuck waiting for a long time (in a system test, not a real production environment) such that we wouldn't want to make this a very conservatively large number? This may also be relevant with the up coming max.block.ms setting from KIP-19 (where I assume the default will be ok, but possibly for a tool like this we'd want to be even more conservative than the default).

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I'm not sure the best solution here.

Basically every replication test results in waiting for a very long time after the initial trigger of the close() method, and typically the wait can be much longer than all of the other test logic.

One alternative method might be the throttle the throughput more aggressively.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why are they waiting that long? Do they just have a ton of data buffered? Shouldn't the default buffer size keep the outstanding data to a reasonable size so close() wouldn't have to wait for very long?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My current hypothesis is that printing to stdout in each callback has enough overhead that a huge lag develops between the stuff queued up for stdout and the messages actually sent.

If you run the producer with no close timeout at with default throughput of -1, and then hit ctrl-c, you'll see many many thousands of messages printed after the fact, and wait a very long time for everything to flush. I don't think the buffer size is the issue (~16,000 by default), since many many more than 16,000 messages print after hitting ctrl-c.

If you comment out the println statements in the callback and replace with some computations, the producer exits almost immediately when you hit ctrl-c.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How much more backlogged can it get than the buffer size? Aren't those callbacks invoked in the producer's network thread such that they would block any further sends until they complete?

In any case, this probably means we need to reduce the cost of this logging. It probably needs some profiling to determine what the issue is for sure, but some obvious things that might be affecting how expensive this is:

  • System.out will flush with every newline, i.e. for every call to println. This could add up since each line isn't that long.
  • There's a lot of redundant work being done, e.g. creating JSONObject, getting the class name, etc.
  • How fast is this JSON library? It could end up being faster to just do the encoding manually even though that's less than ideal.
  • We're converting to a string, then writing to System.out rather than writing directly.

Also, be careful evaluating this by running directly in the console. If the issue has anything to do with the output, involving a console can significantly affect performance. You're better off logging something so you can tell when Ctrl-C was hit, then using the subsequent log entries and their timestamps to see how many more events there were and how long they took. Along the same lines, is this log being written locally and then synced via ducktape or is it running via SSH and with the SSH output being processed on the test runner? The SSH connection could also end up being a bottleneck.

.type(Long.class)
.metavar("CLOSE-TIMEOUT")
.dest("closeTimeoutSeconds")
.help("When SIGTERM is caught, wait at most this many seconds for unsent messages to flush before stopping the VerifiableProducer process.");

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Generally configs for anything time related are in ms. I think there may be an exception or two when the time scale is expected to be much larger (log rolling, log retention have flexible units). Not sure if we want to try to be as consistent as possible (use ms) or use the units that most likely match what the user will want to express (use seconds).

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changed to ms


return parser;
}
Expand All @@ -134,13 +159,12 @@ public static VerifiableProducer createFromArgs(String[] args) {
VerifiableProducer producer = null;

try {
Namespace res;
res = parser.parseArgs(args);

Namespace res = parser.parseArgs(args);
int maxMessages = res.getInt("maxMessages");
String topic = res.getString("topic");
int throughput = res.getInt("throughput");

long closeTimeoutSeconds = res.getLong("closeTimeoutSeconds");

Properties producerProps = new Properties();
producerProps.put(ProducerConfig.BOOTSTRAP_SERVERS_CONFIG, res.getString("brokerList"));
producerProps.put(ProducerConfig.KEY_SERIALIZER_CLASS_CONFIG,
Expand All @@ -150,8 +174,24 @@ public static VerifiableProducer createFromArgs(String[] args) {
producerProps.put(ProducerConfig.ACKS_CONFIG, Integer.toString(res.getInt("acks")));
// No producer retries
producerProps.put("retries", "0");

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unrelated but I just saw this -- why isn't this just ProducerConfig.RETRIES_CONFIG?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

oops, good call. Updated


// Properties specified using the --producer-prop key=val format override
// other properties
List<String> userSpecifiedProducerProps = res.getList("userSpecifiedProducerProps");
for (String prop: userSpecifiedProducerProps) {

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we have code for this somewhere already. Looks like it should be reusable across a bunch of tools.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nothing like this in clients/tools, since this is the first introduction of an option parsing library,

There may be something analogous in core.

However I'm not sure if it's good to add a dependency on core, where jopt-simple is used. Also, as noted with the problems parsing "-1", jopt-simple had some impressively obnoxious corner cases.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right, I just thought a few tools allowed a set of generic config opts in opt=value form already, but maybe those are all housed in core. Maybe we need a few more tools here before we can figure out which things should be refactored into utilities.

int index = prop.indexOf('=');
if (index < 0 || index == prop.length() - 1) {
throw new IllegalArgumentException(
"Invalid format for producer prop: " + prop);
}

String key = prop.substring(0, index);
String val = prop.substring(index + 1, prop.length());
producerProps.put(key, val);
}

producer = new VerifiableProducer(producerProps, topic, throughput, maxMessages);
producer = new VerifiableProducer(
producerProps, topic, throughput, maxMessages, closeTimeoutSeconds);
} catch (ArgumentParserException e) {
if (args.length == 0) {
parser.printHelp();
Expand Down Expand Up @@ -181,7 +221,7 @@ public void send(String key, String value) {

/** Close the producer to flush any remaining messages. */
public void close() {
producer.close();
producer.close(this.closeTimeoutSeconds, TimeUnit.SECONDS);
}

/**
Expand All @@ -193,7 +233,7 @@ String errorString(Exception e, String key, String value, Long nowMs) {

JSONObject obj = new JSONObject();
obj.put("class", this.getClass().toString());
obj.put("name", "producer_send_error");
obj.put("name", "f_error");

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why this change? Looks like it might be a typo?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah this must have been a typo. Reverted.


obj.put("time_ms", nowMs);
obj.put("exception", e.getClass().toString());
Expand Down Expand Up @@ -233,6 +273,11 @@ private class PrintInfoCallback implements Callback {

public void onCompletion(RecordMetadata recordMetadata, Exception e) {
synchronized (System.out) {
if (VerifiableProducer.this.stopProducing.get()) {

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure about this behavior. The whole point of this producer is to log complete information about what it sent and what it knows about the success of those sends. If we ignore some callbacks, we won't have logged all the data. It seems very likely we would regularly see "extra" data at consumers if we used this approach.

One solution would be to still log these events, but adjust the output when you see an error and stopProducing is true, e.g. use producer_send_closing_error instead of producer_send_error to indicate it may have just been due to a timeout (although again, with the addition of KIP-19's patch with client-side timeouts, we may have to rethink what exactly these messages mean since sends could succeed but timeout too quickly).

// Stop writing to stdout
return;
}

if (e == null) {
VerifiableProducer.this.numAcked++;
System.out.println(successString(recordMetadata, this.key, this.value, System.currentTimeMillis()));
Expand All @@ -253,7 +298,7 @@ public static void main(String[] args) throws IOException {
@Override
public void run() {
// Trigger main thread to stop producing messages
producer.stopProducing = true;
producer.stopProducing.set(true);

// Flush any remaining messages
producer.close();
Expand All @@ -274,7 +319,7 @@ public void run() {

ThroughputThrottler throttler = new ThroughputThrottler(producer.throughput, startMs);
for (int i = 0; i < producer.maxMessages || infinite; i++) {
if (producer.stopProducing) {
if (producer.stopProducing.get()) {
break;
}
long sendStartMs = System.currentTimeMillis();
Expand Down
2 changes: 1 addition & 1 deletion tests/kafkatest/services/console_consumer.py
Original file line number Diff line number Diff line change
Expand Up @@ -91,6 +91,7 @@ def __init__(self, context, num_nodes, kafka, topic, message_validator=is_int, f
"""
super(ConsoleConsumer, self).__init__(context, num_nodes)
self.kafka = kafka
self.topic = topic
self.args = {
'topic': topic,
}
Expand Down Expand Up @@ -132,7 +133,6 @@ def _worker(self, idx, node):
msg = line.strip()
msg = self.message_validator(msg)
if msg is not None:
self.logger.debug("consumed a message: " + str(msg))
self.messages_consumed[idx].append(msg)

def start_node(self, node):
Expand Down
73 changes: 53 additions & 20 deletions tests/kafkatest/services/kafka.py
Original file line number Diff line number Diff line change
Expand Up @@ -54,6 +54,14 @@ def start(self):
topic_cfg["topic"] = topic
self.create_topic(topic_cfg)

# Sanity check - are the broker processes actually running?

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just a side note, but it'd be really nice to have some utility code to help parallelize stuff like this.

for node in self.nodes:
for pid in self.pids(node):
if not node.account.alive(pid):
raise Exception(
"Expected Kafka process %s to be running on node %s, but found that the process is not alive." %
(str(pid), str(node.account)))

def start_node(self, node):
props_file = self.render('kafka.properties', node=node, broker_id=self.idx(node))
self.logger.info("kafka.properties:")
Expand Down Expand Up @@ -96,7 +104,7 @@ def clean_node(self, node):
node.account.ssh("rm -rf /mnt/kafka-logs /mnt/kafka.properties /mnt/kafka.log /mnt/kafka.pid", allow_fail=False)

def create_topic(self, topic_cfg):
node = self.nodes[0] # any node is fine here
node = self.nodes[0] # any node is fine here
self.logger.info("Creating topic %s with settings %s", topic_cfg["topic"], topic_cfg)

cmd = "/opt/kafka/bin/kafka-topics.sh --zookeeper %(zk_connect)s --create "\
Expand All @@ -116,6 +124,7 @@ def create_topic(self, topic_cfg):

time.sleep(1)
self.logger.info("Checking to see if topic was properly created...\n%s" % cmd)

for line in self.describe_topic(topic_cfg["topic"]).split("\n"):
self.logger.info(line)

Expand Down Expand Up @@ -199,29 +208,53 @@ def restart_node(self, node, wait_sec=0, clean_shutdown=True):
def leader(self, topic, partition=0):
""" Get the leader replica for the given topic and partition.
"""
cmd = "/opt/kafka/bin/kafka-run-class.sh kafka.tools.ZooKeeperMainWrapper -server %s " \
% self.zk.connect_setting()
cmd += "get /brokers/topics/%s/partitions/%d/state" % (topic, partition)
self.logger.debug(cmd)
topic_partition_data = self.zk_get_data("/brokers/topics/%s/partitions/%d/state" % (topic, partition))

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These paths don't account for ZK chroots. Or is that just handled by the zkconnect setting?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm, is this really necessary? There is no mechanism in ZookeeperService for creating a chroot

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's part of why I was asking about the zkconnect setting. It's just something to keep in mind because we're increasing the number of ways we're relying on the semantics of the ZookeeperService class, and I realized that chroots are something we may want to test at some point. May not require anything in this patch, could be a parameter where we only use the default, or something else. It's worth thinking through the implications as we add more utility methods like this.


if topic_partition_data is None:
raise Exception("Error finding data for topic %s and partition %d." % (topic, partition))
self.logger.info(topic_partition_data)

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Logging this to info for every lookup seems like overkill.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is pretty useful to have at some level - changed to debug

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With stuff like this, I like to ask whether anyone might ever call this in a pretty tight loop, e.g. in order to wait to meet some condition (like leader failover) but detect it fairly promptly. In those cases, logging in an accessor can be dangerous (huge amount of log output).


leader_idx = int(topic_partition_data["leader"])
self.logger.info("Leader for topic %s and partition %d is now: %d" % (topic, partition, leader_idx))

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same here actually -- if it's important enough to log, the caller of this method should probably log it. Logging in accessors gets annoying if anything ends up needing to call it frequently.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

moved to test code

return self.get_node(leader_idx)

def controller(self):
"""
Get the current controller
"""
controller_data = self.zk_get_data("/controller")
if controller_data is None:
raise Exception("Error finding controller.")
self.logger.info(controller_data)

controller_idx = int(controller_data["brokerid"])
self.logger.info("Controller is: %d" % controller_idx)
controller_node = self.get_node(controller_idx)

if controller_node is None:
raise Exception("Found no node corresponding to the id: %d" % controller_idx)
return controller_node

def zk_get_data(self, path):

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we just move this to the Zookeeper service? Seems like it's a better home for it.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yup, moved

"""
Get data from zookeeper on the given path. This method assumes the data is in JSON format.

:param path Zookeeper path to query for data
:param node optional node on which query will be run

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

docs seem out of date, there's no node parameter here

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

updated

"""
cmd = "/opt/kafka/bin/kafka-run-class.sh kafka.tools.ZooKeeperMainWrapper -server %s get %s" % \
(self.zk.connect_setting(), path)
data = None
node = self.nodes[0]
self.logger.debug("Querying zookeeper to find leader replica for topic %s: \n%s" % (cmd, topic))
partition_state = None
for line in node.account.ssh_capture(cmd):
match = re.match("^({.+})$", line)
if match is not None:
partition_state = match.groups()[0]
try:
data = json.loads(line)
break
except ValueError:
pass

if partition_state is None:
raise Exception("Error finding partition state for topic %s and partition %d." % (topic, partition))

partition_state = json.loads(partition_state)
self.logger.info(partition_state)

leader_idx = int(partition_state["leader"])
self.logger.info("Leader for topic %s and partition %d is now: %d" % (topic, partition, leader_idx))
return self.get_node(leader_idx)
return data

def bootstrap_servers(self):
return ','.join([node.account.hostname + ":9092" for node in self.nodes])
return ','.join([node.account.hostname + ":9092" for node in self.nodes])

11 changes: 9 additions & 2 deletions tests/kafkatest/services/verifiable_producer.py
Original file line number Diff line number Diff line change
Expand Up @@ -23,16 +23,18 @@ class VerifiableProducer(BackgroundThreadService):
logs = {
"producer_log": {
"path": "/mnt/producer.log",
"collect_default": False}
"collect_default": True}

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why did this change? Isn't there a data size problem since it logs every single message?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changed while debugging. Reverted.

}

def __init__(self, context, num_nodes, kafka, topic, max_messages=-1, throughput=100000):
def __init__(self, context, num_nodes, kafka, topic, max_messages=-1, throughput=100000, close_timeout_sec=60, producer_props=None):
super(VerifiableProducer, self).__init__(context, num_nodes)

self.kafka = kafka
self.topic = topic
self.max_messages = max_messages
self.throughput = throughput
self.close_timeout_sec = close_timeout_sec
self.producer_props = producer_props # Overrides for Kafka producer settings

self.acked_values = []
self.not_acked_values = []
Expand Down Expand Up @@ -63,6 +65,11 @@ def start_cmd(self):
cmd += " --max-messages %s" % str(self.max_messages)
if self.throughput > 0:
cmd += " --throughput %s" % str(self.throughput)
cmd += " --close-timeout %s" % str(self.close_timeout_sec)

if self.producer_props is not None:

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could change the default to be an empty list (or zero-tuple if you prefer making it immutable), which avoids is not None checks like this littering the code.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm. I suppose it's ok to have a mutable default argument in the init method since it will only be called once in the object's lifetime.

Changed to empty dict.

for key in self.producer_props:
cmd += " --producer-prop %s=%s" % (key, str(self.producer_props[key]))

cmd += " 2>> /mnt/producer.log | tee -a /mnt/producer.log &"
return cmd
Expand Down
Loading