cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Tim Snyder" <...@proinnovations.com>
Subject RE: Trying to find the problem with a broken pipe
Date Thu, 04 Aug 2011 13:05:59 GMT
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

Tim

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

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

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?


 
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.


So far it's still a mystery.





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:
 
> The link (which I may be misreading)
 > is
http://groups.google.com/group/hector-users/browse_thread/thread/8d7004b6f85a0f2e
 
 
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
client:
 > 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 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>
 > 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
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>
 >
 > 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 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:
 >
<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
 >
<ConcurrentCassandraClientPoolByHost>:{cassandradevrk2(10.130.202.35):9393}
 > 2011-08-02 08:43:06,559 ERROR
 > [me.prettyprint.cassandra.connection.ConcurrentHClientPool] -
Shutdown
 > complete on
 >
<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
 
 

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, 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
 
 
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
with
 >> > the
 >> > amount of data we are trying to store, although I'm certain our
datasets
 >> > 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         DC          Rack        Status State   Load
 >> >  Owns
 >> >    Token
 >> >
 >> >   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
 >> >
 >> > 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
 >> >       at
 >> >
 >> >
org.apache.thrift.transport.TIOStreamTransport.write(TIOStreamTransport.java:147)
 >> >       at
 >> >
 >> >
org.apache.thrift.transport.TFramedTransport.flush(TFramedTransport.java:156)
 >> >       at
 >> >
 >> >
me.prettyprint.cassandra.connection.HThriftClient.close(HThriftClient.java:85)
 >> >       at
 >> >
 >> >
me.prettyprint.cassandra.connection.HConnectionManager.operateWithFailover(HConnectionManager.java:232)
 >> >       at
 >> >
 >> >
me.prettyprint.cassandra.service.KeyspaceServiceImpl.operateWithFailover(KeyspaceServiceImpl.java:131)
 >> >       at
 >> >
 >> >
me.prettyprint.cassandra.service.KeyspaceServiceImpl.getSlice(KeyspaceServiceImpl.java:289)
 >> >       at
 >> >
 >> >
me.prettyprint.cassandra.model.thrift.ThriftSliceQuery$1.doInKeyspace(ThriftSliceQuery.java:53)
 >> >       at
 >> >
 >> >
me.prettyprint.cassandra.model.thrift.ThriftSliceQuery$1.doInKeyspace(ThriftSliceQuery.java:49)
 >> >       at
 >> >
 >> >
me.prettyprint.cassandra.model.KeyspaceOperationCallback.doInKeyspaceAndMeasure(KeyspaceOperationCallback.java:20)
 >> >       at
 >> >
 >> >
me.prettyprint.cassandra.model.ExecutingKeyspace.doExecute(ExecutingKeyspace.java:85)
 >> >       at
 >> >
 >> >
me.prettyprint.cassandra.model.thrift.ThriftSliceQuery.execute(ThriftSliceQuery.java:48)
 >> >       at
 >> >
 >> >
com.wsgc.services.registry.persistenceservice.impl.cassandra.strategy.read.StandardFindRegistryPersistenceStrategy.findRegistryByProfileId(StandardFindRegistryPersistenceStrategy.java:237)
 >> >       at
 >> >
 >> >
com.wsgc.services.registry.persistenceservice.impl.cassandra.strategy.read.StandardFindRegistryPersistenceStrategy.execute(StandardFindRegistryPersistenceStrategy.java:277)
 >> >       at
 >> >
 >> >
com.wsgc.services.registry.registryservice.impl.service.StandardRegistryService.getRegistriesByProfileId(StandardRegistryService.java:327)
 >> >       at
 >> >
 >> >
com.wsgc.services.registry.webapp.impl.RegistryServicesController.getRegistriesByProfileId(RegistryServicesController.java:247)
 >> >       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
 >> >       at
 >> >
 >> >
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 >> >       at
 >> >
 >> >
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 >> >       at java.lang.reflect.Method.invoke(Method.java:597)
 >> >       at
 >> >
 >> >
org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:175)
 >> >       at
 >> >
 >> >
org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:421)
 >> >       at
 >> >
 >> >
org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:409)
 >> >       at
 >> >
 >> >
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:774)
 >> >       at
 >> >
 >> >
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:719)
 >> >       at
 >> >
 >> >
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:644)
 >> >       at
 >> >
 >> >
org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:549)
 >> >       at
javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
 >> >       at
javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
 >> >       at
 >> >
 >> >
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
 >> >       at
 >> >
 >> >
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
 >> >       at
 >> >
 >> >
org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77)
 >> >       at
 >> >
 >> >
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
 >> >       at
 >> >
 >> >
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
 >> >       at
 >> >
 >> >
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
 >> >       at
 >> >
 >> >
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
 >> >       at
 >> >
 >> >
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
 >> >       at
 >> >
 >> >
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:563)
 >> >       at
 >> >
 >> >
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
 >> >       at
 >> >
 >> >
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
 >> >       at
 >> >
 >> >
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
 >> >       at
 >> >
 >> >
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
 >> >       at
 >> >
org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190)
 >> >       at
 >> >
org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:291)
 >> >       at
 >> > org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:774)
 >> >       at
 >> >
 >> >
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:703)
 >> >       at
 >> >
 >> >
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:896)
 >> >       at
 >> >
 >> >
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690)
 >> >       at java.lang.Thread.run(Thread.java:662)
 >> > Caused by: java.net.SocketException: Broken pipe
 >> >       at java.net.SocketOutputStream.socketWrite0(Native Method)
 >> >       at
 >> >
java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
 >> >       at
java.net.SocketOutputStream.write(SocketOutputStream.java:136)
 >> >       at
 >> >
 >> >
org.apache.thrift.transport.TIOStreamTransport.write(TIOStreamTransport.java: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:
 >> >
 >> >
<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>
 >> >
 >
 >


Mime
View raw message