[HBASE-14430] TestHttpServerLifecycle#testStartedServerIsAlive times out

• Type: Sub-task
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.2.0, 1.3.0, 2.0.0
• Component/s: test
• Assignee: Michael Stack
• Reporter: Michael Stack
• Created: 14/Sep/15 16:56
• Updated: 23/Jun/22 19:04
• Resolved: 29/Sep/15 04:40

Description

Running on my test rig, I see this test timeout from time to time. It just hangs after jetty setup. Port clash?

2015-09-14 09:08:54,474 INFO  [main] hbase.ResourceChecker(148): before: http.TestHttpServerLifecycle#testCreatedServerIsNotAlive Thread=4, OpenFileDescriptor=192, MaxFileDescriptor=32768, SystemLoadAverage=122, ProcessCount=507, Availabl
2015-09-14 09:08:54,592 INFO  [Time-limited test] log.Slf4jLog(67): Logging to org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog
2015-09-14 09:08:54,911 INFO  [Time-limited test] http.HttpRequestLog(69): Http request log for http.requests.test is not defined
2015-09-14 09:08:54,923 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'safety' (class=org.apache.hadoop.hbase.http.HttpServer$QuotingInputFilter)
2015-09-14 09:08:54,924 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'clickjackingprevention' (class=org.apache.hadoop.hbase.http.ClickjackingPreventionFilter)
2015-09-14 09:08:54,985 INFO  [main] hbase.ResourceChecker(172): after: http.TestHttpServerLifecycle#testCreatedServerIsNotAlive Thread=5 (was 4)
Potentially hanging thread: process reaper
        sun.misc.Unsafe.park(Native Method)
        java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
        java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
        java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359)
        java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:942)
        java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
        java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
        java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        java.lang.Thread.run(Thread.java:745)
 - Thread LEAK? -, OpenFileDescriptor=192 (was 192), MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=122 (was 122), ProcessCount=507 (was 507), AvailableMemoryMB=28014 (was 28054)
2015-09-14 09:08:55,013 INFO  [main] hbase.ResourceChecker(148): before: http.TestHttpServerLifecycle#testWepAppContextAfterServerStop Thread=5, OpenFileDescriptor=192, MaxFileDescriptor=32768, SystemLoadAverage=122, ProcessCount=507, Ava
2015-09-14 09:08:55,088 INFO  [Time-limited test] http.HttpRequestLog(69): Http request log for http.requests.test is not defined
2015-09-14 09:08:55,089 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'safety' (class=org.apache.hadoop.hbase.http.HttpServer$QuotingInputFilter)
2015-09-14 09:08:55,090 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'clickjackingprevention' (class=org.apache.hadoop.hbase.http.ClickjackingPreventionFilter)
2015-09-14 09:08:55,113 INFO  [Time-limited test] http.HttpServer(1013): Jetty bound to port 60242
2015-09-14 09:08:55,113 INFO  [Time-limited test] log.Slf4jLog(67): jetty-6.1.26
2015-09-14 09:08:55,263 INFO  [Time-limited test] log.Slf4jLog(67): Started SelectChannelConnector@localhost:60242
2015-09-14 09:08:55,270 INFO  [Time-limited test] log.Slf4jLog(67): Stopped SelectChannelConnector@localhost:0
2015-09-14 09:08:55,401 INFO  [main] hbase.ResourceChecker(172): after: http.TestHttpServerLifecycle#testWepAppContextAfterServerStop Thread=5 (was 5), OpenFileDescriptor=197 (was 192) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768
2015-09-14 09:08:55,428 INFO  [main] hbase.ResourceChecker(148): before: http.TestHttpServerLifecycle#testStopUnstartedServer Thread=5, OpenFileDescriptor=197, MaxFileDescriptor=32768, SystemLoadAverage=122, ProcessCount=507, AvailableMem
2015-09-14 09:08:55,489 INFO  [Time-limited test] http.HttpRequestLog(69): Http request log for http.requests.test is not defined
2015-09-14 09:08:55,489 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'safety' (class=org.apache.hadoop.hbase.http.HttpServer$QuotingInputFilter)
2015-09-14 09:08:55,490 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'clickjackingprevention' (class=org.apache.hadoop.hbase.http.ClickjackingPreventionFilter)
2015-09-14 09:08:55,521 INFO  [main] hbase.ResourceChecker(172): after: http.TestHttpServerLifecycle#testStopUnstartedServer Thread=5 (was 5), OpenFileDescriptor=197 (was 197), MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=122 (w
2015-09-14 09:08:55,548 INFO  [main] hbase.ResourceChecker(148): before: http.TestHttpServerLifecycle#testStartedServerIsAlive Thread=5, OpenFileDescriptor=197, MaxFileDescriptor=32768, SystemLoadAverage=122, ProcessCount=507, AvailableMe
2015-09-14 09:08:55,592 INFO  [Time-limited test] http.HttpRequestLog(69): Http request log for http.requests.test is not defined
2015-09-14 09:08:55,593 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'safety' (class=org.apache.hadoop.hbase.http.HttpServer$QuotingInputFilter)
2015-09-14 09:08:55,593 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'clickjackingprevention' (class=org.apache.hadoop.hbase.http.ClickjackingPreventionFilter)
2015-09-14 09:08:55,596 INFO  [Time-limited test] http.HttpServer(1013): Jetty bound to port 34027
2015-09-14 09:08:55,596 INFO  [Time-limited test] log.Slf4jLog(67): jetty-6.1.26
2015-09-14 09:08:55,620 INFO  [Time-limited test] log.Slf4jLog(67): Started SelectChannelConnector@localhost:34027
2015-09-14 09:09:55,589 INFO  [main] hbase.ResourceChecker(172): after: http.TestHttpServerLifecycle#testStartedServerIsAlive Thread=8 (was 5)
Potentially hanging thread: 665017523@qtp-1303167268-1 - Acceptor0 SelectChannelConnector@localhost:34027
        org.mortbay.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:464)
        org.mortbay.io.nio.SelectorManager.doSelect(SelectorManager.java:192)
        org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:124)
        org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:708)
        org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)

