环境

  • 管理端：soul-admin v2.2.1
  • 客户端：soul-spring-boot-starter-client-springmvc v2.2.1
  • 网关：v2.2.1 websocket连接
  • 插件：divide
  • 单机+多机
    • 网段有两个
  • springboot项目

**

问题叙述和处理

  • 在开发中的某一天发现有时候项目注册不到soul上去，检查发现数据库连接问题于是换了个数据库
    • 数据库发现问题有二
      • 放数据库的机子ip访问慢
      • 数据库连接满了
    • 项目使用divide插件注册失败问题阐述 - 图1

  • 更改了数据库时顺便更换了部署 soul-admin的服务器，于是新的问题出现了

    • 由于是双ip段，导致soul-admin轮询是ping不同注册上去的ip，源码追踪发现的问题和解决方法

      • 轮询 UpstreamCheckService 155行 check方法 检查服务健康状况

      • UpstreamCheckUtils 类 68行使用socket做的ip端口的有效验证

        • 发现检查时使用的 host = 注册上去的ip
          1. socket.connect(new InetSocketAddress(host, port));

      • 同时发现注册的方法入参（org.dromara.soul.client.springmvc.config.SoulSpringMvcConfig）中有 host

  • 上述问题处理完之后遇到了大麻烦，我也不清楚是配置问题还是其他，总之三个项目就其中一个老是出现这个问题，描述如下socket 连接超时造成了异常下线

