You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@kafka.apache.org by Benjamin Black <b...@b3k.us> on 2013/07/19 07:00:45 UTC
SimpleConsumer metadata request hangs
Using Kafka 0.8 (current as of a few hours ago), I am seeing metadata
requests using SimpleConsumer hang. Log below, and the call never returns
or times out. Broker is working and passing traffic for other clients.
Anyone else seeing this?
> DEBUG [2013-07-19 04:13:34,779] kafka.network.BlockingChannel: Created
socket with SO_TIMEOUT = 5000 (requested 5000), SO_RCVBUF = 65328
(requested 65000), SO_SNDBUF = 81660 (requested -1).
> TRACE [2013-07-19 04:13:34,790] kafka.network.BoundedByteBufferSend: 30
bytes written.
> TRACE [2013-07-19 04:13:37,168] kafka.network.BoundedByteBufferReceive:
98 bytes read.
>
Re: SimpleConsumer metadata request hangs
Posted by Benjamin Black <b...@b3k.us>.
Solution: this is caused by mixing Scala 2.8.0 Kafka with some 2.9.1 client
code. Rebuilding Kafka with 2.9.2 solved the problem.
On Jul 19, 2013 11:30 AM, "Benjamin Black" <b...@b3k.us> wrote:
> Looks fine on the broker. The data is just not being returned from the
> call to SimpleConsumer.
>
> [2013-07-19 11:22:09,426] DEBUG Processor 0 listening to new connection
> from /127.0.0.1:58809 (kafka.network.Processor)
> [2013-07-19 11:22:09,426] DEBUG Processor 1 listening to new connection
> from /127.0.0.1:58810 (kafka.network.Processor)
> [2013-07-19 11:22:09,462] TRACE Processor id 1 selection time = 36 ms
> (kafka.network.Processor)
> [2013-07-19 11:22:09,462] TRACE 26 bytes read from /127.0.0.1:58810(kafka.network.Processor)
> [2013-07-19 11:22:09,463] TRACE Processor id 0 selection time = 37 ms
> (kafka.network.Processor)
> [2013-07-19 11:22:09,464] TRACE 26 bytes read from /127.0.0.1:58809(kafka.network.Processor)
> [2013-07-19 11:22:09,470] TRACE Processor id 1 selection time = 5 ms
> (kafka.network.Processor)
> [2013-07-19 11:22:09,470] TRACE Socket server received response to send,
> registering for write:
> Response(1,Request(1,sun.nio.ch.SelectionKeyImpl@62d9f20a
> ,null,1374258129462,/127.0.0.1:58810
> ),kafka.network.BoundedByteBufferSend@715fcf90) (kafka.network.Processor)
> [2013-07-19 11:22:09,470] TRACE Processor id 1 selection time = 0 ms
> (kafka.network.Processor)
> [2013-07-19 11:22:09,471] TRACE 106 bytes written to /127.0.0.1:58810using key sun.nio.ch.SelectionKeyImpl@62d9f20a(kafka.network.Processor)
> [2013-07-19 11:22:09,471] TRACE Finished writing, registering for read on
> connection /127.0.0.1:58810 (kafka.network.Processor)
> [2013-07-19 11:22:09,474] TRACE Processor id 0 selection time = 1 ms
> (kafka.network.Processor)
> [2013-07-19 11:22:09,476] TRACE Socket server received response to send,
> registering for write:
> Response(0,Request(0,sun.nio.ch.SelectionKeyImpl@5f4b2eb1
> ,null,1374258129464,/127.0.0.1:58809
> ),kafka.network.BoundedByteBufferSend@49343116) (kafka.network.Processor)
> [2013-07-19 11:22:09,477] TRACE Processor id 0 selection time = 0 ms
> (kafka.network.Processor)
> [2013-07-19 11:22:09,477] TRACE 106 bytes written to /127.0.0.1:58809using key sun.nio.ch.SelectionKeyImpl@5f4b2eb1(kafka.network.Processor)
> [2013-07-19 11:22:09,478] TRACE Finished writing, registering for read on
> connection /127.0.0.1:58809 (kafka.network.Processor)
> [2013-07-19 11:22:09,496] TRACE Processor id 0 selection time = 18 ms
> (kafka.network.Processor)
> [2013-07-19 11:22:09,496] TRACE Processor id 1 selection time = 24 ms
> (kafka.network.Processor)
> [2013-07-19 11:22:09,496] INFO Closing socket connection to /127.0.0.1.
> (kafka.network.Processor)
> [2013-07-19 11:22:09,496] DEBUG Closing connection from /127.0.0.1:58809(kafka.network.Processor)
> [2013-07-19 11:22:09,497] INFO Closing socket connection to /127.0.0.1.
> (kafka.network.Processor)
> [2013-07-19 11:22:09,497] DEBUG Closing connection from /127.0.0.1:58810(kafka.network.Processor)
> On Jul 19, 2013 9:40 AM, "Jay Kreps" <ja...@gmail.com> wrote:
>
>> Interesting. Could you try turning on trace level logging on the broker
>> and
>> reproduce? Or, if you have a reproducible test case I can take a look.
>>
>> We haven't hit this yet in our production usage.
>>
>> -Jay
>>
>>
>> On Thu, Jul 18, 2013 at 10:00 PM, Benjamin Black <b...@b3k.us> wrote:
>>
>> > Using Kafka 0.8 (current as of a few hours ago), I am seeing metadata
>> > requests using SimpleConsumer hang. Log below, and the call never
>> returns
>> > or times out. Broker is working and passing traffic for other clients.
>> > Anyone else seeing this?
>> >
>> > > DEBUG [2013-07-19 04:13:34,779] kafka.network.BlockingChannel: Created
>> > socket with SO_TIMEOUT = 5000 (requested 5000), SO_RCVBUF = 65328
>> > (requested 65000), SO_SNDBUF = 81660 (requested -1).
>> > > TRACE [2013-07-19 04:13:34,790] kafka.network.BoundedByteBufferSend:
>> 30
>> > bytes written.
>> > > TRACE [2013-07-19 04:13:37,168]
>> kafka.network.BoundedByteBufferReceive:
>> > 98 bytes read.
>> > >
>> >
>>
>
Re: SimpleConsumer metadata request hangs
Posted by Benjamin Black <b...@b3k.us>.
Looks fine on the broker. The data is just not being returned from the call
to SimpleConsumer.
[2013-07-19 11:22:09,426] DEBUG Processor 0 listening to new connection
from /127.0.0.1:58809 (kafka.network.Processor)
[2013-07-19 11:22:09,426] DEBUG Processor 1 listening to new connection
from /127.0.0.1:58810 (kafka.network.Processor)
[2013-07-19 11:22:09,462] TRACE Processor id 1 selection time = 36 ms
(kafka.network.Processor)
[2013-07-19 11:22:09,462] TRACE 26 bytes read from
/127.0.0.1:58810(kafka.network.Processor)
[2013-07-19 11:22:09,463] TRACE Processor id 0 selection time = 37 ms
(kafka.network.Processor)
[2013-07-19 11:22:09,464] TRACE 26 bytes read from
/127.0.0.1:58809(kafka.network.Processor)
[2013-07-19 11:22:09,470] TRACE Processor id 1 selection time = 5 ms
(kafka.network.Processor)
[2013-07-19 11:22:09,470] TRACE Socket server received response to send,
registering for write:
Response(1,Request(1,sun.nio.ch.SelectionKeyImpl@62d9f20a
,null,1374258129462,/127.0.0.1:58810
),kafka.network.BoundedByteBufferSend@715fcf90) (kafka.network.Processor)
[2013-07-19 11:22:09,470] TRACE Processor id 1 selection time = 0 ms
(kafka.network.Processor)
[2013-07-19 11:22:09,471] TRACE 106 bytes written to /127.0.0.1:58810 using
key sun.nio.ch.SelectionKeyImpl@62d9f20a (kafka.network.Processor)
[2013-07-19 11:22:09,471] TRACE Finished writing, registering for read on
connection /127.0.0.1:58810 (kafka.network.Processor)
[2013-07-19 11:22:09,474] TRACE Processor id 0 selection time = 1 ms
(kafka.network.Processor)
[2013-07-19 11:22:09,476] TRACE Socket server received response to send,
registering for write:
Response(0,Request(0,sun.nio.ch.SelectionKeyImpl@5f4b2eb1
,null,1374258129464,/127.0.0.1:58809
),kafka.network.BoundedByteBufferSend@49343116) (kafka.network.Processor)
[2013-07-19 11:22:09,477] TRACE Processor id 0 selection time = 0 ms
(kafka.network.Processor)
[2013-07-19 11:22:09,477] TRACE 106 bytes written to /127.0.0.1:58809 using
key sun.nio.ch.SelectionKeyImpl@5f4b2eb1 (kafka.network.Processor)
[2013-07-19 11:22:09,478] TRACE Finished writing, registering for read on
connection /127.0.0.1:58809 (kafka.network.Processor)
[2013-07-19 11:22:09,496] TRACE Processor id 0 selection time = 18 ms
(kafka.network.Processor)
[2013-07-19 11:22:09,496] TRACE Processor id 1 selection time = 24 ms
(kafka.network.Processor)
[2013-07-19 11:22:09,496] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)
[2013-07-19 11:22:09,496] DEBUG Closing connection from
/127.0.0.1:58809(kafka.network.Processor)
[2013-07-19 11:22:09,497] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)
[2013-07-19 11:22:09,497] DEBUG Closing connection from
/127.0.0.1:58810(kafka.network.Processor)
On Jul 19, 2013 9:40 AM, "Jay Kreps" <ja...@gmail.com> wrote:
> Interesting. Could you try turning on trace level logging on the broker and
> reproduce? Or, if you have a reproducible test case I can take a look.
>
> We haven't hit this yet in our production usage.
>
> -Jay
>
>
> On Thu, Jul 18, 2013 at 10:00 PM, Benjamin Black <b...@b3k.us> wrote:
>
> > Using Kafka 0.8 (current as of a few hours ago), I am seeing metadata
> > requests using SimpleConsumer hang. Log below, and the call never returns
> > or times out. Broker is working and passing traffic for other clients.
> > Anyone else seeing this?
> >
> > > DEBUG [2013-07-19 04:13:34,779] kafka.network.BlockingChannel: Created
> > socket with SO_TIMEOUT = 5000 (requested 5000), SO_RCVBUF = 65328
> > (requested 65000), SO_SNDBUF = 81660 (requested -1).
> > > TRACE [2013-07-19 04:13:34,790] kafka.network.BoundedByteBufferSend: 30
> > bytes written.
> > > TRACE [2013-07-19 04:13:37,168] kafka.network.BoundedByteBufferReceive:
> > 98 bytes read.
> > >
> >
>
Re: SimpleConsumer metadata request hangs
Posted by Jay Kreps <ja...@gmail.com>.
Interesting. Could you try turning on trace level logging on the broker and
reproduce? Or, if you have a reproducible test case I can take a look.
We haven't hit this yet in our production usage.
-Jay
On Thu, Jul 18, 2013 at 10:00 PM, Benjamin Black <b...@b3k.us> wrote:
> Using Kafka 0.8 (current as of a few hours ago), I am seeing metadata
> requests using SimpleConsumer hang. Log below, and the call never returns
> or times out. Broker is working and passing traffic for other clients.
> Anyone else seeing this?
>
> > DEBUG [2013-07-19 04:13:34,779] kafka.network.BlockingChannel: Created
> socket with SO_TIMEOUT = 5000 (requested 5000), SO_RCVBUF = 65328
> (requested 65000), SO_SNDBUF = 81660 (requested -1).
> > TRACE [2013-07-19 04:13:34,790] kafka.network.BoundedByteBufferSend: 30
> bytes written.
> > TRACE [2013-07-19 04:13:37,168] kafka.network.BoundedByteBufferReceive:
> 98 bytes read.
> >
>