Skip to content

Instantly share code, notes, and snippets.

@apple-corps
Created May 21, 2015 16:09
Show Gist options
  • Select an option

  • Save apple-corps/6ee6053c70f9fc74d6d2 to your computer and use it in GitHub Desktop.

Select an option

Save apple-corps/6ee6053c70f9fc74d6d2 to your computer and use it in GitHub Desktop.
Entire HBASE cluster goes down due to Zookeeper expiry
2015-05-20 06:43:54,808 DEBUG org.apache.hadoop.hbase.master.CatalogJanitor: Scanned 38 catalog row(s) and gc'd 0 unreferenced parent region(s)
2015-05-20 06:48:54,775 DEBUG org.apache.hadoop.hbase.client.HTable$ClientScanner: Creating scanner over .META. starting at key ''
2015-05-20 06:48:54,775 DEBUG org.apache.hadoop.hbase.client.HTable$ClientScanner: Advancing internal scanner to startKey at ''
2015-05-20 06:48:54,816 DEBUG org.apache.hadoop.hbase.client.HTable$ClientScanner: Finished with scanning at {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2015-05-20 06:48:54,817 DEBUG org.apache.hadoop.hbase.master.CatalogJanitor: Scanned 38 catalog row(s) and gc'd 0 unreferenced parent region(s)
2015-05-20 06:53:54,776 DEBUG org.apache.hadoop.hbase.client.HTable$ClientScanner: Creating scanner over .META. starting at key ''
2015-05-20 06:53:54,776 DEBUG org.apache.hadoop.hbase.client.HTable$ClientScanner: Advancing internal scanner to startKey at ''
2015-05-20 06:53:54,809 DEBUG org.apache.hadoop.hbase.client.HTable$ClientScanner: Finished with scanning at {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2015-05-20 06:53:54,810 DEBUG org.apache.hadoop.hbase.master.CatalogJanitor: Scanned 38 catalog row(s) and gc'd 0 unreferenced parent region(s)
2015-05-20 06:57:59,624 INFO org.apache.hadoop.hbase.zookeeper.RegionServerTracker: RegionServer ephemeral node deleted, processing expiration [us3sm2hbcm006r07.comp.prod.local,60020,1429219111318]
2015-05-20 06:57:59,626 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: based on AM, current region=-ROOT-,,0.70236052 is on server=us3sm2hbcm001r08.comp.prod.local,60020,1429219098740 server being checked: us3sm2hbcm006r07.comp.prod.local,60020,1429219111318
2015-05-20 06:57:59,627 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: based on AM, current region=.META.,,1.1028785192 is on server=us3sm2hbcm002r09.comp.prod.local,60020,1429219101947 server being checked: us3sm2hbcm006r07.comp.prod.local,60020,1429219111318
2015-05-20 06:57:59,627 DEBUG org.apache.hadoop.hbase.master.ServerManager: Added=us3sm2hbcm006r07.comp.prod.local,60020,1429219111318 to dead servers, submitted shutdown handler to be executed, root=false, meta=false
2015-05-20 06:57:59,627 INFO org.apache.hadoop.hbase.master.handler.ServerShutdownHandler: Splitting logs for us3sm2hbcm006r07.comp.prod.local,60020,1429219111318
2015-05-20 06:57:59,628 INFO org.apache.zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x14cc399c4620007, likely server has closed socket, closing socket connection and attempting reconnect
2015-05-20 06:57:59,637 INFO org.apache.hadoop.hbase.zookeeper.RegionServerTracker: RegionServer ephemeral node deleted, processing expiration [us3sm2hbcm003r07.comp.prod.local,60020,1429219103986]
2015-05-20 06:57:59,638 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: based on AM, current region=-ROOT-,,0.70236052 is on server=us3sm2hbcm001r08.comp.prod.local,60020,1429219098740 server being checked: us3sm2hbcm003r07.comp.prod.local,60020,1429219103986
2015-05-20 06:57:59,639 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: based on AM, current region=.META.,,1.1028785192 is on server=us3sm2hbcm002r09.comp.prod.local,60020,1429219101947 server being checked: us3sm2hbcm003r07.comp.prod.local,60020,1429219103986
2015-05-20 06:57:59,639 DEBUG org.apache.hadoop.hbase.master.ServerManager: Added=us3sm2hbcm003r07.comp.prod.local,60020,1429219103986 to dead servers, submitted shutdown handler to be executed, root=false, meta=false
2015-05-20 06:57:59,639 INFO org.apache.hadoop.hbase.master.handler.ServerShutdownHandler: Splitting logs for us3sm2hbcm003r07.comp.prod.local,60020,1429219103986
2015-05-20 06:57:59,640 INFO org.apache.hadoop.hbase.zookeeper.RegionServerTracker: RegionServer ephemeral node deleted, processing expiration [us3sm2hbcm005r09.comp.prod.local,60020,1429219109394]
2015-05-20 06:57:59,641 DEBUG org.apache.hadoop.hbase.master.MasterFileSystem: Renamed region directory: hdfs://haprod/author_details/.logs/us3sm2hbcm006r07.comp.prod.local,60020,1429219111318-splitting
2015-05-20 06:57:59,641 INFO org.apache.hadoop.hbase.master.SplitLogManager: dead splitlog workers [us3sm2hbcm006r07.comp.prod.local,60020,1429219111318]
2015-05-20 06:57:59,642 INFO org.apache.zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x34cc39a98300007, likely server has closed socket, closing socket connection and attempting reconnect
2015-05-20 06:57:59,645 DEBUG org.apache.hadoop.hbase.master.MasterFileSystem: Renamed region directory: hdfs://haprod/author_details/.logs/us3sm2hbcm003r07.comp.prod.local,60020,1429219103986-splitting
2015-05-20 06:57:59,645 INFO org.apache.hadoop.hbase.master.SplitLogManager: dead splitlog workers [us3sm2hbcm003r07.comp.prod.local,60020,1429219103986]
2015-05-20 06:57:59,646 DEBUG org.apache.hadoop.hbase.master.SplitLogManager: Scheduling batch of logs to split
2015-05-20 06:57:59,646 INFO org.apache.hadoop.hbase.master.SplitLogManager: started splitting logs in [hdfs://haprod/author_details/.logs/us3sm2hbcm006r07.comp.prod.local,60020,1429219111318-splitting]
2015-05-20 06:57:59,649 DEBUG org.apache.hadoop.hbase.master.SplitLogManager: Scheduling batch of logs to split
2015-05-20 06:57:59,649 INFO org.apache.hadoop.hbase.master.SplitLogManager: started splitting logs in [hdfs://haprod/author_details/.logs/us3sm2hbcm003r07.comp.prod.local,60020,1429219103986-splitting]
2015-05-20 06:57:59,745 WARN org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper: Possibly transient ZooKeeper exception: org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss for /hbase/unassigned/70236052
2015-05-20 06:57:59,745 INFO org.apache.hadoop.hbase.util.RetryCounter: The 1 times to retry after sleeping 2000 ms
2015-05-20 06:57:59,746 WARN org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper: Possibly transient ZooKeeper exception: org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss for /hbase/splitlog
2015-05-20 06:57:59,746 WARN org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper: Possibly transient ZooKeeper exception: org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss for /hbase/splitlog
2015-05-20 06:57:59,746 INFO org.apache.hadoop.hbase.util.RetryCounter: The 1 times to retry after sleeping 2000 ms
2015-05-20 06:57:59,746 INFO org.apache.hadoop.hbase.util.RetryCounter: The 1 times to retry after sleeping 2000 ms
2015-05-20 06:57:59,863 ERROR org.apache.hadoop.hbase.master.HMaster: Region server ^@^@us3sm2hbcm006r07.comp.prod.local,60020,1429219111318 reported a fatal error:
ABORTING region server us3sm2hbcm006r07.comp.prod.local,60020,1429219111318: regionserver:60020-0x34cc39a9830000e-0x34cc39a9830000e-0x34cc39a9830000e regionserver:60020-0x34cc39a9830000e-0x34cc39a9830000e-0x34cc39a9830000e received expired from ZooKeeper, aborting
Cause:
org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired
at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.connectionEvent(ZooKeeperWatcher.java:374)
at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.process(ZooKeeperWatcher.java:271)
at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:521)
at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:497)
2015-05-20 06:58:00,032 ERROR org.apache.hadoop.hbase.master.HMaster: Region server ^@^@us3sm2hbcm005r09.comp.prod.local,60020,1429219109394 reported a fatal error:
ABORTING region server us3sm2hbcm005r09.comp.prod.local,60020,1429219109394: regionserver:60020-0x34cc39a9830000c-0x34cc39a9830000c-0x34cc39a9830000c regionserver:60020-0x34cc39a9830000c-0x34cc39a9830000c-0x34cc39a9830000c received expired from ZooKeeper, aborting
Cause:
org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired
at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.connectionEvent(ZooKeeperWatcher.java:374)
at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.process(ZooKeeperWatcher.java:271)
at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:521)
at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:497)
2015-05-20 06:58:00,259 ERROR org.apache.hadoop.hbase.master.HMaster: Region server ^@^@us3sm2hbcm003r07.comp.prod.local,60020,1429219103986 reported a fatal error:
ABORTING region server us3sm2hbcm003r07.comp.prod.local,60020,1429219103986: regionserver:60020-0x14cc399c4620009-0x14cc399c4620009-0x14cc399c4620009 regionserver:60020-0x14cc399c4620009-0x14cc399c4620009-0x14cc399c4620009 received expired from ZooKeeper, aborting
Cause:
org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired
2015-05-20 06:50:06,762 INFO org.apache.hadoop.hbase.regionserver.StoreFile$Reader: Loaded ROW CompoundBloomFilter metadata for 7276d0818b0a4d7d8296c54a05a70bcd
2015-05-20 06:50:06,762 INFO org.apache.hadoop.hbase.regionserver.Store: Added hdfs://haprod/author_details/AuthorDetailsMd5_Copy/da7008357c44d9eedc5963e95daf1e65/a/7276d0818b0a4d7d8296c54a05a70bcd, entries=429924, sequenceid=1244581167, memsize=96.0m, filesize=7.2m
2015-05-20 06:50:06,763 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished memstore flush of ~128.0m/134220944, currentsize=47.1k/48240 for region AuthorDetailsMd5_Copy,ke4Bax6FztlPTq5cToX9DA==,1407853846804.da7008357c44d9eedc5963e95daf1e65. in 833ms, sequenceid=1244581167, compaction requested=false
2015-05-20 06:51:29,516 DEBUG org.apache.hadoop.hbase.io.hfile.LruBlockCache: Block cache LRU eviction started; Attempting to free 397.32 MB of total=3.3 GB
2015-05-20 06:51:29,562 DEBUG org.apache.hadoop.hbase.io.hfile.LruBlockCache: Block cache LRU eviction completed; freed=397.38 MB, total=2.91 GB, single=1.75 GB, multi=1.52 GB, memory=0 KB
2015-05-20 06:53:31,745 DEBUG org.apache.hadoop.hbase.io.hfile.LruBlockCache: LRU Stats: total=3.11 GB, free=787.73 MB, max=3.88 GB, blocks=47045, accesses=2541663033, hits=2381038229, hitRatio=93.68%, cachingAccesses=2479309754, cachingHits=2377624792, cachingHitsRatio=95.89%, evictions=15532, evicted=101637917, evictedPerRun=6543.775390625
2015-05-20 06:54:49,246 DEBUG org.apache.hadoop.hbase.io.hfile.LruBlockCache: Block cache LRU eviction started; Attempting to free 397.34 MB of total=3.3 GB
2015-05-20 06:54:49,291 DEBUG org.apache.hadoop.hbase.io.hfile.LruBlockCache: Block cache LRU eviction completed; freed=397.38 MB, total=2.91 GB, single=1.74 GB, multi=1.52 GB, memory=0 KB
2015-05-20 06:57:20,687 DEBUG org.apache.hadoop.hbase.io.hfile.LruBlockCache: Block cache LRU eviction started; Attempting to free 397.3 MB of total=3.3 GB
2015-05-20 06:57:20,731 DEBUG org.apache.hadoop.hbase.io.hfile.LruBlockCache: Block cache LRU eviction completed; freed=397.32 MB, total=2.91 GB, single=1.75 GB, multi=1.52 GB, memory=0 KB
2015-05-20 06:57:59,639 INFO org.apache.zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x34cc39a9830000f, likely server has closed socket, closing socket connection and attempting reconnect
2015-05-20 06:57:59,639 INFO org.apache.zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x34cc39a9830000e, likely server has closed socket, closing socket connection and attempting reconnect
2015-05-20 06:57:59,776 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection to server us3sm2zkcm002.comp.prod.local/10.51.28.222:2181. Will not attempt to authenticate using SASL (unknown error)
2015-05-20 06:57:59,777 INFO org.apache.zookeeper.ClientCnxn: Socket connection established to us3sm2zkcm002.comp.prod.local/10.51.28.222:2181, initiating session
2015-05-20 06:57:59,848 INFO org.apache.zookeeper.ClientCnxn: Unable to reconnect to ZooKeeper service, session 0x34cc39a9830000e has expired, closing socket connection
2015-05-20 06:57:59,860 FATAL org.apache.hadoop.hbase.regionserver.HRegionServer: ABORTING region server us3sm2hbcm006r07.comp.prod.local,60020,1429219111318: regionserver:60020-0x34cc39a9830000e-0x34cc39a9830000e-0x34cc39a9830000e regionserver:60020-0x34cc39a9830000e-0x34cc39a9830000e-0x34cc39a9830000e received expired from ZooKeeper, aborting
org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired
at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.connectionEvent(ZooKeeperWatcher.java:374)
at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.process(ZooKeeperWatcher.java:271)
at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:521)
at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:497)
2015-05-20 06:57:59,861 FATAL org.apache.hadoop.hbase.regionserver.HRegionServer: RegionServer abort: loaded coprocessors are: []
2015-05-20 06:57:59,863 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Dump of metrics: requestsPerSecond=0, numberOfOnlineRegions=6, numberOfStores=6, numberOfStorefiles=14, storefileIndexSizeMB=0, rootIndexSizeKB=569, totalStaticIndexSizeKB=108812, totalStaticBloomSizeKB=282488, memstoreSizeMB=442, mbInMemoryWithoutWAL=0, numberOfPutsWithoutWAL=0, readRequestsCount=284655106, writeRequestsCount=130965073, compactionQueueSize=0, flushQueueSize=0, usedHeapMB=7018, maxHeapMB=15891, blockCacheSizeMB=3104.47, blockCacheFreeMB=868.5, blockCacheCount=45763, blockCacheHitCount=2381209081, blockCacheMissCount=160636141, blockCacheEvictedCount=101650536, blockCacheHitRatio=93%, blockCacheHitCachingRatio=95%, hdfsBlocksLocalityIndex=100, deleteRequestLatencyMean=0, deleteRequestLatencyCount=0, deleteRequestLatencyMedian=0, deleteRequestLatency75th=0, deleteRequestLatency95th=0, deleteRequestLatency99th=0, deleteRequestLatency999th=0, getRequestLatencyMean=4454845.78, getRequestLatencyCount=142327566, getRequestLatencyMedian=3845741, getRequestLatency75th=8990516.5, getRequestLatency95th=17201329.55, getRequestLatency99th=50718254.14, getRequestLatency999th=474934967.91, putRequestLatencyMean=0, putRequestLatencyCount=0, putRequestLatencyMedian=0, putRequestLatency75th=0, putRequestLatency95th=0, putRequestLatency99th=0, putRequestLatency999th=0, fsReadLatencyHistogramMean=4521972.77, fsReadLatencyHistogramCount=130206036, fsReadLatencyHistogramMedian=6041146.5, fsReadLatencyHistogram75th=9932385, fsReadLatencyHistogram95th=18606239, fsReadLatencyHistogram99th=95780608.27, fsReadLatencyHistogram999th=487312635.77, fsWriteLatencyHistogramMean=234201.46, fsWriteLatencyHistogramCount=33046940, fsWriteLatencyHistogramMedian=218762, fsWriteLatencyHistogram75th=398414.75, fsWriteLatencyHistogram95th=432530.85, fsWriteLatencyHistogram99th=490923.63, fsWriteLatencyHistogram999th=1879167.9
2015-05-20 06:57:59,864 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection to server us3sm2zkcm002.comp.prod.local/10.51.28.222:2181. Will not attempt to authenticate using SASL (unknown error)
2015-05-20 06:57:59,864 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: STOPPED: regionserver:60020-0x34cc39a9830000e-0x34cc39a9830000e-0x34cc39a9830000e regionserver:60020-0x34cc39a9830000e-0x34cc39a9830000e-0x34cc39a9830000e received expired from ZooKeeper, aborting
2015-05-20 06:57:59,865 INFO org.apache.zookeeper.ClientCnxn: Socket connection established to us3sm2zkcm002.comp.prod.local/10.51.28.222:2181, initiating session
2015-05-20 06:57:59,865 INFO org.apache.zookeeper.ClientCnxn: EventThread shut down
2015-05-20 06:57:59,867 INFO org.apache.zookeeper.ClientCnxn: Unable to reconnect to ZooKeeper service, session 0x34cc39a9830000f has expired, closing socket connection
2015-05-20 06:57:59,867 INFO org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation: This client just lost it's session with ZooKeeper, trying to reconnect.
2015-05-20 06:57:59,868 INFO org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation: Trying to reconnect to zookeeper
2015-05-20 06:57:59,886 INFO org.apache.zookeeper.ZooKeeper: Initiating client connection, connectString=US3SM2ZKCM003.comp.prod.local:2181,US3SM2ZKCM002.comp.prod.local:2181 sessionTimeout=1200000 watcher=hconnection
2015-05-20 06:57:59,902 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection to server us3sm2zkcm002.comp.prod.local/10.51.28.222:2181. Will not attempt to authenticate using SASL (unknown error)
2015-05-20 06:57:59,902 INFO org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper: The identifier of this process is [email protected]
2015-05-20 06:57:59,903 INFO org.apache.zookeeper.ClientCnxn: Socket connection established to us3sm2zkcm002.comp.prod.local/10.51.28.222:2181, initiating session
2015-05-20 06:57:59,906 INFO org.apache.zookeeper.ClientCnxn: Session establishment complete on server us3sm2zkcm002.comp.prod.local/10.51.28.222:2181, sessionid = 0x24d65ad67c60003, negotiated timeout = 40000
2015-05-20 06:57:59,908 INFO org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation: Reconnected successfully. This disconnect could have been caused by a network partition or a long-running GC pause, either way it's recommended that you verify your environment.
2015-05-20 06:57:59,908 INFO org.apache.zookeeper.ClientCnxn: EventThread shut down
2015-05-20 06:57:59,918 INFO org.apache.hadoop.hbase.regionserver.LogRoller: LogRoller exiting.
2015-05-20 06:58:02,167 INFO org.apache.hadoop.ipc.HBaseServer: Stopping server on 60020
2015-05-20 06:58:02,167 INFO org.apache.hadoop.ipc.HBaseServer: IPC Server handler 5 on 60020: exiting
2015-05-20 06:58:02,167 INFO org.apache.hadoop.ipc.HBaseServer: PRI IPC Server handler 4 on 60020: exiting
2015-05-20 06:58:02,167 INFO org.apache.hadoop.ipc.HBaseServer: PRI IPC Server handler 3 on 60020: exiting
2015-05-20 06:58:02,167 INFO org.apache.hadoop.ipc.HBaseServer: Stopping IPC Server listener on 60020
2015-05-20 06:58:02,167 INFO org.apache.hadoop.ipc.HBaseServer: PRI IPC Server handler 5 on 60020: exiting
2015-05-20 06:58:02,168 INFO org.apache.hadoop.ipc.HBaseServer: IPC Server handler 9 on 60020: exiting
2015-05-20 06:58:02,168 INFO org.apache.hadoop.ipc.HBaseServer: IPC Server handler 0 on 60020: exiting
2015-05-20 06:58:02,168 INFO org.apache.hadoop.hbase.regionserver.SplitLogWorker: Sending interrupt to stop the worker thread
2015-05-20 06:58:02,167 INFO org.apache.hadoop.ipc.HBaseServer: IPC Server handler 4 on 60020: exiting
2015-05-20 06:58:02,167 INFO org.apache.hadoop.ipc.HBaseServer: IPC Server handler 3 on 60020: exiting
2015-05-20 06:58:02,167 INFO org.apache.hadoop.ipc.HBaseServer: IPC Server handler 2 on 60020: exiting
2015-05-20 06:58:02,167 INFO org.apache.hadoop.ipc.HBaseServer: IPC Server handler 7 on 60020: exiting
2015-05-20 06:58:02,168 INFO org.apache.hadoop.hbase.regionserver.SplitLogWorker: SplitLogWorker interrupted while waiting for task, exiting: java.lang.InterruptedException
@apple-corps
Copy link
Copy Markdown
Author

                                                                      2015-05-20 06:57:59,764 [myid:2] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.223:41837

