Agreed. But those connection errors were happening at a sort of random time. Not the time when I was seeing the problem. Now I am seeing the problem and here are some logs without ConnectionExceptions.
Here we're asking 10.33.2.70 for key: 52e86817a577f75e545cdecd174d8b17 which resides only on 10.33.3.10 and 10.33.3.20. Note all the apparently normal communication. Execept that no mention of a request for key 52e86817a577f75e545cdecd174d8b17 ever comes up in 10.33.3.10's log, despite 10.33.2.70 saying it was reading from 10.33.3.10 The problem resolved itself again at 20:02, maybe 20 minutes later. where all of a sudden I get my columns returned in milliseconds and I see good stuff like: DEBUG 20:06:35,238 Reading consistency digest for 52e86817a577f75e545cdecd174d8b17 from 59...@[/10.33.3.10, /10.33.3.20] Here's some logs from the problem period 10.33.2.70:/var/log/cassandra/output.log DEBUG 19:42:03,230 get_slice DEBUG 19:42:03,231 weakreadremote reading SliceFromReadCommand(table='jolitics.c om', key='52e86817a577f75e545cdecd174d8b17', column_parent='QueryPath(columnFami lyName='Images', superColumnName='null', columnName='null')', start='', finish=' ', reversed=false, count=100) DEBUG 19:42:03,231 weakreadremote reading SliceFromReadCommand(table='jolitics.c om', key='52e86817a577f75e545cdecd174d8b17', column_parent='QueryPath(columnFami lyName='Images', superColumnName='null', columnName='null')', start='', finish=' ', reversed=false, count=100) from 57663@/10.33.3.10 TRACE 19:42:03,619 Gossip Digests are : /10.33.2.70:1276981671:20386 /10.33.3.10 :1276983719:18303 /10.33.3.20:1276983726:18295 /10.33.2.70:1276981671:20386 TRACE 19:42:03,619 Sending a GossipDigestSynMessage to /10.33.3.20 ... TRACE 19:42:03,619 Performing status check ... TRACE 19:42:03,619 PHI for /10.33.3.10 : 0.95343619570936 TRACE 19:42:03,619 PHI for /10.33.3.20 : 0.8635116192106644 TRACE 19:42:03,621 Received a GossipDigestAckMessage from /10.33.3.20 TRACE 19:42:03,621 reporting /10.33.3.10 TRACE 19:42:03,621 reporting /10.33.3.20 TRACE 19:42:03,621 marking as alive /10.33.3.10 TRACE 19:42:03,621 Updating heartbeat state version to 18304 from 18303 for /10. 33.3.10 ... TRACE 19:42:03,621 marking as alive /10.33.3.20 TRACE 19:42:03,621 Updating heartbeat state version to 18296 from 18295 for /10. 33.3.20 ... TRACE 19:42:03,622 Scanning for state greater than 20385 for /10.33.2.70 TRACE 19:42:03,622 Scanning for state greater than 20385 for /10.33.2.70 TRACE 19:42:03,622 Sending a GossipDigestAck2Message to /10.33.3.20 TRACE 19:42:04,172 Received a GossipDigestSynMessage from /10.33.3.10 TRACE 19:42:04,172 reporting /10.33.3.10 TRACE 19:42:04,172 reporting /10.33.3.10 TRACE 19:42:04,172 Scanning for state greater than 20385 for /10.33.2.70 TRACE 19:42:04,172 @@@@ Size of GossipDigestAckMessage is 52 TRACE 19:42:04,172 Sending a GossipDigestAckMessage to /10.33.3.10 TRACE 19:42:04,174 Received a GossipDigestAck2Message from /10.33.3.10 TRACE 19:42:04,174 reporting /10.33.3.10 TRACE 19:42:04,174 marking as alive /10.33.3.10 TRACE 19:42:04,174 Updating heartbeat state version to 18305 from 18304 for /10. 33.3.10 ... 10.33.3.10:/var/log/cassandra/output.log TRACE 19:42:03,174 Sending a GossipDigestSynMessage to /10.33.3.20 ... TRACE 19:42:03,174 Performing status check ... TRACE 19:42:03,174 PHI for /10.33.2.70 : 1.3363463863632534 TRACE 19:42:03,174 PHI for /10.33.3.20 : 0.9297110501502452 TRACE 19:42:03,175 Received a GossipDigestAckMessage from /10.33.3.20 TRACE 19:42:03,176 reporting /10.33.2.70 TRACE 19:42:03,176 marking as alive /10.33.2.70 TRACE 19:42:03,176 Updating heartbeat state version to 20385 from 20384 for /10. 33.2.70 ... TRACE 19:42:03,176 Scanning for state greater than 18303 for /10.33.3.10 TRACE 19:42:03,176 Scanning for state greater than 18303 for /10.33.3.10 TRACE 19:42:03,176 Sending a GossipDigestAck2Message to /10.33.3.20 TRACE 19:42:03,230 Received a GossipDigestSynMessage from /10.33.3.20 TRACE 19:42:03,230 reporting /10.33.3.20 TRACE 19:42:03,231 reporting /10.33.3.20 TRACE 19:42:03,231 @@@@ Size of GossipDigestAckMessage is 35 TRACE 19:42:03,231 Sending a GossipDigestAckMessage to /10.33.3.20 TRACE 19:42:03,232 Received a GossipDigestAck2Message from /10.33.3.20 TRACE 19:42:03,232 reporting /10.33.3.20 TRACE 19:42:03,232 marking as alive /10.33.3.20 TRACE 19:42:03,232 Updating heartbeat state version to 18296 from 18295 for /10. 33.3.20 ... TRACE 19:42:04,173 Gossip Digests are : /10.33.3.10:1276983719:18305 /10.33.2.70 10.33.3.20:/var/log/cassandra/output.log TRACE 19:42:03,174 Received a GossipDigestSynMessage from /10.33.3.10 TRACE 19:42:03,174 reporting /10.33.3.10 TRACE 19:42:03,174 reporting /10.33.3.10 TRACE 19:42:03,174 Scanning for state greater than 20384 for /10.33.2.70 TRACE 19:42:03,175 @@@@ Size of GossipDigestAckMessage is 52 TRACE 19:42:03,175 Sending a GossipDigestAckMessage to /10.33.3.10 TRACE 19:42:03,176 Received a GossipDigestAck2Message from /10.33.3.10 TRACE 19:42:03,176 reporting /10.33.3.10 TRACE 19:42:03,177 marking as alive /10.33.3.10 TRACE 19:42:03,177 Updating heartbeat state version to 18304 from 18303 for /10. 33.3.10 ... TRACE 19:42:03,229 Gossip Digests are : /10.33.3.20:1276983726:18296 /10.33.3.10 :1276983719:18304 /10.33.3.20:1276983726:18296 /10.33.2.70:1276981671:20385 TRACE 19:42:03,229 Sending a GossipDigestSynMessage to /10.33.3.10 ... TRACE 19:42:03,229 Performing status check ... TRACE 19:42:03,229 PHI for /10.33.2.70 : 0.5938079948279411 TRACE 19:42:03,229 PHI for /10.33.3.10 : 0.045531699282787594 TRACE 19:42:03,231 Received a GossipDigestAckMessage from /10.33.3.10 TRACE 19:42:03,231 Scanning for state greater than 18295 for /10.33.3.20 TRACE 19:42:03,231 Scanning for state greater than 18295 for /10.33.3.20 TRACE 19:42:03,232 Sending a GossipDigestAck2Message to /10.33.3.10 TRACE 19:42:03,622 Received a GossipDigestSynMessage from /10.33.2.70 TRACE 19:42:03,622 reporting /10.33.2.70 TRACE 19:42:03,622 reporting /10.33.2.70 TRACE 19:42:03,622 Scanning for state greater than 18295 for /10.33.3.20 TRACE 19:42:03,623 Scanning for state greater than 18303 for /10.33.3.10 TRACE 19:42:03,623 @@@@ Size of GossipDigestAckMessage is 69 TRACE 19:42:03,623 Sending a GossipDigestAckMessage to /10.33.2.70 TRACE 19:42:03,625 Received a GossipDigestAck2Message from /10.33.2.70 TRACE 19:42:03,625 reporting /10.33.2.70 TRACE 19:42:03,625 marking as alive /10.33.2.70 TRACE 19:42:03,625 Updating heartbeat state version to 20386 from 20385 for /10. 33.2.70 ... TRACE 19:42:04,229 Gossip Digests are : /10.33.3.20:1276983726:18297 /10.33.2.70 :1276981671:20386 /10.33.3.10:1276983719:18304 /10.33.3.20:1276983726:18297 TRACE 19:42:04,229 Sending a GossipDigestSynMessage to /10.33.3.10 ... TRACE 19:42:04,229 Performing status check ... AJ On Sat, Jun 19, 2010 at 7:02 PM, Jonathan Ellis <jbel...@gmail.com> wrote: > This is definitely not a Cassandra bug, something external is causing > those connection failures. > > On Sat, Jun 19, 2010 at 3:12 PM, AJ Slater <a...@zuno.com> wrote: >> Logging with TRACE reveals immediate problems with no client requests >> coming in to the servers. The problem was immediate and persisted over >> the course of half an hour: >> >> 10.33.2.70 lpc03 >> 10.33.3.10 fs01 >> 10.33.3.20 fs02 >> >> a...@lpc03:~$ grep unable /var/log/cassandra/output.log >> TRACE 14:07:52,104 unable to connect to /10.33.3.10 >> ... >> TRACE 14:42:00,008 unable to connect to /10.33.3.20 >> ... >> TRACE 14:42:06,751 unable to connect to /10.33.3.20 >> >> Note that lpc03 has trouble talking to fs01 and fs02. But after After >> seeing this I started logging TRACE on fs01 and fs02. >> >> During the six seconds before I restarted fs02: >> >> a...@fs01:~/logs$ grep unable /var/log/cassandra/output.log | grep unable >> Bad configuration; unable to start server >> TRACE 14:42:00,865 unable to connect to /10.33.3.20 >> ... >> TRACE 14:42:06,730 unable to connect to /10.33.3.20 >> >> Restarted fs02 and no issues in any of the logs. >> >> a...@fs02:~$ grep unable /var/log/cassandra/output.log >> a...@fs02:~$ >> >> >> >> The unfiltered log messages all look more like: >> >> TRACE 14:42:06,248 unable to connect to /10.33.3.20 >> java.net.ConnectException: Connection refused >> at java.net.PlainSocketImpl.socketConnect(Native Method) >> at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333) >> at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195) >> at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182) >> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366) >> at java.net.Socket.connect(Socket.java:529) >> at java.net.Socket.connect(Socket.java:478) >> at java.net.Socket.<init>(Socket.java:375) >> at java.net.Socket.<init>(Socket.java:276) >> at >> org.apache.cassandra.net.OutboundTcpConnection.connect(OutboundTcpCon >> nection.java:149) >> at >> org.apache.cassandra.net.OutboundTcpConnection.run(OutboundTcpConnect >> ion.java:85) >> >> >> On Sat, Jun 19, 2010 at 2:19 PM, AJ Slater <a...@zuno.com> wrote: >>> I shall do just that. I did a bunch of tests this morning and the >>> situation appears to be this: >>> >>> I have three nodes A, B and C, with RF=2. I understand now why this >>> issue wasn't apparent with RF=3. >>> >>> If there are regular intranode column requests going on (e.g. i set up >>> a pinger to get remote columns), the cluster functions normally. >>> However, if no intranode column requests happen for a few hours, (3 >>> hours is the minimum I've seen, but sometimes it takes longer), things >>> go wrong. Using node A as the point of contact from the client, all >>> columns that live on A are returned in a timely fashion, but for >>> columns that only live on B & C, the retrieval times out, with this in >>> the log: >>> >>> INFO 13:13:28,345 error writing to /10.33.3.20 >>> >>> No request for replicas, or consistency checks are seen in the logs of >>> B & C at this time. Using 'nodetool ring' from each of the three nodes >>> shows all nodes as Up. Telnet from A to B on port 7000 connects. >>> Tcpdump logs look like, at first glance, that gossip communication, >>> perhaps heartbeats, are proceeding normally, but I haven't really >>> analyzed them. >>> >>> Fifteen minutes later, the cluster decided to behave normally again. >>> Everyone talks to each other like buddies and delivers columns fast an >>> regularly. >>> >>> This is really looking like a Cassandra bug. I'll report back with my >>> TRACE log later and I expect I'll be opening a ticket. The confidence >>> level of my employer in my Cassandra solution to their petabyte data >>> storage project is... uh... well... it could be better. >>> >>> AJ >>> >>> >>> On Fri, Jun 18, 2010 at 8:16 PM, Jonathan Ellis <jbel...@gmail.com> wrote: >>>> set log level to TRACE and see if the OutboundTcpConnection is going >>>> bad. that would explain the message never arriving. >>>> >>>> On Fri, Jun 18, 2010 at 10:39 AM, AJ Slater <a...@zuno.com> wrote: >>>>> To summarize: >>>>> >>>>> If a request for a column comes in *after a period of several hours >>>>> with no requests*, then the node servicing the request hangs while >>>>> looking for its peer rather than servicing the request like it should. >>>>> It then throws either a TimedOutException or a (wrong) >>>>> NotFoundExeption. >>>>> >>>>> And it doen't appear to actually send the message it says it does to >>>>> its peer. Or at least its peer doesn't report the request being >>>>> received. >>>>> >>>>> And then the situation magically clears up after approximately 2 minutes. >>>>> >>>>> However, if the idle period never occurs, then the problem does not >>>>> manifest. If I run a cron job with wget against my server every >>>>> minute, I do not see the problem. >>>>> >>>>> I'll be looking at some tcpdump logs to see if i can suss out what's >>>>> really happening, and perhaps file this as a bug. The several hours >>>>> between reproducible events makes this whole thing aggravating for >>>>> detection, debugging and I'll assume, fixing, if it is indeed a >>>>> cassandra problem. >>>>> >>>>> It was suggested on IRC that it may be my network. But gossip is >>>>> continually sending heartbeats and nodetool and the logs show the >>>>> nodes as up and available. If my network was flaking out I'd think it >>>>> would be dropping heartbeats and I'd see that. >>>>> >>>>> AJ >>>>> >>>>> On Thu, Jun 17, 2010 at 2:26 PM, AJ Slater <a...@zuno.com> wrote: >>>>>> These are physical machines. >>>>>> >>>>>> storage-conf.xml.fs03 is here: >>>>>> >>>>>> http://pastebin.com/weL41NB1 >>>>>> >>>>>> Diffs from that for the other two storage-confs are inline here: >>>>>> >>>>>> a...@worm:../Z3/cassandra/conf/dev$ diff storage-conf.xml.lpc03 >>>>>> storage-conf.xml.fs01 >>>>>> 185c185 >>>>>> >>>>>>> <InitialToken>71603818521973537678586548668074777838</InitialToken> >>>>>> 229c229 >>>>>> < <ListenAddress>10.33.2.70</ListenAddress> >>>>>> --- >>>>>>> <ListenAddress>10.33.3.10</ListenAddress> >>>>>> 241c241 >>>>>> < <ThriftAddress>10.33.2.70</ThriftAddress> >>>>>> --- >>>>>>> <ThriftAddress>10.33.3.10</ThriftAddress> >>>>>> 341c341 >>>>>> < <ConcurrentReads>16</ConcurrentReads> >>>>>> --- >>>>>>> <ConcurrentReads>4</ConcurrentReads> >>>>>> >>>>>> >>>>>> a...@worm:../Z3/cassandra/conf/dev$ diff storage-conf.xml.lpc03 >>>>>> storage-conf.xml.fs02 >>>>>> 185c185 >>>>>> < <InitialToken>0</InitialToken> >>>>>> --- >>>>>>> <InitialToken>120215585224964746744782921158327379306</InitialToken> >>>>>> 206d205 >>>>>> < <Seed>10.33.3.20</Seed> >>>>>> 229c228 >>>>>> < <ListenAddress>10.33.2.70</ListenAddress> >>>>>> --- >>>>>>> <ListenAddress>10.33.3.20</ListenAddress> >>>>>> 241c240 >>>>>> < <ThriftAddress>10.33.2.70</ThriftAddress> >>>>>> --- >>>>>>> <ThriftAddress>10.33.3.20</ThriftAddress> >>>>>> 341c340 >>>>>> < <ConcurrentReads>16</ConcurrentReads> >>>>>> --- >>>>>>> <ConcurrentReads>4</ConcurrentReads> >>>>>> >>>>>> >>>>>> Thank you for your attention, >>>>>> >>>>>> AJ >>>>>> >>>>>> >>>>>> On Thu, Jun 17, 2010 at 2:09 PM, Benjamin Black <b...@b3k.us> wrote: >>>>>>> Are these physical machines or virtuals? Did you post your >>>>>>> cassandra.in.sh and storage-conf.xml someplace? >>>>>>> >>>>>>> On Thu, Jun 17, 2010 at 10:31 AM, AJ Slater <a...@zuno.com> wrote: >>>>>>>> Total data size in the entire cluster is about twenty 12k images. With >>>>>>>> no other load on the system. I just ask for one column and I get these >>>>>>>> timeouts. Performing multiple gets on the columns leads to multiple >>>>>>>> timeouts for a period of a few seconds or minutes and then the >>>>>>>> situation magically resolves itself and response times are down to >>>>>>>> single digit milliseconds for a column get. >>>>>>>> >>>>>>>> On Thu, Jun 17, 2010 at 10:24 AM, AJ Slater <a...@zuno.com> wrote: >>>>>>>>> Cassandra 0.6.2 from the apache debian source. >>>>>>>>> Ubunutu Jaunty. Sun Java6 jvm. >>>>>>>>> >>>>>>>>> All nodes in separate racks at 365 main. >>>>>>>>> >>>>>>>>> On Thu, Jun 17, 2010 at 10:12 AM, AJ Slater <a...@zuno.com> wrote: >>>>>>>>>> I'm seing 10s timeouts on reads few times a day. Its hard to >>>>>>>>>> reproduce >>>>>>>>>> consistently but seems to happen most often after its been a long >>>>>>>>>> time >>>>>>>>>> between reads. After presenting itself for a couple minutes the >>>>>>>>>> problem then goes away. >>>>>>>>>> >>>>>>>>>> I've got a three node cluster with replication factor 2, reading at >>>>>>>>>> consistency level ONE. The columns being read are around 12k each. >>>>>>>>>> The >>>>>>>>>> nodes are 8GB multicore boxes with the JVM limits between 4GB and >>>>>>>>>> 6GB. >>>>>>>>>> >>>>>>>>>> Here's an application log from early this morning when a developer in >>>>>>>>>> Belgrade accessed the system: >>>>>>>>>> >>>>>>>>>> Jun 17 03:54:17 lpc03 pinhole[5736]: MainThread:pinhole.py:61 | >>>>>>>>>> Requested image_id: 5827067133c3d670071c17d9144f0b49 >>>>>>>>>> Jun 17 03:54:27 lpc03 pinhole[5736]: MainThread:pinhole.py:76 | >>>>>>>>>> TimedOutException for Image 5827067133c3d670071c17d9144f0b49 >>>>>>>>>> Jun 17 03:54:27 lpc03 pinhole[5736]: MainThread:zlog.py:105 | Image >>>>>>>>>> Get took 10005.388975 ms >>>>>>>>>> Jun 17 03:54:27 lpc03 pinhole[5736]: MainThread:pinhole.py:61 | >>>>>>>>>> Requested image_id: af8caf3b76ce97d13812ddf795104a5c >>>>>>>>>> Jun 17 03:54:27 lpc03 pinhole[5736]: MainThread:zlog.py:105 | Image >>>>>>>>>> Get took 3.658056 ms >>>>>>>>>> Jun 17 03:54:27 lpc03 pinhole[5736]: MainThread:zlog.py:105 | Image >>>>>>>>>> Transform took 0.978947 ms >>>>>>>>>> >>>>>>>>>> That's a Timeout and then a successful get of another column. >>>>>>>>>> >>>>>>>>>> Here's the cassandra log for 10.33.2.70: >>>>>>>>>> >>>>>>>>>> DEBUG 03:54:17,070 get_slice >>>>>>>>>> DEBUG 03:54:17,071 weakreadremote reading >>>>>>>>>> SliceFromReadCommand(table='jolitics.com', >>>>>>>>>> key='5827067133c3d670071c17d9144f0b49', >>>>>>>>>> column_parent='QueryPath(columnFamilyName='Images', >>>>>>>>>> superColumnName='null', columnName='null')', start='', finish=' >>>>>>>>>> ', reversed=false, count=100) >>>>>>>>>> DEBUG 03:54:17,071 weakreadremote reading >>>>>>>>>> SliceFromReadCommand(table='jolitics.com', >>>>>>>>>> key='5827067133c3d670071c17d9144f0b49', >>>>>>>>>> column_parent='QueryPath(columnFamilyName='Images', >>>>>>>>>> superColumnName='null', columnName='null')', start='', finish=' >>>>>>>>>> ', reversed=false, count=100) from 45138@/10.33.3.10 >>>>>>>>>> DEBUG 03:54:27,077 get_slice >>>>>>>>>> DEBUG 03:54:27,078 weakreadlocal reading >>>>>>>>>> SliceFromReadCommand(table='jolitics.com', >>>>>>>>>> key='af8caf3b76ce97d13812ddf795104a5c', >>>>>>>>>> column_parent='QueryPath(columnFamilyName='Images', >>>>>>>>>> superColumnName='null', columnName='null')', start='', finish='' >>>>>>>>>> , reversed=false, count=100) >>>>>>>>>> DEBUG 03:54:27,079 collecting body:false:1...@1275951327610885 >>>>>>>>>> DEBUG 03:54:27,080 collecting body:false:1...@1275951327610885 >>>>>>>>>> DEBUG 03:54:27,080 Reading consistency digest for >>>>>>>>>> af8caf3b76ce97d13812ddf795104a >>>>>>>>>> 5c from 45...@[/10.33.2.70, /10.33.3.10] >>>>>>>>>> DEBUG 03:54:50,779 Disseminating load info ... >>>>>>>>>> >>>>>>>>>> It looks like it asks for key='5827067133c3d670071c17d9144f0b49' from >>>>>>>>>> the local host and also queries 10.33.3.10 for the first one and then >>>>>>>>>> for 'af8caf3b76ce97d13812ddf795104a5c' it only queries the local host >>>>>>>>>> and then returns appropriately. >>>>>>>>>> >>>>>>>>>> Here's the log for 10.33.3.10 around that time: >>>>>>>>>> >>>>>>>>>> DEBUG 03:54:19,645 Disseminating load info ... >>>>>>>>>> DEBUG 03:55:19,645 Disseminating load info ... >>>>>>>>>> DEBUG 03:56:19,646 Disseminating load info ... >>>>>>>>>> DEBUG 03:57:19,645 Disseminating load info ... >>>>>>>>>> DEBUG 03:58:19,645 Disseminating load info ... >>>>>>>>>> DEBUG 03:59:19,646 Disseminating load info ... >>>>>>>>>> DEBUG 04:00:18,635 GC for ParNew: 4 ms, 21443128 reclaimed leaving >>>>>>>>>> 55875144 used; max is 6580535296 >>>>>>>>>> >>>>>>>>>> No record of communication from 10.33.2.70. >>>>>>>>>> >>>>>>>>>> Does this ring any bells for anyone? I can of course attach >>>>>>>>>> storage-conf's for all nodes if that sounds useful and I'll be on >>>>>>>>>> #cassandra as ajslater. >>>>>>>>>> >>>>>>>>>> Much thanks for taking a look and any suggestions. We fear we'll have >>>>>>>>>> to abandon Cassandra if this bug cannot be resolved. >>>>>>>>>> >>>>>>>>>> AJ >>>>>>>>>> >>>>>>>>> >>>>>>>> >>>>>>> >>>>>> >>>>> >>>> >>>> >>>> >>>> -- >>>> Jonathan Ellis >>>> Project Chair, Apache Cassandra >>>> co-founder of Riptano, the source for professional Cassandra support >>>> http://riptano.com >>>> >>> >> > > > > -- > Jonathan Ellis > Project Chair, Apache Cassandra > co-founder of Riptano, the source for professional Cassandra support > http://riptano.com >
