java - JSch - wait() 在 Channel.sendChannelOpen 调用期间无效

Question

我们最近开始在客户端站点出现零星问题，JSch 在成功运行多年后，在调用 sendChannelOpen 期间开始报告“ channel 未打开”。在深入研究代码并看到两个选项(超时与失败消息)之后，我们很可能遇到了失败。

由于消息是一样的，所以我下载了源码并添加了一些输出语句来验证。经过几次测试后，我惊讶地发现我们实际上达到了超时部分，但速度太快以至于在检查代码和考虑 wait() 语句时没有意义。

为了进一步排除故障，我将一个快速的独立应用放在一起进行测试，使用以下方法作为核心调用:

    public static void testConnectionJCraft(String host, String user, String password, int port, int timeout) throws Exception {
    JSch jsch = new JSch();
    Session session = jsch.getSession(user, host, port);
    try {
        session.setPassword(password);
        session.setConfig("StrictHostKeyChecking", "no");
        session.connect();

        if (session.isConnected()) {
            System.out.println("JCraft Connected sucessfully to server : " + host);
        } else {
            throw new Exception("JCraft Connection Failed: " + host);
        }                       
        Channel channel = session.openChannel("sftp");
        try {
            if (timeout > 0) {
                channel.connect(timeout);
            } else {
                channel.connect();
            }
        } finally {
            channel.disconnect();
        }

    } finally {
        if (session != null) {
            session.disconnect();
        }
    }
}

注意 - 我知道 if (timeout > 0) 是无关紧要的，我可以调用 channel.connect(timeout) 并在超时 == 0 时得到相同的结果，但我想确保调用被模仿为了以防万一，我正在对应用内的调用进行故障排除。

然后我在 com.jcraft.jsch.Channel 的 sendChannelOpen 方法中添加了一些额外的语句:

  protected void sendChannelOpen() throws Exception {
    Session _session=getSession();
    if(!_session.isConnected()){
      throw new JSchException("session is down");
    }

    Packet packet = genChannelOpenPacket();
    _session.write(packet);

    int retry=2000;
    long start=System.currentTimeMillis();
    long timeout=connectTimeout;
    long iteration = 0;
    if(timeout!=0L) retry = 1;
    System.out.println("Timeout: " + timeout);

    long t = timeout== 0L ? 10L : timeout;
    System.out.println("t: " + t);

    synchronized(this){
      while(this.getRecipient()==-1 &&
            _session.isConnected() &&
             retry>0){
        if(timeout>0L){
          long dur = (System.currentTimeMillis()-start);
          if(dur>timeout){
            System.out.println("Dur: " + dur + " > " + timeout);
            retry=0;
            continue;
          }
        }

        try{
          this.notifyme=1;
          wait(t);
        }
        catch(java.lang.InterruptedException e){
            System.out.println("Interrupted?");
        }
        finally{
          this.notifyme=0;
        }
        retry--;
        iteration++;
      }
    }

    long end = System.currentTimeMillis();
    System.out.println("Channel open duration: " + (end - start) + "ms");
    System.out.println("Channel open iterations: " + iteration);
    if(!_session.isConnected()){
      throw new JSchException("session is down");
    }
    if(this.getRecipient()==-1){  // timeout
      throw new JSchException("channel is not opened.");
    }
    if(this.open_confirmation==false){  // SSH_MSG_CHANNEL_OPEN_FAILURE
      throw new JSchException("channel unable to be opened, SSH_MSG_CHANNEL_OPEN_FAILURE received.");
    }
    connected=true;
  }

我确实向上移动了 t 的定义，只是为了避免垃圾邮件的值(value)。报告“ channel 未打开”消息的尝试结果表明上面的 wait(t) 语句似乎没有遵守超时。输出示例(服务器名称 x'd out):

JCraft Connected sucessfully to server : xxx.xxxx.xxx
Timeout: 0
t: 10
Channel open duration: 8ms
Channel open iterations: 2000
ERROR: channel is not opened.
com.jcraft.jsch.JSchException: channel is not opened.
        at com.jcraft.jsch.Channel.sendChannelOpen(Channel.java:783)
        at com.jcraft.jsch.Channel.connect(Channel.java:153)
        at com.jcraft.jsch.Channel.connect(Channel.java:147)
        at com.gorman.tools.FTPTestUtility.testConnectionJCraft(FTPTestUtility.java:46)
        at com.gorman.tools.FTPTestUtility.main(FTPTestUtility.java:21)

因此在这种情况下，请求在总共 8 毫秒内完成了所有 2000 次迭代。有时尝试成功并且 wait() 似乎受到尊重:

JCraft Connected sucessfully to server : xxx.xxxx.xxx
Timeout: 0
t: 10
Notifying all for setRecipient
Channel open duration: 21ms
Channel open iterations: 3

这里我们有 3 次迭代，当我单独记录它们时，我得到了 10/11/0 的时间分配，这正是我所期望的。我确实在调用 notifyAll() 的区域中添加了语句，以确保无意的调用不会导致等待继续，但除了设置收件人 ID 之外没有调用 - 正如预期的那样。

奇怪的是，如果我向调用传递一个 >= 1200 毫秒的超时值，我就无法让它发生。我想知道这是否只是 wait() 异常的副产品，特别是 JavaDoc 中关于超时值的注释:

• 已经过去了指定的实时时间，或多或少。

正如我所说，我们已经运行了多年，默认调用 channel.connect() 到位，但我想知道是否有一些新的延迟让我们发现了这个问题。即使对 println 调用的杀伤力过大也会使速度减慢到足以持续连接，看起来 21ms 是我现在应该期望的，但在上周五之前一切正常，据我所知我们以前没有见过这个问题。

欢迎提出任何想法，此时我的解决方法似乎是 channel.connect(reasonableValue)。我只是想进一步了解这个案例并将它放在这里以防它帮助其他人避免拉扯他们的头发!

Answer 1

找到解决方案 这似乎是闰秒的牺牲品，显然需要重新启动我们的 CentOS 机器(正常运行时间 45 天)。 RHEL 盒子在其他客户端上运行良好，但这个 CentOS 盒子表现出上述行为。

我们已验证在 12 月 31 日之前存在适当的内核版本，并且 ntpdate 和 tzdata 版本高于建议的版本以解决闰秒问题。最近一次重启是 11 月 18 日，用于 Dirty Cow 补丁。

但是，许多补丁已在 12/18 自动应用(补丁级别 = BASIC)，包括 tzdata 更新 (tzdata-java-2016j-1.el7.noarch)。我们捕获了机会，走上了 MS 路线，今天重新启动了盒子。重新启动后，wait() 调用按预期运行，我们的问题已解决。