上周发布的一个系统,出现了一个很诡异的现象。抽象一下描述,问题大概是这样的:

  需求: 一次http请求,通过url的params来读取服务器上的一个日志,并将日志内容返回给用户。

  问题表现:存在一定的机率,一次请求返回的内容,与期望的内容不一致。也是所谓的串日志问题。

  这个问题出现后,我们都认为后台请求应该没有问题,因为我们是直接用的JDK自带的HttpServer来起的服务,心中对JDK还是有一些信任的。所以我们还是前端发送请求的时候发乱了,返回的结果和请求是能够匹配的。

  为了定位问题,我们在后台加了些日志,对比了每次请求和请求的返回内容。在1~2天的监控下,发现真的出现了请求和返回内容之间存在不一致的地方,而前端发送的请求没有错,问题直接定位到后台处理的问题。

  简单说来,大致类似这样:前端发送请求 http://127.0.0.1/getlog?id=123&path=testlog&type=r,期望是读取的是testlog文件,但是实际确是把devlog的内容返回给前端了。由于定位到这个现象,问题也可以定位到后台读文件拿参数是错的。

  我们怎么获取url中的参数呢,翻下源码,如下:

  Map Params = (Map) httpExchange.getAttribute(“parameters”);

  JDK上是这么定义这个方法的,getAttribute:

  Filter modules may store arbitrary objects with HttpExchange instances as an out-of-band communication mechanism. Other Filters or the exchange handler may then access these objects.

  并没有说他存在线程不安全,至于到底是不是这里出现的问题了,写了一个测试程序:

  1000并发,下发10000个请求,看看出现多少次这样的问题。结果很明显,统计下来,发现存在这种问题的数据接近1000条左右,这问题非常明显了。

  httpExchange.getAttribute()在一定并发的情况下,存在线程不安全的问题。

  public class HttpServersPerfTest extends BaseCase {

  private static final Log logger = LogFactory.getLog(AlisaNodeHttpServersPerfTest.class);

  int maxThread = 1000;

  private int totalTask = 1000;

  @Test

  public void testRequestRunningLog() throws InterruptedException {

  execute();

  }

  private void execute() throws InterruptedException {

  ExecutorService pool = Executors.newFixedThreadPool(maxThread);

  final CountDownLatch countDownLatch = new CountDownLatch(totalTask);

  for (int n = 0; n < totalTask; n++) {

  pool.execute(new RequestHttpServerThread(countDownLatch));

  }

  try {

  countDownLatch.await();

  System.err.println(“==============>>>>> 下发结束” );

  } catch (InterruptedException e) {

  e.printStackTrace();

  }

  }

  private class RequestHttpServerThread implements Runnable {

  private CountDownLatch countDownLatch;

  public RequestHttpServerThread(CountDownLatch countDownLatch) {

  this.countDownLatch = countDownLatch;

  }

  /**

  * 任务执行,这里实际上在服务器上准备好一堆文件,文件内容按行将文件名写入

  * 读取到内容可以和文件名进行比较

  */