Issues trying to run the QuickStart

1,303 views
Skip to first unread message

Roger Hoover

unread,
Mar 5, 2015, 6:33:07 PM3/5/15
to confluent...@googlegroups.com
Hi,

I'm trying to follow the quickstart guide and am not able to send any data to Kafka.  When I run the kafka-avro-console-producer command and paste in one message, I see this debug log

[2015-03-05 15:28:21,679] DEBUG Sending POST with input {"schema":"{\"type\":\"record\",\"name\":\"myrecord\",\"fields\":[{\"name\":\"f1\",\"type\":\"string\"}]}"} to http://localhost:8081/subjects/test-value/versions (io.confluent.kafka.schemaregistry.client.rest.utils.RestUtils:105)

However, nothing gets logged on the schema registry server side (I have it set to DEBUG level) so it seems the request never even started.

After a minute or so, I see this error:

org.apache.kafka.common.errors.SerializationException: Error serializing Avro message

Caused by: com.fasterxml.jackson.core.JsonParseException: Unexpected character ('<' (code 60)): expected a valid value (number, String, array, object, 'true', 'false' or 'null')

 at [Source: sun.net.www.protocol.http.HttpURLConnection$HttpInputStream@a072d8c; line: 1, column: 2]

at com.fasterxml.jackson.core.JsonParser._constructError(JsonParser.java:1419)

at com.fasterxml.jackson.core.base.ParserMinimalBase._reportError(ParserMinimalBase.java:508)

at com.fasterxml.jackson.core.base.ParserMinimalBase._reportUnexpectedChar(ParserMinimalBase.java:437)

at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._handleUnexpectedValue(UTF8StreamJsonParser.java:2363)

at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._nextTokenNotInObject(UTF8StreamJsonParser.java:794)

at com.fasterxml.jackson.core.json.UTF8StreamJsonParser.nextToken(UTF8StreamJsonParser.java:690)

at com.fasterxml.jackson.databind.ObjectMapper._initForReading(ObjectMapper.java:3090)

at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3036)

at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2192)

at io.confluent.kafka.schemaregistry.client.rest.utils.RestUtils.httpRequest(RestUtils.java:144)

at io.confluent.kafka.schemaregistry.client.rest.utils.RestUtils.registerSchema(RestUtils.java:174)

at io.confluent.kafka.schemaregistry.client.CachedSchemaRegistryClient.registerAndGetId(CachedSchemaRegistryClient.java:51)

at io.confluent.kafka.schemaregistry.client.CachedSchemaRegistryClient.register(CachedSchemaRegistryClient.java:89)

at io.confluent.kafka.serializers.AbstractKafkaAvroSerializer.serializeImpl(AbstractKafkaAvroSerializer.java:49)

at io.confluent.kafka.formatter.AvroMessageReader.readMessage(AvroMessageReader.java:155)

at kafka.tools.ConsoleProducer$.main(ConsoleProducer.scala:94)

at kafka.tools.ConsoleProducer.main(ConsoleProducer.scala)

[2015-03-05 15:29:37,460] INFO Shutting down producer (kafka.producer.Producer:68)

[2015-03-05 15:29:37,460] INFO Shutting down producer (kafka.producer.Producer:68)

[2015-03-05 15:29:37,466] INFO Closing all sync producers (kafka.producer.ProducerPool:68)

[2015-03-05 15:29:37,466] INFO Closing all sync producers (kafka.producer.ProducerPool:68)

[2015-03-05 15:29:37,468] INFO Producer shutdown completed in 7 ms (kafka.producer.Producer:68)

[2015-03-05 15:29:37,468] INFO Producer shutdown completed in 7 ms (kafka.producer.Producer:68)

I'm running Oracle Java 1.7.0_65 on Mac OS X.

I appreciate any help.  Thanks,

Roger

P.S.  While trying to debug this, I found a bug in the path to log4j.properties file: https://github.com/confluentinc/schema-registry/pull/141

Ewen Cheslack-Postava

unread,
Mar 5, 2015, 7:02:13 PM3/5/15
to Roger Hoover, confluent...@googlegroups.com
Thanks for trying it out, and sorry it's been bumpy. The schema registry definitely shouldn't have any problem registering the initial schema.

