Uploaded image for project: 'IMPALA'
  1. IMPALA
  2. IMPALA-4088

HDFS data nodes pick HTTP server ports at random, sometimes stealing HBase master's port

    Details

      Description

      Michael, can you take a first look since you've dabbled with HBase startup before? It looks like HBase may not be in a good state. I will not cancel the build so you can log into the machine if necessary. Feel free to cancel the build if you have all the info you need.

      There are several issues here:

      • figure out why data loading did not succeed
      • the build should not hang even if there are errors in data loading

      This is where it hangs:

      ...
      00:35:24.252 [INFO] BUILD SUCCESS
      00:35:24.253 ------------------------------------------------------------------------
      00:35:24.253 
      00:35:24.260 ========================================================================
      00:35:24.260 Running mvn package
      00:35:24.262 Directory: /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/testdata
      00:35:24.262 ========================================================================
      00:35:32.241 [INFO] /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/testdata/src/main/java/com/cloudera/impala/datagenerator/HBaseTestDataRegionAssigment.java: Some input files use or override a deprecated API.
      00:35:32.242 [INFO] /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/testdata/src/main/java/com/cloudera/impala/datagenerator/HBaseTestDataRegionAssigment.java: Recompile with -Xlint:deprecation for details.
      00:35:32.242 [INFO] BUILD SUCCESS
      00:35:32.242 ------------------------------------------------------------------------
      00:35:32.243 
      00:35:32.249 /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/testdata/target
      00:35:34.029 SUCCESS, data generated into /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/testdata/target
      00:45:44.231 Loading HDFS data from snapshot: /data/jenkins/workspace/impala-umbrella-build-and-test/testdata/test-warehouse-SNAPSHOT/test-warehouse-cdh5-59-SNAPSHOT.tar.gz (logging to load-test-warehouse-snapshot.log)... OK
      00:46:24.762 Starting Impala cluster (logging to start-impala-cluster.log)... OK
      00:46:44.765 Setting up HDFS environment (logging to setup-hdfs-env.log)... OK
      00:46:44.765 Skipped loading the metadata.
      <does not proceed beyond here>
      

      From the hive logs (repeats very often):

      org.apache.hadoop.hbase.client.NoServerForRegionException: Unable to find region for 126 in functional_hbase.alltypes after 35 tries.
      	at org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.locateRegionInMeta(ConnectionManager.java:1329)
      	at org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.locateRegion(ConnectionManager.java:1199)
      	at org.apache.hadoop.hbase.client.AsyncProcess.submit(AsyncProcess.java:395)
      	at org.apache.hadoop.hbase.client.AsyncProcess.submit(AsyncProcess.java:344)
      	at org.apache.hadoop.hbase.client.BufferedMutatorImpl.backgroundFlushCommits(BufferedMutatorImpl.java:238)
      	at org.apache.hadoop.hbase.client.BufferedMutatorImpl.mutate(BufferedMutatorImpl.java:146)
      	at org.apache.hadoop.hbase.client.BufferedMutatorImpl.mutate(BufferedMutatorImpl.java:113)
      	at org.apache.hadoop.hbase.client.HTable.put(HTable.java:1084)
      	at org.apache.hadoop.hive.hbase.HiveHBaseTableOutputFormat$MyRecordWriter.write(HiveHBaseTableOutputFormat.java:146)
      	at org.apache.hadoop.hive.hbase.HiveHBaseTableOutputFormat$MyRecordWriter.write(HiveHBaseTableOutputFormat.java:117)
      	at org.apache.hadoop.hive.ql.io.HivePassThroughRecordWriter.write(HivePassThroughRecordWriter.java:40)
      	at org.apache.hadoop.hive.ql.exec.FileSinkOperator.processOp(FileSinkOperator.java:697)
      	at org.apache.hadoop.hive.ql.exec.Operator.forward(Operator.java:815)
      	at org.apache.hadoop.hive.ql.exec.SelectOperator.processOp(SelectOperator.java:84)
      	at org.apache.hadoop.hive.ql.exec.Operator.forward(Operator.java:815)
      	at org.apache.hadoop.hive.ql.exec.TableScanOperator.processOp(TableScanOperator.java:95)
      	at org.apache.hadoop.hive.ql.exec.MapOperator$MapOpCtx.forward(MapOperator.java:157)
      	at org.apache.hadoop.hive.ql.exec.MapOperator.process(MapOperator.java:497)
      	at org.apache.hadoop.hive.ql.exec.mr.ExecMapper.map(ExecMapper.java:170)
      	at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
      	at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:453)
      	at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
      	at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:270)
      	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
      	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
      	at java.lang.Thread.run(Thread.java:745)
      

      Build:
      http://sandbox.jenkins.cloudera.com/job/impala-umbrella-build-and-test/4465/

      1. logs.tar.gz
        326 kB
        Alexander Behm

        Issue Links

          Activity

          Hide
          mikesbrown Michael Brown added a comment -

          Duplicating this to IMPALA-2013. I see evidence here with the same symptom I found and posted there. I think David Knupp's patch will help illuminate these problems more.

          Show
          mikesbrown Michael Brown added a comment - Duplicating this to IMPALA-2013 . I see evidence here with the same symptom I found and posted there. I think David Knupp 's patch will help illuminate these problems more.
          Hide
          mikesbrown Michael Brown added a comment -

          Strike that. The patch David Knupp introduced was going to be fixing a different problem relasted to HBase, although the problem here was mentioned in IMPALA-2013. Let's not dupe this after all.

          Show
          mikesbrown Michael Brown added a comment - Strike that. The patch David Knupp introduced was going to be fixing a different problem relasted to HBase, although the problem here was mentioned in IMPALA-2013 . Let's not dupe this after all.
          Hide
          mikesbrown Michael Brown added a comment -

          We see what I mentioned in one of the IMPALA-2013 comments: that there were some ports apparently in use that HBase master wanted. Why the HBase startup scripts didn't catch the fact that master exited is beyond me.

          This is from logs/cluster/hbase/hbase-jenkins-master-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out:

          16/09/05 22:03:27 ERROR master.HMasterCommandLine: Master exiting
          java.lang.RuntimeException: Failed construction of Master: class org.apache.hadoop.hbase.master.HMaster.
                  at org.apache.hadoop.hbase.master.HMaster.constructMaster(HMaster.java:2457)
                  at org.apache.hadoop.hbase.master.HMasterCommandLine.startMaster(HMasterCommandLine.java:232)
                  at org.apache.hadoop.hbase.master.HMasterCommandLine.run(HMasterCommandLine.java:138)
                  at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:70)
                  at org.apache.hadoop.hbase.util.ServerCommandLine.doMain(ServerCommandLine.java:127)
                  at org.apache.hadoop.hbase.master.HMaster.main(HMaster.java:2467)
          Caused by: java.net.BindException: Port in use: 0.0.0.0:60010
                  at org.apache.hadoop.hbase.http.HttpServer.openListeners(HttpServer.java:1017)
                  at org.apache.hadoop.hbase.http.HttpServer.start(HttpServer.java:953)
                  at org.apache.hadoop.hbase.http.InfoServer.start(InfoServer.java:91)
                  at org.apache.hadoop.hbase.regionserver.HRegionServer.putUpWebUI(HRegionServer.java:1803)
                  at org.apache.hadoop.hbase.regionserver.HRegionServer.<init>(HRegionServer.java:611)
                  at org.apache.hadoop.hbase.master.HMaster.<init>(HMaster.java:390)
                  at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
                  at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
                  at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
                  at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
                  at org.apache.hadoop.hbase.master.HMaster.constructMaster(HMaster.java:2450)
                  ... 5 more
          Caused by: java.net.BindException: Address already in use
                  at sun.nio.ch.Net.bind0(Native Method)
                  at sun.nio.ch.Net.bind(Net.java:444)
                  at sun.nio.ch.Net.bind(Net.java:436)
                  at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:214)
                  at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)
                  at org.mortbay.jetty.nio.SelectChannelConnector.open(SelectChannelConnector.java:216)
                  at org.apache.hadoop.hbase.http.HttpServer.openListeners(HttpServer.java:1012)
                  ... 15 more
          

          This is the console log at that time:

          22:03:14  --> Starting HBase
          22:03:15 HBase start attempt: 1/5
          22:03:15 Killing any HBase processes possibly lingering from previous start attempts
          22:03:15 Stopping Hbase
          22:03:21 localhost: starting zookeeper, logging to /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/logs/cluster/hbase/hbase-jenkins-zookeeper-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out
          22:03:21 starting master, logging to /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/logs/cluster/hbase/hbase-jenkins-master-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out
          22:03:23 starting regionserver, logging to /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/logs/cluster/hbase/hbase-jenkins-1-regionserver-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out
          22:03:24 starting regionserver, logging to /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/logs/cluster/hbase/hbase-jenkins-2-regionserver-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out
          22:03:25 starting regionserver, logging to /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/logs/cluster/hbase/hbase-jenkins-3-regionserver-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out
          22:03:26 HBase startup scripts succeeded
          22:03:26  --> Starting Hive Server and Metastore Service
          
          Show
          mikesbrown Michael Brown added a comment - We see what I mentioned in one of the IMPALA-2013 comments: that there were some ports apparently in use that HBase master wanted. Why the HBase startup scripts didn't catch the fact that master exited is beyond me. This is from logs/cluster/hbase/hbase-jenkins-master-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out : 16/09/05 22:03:27 ERROR master.HMasterCommandLine: Master exiting java.lang.RuntimeException: Failed construction of Master: class org.apache.hadoop.hbase.master.HMaster. at org.apache.hadoop.hbase.master.HMaster.constructMaster(HMaster.java:2457) at org.apache.hadoop.hbase.master.HMasterCommandLine.startMaster(HMasterCommandLine.java:232) at org.apache.hadoop.hbase.master.HMasterCommandLine.run(HMasterCommandLine.java:138) at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:70) at org.apache.hadoop.hbase.util.ServerCommandLine.doMain(ServerCommandLine.java:127) at org.apache.hadoop.hbase.master.HMaster.main(HMaster.java:2467) Caused by: java.net.BindException: Port in use: 0.0.0.0:60010 at org.apache.hadoop.hbase.http.HttpServer.openListeners(HttpServer.java:1017) at org.apache.hadoop.hbase.http.HttpServer.start(HttpServer.java:953) at org.apache.hadoop.hbase.http.InfoServer.start(InfoServer.java:91) at org.apache.hadoop.hbase.regionserver.HRegionServer.putUpWebUI(HRegionServer.java:1803) at org.apache.hadoop.hbase.regionserver.HRegionServer.<init>(HRegionServer.java:611) at org.apache.hadoop.hbase.master.HMaster.<init>(HMaster.java:390) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:526) at org.apache.hadoop.hbase.master.HMaster.constructMaster(HMaster.java:2450) ... 5 more Caused by: java.net.BindException: Address already in use at sun.nio.ch.Net.bind0(Native Method) at sun.nio.ch.Net.bind(Net.java:444) at sun.nio.ch.Net.bind(Net.java:436) at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:214) at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74) at org.mortbay.jetty.nio.SelectChannelConnector.open(SelectChannelConnector.java:216) at org.apache.hadoop.hbase.http.HttpServer.openListeners(HttpServer.java:1012) ... 15 more This is the console log at that time: 22:03:14 --> Starting HBase 22:03:15 HBase start attempt: 1/5 22:03:15 Killing any HBase processes possibly lingering from previous start attempts 22:03:15 Stopping Hbase 22:03:21 localhost: starting zookeeper, logging to /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/logs/cluster/hbase/hbase-jenkins-zookeeper-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out 22:03:21 starting master, logging to /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/logs/cluster/hbase/hbase-jenkins-master-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out 22:03:23 starting regionserver, logging to /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/logs/cluster/hbase/hbase-jenkins-1-regionserver-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out 22:03:24 starting regionserver, logging to /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/logs/cluster/hbase/hbase-jenkins-2-regionserver-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out 22:03:25 starting regionserver, logging to /data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/logs/cluster/hbase/hbase-jenkins-3-regionserver-impala-boost-static-burst-slave-01fe.vpc.cloudera.com.out 22:03:26 HBase startup scripts succeeded 22:03:26 --> Starting Hive Server and Metastore Service
          Hide
          dknupp David Knupp added a comment -

          Something I noticed when I was poking around testdata/bin while working on remote data loading. We have these three scripts:

          ~/Impala (asf-gerrit-master) $ find . | grep wait-for-
          ./testdata/bin/wait-for-metastore.py
          ./testdata/bin/wait-for-hiveserver2.py
          ./testdata/bin/wait-for-hbase-master.py
          

          ...but only the first two from that list ever seem to get called anywhere:

          ~/Impala (asf-gerrit-master) $ git grep wait-for-hiveserver2.py
          testdata/bin/run-hive-server.sh:  ${CLUSTER_BIN}/wait-for-hiveserver2.py --transport=${HIVES2_TRANSPORT}
          ~/Impala (asf-gerrit-master) $ git grep wait-for-metastore.py
          testdata/bin/run-hive-server.sh:${CLUSTER_BIN}/wait-for-metastore.py --transport=${METASTORE_TRANSPORT}
          testdata/bin/wait-for-hiveserver2.py:# TODO: Consider combining this with wait-for-metastore.py. A TCLIService client
          ~/Impala (asf-gerrit-master) $ git grep wait-for-hbase-master.py
          ~/Impala (asf-gerrit-master) $
          
          Show
          dknupp David Knupp added a comment - Something I noticed when I was poking around testdata/bin while working on remote data loading. We have these three scripts: ~/Impala (asf-gerrit-master) $ find . | grep wait- for - ./testdata/bin/wait- for -metastore.py ./testdata/bin/wait- for -hiveserver2.py ./testdata/bin/wait- for -hbase-master.py ...but only the first two from that list ever seem to get called anywhere: ~/Impala (asf-gerrit-master) $ git grep wait- for -hiveserver2.py testdata/bin/run-hive-server.sh: ${CLUSTER_BIN}/wait- for -hiveserver2.py --transport=${HIVES2_TRANSPORT} ~/Impala (asf-gerrit-master) $ git grep wait- for -metastore.py testdata/bin/run-hive-server.sh:${CLUSTER_BIN}/wait- for -metastore.py --transport=${METASTORE_TRANSPORT} testdata/bin/wait- for -hiveserver2.py:# TODO: Consider combining this with wait- for -metastore.py. A TCLIService client ~/Impala (asf-gerrit-master) $ git grep wait- for -hbase-master.py ~/Impala (asf-gerrit-master) $
          Hide
          mikesbrown Michael Brown added a comment -

          We got lucky and can see another process using port 60010. It's a HDFS data node:

          # netstat -ntlp | grep 60010
          tcp        0      0 127.0.0.1:60010             0.0.0.0:*                   LISTEN      23214/java
          # ps afuxw | grep [2]3214
          jenkins  23214  0.1  0.3 1661508 244792 ?      Sl   Sep05   3:48 /opt/toolchain/sun-jdk-64bit-1.7.0.75/bin/java -Dproc_datanode -Xmx1000m -DIBelongToTheMiniCluster -Dhadoop.log.dir=/data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/testdata/cluster/cdh5/node-2/var/log/hadoop-hdfs -Dhadoop.log.file=hdfs-datanode.log -Dhadoop.home.dir=/data/jenkins/workspace/impala-umbrella-build-and-test/Impala-Toolchain/cdh_components/hadoop-2.6.0-cdh5.10.0-SNAPSHOT -Dhadoop.id.str= -Dhadoop.root.logger=INFO,RFA -Djava.library.path=/data/jenkins/workspace/impala-umbrella-build-and-test/Impala-Toolchain/snappy-1.1.3/lib:/data/jenkins/workspace/impala-umbrella-build-and-test/Impala-Toolchain/cdh_components/hadoop-2.6.0-cdh5.10.0-SNAPSHOT/lib/native -Dhadoop.policy.file=hadoop-policy.xml -Djava.net.preferIPv4Stack=true -server -Dhadoop.security.logger=INFO,NullAppender org.apache.hadoop.hdfs.server.datanode.DataNode
          

          We can be reasonably sure this was the culprit interfering with HBase master at 22:03. From testdata/cluster/cdh5/node-2/var/log/hadoop-hdfs/hdfs-datanode.log:

          2016-09-05 22:02:40,598 INFO org.apache.hadoop.hdfs.server.datanode.web.DatanodeHttpServer: Listening HTTP traffic on /127.0.0.1:60010
          

          Why did this data node process choose 60010? What did the others choose?

          # find testdata/cluster/cdh5 -name hdfs-datanode.log -exec grep "Listening HTTP traffic" {} \;
          2016-09-05 22:02:40,633 INFO org.apache.hadoop.hdfs.server.datanode.web.DatanodeHttpServer: Listening HTTP traffic on /127.0.0.1:48373
          2016-09-05 22:02:40,598 INFO org.apache.hadoop.hdfs.server.datanode.web.DatanodeHttpServer: Listening HTTP traffic on /127.0.0.1:60010
          2016-09-05 22:02:43,612 INFO org.apache.hadoop.hdfs.server.datanode.web.DatanodeHttpServer: Listening HTTP traffic on /127.0.0.1:51398
          #
          

          This looks suspicious. The port numbers look random.


          Let's shift gears and look at my workstation/mincluster. I have some logs on my desktop minicluster going back a ways.... what do they say?

          Using some find/awk/grep/sort -u/wc commands I can say the following:

          1. The earliest log entry is from April 28
          2. There are 138 matches for "Listening HTTP traffic on". That's 46 minicluster restarts (138/3).
          3. There are 138 unique ports chosen. This means HDFS data nodes never picked the same HTTP server port twice.
          4. The lowest port number chosen was 33074.
          5. The highest port number chosen was 60781.
          $ cat /proc/sys/net/ipv4/ip_local_port_range
          32768	61000
          

          I think it's highly likely that HDFS data nodes pick a port from this range with which to start a HTTP server. Meanwhile HBase master always wants to be on 60100 (notably also in a very high port range and not traditionally well-known).

          So at random, HDFS will pick the port HBase master needs.

          I need to look into this HDFS HTTP server business and see if that can be changed.

          Show
          mikesbrown Michael Brown added a comment - We got lucky and can see another process using port 60010. It's a HDFS data node: # netstat -ntlp | grep 60010 tcp 0 0 127.0.0.1:60010 0.0.0.0:* LISTEN 23214/java # ps afuxw | grep [2]3214 jenkins 23214 0.1 0.3 1661508 244792 ? Sl Sep05 3:48 /opt/toolchain/sun-jdk-64bit-1.7.0.75/bin/java -Dproc_datanode -Xmx1000m -DIBelongToTheMiniCluster -Dhadoop.log.dir=/data/jenkins/workspace/impala-umbrella-build-and-test/repos/Impala/testdata/cluster/cdh5/node-2/var/log/hadoop-hdfs -Dhadoop.log.file=hdfs-datanode.log -Dhadoop.home.dir=/data/jenkins/workspace/impala-umbrella-build-and-test/Impala-Toolchain/cdh_components/hadoop-2.6.0-cdh5.10.0-SNAPSHOT -Dhadoop.id.str= -Dhadoop.root.logger=INFO,RFA -Djava.library.path=/data/jenkins/workspace/impala-umbrella-build-and-test/Impala-Toolchain/snappy-1.1.3/lib:/data/jenkins/workspace/impala-umbrella-build-and-test/Impala-Toolchain/cdh_components/hadoop-2.6.0-cdh5.10.0-SNAPSHOT/lib/native -Dhadoop.policy.file=hadoop-policy.xml -Djava.net.preferIPv4Stack=true -server -Dhadoop.security.logger=INFO,NullAppender org.apache.hadoop.hdfs.server.datanode.DataNode We can be reasonably sure this was the culprit interfering with HBase master at 22:03. From testdata/cluster/cdh5/node-2/var/log/hadoop-hdfs/hdfs-datanode.log : 2016-09-05 22:02:40,598 INFO org.apache.hadoop.hdfs.server.datanode.web.DatanodeHttpServer: Listening HTTP traffic on /127.0.0.1:60010 Why did this data node process choose 60010? What did the others choose? # find testdata/cluster/cdh5 -name hdfs-datanode.log -exec grep "Listening HTTP traffic" {} \; 2016-09-05 22:02:40,633 INFO org.apache.hadoop.hdfs.server.datanode.web.DatanodeHttpServer: Listening HTTP traffic on /127.0.0.1:48373 2016-09-05 22:02:40,598 INFO org.apache.hadoop.hdfs.server.datanode.web.DatanodeHttpServer: Listening HTTP traffic on /127.0.0.1:60010 2016-09-05 22:02:43,612 INFO org.apache.hadoop.hdfs.server.datanode.web.DatanodeHttpServer: Listening HTTP traffic on /127.0.0.1:51398 # This looks suspicious. The port numbers look random. Let's shift gears and look at my workstation/mincluster. I have some logs on my desktop minicluster going back a ways.... what do they say? Using some find/awk/grep/sort -u/wc commands I can say the following: The earliest log entry is from April 28 There are 138 matches for "Listening HTTP traffic on". That's 46 minicluster restarts (138/3). There are 138 unique ports chosen. This means HDFS data nodes never picked the same HTTP server port twice. The lowest port number chosen was 33074. The highest port number chosen was 60781. $ cat /proc/sys/net/ipv4/ip_local_port_range 32768 61000 I think it's highly likely that HDFS data nodes pick a port from this range with which to start a HTTP server. Meanwhile HBase master always wants to be on 60100 (notably also in a very high port range and not traditionally well-known). So at random, HDFS will pick the port HBase master needs. I need to look into this HDFS HTTP server business and see if that can be changed.
          Hide
          alex.behm Alexander Behm added a comment -

          Fantastic, thanks for digging into this Michael Brown and David Knupp!

          Show
          alex.behm Alexander Behm added a comment - Fantastic, thanks for digging into this Michael Brown and David Knupp !
          Hide
          mikesbrown Michael Brown added a comment -

          This particular culprit is the dfs.datanode.http.address in testdata/cluster/cdh5/node-{1,2,3}/etc/hadoop/conf/hdfs-site.xml.

          By default, the value is 127.0.0.1:0. I changed node-1 to be 127.0.0.1:65530 and sure enough, node-1 says this when it starts:

          2016-09-07 14:33:53,755 INFO org.apache.hadoop.hdfs.server.datanode.web.DatanodeHttpServer: Listening HTTP traffic on /127.0.0.1:65530
          

          I can't find the docs to confirm, but "127.0.0.1:0" or "0.0.0.0:0" must mean "pick any port in the IP local port range and bind accordingly." If this is true, there are many places in config templates where various ports might be opened that could be in the ip_local_port_range:

          $ find . -name "*tmpl" -exec egrep -q "<value>(127|0).0.0.[01]:0</value>" {} \; -print
          ./testdata/cluster/node_templates/cdh5/etc/hadoop/conf/yarn-site.xml.tmpl
          ./testdata/cluster/node_templates/common/etc/hadoop/conf/yarn-site.xml.tmpl
          ./testdata/cluster/node_templates/common/etc/hadoop/conf/hdfs-site.xml.tmpl
          $ 
          

          This might be hard to fix due to the minicluster, offsets, etc.

          A useful audit might be to see if there is a way to fix the case where hard-coded server ports exist within the ip_local_port_range and whether those are configurable to something outside it. HBase master is one; are there others?

          Show
          mikesbrown Michael Brown added a comment - This particular culprit is the dfs.datanode.http.address in testdata/cluster/cdh5/node-{1,2,3}/etc/hadoop/conf/hdfs-site.xml . By default, the value is 127.0.0.1:0 . I changed node-1 to be 127.0.0.1:65530 and sure enough, node-1 says this when it starts: 2016-09-07 14:33:53,755 INFO org.apache.hadoop.hdfs.server.datanode.web.DatanodeHttpServer: Listening HTTP traffic on /127.0.0.1:65530 I can't find the docs to confirm, but "127.0.0.1:0" or "0.0.0.0:0" must mean "pick any port in the IP local port range and bind accordingly." If this is true, there are many places in config templates where various ports might be opened that could be in the ip_local_port_range : $ find . -name "*tmpl" -exec egrep -q "<value>(127|0).0.0.[01]:0</value>" {} \; -print ./testdata/cluster/node_templates/cdh5/etc/hadoop/conf/yarn-site.xml.tmpl ./testdata/cluster/node_templates/common/etc/hadoop/conf/yarn-site.xml.tmpl ./testdata/cluster/node_templates/common/etc/hadoop/conf/hdfs-site.xml.tmpl $ This might be hard to fix due to the minicluster, offsets, etc. A useful audit might be to see if there is a way to fix the case where hard-coded server ports exist within the ip_local_port_range and whether those are configurable to something outside it. HBase master is one; are there others?
          Hide
          ishaan Ishaan Joshi added a comment -

          Michael Brown, unless I'm mistaken, I think we assign DN ports in testdata/server/admin script.

          https://github.com/cloudera/Impala/blob/cdh5-trunk/testdata/cluster/admin
          Relevant code:

          65 # All DataNodes and NodeManagers need a unique but fixed address. The IP is fixed at
           66 # 127.0.0.1, so the only difference is the port. The address must be fixed because it is
           67 # used as an identifier. If a node were restarted with a different address it would be
           68 # considered a new node. The values below are arbitrary and may conflict with existing
           69 # services. Fixed ports were preferred to dynamically chosen free ports for consistency.
           70 DATANODE_FREE_PORT_START=31000
          
          225   # For consistency, the first node will host all the master roles, including llama. Llama
          226   # needs to know the ports of the datanodes and nodemanagers. The ports are generated
          227   # below as part of setting up each node. The slave nodes are created first so the ports
          228   # will be known when it is time to configure llama.
          229   for ((NODE_IDX=$NODE_COUNT; NODE_IDX >= 1; NODE_IDX--)); do
          .
          .
          .
          .
          257     # Template population
          258     DATANODE_PORT=$((DATANODE_FREE_PORT_START++))
          259     NODEMANAGER_PORT=$((NODEMANAGER_FREE_PORT_START++))
          260     KUDU_TS_RPC_PORT=$((KUDU_TS_RPC_FREE_PORT_START++))
          261     echo "$NODE will use ports DATANODE_PORT=$DATANODE_PORT," \
          262         "NODEMANAGER_PORT=$NODEMANAGER_PORT, and KUDU_TS_RPC_PORT=$KUDU_TS_RPC_PORT"
          

          You might be able to affect a change there, and constrain the ports used by the DN.

          Show
          ishaan Ishaan Joshi added a comment - Michael Brown , unless I'm mistaken, I think we assign DN ports in testdata/server/admin script. https://github.com/cloudera/Impala/blob/cdh5-trunk/testdata/cluster/admin Relevant code: 65 # All DataNodes and NodeManagers need a unique but fixed address. The IP is fixed at 66 # 127.0.0.1, so the only difference is the port. The address must be fixed because it is 67 # used as an identifier. If a node were restarted with a different address it would be 68 # considered a new node. The values below are arbitrary and may conflict with existing 69 # services. Fixed ports were preferred to dynamically chosen free ports for consistency. 70 DATANODE_FREE_PORT_START=31000 225 # For consistency, the first node will host all the master roles, including llama. Llama 226 # needs to know the ports of the datanodes and nodemanagers. The ports are generated 227 # below as part of setting up each node. The slave nodes are created first so the ports 228 # will be known when it is time to configure llama. 229 for ((NODE_IDX=$NODE_COUNT; NODE_IDX >= 1; NODE_IDX--)); do . . . . 257 # Template population 258 DATANODE_PORT=$((DATANODE_FREE_PORT_START++)) 259 NODEMANAGER_PORT=$((NODEMANAGER_FREE_PORT_START++)) 260 KUDU_TS_RPC_PORT=$((KUDU_TS_RPC_FREE_PORT_START++)) 261 echo "$NODE will use ports DATANODE_PORT=$DATANODE_PORT," \ 262 "NODEMANAGER_PORT=$NODEMANAGER_PORT, and KUDU_TS_RPC_PORT=$KUDU_TS_RPC_PORT" You might be able to affect a change there, and constrain the ports used by the DN.
          Hide
          mikesbrown Michael Brown added a comment -

          This has happened a few more times, but thanks to David Knupp's patch we fail a lot faster now. Thanks David Knupp!

          Show
          mikesbrown Michael Brown added a comment - This has happened a few more times, but thanks to David Knupp 's patch we fail a lot faster now. Thanks David Knupp !
          Show
          twmarshall Thomas Tauber-Marshall added a comment - Looks like we saw another instance of this: http://sandbox.jenkins.cloudera.com/view/Impala/view/Evergreen-asf-master/job/impala-asf-master-exhaustive/134/
          Hide
          laszlog Laszlo Gaal added a comment - - edited

          There are several such port assignments in yarn-site.xml.tmpl and hdfs-site.xml.tmpl:

          laszlog@laszlog1:~/Impala-ref$ find . -name "*.tmpl" -exec grep -H  ':0</value>' {} \;
          ./testdata/cluster/node_templates/cdh5/etc/hadoop/conf/yarn-site.xml.tmpl:    <value>127.0.0.1:0</value>
          ./testdata/cluster/node_templates/cdh5/etc/hadoop/conf/yarn-site.xml.tmpl:    <value>127.0.0.1:0</value>
          ./testdata/cluster/node_templates/common/etc/hadoop/conf/hdfs-site.xml.tmpl:    <value>127.0.0.1:0</value>
          ./testdata/cluster/node_templates/common/etc/hadoop/conf/hdfs-site.xml.tmpl:    <value>127.0.0.1:0</value>
          ./testdata/cluster/node_templates/common/etc/hadoop/conf/hdfs-site.xml.tmpl:    <value>0.0.0.0:0</value>
          ./testdata/cluster/node_templates/common/etc/hadoop/conf/yarn-site.xml.tmpl:    <value>127.0.0.1:0</value>
          ./testdata/cluster/node_templates/common/etc/hadoop/conf/yarn-site.xml.tmpl:    <value>127.0.0.1:0</value>
          

          Following Ishaan Joshi's pointer, I"m proposing to add predefined ranges for all these port assingments in the testdata/cluster/admin script:

          DATANODE_FREE_PORT_START=31000
          DATANODE_FREE_HTTP_PORT_START=31010
          DATANODE_FREE_IPC_PORT_START=31020
          DATANODE_FREE_HTTPS_PORT_START=31030
          NODEMANAGER_FREE_PORT_START=31100
          NODEMANAGER_FREE_LOCALIZER_PORT_START=31120
          NODEMANAGER_FREE_WEBUI_PORT_START=31140
          KUDU_TS_RPC_FREE_PORT_START=31200
          KUDU_TS_WEBUI_FREE_PORT_START=31300
          

          [edited a typo in the name "yarn-site.xml.tmpl"]

          Show
          laszlog Laszlo Gaal added a comment - - edited There are several such port assignments in yarn-site.xml.tmpl and hdfs-site.xml.tmpl: laszlog@laszlog1:~/Impala-ref$ find . -name "*.tmpl" -exec grep -H ':0</value>' {} \; ./testdata/cluster/node_templates/cdh5/etc/hadoop/conf/yarn-site.xml.tmpl: <value>127.0.0.1:0</value> ./testdata/cluster/node_templates/cdh5/etc/hadoop/conf/yarn-site.xml.tmpl: <value>127.0.0.1:0</value> ./testdata/cluster/node_templates/common/etc/hadoop/conf/hdfs-site.xml.tmpl: <value>127.0.0.1:0</value> ./testdata/cluster/node_templates/common/etc/hadoop/conf/hdfs-site.xml.tmpl: <value>127.0.0.1:0</value> ./testdata/cluster/node_templates/common/etc/hadoop/conf/hdfs-site.xml.tmpl: <value>0.0.0.0:0</value> ./testdata/cluster/node_templates/common/etc/hadoop/conf/yarn-site.xml.tmpl: <value>127.0.0.1:0</value> ./testdata/cluster/node_templates/common/etc/hadoop/conf/yarn-site.xml.tmpl: <value>127.0.0.1:0</value> Following Ishaan Joshi 's pointer, I"m proposing to add predefined ranges for all these port assingments in the testdata/cluster/admin script: DATANODE_FREE_PORT_START=31000 DATANODE_FREE_HTTP_PORT_START=31010 DATANODE_FREE_IPC_PORT_START=31020 DATANODE_FREE_HTTPS_PORT_START=31030 NODEMANAGER_FREE_PORT_START=31100 NODEMANAGER_FREE_LOCALIZER_PORT_START=31120 NODEMANAGER_FREE_WEBUI_PORT_START=31140 KUDU_TS_RPC_FREE_PORT_START=31200 KUDU_TS_WEBUI_FREE_PORT_START=31300 [edited a typo in the name "yarn-site.xml.tmpl"]
          Hide
          laszlog Laszlo Gaal added a comment -

          I've posted a review for the change at https://gerrit.cloudera.org/#/c/6531/1

          Show
          laszlog Laszlo Gaal added a comment - I've posted a review for the change at https://gerrit.cloudera.org/#/c/6531/1
          Hide
          laszlog Laszlo Gaal added a comment -

          https://git-wip-us.apache.org/repos/asf?p=incubator-impala.git;a=commit;h=9e7fb830fd047ed6445ea82280993e56ea51e15b

          IMPALA-4088: Assign fix values to the minicluster server ports

          The minicluster setup logic assigned fixed port numbers to several
          but not all listening sockets of the data nodes. This change
          assigns similar port ranges to all the listening ports that were
          so far allowed to pick their own port numbers, interfering with
          other components, e.g. HBase.

          Change-Id: Iecf312873b7026c52b0ac0e71adbecab181925a0
          Reviewed-on: http://gerrit.cloudera.org:8080/6531
          Reviewed-by: Michael Brown <mikeb@cloudera.com>
          Tested-by: Impala Public Jenkins

          Show
          laszlog Laszlo Gaal added a comment - https://git-wip-us.apache.org/repos/asf?p=incubator-impala.git;a=commit;h=9e7fb830fd047ed6445ea82280993e56ea51e15b IMPALA-4088 : Assign fix values to the minicluster server ports The minicluster setup logic assigned fixed port numbers to several but not all listening sockets of the data nodes. This change assigns similar port ranges to all the listening ports that were so far allowed to pick their own port numbers, interfering with other components, e.g. HBase. Change-Id: Iecf312873b7026c52b0ac0e71adbecab181925a0 Reviewed-on: http://gerrit.cloudera.org:8080/6531 Reviewed-by: Michael Brown <mikeb@cloudera.com> Tested-by: Impala Public Jenkins

            People

            • Assignee:
              laszlog Laszlo Gaal
              Reporter:
              alex.behm Alexander Behm
            • Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development