socket 连接超时造成了异常下线

  • 在org.dromara.soul.admin.service.impl.UpstreamCheckService中的轮询final boolean pass = UpstreamCheckUtils.checkUrl(divideUpstream.getUpstreamUrl());上下输出ping服务的开始结束时间，发现了问题
    • 当15:51:19进行轮询时，15:51:20时项目进行了注册，同时在15:51:19 socket 验证时发生了延迟，导致15:51:21后才验证完，此时服务已经注册，这边才验证玩，并且验证结果为false,从而进行了下线操作
      • 15:51:19 项目还没启动socket时访问不到的
    • 项目使用divide插件注册失败问题阐述 - 图2

  • 尝试处理

    • 在org.dromara.soul.common.utils.checkUrl 方法中加入了一个重连

      • 导致加剧了这种情况 - 废弃 ```java /**
        • Check url boolean. *
        • @param url the url
        • @return the boolean */ public static boolean checkUrl(final String url) { if (!checkUrl2(url)) { return checkUrl2(url); } return true;

      }

/**

  1.  * Check url boolean.
  2.  *
  3.  * @param url the url
  4.  * @return the boolean
  5.  */
  6. private static boolean checkUrl2(final String url) {
  7.     if (StringUtils.isBlank(url)) {
  8.         return false;
  9.     }
  10.     if (checkIP(url)) {
  11.         String[] hostPort;
  12.         if (url.startsWith(HTTP)) {
  13.             final String[] http = StringUtils.split(url, "\\/\\/");
  14.             hostPort = StringUtils.split(http[1], Constants.COLONS);
  15.         } else {
  16.             hostPort = StringUtils.split(url, Constants.COLONS);
  17.         }
  18.         return isHostConnector(hostPort[0], Integer.parseInt(hostPort[1]));
  19.     } else {
  20.         return isHostReachable(url);
  21.     }
  22. }
  2.    - 发现 socket连接没有设置超时
  3.       - 测试发现连接异常时默认2050毫秒左右才抛出异常断（测试2次）
  4.          - 正常连接时在0~11毫秒之间
  5.       - 手动设置100~500毫秒试试（测试3次）
  6.          - 异常抛出稳定在了100~毫秒
  7. ```java
  8. private static boolean isHostConnector(final String host, final int port) {
  9.         Long startTime = System.currentTimeMillis();
  10.         try (Socket socket = new Socket()) {
  11.             //socket.connect(new InetSocketAddress(host, port));
  12.             socket.connect(new InetSocketAddress(host, port),100);
  13.         } catch (IOException e) {
  14.             Long endTime = System.currentTimeMillis();
  15.             System.out.println("sockt连接时间"+(endTime-startTime)+"毫秒");
  16.             return false;
  17.         }
  18.         Long endTime = System.currentTimeMillis();
  19.         System.out.println("sockt连接时间"+(endTime-startTime)+"毫秒");
  20.         return true;
  21.     }
  23. /*----------------------- 默认超时测试 -----------------------*/
  24. ping项目开始：2021-02-19 10:32:10
  25. sockt连接时间1毫秒
  26. ping项目结束 -> true：2021-02-19 10:32:10
  27. ping项目开始：2021-02-19 10:32:20
  28. sockt连接时间1毫秒
  29. ping项目结束 -> true：2021-02-19 10:32:20
  30. ping项目开始：2021-02-19 10:32:30
  31. sockt连接时间0毫秒
  32. ping项目结束 -> true：2021-02-19 10:32:30
  33. ping项目开始：2021-02-19 10:32:40
  34. sockt连接时间2042毫秒
  35. ping项目结束 -> false：2021-02-19 10:32:42
  36. 2021-02-19 10:32:42.895 ERROR 25448 --- [upstream-task-1] o.d.s.a.s.impl.UpstreamCheckService      : check the url=192.168.0.51:9001 is fail 
  37. ping项目开始：2021-02-19 10:33:13
  38. sockt连接时间1毫秒
  39. ping项目结束 -> true：2021-02-19 10:33:13
  40. ping项目开始：2021-02-19 10:33:23
  41. sockt连接时间0毫秒
  42. ping项目结束 -> true：2021-02-19 10:33:23
  43. ping项目开始：2021-02-19 10:33:33
  44. sockt连接时间11毫秒
  45. ping项目结束 -> true：2021-02-19 10:33:33
  46. ping项目开始：2021-02-19 10:33:43
  47. sockt连接时间0毫秒
  48. ping项目结束 -> true：2021-02-19 10:33:43
  49. ping项目开始：2021-02-19 10:33:53
  50. sockt连接时间1毫秒
  51. ping项目结束 -> true：2021-02-19 10:33:53
  52. ping项目开始：2021-02-19 10:34:03
  53. sockt连接时间0毫秒
  54. ping项目结束 -> true：2021-02-19 10:34:03
  55. ping项目开始：2021-02-19 10:34:13
  56. sockt连接时间1毫秒
  57. ping项目结束 -> true：2021-02-19 10:34:13
  58. ping项目开始：2021-02-19 10:34:23
  59. sockt连接时间0毫秒
  60. ping项目结束 -> true：2021-02-19 10:34:23
  61. ping项目开始：2021-02-19 10:34:33
  62. sockt连接时间0毫秒
  63. ping项目结束 -> true：2021-02-19 10:34:33
  64. ping项目开始：2021-02-19 10:34:43
  65. sockt连接时间0毫秒
  66. ping项目结束 -> true：2021-02-19 10:34:43
  67. ping项目开始：2021-02-19 10:34:53
  68. sockt连接时间1毫秒
  69. ping项目结束 -> true：2021-02-19 10:34:53
  70. ping项目开始：2021-02-19 10:35:03
  71. sockt连接时间0毫秒
  72. ping项目结束 -> true：2021-02-19 10:35:03
  73. ping项目开始：2021-02-19 10:35:13
  74. sockt连接时间1毫秒
  75. ping项目结束 -> true：2021-02-19 10:35:13
  76. ping项目开始：2021-02-19 10:35:23
  77. sockt连接时间0毫秒
  78. ping项目结束 -> true：2021-02-19 10:35:23
  79. ping项目开始：2021-02-19 10:35:33
  80. sockt连接时间2毫秒
  81. ping项目结束 -> true：2021-02-19 10:35:33
  82. ping项目开始：2021-02-19 10:35:43
  83. sockt连接时间2039毫秒
  84. ping项目结束 -> false：2021-02-19 10:35:45
  85. 2021-02-19 10:35:45.334 ERROR 25448 --- [upstream-task-2] o.d.s.a.s.impl.UpstreamCheckService      : check the url=192.168.0.51:9001 is fail 
  87. /*----------------------- 设置100~500毫秒超时测试 -----------------------*/
  88. ping项目开始：2021-02-19 10:46:29
  89. sockt连接时间1毫秒
  90. ping项目结束 -> true：2021-02-19 10:46:29
  91. ping项目开始：2021-02-19 10:46:39
  92. sockt连接时间0毫秒
  93. ping项目结束 -> true：2021-02-19 10:46:39
  94. ping项目开始：2021-02-19 10:46:49
  95. sockt连接时间1毫秒
  96. ping项目结束 -> true：2021-02-19 10:46:49
  97. ping项目开始：2021-02-19 10:46:59
  98. sockt连接时间0毫秒
  99. ping项目结束 -> true：2021-02-19 10:46:59
  100. ping项目开始：2021-02-19 10:47:09
  101. sockt连接时间111毫秒
  102. ping项目结束 -> false：2021-02-19 10:47:09
  103. 2021-02-19 10:47:09.993 ERROR 12728 --- [upstream-task-3] o.d.s.a.s.impl.UpstreamCheckService      : check the url=192.168.0.51:9001 is fail 
  104. 2021-02-19 10:47:15.002  WARN 12728 --- [upstream-task-3] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection com.mysql.jdbc.JDBC4Connection@6546761b (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
  105. ping项目开始：2021-02-19 10:47:25
  106. sockt连接时间112毫秒
  107. ping项目结束 -> false：2021-02-19 10:47:25
  108. 2021-02-19 10:47:25.431 ERROR 12728 --- [upstream-task-3] o.d.s.a.s.impl.UpstreamCheckService      : check the url=192.168.0.51:9001 is fail 
  109. ping项目开始：2021-02-19 10:47:55
  110. sockt连接时间1毫秒
  111. ping项目结束 -> true：2021-02-19 10:47:55
  112. ping项目开始：2021-02-19 10:48:05
  113. sockt连接时间0毫秒
  114. ping项目结束 -> true：2021-02-19 10:48:05
  115. ping项目开始：2021-02-19 10:48:15
  116. sockt连接时间112毫秒
  117. ping项目结束 -> false：2021-02-19 10:48:15
  118. 2021-02-19 10:48:15.819 ERROR 12728 --- [upstream-task-3] o.d.s.a.s.impl.UpstreamCheckService      : check the url=192.168.0.51:9001 is fail 
  119. ping项目开始：2021-02-19 10:48:36
  120. sockt连接时间1毫秒
  121. ping项目结束 -> true：2021-02-19 10:48:36
  122. ping项目开始：2021-02-19 10:48:46
  123. sockt连接时间0毫秒
  124. ping项目结束 -> true：2021-02-19 10:48:46
  125. ping项目开始：2021-02-19 10:48:56
  126. sockt连接时间112毫秒
  127. ping项目结束 -> false：2021-02-19 10:48:56
  128. 2021-02-19 10:48:56.180 ERROR 12728 --- [upstream-task-2] o.d.s.a.s.impl.UpstreamCheckService      : check the url=192.168.0.51:9001 is fail
  1.      - 同时测试上述 **轮询** 出现的异常下线问题  （测试方法疯狂重启）
  2.         - 问题并没有改善,但是发现注册成功后一秒，轮询发生了检查失败，猜想可能是项目完成启动
  1. 2021-02-19 10:56:57 |INFO   |org.dromara.soul.client.common.utils.RegisterUtils:48 
  2. ping项目开始：2021-02-19 10:56:58
  3. sockt连接时间112毫秒
  4. ping项目结束 -> false：2021-02-19 10:56:58
  • 启动时自动注册的实现方法为org.dromara.soul.client.springmvc.init.ContextRegisterListener
    • 调用注册接口 -> 保存数据 -> 发布事件 -> 触发DataChangedEventDispatcher -> 将注册信息写进缓存 && 发送webSocket消息
  • 注册后发布事件
    1. - `org.dromara.soul.admin.service.impl.handlerSpringMvcSelector`

    测试注册流程

    测试数据

  • 数据说明

    • 注册时间 = org.dromara.soul.client.common.utils.RegisterUtils:48 打印
    • 轮询时间 = final boolean pass = UpstreamCheckUtils.checkUrl(divideUpstream.getUpstreamUrl());之前的打印
    • 项目启动时间 = org.apache.coyote.http11.Http11NioProtocol:173 打印 Starting ProtocolHandler [“http-nio-9001”]
    • socket监控项目启动成功时间 = demo项目监控，用作跟项目启动时间的对比和 | 序号 | 注册时间 | 发起轮询时间 | 项目启动成功时间 | socket监控项目启动成功时间 | 是否注册成功 | | —- | —- | —- | —- | —- | —- | | 1 | 2021-02-20 13:06:43 | 2021-02-20 13:06:51 | 2021-02-20 13:06:46 | 2021-02-20 13:06:46.038 | true | | 2 | 2021-02-20 13:28:17 | 2021-02-20 13:28:23 | 2021-02-20 13:28:20 | 2021-02-20 13:28:20.530 | true | | 3 | 2021-02-20 13:32:43 | 2021-02-20 13:32:54 | 2021-02-20 13:32:46 | 2021-02-20 13:32:46.489 | true | | 4 | 2021-02-20 13:34:21 | 2021-02-20 13:34:24 | 2021-02-20 13:34:24 | 遗漏 | false | | 5 | 2021-02-20 13:35:40 | 2021-02-20 13:35:44 | 2021-02-20 13:35:43 | 2021-02-20 13:35:43.936 | false | | 6 | 2021-02-20 13:37:59 | 2021-02-20 13:38:04 | 2021-02-20 13:38:02 | 2021-02-20 13:38:02.802 | true | | 7 | 2021-02-20 13:41:41 | 2021-02-20 13:41:45 | 2021-02-20 13:41:44 | 2021-02-20 13:41:44.301 | false | | 8 | 2021-02-20 13:43:29 | 2021-02-20 13:43:32 | 2021-02-20 13:43:32 | 2021-02-20 13:43:32.526 | true | | 9 | 2021-02-20 13:44:59 | 2021-02-20 13:45:05 | 2021-02-20 13:45:02 | 2021-02-20 13:45:02.745 | true | | 10 | 2021-02-20 13:46:35 | 2021-02-20 13:46:32 | 2021-02-20 13:46:35 | 2021-02-20 13:46:35.623 | false |

  • 数据说话

    • 成功率：6/10 , 失败率：4/10
    • 根据轮询时间跟启动时间得出异常下线的原因如下
      • 轮询时间刚刚好在启动成功0-1秒 （由于没有毫秒对比所以是近似值且小于1s）
      • 轮询的时间早于启动成功的时间 | 发起轮询时间 | 项目启动成功时间 | 相差时间/s | 是否注册成功 | | —- | —- | —- | —- | | 13:06:51 | 13:06:46 | 5.00 | true | | 13:28:23 | 13:28:20 | 3.00 | true | | 13:32:54 | 13:32:46 | 8.00 | true | | 13:34:24 | 13:34:24 | 0.00 | false | | 13:35:44 | 13:35:43 | 1.00 | false | | 13:38:04 | 13:38:02 | 2.00 | true | | 13:41:45 | 13:41:44 | 1.00 | false | | 13:43:32 | 13:43:32 | 0.00 | true | | 13:45:05 | 13:45:02 | 3.00 | true | | 13:46:32 | 13:46:35 | -3.00 | false |

猜想

  • 可能是由于ContextRegisterListener注册时跟轮询重合了，或者轮询出现延迟导致下线通知在注册之后才发送，导致被异常下线

    尝试修改

    1. 尝试注册后延迟写进缓存，既

      1. // publish change event.
      2. Thread.sleep(2000);
      3. upstreamCheckService.submit(contextPath, addDivideUpstream);
      • 据测试 submit 方法不是异步执行，所以问题并未得到解决
    1. debug看看 ContextRegisterListener
      • Spring 中的事件监听的实现
        • ContextClosedEvent（容器关闭时）
        • ContextRefreshedEvent（容器刷新时）
        • ContextStartedEvent（容器启动时）
        • ContextStoppedEvent（容器停止时）
      • 将ContextRegisterListener 的实现从 ApplicationListener 改成了 ApplicationRunner
        • 每次注册都在启动彻底完成之后了，好像暂时解决上述的异常下线（测试10次）

最终解决

  • 将ContextRegisterListener 的实现从 ApplicationListener 改成了 ApplicationRunner 保证注册每次都在项目启动后执行
    • 每次注册都在启动彻底完成之后了，此后无异常。
  • 参考：https://jishuin.proginn.com/p/763bfbd23539

    关于PR