The schema registry does have some initial setup it needs to do (it stores all its data in Kafka, so it needs to create the topic for storage). It's possible that's where you were some of the delay came from. Are there any logs from the initial startup of the schema registry (after your fix to the bin script)? You should see it log a few messages about initializing the _schemas topic for storage and about becoming the leader.

It looks like we don't log the start of the register request, which is why you didn't see any log in response to that specific request. However, we have a generic request log, in web server common log format. We isolate that to its own logger since it doesn't use the standard format, so you might need to adjust the settings for that logger to see it (default logger is io.confluent.rest-utils.requests). That could at least tell us that the requests is being received, show us the HTTP response status, and maybe tell us if this is caused by a timeout (it should log response latency).

The exception that the serializer is seeing looks like it's due to the server returning non-JSON content, which it shouldn't be doing. I filed https://github.com/confluentinc/schema-registry/issues/142 to at least handle that when we see it. If we can track down exactly what the response was, we should also be able to keep it from generating html in the first place.

For the PR, already merged it, and thanks for the contribution!

--
You received this message because you are subscribed to the Google Groups "Confluent Platform" group.
To unsubscribe from this group and stop receiving emails from it, send an email to confluent-platf...@googlegroups.com.
To post to this group, send email to confluent...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/confluent-platform/f41112d1-a350-4347-9ba7-cd298ace8c1f%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.



--
Thanks,
Ewen

Roger Hoover

unread,
Mar 5, 2015, 7:21:35 PM3/5/15
to Ewen Cheslack-Postava, confluent...@googlegroups.com
Ewen,

Thanks for getting back to me.  From the log below (INFO level), it looks like the schema registry initializes ok.  I see the _schemas topic in Kafka using the kafka-topics script.


I tried setting the request logging to TRACE but still don't see anything.

log4j.logger.io.confluent.rest-utils.requests=TRACE, stdout

Here's the registry server init log:

[2015-03-05 16:12:28,441] INFO Client environment:java.library.path=/Users/rhoover/Library/Java/Extensions:/Library/Java/Extensions:/Network/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java:. (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:java.library.path=/Users/rhoover/Library/Java/Extensions:/Library/Java/Extensions:/Network/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java:. (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:java.io.tmpdir=/var/folders/jt/m_l1nzr16tgdvhh5r1jvr4500000gn/T/ (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:java.io.tmpdir=/var/folders/jt/m_l1nzr16tgdvhh5r1jvr4500000gn/T/ (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:java.compiler=<NA> (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:java.compiler=<NA> (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:os.name=Mac OS X (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:os.name=Mac OS X (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:os.arch=x86_64 (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:os.arch=x86_64 (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:os.version=10.10.2 (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,441] INFO Client environment:os.version=10.10.2 (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,442] INFO Client environment:user.name=rhoover (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,442] INFO Client environment:user.name=rhoover (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,442] INFO Client environment:user.home=/Users/rhoover (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,442] INFO Client environment:user.home=/Users/rhoover (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,444] INFO Client environment:user.dir=/Users/rhoover/Work/confluent/confluent-1.0 (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,444] INFO Client environment:user.dir=/Users/rhoover/Work/confluent/confluent-1.0 (org.apache.zookeeper.ZooKeeper:97)

[2015-03-05 16:12:28,445] INFO Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.I0Itec.zkclient.ZkClient@595938f3 (org.apache.zookeeper.ZooKeeper:373)

[2015-03-05 16:12:28,445] INFO Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.I0Itec.zkclient.ZkClient@595938f3 (org.apache.zookeeper.ZooKeeper:373)

[2015-03-05 16:12:28,455] INFO Opening socket connection to server localhost/0:0:0:0:0:0:0:1:2181 (org.apache.zookeeper.ClientCnxn:1000)

[2015-03-05 16:12:28,455] INFO Opening socket connection to server localhost/0:0:0:0:0:0:0:1:2181 (org.apache.zookeeper.ClientCnxn:1000)

[2015-03-05 16:12:28,465] INFO Socket connection established to localhost/0:0:0:0:0:0:0:1:2181, initiating session (org.apache.zookeeper.ClientCnxn:908)

[2015-03-05 16:12:28,465] INFO Socket connection established to localhost/0:0:0:0:0:0:0:1:2181, initiating session (org.apache.zookeeper.ClientCnxn:908)

[2015-03-05 16:12:28,473] INFO Session establishment complete on server localhost/0:0:0:0:0:0:0:1:2181, sessionid = 0x14bec1b5423002b, negotiated timeout = 30000 (org.apache.zookeeper.ClientCnxn:701)

[2015-03-05 16:12:28,473] INFO Session establishment complete on server localhost/0:0:0:0:0:0:0:1:2181, sessionid = 0x14bec1b5423002b, negotiated timeout = 30000 (org.apache.zookeeper.ClientCnxn:701)

[2015-03-05 16:12:28,475] INFO zookeeper state changed (SyncConnected) (org.I0Itec.zkclient.ZkClient:449)

[2015-03-05 16:12:28,475] INFO zookeeper state changed (SyncConnected) (org.I0Itec.zkclient.ZkClient:449)

[2015-03-05 16:12:28,599] INFO Initialized the consumer offset to -1 (io.confluent.kafka.schemaregistry.storage.KafkaStoreReaderThread:87)

[2015-03-05 16:12:28,721] INFO Verifying properties (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,721] INFO Verifying properties (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,767] INFO Property auto.commit.enable is overridden to false (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,767] INFO Property auto.commit.enable is overridden to false (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,767] INFO Property auto.offset.reset is overridden to smallest (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,767] INFO Property auto.offset.reset is overridden to smallest (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,767] INFO Property client.id is overridden to KafkaStore-reader-_schemas (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,767] INFO Property client.id is overridden to KafkaStore-reader-_schemas (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,767] INFO Property group.id is overridden to schema-registry-thedude-2-8081 (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,767] INFO Property group.id is overridden to schema-registry-thedude-2-8081 (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,768] INFO Property zookeeper.connect is overridden to localhost:2181 (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,768] INFO Property zookeeper.connect is overridden to localhost:2181 (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:28,823] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Connecting to zookeeper instance at localhost:2181 (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:28,823] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Connecting to zookeeper instance at localhost:2181 (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:28,824] INFO Initiating client connection, connectString=localhost:2181 sessionTimeout=6000 watcher=org.I0Itec.zkclient.ZkClient@10bd314a (org.apache.zookeeper.ZooKeeper:373)

[2015-03-05 16:12:28,833] INFO Starting ZkClient event thread. (org.I0Itec.zkclient.ZkEventThread:64)

[2015-03-05 16:12:28,824] INFO Initiating client connection, connectString=localhost:2181 sessionTimeout=6000 watcher=org.I0Itec.zkclient.ZkClient@10bd314a (org.apache.zookeeper.ZooKeeper:373)

[2015-03-05 16:12:28,833] INFO Starting ZkClient event thread. (org.I0Itec.zkclient.ZkEventThread:64)

[2015-03-05 16:12:28,834] INFO Opening socket connection to server localhost/fe80:0:0:0:0:0:0:1%1:2181 (org.apache.zookeeper.ClientCnxn:1000)

[2015-03-05 16:12:28,834] INFO Opening socket connection to server localhost/fe80:0:0:0:0:0:0:1%1:2181 (org.apache.zookeeper.ClientCnxn:1000)

[2015-03-05 16:12:28,834] INFO Socket connection established to localhost/fe80:0:0:0:0:0:0:1%1:2181, initiating session (org.apache.zookeeper.ClientCnxn:908)

[2015-03-05 16:12:28,834] INFO Socket connection established to localhost/fe80:0:0:0:0:0:0:1%1:2181, initiating session (org.apache.zookeeper.ClientCnxn:908)

[2015-03-05 16:12:28,837] INFO Session establishment complete on server localhost/fe80:0:0:0:0:0:0:1%1:2181, sessionid = 0x14bec1b5423002c, negotiated timeout = 6000 (org.apache.zookeeper.ClientCnxn:701)

[2015-03-05 16:12:28,837] INFO Session establishment complete on server localhost/fe80:0:0:0:0:0:0:1%1:2181, sessionid = 0x14bec1b5423002c, negotiated timeout = 6000 (org.apache.zookeeper.ClientCnxn:701)

[2015-03-05 16:12:28,837] INFO zookeeper state changed (SyncConnected) (org.I0Itec.zkclient.ZkClient:449)

[2015-03-05 16:12:28,837] INFO zookeeper state changed (SyncConnected) (org.I0Itec.zkclient.ZkClient:449)

[2015-03-05 16:12:28,876] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], begin registering consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 in ZK (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:28,876] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], begin registering consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 in ZK (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:28,911] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], end registering consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 in ZK (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:28,911] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], end registering consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 in ZK (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:28,916] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], starting watcher executor thread for consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:28,916] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], starting watcher executor thread for consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:28,940] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], begin rebalancing consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 try #0 (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:28,940] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], begin rebalancing consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 try #0 (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,087] INFO [ConsumerFetcherManager-1425600748841] Stopping leader finder thread (kafka.consumer.ConsumerFetcherManager:68)

[2015-03-05 16:12:29,087] INFO [ConsumerFetcherManager-1425600748841] Stopping leader finder thread (kafka.consumer.ConsumerFetcherManager:68)

[2015-03-05 16:12:29,087] INFO [ConsumerFetcherManager-1425600748841] Stopping all fetchers (kafka.consumer.ConsumerFetcherManager:68)

[2015-03-05 16:12:29,087] INFO [ConsumerFetcherManager-1425600748841] Stopping all fetchers (kafka.consumer.ConsumerFetcherManager:68)

[2015-03-05 16:12:29,088] INFO [ConsumerFetcherManager-1425600748841] All connections stopped (kafka.consumer.ConsumerFetcherManager:68)

[2015-03-05 16:12:29,088] INFO [ConsumerFetcherManager-1425600748841] All connections stopped (kafka.consumer.ConsumerFetcherManager:68)

[2015-03-05 16:12:29,089] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Cleared all relevant queues for this fetcher (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,089] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Cleared all relevant queues for this fetcher (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,090] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Cleared the data chunks in all the consumer message iterators (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,090] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Cleared the data chunks in all the consumer message iterators (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,091] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Committing all offsets after clearing the fetcher queues (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,091] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Committing all offsets after clearing the fetcher queues (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,091] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Releasing partition ownership (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,091] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Releasing partition ownership (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,155] INFO Consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 rebalancing the following partitions: ArrayBuffer(0) for topic _schemas with consumers: List(schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581-0) (kafka.consumer.RangeAssignor:68)

[2015-03-05 16:12:29,155] INFO Consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 rebalancing the following partitions: ArrayBuffer(0) for topic _schemas with consumers: List(schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581-0) (kafka.consumer.RangeAssignor:68)

[2015-03-05 16:12:29,157] INFO schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581-0 attempting to claim partition 0 (kafka.consumer.RangeAssignor:68)

[2015-03-05 16:12:29,157] INFO schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581-0 attempting to claim partition 0 (kafka.consumer.RangeAssignor:68)

[2015-03-05 16:12:29,179] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581-0 successfully owned partition 0 for topic _schemas (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,179] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581-0 successfully owned partition 0 for topic _schemas (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,206] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 selected partitions : _schemas:0: fetched offset = -1: consumed offset = -1 (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,206] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], Consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 selected partitions : _schemas:0: fetched offset = -1: consumed offset = -1 (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,207] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581-leader-finder-thread], Starting  (kafka.consumer.ConsumerFetcherManager$LeaderFinderThread:68)

