Return-Path: X-Original-To: apmail-zookeeper-bookkeeper-user-archive@minotaur.apache.org Delivered-To: apmail-zookeeper-bookkeeper-user-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id E6C779237 for ; Thu, 5 Apr 2012 18:41:33 +0000 (UTC) Received: (qmail 97372 invoked by uid 500); 5 Apr 2012 18:41:33 -0000 Delivered-To: apmail-zookeeper-bookkeeper-user-archive@zookeeper.apache.org Received: (qmail 97339 invoked by uid 500); 5 Apr 2012 18:41:33 -0000 Mailing-List: contact bookkeeper-user-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: bookkeeper-user@zookeeper.apache.org Delivered-To: mailing list bookkeeper-user@zookeeper.apache.org Received: (qmail 97330 invoked by uid 99); 5 Apr 2012 18:41:33 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 05 Apr 2012 18:41:33 +0000 X-ASF-Spam-Status: No, hits=-0.1 required=5.0 tests=HTML_MESSAGE,NORMAL_HTTP_TO_IP,RCVD_IN_DNSWL_MED,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of jnagro@hubspot.com designates 74.125.149.209 as permitted sender) Received: from [74.125.149.209] (HELO na3sys009aog113.obsmtp.com) (74.125.149.209) by apache.org (qpsmtpd/0.29) with SMTP; Thu, 05 Apr 2012 18:41:26 +0000 Received: from mail-ob0-f180.google.com ([209.85.214.180]) (using TLSv1) by na3sys009aob113.postini.com ([74.125.148.12]) with SMTP ID DSNKT33nP7dLrqV5uMaW3FZX9p0TIveNvePt@postini.com; Thu, 05 Apr 2012 11:41:04 PDT Received: by obbun3 with SMTP id un3so3386069obb.39 for ; Thu, 05 Apr 2012 11:41:03 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20120113; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type:x-gm-message-state; bh=2RRovmTuJYT3uk8KZ2v/A0K4R2N1N0Q12Qby+rK3BXA=; b=Z7gq183g6PCJoPu8ZMV8G0R8vfsLyKQl/xXADIfTkoLVzKZlfCItVhoUIeGligKOwB fAAaZmgReFJGz0mswrPhlpc2HPoDAGMVSI2k34aU68EPJLSSoEsSMs+8eMI7GA06kcr0 Qfup7yh+GaBDEMV3Iba3zmHlMaPrDuSIvdVLX8VslSxrj+qOz+/wZYftj/d3N/eisb9p kF3WohpzAmGuCNZXPNOlsLo7XMh8oEjvtBpQzyfs87w+UT4CIr6iv6Nh/pc+TZjkHDCb forwMcUibLF0/OBjfXsSQajUQqLDKZg8Yd4OomvGAKYPUM8FHhnmfbvuhaFq0LOGiHX6 Lhxw== MIME-Version: 1.0 Received: by 10.182.169.41 with SMTP id ab9mr5608421obc.4.1333651263394; Thu, 05 Apr 2012 11:41:03 -0700 (PDT) Received: by 10.182.81.134 with HTTP; Thu, 5 Apr 2012 11:41:03 -0700 (PDT) In-Reply-To: <8E94A8C7-FA3E-48BC-ACEA-26230D0A0605@yahoo-inc.com> References: <7342CE1F-DD3A-4887-9D7E-980A2CF24867@yahoo-inc.com> <8E94A8C7-FA3E-48BC-ACEA-26230D0A0605@yahoo-inc.com> Date: Thu, 5 Apr 2012 14:41:03 -0400 Message-ID: Subject: Re: BK servers in a funky state From: John Nagro To: bookkeeper-user@zookeeper.apache.org Content-Type: multipart/alternative; boundary=e89a8f643bf2cf150c04bcf2e13c X-Gm-Message-State: ALoCoQkb2jJR+XuO3pGR8fhdjbP05TunTgvmG/sQzd0Y/JE/VR98gmNK77VrBLJ0ECzRjTSMIRD/ --e89a8f643bf2cf150c04bcf2e13c Content-Type: text/plain; charset=ISO-8859-1 All 5 machines behave the same way. It is not the end of the world if we can't recover the data from them in this instance, but at some point the data sent through this WAL will be very important to be able to recover in the event of a crash. I tried to move the logs/current directory out of the way, replacing it with another and got this: 2012-04-05 14:39:31,829 - INFO [main-EventThread:Bookie$3@678] - ZK client has been reconnected to the ZK server! 2012-04-05 14:39:31,854 - ERROR [main:Bookie@331] - Cookie exists in zookeeper, but not in all local directories java.io.FileNotFoundException: /opt/bookkeeper/logs/current/VERSION (No such file or directory) at java.io.FileInputStream.open(Native Method) at java.io.FileInputStream.(FileInputStream.java:106) at java.util.Scanner.(Scanner.java:636) at org.apache.bookkeeper.bookie.Cookie.readFromDirectory(Cookie.java:188) at org.apache.bookkeeper.bookie.Bookie.checkEnvironment(Bookie.java:326) at org.apache.bookkeeper.bookie.Bookie.(Bookie.java:401) at org.apache.bookkeeper.proto.BookieServer.(BookieServer.java:75) at org.apache.bookkeeper.proto.BookieServer.main(BookieServer.java:294) 2012-04-05 14:39:31,856 - ERROR [main:BookieServer@308] - Exception running bookie server : org.apache.bookkeeper.bookie.BookieException$InvalidCookieException at org.apache.bookkeeper.bookie.Bookie.checkEnvironment(Bookie.java:332) at org.apache.bookkeeper.bookie.Bookie.(Bookie.java:401) at org.apache.bookkeeper.proto.BookieServer.(BookieServer.java:75) at org.apache.bookkeeper.proto.BookieServer.main(BookieServer.java:294) which makes me believe i'd need to clean out the cookie entry in ZK for this server? Thanks. -John On Thu, Apr 5, 2012 at 1:54 PM, Flavio Junqueira wrote: > By cleaning it up, I meant deleting the log and index files. You must have > passed paths when you started bookies, I was suggesting to wipe them out. > > I just realized that there are a couple of things I don't understand: > > 1- How many bookies have been affected? Just one or all of them? If it is > just one, then you may need to use the bookie recovery tool to reconstruct > the ledger fragments of the problematic bookie. > 2- Can you clean up all bookies and zookeeper and start it over or there > is data you need to recover? > > -Flavio > > On Apr 5, 2012, at 7:32 PM, John Nagro wrote: > > Flavio - > > The log is from an existing server which crashed and I am trying to bring > it back up. How might i clean things up? What about existing ledgers? > > -John > > On Thu, Apr 5, 2012 at 12:57 PM, Flavio Junqueira wrote: > >> Actually, I have a question about the new logs you sent. Have you tried >> to clean up the state of bookies before rerunning them or these logs >> correspond to a bookie that you're bringing back up and the bookie is >> trying to read its old state? If it is the latter, then I would suggest to >> give it a fresh start. >> >> -Flavio >> >> On Apr 5, 2012, at 4:53 PM, John Nagro wrote: >> >> Flavio - >> >> I really appreciate your prompt response. Some quick background - we use >> some of the hadoop technologies for storage, coordination, and processing. >> Recently we wanted to add a write-ahead-log to our infrastructure so that >> clients could record "transactions" prior to executing them - such as >> updates going to an API or processing of an event. I've written a set of >> tools that use BK as a generic write-ahead-logger. Clients (using zookeeper >> for coordination) can create named write ahead logs with custom chunking >> (how frequently a new ledger is created - based on size/time). Once a >> ledger has rolled-over (or a client crashes), a persister (monitoring ZK) >> reads that ledger and persists it to S3/HDFS as hadoop sequence files where >> a map-reduce process can reconcile it. The ledger is then deleted from BK. >> This is all done using ZK in a fashion where (hopefully) once a client has >> written any data to the ledger it will always end up on S3/HDFS (via BK) >> even if the client crashes (the persister will always know which ledger >> belongs to which log and which ledgers are currently in use). >> >> Does that sound like an appropriate use of BK? It seemed like a natural >> fit as a durable storage solution until something can reliably get it to a >> place where it would ultimately be archived and could be >> reprocessed/reconciled (S3/HDFS). >> >> As for the bug fix you mentioned, this gist shows the logs from the cut i >> made this morning: >> >> https://gist.github.com/aea874d89b28d4cfef31 >> >> As you can see, there are still some exceptions and error messages that >> repeat (forever). This is the newest cut available on github, last commit >> is: >> >> commit f694716e289c448ab89cab5fa81ea0946f9d9193 >> Author: Flavio Paiva Junqueira >> Date: Tue Apr 3 16:02:44 2012 +0000 >> >> BOOKKEEPER-207: BenchBookie doesn't run correctly (ivank via fpj) >> >> git-svn-id: >> https://svn.apache.org/repos/asf/zookeeper/bookkeeper/trunk@130900713f79535-47bb-0310-9956-ffa450edef68 >> >> >> What are your thoughts? Thanks! >> >> -John >> >> >> On Thu, Apr 5, 2012 at 10:10 AM, Flavio Junqueira wrote: >> >>> Hi John, Let's see if I can help: >>> >>> On Apr 5, 2012, at 3:19 PM, John Nagro wrote: >>> >>> Hello - >>> >>> I've been hitting Ivan up for advice about a bookkeeper project of mine. >>> I recently ran into another issue and he suggested I inquire here since he >>> is traveling. >>> >>> We've got a pool of 5 BK servers running in EC2. Last night they got >>> into a funky state and/or crashed - unfortunately the log with the original >>> event got rotated (that has been fixed). I was running a cut of >>> 4.1.0-SNAPSHOT sha 6d56d60831a63fe9520ce156686d0cb1142e44f5 from Wed Mar 28 >>> 21:57:40 2012 +0000 which brought everything up to BOOKKEEPER-195. That >>> build had some bugfixes over 4.0.0 that I was originally running (and a >>> previous version before that). >>> >>> >>> Is there anything else you can say about your application, like how fast >>> you're writing and how often you're rolling ledgers maybe? Are you deleting >>> ledgers at all? >>> >>> >>> When I restart the servers after the incident this is what the logs >>> looked like: >>> >>> https://gist.github.com/f2b9c8c76943b057546e >>> >>> Which contain a lot of errors - although it appears the servers come up >>> (i have not tried to use the servers yet). Although I don't have the >>> original stack that caused the crash, the logs from recently after the >>> crash contained a lot of this stack: >>> >>> 2012-04-04 21:04:58,833 - INFO >>> [GarbageCollectorThread:GarbageCollectorThread@266] - Deleting >>> entryLogId 4 as it has no active ledgers! >>> 2012-04-04 21:04:58,834 - ERROR [GarbageCollectorThread:EntryLogger@188] >>> - Trying to delete an entryLog file that could not be found: 4.log >>> 2012-04-04 21:04:59,783 - WARN >>> [NIOServerFactory-3181:NIOServerFactory@129] - Exception in server >>> socket loop: /0.0.0.0 >>> >>> java.util.NoSuchElementException >>> at java.util.LinkedList.getFirst(LinkedList.java:109) >>> at >>> org.apache.bookkeeper.bookie.LedgerCacheImpl.grabCleanPage(LedgerCacheImpl.java:458) >>> at >>> org.apache.bookkeeper.bookie.LedgerCacheImpl.putEntryOffset(LedgerCacheImpl.java:165) >>> at >>> org.apache.bookkeeper.bookie.LedgerDescriptorImpl.addEntry(LedgerDescriptorImpl.java:93) >>> at >>> org.apache.bookkeeper.bookie.Bookie.addEntryInternal(Bookie.java:999) >>> at org.apache.bookkeeper.bookie.Bookie.addEntry(Bookie.java:1034) >>> at >>> org.apache.bookkeeper.proto.BookieServer.processPacket(BookieServer.java:359) >>> at >>> org.apache.bookkeeper.proto.NIOServerFactory$Cnxn.readRequest(NIOServerFactory.java:315) >>> at >>> org.apache.bookkeeper.proto.NIOServerFactory$Cnxn.doIO(NIOServerFactory.java:213) >>> >>> at >>> org.apache.bookkeeper.proto.NIOServerFactory.run(NIOServerFactory.java:124) >>> >>> >>> This looks like what we found and resolved here: >>> >>> https://issues.apache.org/jira/browse/BOOKKEEPER-198 >>> >>> >>> This morning I upgraded to the most recent cut - >>> sha f694716e289c448ab89cab5fa81ea0946f9d9193 made on Tue Apr 3 16:02:44 >>> 2012 +0000 and restarted. That did not seem to correct matters, although >>> the log has slightly different error messages: >>> >>> https://gist.github.com/aea874d89b28d4cfef31 >>> >>> Does anyone know whats going on? How i can correct these errors? Are the >>> machines in an okay state to use? >>> >>> >>> It sounds like we have resolved it in 198, so if you're using a recent >>> cut, you shouldn't observe this problem anymore. But, if it does happen >>> again, it would be great to try to find a way to reproduce it so that we >>> can track the bug... assuming it is a bug. >>> >>> -Flavio >>> >>> >>> >> >> flavio >> junqueira >> senior research scientist >> >> fpj@yahoo-inc.com >> direct +34 93-183-8828 >> >> avinguda diagonal 177, 8th floor, barcelona, 08018, es >> phone (408) 349 3300 fax (408) 349 3301 >> >> > > flavio > junqueira > senior research scientist > > fpj@yahoo-inc.com > direct +34 93-183-8828 > > avinguda diagonal 177, 8th floor, barcelona, 08018, es > phone (408) 349 3300 fax (408) 349 3301 > > --e89a8f643bf2cf150c04bcf2e13c Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable All 5 machines behave the same way. It is not the end of the world if we ca= n't recover the data from them in this instance, but at some point the = data sent through this WAL will be very important to be able to recover in = the event of a crash.

