[
https://issues.apache.org/jira/browse/HBASE-21323?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16655843#comment-16655843
]
stack commented on HBASE-21323:
-------------------------------
Took a look. 2 seems to be the right answer. There is only the parent
procedure, pid=1, and the waiting subprocedure, pid=3, after the store is
restarted (the DummyProcedure has finished, pid=2). Logs are below. Will commit
addendum. Let me know if I have it wrong [~Apache9].
{code}
/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/bin/java
-agentlib:jdwp=transport=dt_socket,address=127.0.0.1:56370,suspend=y,server=n
-ea
-Dtest.build.classes=/Users/stack/checkouts/hbase/hbase-procedure/target/test-classes
-Didea.test.cyclic.buffer.size=1048576
-javaagent:/Users/stack/Library/Caches/IdeaIC2018.1/captureAgent/debugger-agent.jar=file:/private/var/folders/d8/8lyxycpd129d4fj7lb684dwh0000gp/T/capture.props
-Dfile.encoding=UTF-8 -classpath "/Applications/IntelliJ IDEA
CE.app/Contents/lib/idea_rt.jar:/Applications/IntelliJ IDEA
CE.app/Contents/plugins/junit/lib/junit-rt.jar:/Applications/IntelliJ IDEA
CE.app/Contents/plugins/junit/lib/junit5-rt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/charsets.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/deploy.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/ext/cldrdata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/ext/dnsns.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/ext/jaccess.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/ext/jfxrt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/ext/localedata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/ext/nashorn.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/ext/sunec.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/ext/sunjce_provider.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/ext/sunpkcs11.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/ext/zipfs.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/javaws.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/jce.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/jfr.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/jfxswt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/jsse.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/management-agent.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/plugin.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/resources.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/rt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/lib/ant-javafx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/lib/dt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/lib/javafx-mx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/lib/jconsole.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/lib/packager.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/lib/sa-jdi.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/lib/tools.jar:/Users/stack/checkouts/hbase/hbase-procedure/target/test-classes:/Users/stack/checkouts/hbase/hbase-procedure/target/classes:/Users/stack/.m2/repository/commons-codec/commons-codec/1.10/commons-codec-1.10.jar:/Users/stack/.m2/repository/org/apache/commons/commons-lang3/3.6/commons-lang3-3.6.jar:/Users/stack/.m2/repository/commons-io/commons-io/2.5/commons-io-2.5.jar:/Users/stack/.m2/repository/com/google/protobuf/protobuf-java/2.5.0/protobuf-java-2.5.0.jar:/Users/stack/.m2/repository/org/apache/htrace/htrace-core4/4.2.0-incubating/htrace-core4-4.2.0-incubating.jar:/Users/stack/.m2/repository/org/apache/commons/commons-crypto/1.0.0/commons-crypto-1.0.0.jar:/Users/stack/.m2/repository/com/fasterxml/jackson/core/jackson-databind/2.9.2/jackson-databind-2.9.2.jar:/Users/stack/.m2/repository/com/fasterxml/jackson/core/jackson-annotations/2.9.2/jackson-annotations-2.9.2.jar:/Users/stack/.m2/repository/com/fasterxml/jackson/core/jackson-core/2.9.2/jackson-core-2.9.2.jar:/Users/stack/.m2/repository/log4j/log4j/1.2.17/log4j-1.2.17.jar:/Users/stack/.m2/repository/org/apache/hbase/thirdparty/hbase-shaded-protobuf/2.1.0/hbase-shaded-protobuf-2.1.0.jar:/Users/stack/.m2/repository/org/apache/hbase/thirdparty/hbase-shaded-miscellaneous/2.1.0/hbase-shaded-miscellaneous-2.1.0.jar:/Users/stack/.m2/repository/org/slf4j/slf4j-api/1.7.25/slf4j-api-1.7.25.jar:/Users/stack/.m2/repository/com/github/stephenc/findbugs/findbugs-annotations/1.3.9-1/findbugs-annotations-1.3.9-1.jar:/Users/stack/.m2/repository/junit/junit/4.12/junit-4.12.jar:/Users/stack/.m2/repository/org/hamcrest/hamcrest-core/1.3/hamcrest-core-1.3.jar:/Users/stack/.m2/repository/org/mockito/mockito-core/2.1.0/mockito-core-2.1.0.jar:/Users/stack/.m2/repository/net/bytebuddy/byte-buddy/1.4.26/byte-buddy-1.4.26.jar:/Users/stack/.m2/repository/net/bytebuddy/byte-buddy-agent/1.4.26/byte-buddy-agent-1.4.26.jar:/Users/stack/.m2/repository/org/objenesis/objenesis/2.4/objenesis-2.4.jar:/Users/stack/.m2/repository/org/apache/hadoop/hadoop-common/2.7.7/hadoop-common-2.7.7.jar:/Users/stack/.m2/repository/org/apache/hadoop/hadoop-annotations/2.7.7/hadoop-annotations-2.7.7.jar:/Users/stack/.m2/repository/com/google/guava/guava/11.0.2/guava-11.0.2.jar:/Users/stack/.m2/repository/commons-cli/commons-cli/1.2/commons-cli-1.2.jar:/Users/stack/.m2/repository/org/apache/commons/commons-math3/3.6.1/commons-math3-3.6.1.jar:/Users/stack/.m2/repository/xmlenc/xmlenc/0.52/xmlenc-0.52.jar:/Users/stack/.m2/repository/commons-httpclient/commons-httpclient/3.1/commons-httpclient-3.1.jar:/Users/stack/.m2/repository/commons-net/commons-net/3.1/commons-net-3.1.jar:/Users/stack/.m2/repository/commons-collections/commons-collections/3.2.2/commons-collections-3.2.2.jar:/Users/stack/.m2/repository/org/mortbay/jetty/jetty/6.1.26/jetty-6.1.26.jar:/Users/stack/.m2/repository/org/mortbay/jetty/jetty-util/6.1.26/jetty-util-6.1.26.jar:/Users/stack/.m2/repository/org/mortbay/jetty/jetty-sslengine/6.1.26/jetty-sslengine-6.1.26.jar:/Users/stack/.m2/repository/com/sun/jersey/jersey-core/1.9/jersey-core-1.9.jar:/Users/stack/.m2/repository/com/sun/jersey/jersey-json/1.9/jersey-json-1.9.jar:/Users/stack/.m2/repository/org/codehaus/jettison/jettison/1.3.8/jettison-1.3.8.jar:/Users/stack/.m2/repository/com/sun/xml/bind/jaxb-impl/2.2.3-1/jaxb-impl-2.2.3-1.jar:/Users/stack/.m2/repository/javax/xml/bind/jaxb-api/2.2.12/jaxb-api-2.2.12.jar:/Users/stack/.m2/repository/org/codehaus/jackson/jackson-jaxrs/1.8.3/jackson-jaxrs-1.8.3.jar:/Users/stack/.m2/repository/org/codehaus/jackson/jackson-xc/1.8.3/jackson-xc-1.8.3.jar:/Users/stack/.m2/repository/com/sun/jersey/jersey-server/1.9/jersey-server-1.9.jar:/Users/stack/.m2/repository/asm/asm/3.1/asm-3.1.jar:/Users/stack/.m2/repository/commons-logging/commons-logging/1.2/commons-logging-1.2.jar:/Users/stack/.m2/repository/net/java/dev/jets3t/jets3t/0.9.0/jets3t-0.9.0.jar:/Users/stack/.m2/repository/org/apache/httpcomponents/httpclient/4.5.3/httpclient-4.5.3.jar:/Users/stack/.m2/repository/org/apache/httpcomponents/httpcore/4.4.6/httpcore-4.4.6.jar:/Users/stack/.m2/repository/com/jamesmurty/utils/java-xmlbuilder/0.4/java-xmlbuilder-0.4.jar:/Users/stack/.m2/repository/commons-lang/commons-lang/2.6/commons-lang-2.6.jar:/Users/stack/.m2/repository/commons-configuration/commons-configuration/1.6/commons-configuration-1.6.jar:/Users/stack/.m2/repository/commons-digester/commons-digester/1.8/commons-digester-1.8.jar:/Users/stack/.m2/repository/commons-beanutils/commons-beanutils-core/1.8.0/commons-beanutils-core-1.8.0.jar:/Users/stack/.m2/repository/org/slf4j/slf4j-log4j12/1.7.25/slf4j-log4j12-1.7.25.jar:/Users/stack/.m2/repository/org/apache/avro/avro/1.7.7/avro-1.7.7.jar:/Users/stack/.m2/repository/com/thoughtworks/paranamer/paranamer/2.3/paranamer-2.3.jar:/Users/stack/.m2/repository/org/xerial/snappy/snappy-java/1.0.5/snappy-java-1.0.5.jar:/Users/stack/.m2/repository/com/google/code/gson/gson/2.2.4/gson-2.2.4.jar:/Users/stack/.m2/repository/org/apache/hadoop/hadoop-auth/2.7.7/hadoop-auth-2.7.7.jar:/Users/stack/.m2/repository/org/apache/directory/server/apacheds-kerberos-codec/2.0.0-M15/apacheds-kerberos-codec-2.0.0-M15.jar:/Users/stack/.m2/repository/org/apache/directory/server/apacheds-i18n/2.0.0-M15/apacheds-i18n-2.0.0-M15.jar:/Users/stack/.m2/repository/org/apache/directory/api/api-asn1-api/1.0.0-M20/api-asn1-api-1.0.0-M20.jar:/Users/stack/.m2/repository/org/apache/directory/api/api-util/1.0.0-M20/api-util-1.0.0-M20.jar:/Users/stack/.m2/repository/org/apache/curator/curator-framework/4.0.0/curator-framework-4.0.0.jar:/Users/stack/.m2/repository/com/jcraft/jsch/0.1.54/jsch-0.1.54.jar:/Users/stack/.m2/repository/org/apache/curator/curator-client/4.0.0/curator-client-4.0.0.jar:/Users/stack/.m2/repository/org/apache/curator/curator-recipes/4.0.0/curator-recipes-4.0.0.jar:/Users/stack/.m2/repository/org/apache/htrace/htrace-core/3.1.0-incubating/htrace-core-3.1.0-incubating.jar:/Users/stack/.m2/repository/org/apache/zookeeper/zookeeper/3.4.10/zookeeper-3.4.10.jar:/Users/stack/.m2/repository/org/apache/commons/commons-compress/1.4.1/commons-compress-1.4.1.jar:/Users/stack/.m2/repository/org/tukaani/xz/1.0/xz-1.0.jar:/Users/stack/.m2/repository/org/apache/yetus/audience-annotations/0.5.0/audience-annotations-0.5.0.jar:/Users/stack/checkouts/hbase/hbase-common/target/test-classes:/Users/stack/checkouts/hbase/hbase-annotations/target/test-classes:/Users/stack/checkouts/hbase/hbase-protocol-shaded/target/classes:/Users/stack/checkouts/hbase/hbase-common/target/classes:/Users/stack/checkouts/hbase/hbase-metrics-api/target/classes:/Applications/IntelliJ
IDEA CE.app/Contents/jdk/Contents/Home/lib/tools.jar"
com.intellij.rt.execution.junit.JUnitStarter -ideVersion5 -junit4
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure,test
objc[52501]: Class JavaLaunchHelper is implemented in both
/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/bin/java
(0x101b464c0) and
/Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/libinstrument.dylib
(0x101bd64e0). One of the two will be used. Which one is undefined.
Connected to the target VM, address: '127.0.0.1:56370', transport: 'socket'
2018-10-18 13:35:39,911 WARN [Time-limited test] util.NativeCodeLoader(62):
Unable to load native-hadoop library for your platform... using builtin-java
classes where applicable
2018-10-18 13:35:40,116 INFO [Time-limited test]
procedure2.ProcedureExecutor(676): Starting 1 core workers (bigger of cpus/4 or
16) with max (burst) worker count=10
2018-10-18 13:35:40,161 DEBUG [Time-limited test]
util.CommonFSUtils$DfsBuilderUtility(872):
org.apache.hadoop.hdfs.DistributedFileSystem not available, will not use
builder API for file creation.
2018-10-18 13:35:40,162 DEBUG [Time-limited test]
util.CommonFSUtils$DfsBuilderUtility(877):
org.apache.hadoop.hdfs.DistributedFileSystem$HdfsDataOutputStreamBuilder not
available, will not use builder API for file creation.
2018-10-18 13:35:40,225 INFO [Time-limited test] wal.WALProcedureStore(1123):
Rolled new Procedure Store WAL, id=1
2018-10-18 13:35:40,229 INFO [Time-limited test]
procedure2.ProcedureExecutor(695): Recovered WALProcedureStore lease in 108msec
2018-10-18 13:35:40,233 INFO [Time-limited test]
procedure2.ProcedureExecutor(709): Loaded WALProcedureStore in 3msec
2018-10-18 13:35:40,256 INFO [Time-limited test]
procedure2.TimeoutExecutorThread(82): ADDED pid=-1, state=WAITING_TIMEOUT;
org.apache.hadoop.hbase.procedure2.ProcedureExecutor$CompletedProcedureCleaner;
timeout=30000, timestamp=1539894970256
2018-10-18 13:35:40,321 DEBUG [Time-limited test]
procedure2.ProcedureExecutor(1185): Stored pid=1, state=RUNNABLE;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$ParentProcedure
2018-10-18 13:35:40,348 INFO [PEWorker-1] procedure2.ProcedureExecutor(1796):
Initialized subprocedures=[{pid=2, ppid=1, state=RUNNABLE;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$DummyProcedure},
{pid=3, ppid=1, state=RUNNABLE;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$WaitingProcedure}]
2018-10-18 13:35:40,360 INFO [PEWorker-1]
procedure2.TimeoutExecutorThread(82): ADDED pid=3, ppid=1,
state=WAITING_TIMEOUT, locked=true;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$WaitingProcedure;
timeout=2147483647, timestamp=1542042424007
2018-10-18 13:35:40,362 INFO [PEWorker-1] procedure2.ProcedureExecutor(1562):
Finished pid=2, ppid=1, state=SUCCESS;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$DummyProcedure
in 34msec, unfinishedSiblingCount=1
2018-10-18 13:35:40,381 INFO [Time-limited test] hbase.Waiter(189): Waiting up
to [10,000] milli-secs(wait.for.ratio=[1])
2018-10-18 13:35:40,382 DEBUG [Time-limited test]
procedure2.ProcedureExecutor(1185): Stored pid=4, state=RUNNABLE;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$ExchangeProcedure
2018-10-18 13:35:40,419 INFO [Time-limited test] wal.WALProcedureStore(1123):
Rolled new Procedure Store WAL, id=2
2018-10-18 13:35:41,437 INFO [Time-limited test] wal.WALProcedureStore(1123):
Rolled new Procedure Store WAL, id=3
2018-10-18 13:35:42,460 INFO [Time-limited test] wal.WALProcedureStore(1123):
Rolled new Procedure Store WAL, id=4
2018-10-18 13:35:43,482 INFO [Time-limited test] wal.WALProcedureStore(1123):
Rolled new Procedure Store WAL, id=5
2018-10-18 13:35:44,506 WARN [Time-limited test] wal.WALProcedureStore(1108):
procedure WALs count=6 above the warning threshold 5. check running procedures
to see if something is stuck.
2018-10-18 13:35:44,522 INFO [Time-limited test] wal.WALProcedureStore(1123):
Rolled new Procedure Store WAL, id=6
2018-10-18 13:35:44,523 DEBUG [Force-Update-PEWorker-0]
procedure2.ProcedureExecutor(390): Force update procedure pid=1, state=WAITING;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$ParentProcedure
2018-10-18 13:35:44,526 DEBUG [Force-Update-PEWorker-0]
procedure2.ProcedureExecutor(390): Force update procedure pid=2, ppid=1,
state=SUCCESS;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$DummyProcedure
2018-10-18 13:35:44,526 INFO [Time-limited test] hbase.Waiter(189): Waiting up
to [10,000] milli-secs(wait.for.ratio=[1])
2018-10-18 13:35:44,527 DEBUG [Force-Update-PEWorker-0]
procedure2.ProcedureExecutor(390): Force update procedure pid=3, ppid=1,
state=WAITING_TIMEOUT;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$WaitingProcedure
2018-10-18 13:35:44,528 INFO [PEWorker-1] procedure2.ProcedureExecutor(1562):
Finished pid=4, state=SUCCESS;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$ExchangeProcedure
in 4.1440sec
2018-10-18 13:35:44,528 DEBUG [WALProcedureStoreSyncThread]
wal.WALProcedureStore(1212): Removed
log=/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000001.log,
activeLogs=[/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000002.log,
/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000003.log,
/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000004.log,
/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000005.log,
/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000006.log]
2018-10-18 13:35:44,529 DEBUG [WALProcedureStoreSyncThread]
wal.WALProcedureStore(1212): Removed
log=/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000002.log,
activeLogs=[/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000003.log,
/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000004.log,
/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000005.log,
/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000006.log]
2018-10-18 13:35:44,530 DEBUG [WALProcedureStoreSyncThread]
wal.WALProcedureStore(1212): Removed
log=/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000003.log,
activeLogs=[/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000004.log,
/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000005.log,
/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000006.log]
2018-10-18 13:35:44,531 DEBUG [WALProcedureStoreSyncThread]
wal.WALProcedureStore(1212): Removed
log=/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000004.log,
activeLogs=[/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000005.log,
/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000006.log]
2018-10-18 13:35:44,532 DEBUG [WALProcedureStoreSyncThread]
wal.WALProcedureStore(1212): Removed
log=/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000005.log,
activeLogs=[/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000006.log]
2018-10-18 13:35:44,632 INFO [Time-limited test] hbase.Waiter(189): Waiting up
to [10,000] milli-secs(wait.for.ratio=[1])
2018-10-18 13:35:44,632 INFO [Time-limited test]
procedure2.ProcedureExecutor(740): Stopping
2018-10-18 13:35:44,632 INFO [Time-limited test] wal.WALProcedureStore(330):
Stopping the WAL Procedure Store, isAbort=false
2018-10-18 13:35:44,635 INFO [Time-limited test]
procedure2.ProcedureExecutor(676): Starting 1 core workers (bigger of cpus/4 or
16) with max (burst) worker count=10
2018-10-18 13:35:44,636 DEBUG [Time-limited test] wal.WALProcedureStore(1343):
Opening Pv2
DeprecatedRawLocalFileStatus{path=file:/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000006.log;
isDirectory=false; length=640; replication=1; blocksize=33554432;
modification_time=1539894944000; access_time=0; owner=; group=;
permission=rw-rw-rw-; isSymlink=false}
2018-10-18 13:35:44,681 INFO [Time-limited test] wal.WALProcedureStore(1123):
Rolled new Procedure Store WAL, id=7
2018-10-18 13:35:44,682 INFO [Time-limited test]
procedure2.ProcedureExecutor(695): Recovered WALProcedureStore lease in 46msec
2018-10-18 13:35:44,687 INFO [Time-limited test]
wal.ProcedureWALFormatReader(168): Read 6 entries in
file:/Users/stack/checkouts/hbase/hbase-procedure/target/test-data/667eff5d-7fd0-995e-5958-9109010f03a5/proc-wals/pv2-00000000000000000006.log
2018-10-18 13:35:44,689 DEBUG [Time-limited test]
procedure2.ProcedureExecutor(510): Completed pid=4, state=SUCCESS;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$ExchangeProcedure
2018-10-18 13:35:44,689 DEBUG [Time-limited test]
procedure2.ProcedureExecutor(558): Loading pid=3, ppid=1,
state=WAITING_TIMEOUT;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$WaitingProcedure
2018-10-18 13:35:44,689 DEBUG [Time-limited test]
procedure2.ProcedureExecutor(558): Loading pid=2, ppid=1, state=SUCCESS;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$DummyProcedure
2018-10-18 13:35:44,689 DEBUG [Time-limited test]
procedure2.ProcedureExecutor(558): Loading pid=1, state=WAITING;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$ParentProcedure
2018-10-18 13:35:44,690 INFO [Time-limited test]
procedure2.TimeoutExecutorThread(82): ADDED pid=3, ppid=1,
state=WAITING_TIMEOUT;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$WaitingProcedure;
timeout=2147483647, timestamp=1542042424007
2018-10-18 13:35:44,692 DEBUG [Time-limited test] procedure2.Procedure(978):
pid=1, state=WAITING;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$ParentProcedure
didn't hold the lock before restarting, skip acquiring lock.
2018-10-18 13:35:44,692 DEBUG [Time-limited test] procedure2.Procedure(978):
pid=2, ppid=1, state=SUCCESS;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$DummyProcedure
didn't hold the lock before restarting, skip acquiring lock.
2018-10-18 13:35:44,692 DEBUG [Time-limited test] procedure2.Procedure(978):
pid=3, ppid=1, state=WAITING_TIMEOUT;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$WaitingProcedure
didn't hold the lock before restarting, skip acquiring lock.
2018-10-18 13:35:44,694 INFO [Time-limited test]
procedure2.ProcedureExecutor(709): Loaded WALProcedureStore in 12msec
2018-10-18 13:35:44,694 INFO [Time-limited test]
procedure2.TimeoutExecutorThread(82): ADDED pid=-1, state=WAITING_TIMEOUT;
org.apache.hadoop.hbase.procedure2.ProcedureExecutor$CompletedProcedureCleaner;
timeout=30000, timestamp=1539894974694
2018-10-18 13:35:44,706 INFO [Time-limited test]
procedure2.ProcedureExecutor(740): Stopping
2018-10-18 13:35:44,706 INFO [Time-limited test] wal.WALProcedureStore(330):
Stopping the WAL Procedure Store, isAbort=false
java.lang.AssertionError: class
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$ParentProcedure
pid=1, state=WAITING;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$ParentProcedure,
class
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$WaitingProcedure
pid=3, ppid=1, state=WAITING_TIMEOUT;
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure$WaitingProcedure
Expected :3
Actual :2
<Click to see difference>
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.failNotEquals(Assert.java:834)
at org.junit.Assert.assertEquals(Assert.java:645)
at
org.apache.hadoop.hbase.procedure2.store.wal.TestForceUpdateProcedure.test(TestForceUpdateProcedure.java:244)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266)
at java.util.concurrent.FutureTask.run(FutureTask.java)
at java.lang.Thread.run(Thread.java:745)
Disconnected from the target VM, address: '127.0.0.1:56370', transport: 'socket'
Process finished with exit code 255
{code}
> Should not skip force updating for a sub procedure even if it has been
> finished
> -------------------------------------------------------------------------------
>
> Key: HBASE-21323
> URL: https://issues.apache.org/jira/browse/HBASE-21323
> Project: HBase
> Issue Type: Sub-task
> Components: proc-v2
> Reporter: Duo Zhang
> Assignee: Duo Zhang
> Priority: Major
> Fix For: 3.0.0, 2.2.0, 2.1.1, 2.0.3
>
> Attachments: HBASE-21323.patch, HBASE-21323.patch
>
>
> Keep seeing this
> {noformat}
> 2018-10-16,20:03:02,027 WARN [WALProcedureStoreSyncThread]
> org.apache.hadoop.hbase.procedure2.store.wal.WALProcedureStore: procedure
> WALs count=340 above the warning threshold 10. check running procedures to
> see if something is stuck.
> 2018-10-16,20:03:02,027 INFO [WALProcedureStoreSyncThread]
> org.apache.hadoop.hbase.procedure2.store.wal.WALProcedureStore: Rolled new
> Procedure Store WAL, id=343
> 2018-10-16,20:03:02,027 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=991,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:02,027 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=992,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:02,027 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=994,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:02,027 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=995,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:02,870 WARN [WALProcedureStoreSyncThread]
> org.apache.hadoop.hbase.procedure2.store.wal.WALProcedureStore: procedure
> WALs count=341 above the warning threshold 10. check running procedures to
> see if something is stuck.
> 2018-10-16,20:03:02,870 INFO [WALProcedureStoreSyncThread]
> org.apache.hadoop.hbase.procedure2.store.wal.WALProcedureStore: Rolled new
> Procedure Store WAL, id=344
> 2018-10-16,20:03:02,870 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=991,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:02,870 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=992,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:02,870 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=994,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:02,870 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=995,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:03,816 WARN [WALProcedureStoreSyncThread]
> org.apache.hadoop.hbase.procedure2.store.wal.WALProcedureStore: procedure
> WALs count=342 above the warning threshold 10. check running procedures to
> see if something is stuck.
> 2018-10-16,20:03:03,816 INFO [WALProcedureStoreSyncThread]
> org.apache.hadoop.hbase.procedure2.store.wal.WALProcedureStore: Rolled new
> Procedure Store WAL, id=345
> 2018-10-16,20:03:03,816 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=991,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:03,816 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=992,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:03,816 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=994,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> 2018-10-16,20:03:03,816 DEBUG [Force-Update-PEWorker-0]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: Procedure pid=995,
> ppid=990, state=SUCCESS;
> org.apache.hadoop.hbase.master.replication.RefreshPeerProcedure has already
> been finished, skip force updating.
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