[2015-03-05 16:12:29,207] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581-leader-finder-thread], Starting  (kafka.consumer.ConsumerFetcherManager$LeaderFinderThread:68)

[2015-03-05 16:12:29,208] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], end rebalancing consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 try #0 (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,208] INFO [schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581], end rebalancing consumer schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581 try #0 (kafka.consumer.ZookeeperConsumerConnector:68)

[2015-03-05 16:12:29,231] INFO Verifying properties (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:29,231] INFO Verifying properties (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:29,231] INFO Property client.id is overridden to KafkaStore-reader-_schemas (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:29,231] INFO Property client.id is overridden to KafkaStore-reader-_schemas (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:29,232] INFO Property metadata.broker.list is overridden to thedude-2:9092 (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:29,232] INFO Property metadata.broker.list is overridden to thedude-2:9092 (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:29,232] INFO Property request.timeout.ms is overridden to 30000 (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:29,232] INFO Property request.timeout.ms is overridden to 30000 (kafka.utils.VerifiableProperties:68)

[2015-03-05 16:12:29,243] WARN The replication factor of the schema topic _schemas is less than the desired one of 3. If this is a production environment, it's crucial to add more brokers and increase the replication factor of the topic. (io.confluent.kafka.schemaregistry.storage.KafkaStore:201)