I tried to move the logs/current directory out of the way, r= eplacing it with another and got this:

2012-0= 4-05 14:39:31,829 - INFO =A0[main-EventThread:Bookie$3@678] - ZK client has= been reconnected to the ZK server!
2012-04-05 14:39:31,854 - ERROR [main:Bookie@331] - Cookie exists in z= ookeeper, but not in all local directories
java.io.FileNotFoundEx= ception: /opt/bookkeeper/logs/current/VERSION (No such file or directory)
at ja= va.io.FileInputStream.open(Native Method)
at java.io.FileInputStream.<in= it>(FileInputStream.java:106)
at ja= va.util.Scanner.<init>(Scanner.java:636)
at org.apache.bookkeeper.boo= kie.Cookie.readFromDirectory(Cookie.java:188)
at or= g.apache.bookkeeper.bookie.Bookie.checkEnvironment(Bookie.java:326)
at org.= apache.bookkeeper.bookie.Bookie.<init>(Bookie.java:401)
at or= g.apache.bookkeeper.proto.BookieServer.<init>(BookieServer.java:75)
a= t org.apache.bookkeeper.proto.BookieServer.main(BookieServer.java:294)
2012-04-05 14:39:31,856 - ERROR [main:BookieServer@308] - Exception ru= nning bookie server :=A0
org.apache.bookkeeper.bookie.BookieExcep= tion$InvalidCookieException
at org.apache.bookkeeper.bookie.Bookie.checkEn= vironment(Bookie.java:332)
at or= g.apache.bookkeeper.bookie.Bookie.<init>(Bookie.java:401)
<= span class=3D"Apple-tab-span" style=3D"white-space:pre"> at org.apac= he.bookkeeper.proto.BookieServer.<init>(BookieServer.java:75)
at or= g.apache.bookkeeper.proto.BookieServer.main(BookieServer.java:294)

which makes me believe i'd need to clean out the= cookie entry in ZK for this server?

Thanks.
-John

On Thu, Apr 5, 2012 at 1:54 PM, Flavio Junqueira <<= a href=3D"mailto:fpj@yahoo-inc.com">fpj@yahoo-inc.com> wrote:=
By clean= ing it up, I meant deleting the log and index files. You must have passed p= aths when you started bookies, I was suggesting to wipe them out.=A0

I just realized that there are a couple of things I don'= t understand:

1- How many bookies have been affected? Ju= st one or all of them? If it is just one, then you may need to use the book= ie recovery tool to reconstruct the ledger fragments of the problematic boo= kie.
2- Can you clean up all bookies and zookeeper and start it over or the= re is data you need to recover?=A0

-Flavio

On Apr 5, 2012, at 7:32 PM, John Nagro wrote:
Flavio -

The log is from = an existing server which crashed and I am trying to bring it back up. How m= ight i clean things up? What about existing ledgers?

-John

On Thu, Apr 5, 2012 at 12:57 PM, Flavio Junqueira <fpj@yahoo-inc.com&g= t; wrote:
Actually, I have a question about the n= ew logs you sent. Have you tried to clean up the state of bookies before re= running them or these logs correspond to a bookie that you're bringing = back up and the bookie is trying to read its old state? If it is the latter= , then I would suggest to give it a fresh start.=A0

-Flavio

On Apr 5, 2012, at 4:53 PM, John Nag= ro wrote:

Flavio -

I really appreciate your prompt response. Some quick backgro= und - we use some of the hadoop technologies for storage, coordination, and= processing. Recently we wanted to add a write-ahead-log to our infrastruct= ure so that clients could record "transactions" prior to executin= g them - such as updates going to an API or processing of an event. I'v= e written a set of tools that use BK as a generic write-ahead-logger. Clien= ts (using zookeeper for coordination) can create named write ahead logs wit= h custom chunking (how frequently a new ledger is created - based on size/t= ime). Once a ledger has rolled-over (or a client crashes), a persister (mon= itoring ZK) reads that ledger and persists it to S3/HDFS as hadoop sequence= files where a map-reduce process can reconcile it. The ledger is then dele= ted from BK. This is all done using ZK in a fashion where (hopefully) once = a client has written any data to the ledger it will always end up on S3/HDF= S (via BK) even if the client crashes (the persister will always know which= ledger belongs to which log and which ledgers are currently in use).

Does that sound like an appropriate use of BK? It seeme= d like a natural fit as a durable storage solution until something can reli= ably get it to a place where it would ultimately be archived and could be r= eprocessed/reconciled (S3/HDFS).

As for the bug fix you mentioned, this gist shows the l= ogs from the cut i made this morning:


As you can see, there are still some exceptions and err= or messages that repeat (forever). This is the newest cut available on gith= ub, last commit is:

commit f694716e289c448ab8= 9cab5fa81ea0946f9d9193
Author: Flavio Paiva Junqueira <fpj@apache.org>
Date: =A0 Tue Apr 3 16:02= :44 2012 +0000

BOOKKEEPER-207: BenchBookie doesn&#= 39;t run correctly (ivank via fpj)

git-svn-id: https://svn.apache.o= rg/repos/asf/zookeeper/bookkeeper/trunk@1309007 13f79535-47bb-0310-9956= -ffa450edef68


What are your thoughts? Thanks!

-John


O= n Thu, Apr 5, 2012 at 10:10 AM, Flavio Junqueira <fpj@yahoo-inc.com>= ; wrote:
Hi John,= Let's see if I can help:

On Apr 5, 2012, at 3:1= 9 PM, John Nagro wrote:

Hello -

I've been hitt= ing Ivan up for advice about a bookkeeper project of mine. I recently ran i= nto another issue and he suggested I inquire here since he is traveling.

We've got a pool of 5 BK servers running in EC2. Last night they got in= to a funky state and/or crashed - unfortunately the log with the original e= vent got rotated (that has been fixed). I was running a cut of 4.1.0-SNAPSH= OT sha=A06d56d60831a63fe9520ce156686d0cb1142e44f5 from=A0Wed Mar 28 21:57:4= 0 2012 +0000 which brought everything up to BOOKKEEPER-195.=A0That build ha= d some bugfixes over 4.0.0 that I was originally running (and a previous ve= rsion before that).


