标签： acquire timeouted

WxJava是一个目前应用广泛的微信SDK工具开发包，本文记录一个WxJava获取微信AccessToken失败出现acquire timeouted的问题。

1. 故障现象

最近产线出现了一个严重的技术故障问题，用户无法登录长达1个多小时，通过查看日志发现和WxJava相关，在故障期间内，WxJava一直无法正常获取微信Access Token，报acquire timeouted的错误，见下图。

期间尝试重启两次，在19:20第一次重启应用后问题有所减弱，但是过了5分钟又重新大量发生，直到第二次重启应用后问题消失。

2. 问题定位

通过查看错误日志的堆栈信息，

java.lang.RuntimeException: acquire timeouted
    at cn.binarywang.wx.miniapp.config.impl.WxMaRedisConfigImpl$DistributedLock.lock(WxMaRedisConfigImpl.java:332)
    at cn.binarywang.wx.miniapp.api.impl.WxMaServiceImpl.getAccessToken(WxMaServiceImpl.java:110)
    at cn.binarywang.wx.miniapp.api.impl.WxMaServiceImpl.executeInternal(WxMaServiceImpl.java:249)
    at cn.binarywang.wx.miniapp.api.impl.WxMaServiceImpl.execute(WxMaServiceImpl.java:215)
    at cn.binarywang.wx.miniapp.api.impl.WxMaServiceImpl.get(WxMaServiceImpl.java:199)
    at cn.binarywang.wx.miniapp.api.impl.WxMaServiceImpl.jsCode2SessionInfo(WxMaServiceImpl.java:178)
    at cn.binarywang.wx.miniapp.api.impl.WxMaUserServiceImpl.getSessionInfo(WxMaUserServiceImpl.java:28)

可以看到和WxJava通过分布式锁获取token有关，产线用的WxJava代码版本是3.6.0，之前已经稳定运行了一年多。

下载相应版本WxJava代码，找到报错的代码行，

// 类文件 - cn.binarywang.wx.miniapp.api.impl.WxMaServiceImpl

public class WxMaServiceImpl implements WxMaService {

  public String getAccessToken(boolean forceRefresh) throws WxErrorException {
    if (!this.getWxMaConfig().isAccessTokenExpired() && !forceRefresh) {
      return this.getWxMaConfig().getAccessToken();
    }

    Lock lock = this.getWxMaConfig().getAccessTokenLock();
    lock.lock(); // <-- 问题发生代码行 WxMaServiceImpl.java:110
    try {
      String url = String.format(WxMaService.GET_ACCESS_TOKEN_URL, this.getWxMaConfig().getAppid(),
        this.getWxMaConfig().getSecret());
      try {
        HttpGet httpGet = new HttpGet(url);
        if (this.getRequestHttpProxy() != null) {
          RequestConfig config = RequestConfig.custom().setProxy(this.getRequestHttpProxy()).build();
          httpGet.setConfig(config);
        }
        try (CloseableHttpResponse response = getRequestHttpClient().execute(httpGet)) {
          String resultContent = new BasicResponseHandler().handleResponse(response);
          WxError error = WxError.fromJson(resultContent, WxType.MiniApp);
          if (error.getErrorCode() != 0) {
            throw new WxErrorException(error);
          }
          WxAccessToken accessToken = WxAccessToken.fromJson(resultContent);
          this.getWxMaConfig().updateAccessToken(accessToken.getAccessToken(), accessToken.getExpiresIn());

          return this.getWxMaConfig().getAccessToken();
        } finally {
          httpGet.releaseConnection();
        }
      } catch (IOException e) {
        throw new RuntimeException(e);
      }
    } finally {
      lock.unlock();
    }

  }
}

// 类文件 - cn.binarywang.wx.miniapp.config.impl.WxMaRedisConfigImpl$DistributedLock

public class WxMaRedisConfigImpl implements WxMaConfig {

  private class DistributedLock implements Lock {

    private JedisLock lock;

    private DistributedLock(String key) {
      this.lock = new JedisLock(getRedisKey(key));
    }

    @Override
    public void lock() {
      try (Jedis jedis = jedisPool.getResource()) {
        if (!lock.acquire(jedis)) {
          throw new RuntimeException("acquire timeouted"); // <-- 问题发生代码行 WxMaRedisConfigImpl.java:332
        }
      } catch (InterruptedException e) {
        throw new RuntimeException("lock failed", e);
      }
    }

    // ...
  }
}

上面的代码主要是通过redis分布式锁，使得只有一个进程中的一个线程执行token获取并存储到redis，梳理getAccessToken()方法的执行路径，可以发现其大概经历的步骤如下，

若仔细研读这个流程图，可以发现其中有很多相互抢占竞争资源的问题，其中有竞争的资源有3处，

1. DistributedLock.lock()：分布式锁，多个进程/线程抢占这个锁，只有获取到此锁的线程才能执行锁更新操作。
2. jedisPool.getResource()：单进程中多个线程竞争从连接池获取redis连接。
3. JedisLock.acquire()和JedisLock.release()：两个方法被synchronized修饰，这个是一个比较隐蔽的同步琐，被单进程中的多个线程所竞争抢占。