Mailing-List: contact user-help@cassandra.apache.org; run by ezmlm
Precedence: bulk
Reply-To: user@cassandra.apache.org
Received-SPF: neutral (nike.apache.org: local policy)
MIME-Version: 1.0
In-Reply-To: 
 <CAFk=5qCQHdV24n5b36xS__u8BdN2GM7dsEL7FRM6x0v8A6uAkw@mail.gmail.com>
References: 
 <CAFk=5qBqiLErSyLNKwR3wtdRazQCGs9bDcctwwmdw6Mid0-x8g@mail.gmail.com>
	<CAKYY9AKkXE8iiWQ4qDd2MpB1b4D5B29mjO=2BG7qsYHOzrBEFg@mail.gmail.com>
	<CAFk=5qCQHdV24n5b36xS__u8BdN2GM7dsEL7FRM6x0v8A6uAkw@mail.gmail.com>
Date: Tue, 2 Aug 2011 20:25:14 +0000
Message-ID: 
 <CAKYY9AJ2_TeywpcxvEojUHMfivpgWL3gEqYiMjLmSt0jZSLbXg@mail.gmail.com>
Subject: Re: Trying to find the problem with a broken pipe
From: Jim Ancona <jim@anconafamily.com>
To: user@cassandra.apache.org
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable

On Tue, Aug 2, 2011 at 6:13 PM, Anthony Ikeda
<anthony.ikeda.dev@gmail.com> wrote:
> The link (which I may be misreading)
> is=A0http://groups.google.com/group/hector-users/browse_thread/thread/8d7=
004b6f85a0f2e

I hadn't found that one, but I doubt that our issue is related to that.

> 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:
>
> 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 clie=
nt:
> CassandraClient<cassandradevrk1:9393-33>
> org.apache.thrift.transport.TTransportException: java.net.SocketException=
:
> Broken pipe
>
> ...
> 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,543 ERROR
> [me.prettyprint.cassandra.connection.HConnectionManager] - MARK HOST AS D=
OWN
> 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:
> <ConcurrentCassandraClientPoolByHost>:{cassandradevrk1(10.130.202.34):939=
3};
> 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
> <ConcurrentCassandraClientPoolByHost>:{cassandradevrk1(10.130.202.34):939=
3}
> 2011-08-02 08:43:06,544 ERROR
> [me.prettyprint.cassandra.connection.ConcurrentHClientPool] - Shutdown
> complete on
> <ConcurrentCassandraClientPoolByHost>:{cassandradevrk1(10.130.202.34):939=
3}
> 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
>
>
> Then it appears to try the second node and fails:
>
> 2011-08-02 08:43:06,556 INFO
> [me.prettyprint.cassandra.connection.HConnectionManager] - Client
> CassandraClient<cassandradevrk1:9393-33> released to inactive or dead poo=
l.
> 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 clie=
nt:
> CassandraClient<cassandradevrk2:9393-49>
>
> org.apache.thrift.transport.TTransportException: java.net.SocketException=
:
> Broken pipe
>
> 2011-08-02 08:43:06,558 ERROR
> [me.prettyprint.cassandra.connection.HConnectionManager] - MARK HOST AS D=
OWN
> 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:
> <ConcurrentCassandraClientPoolByHost>:{cassandradevrk2(10.130.202.35):939=
3};
> 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
> <ConcurrentCassandraClientPoolByHost>:{cassandradevrk2(10.130.202.35):939=
3}
> 2011-08-02 08:43:06,559 ERROR
> [me.prettyprint.cassandra.connection.ConcurrentHClientPool] - Shutdown
> complete on
> <ConcurrentCassandraClientPoolByHost>:{cassandradevrk2(10.130.202.35):939=
3}
> 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

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"?

Does your client recover after a period of time?