Is there anythi= ng else you can say about your application, like how fast you're writin= g and how often you're rolling ledgers maybe? Are you deleting ledgers = at all?


When I restart the s= ervers after the incident this is what the logs looked like:

=

Which contain a lot of errors - although it appears the= servers come up (i have not tried to use the servers yet).=A0Although I do= n't have the original stack that caused the crash, the logs from recent= ly after the crash contained a lot of this stack:

2012-04-04 21:04:58,833 - INFO=A0 [GarbageCollectorThread:Ga= rbageCollectorThread@266] - Deleting entryLogId 4 as it has no active ledge= rs!
2012-04-04 21:04:58,834 - ERROR [GarbageCollectorThread:EntryLogger@= 188] - Trying to delete an entryLog file that could not be found: 4.log
2012-04-04 21:04:59,783 - WARN=A0 [NIOServerFactory-3181:NIOServerFactory@1= 29] - Exception in server socket loop: /0.0.0.0

java.util.NoSuchElementException
=A0=A0= =A0=A0=A0=A0=A0 at java.util.LinkedList.getFirst(LinkedList.java:109)
=A0=A0=A0=A0=A0=A0=A0 at org.apache.bookkeeper.bookie.LedgerCacheImpl.grabC= leanPage(LedgerCacheImpl.java:458)
=A0=A0=A0=A0=A0=A0=A0 at org.apache.b= ookkeeper.bookie.LedgerCacheImpl.putEntryOffset(LedgerCacheImpl.java:165)=A0=A0=A0=A0=A0=A0=A0 at org.apache.bookkeeper.bookie.LedgerDescriptorImp= l.addEntry(LedgerDescriptorImpl.java:93)
=A0=A0=A0=A0=A0=A0=A0 at org.apache.bookkeeper.bookie.Bookie.addEntryIntern= al(Bookie.java:999)
=A0=A0=A0=A0=A0=A0=A0 at org.apache.bookkeeper.booki= e.Bookie.addEntry(Bookie.java:1034)
=A0=A0=A0=A0=A0=A0=A0 at org.apache.= bookkeeper.proto.BookieServer.processPacket(BookieServer.java:359)
=A0=A0=A0=A0=A0=A0=A0 at org.apache.bookkeeper.proto.NIOServerFactory$Cnxn.= readRequest(NIOServerFactory.java:315)
=A0=A0=A0=A0=A0=A0=A0 at org.apac= he.bookkeeper.proto.NIOServerFactory$Cnxn.doIO(NIOServerFactory.java:213)
=A0=A0=A0=A0=A0=A0=A0 at org.apache.bookkeeper.proto.NIOServerFactory.run(N= IOServerFactory.java:124)

This l= ooks like what we found and resolved here:



This morning I upgraded to the most recent cut - sha=A0f6947= 16e289c448ab89cab5fa81ea0946f9d9193 made on=A0Tue Apr 3 16:02:44 2012 +0000= and restarted. That did not seem to correct matters, although the log has = slightly different error messages:

<= div>
Does anyone know whats going on? How i can correct these= errors? Are the machines in an okay state to use?

It sounds like we have resolved it i= n 198, so if you're using a recent cut, you shouldn't observe this = problem anymore. But, if it does happen again, it would be great to try to = find a way to reproduce it so that we can track the bug... assuming it is a= bug.

-Flavio




flavio
junqueira
senior research scientist=
=A0
fpj@yah= oo-inc.com
direct +34 93-183-882= 8
=A0
avin= guda diagonal 177, 8th floor, barcelona, 08018, es
phone (408) 349 3300=A0=A0=A0=A0fax (408) 349 3301



flavio
junqueira
senior research scientist=
=A0
fpj@yah= oo-inc.com
direct +34 93-183-882= 8
=A0
avin= guda diagonal 177, 8th floor, barcelona, 08018, es
phone (408) 349 3300=A0=A0=A0=A0fax (408) 349 3301


--e89a8f643bf2cf150c04bcf2e13c--