spring cloud zuul路由组件GENERAL异常之192.168.2.103:8080 connect timed out
本文只是将自己在学习spring cloud zuul组件时发现的connect timed out问题进行了归纳总结。大致背景是这样的:
项目路径: https://github.com/AvengerEug/spring-cloud.git 的zuul分支。若读者要自行测试(最好是跟着一起来，可以学会如何debug源码找到问题根源)，可执行如下代码:
git clone https://github.com/AvengerEug/spring-cloud.git -b zuul
项目结构
| 微服务名 | ip地址 | 端口 | 是否启动 |
|---|---|---|---|
| eureka | 102.168.2.103 | 8000 | 是 |
| zuul | 192.168.2.103 | 9000 | 是 |
| user-service | 192.168.2.103 | 5000(以java config的方式配置的，这里有坑，注意下) | 是 |
| order-service | 192.168.2.103 | 6001 | 否 |
| order-service-2 | 192.168.2.103 | 6002 | 否 |
| goods-service | 192.168.2.103 | 7001 | 否 |
| goods-service-2 | 192.168.2.103 | 7002 | 否 |
注意事项: spring cloud版本: Finchley.SR2, 使用@EnableZuulProxy注解启动zuul(有两个注解可以启动, 分别是: @EnableZuulProxy和@EnableZuulServer, 这两个有区别，但不在此篇博客中总结)
我们在学习zuul时能知道，它具有路由网关的作用，若我们不添加zuul路由的相关配置时，我们可以指定服务名来请求具体的服务. eg: http://192.168.2.103:9000/user-service/v1/users/index, 这样我们就能请求到user这个模块的/v1/users/index这个接口了。
将项目clone下来并编译完成(maven项目)。相继启动: eureka, user-service, zuul三个模块。随后在浏览器中访问: http://localhost:9000/user-service/v1/users/index。 然后你会发现，卧槽，页面报500？
我们再看一下控制台？纳尼？connect time out?
再仔细一看，咦，zuul作为路由网管，讲道理会将这个请求转发给user-service模块呀，可是我的user-service模块的端口是5000呀？怎么会变成了8080, 于是我不信邪，又将order-service-2模块(因为order-service模块的/v1/orders/index api当时测试了hystrix的功能，所以在内部抛了异常，为了验证zuul有没有生效，所以启动了order-service-2模块)启动了，怀着满腔热血的我在项目启动后立马在浏览器上访问: http://localhost:9000/order-service/v1/orders/index，卧槽？玩我？404？
我当时是内心崩溃的，我以为我的zuul是假的，别人玩的都是正常的，一到我来玩它它就坏了？经过狂刷新浏览器的一番操作后，它终于出现了我想要的页面。(在这里我踩了很久的坑，最后才发现是因为order-service-2服务启动后，刚好过了zuul定时从eureka同步服务信息的时间，zuul中无order-service-2服务的相关信息，导致请求是404)
经过我的一番研究后(对比user-service和order-service模块的差异)，发现差异点就是我将user-service模块tomcat的端口是以java config的方式配置的:
后来我灵机一动，将user-service模块的tomcat端口配置移动至application.yml文件中(去掉java config的方式，在application.yml文件中配置server.port = 5000)，重启、访问(最好是将zuul也重启下，否则需要等zuul同步完信息后才能正常访问user-service模块的api)。最后，浏览器上出现了我想要的画面：
俗话说好奇害死猫，但我不是猫。我想知道为什么以java config的方式配置的端口，最终经过zuul后会变成默认的8080端口？于是我决定看一下最开始呈现出来的异常: GENERAL异常之 192.168.2.103:8080 connect timed out
通常java抛出的异常我们是能在控制台中看到完成的调用链的。现在我们回归文章的第二张图:
其实异常栈很长，具体如下:
com.netflix.zuul.exception.ZuulException: Forwarding error
at org.springframework.cloud.netflix.zuul.filters.route.RibbonRoutingFilter.handleException(RibbonRoutingFilter.java:191) ~[spring-cloud-netflix-zuul-2.0.2.RELEASE.jar:2.0.2.RELEASE]
xxxx 后面的调用栈省略
Caused by: com.netflix.client.ClientException: null
at com.netflix.client.AbstractLoadBalancerAwareClient.executeWithLoadBalancer(AbstractLoadBalancerAwareClient.java:118) ~[ribbon-loadbalancer-2.2.5.jar:2.2.5]
xxxx 后面的调用栈省略
Caused by: java.lang.RuntimeException: org.apache.http.conn.ConnectTimeoutException: Connect to 192.168.2.103:8080 [/192.168.2.103] failed: connect timed out
at rx.exceptions.Exceptions.propagate(Exceptions.java:57) ~[rxjava-1.3.8.jar:1.3.8]
xxxx 后面的调用栈省略
Caused by: org.apache.http.conn.ConnectTimeoutException: Connect to 192.168.2.103:8080 [/192.168.2.103] failed: connect timed out
at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:151) ~[httpclient-4.5.6.jar:4.5.6]
xxxx 后面的调用栈省略
Caused by: java.net.SocketTimeoutException: connect timed out
at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method) ~[na:1.8.0_131]
xxxx 后面的调用栈省略
那我们要如何定位到具体是哪一个方法抛出的异常呢？一般是自下而上！
其实抛出的异常已经告诉我们了，
拿最下面一段异常来说:
Caused by: java.net.SocketTimeoutException: connect timed out
at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method) ~[na:1.8.0_131]
xxxx 后面的调用栈省略
它已经明确告诉了我们具体在哪一个地方抛出了异常(一般是caused by下面的第一行调用栈)，对这段异常而言，出现问题的方法是在java.net.DualStackPlainSocketImpl.waitForConnect(Native Method)中，但是请注意，它有native修饰，一般就是调用open jdk里面的方法了，这里比较底层，我们不需要关注。所以我们继续看上一段异常。
Caused by: org.apache.http.conn.ConnectTimeoutException: Connect to 192.168.2.103:8080 [/192.168.2.103] failed: connect timed out
at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:151) ~[httpclient-4.5.6.jar:4.5.6]
xxxx 后面的调用栈省略
咦，这个应该就是普通的java类抛出的异常了，于是我们立马定位到DefaultHttpClientConnectionOperator类的connect方法的151行，于是在这个地方添加断点。并重新在浏览器请求http://localhost:9000/user-service/v1/users/index，发现进入了断点，如图：
我们来分析下背景：http://localhost:9000/user-service/v1/users/index请求是通过zuul路由到具体的user-service服务的，所以最终的请求应该会指向user-service(即需要ip地址和port以及请求的uri)，但是我们从图中可以知道，host为192.168.2.103:8080，是我本地ip没错，但是port为什么变成了8080？我压根就没有服务占用8080端口啊，而且设置的链接时间为1s，那肯定会connect time out呀！。于是我根据左侧的方法调用栈一步一步追踪host的传递链。最终发现在host的信息是com.netflix.loadbalancer.reactive.LoadBalancerCommand的selectServer()方法中返回的。方法源码如下:
private Observable selectServer() {
return Observable.create(new OnSubscribe() {
@Override
public void call(Subscriber next) {
try {
Server server = loadBalancerContext.getServerFromLoadBalancer(loadBalancerURI, loadBalancerKey);
next.onNext(server);
next.onCompleted();
} catch (Exception e) {
next.onError(e);
}
}
});
}
最终在Server server = loadBalancerContext.getServerFromLoadBalancer(loadBalancerURI, loadBalancerKey); 处添加了断点，于是重新在浏览器请求: http://localhost:9000/user-service/v1/users/index, 进入断点:
于是我们进入方法(我使用的是eclipse的快捷键，所以我按了f5)。我的天，里面的逻辑这么多，我怎么知道他是怎么返回的呀，于是我将方法所有的return处都加上断点，直接按f8(再次说明我用的是eclipse的跳过断点的快捷键)，最终发现它是在如图所示处return出去的:
发现它return出去的只是一个局部变量svc, 而这个svc是通过Server svc = lb.chooseServer(loadBalancerKey)获取的，于是我们将断点加到这一行，并重新发送http://localhost:9000/user-service/v1/users/index请求，进入断点:
同理，按F5进入方法内部(此时的lb的类型为ZoneAwareLoadBalancer，由debug下方Variables区域可知)，同上，将所有的return都加上断点，最终发现在super.chooseServer(key); 进行了return，如图：
根据上述debug流程，一步步的往下走，最终在PredicateBasedRule类的choose(Object key)方法中获取到了server：
，经过多次断点测试，最终得知是从图中的ZoneAwareLoadBalancer类的getAllServers()方法获取到server。可是ZoneAwareLoadBalancer类中并没有getAllservers方法，而lb是一个接口，那么为啥没有getAllservers方法呢？很简单，它继承了一个父类，由父类实现了getAllservers方法。所以最终执行getAllservers方法的是父类com.netflix.loadbalancer.BaseLoadBalancer。源码如下:
@Override
public List getAllServers() {
return Collections.unmodifiableList(allServerList);
}
由源码可知，所有的server(这里就是注册微服务)信息会从当前类(BaseLoadBalancer)中的allServerList属性中去获取。所以我们现在要改变下反向，即要确认BaseLoadBalancer类的allServerList属性的值什么时候被填充的。
2.2 探究BaseLoadBalancer类的allServerList属性何时被填充 看源码得知，此属性是一个list:@Monitor(name = PREFIX + "AllServerList", type = DataSourceType.INFORMATIONAL)
protected volatile List allServerList = Collections
.synchronizedList(new ArrayList());
根据list的特性，要想增加元素的数量，最终会执行add方法，或者修改它的引用，所以我搜索了所有用到了allServerList属性的地方。发现类中并没有它的add操作。这样的话，那就只有一种情况了: 修改了它的引用。最终发现在setServersList(List lsrv)方法中对allServerList做了修改引用的操作，public void setServersList(List lsrv) {
Lock writeLock = allServerLock.writeLock();
logger.debug("LoadBalancer [{}]: clearing server list (SET op)", name);
ArrayList newServers = new ArrayList();
writeLock.lock();
try {
ArrayList allServers = new ArrayList();
for (Object server : lsrv) {
if (server == null) {
continue;
}
if (server instanceof String) {
server = new Server((String) server);
}
if (server instanceof Server) {
logger.debug("LoadBalancer [{}]: addServer [{}]", name, ((Server) server).getId());
allServers.add((Server) server);
} else {
throw new IllegalArgumentException(
"Type String or Server expected, instead found:"
+ server.getClass());
}
}
boolean listChanged = false;
if (!allServerList.equals(allServers)) {
listChanged = true;
if (changeListeners != null && changeListeners.size() > 0) {
List oldList = ImmutableList.copyOf(allServerList);
List newList = ImmutableList.copyOf(allServers);
for (ServerListChangeListener l: changeListeners) {
try {
l.serverListChanged(oldList, newList);
} catch (Exception e) {
logger.error("LoadBalancer [{}]: Error invoking server list change listener", name, e);
}
}
}
}
if (isEnablePrimingConnections()) {
for (Server server : allServers) {
if (!allServerList.contains(server)) {
server.setReadyToServe(false);
newServers.add((Server) server);
}
}
if (primeConnections != null) {
primeConnections.primeConnectionsAsync(newServers, this);
}
}
// This will reset readyToServe flag to true on all servers
// regardless whether
// previous priming connections are success or not
// 在此处修改了引用
allServerList = allServers;
if (canSkipPing()) {
for (Server s : allServerList) {
s.setAlive(true);
}
upServerList = allServerList;
} else if (listChanged) {
forceQuickPing();
}
} finally {
writeLock.unlock();
}
}
根据此方法的逻辑，最终发现是根据遍历传入的lsrv参数(一个list)来填充内部维护的list，再赋值给allServerList。所以我们在allServerList = allServers; 代码处添加了断点。按照上述的套路，我重新发送请求: http://localhost:9000/user-service/v1/users/index. 可是它死活不进入这个断点。于是我使用了万能的 重启大法, 将zuul服务重启，启动完成后，我什么事都没干，于是它出奇的进入了刚刚打入的断点，于是才恍然大悟: zuul内部维护了一些定时task来同步eureka的服务信息。
由断点的图可知，allServers总共数量就为1，且appName就是user-service。所以我们要定位到参数lsrv是哪里传进去的。最终我们定位到了com.netflix.loadbalancer.DynamicServerListLoadBalancer类的
updateListOfServers方法。源码如下:@VisibleForTesting
public void updateListOfServers() {
List servers = new ArrayList();
if (serverListImpl != null) {
servers = serverListImpl.getUpdatedListOfServers();
LOGGER.debug("List of Servers for {} obtained from Discovery client: {}",
getIdentifier(), servers);
if (filter != null) {
servers = filter.getFilteredListOfServers(servers);
LOGGER.debug("Filtered List of Servers for {} obtained from Discovery client: {}",
getIdentifier(), servers);
}
}
updateAllServerList(servers);
}
最终我们定位到了这行代码: servers = serverListImpl.getUpdatedListOfServers(), 于是我们将断点定位到此。并等待zuul的定时任务启动，
由图可知serverListImpl的具体类是org.springframework.cloud.netflix.ribbon.eureka.DomainExtractingServerList, 所以点击进入DomainExtractingServerList的getUpdatedListOfServers()方法:
@Override
public List getUpdatedListOfServers() {
List servers = setZones(this.list
.getUpdatedListOfServers());
return servers;
}
发现是通过内部维护的list来更新存储服务的list的。
最终进入com.netflix.niws.loadbalancer.DiscoveryEnabledNIWSServerList的getUpdatedListOfServers方法，继续debug并探究一番代码后，发现它在如下图所示的代码处从eureka获取了服务信息
由图中可知eurekaClient是一个CloudEurekaClient的动态代理对象，因为我们只关系核心业务逻辑，所以我们直接在CloudEurekaClient中找带三个参数的getInstancesByVipAddress方法。可是它没有这个方法，同上，我们在它的父类中找，然后在父类找到了带三个参数的getInstancesByVipAddress方法。最终定位在这。
发现它是在如图所示的代码中将eureka的实例信息进行返回的。最终我们又找到了Applications类的getInstancesByVirtualHostName方法，发现所有的实例信息是从它内部维护一个叫virtualHostNameAppMap的ConcurrentHashMap得到的。所以我们现在又把目标移动到了Applications类的virtualHostNameAppMap属性何时被填充的过程中去了。 2.3 探究BApplications类的virtualHostNameAppMap属性何时被填充 同上，我们从两个方向去定位: 一个是ConcurrentHashMap的put api。另一个是赋值引用。根据这两个方向，和不断尝试(这个尝试也是坑，因为这个属性的填充是在启动zuul服务时触发的)，我们把问题定位到了addInstancesToVIPMaps方法中。 所以我们重启zuul，最终发现user-service服务和order-service都是在此方法中被注册了，如图:
根据debug调用链，我定位到了如下两个地方:
看到这，我们是否已经明白了什么了呢？我大胆的在浏览器输入
http://localhost:8000/eureka/apps, 浏览器渲染出我debug这么久想知道的信息:
这尼玛，我想知道的信息原来这么容易就出现了！！！ 三、小结 我相信大多数人学东西的时候都是直接在百度上搜索教程，或者直接找视频照着敲。其实最好的方式是还要结合官网 + github。因为官网有些东西是最权威的，而且一些开源的项目肯定会在全球最大同性交友网中提供源码，所以还要关注下github项目中的README.md文件以及wiki中的文档。比如刚刚就花了大多数时间去看源码找为什么会time out，我也是跟着源码才发现eureka有rest api操作, 后来才去github上找到了eureka关于rest api操作的文档(点击可跳转)，虽然这是eureka提供的api，spring cloud封装eureka后可能会进行修改，但是我们有这个方向后，再去百度上度一下相关内容，不就也能明白大概了么。
当然此次总结最重要的还是要了解项目抛出异常时如何去定位问题，以及一些经验(重启大法等等)，开源项目那么多，所涉及的技术那么多，当我们遇到问题时有时候只能靠猜，当然这个猜也不是乱猜，也要根据自己的一些自己的经验、项目的背景和功能需求去猜。比如我们若是不知道zuul可以做路由网关，那么我们怎么就能知道 http://192.168.2.103:8080 一定就是和user-service的端口不匹配呢？ 因为我们知道它最终肯定要请求到user-service模块，那么肯定要知道模块的ip地址和端口号呀。
还记录一个坑: 版本为Finchley.SR2的spring cloud，服务以java config的方式进行配置tomcat端口，并注册到eureka。通过eureka的rest api获取所有的服务信息时，此端口信息不会正常返回，而是返回默认的8080
仓库地址:https://github.com/AvengerEug/spring-cloud/tree/zuul
clone至本地: git clone https://github.com/AvengerEug/spring-cloud.git -b zuul
I am a slow walker, but I never walk backwards.
作者：AvengerEug