Potentially hanging thread: Time-limited test
        org.mortbay.io.nio.SelectorManager$SelectSet.stop(SelectorManager.java:879)
        org.mortbay.io.nio.SelectorManager.doStop(SelectorManager.java:240)
        org.mortbay.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:76)
        org.mortbay.jetty.nio.SelectChannelConnector.close(SelectChannelConnector.java:136)
        org.apache.hadoop.hbase.http.HttpServer.stop(HttpServer.java:1041)
        org.apache.hadoop.hbase.http.HttpServerFunctionalTest.stop(HttpServerFunctionalTest.java:195)
        org.apache.hadoop.hbase.http.TestHttpServerLifecycle.testStartedServerIsAlive(TestHttpServerLifecycle.java:73)
        sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        java.lang.reflect.Method.invoke(Method.java:606)
        org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
        org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
        java.util.concurrent.FutureTask.run(FutureTask.java:262)
        java.lang.Thread.run(Thread.java:745)

Potentially hanging thread: Timer-1
        java.lang.Object.wait(Native Method)
        java.util.TimerThread.mainLoop(Timer.java:552)
        java.util.TimerThread.run(Timer.java:505)

Potentially hanging thread: 1272155315@qtp-1303167268-0
        java.lang.Object.wait(Native Method)
        org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:626)
 - Thread LEAK? -, OpenFileDescriptor=201 (was 197) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=112 (was 122), ProcessCount=507 (was 507), AvailableMemoryMB=27985 (was 27994)
2015-09-14 09:09:55,619 INFO  [main] hbase.ResourceChecker(148): before: http.TestHttpServerLifecycle#testStoppedServerIsNotAlive Thread=9, OpenFileDescriptor=201, MaxFileDescriptor=32768, SystemLoadAverage=112, ProcessCount=507, Availabl
2015-09-14 09:09:55,652 INFO  [Time-limited test] http.HttpRequestLog(69): Http request log for http.requests.test is not defined
2015-09-14 09:09:55,653 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'safety' (class=org.apache.hadoop.hbase.http.HttpServer$QuotingInputFilter)
2015-09-14 09:09:55,654 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'clickjackingprevention' (class=org.apache.hadoop.hbase.http.ClickjackingPreventionFilter)
2015-09-14 09:09:55,657 INFO  [Time-limited test] http.HttpServer(1013): Jetty bound to port 49253
2015-09-14 09:09:55,657 INFO  [Time-limited test] log.Slf4jLog(67): jetty-6.1.26
2015-09-14 09:09:55,681 INFO  [Time-limited test] log.Slf4jLog(67): Started SelectChannelConnector@localhost:49253
2015-09-14 09:09:55,684 INFO  [Time-limited test] log.Slf4jLog(67): Stopped SelectChannelConnector@localhost:0
2015-09-14 09:09:55,817 INFO  [main] hbase.ResourceChecker(172): after: http.TestHttpServerLifecycle#testStoppedServerIsNotAlive Thread=9 (was 9), OpenFileDescriptor=201 (was 201), MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=11
2015-09-14 09:09:55,847 INFO  [main] hbase.ResourceChecker(148): before: http.TestHttpServerLifecycle#testStoppingTwiceServerIsAllowed Thread=9, OpenFileDescriptor=201, MaxFileDescriptor=32768, SystemLoadAverage=112, ProcessCount=507, Ava
2015-09-14 09:09:55,879 INFO  [Time-limited test] http.HttpRequestLog(69): Http request log for http.requests.test is not defined
2015-09-14 09:09:55,880 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'safety' (class=org.apache.hadoop.hbase.http.HttpServer$QuotingInputFilter)
2015-09-14 09:09:55,880 INFO  [Time-limited test] http.HttpServer(821): Added global filter 'clickjackingprevention' (class=org.apache.hadoop.hbase.http.ClickjackingPreventionFilter)
2015-09-14 09:09:55,883 INFO  [Time-limited test] http.HttpServer(1013): Jetty bound to port 53449
2015-09-14 09:09:55,884 INFO  [Time-limited test] log.Slf4jLog(67): jetty-6.1.26
2015-09-14 09:09:55,906 INFO  [Time-limited test] log.Slf4jLog(67): Started SelectChannelConnector@localhost:53449
2015-09-14 09:09:55,910 INFO  [Time-limited test] log.Slf4jLog(67): Stopped SelectChannelConnector@localhost:0
2015-09-14 09:09:56,038 INFO  [main] hbase.ResourceChecker(172): after: http.TestHttpServerLifecycle#testStoppingTwiceServerIsAllowed Thread=9 (was 9), OpenFileDescriptor=201 (was 201), MaxFileDescriptor=32768 (was 32768), SystemLoadAvera

This test came over from hadoop.

Looking at history, it usually passes up on apache jenkins so not disabling for now. Just noting this failure.

https://builds.apache.org/view/H-L/view/HBase/job/PreCommit-HBASE-Build/15579/testReport/org.apache.hadoop.hbase.http/TestHttpServerLifecycle/history/

Issue Links

• relates to: HBASE-14505 Reenable tests disabled by HBASE-14430 in TestHttpServerLifecycle