Hi, after a planned power outage one of our HBase clusters isn’t coming back up healthy. The master shows the 16 region servers but zero regions. All the RegionServers are experiencing the same problem, which is that they’re getting a BadVersion error from ZooKeeper. This was with HBase 1.1.2 and I just upgraded all the nodes to 1.1.3 to see if this would make a difference, but it didn’t.
2016-01-27 05:54:02,402 WARN [RS_LOG_REPLAY_OPS-r12s4:9104-0] coordination.ZkSplitLogWorkerCoordination: BADVERSION failed to assert ownership for /hbase/splitWAL/WALs%2Fr12s16.sjc.aristanetworks.com %2C9104%2C1452811286456-splitting%2Fr12s16.sjc.aristanetworks.com %252C9104%252C1452811286456.default.1453728374800 org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/WALs%2Fr12s16.sjc.aristanetworks.com %2C9104%2C1452811286456-splitting%2Fr12s16.sjc.aristanetworks.com %252C9104%252C1452811286456.default.1453728374800 at org.apache.zookeeper.KeeperException.create(KeeperException.java:115) at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1270) at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:429) at org.apache.hadoop.hbase.coordination.ZkSplitLogWorkerCoordination.attemptToOwnTask(ZkSplitLogWorkerCoordination.java:370) at org.apache.hadoop.hbase.coordination.ZkSplitLogWorkerCoordination$1.progress(ZkSplitLogWorkerCoordination.java:304) at org.apache.hadoop.hbase.util.FSHDFSUtils.checkIfCancelled(FSHDFSUtils.java:329) at org.apache.hadoop.hbase.util.FSHDFSUtils.recoverDFSFileLease(FSHDFSUtils.java:244) at org.apache.hadoop.hbase.util.FSHDFSUtils.recoverFileLease(FSHDFSUtils.java:162) at org.apache.hadoop.hbase.wal.WALSplitter.getReader(WALSplitter.java:761) at org.apache.hadoop.hbase.wal.WALSplitter.splitLogFile(WALSplitter.java:297) at org.apache.hadoop.hbase.wal.WALSplitter.splitLogFile(WALSplitter.java:235) at org.apache.hadoop.hbase.regionserver.SplitLogWorker$1.exec(SplitLogWorker.java:104) at org.apache.hadoop.hbase.regionserver.handler.WALSplitterHandler.process(WALSplitterHandler.java:72) at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:129) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 2016-01-27 05:54:02,404 WARN [RS_LOG_REPLAY_OPS-r12s4:9104-0] coordination.ZkSplitLogWorkerCoordination: Failed to heartbeat the task/hbase/splitWAL/WALs%2Fr12s16.sjc.aristanetworks.com %2C9104%2C1452811286456-splitting%2Fr12s16.sjc.aristanetworks.com %252C9104%252C1452811286456.default.1453728374800 I’m attaching the full log of the RS this was extracted from, which I just restarted on 1.1.3, in case that’s of any help. I’ve never seen this before and after a bit of digging, I’m not really going anywhere. Any ideas / suggestions? -- Benoit "tsuna" Sigoure
Wed Jan 27 05:51:58 UTC 2016 Starting regionserver on r12s4.sjc.aristanetworks.com core file size (blocks, -c) 0 data seg size (kbytes, -d) unlimited scheduling priority (-e) 0 file size (blocks, -f) unlimited pending signals (-i) 257492 max locked memory (kbytes, -l) 64 max memory size (kbytes, -m) unlimited open files (-n) 1048576 pipe size (512 bytes, -p) 8 POSIX message queues (bytes, -q) 819200 real-time priority (-r) 0 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 1048576 virtual memory (kbytes, -v) unlimited file locks (-x) unlimited 2016-01-27 05:51:58,859 INFO [main] util.VersionInfo: HBase 1.1.3 2016-01-27 05:51:58,859 INFO [main] util.VersionInfo: Source code repository git://diocles.local/Volumes/hbase-1.1.3RC1/hbase revision=72bc50f5fafeb105b2139e42bbee3d61ca724989 2016-01-27 05:51:58,859 INFO [main] util.VersionInfo: Compiled by ndimiduk on Sat Jan 16 18:29:00 PST 2016 2016-01-27 05:51:58,859 INFO [main] util.VersionInfo: From source with checksum 72c910d76fba182fa4e3c7e048275ca3 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:HBASE_LOGFILE=hbase-foo-regionserver-r12s4.sjc.aristanetworks.com.log 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:JAVA_HOME=/usr/lib/jvm/jdk1.8.0_66 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:XFILESEARCHPATH=/usr/dt/app-defaults/%L/Dt 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:LD_LIBRARY_PATH=:/home/foo/hadoop-2.7.1/lib/native 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:HBASE_REST_OPTS= -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.port=11105 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:HBASE_VERSION=1.1.3 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:HADOOP_VERSION=2.7.1 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:PWD=/home/foo/hbase-1.1.3 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:HBASE_CLASSPATH=/home/foo/hadoop-2.7.1/etc/hadoop 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:HBASE_ROOT_LOGGER=INFO,RFA 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:HBASE_HEAPSIZE=10000 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:HBASE_ENV_INIT=true 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:HBASE_IDENT_STRING=foo 2016-01-27 05:51:59,161 INFO [main] util.ServerCommandLine: env:HBASE_ZNODE_FILE=/tmp/hbase-foo-regionserver.znode 2016-01-27 05:51:59,162 INFO [main] util.ServerCommandLine: env:HBASE_LOG_PREFIX=hbase-foo-regionserver-r12s4.sjc.aristanetworks.com 2016-01-27 05:51:59,162 INFO [main] util.ServerCommandLine: env:HBASE_LOG_DIR=/data4/hbase/logs 2016-01-27 05:51:59,162 INFO [main] util.ServerCommandLine: env:USER=foo 2016-01-27 05:51:59,162 INFO [main] util.ServerCommandLine: env:CLASSPATH=/home/foo/hbase-1.1.3/bin/../conf:/usr/lib/jvm/jdk1.8.0_66/lib/tools.jar:/home/foo/hbase-1.1.3/bin/..:/home/foo/hbase-1.1.3/bin/../lib/activation-1.1.jar:/home/foo/hbase-1.1.3/bin/../lib/aopalliance-1.0.jar:/home/foo/hbase-1.1.3/bin/../lib/apacheds-i18n-2.0.0-M15.jar:/home/foo/hbase-1.1.3/bin/../lib/apacheds-kerberos-codec-2.0.0-M15.jar:/home/foo/hbase-1.1.3/bin/../lib/api-asn1-api-1.0.0-M20.jar:/home/foo/hbase-1.1.3/bin/../lib/api-util-1.0.0-M20.jar:/home/foo/hbase-1.1.3/bin/../lib/asm-3.1.jar:/home/foo/hbase-1.1.3/bin/../lib/avro-1.7.4.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-beanutils-1.7.0.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-beanutils-core-1.8.0.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-cli-1.2.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-codec-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-collections-3.2.2.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-compress-1.4.1.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-configuration-1.6.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-daemon-1.0.13.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-digester-1.8.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-el-1.0.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-httpclient-3.1.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-io-2.4.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-lang-2.6.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-logging-1.2.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-math-2.2.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-math3-3.1.1.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-net-3.1.jar:/home/foo/hbase-1.1.3/bin/../lib/disruptor-3.3.0.jar:/home/foo/hbase-1.1.3/bin/../lib/findbugs-annotations-1.3.9-1.jar:/home/foo/hbase-1.1.3/bin/../lib/guava-12.0.1.jar:/home/foo/hbase-1.1.3/bin/../lib/guice-3.0.jar:/home/foo/hbase-1.1.3/bin/../lib/guice-servlet-3.0.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-annotations-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-auth-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-client-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-common-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-hdfs-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-mapreduce-client-app-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-mapreduce-client-common-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-mapreduce-client-core-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-mapreduce-client-jobclient-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-mapreduce-client-shuffle-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-yarn-api-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-yarn-client-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-yarn-common-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-yarn-server-common-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-annotations-1.1.3-tests.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-annotations-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-client-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-common-1.1.3-tests.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-common-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-examples-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-hadoop-compat-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-hadoop2-compat-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-it-1.1.3-tests.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-it-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-prefix-tree-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-procedure-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-protocol-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-resource-bundle-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-rest-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-server-1.1.3-tests.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-server-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-shell-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-thrift-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/htrace-core-3.1.0-incubating.jar:/home/foo/hbase-1.1.3/bin/../lib/httpclient-4.2.5.jar:/home/foo/hbase-1.1.3/bin/../lib/httpcore-4.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/jackson-core-asl-1.9.13.jar:/home/foo/hbase-1.1.3/bin/../lib/jackson-jaxrs-1.9.13.jar:/home/foo/hbase-1.1.3/bin/../lib/jackson-mapper-asl-1.9.13.jar:/home/foo/hbase-1.1.3/bin/../lib/jackson-xc-1.9.13.jar:/home/foo/hbase-1.1.3/bin/../lib/jamon-runtime-2.3.1.jar:/home/foo/hbase-1.1.3/bin/../lib/jasper-compiler-5.5.23.jar:/home/foo/hbase-1.1.3/bin/../lib/jasper-runtime-5.5.23.jar:/home/foo/hbase-1.1.3/bin/../lib/java-xmlbuilder-0.4.jar:/home/foo/hbase-1.1.3/bin/../lib/javax.inject-1.jar:/home/foo/hbase-1.1.3/bin/../lib/jaxb-api-2.2.2.jar:/home/foo/hbase-1.1.3/bin/../lib/jaxb-impl-2.2.3-1.jar:/home/foo/hbase-1.1.3/bin/../lib/jcodings-1.0.8.jar:/home/foo/hbase-1.1.3/bin/../lib/jersey-client-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/jersey-core-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/jersey-guice-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/jersey-json-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/jersey-server-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/jets3t-0.9.0.jar:/home/foo/hbase-1.1.3/bin/../lib/jettison-1.3.3.jar:/home/foo/hbase-1.1.3/bin/../lib/jetty-6.1.26.jar:/home/foo/hbase-1.1.3/bin/../lib/jetty-sslengine-6.1.26.jar:/home/foo/hbase-1.1.3/bin/../lib/jetty-util-6.1.26.jar:/home/foo/hbase-1.1.3/bin/../lib/joni-2.1.2.jar:/home/foo/hbase-1.1.3/bin/../lib/jruby-complete-1.6.8.jar:/home/foo/hbase-1.1.3/bin/../lib/jsch-0.1.42.jar:/home/foo/hbase-1.1.3/bin/../lib/jsp-2.1-6.1.14.jar:/home/foo/hbase-1.1.3/bin/../lib/jsp-api-2.1-6.1.14.jar:/home/foo/hbase-1.1.3/bin/../lib/jsr305-1.3.9.jar:/home/foo/hbase-1.1.3/bin/../lib/junit-4.12.jar:/home/foo/hbase-1.1.3/bin/../lib/leveldbjni-all-1.8.jar:/home/foo/hbase-1.1.3/bin/../lib/libthrift-0.9.0.jar:/home/foo/hbase-1.1.3/bin/../lib/log4j-1.2.17.jar:/home/foo/hbase-1.1.3/bin/../lib/metrics-core-2.2.0.jar:/home/foo/hbase-1.1.3/bin/../lib/netty-3.2.4.Final.jar:/home/foo/hbase-1.1.3/bin/../lib/netty-all-4.0.23.Final.jar:/home/foo/hbase-1.1.3/bin/../lib/paranamer-2.3.jar:/home/foo/hbase-1.1.3/bin/../lib/protobuf-java-2.5.0.jar:/home/foo/hbase-1.1.3/bin/../lib/servlet-api-2.5-6.1.14.jar:/home/foo/hbase-1.1.3/bin/../lib/servlet-api-2.5.jar:/home/foo/hbase-1.1.3/bin/../lib/slf4j-api-1.7.7.jar:/home/foo/hbase-1.1.3/bin/../lib/slf4j-log4j12-1.7.5.jar:/home/foo/hbase-1.1.3/bin/../lib/snappy-java-1.0.4.1.jar:/home/foo/hbase-1.1.3/bin/../lib/spymemcached-2.11.6.jar:/home/foo/hbase-1.1.3/bin/../lib/xmlenc-0.52.jar:/home/foo/hbase-1.1.3/bin/../lib/xz-1.0.jar:/home/foo/hbase-1.1.3/bin/../lib/zookeeper-3.4.6.jar::/home/foo/hadoop-2.7.1/etc/hadoop 2016-01-27 05:51:59,162 INFO [main] util.ServerCommandLine: env:SERVER_GC_OPTS=-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data4/hbase/logs/hbase-foo-regionserver-r12s4.sjc.aristanetworks.com.gc -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=4 -XX:GCLogFileSize=256M 2016-01-27 05:51:59,162 INFO [main] util.ServerCommandLine: env:HBASE_LIBRARY_PATH=/home/foo/hadoop-2.7.1/lib/native 2016-01-27 05:51:59,162 INFO [main] util.ServerCommandLine: env:HOSTNAME=r12s4.sjc.aristanetworks.com 2016-01-27 05:51:59,162 INFO [main] util.ServerCommandLine: env:NLSPATH=/usr/dt/lib/nls/msg/%L/%N.cat 2016-01-27 05:51:59,163 INFO [main] util.ServerCommandLine: env:HBASE_NICENESS=0 2016-01-27 05:51:59,163 INFO [main] util.ServerCommandLine: env:SNAPPY_VERSION=1.1.1.7-2 2016-01-27 05:51:59,163 INFO [main] util.ServerCommandLine: env:HBASE_START_FILE=/tmp/hbase-foo-regionserver.autorestart 2016-01-27 05:51:59,163 INFO [main] util.ServerCommandLine: env:HBASE_SECURITY_LOGGER=INFO,RFAS 2016-01-27 05:51:59,163 INFO [main] util.ServerCommandLine: env:HBASE_THRIFT_OPTS= -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.port=11103 2016-01-27 05:51:59,163 INFO [main] util.ServerCommandLine: env:HBASE_HOME=/home/foo/hbase-1.1.3/bin/.. 2016-01-27 05:51:59,163 INFO [main] util.ServerCommandLine: env:HOME=/home/foo 2016-01-27 05:51:59,163 INFO [main] util.ServerCommandLine: env:SHLVL=2 2016-01-27 05:51:59,163 INFO [main] util.ServerCommandLine: env:MALLOC_ARENA_MAX=4 2016-01-27 05:51:59,163 INFO [main] util.ServerCommandLine: vmName=Java HotSpot(TM) 64-Bit Server VM, vmVendor=Oracle Corporation, vmVersion=25.66-b17 2016-01-27 05:51:59,164 INFO [main] util.ServerCommandLine: vmInputArguments=[-Dproc_regionserver, -XX:OnOutOfMemoryError=kill -9 %p, -Xmx10000m, -verbose:gc, -XX:+PrintGCDetails, -XX:+PrintGCDateStamps, -Xloggc:/data4/hbase/logs/hbase-foo-regionserver-r12s4.sjc.aristanetworks.com.gc, -XX:+UseGCLogFileRotation, -XX:NumberOfGCLogFiles=4, -XX:GCLogFileSize=256M, -Dhbase.log.dir=/data4/hbase/logs, -Dhbase.log.file=hbase-foo-regionserver-r12s4.sjc.aristanetworks.com.log, -Dhbase.home.dir=/home/foo/hbase-1.1.3/bin/.., -Dhbase.id.str=foo, -Dhbase.root.logger=INFO,RFA, -Djava.library.path=/home/foo/hadoop-2.7.1/lib/native, -Dhbase.security.logger=INFO,RFAS] 2016-01-27 05:51:59,399 INFO [main] regionserver.RSRpcServices: regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104 server-side HConnection retries=350 2016-01-27 05:51:59,534 INFO [main] ipc.SimpleRpcScheduler: Using deadline as user call queue, count=5 2016-01-27 05:51:59,554 INFO [main] ipc.RpcServer: regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104: started 10 reader(s) listening on port=9104 2016-01-27 05:51:59,611 INFO [main] impl.MetricsConfig: loaded properties from hadoop-metrics2-hbase.properties 2016-01-27 05:51:59,674 INFO [main] impl.MetricsSystemImpl: Scheduled snapshot period at 10 second(s). 2016-01-27 05:51:59,674 INFO [main] impl.MetricsSystemImpl: HBase metrics system started 2016-01-27 05:52:00,184 INFO [main] fs.HFileSystem: Added intercepting call to namenode#getBlockLocations so can do block reordering using class class org.apache.hadoop.hbase.fs.HFileSystem$ReorderWALBlocks 2016-01-27 05:52:00,365 INFO [main] zookeeper.RecoverableZooKeeper: Process identifier=regionserver:9104 connecting to ZooKeeper ensemble=0.zookeeper:2181,1.zookeeper:2181,2.zookeeper:2181 2016-01-27 05:52:00,371 INFO [main] zookeeper.ZooKeeper: Client environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT 2016-01-27 05:52:00,371 INFO [main] zookeeper.ZooKeeper: Client environment:host.name=r12s4.sjc.aristanetworks.com 2016-01-27 05:52:00,371 INFO [main] zookeeper.ZooKeeper: Client environment:java.version=1.8.0_66 2016-01-27 05:52:00,371 INFO [main] zookeeper.ZooKeeper: Client environment:java.vendor=Oracle Corporation 2016-01-27 05:52:00,371 INFO [main] zookeeper.ZooKeeper: Client environment:java.home=/usr/lib/jvm/jdk1.8.0_66/jre 2016-01-27 05:52:00,372 INFO [main] zookeeper.ZooKeeper: Client environment:java.class.path=/home/foo/hbase-1.1.3/bin/../conf:/usr/lib/jvm/jdk1.8.0_66/lib/tools.jar:/home/foo/hbase-1.1.3/bin/..:/home/foo/hbase-1.1.3/bin/../lib/activation-1.1.jar:/home/foo/hbase-1.1.3/bin/../lib/aopalliance-1.0.jar:/home/foo/hbase-1.1.3/bin/../lib/apacheds-i18n-2.0.0-M15.jar:/home/foo/hbase-1.1.3/bin/../lib/apacheds-kerberos-codec-2.0.0-M15.jar:/home/foo/hbase-1.1.3/bin/../lib/api-asn1-api-1.0.0-M20.jar:/home/foo/hbase-1.1.3/bin/../lib/api-util-1.0.0-M20.jar:/home/foo/hbase-1.1.3/bin/../lib/asm-3.1.jar:/home/foo/hbase-1.1.3/bin/../lib/avro-1.7.4.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-beanutils-1.7.0.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-beanutils-core-1.8.0.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-cli-1.2.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-codec-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-collections-3.2.2.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-compress-1.4.1.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-configuration-1.6.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-daemon-1.0.13.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-digester-1.8.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-el-1.0.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-httpclient-3.1.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-io-2.4.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-lang-2.6.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-logging-1.2.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-math-2.2.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-math3-3.1.1.jar:/home/foo/hbase-1.1.3/bin/../lib/commons-net-3.1.jar:/home/foo/hbase-1.1.3/bin/../lib/disruptor-3.3.0.jar:/home/foo/hbase-1.1.3/bin/../lib/findbugs-annotations-1.3.9-1.jar:/home/foo/hbase-1.1.3/bin/../lib/guava-12.0.1.jar:/home/foo/hbase-1.1.3/bin/../lib/guice-3.0.jar:/home/foo/hbase-1.1.3/bin/../lib/guice-servlet-3.0.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-annotations-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-auth-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-client-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-common-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-hdfs-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-mapreduce-client-app-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-mapreduce-client-common-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-mapreduce-client-core-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-mapreduce-client-jobclient-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-mapreduce-client-shuffle-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-yarn-api-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-yarn-client-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-yarn-common-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hadoop-yarn-server-common-2.5.1.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-annotations-1.1.3-tests.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-annotations-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-client-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-common-1.1.3-tests.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-common-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-examples-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-hadoop-compat-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-hadoop2-compat-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-it-1.1.3-tests.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-it-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-prefix-tree-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-procedure-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-protocol-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-resource-bundle-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-rest-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-server-1.1.3-tests.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-server-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-shell-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/hbase-thrift-1.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/htrace-core-3.1.0-incubating.jar:/home/foo/hbase-1.1.3/bin/../lib/httpclient-4.2.5.jar:/home/foo/hbase-1.1.3/bin/../lib/httpcore-4.1.3.jar:/home/foo/hbase-1.1.3/bin/../lib/jackson-core-asl-1.9.13.jar:/home/foo/hbase-1.1.3/bin/../lib/jackson-jaxrs-1.9.13.jar:/home/foo/hbase-1.1.3/bin/../lib/jackson-mapper-asl-1.9.13.jar:/home/foo/hbase-1.1.3/bin/../lib/jackson-xc-1.9.13.jar:/home/foo/hbase-1.1.3/bin/../lib/jamon-runtime-2.3.1.jar:/home/foo/hbase-1.1.3/bin/../lib/jasper-compiler-5.5.23.jar:/home/foo/hbase-1.1.3/bin/../lib/jasper-runtime-5.5.23.jar:/home/foo/hbase-1.1.3/bin/../lib/java-xmlbuilder-0.4.jar:/home/foo/hbase-1.1.3/bin/../lib/javax.inject-1.jar:/home/foo/hbase-1.1.3/bin/../lib/jaxb-api-2.2.2.jar:/home/foo/hbase-1.1.3/bin/../lib/jaxb-impl-2.2.3-1.jar:/home/foo/hbase-1.1.3/bin/../lib/jcodings-1.0.8.jar:/home/foo/hbase-1.1.3/bin/../lib/jersey-client-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/jersey-core-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/jersey-guice-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/jersey-json-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/jersey-server-1.9.jar:/home/foo/hbase-1.1.3/bin/../lib/jets3t-0.9.0.jar:/home/foo/hbase-1.1.3/bin/../lib/jettison-1.3.3.jar:/home/foo/hbase-1.1.3/bin/../lib/jetty-6.1.26.jar:/home/foo/hbase-1.1.3/bin/../lib/jetty-sslengine-6.1.26.jar:/home/foo/hbase-1.1.3/bin/../lib/jetty-util-6.1.26.jar:/home/foo/hbase-1.1.3/bin/../lib/joni-2.1.2.jar:/home/foo/hbase-1.1.3/bin/../lib/jruby-complete-1.6.8.jar:/home/foo/hbase-1.1.3/bin/../lib/jsch-0.1.42.jar:/home/foo/hbase-1.1.3/bin/../lib/jsp-2.1-6.1.14.jar:/home/foo/hbase-1.1.3/bin/../lib/jsp-api-2.1-6.1.14.jar:/home/foo/hbase-1.1.3/bin/../lib/jsr305-1.3.9.jar:/home/foo/hbase-1.1.3/bin/../lib/junit-4.12.jar:/home/foo/hbase-1.1.3/bin/../lib/leveldbjni-all-1.8.jar:/home/foo/hbase-1.1.3/bin/../lib/libthrift-0.9.0.jar:/home/foo/hbase-1.1.3/bin/../lib/log4j-1.2.17.jar:/home/foo/hbase-1.1.3/bin/../lib/metrics-core-2.2.0.jar:/home/foo/hbase-1.1.3/bin/../lib/netty-3.2.4.Final.jar:/home/foo/hbase-1.1.3/bin/../lib/netty-all-4.0.23.Final.jar:/home/foo/hbase-1.1.3/bin/../lib/paranamer-2.3.jar:/home/foo/hbase-1.1.3/bin/../lib/protobuf-java-2.5.0.jar:/home/foo/hbase-1.1.3/bin/../lib/servlet-api-2.5-6.1.14.jar:/home/foo/hbase-1.1.3/bin/../lib/servlet-api-2.5.jar:/home/foo/hbase-1.1.3/bin/../lib/slf4j-api-1.7.7.jar:/home/foo/hbase-1.1.3/bin/../lib/slf4j-log4j12-1.7.5.jar:/home/foo/hbase-1.1.3/bin/../lib/snappy-java-1.0.4.1.jar:/home/foo/hbase-1.1.3/bin/../lib/spymemcached-2.11.6.jar:/home/foo/hbase-1.1.3/bin/../lib/xmlenc-0.52.jar:/home/foo/hbase-1.1.3/bin/../lib/xz-1.0.jar:/home/foo/hbase-1.1.3/bin/../lib/zookeeper-3.4.6.jar::/home/foo/hadoop-2.7.1/etc/hadoop 2016-01-27 05:52:00,372 INFO [main] zookeeper.ZooKeeper: Client environment:java.library.path=/home/foo/hadoop-2.7.1/lib/native 2016-01-27 05:52:00,372 INFO [main] zookeeper.ZooKeeper: Client environment:java.io.tmpdir=/tmp 2016-01-27 05:52:00,372 INFO [main] zookeeper.ZooKeeper: Client environment:java.compiler=<NA> 2016-01-27 05:52:00,372 INFO [main] zookeeper.ZooKeeper: Client environment:os.name=Linux 2016-01-27 05:52:00,372 INFO [main] zookeeper.ZooKeeper: Client environment:os.arch=amd64 2016-01-27 05:52:00,372 INFO [main] zookeeper.ZooKeeper: Client environment:os.version=4.2.2-coreos-r2 2016-01-27 05:52:00,372 INFO [main] zookeeper.ZooKeeper: Client environment:user.name=foo 2016-01-27 05:52:00,372 INFO [main] zookeeper.ZooKeeper: Client environment:user.home=/home/foo 2016-01-27 05:52:00,372 INFO [main] zookeeper.ZooKeeper: Client environment:user.dir=/home/foo/hbase-1.1.3 2016-01-27 05:52:00,373 INFO [main] zookeeper.ZooKeeper: Initiating client connection, connectString=0.zookeeper:2181,1.zookeeper:2181,2.zookeeper:2181 sessionTimeout=90000 watcher=regionserver:91040x0, quorum=0.zookeeper:2181,1.zookeeper:2181,2.zookeeper:2181, baseZNode=/hbase 2016-01-27 05:52:00,392 INFO [main-SendThread(r12s9.sjc.aristanetworks.com:2181)] zookeeper.ClientCnxn: Opening socket connection to server r12s9.sjc.aristanetworks.com/172.24.32.9:2181. Will not attempt to authenticate using SASL (unknown error) 2016-01-27 05:52:00,396 INFO [main-SendThread(r12s9.sjc.aristanetworks.com:2181)] zookeeper.ClientCnxn: Socket connection established to r12s9.sjc.aristanetworks.com/172.24.32.9:2181, initiating session 2016-01-27 05:52:00,410 INFO [main-SendThread(r12s9.sjc.aristanetworks.com:2181)] zookeeper.ClientCnxn: Session establishment complete on server r12s9.sjc.aristanetworks.com/172.24.32.9:2181, sessionid = 0x3527c36549f027b, negotiated timeout = 40000 2016-01-27 05:52:00,429 INFO [RpcServer.responder] ipc.RpcServer: RpcServer.responder: starting 2016-01-27 05:52:00,429 INFO [RpcServer.listener,port=9104] ipc.RpcServer: RpcServer.listener,port=9104: starting 2016-01-27 05:52:00,496 INFO [main] mortbay.log: Logging to org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog 2016-01-27 05:52:00,500 INFO [main] http.HttpRequestLog: Http request log for http.requests.regionserver is not defined 2016-01-27 05:52:00,510 INFO [main] http.HttpServer: Added global filter 'safety' (class=org.apache.hadoop.hbase.http.HttpServer$QuotingInputFilter) 2016-01-27 05:52:00,511 INFO [main] http.HttpServer: Added filter static_user_filter (class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter) to context regionserver 2016-01-27 05:52:00,512 INFO [main] http.HttpServer: Added filter static_user_filter (class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter) to context static 2016-01-27 05:52:00,512 INFO [main] http.HttpServer: Added filter static_user_filter (class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter) to context logs 2016-01-27 05:52:00,524 INFO [main] http.HttpServer: Jetty bound to port 9103 2016-01-27 05:52:00,524 INFO [main] mortbay.log: jetty-6.1.26 2016-01-27 05:52:00,740 INFO [main] mortbay.log: Started [email protected]:9103 2016-01-27 05:52:00,787 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x2cdfcd31 connecting to ZooKeeper ensemble=0.zookeeper:2181,1.zookeeper:2181,2.zookeeper:2181 2016-01-27 05:52:00,787 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] zookeeper.ZooKeeper: Initiating client connection, connectString=0.zookeeper:2181,1.zookeeper:2181,2.zookeeper:2181 sessionTimeout=90000 watcher=hconnection-0x2cdfcd310x0, quorum=0.zookeeper:2181,1.zookeeper:2181,2.zookeeper:2181, baseZNode=/hbase 2016-01-27 05:52:00,790 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104-SendThread(r12s5.sjc.aristanetworks.com:2181)] zookeeper.ClientCnxn: Opening socket connection to server r12s5.sjc.aristanetworks.com/172.24.32.5:2181. Will not attempt to authenticate using SASL (unknown error) 2016-01-27 05:52:00,790 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104-SendThread(r12s5.sjc.aristanetworks.com:2181)] zookeeper.ClientCnxn: Socket connection established to r12s5.sjc.aristanetworks.com/172.24.32.5:2181, initiating session 2016-01-27 05:52:00,804 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104-SendThread(r12s5.sjc.aristanetworks.com:2181)] zookeeper.ClientCnxn: Session establishment complete on server r12s5.sjc.aristanetworks.com/172.24.32.5:2181, sessionid = 0x2527c36542d027c, negotiated timeout = 40000 2016-01-27 05:52:00,865 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] regionserver.HRegionServer: ClusterId : b6d96538-0c60-4d8c-85e9-5898dbfd16a8 2016-01-27 05:52:00,916 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] regionserver.MemStoreFlusher: globalMemStoreLimit=3.5 G, globalMemStoreLimitLowMark=3.3 G, maxHeap=8.7 G 2016-01-27 05:52:00,920 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] regionserver.HRegionServer: CompactionChecker runs every 10sec 2016-01-27 05:52:00,949 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] regionserver.RegionServerCoprocessorHost: System coprocessor loading is enabled 2016-01-27 05:52:00,950 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] regionserver.RegionServerCoprocessorHost: Table coprocessor loading is enabled 2016-01-27 05:52:00,954 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] regionserver.HRegionServer: reportForDuty to master=r12s3.sjc.aristanetworks.com,9102,1453873696818 with port=9104, startcode=1453873919688 2016-01-27 05:52:01,116 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] hfile.CacheConfig: Allocating LruBlockCache size=3.47 GB, blockSize=64 KB 2016-01-27 05:52:01,127 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] hfile.CacheConfig: blockCache=LruBlockCache{blockCount=0, currentSize=3824344, freeSize=3724492584, maxSize=3728316928, heapSize=3824344, minSize=3541901056, minFactor=0.95, multiSize=1770950528, multiFactor=0.5, singleSize=885475264, singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false 2016-01-27 05:52:01,226 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] wal.WALFactory: Instantiating WALProvider of type class org.apache.hadoop.hbase.wal.DefaultWALProvider 2016-01-27 05:52:01,372 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] wal.FSHLog: WAL configuration: blocksize=128 MB, rollsize=121.60 MB, prefix=r12s4.sjc.aristanetworks.com%2C9104%2C1453873919688.default, suffix=, logDir=hdfs://0.namenode.sjc.aristanetworks.com:8820/hbase/WALs/r12s4.sjc.aristanetworks.com,9104,1453873919688, archiveDir=hdfs://0.namenode.sjc.aristanetworks.com:8820/hbase/oldWALs 2016-01-27 05:52:01,782 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] wal.FSHLog: Slow sync cost: 224 ms, current pipeline: [] 2016-01-27 05:52:01,784 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] wal.FSHLog: New WAL /hbase/WALs/r12s4.sjc.aristanetworks.com,9104,1453873919688/r12s4.sjc.aristanetworks.com%2C9104%2C1453873919688.default.1453873921372 2016-01-27 05:52:01,811 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] regionserver.MetricsRegionServerWrapperImpl: Computing regionserver metrics every 5000 milliseconds 2016-01-27 05:52:01,836 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] regionserver.ReplicationSourceManager: Current list of replicators: [r12s14.sjc.aristanetworks.com,9104,1453785742994, r12s2.sjc.aristanetworks.com,9104,1453873919713, r12s5.sjc.aristanetworks.com,9104,1453873920108, r12s11.sjc.aristanetworks.com,9104,1453785893471, r12s11.sjc.aristanetworks.com,9104,1453873919623, r12s10.sjc.aristanetworks.com,9104,1453873919762, r12s16.sjc.aristanetworks.com,9104,1453785743245, r12s6.sjc.aristanetworks.com,9104,1453873919996, r12s15.sjc.aristanetworks.com,9104,1453785742831, r12s7.sjc.aristanetworks.com,9104,1453785743694, r12s5.sjc.aristanetworks.com,9104,1453785743411, r12s15.sjc.aristanetworks.com,9104,1453873919845, r12s4.sjc.aristanetworks.com,9104,1453785742949, r12s3.sjc.aristanetworks.com,9104,1453873919553, r12s12.sjc.aristanetworks.com,9104,1453873919724, r12s6.sjc.aristanetworks.com,9104,1453785743131, r12s12.sjc.aristanetworks.com,9104,1453785743438, r12s9.sjc.aristanetworks.com,9104,1453873919799, r12s14.sjc.aristanetworks.com,9104,1453873919711, r12s4.sjc.aristanetworks.com,9104,1453873919688, r12s16.sjc.aristanetworks.com,9104,1453873919798, r12s8.sjc.aristanetworks.com,9104,1453785783387, r12s9.sjc.aristanetworks.com,9104,1453785741208, r12s3.sjc.aristanetworks.com,9104,1453785739822, r12s1.sjc.aristanetworks.com,9104,1453873919645, r12s13.sjc.aristanetworks.com,9104,1453873919678, r12s1.sjc.aristanetworks.com,9104,1453785743929, r12s10.sjc.aristanetworks.com,9104,1453785743707, r12s7.sjc.aristanetworks.com,9104,1453873919985, r12s2.sjc.aristanetworks.com,9104,1453785743025, r12s8.sjc.aristanetworks.com,9104,1453873919941, r12s13.sjc.aristanetworks.com,9104,1453785743246] other RSs: [r12s14.sjc.aristanetworks.com,9104,1453785742994, r12s2.sjc.aristanetworks.com,9104,1453873919713, r12s5.sjc.aristanetworks.com,9104,1453873920108, r12s11.sjc.aristanetworks.com,9104,1453785893471, r12s11.sjc.aristanetworks.com,9104,1453873919623, r12s10.sjc.aristanetworks.com,9104,1453873919762, r12s16.sjc.aristanetworks.com,9104,1453785743245, r12s6.sjc.aristanetworks.com,9104,1453873919996, r12s15.sjc.aristanetworks.com,9104,1453785742831, r12s7.sjc.aristanetworks.com,9104,1453785743694, r12s5.sjc.aristanetworks.com,9104,1453785743411, r12s15.sjc.aristanetworks.com,9104,1453873919845, r12s4.sjc.aristanetworks.com,9104,1453785742949, r12s3.sjc.aristanetworks.com,9104,1453873919553, r12s12.sjc.aristanetworks.com,9104,1453873919724, r12s6.sjc.aristanetworks.com,9104,1453785743131, r12s12.sjc.aristanetworks.com,9104,1453785743438, r12s9.sjc.aristanetworks.com,9104,1453873919799, r12s14.sjc.aristanetworks.com,9104,1453873919711, r12s4.sjc.aristanetworks.com,9104,1453873919688, r12s16.sjc.aristanetworks.com,9104,1453873919798, r12s8.sjc.aristanetworks.com,9104,1453785783387, r12s9.sjc.aristanetworks.com,9104,1453785741208, r12s3.sjc.aristanetworks.com,9104,1453785739822, r12s1.sjc.aristanetworks.com,9104,1453873919645, r12s13.sjc.aristanetworks.com,9104,1453873919678, r12s1.sjc.aristanetworks.com,9104,1453785743929, r12s10.sjc.aristanetworks.com,9104,1453785743707, r12s7.sjc.aristanetworks.com,9104,1453873919985, r12s2.sjc.aristanetworks.com,9104,1453785743025, r12s8.sjc.aristanetworks.com,9104,1453873919941, r12s13.sjc.aristanetworks.com,9104,1453785743246] 2016-01-27 05:52:01,878 INFO [SplitLogWorker-r12s4:9104] regionserver.SplitLogWorker: SplitLogWorker r12s4.sjc.aristanetworks.com,9104,1453873919688 starting 2016-01-27 05:52:01,879 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] regionserver.HeapMemoryManager: Starting HeapMemoryTuner chore. 2016-01-27 05:52:01,881 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] regionserver.HRegionServer: Serving as r12s4.sjc.aristanetworks.com,9104,1453873919688, RpcServer on r12s4.sjc.aristanetworks.com/172.24.32.4:9104, sessionid=0x3527c36549f027b 2016-01-27 05:52:01,920 INFO [regionserver/r12s4.sjc.aristanetworks.com/172.24.32.4:9104] quotas.RegionServerQuotaManager: Quota support disabled 2016-01-27 05:52:02,057 INFO [SplitLogWorker-r12s4:9104] coordination.ZkSplitLogWorkerCoordination: worker r12s4.sjc.aristanetworks.com,9104,1453873919688 acquired task /hbase/splitWAL/WALs%2Fr12s16.sjc.aristanetworks.com%2C9104%2C1452811286456-splitting%2Fr12s16.sjc.aristanetworks.com%252C9104%252C1452811286456.default.1453728374800 2016-01-27 05:52:02,090 INFO [RS_LOG_REPLAY_OPS-r12s4:9104-0] wal.WALSplitter: Splitting wal: hdfs://0.namenode.sjc.aristanetworks.com:8820/hbase/WALs/r12s16.sjc.aristanetworks.com,9104,1452811286456-splitting/r12s16.sjc.aristanetworks.com%2C9104%2C1452811286456.default.1453728374800, length=83 2016-01-27 05:52:02,090 INFO [RS_LOG_REPLAY_OPS-r12s4:9104-0] wal.WALSplitter: DistributedLogReplay = false 2016-01-27 05:52:02,120 INFO [RS_LOG_REPLAY_OPS-r12s4:9104-0] util.FSHDFSUtils: Recovering lease on dfs file hdfs://0.namenode.sjc.aristanetworks.com:8820/hbase/WALs/r12s16.sjc.aristanetworks.com,9104,1452811286456-splitting/r12s16.sjc.aristanetworks.com%2C9104%2C1452811286456.default.1453728374800 2016-01-27 05:52:02,157 INFO [RS_LOG_REPLAY_OPS-r12s4:9104-0] util.FSHDFSUtils: recoverLease=false, attempt=0 on file=hdfs://0.namenode.sjc.aristanetworks.com:8820/hbase/WALs/r12s16.sjc.aristanetworks.com,9104,1452811286456-splitting/r12s16.sjc.aristanetworks.com%2C9104%2C1452811286456.default.1453728374800 after 37ms 2016-01-27 05:52:06,214 INFO [RS_LOG_REPLAY_OPS-r12s4:9104-0] util.FSHDFSUtils: recoverLease=false, attempt=1 on file=hdfs://0.namenode.sjc.aristanetworks.com:8820/hbase/WALs/r12s16.sjc.aristanetworks.com,9104,1452811286456-splitting/r12s16.sjc.aristanetworks.com%2C9104%2C1452811286456.default.1453728374800 after 4094ms 2016-01-27 05:52:26,036 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s16.sjc.aristanetworks.com,9104,1453785743245 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:26,054 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s12.sjc.aristanetworks.com,9104,1453785743438 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:26,069 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s9.sjc.aristanetworks.com,9104,1453785741208 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:34,033 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s2.sjc.aristanetworks.com,9104,1453785743025 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:34,048 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s5.sjc.aristanetworks.com,9104,1453785743411 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:34,058 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s6.sjc.aristanetworks.com,9104,1453785743131 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:34,062 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s1.sjc.aristanetworks.com,9104,1453785743929 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:34,067 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s15.sjc.aristanetworks.com,9104,1453785742831 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:34,072 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s10.sjc.aristanetworks.com,9104,1453785743707 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:34,076 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s14.sjc.aristanetworks.com,9104,1453785742994 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:34,080 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s13.sjc.aristanetworks.com,9104,1453785743246 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:36,032 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s11.sjc.aristanetworks.com,9104,1453785893471 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:36,040 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s4.sjc.aristanetworks.com,9104,1453785742949 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:36,048 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s8.sjc.aristanetworks.com,9104,1453785783387 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:36,051 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s3.sjc.aristanetworks.com,9104,1453785739822 znode expired, triggering replicatorRemoved event 2016-01-27 05:52:40,028 INFO [main-EventThread] replication.ReplicationTrackerZKImpl: /hbase/rs/r12s7.sjc.aristanetworks.com,9104,1453785743694 znode expired, triggering replicatorRemoved event 2016-01-27 05:53:09,221 INFO [ReplicationExecutor-0] replication.ReplicationQueuesZKImpl: Atomically moving r12s16.sjc.aristanetworks.com,9104,1453785743245's wals to my queue 2016-01-27 05:53:10,338 INFO [RS_LOG_REPLAY_OPS-r12s4:9104-0] util.FSHDFSUtils: recoverLease=false, attempt=2 on file=hdfs://0.namenode.sjc.aristanetworks.com:8820/hbase/WALs/r12s16.sjc.aristanetworks.com,9104,1452811286456-splitting/r12s16.sjc.aristanetworks.com%2C9104%2C1452811286456.default.1453728374800 after 68218ms 2016-01-27 05:53:50,499 INFO [ReplicationExecutor-0] replication.ReplicationQueuesZKImpl: Atomically moving r12s12.sjc.aristanetworks.com,9104,1453785743438's wals to my queue 2016-01-27 05:54:02,402 WARN [RS_LOG_REPLAY_OPS-r12s4:9104-0] coordination.ZkSplitLogWorkerCoordination: BADVERSION failed to assert ownership for /hbase/splitWAL/WALs%2Fr12s16.sjc.aristanetworks.com%2C9104%2C1452811286456-splitting%2Fr12s16.sjc.aristanetworks.com%252C9104%252C1452811286456.default.1453728374800 org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/WALs%2Fr12s16.sjc.aristanetworks.com%2C9104%2C1452811286456-splitting%2Fr12s16.sjc.aristanetworks.com%252C9104%252C1452811286456.default.1453728374800 at org.apache.zookeeper.KeeperException.create(KeeperException.java:115) at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1270) at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:429) at org.apache.hadoop.hbase.coordination.ZkSplitLogWorkerCoordination.attemptToOwnTask(ZkSplitLogWorkerCoordination.java:370) at org.apache.hadoop.hbase.coordination.ZkSplitLogWorkerCoordination$1.progress(ZkSplitLogWorkerCoordination.java:304) at org.apache.hadoop.hbase.util.FSHDFSUtils.checkIfCancelled(FSHDFSUtils.java:329) at org.apache.hadoop.hbase.util.FSHDFSUtils.recoverDFSFileLease(FSHDFSUtils.java:244) at org.apache.hadoop.hbase.util.FSHDFSUtils.recoverFileLease(FSHDFSUtils.java:162) at org.apache.hadoop.hbase.wal.WALSplitter.getReader(WALSplitter.java:761) at org.apache.hadoop.hbase.wal.WALSplitter.splitLogFile(WALSplitter.java:297) at org.apache.hadoop.hbase.wal.WALSplitter.splitLogFile(WALSplitter.java:235) at org.apache.hadoop.hbase.regionserver.SplitLogWorker$1.exec(SplitLogWorker.java:104) at org.apache.hadoop.hbase.regionserver.handler.WALSplitterHandler.process(WALSplitterHandler.java:72) at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:129) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 2016-01-27 05:54:02,404 WARN [RS_LOG_REPLAY_OPS-r12s4:9104-0] coordination.ZkSplitLogWorkerCoordination: Failed to heartbeat the task/hbase/splitWAL/WALs%2Fr12s16.sjc.aristanetworks.com%2C9104%2C1452811286456-splitting%2Fr12s16.sjc.aristanetworks.com%252C9104%252C1452811286456.default.1453728374800 2016-01-27 05:54:02,405 INFO [RS_LOG_REPLAY_OPS-r12s4:9104-0] wal.WALSplitter: Processed 0 edits across 0 regions; edits skipped=0; log file=hdfs://0.namenode.sjc.aristanetworks.com:8820/hbase/WALs/r12s16.sjc.aristanetworks.com,9104,1452811286456-splitting/r12s16.sjc.aristanetworks.com%2C9104%2C1452811286456.default.1453728374800, length=83, corrupted=false, progress failed=false 2016-01-27 05:54:02,406 WARN [RS_LOG_REPLAY_OPS-r12s4:9104-0] regionserver.SplitLogWorker: log splitting of WALs/r12s16.sjc.aristanetworks.com,9104,1452811286456-splitting/r12s16.sjc.aristanetworks.com%2C9104%2C1452811286456.default.1453728374800 interrupted, resigning java.io.InterruptedIOException: Operation cancelled at org.apache.hadoop.hbase.util.FSHDFSUtils.checkIfCancelled(FSHDFSUtils.java:329) at org.apache.hadoop.hbase.util.FSHDFSUtils.recoverDFSFileLease(FSHDFSUtils.java:244) at org.apache.hadoop.hbase.util.FSHDFSUtils.recoverFileLease(FSHDFSUtils.java:162) at org.apache.hadoop.hbase.wal.WALSplitter.getReader(WALSplitter.java:761) at org.apache.hadoop.hbase.wal.WALSplitter.splitLogFile(WALSplitter.java:297) at org.apache.hadoop.hbase.wal.WALSplitter.splitLogFile(WALSplitter.java:235) at org.apache.hadoop.hbase.regionserver.SplitLogWorker$1.exec(SplitLogWorker.java:104) at org.apache.hadoop.hbase.regionserver.handler.WALSplitterHandler.process(WALSplitterHandler.java:72) at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:129) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 2016-01-27 05:54:02,418 WARN [RS_LOG_REPLAY_OPS-r12s4:9104-0] coordination.ZkSplitLogWorkerCoordination: transisition task /hbase/splitWAL/WALs%2Fr12s16.sjc.aristanetworks.com%2C9104%2C1452811286456-splitting%2Fr12s16.sjc.aristanetworks.com%252C9104%252C1452811286456.default.1453728374800 to RESIGNED r12s4.sjc.aristanetworks.com,9104,1453873919688 failed because of version mismatch org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/WALs%2Fr12s16.sjc.aristanetworks.com%2C9104%2C1452811286456-splitting%2Fr12s16.sjc.aristanetworks.com%252C9104%252C1452811286456.default.1453728374800 at org.apache.zookeeper.KeeperException.create(KeeperException.java:115) at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1270) at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:429) at org.apache.hadoop.hbase.zookeeper.ZKUtil.setData(ZKUtil.java:940) at org.apache.hadoop.hbase.coordination.ZkSplitLogWorkerCoordination.endTask(ZkSplitLogWorkerCoordination.java:595) at org.apache.hadoop.hbase.regionserver.handler.WALSplitterHandler.process(WALSplitterHandler.java:96) at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:129) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 2016-01-27 05:54:02,419 INFO [RS_LOG_REPLAY_OPS-r12s4:9104-0] handler.WALSplitterHandler: worker r12s4.sjc.aristanetworks.com,9104,1453873919688 done with task org.apache.hadoop.hbase.coordination.ZkSplitLogWorkerCoordination$ZkSplitTaskDetails@31e0516a in 120357ms 2016-01-27 05:54:29,274 INFO [ReplicationExecutor-0] replication.ReplicationQueuesZKImpl: Atomically moving r12s9.sjc.aristanetworks.com,9104,1453785741208's wals to my queue 2016-01-27 05:55:11,815 INFO [ReplicationExecutor-0] replication.ReplicationQueuesZKImpl: Atomically moving r12s2.sjc.aristanetworks.com,9104,1453785743025's wals to my queue 2016-01-27 05:55:50,289 INFO [ReplicationExecutor-0] replication.ReplicationQueuesZKImpl: Atomically moving r12s5.sjc.aristanetworks.com,9104,1453785743411's wals to my queue 2016-01-27 05:55:50,320 INFO [ReplicationExecutor-0] replication.ReplicationQueuesZKImpl: Atomically moved the dead regionserver logs. 2016-01-27 05:56:38,030 INFO [ReplicationExecutor-0] replication.ReplicationQueuesZKImpl: Atomically moving r12s6.sjc.aristanetworks.com,9104,1453785743131's wals to my queue 2016-01-27 05:57:01,128 INFO [LruBlockCacheStatsExecutor] hfile.LruBlockCache: totalSize=3.65 MB, freeSize=3.47 GB, max=3.47 GB, blockCount=0, accesses=0, hits=0, hitRatio=0, cachingAccesses=0, cachingHits=0, cachingHitsRatio=0,evictions=29, evicted=0, evictedPerRun=0.0 2016-01-27 05:57:16,792 INFO [ReplicationExecutor-0] replication.ReplicationQueuesZKImpl: Atomically moving r12s1.sjc.aristanetworks.com,9104,1453785743929's wals to my queue 2016-01-27 05:57:48,649 INFO [ReplicationExecutor-0] replication.ReplicationQueuesZKImpl: Atomically moving r12s15.sjc.aristanetworks.com,9104,1453785742831's wals to my queue 2016-01-27 05:57:48,673 INFO [ReplicationExecutor-0] replication.ReplicationQueuesZKImpl: Atomically moved the dead regionserver logs.