[2015-03-05 16:12:29,247] INFO Fetching metadata from broker id:0,host:thedude-2,port:9092 with correlation id 0 for 1 topic(s) Set(_schemas) (kafka.client.ClientUtils$:68)

[2015-03-05 16:12:29,247] INFO Fetching metadata from broker id:0,host:thedude-2,port:9092 with correlation id 0 for 1 topic(s) Set(_schemas) (kafka.client.ClientUtils$:68)

[2015-03-05 16:12:29,249] INFO Connected to thedude-2:9092 for producing (kafka.producer.SyncProducer:68)

[2015-03-05 16:12:29,249] INFO Connected to thedude-2:9092 for producing (kafka.producer.SyncProducer:68)

[2015-03-05 16:12:29,260] INFO ProducerConfig values: 

value.serializer = class org.apache.kafka.common.serialization.ByteArraySerializer

key.serializer = class org.apache.kafka.common.serialization.ByteArraySerializer

block.on.buffer.full = true

retry.backoff.ms = 100

buffer.memory = 33554432

batch.size = 16384

metrics.sample.window.ms = 30000

metadata.max.age.ms = 300000

receive.buffer.bytes = 32768

timeout.ms = 30000

max.in.flight.requests.per.connection = 5

bootstrap.servers = [thedude-2:9092]

metric.reporters = []

client.id

compression.type = none

retries = 0

max.request.size = 1048576

send.buffer.bytes = 131072

acks = -1

reconnect.backoff.ms = 10

linger.ms = 0

metrics.num.samples = 2

metadata.fetch.timeout.ms = 60000

 (org.apache.kafka.clients.producer.ProducerConfig:113)

[2015-03-05 16:12:29,260] INFO ProducerConfig values: 

value.serializer = class org.apache.kafka.common.serialization.ByteArraySerializer

key.serializer = class org.apache.kafka.common.serialization.ByteArraySerializer

block.on.buffer.full = true

retry.backoff.ms = 100

buffer.memory = 33554432

batch.size = 16384

metrics.sample.window.ms = 30000

metadata.max.age.ms = 300000

receive.buffer.bytes = 32768

timeout.ms = 30000

max.in.flight.requests.per.connection = 5

bootstrap.servers = [thedude-2:9092]

metric.reporters = []

client.id

compression.type = none

retries = 0

max.request.size = 1048576

send.buffer.bytes = 131072

acks = -1

reconnect.backoff.ms = 10

linger.ms = 0

metrics.num.samples = 2

metadata.fetch.timeout.ms = 60000

 (org.apache.kafka.clients.producer.ProducerConfig:113)

[2015-03-05 16:12:29,267] INFO Disconnecting from thedude-2:9092 (kafka.producer.SyncProducer:68)

[2015-03-05 16:12:29,267] INFO Disconnecting from thedude-2:9092 (kafka.producer.SyncProducer:68)

[2015-03-05 16:12:29,282] INFO [ConsumerFetcherThread-schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581-0-0], Starting  (kafka.consumer.ConsumerFetcherThread:68)

[2015-03-05 16:12:29,282] INFO [ConsumerFetcherThread-schema-registry-thedude-2-8081_thedude-2-1425600748822-cee59581-0-0], Starting  (kafka.consumer.ConsumerFetcherThread:68)

[2015-03-05 16:12:29,286] INFO [kafka-store-reader-thread-_schemas], Starting  (io.confluent.kafka.schemaregistry.storage.KafkaStoreReaderThread:68)

[2015-03-05 16:12:29,294] INFO [ConsumerFetcherManager-1425600748841] Added fetcher for partitions ArrayBuffer([[_schemas,0], initOffset -1 to broker id:0,host:thedude-2,port:9092] ) (kafka.consumer.ConsumerFetcherManager:68)

[2015-03-05 16:12:29,294] INFO [ConsumerFetcherManager-1425600748841] Added fetcher for partitions ArrayBuffer([[_schemas,0], initOffset -1 to broker id:0,host:thedude-2,port:9092] ) (kafka.consumer.ConsumerFetcherManager:68)

[2015-03-05 16:12:29,407] INFO Wait to catch up until the offset of the last message at 6 (io.confluent.kafka.schemaregistry.storage.KafkaStore:221)

[2015-03-05 16:12:29,414] INFO Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.I0Itec.zkclient.ZkClient@d35cddb (org.apache.zookeeper.ZooKeeper:373)

[2015-03-05 16:12:29,414] INFO Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.I0Itec.zkclient.ZkClient@d35cddb (org.apache.zookeeper.ZooKeeper:373)

[2015-03-05 16:12:29,414] INFO Starting ZkClient event thread. (org.I0Itec.zkclient.ZkEventThread:64)

[2015-03-05 16:12:29,414] INFO Starting ZkClient event thread. (org.I0Itec.zkclient.ZkEventThread:64)

[2015-03-05 16:12:29,414] INFO Opening socket connection to server localhost/127.0.0.1:2181 (org.apache.zookeeper.ClientCnxn:1000)

[2015-03-05 16:12:29,414] INFO Opening socket connection to server localhost/127.0.0.1:2181 (org.apache.zookeeper.ClientCnxn:1000)

[2015-03-05 16:12:29,415] INFO Socket connection established to localhost/127.0.0.1:2181, initiating session (org.apache.zookeeper.ClientCnxn:908)

[2015-03-05 16:12:29,415] INFO Socket connection established to localhost/127.0.0.1:2181, initiating session (org.apache.zookeeper.ClientCnxn:908)

[2015-03-05 16:12:29,418] INFO Session establishment complete on server localhost/127.0.0.1:2181, sessionid = 0x14bec1b5423002d, negotiated timeout = 30000 (org.apache.zookeeper.ClientCnxn:701)

[2015-03-05 16:12:29,418] INFO Session establishment complete on server localhost/127.0.0.1:2181, sessionid = 0x14bec1b5423002d, negotiated timeout = 30000 (org.apache.zookeeper.ClientCnxn:701)

[2015-03-05 16:12:29,418] INFO zookeeper state changed (SyncConnected) (org.I0Itec.zkclient.ZkClient:449)

[2015-03-05 16:12:29,418] INFO zookeeper state changed (SyncConnected) (org.I0Itec.zkclient.ZkClient:449)

[2015-03-05 16:12:29,419] INFO Created schema registry namespace localhost:2181/schema_registry (io.confluent.kafka.schemaregistry.storage.KafkaSchemaRegistry:194)

[2015-03-05 16:12:29,419] INFO Terminate ZkClient event thread. (org.I0Itec.zkclient.ZkEventThread:82)

[2015-03-05 16:12:29,419] INFO Terminate ZkClient event thread. (org.I0Itec.zkclient.ZkEventThread:82)

[2015-03-05 16:12:29,420] INFO Session: 0x14bec1b5423002d closed (org.apache.zookeeper.ZooKeeper:538)

[2015-03-05 16:12:29,420] INFO Session: 0x14bec1b5423002d closed (org.apache.zookeeper.ZooKeeper:538)

[2015-03-05 16:12:29,420] INFO Initiating client connection, connectString=localhost:2181/schema_registry sessionTimeout=30000 watcher=org.I0Itec.zkclient.ZkClient@b11ae02 (org.apache.zookeeper.ZooKeeper:373)

[2015-03-05 16:12:29,420] INFO Initiating client connection, connectString=localhost:2181/schema_registry sessionTimeout=30000 watcher=org.I0Itec.zkclient.ZkClient@b11ae02 (org.apache.zookeeper.ZooKeeper:373)

[2015-03-05 16:12:29,420] INFO Starting ZkClient event thread. (org.I0Itec.zkclient.ZkEventThread:64)

[2015-03-05 16:12:29,420] INFO Starting ZkClient event thread. (org.I0Itec.zkclient.ZkEventThread:64)

[2015-03-05 16:12:29,438] INFO Opening socket connection to server localhost/0:0:0:0:0:0:0:1:2181 (org.apache.zookeeper.ClientCnxn:1000)

[2015-03-05 16:12:29,438] INFO Opening socket connection to server localhost/0:0:0:0:0:0:0:1:2181 (org.apache.zookeeper.ClientCnxn:1000)

[2015-03-05 16:12:29,438] INFO Socket connection established to localhost/0:0:0:0:0:0:0:1:2181, initiating session (org.apache.zookeeper.ClientCnxn:908)

[2015-03-05 16:12:29,438] INFO Socket connection established to localhost/0:0:0:0:0:0:0:1:2181, initiating session (org.apache.zookeeper.ClientCnxn:908)