2015-05-20 06:57:59,770 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to establish new session at /10.51.28.223:41837
2015-05-20 06:57:59,774 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer@595] - Established session 0x24d65ad67c60000 with negotiated timeout 40000 for client /10.51.28.223:41837
2015-05-20 06:57:59,778 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.190:38101
2015-05-20 06:57:59,779 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@824] - Client attempting to renew session 0x34cc39a9830000e at /10.51.28.190:38101
2015-05-20 06:57:59,779 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@107] - Revalidating client: 0x34cc39a9830000e
2015-05-20 06:57:59,780 [myid:2] - INFO [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@588] - Invalid session 0x34cc39a9830000e for client /10.51.28.190:38101, probably expired
2015-05-20 06:57:59,781 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.190:38101 which had sessionid 0x34cc39a9830000e
2015-05-20 06:57:59,803 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.188:54005
2015-05-20 06:57:59,803 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@824] - Client attempting to renew session 0x34cc39a9830000b at /10.51.28.188:54005
2015-05-20 06:57:59,803 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@107] - Revalidating client: 0x34cc39a9830000b
2015-05-20 06:57:59,804 [myid:2] - INFO [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@588] - Invalid session 0x34cc39a9830000b for client /10.51.28.188:54005, probably expired
2015-05-20 06:57:59,804 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.188:54005 which had sessionid 0x34cc39a9830000b
2015-05-20 06:57:59,817 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.188:54006
2015-05-20 06:57:59,818 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to establish new session at /10.51.28.188:54006
2015-05-20 06:57:59,822 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer@595] - Established session 0x24d65ad67c60001 with negotiated timeout 40000 for client /10.51.28.188:54006
2015-05-20 06:57:59,866 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.190:38102
2015-05-20 06:57:59,867 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@824] - Client attempting to renew session 0x34cc39a9830000f at /10.51.28.190:38102
2015-05-20 06:57:59,867 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@107] - Revalidating client: 0x34cc39a9830000f
2015-05-20 06:57:59,868 [myid:2] - INFO [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@588] - Invalid session 0x34cc39a9830000f for client /10.51.28.190:38102, probably expired
2015-05-20 06:57:59,868 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.190:38102 which had sessionid 0x34cc39a9830000f
2015-05-20 06:57:59,872 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.192:38246
2015-05-20 06:57:59,874 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to establish new session at /10.51.28.192:38246
2015-05-20 06:57:59,876 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer@595] - Established session 0x24d65ad67c60002 with negotiated timeout 40000 for client /10.51.28.192:38246
2015-05-20 06:57:59,904 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.190:38103
2015-05-20 06:57:59,905 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to establish new session at /10.51.28.190:38103
2015-05-20 06:57:59,908 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer@595] - Established session 0x24d65ad67c60003 with negotiated timeout 40000 for client /10.51.28.190:38103
2015-05-20 06:58:00,007 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.189:43108
2015-05-20 06:58:00,007 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@824] - Client attempting to renew session 0x34cc39a9830000d at /10.51.28.189:43108
2015-05-20 06:58:00,007 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@107] - Revalidating client: 0x34cc39a9830000d
2015-05-20 06:58:00,008 [myid:2] - INFO [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@588] - Invalid session 0x34cc39a9830000d for client /10.51.28.189:43108, probably expired
2015-05-20 06:58:00,009 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.189:43108 which had sessionid 0x34cc39a9830000d
2015-05-20 06:58:00,012 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.189:43109
2015-05-20 06:58:00,013 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@824] - Client attempting to renew session 0x34cc39a9830000c at /10.51.28.189:43109
2015-05-20 06:58:00,013 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@107] - Revalidating client: 0x34cc39a9830000c
2015-05-20 06:58:00,013 [myid:2] - INFO [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@588] - Invalid session 0x34cc39a9830000c for client /10.51.28.189:43109, probably expired
2015-05-20 06:58:00,014 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.189:43109 which had sessionid 0x34cc39a9830000c
2015-05-20 06:58:00,051 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.189:43110
2015-05-20 06:58:00,052 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to establish new session at /10.51.28.189:43110
2015-05-20 06:58:00,052 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.223:41845
2015-05-20 06:58:00,053 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@824] - Client attempting to renew session 0x34cc39a98300014 at /10.51.28.223:41845
2015-05-20 06:58:00,053 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@107] - Revalidating client: 0x34cc39a98300014
2015-05-20 06:58:00,054 [myid:2] - INFO [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@588] - Invalid session 0x34cc39a98300014 for client /10.51.28.223:41845, probably expired
2015-05-20 06:58:00,055 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer@595] - Established session 0x24d65ad67c60004 with negotiated timeout 40000 for client /10.51.28.189:43110
2015-05-20 06:58:00,055 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.223:41845 which had sessionid 0x34cc39a98300014
2015-05-20 06:58:00,179 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.221:59523
2015-05-20 06:58:00,180 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to establish new session at /10.51.28.221:59523
2015-05-20 06:58:00,185 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer@595] - Established session 0x24d65ad67c60005 with negotiated timeout 40000 for client /10.51.28.221:59523
2015-05-20 06:58:00,488 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.188:54007
2015-05-20 06:58:00,489 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@824] - Client attempting to renew session 0x34cc39a9830000a at /10.51.28.188:54007
2015-05-20 06:58:00,489 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@107] - Revalidating client: 0x34cc39a9830000a
2015-05-20 06:58:00,490 [myid:2] - INFO [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@588] - Invalid session 0x34cc39a9830000a for client /10.51.28.188:54007, probably expired
2015-05-20 06:58:00,490 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.188:54007 which had sessionid 0x34cc39a9830000a
2015-05-20 06:58:00,491 [myid:2] - ERROR [CommitProcessor:2:NIOServerCnxn@180] - Unexpected Exception:
java.nio.channels.CancelledKeyException
at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
at org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153)
at org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1075)
at org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:404)
at org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:74)
2015-05-20 06:58:00,515 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.223:41850
2015-05-20 06:58:00,519 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to establish new session at /10.51.28.223:41850
2015-05-20 06:58:00,522 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer@595] - Established session 0x24d65ad67c60006 with negotiated timeout 40000 for client /10.51.28.223:41850
2015-05-20 06:58:00,628 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.187:50644
2015-05-20 06:58:00,629 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to establish new session at /10.51.28.187:50644
2015-05-20 06:58:00,631 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer@595] - Established session 0x24d65ad67c60007 with negotiated timeout 40000 for client /10.51.28.187:50644
2015-05-20 06:58:01,393 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.192:38246 which had sessionid 0x24d65ad67c60002
2015-05-20 06:58:01,752 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.221:59529
2015-05-20 06:58:01,753 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@202] - Accepted socket connection from /10.51.28.221:59530
2015-05-20 06:58:01,756 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to establish new session at /10.51.28.221:59529
2015-05-20 06:58:01,759 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to establish new session at /10.51.28.221:59530
2015-05-20 06:58:01,760 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer@595] - Established session 0x24d65ad67c60008 with negotiated timeout 40000 for client /10.51.28.221:59529
2015-05-20 06:58:01,765 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer@595] - Established session 0x24d65ad67c60009 with negotiated timeout 40000 for client /10.51.28.221:59530
2015-05-20 06:58:01,791 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.188:54006 which had sessionid 0x24d65ad67c60001
2015-05-20 06:58:02,041 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.189:43110 which had sessionid 0x24d65ad67c60004
2015-05-20 06:58:02,336 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.190:38103 which had sessionid 0x24d65ad67c60003
2015-05-20 06:58:02,597 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /10.51.28.187:50644 which had sessionid 0x24d65ad67c60007

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment