[LIVY-745] more than 11 concurrent clients lead to java.io.IOException: Unable to connect to provided ports 10000~10010

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.6.0
• Fix Version/s: 0.8.0
• Component/s: RSC
• Assignee: Wing Yew Poon
• Reporter: Wing Yew Poon
• Created: 17/Jan/20 21:44
• Updated: 21/Mar/23 09:48
• Resolved: 15/Feb/20 21:44

Description

In testing scalability of the Livy Thrift server, I am simultaneously starting multiple connections to it. When there are more than 11 connections started simultaneously, the 12th (and subsequent) connection will fail with:

2020-01-10 13:53:28,686 ERROR org.apache.livy.thriftserver.LivyExecuteStatementOperation: Error running hive query: 
org.apache.hive.service.cli.HiveSQLException: java.lang.RuntimeException: java.io.IOException: Unable to connect to provided ports 10000~10010

Here is the excerpt from the Livy server log:

2020-01-10 13:53:28,138 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 0: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
...
2020-01-10 13:53:28,147 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 1: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
...
2020-01-10 13:53:28,196 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 2: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
...
2020-01-10 13:53:28,247 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 3: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
...
2020-01-10 13:53:28,304 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 4: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
2020-01-10 13:53:28,329 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
2020-01-10 13:53:28,329 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
2020-01-10 13:53:28,329 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
2020-01-10 13:53:28,329 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
2020-01-10 13:53:28,329 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10000
...
2020-01-10 13:53:28,331 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10001
...
2020-01-10 13:53:28,335 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10001 Address already in use
2020-01-10 13:53:28,335 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10001 Address already in use
2020-01-10 13:53:28,335 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10001 Address already in use
2020-01-10 13:53:28,338 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10002
2020-01-10 13:53:28,338 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10002 Address already in use
...
2020-01-10 13:53:28,339 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10002 Address already in use
2020-01-10 13:53:28,341 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10003
...
2020-01-10 13:53:28,341 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10003 Address already in use
...
2020-01-10 13:53:28,343 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10004
...
2020-01-10 13:53:28,362 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 5: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
2020-01-10 13:53:28,367 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
2020-01-10 13:53:28,369 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10001 Address already in use
2020-01-10 13:53:28,371 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10002 Address already in use
2020-01-10 13:53:28,373 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10003 Address already in use
2020-01-10 13:53:28,376 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10004 Address already in use
2020-01-10 13:53:28,379 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10005
...
2020-01-10 13:53:28,412 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 6: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
...
2020-01-10 13:53:28,416 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
...
2020-01-10 13:53:28,418 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10001 Address already in use
2020-01-10 13:53:28,419 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10002 Address already in use
2020-01-10 13:53:28,420 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10003 Address already in use
2020-01-10 13:53:28,422 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10004 Address already in use
2020-01-10 13:53:28,423 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10005 Address already in use
2020-01-10 13:53:28,424 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10006
...
2020-01-10 13:53:28,462 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 7: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
2020-01-10 13:53:28,466 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
2020-01-10 13:53:28,468 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10001 Address already in use
2020-01-10 13:53:28,470 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10002 Address already in use
2020-01-10 13:53:28,471 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10003 Address already in use
2020-01-10 13:53:28,472 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10004 Address already in use
2020-01-10 13:53:28,473 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10005 Address already in use
2020-01-10 13:53:28,475 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10006 Address already in use
2020-01-10 13:53:28,476 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10007
...
2020-01-10 13:53:28,510 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 8: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
2020-01-10 13:53:28,513 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
2020-01-10 13:53:28,514 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10001 Address already in use
2020-01-10 13:53:28,515 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10002 Address already in use
2020-01-10 13:53:28,522 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10003 Address already in use
2020-01-10 13:53:28,524 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10004 Address already in use
2020-01-10 13:53:28,525 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10005 Address already in use
2020-01-10 13:53:28,526 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10006 Address already in use
2020-01-10 13:53:28,527 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10007 Address already in use
2020-01-10 13:53:28,527 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10008
...
2020-01-10 13:53:28,561 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 9: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
2020-01-10 13:53:28,564 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
2020-01-10 13:53:28,565 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10001 Address already in use
2020-01-10 13:53:28,565 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10002 Address already in use
2020-01-10 13:53:28,567 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10003 Address already in use
2020-01-10 13:53:28,568 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10004 Address already in use
2020-01-10 13:53:28,568 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10005 Address already in use
2020-01-10 13:53:28,569 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10006 Address already in use
2020-01-10 13:53:28,569 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10007 Address already in use
2020-01-10 13:53:28,570 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10008 Address already in use
2020-01-10 13:53:28,570 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10009
...
2020-01-10 13:53:28,611 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 10: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
2020-01-10 13:53:28,614 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
2020-01-10 13:53:28,615 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10001 Address already in use
2020-01-10 13:53:28,616 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10002 Address already in use
2020-01-10 13:53:28,617 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10003 Address already in use
2020-01-10 13:53:28,618 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10004 Address already in use
2020-01-10 13:53:28,618 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10005 Address already in use
2020-01-10 13:53:28,619 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10006 Address already in use
2020-01-10 13:53:28,620 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10007 Address already in use
2020-01-10 13:53:28,620 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10008 Address already in use
2020-01-10 13:53:28,621 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10009 Address already in use
2020-01-10 13:53:28,621 INFO org.apache.livy.rsc.rpc.RpcServer: Connected to the port 10010
...
2020-01-10 13:53:28,661 INFO org.apache.livy.server.interactive.InteractiveSession$: Creating Interactive session 11: [owner: systest, request: [kind: spark, proxyUser: None, heartbeatTimeoutInSecond: 0]]
2020-01-10 13:53:28,664 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10000 Address already in use
2020-01-10 13:53:28,664 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10001 Address already in use
2020-01-10 13:53:28,665 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10002 Address already in use
2020-01-10 13:53:28,666 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10003 Address already in use
2020-01-10 13:53:28,667 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10004 Address already in use
2020-01-10 13:53:28,677 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10005 Address already in use
2020-01-10 13:53:28,678 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10006 Address already in use
2020-01-10 13:53:28,679 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10007 Address already in use
2020-01-10 13:53:28,679 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10008 Address already in use
2020-01-10 13:53:28,679 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10009 Address already in use
2020-01-10 13:53:28,680 DEBUG org.apache.livy.rsc.rpc.RpcServer: RPC not able to connect port 10010 Address already in use
2020-01-10 13:53:28,683 INFO org.apache.livy.thriftserver.LivyExecuteStatementOperation: (Error executing query, currentState RUNNING, ,java.lang.RuntimeException: java.io.IOException: Unable to connect to provided ports 10000~10010)
2020-01-10 13:53:28,686 ERROR org.apache.livy.thriftserver.LivyExecuteStatementOperation: Error running hive query: 
org.apache.hive.service.cli.HiveSQLException: java.lang.RuntimeException: java.io.IOException: Unable to connect to provided ports 10000~10010
	at org.apache.livy.thriftserver.LivyExecuteStatementOperation.execute(LivyExecuteStatementOperation.scala:147)
	at org.apache.livy.thriftserver.LivyExecuteStatementOperation$$anon$1$$anon$2.run(LivyExecuteStatementOperation.scala:97)
	at org.apache.livy.thriftserver.LivyExecuteStatementOperation$$anon$1$$anon$2.run(LivyExecuteStatementOperation.scala:94)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.Subject.doAs(Subject.java:422)
	at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1876)
	at org.apache.livy.thriftserver.LivyExecuteStatementOperation$$anon$1.run(LivyExecuteStatementOperation.scala:107)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.RuntimeException: java.io.IOException: Unable to connect to provided ports 10000~10010
	at org.apache.livy.rsc.Utils.propagate(Utils.java:60)
	at org.apache.livy.rsc.RSCClientFactory.createClient(RSCClientFactory.java:81)
	at org.apache.livy.LivyClientBuilder.build(LivyClientBuilder.java:130)
	at org.apache.livy.server.interactive.InteractiveSession$$anonfun$2.apply(InteractiveSession.scala:114)
	at org.apache.livy.server.interactive.InteractiveSession$$anonfun$2.apply(InteractiveSession.scala:84)
	at scala.Option.orElse(Option.scala:289)
	at org.apache.livy.server.interactive.InteractiveSession$.create(InteractiveSession.scala:84)
	at org.apache.livy.thriftserver.LivyThriftSessionManager$$anonfun$4.apply(LivyThriftSessionManager.scala:229)
	at org.apache.livy.thriftserver.LivyThriftSessionManager$$anonfun$4.apply(LivyThriftSessionManager.scala:227)
	at org.apache.livy.thriftserver.LivyThriftSessionManager.org$apache$livy$thriftserver$LivyThriftSessionManager$$getOrCreateLivySession(LivyThriftSessionManager.scala:185)
	at org.apache.livy.thriftserver.LivyThriftSessionManager$$anonfun$5$$anon$1.run(LivyThriftSessionManager.scala:248)
	at org.apache.livy.thriftserver.LivyThriftSessionManager$$anonfun$5$$anon$1.run(LivyThriftSessionManager.scala:245)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.Subject.doAs(Subject.java:422)
	at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1876)
	at org.apache.livy.thriftserver.LivyThriftSessionManager$$anonfun$5.apply(LivyThriftSessionManager.scala:245)
	at org.apache.livy.thriftserver.LivyThriftSessionManager$$anonfun$5.apply(LivyThriftSessionManager.scala:241)
	at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)
	at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)
	at scala.concurrent.impl.ExecutionContextImpl$AdaptedForkJoinTask.exec(ExecutionContextImpl.scala:121)
	at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
	at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
	at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
	at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
Caused by: java.io.IOException: Unable to connect to provided ports 10000~10010
	at org.apache.livy.rsc.rpc.RpcServer.<init>(RpcServer.java:101)
	at org.apache.livy.rsc.RSCClientFactory.ref(RSCClientFactory.java:98)
	at org.apache.livy.rsc.RSCClientFactory.createClient(RSCClientFactory.java:71)
	... 22 more

As can be seen, the first 5 connections (session 0 to session 4) are created almost at the same time, and after some jostling, claim ports 10000 to 10004. The log then shows subsequent connections trying the ports from 10000 on up until they find one that is not in use. The last successful one is session 10, which claims port 10010. After that, session 11 fails.
The port range (10000~10010) is configurable, but I'm using the default.

Issue Links

• links to: GitHub Pull Request #275