Mailing-List: contact user-help@cassandra.apache.org; run by ezmlm
Precedence: bulk
Reply-To: user@cassandra.apache.org
Received-SPF: pass (nike.apache.org: local policy)
DomainKey-Signature: a=rsa-sha1; c=nofws; d=thelastpickle.com; h=content-type
	:mime-version:subject:from:in-reply-to:date
	:content-transfer-encoding:message-id:references:to; q=dns; s=
	thelastpickle.com; b=LwimL2Q342jJC0Pkp/WE9fIx9JvktHTCZeLDfUfXETY
	Rjgovzx2J0ivBXeKejm0No0XIEXH30Ilxbw5gxKoy58ENAjss/la/qPyvxVYVYTN
	mhA71yQw3J7UTnDyMshuBPrkrcNTuig7P4i03r8AGYClkDDM17MLzLIlz8KQwtIk
	=
Content-Type: text/plain; charset=us-ascii
Mime-Version: 1.0 (Apple Message framework v1244.3)
Subject: Re: Trying to find the problem with a broken pipe
From: aaron morton <aaron@thelastpickle.com>
In-Reply-To: 
 <20110804060559.050558854cd8e3604bbb7dcb1d74d208.9ced5c3d31.wbe@email13.secureserver.net>
Date: Fri, 5 Aug 2011 08:58:06 +1000
Content-Transfer-Encoding: quoted-printable
Message-Id: <99C0CBAC-B07C-4BB2-BA08-BA4CA190BA2B@thelastpickle.com>
References: 
 <20110804060559.050558854cd8e3604bbb7dcb1d74d208.9ced5c3d31.wbe@email13.secureserver.net>
To: user@cassandra.apache.org

It's probably a network thing.=20

The only thing I can think of in cassandra is =
thrift_max_message_length_in_mb in the config. That config setting will =
result in a TException thrown on the server side (i think), not sure if =
that makes the server kill the socket. I would hope the error returns to =
the client.=20

Perhaps check the server log.=20

Cheers
=20
-----------------
Aaron Morton
Freelance Cassandra Developer
@aaronmorton
http://www.thelastpickle.com

On 4 Aug 2011, at 23:05, Tim Snyder wrote:

> I am getting the same problem (Broken Pipe) on a loader program, after
> about 8 million read, write pairs. I am pushing serialized objects =
into
> a column with the program, the object it seems to be doing it on is =
much
> larger than the prior objects, so I am wondering if it is possibly a
> column size streaming issue through the thrift api? I am using =
Cassandra
> 0.8.0 and Hector 0.8.0-1
>=20
> Tim
>=20
> -------- Original Message --------
> Subject: Re: Trying to find the problem with a broken pipe
> From: Anthony Ikeda <anthony.ikeda.dev@gmail.com>
> Date: Tue, August 02, 2011 10:43 pm
> To: user@cassandra.apache.org
>=20
>> Very interesting. After the second host goes down do you see
>> "me.prettyprint.hector.api.exceptions.HectorException: All host pools
>> marked down. Retry burden pushed out to client"?
>=20
> No, the last message is:
> 2011-08-02 08:43:06,561 INFO
> [me.prettyprint.cassandra.connection.HConnectionManager] - Client
> CassandraClient<cassandradevrk2:9393-49> released to inactive or dead
> pool. Closing.> Does your client recover after a period of time?
>=20
>=20
>=20
> The application seems to be fine for now but my concern is the
> connection pooling as well - I mean do we have one pool or multiple?
> I'll post to the Hector user group about the pooling because the
> incident seems so isolated. We also have our infrastructure team =
looking
> into the communication between the application server and the =
cassandra
> nodes.
>=20
>=20
> So far it's still a mystery.
>=20
>=20
>=20
>=20
>=20
> On Tue, Aug 2, 2011 at 1:25 PM, Jim Ancona <jim@anconafamily.com> =
wrote:
> On Tue, Aug 2, 2011 at 6:13 PM, Anthony Ikeda
> <anthony.ikeda.dev@gmail.com> wrote:
>=20
>> The link (which I may be misreading)
>> is
> =
http://groups.google.com/group/hector-users/browse_thread/thread/8d7004b6f=
85a0f2e
>=20
>=20
> I hadn't found that one, but I doubt that our issue is related to =
that.
>=20
>=20
>> It's only started happening today and happened on 2 occassions (8:43
> and
>> 10:21) performing the same function (querying a column family).
>> It seems to be trying to access a connection on one of the servers
>> The client accesses the first node:
>>=20
>> 2011-08-02 08:43:06,541 ERROR
>> [me.prettyprint.cassandra.connection.HThriftClient] - Could not flush
>> transport (to be expected if the pool is shutting down) in close for
> client:
>> CassandraClient<cassandradevrk1:9393-33>
>> org.apache.thrift.transport.TTransportException:
> java.net.SocketException:
>> Broken pipe
>>=20
>> ...
>> 2011-08-02 08:43:06,544 WARN
>> [me.prettyprint.cassandra.connection.HConnectionManager] - Could not
>> fullfill request on this host
> CassandraClient<cassandradevrk1:9393-33>
>>=20
>> ...
>>=20
>> 2011-08-02 08:43:06,543 ERROR
>> [me.prettyprint.cassandra.connection.HConnectionManager] - MARK HOST
> AS DOWN
>> TRIGGERED for host cassandradevrk1(10.130.202.34):9393
>> 2011-08-02 08:43:06,543 ERROR
>> [me.prettyprint.cassandra.connection.HConnectionManager] - Pool state
> on
>> shutdown:
>>=20
> =
<ConcurrentCassandraClientPoolByHost>:{cassandradevrk1(10.130.202.34):9393=
};
>> IsActive?: true; Active: 1; Blocked: 0; Idle: 15; NumBeforeExhausted:
> 49
>> 2011-08-02 08:43:06,543 ERROR
>> [me.prettyprint.cassandra.connection.ConcurrentHClientPool] -
> Shutdown
>> triggered on
>>=20
> =
<ConcurrentCassandraClientPoolByHost>:{cassandradevrk1(10.130.202.34):9393=
}
>> 2011-08-02 08:43:06,544 ERROR
>> [me.prettyprint.cassandra.connection.ConcurrentHClientPool] -
> Shutdown
>> complete on
>>=20
> =
<ConcurrentCassandraClientPoolByHost>:{cassandradevrk1(10.130.202.34):9393=
}
>> 2011-08-02 08:43:06,544 INFO
>> [me.prettyprint.cassandra.connection.CassandraHostRetryService] -
> Host
>> detected as down was added to retry queue:
>> cassandradevrk1(10.130.202.34):9393
>> 2011-08-02 08:43:06,544 WARN
>> [me.prettyprint.cassandra.connection.HConnectionManager] - Could not
>> fullfill request on this host CassandraClient<
>> cassandradevrk1:9393-33>
>> 2011-08-02 08:43:06,544 WARN
>> [me.prettyprint.cassandra.connection.HConnectionManager] - Exception:
>> me.prettyprint.hector.api.exceptions.HectorTransportException:
>> org.apache.thrift.transport.TTransportException:
> java.net.SocketException:
>> Connection reset
>>=20
>>=20
>> Then it appears to try the second node and fails:
>>=20
>> 2011-08-02 08:43:06,556 INFO
>> [me.prettyprint.cassandra.connection.HConnectionManager] - Client
>> CassandraClient<cassandradevrk1:9393-33> released to inactive or dead
> pool.
>> Closing.
>> 2011-08-02 08:43:06,557 ERROR
>> [me.prettyprint.cassandra.connection.HThriftClient] - Could not flush
>> transport (to be expected if the pool is shutting down) in close for
> client:
>> CassandraClient<cassandradevrk2:9393-49>
>>=20
>> org.apache.thrift.transport.TTransportException:
> java.net.SocketException:
>> Broken pipe
>>=20
>> 2011-08-02 08:43:06,558 ERROR
>> [me.prettyprint.cassandra.connection.HConnectionManager] - MARK HOST
> AS DOWN
>> TRIGGERED for host cassandradevrk2(10.130.202.35):9393
>> 2011-08-02 08:43:06,559 ERROR
>> [me.prettyprint.cassandra.connection.HConnectionManager] - Pool state
> on
>> shutdown:
>>=20
> =
<ConcurrentCassandraClientPoolByHost>:{cassandradevrk2(10.130.202.35):9393=
};
>> IsActive?: true; Active: 1; Blocked: 0; Idle: 15; NumBeforeExhausted:
> 49
>> 2011-08-02 08:43:06,559 ERROR
>> [me.prettyprint.cassandra.connection.ConcurrentHClientPool] -
> Shutdown
>> triggered on
>>=20
> =
<ConcurrentCassandraClientPoolByHost>:{cassandradevrk2(10.130.202.35):9393=
}
>> 2011-08-02 08:43:06,559 ERROR
>> [me.prettyprint.cassandra.connection.ConcurrentHClientPool] -
> Shutdown
>> complete on
>>=20
> =
<ConcurrentCassandraClientPoolByHost>:{cassandradevrk2(10.130.202.35):9393=
}
>> 2011-08-02 08:43:06,559 INFO
>> [me.prettyprint.cassandra.connection.CassandraHostRetryService] -
> Host
>> detected as down was added to retry queue:
>> cassandradevrk2(10.130.202.35):9393
>> 2011-08-02 08:43:06,560 WARN
>> [me.prettyprint.cassandra.connection.HConnectionManager] - Could not
>> fullfill request on this host
> CassandraClient<cassandradevrk2:9393-49>
>> 2011-08-02 08:43:06,560 WARN
>> [me.prettyprint.cassandra.connection.HConnectionManager] - Exception:
>> me.prettyprint.hector.api.exceptions.HectorTransportException:
>> org.apache.thrift.transport.TTransportException:
> java.net.SocketException:
>> Connection reset
>=20
>=20
>=20
> Very interesting. After the second host goes down do you see
> "me.prettyprint.hector.api.exceptions.HectorException: All host pools
> marked down. Retry burden pushed out to client"?
>=20
> Does your client recover after a period of time?
>=20
>>=20
>> The process is the same at 10:21.
>> Are the exceptions related to any external events (e.g. node
>> restarts, network issues...)?
>> Not that I'm aware, unless there are firewall timeouts between the
>> application and the node servers. Let me find out. The cassandra log
> files
>> have no errors reported.
>> What versions of Hector and Cassandra are you running?
>> Cassandra 0.8.1, Hector 0.8.0-1
>=20
>=20
> Our issue is occurring with Cassandra 0.7.8 and Hector 0.7-30. We plan
> to deploy Hector 0.7-31 this week and to turn on useSocketKeepalive.
> Are you using that? We're also using tcpdump to capture packets when
> failures occur to see if there are anomalies in the network traffic.
>=20
> Jim
>=20
>=20
>=20
>>=20
>>=20
>>=20
>> On Tue, Aug 2, 2011 at 10:37 AM, Jim Ancona <jim@anconafamily.com>
> wrote:
>>>=20
>>> On Tue, Aug 2, 2011 at 4:36 PM, Anthony Ikeda
>>> <anthony.ikeda.dev@gmail.com> wrote:
>>>> I'm not sure if this is a problem with Hector or with Cassandra.
>>>> We seem to be seeing broken pipe issues with our connections on
> the
>>>> client
>>>> side (Exception below). A bit of googling finds possibly a problem
> with
>>>> the
>>>> amount of data we are trying to store, although I'm certain our
> datasets
>>>> are
>>>> not all that large.
>>>=20
>>> I'm not sure what you're referring to here. Large requests could
> lead
>>> to timeouts, but that's not what you're seeing here. Could you link
> to
>>> the page you're referencing?
>>>=20
>>>> A nodetool ring command doesn't seem to present any downed nodes:
>>>> Address         DC          Rack        Status State   Load
>>>> Owns
>>>>   Token
>>>>=20
>>>>  153951716904446304929228999025275230571
>>>> 10.130.202.34   datacenter1 rack1       Up     Normal  470.74 KB
>>>> 79.19%  118538200848404459763384037192174096102
>>>> 10.130.202.35   datacenter1 rack1       Up     Normal  483.63 KB
>>>> 20.81%  153951716904446304929228999025275230571
>>>>=20
>>>> There are no errors in the cassandra server logs.
>>>>=20
>>>> Are there any particular timeouts on connections that we need to
> be
>>>> aware
>>>> of? Or perhaps configure on the Cassandra nodes? Is this purely
> and
>>>> issue
>>>> with the Hector API configuration?
>>>=20
>>> There is a server side timeout (rpc_timeout_in_ms in cassandra.yaml)
>>> and a Hector client-side timeout
>>> (CassandraHostConfigurator.cassandraThriftSocketTimeout). But again,
>>> the "Broken pipe" error is not a timeout, it indicates that
> something
>>> happened to the underlying network socket. For example you will see
>>> those when a server node is restarted.
>>>=20
>>> Some questions that might help troubleshoot this:
>>> How often are these occurring?
>>> Does this affect both nodes in the cluster or just one?
>>> Are the exceptions related to any external events (e.g. node
> restarts,
>>> network issues...)?
>>> What versions of Hector and Cassandra are you running?
>>>=20
>>> Keep in mind that failures like this will normally be retried by
>>> Hector, resulting in no loss of data. For that reason, I think that
>>> exception is logged as a warning in the newest Hector versions.
>>>=20
>>> We've seen something similar, but more catastrophic because it
> affects
>>> connectivity to the entire cluster, not just a single node. See this
>>> post for more details: http://goo.gl/hrgkw So far we haven't
>>> identified the cause.
>>>=20
>>> Jim
>>>=20
>>>> Anthony
>>>>=20
>>>> 2011-08-02 08:43:06,541 ERROR
>>>> [me.prettyprint.cassandra.connection.HThriftClient] - Could not
> flush
>>>> transport (to be expected if the pool is shutting down) in close
> for
>>>> client:
>>>> CassandraClient<cassandradevrk1:9393-33>
>>>> org.apache.thrift.transport.TTransportException:
>>>> java.net.SocketException:
>>>> Broken pipe
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.thrift.transport.TIOStreamTransport.write(TIOStreamTransport.ja=
va:147)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.thrift.transport.TFramedTransport.flush(TFramedTransport.java:1=
56)
>>>>      at
>>>>=20
>>>>=20
> =
me.prettyprint.cassandra.connection.HThriftClient.close(HThriftClient.java=
:85)
>>>>      at
>>>>=20
>>>>=20
> =
me.prettyprint.cassandra.connection.HConnectionManager.operateWithFailover=
(HConnectionManager.java:232)
>>>>      at
>>>>=20
>>>>=20
> =
me.prettyprint.cassandra.service.KeyspaceServiceImpl.operateWithFailover(K=
eyspaceServiceImpl.java:131)
>>>>      at
>>>>=20
>>>>=20
> =
me.prettyprint.cassandra.service.KeyspaceServiceImpl.getSlice(KeyspaceServ=
iceImpl.java:289)
>>>>      at
>>>>=20
>>>>=20
> =
me.prettyprint.cassandra.model.thrift.ThriftSliceQuery$1.doInKeyspace(Thri=
ftSliceQuery.java:53)
>>>>      at
>>>>=20
>>>>=20
> =
me.prettyprint.cassandra.model.thrift.ThriftSliceQuery$1.doInKeyspace(Thri=
ftSliceQuery.java:49)
>>>>      at
>>>>=20
>>>>=20
> =
me.prettyprint.cassandra.model.KeyspaceOperationCallback.doInKeyspaceAndMe=
asure(KeyspaceOperationCallback.java:20)
>>>>      at
>>>>=20
>>>>=20
> =
me.prettyprint.cassandra.model.ExecutingKeyspace.doExecute(ExecutingKeyspa=
ce.java:85)
>>>>      at
>>>>=20
>>>>=20
> =
me.prettyprint.cassandra.model.thrift.ThriftSliceQuery.execute(ThriftSlice=
Query.java:48)
>>>>      at
>>>>=20
>>>>=20
> =
com.wsgc.services.registry.persistenceservice.impl.cassandra.strategy.read=
.StandardFindRegistryPersistenceStrategy.findRegistryByProfileId(StandardF=
indRegistryPersistenceStrategy.java:237)
>>>>      at
>>>>=20
>>>>=20
> =
com.wsgc.services.registry.persistenceservice.impl.cassandra.strategy.read=
.StandardFindRegistryPersistenceStrategy.execute(StandardFindRegistryPersi=
stenceStrategy.java:277)
>>>>      at
>>>>=20
>>>>=20
> =
com.wsgc.services.registry.registryservice.impl.service.StandardRegistrySe=
rvice.getRegistriesByProfileId(StandardRegistryService.java:327)
>>>>      at
>>>>=20
>>>>=20
> =
com.wsgc.services.registry.webapp.impl.RegistryServicesController.getRegis=
triesByProfileId(RegistryServicesController.java:247)
>>>>      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method)
>>>>      at
>>>>=20
>>>>=20
> =
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:=
39)
>>>>      at
>>>>=20
>>>>=20
> =
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorIm=
pl.java:25)
>>>>      at java.lang.reflect.Method.invoke(Method.java:597)
>>>>      at
>>>>=20
>>>>=20
> =
org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invok=
eHandlerMethod(HandlerMethodInvoker.java:175)
>>>>      at
>>>>=20
>>>>=20
> =
org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdap=
ter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:421)
>>>>      at
>>>>=20
>>>>=20
> =
org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdap=
ter.handle(AnnotationMethodHandlerAdapter.java:409)
>>>>      at
>>>>=20
>>>>=20
> =
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherSer=
vlet.java:774)
>>>>      at
>>>>=20
>>>>=20
> =
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServ=
let.java:719)
>>>>      at
>>>>=20
>>>>=20
> =
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkS=
ervlet.java:644)
>>>>      at
>>>>=20
>>>>=20
> =
org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.ja=
va:549)
>>>>      at
> javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
>>>>      at
> javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Applicati=
onFilterChain.java:290)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilter=
Chain.java:206)
>>>>      at
>>>>=20
>>>>=20
> =
org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(Hid=
denHttpMethodFilter.java:77)
>>>>      at
>>>>=20
>>>>=20
> =
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerReques=
tFilter.java:76)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Applicati=
onFilterChain.java:235)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilter=
Chain.java:206)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.=
java:233)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.=
java:191)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBa=
se.java:563)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:1=
27)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:1=
02)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.ja=
va:109)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298=
)
>>>>      at
>>>>=20
> org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190)
>>>>      at
>>>>=20
> org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:291)
>>>>      at
>>>> org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:774)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:70=
3)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.ja=
va:896)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.j=
ava:690)
>>>>      at java.lang.Thread.run(Thread.java:662)
>>>> Caused by: java.net.SocketException: Broken pipe
>>>>      at java.net.SocketOutputStream.socketWrite0(Native Method)
>>>>      at
>>>>=20
> java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
>>>>      at
> java.net.SocketOutputStream.write(SocketOutputStream.java:136)
>>>>      at
>>>>=20
>>>>=20
> =
org.apache.thrift.transport.TIOStreamTransport.write(TIOStreamTransport.ja=
va:145)
>>>>      ... 47 more
>>>> 2011-08-02 08:43:06,543 ERROR
>>>> [me.prettyprint.cassandra.connection.HConnectionManager] - MARK
> HOST AS
>>>> DOWN
>>>> TRIGGERED for host cassandradevrk1(10.130.202.34):9393
>>>> 2011-08-02 08:43:06,543 ERROR
>>>> [me.prettyprint.cassandra.connection.HConnectionManager] - Pool
> state on
>>>> shutdown:
>>>>=20
>>>>=20
> =
<ConcurrentCassandraClientPoolByHost>:{cassandradevrk1(10.130.202.34):9393=
};
>>>> IsActive?: true; Active: 1; Blocked: 0; Idle: 15;
> NumBeforeExhausted: 49
>>>> 2011-08-02 08:43:06,543 ERROR
>>>> [me.prettyprint.cassandra.connection.ConcurrentHClientPool] -
> Shutdown
>>>> triggered on
>>>>=20
>>>>=20
> =
<ConcurrentCassandraClientPoolByHost>:{cassandradevrk1(10.130.202.34):9393=
}
>>>> 2011-08-02 08:43:06,544 ERROR
>>>> [me.prettyprint.cassandra.connection.ConcurrentHClientPool] -
> Shutdown
>>>> complete on
>>>>=20
>>>>=20
> =
<ConcurrentCassandraClientPoolByHost>:{cassandradevrk1(10.130.202.34):9393=
}
>>>> 2011-08-02 08:43:06,544 INFO
>>>> [me.prettyprint.cassandra.connection.CassandraHostRetryService] -
> Host
>>>> detected as down was added to retry queue:
>>>> cassandradevrk1(10.130.202.34):9393
>>>> 2011-08-02 08:43:06,544 WARN
>>>> [me.prettyprint.cassandra.connection.HConnectionManager] - Could
> not
>>>> fullfill request on this host
> CassandraClient<cassandradevrk1:9393-33>
>>>>=20
>>=20
>>=20
>=20