>
> The process is the same at 10:21.
> Are the exceptions related to any external events (e.g. node
> restarts,=A0network 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 file=
s
> have no errors reported.
> What versions of Hector and Cassandra are you running?
> Cassandra 0.8.1, Hector 0.8.0-1

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.

Jim


>
>
>
> On Tue, Aug 2, 2011 at 10:37 AM, Jim Ancona <jim@anconafamily.com> wrote:
>>
>> 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 wit=
h
>> > the
>> > amount of data we are trying to store, although I'm certain our datase=
ts
>> > are
>> > not all that large.
>>
>> 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?
>>
>> > A nodetool ring command doesn't seem to present any downed nodes:
>> > Address =A0 =A0 =A0 =A0 DC =A0 =A0 =A0 =A0 =A0Rack =A0 =A0 =A0 =A0Stat=
us State =A0 Load
>> > =A0Owns
>> > =A0 =A0Token
>> >
>> > =A0 153951716904446304929228999025275230571
>> > 10.130.202.34 =A0 datacenter1 rack1 =A0 =A0 =A0 Up =A0 =A0 Normal =A04=
70.74 KB
>> > 79.19% =A0118538200848404459763384037192174096102
>> > 10.130.202.35 =A0 datacenter1 rack1 =A0 =A0 =A0 Up =A0 =A0 Normal =A04=
83.63 KB
>> > 20.81% =A0153951716904446304929228999025275230571
>> >
>> > There are no errors in the cassandra server logs.
>> >
>> > 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?
>>
>> 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.
>>
>> 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?
>>
>> 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.
>>
>> 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.
>>
>> Jim
>>
>> > Anthony
>> >
>> > 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
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.thrift.transport.TIOStreamTransport.write(TIOStreamTranspor=
t.java:147)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.thrift.transport.TFramedTransport.flush(TFramedTransport.ja=
va:156)
>> > =A0 =A0 =A0 at
>> >
>> > me.prettyprint.cassandra.connection.HThriftClient.close(HThriftClient.=
java:85)
>> > =A0 =A0 =A0 at
>> >
>> > me.prettyprint.cassandra.connection.HConnectionManager.operateWithFail=
over(HConnectionManager.java:232)
>> > =A0 =A0 =A0 at
>> >
>> > me.prettyprint.cassandra.service.KeyspaceServiceImpl.operateWithFailov=
er(KeyspaceServiceImpl.java:131)
>> > =A0 =A0 =A0 at
>> >
>> > me.prettyprint.cassandra.service.KeyspaceServiceImpl.getSlice(Keyspace=
ServiceImpl.java:289)
>> > =A0 =A0 =A0 at
>> >
>> > me.prettyprint.cassandra.model.thrift.ThriftSliceQuery$1.doInKeyspace(=
ThriftSliceQuery.java:53)
>> > =A0 =A0 =A0 at
>> >
>> > me.prettyprint.cassandra.model.thrift.ThriftSliceQuery$1.doInKeyspace(=
ThriftSliceQuery.java:49)
>> > =A0 =A0 =A0 at
>> >
>> > me.prettyprint.cassandra.model.KeyspaceOperationCallback.doInKeyspaceA=
ndMeasure(KeyspaceOperationCallback.java:20)
>> > =A0 =A0 =A0 at
>> >
>> > me.prettyprint.cassandra.model.ExecutingKeyspace.doExecute(ExecutingKe=
yspace.java:85)
>> > =A0 =A0 =A0 at
>> >
>> > me.prettyprint.cassandra.model.thrift.ThriftSliceQuery.execute(ThriftS=
liceQuery.java:48)
>> > =A0 =A0 =A0 at
>> >
>> > com.wsgc.services.registry.persistenceservice.impl.cassandra.strategy.=
read.StandardFindRegistryPersistenceStrategy.findRegistryByProfileId(Standa=
rdFindRegistryPersistenceStrategy.java:237)
>> > =A0 =A0 =A0 at
>> >
>> > com.wsgc.services.registry.persistenceservice.impl.cassandra.strategy.=
read.StandardFindRegistryPersistenceStrategy.execute(StandardFindRegistryPe=
rsistenceStrategy.java:277)
>> > =A0 =A0 =A0 at
>> >
>> > com.wsgc.services.registry.registryservice.impl.service.StandardRegist=
ryService.getRegistriesByProfileId(StandardRegistryService.java:327)
>> > =A0 =A0 =A0 at
>> >
>> > com.wsgc.services.registry.webapp.impl.RegistryServicesController.getR=
egistriesByProfileId(RegistryServicesController.java:247)
>> > =A0 =A0 =A0 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Met=
hod)
>> > =A0 =A0 =A0 at
>> >
>> > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.j=
ava:39)
>> > =A0 =A0 =A0 at
>> >
>> > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccess=
orImpl.java:25)
>> > =A0 =A0 =A0 at java.lang.reflect.Method.invoke(Method.java:597)
>> > =A0 =A0 =A0 at
>> >
>> > org.springframework.web.bind.annotation.support.HandlerMethodInvoker.i=
nvokeHandlerMethod(HandlerMethodInvoker.java:175)
>> > =A0 =A0 =A0 at
>> >
>> > org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandler=
Adapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:421)
>> > =A0 =A0 =A0 at
>> >
>> > org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandler=
Adapter.handle(AnnotationMethodHandlerAdapter.java:409)
>> > =A0 =A0 =A0 at
>> >
>> > org.springframework.web.servlet.DispatcherServlet.doDispatch(Dispatche=
rServlet.java:774)
>> > =A0 =A0 =A0 at
>> >
>> > org.springframework.web.servlet.DispatcherServlet.doService(Dispatcher=
Servlet.java:719)
>> > =A0 =A0 =A0 at
>> >
>> > org.springframework.web.servlet.FrameworkServlet.processRequest(Framew=
orkServlet.java:644)
>> > =A0 =A0 =A0 at
>> >
>> > org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServle=
t.java:549)
>> > =A0 =A0 =A0 at javax.servlet.http.HttpServlet.service(HttpServlet.java=
:617)
>> > =A0 =A0 =A0 at javax.servlet.http.HttpServlet.service(HttpServlet.java=
:717)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appli=
cationFilterChain.java:290)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFi=
lterChain.java:206)
>> > =A0 =A0 =A0 at
>> >
>> > org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal=
(HiddenHttpMethodFilter.java:77)
>> > =A0 =A0 =A0 at
>> >
>> > org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRe=
questFilter.java:76)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appli=
cationFilterChain.java:235)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFi=
lterChain.java:206)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperVa=
lve.java:233)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.core.StandardContextValve.invoke(StandardContextVa=
lve.java:191)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.authenticator.AuthenticatorBase.invoke(Authenticat=
orBase.java:563)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.ja=
va:127)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.ja=
va:102)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValv=
e.java:109)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java=
:298)
>> > =A0 =A0 =A0 at
>> > org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190)
>> > =A0 =A0 =A0 at
>> > org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:291)
>> > =A0 =A0 =A0 at
>> > org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:774)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.jav=
a:703)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocke=
t.java:896)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPo=
ol.java:690)
>> > =A0 =A0 =A0 at java.lang.Thread.run(Thread.java:662)
>> > Caused by: java.net.SocketException: Broken pipe
>> > =A0 =A0 =A0 at java.net.SocketOutputStream.socketWrite0(Native Method)
>> > =A0 =A0 =A0 at
>> > java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
>> > =A0 =A0 =A0 at java.net.SocketOutputStream.write(SocketOutputStream.ja=
va:136)
>> > =A0 =A0 =A0 at
>> >
>> > org.apache.thrift.transport.TIOStreamTransport.write(TIOStreamTranspor=
t.java:145)
>> > =A0 =A0 =A0 ... 47 more
>> > 2011-08-02 08:43:06,543 ERROR
>> > [me.prettyprint.cassandra.connection.HConnectionManager] - MARK HOST A=
S
>> > 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:
>> >
>> > <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
>> >
>> > <ConcurrentCassandraClientPoolByHost>:{cassandradevrk1(10.130.202.34):=
9393}
>> > 2011-08-02 08:43:06,544 ERROR
>> > [me.prettyprint.cassandra.connection.ConcurrentHClientPool] - Shutdown
>> > complete on
>> >
>> > <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>
>> >
>
>