[2015-03-05 16:12:29,439] INFO Session establishment complete on server localhost/0:0:0:0:0:0:0:1:2181, sessionid = 0x14bec1b5423002e, negotiated timeout = 30000 (org.apache.zookeeper.ClientCnxn:701)

[2015-03-05 16:12:29,439] INFO Session establishment complete on server localhost/0:0:0:0:0:0:0:1:2181, sessionid = 0x14bec1b5423002e, negotiated timeout = 30000 (org.apache.zookeeper.ClientCnxn:701)

[2015-03-05 16:12:29,440] INFO zookeeper state changed (SyncConnected) (org.I0Itec.zkclient.ZkClient:449)

[2015-03-05 16:12:29,440] INFO zookeeper state changed (SyncConnected) (org.I0Itec.zkclient.ZkClient:449)

[2015-03-05 16:12:29,448] INFO Successfully elected the new master: {"host":"thedude-2","port":8081,"master_eligibility":true,"version":1} (io.confluent.kafka.schemaregistry.zookeeper.ZookeeperMasterElector:80)

[2015-03-05 16:12:29,451] INFO /schema_registry_master exists with value {"host":"thedude-2","port":8081,"master_eligibility":true,"version":1} during connection loss; this is ok (kafka.utils.ZkUtils$:68)

[2015-03-05 16:12:29,451] INFO /schema_registry_master exists with value {"host":"thedude-2","port":8081,"master_eligibility":true,"version":1} during connection loss; this is ok (kafka.utils.ZkUtils$:68)

[2015-03-05 16:12:29,451] INFO Successfully elected the new master: {"host":"thedude-2","port":8081,"master_eligibility":true,"version":1} (io.confluent.kafka.schemaregistry.zookeeper.ZookeeperMasterElector:80)

[2015-03-05 16:12:29,545] INFO jetty-8.1.16.v20140903 (org.eclipse.jetty.server.Server:272)

Mar 05, 2015 4:12:29 PM org.glassfish.jersey.server.ApplicationHandler initialize

INFO: Initiating Jersey application, version Jersey: 2.6 2014-02-18 21:52:53...

[2015-03-05 16:12:30,220] INFO Started MetricsSelectC...@0.0.0.0:8081 (org.eclipse.jetty.server.AbstractConnector:338)

[2015-03-05 16:12:30,220] INFO Server started, listening for requests... (io.confluent.kafka.schemaregistry.rest.Main:44)



Ewen Cheslack-Postava

unread,
Mar 5, 2015, 10:01:49 PM3/5/15
to Roger Hoover, confluent...@googlegroups.com
Some of the follow up ended up off the list so I just wanted to summarize how this was resolved in case someone else encounters a similar issue.

The problem was that another service was already using the schema registry's default port, 8081, on localhost for IPV4. The schema registry was still able to listen on *:8081, but ended up only listening on IPV6.

The fix was to set port=<new port #> in the schema registry config, then add --property schema.registry.url=http://localhost:<new port #> when running the console Avro producer.

--
Thanks,
Ewen

Roger Hoover

unread,
Mar 5, 2015, 11:00:06 PM3/5/15
to Ewen Cheslack-Postava, confluent...@googlegroups.com
Thanks for summarizing to the list.  Must have hit reply instead of reply all by mistake.

Sent from my iPhone

Sai Krupan

unread,
Apr 5, 2016, 7:06:14 PM4/5/16
to Confluent Platform
I do have similar issue while posting message to topic :

I'm setting local cluster in Ubuntu machine (Zookeeper,Kafka, schema registery servers are working fine)

bin/kafka-avro-console-producer --broker-list localhost:8082 --topic test --property vue.schema='{"type":"record","name":"myrecord","fields":[{"name":"f1","type":"string"}]}'

{"f1": "value1"}
{"f1": "value2"}
{"f1": "value3"} 

getting error 

[2016-04-04 19:41:45,022] ERROR Error when sending message to topic test with key: null, value: 12 bytes with error: Failed to update metadata after 60000 ms. (org.apache.kafka.clients.producer.internals.ErrorLoggingCallback:47)

Roger Hoover/ Ewen  I appreciate your help  !!

Sai Krupan

unread,
Apr 5, 2016, 7:13:31 PM4/5/16
to Confluent Platform


On Thursday, March 5, 2015 at 6:33:07 PM UTC-5, Roger Hoover wrote:
Reply all
Reply to author
Forward
0 new messages