今天吃了一个线上的bug,问题还比较严重,这里记录一下。

    我们的程序其中有一个定时操作,每天在某一时刻只执行一次操作,这个时间必须是准确的,因为要在这一时刻获取外部数据,或者向外部系统发送请求。假设这个时间是在9:24:59,代码的逻辑是这样的:

private readonly TimeSpan beginProcessTime = new TimeSpan(09, 24, 59);
private ManualResetEvent stopME;

public Start()
{
    stopME = new ManualResetEvent(false);
    Thread processThread = new Thread(ProcessLastAuction) { IsBackground = true };
    processThread.Start();
}

private void ProcessLastAuction()
{
    while (true)
    {
        if (beginProcessTime > DateTime.Now.TimeOfDay)
        {
            if (stopME.WaitOne(beginProcessTime - DateTime.Now.TimeOfDay))
            {
                return;
            }
            try
            {
                DoSomething();
            }
            catch (ThreadAbortException)
            {

            }
            catch (Exception e)
            {
                LogError(e);
            }
        }
        else
        {
            break;
        }
    }
}

    调用Start()方法之后,启动了一个线程,在这个线程里面,会比较待处理的时间beginProcessTime跟当前计算机系统时间的差,如果时间还没到,则使用ManualResetEvent.WaitOne来等待,一直等到时间到达,或者主动在其它地方将这个ManualResetEvent进行Reset。当时间到达之后,他会返回false,接着进入到try语句里面执行DoSomething逻辑。

     在正常情况下,DoSomething()这个方法只会执行一次,因为当执行完成之后,两个if条件都不满足,运行DoSomething肯定会需要时间,这样,当前时间肯定已经超过了beginProcessTime,第一个if条件不满足。

     第二个条件也不会满足,因为此时WaitOne里面的TimeSpan会是负数,他会一直阻塞或直接抛出异常,不会执行。因为WaitOne的参数,必须是大于等于0或者-1,如果是-1则永远阻塞,如果是负数且不为-1,则会直接抛出异常。

     紧接着,骚操作来了。

骚操作


     由于我们没有时间发生器等硬件设备,所以定时操作的时间是获取的计算机的本机时间,而这个时间如果不经常跟外面的网络时间进行校准,他会存在滞后或超前。为了保证程序运行的定时操作跟外面系统时间尽量一致,我会每天在程序运行之前,对计算机系统时间进行网络校准(虽然这个可以设置自动同步,通过修改注册表就可以,具体方法自行搜索,这里不描述了),然后再运行程序。

    但是今天,这个顺序我搞反了,先是运行了程序,然后再校准了计算机时间,这样悲剧就发生了。

    在计算机时间没有校准之前,他的本地时间经过一个国庆长假的关机,发生了超前,大概就是比网络时间超前了大概200毫秒,那么程序在启动的时候,他会少等待200毫秒,也就是它会在真实时间的9:24:58.800的时候就运行(程序运行的那一刻,系统时间超前200毫秒,他认为他到了9:24:59)。 

    在程序运行了之后,我校准了计算机时间,此时这200毫秒的滞后就没有了,时间正常了,此时悲剧就发生了。

    在9:24:58.800时刻,WaitOne放行,逻辑继续,进入到了try语句,执行了DoSomething(),这个操作很快,时间可以忽略不计。紧接着,循环又到了if判断语句,这个时候,获取到的真实的DateTime.Now,还没有到9:24:59秒,所以再次进入到了WaitOne,在等待了大概200毫秒之后,又一次执行了DoSomething()操作(这个操作只会多执行一次,不管校准前计算机时间超前多久)。

    这个bug,产生了巨大的问题,但通过后续的一顿手忙脚乱的手动操作,幸好没有造成太大的损失,不然就要删库跑路了。

解决问题


    如果不在程序运行之后,去调整计算机时间且计算机时间在调整前是滞后的,而不是超前的,这个bug就不会触发,程序就会一直愉快的执行下去。但是代码有问题就是有问题,解决方法也很简单,那就是在DoSomething()执行完成之后,加一个return,直接跳出循环,这样就能保证只执行一次,不管外部变量是否发生变化。

     update:今天仔细又看了一遍代码,发现外面这个while循环是有问题的,竟然每天只执行一次,为什么还要放在while循环里面,所以果断把外侧的这个while循环删掉了,上面的return也不需要了,代码修改后如下,更简洁简单了:

private void ProcessLastAuction()
{
     if (beginProcessTime > DateTime.Now.TimeOfDay)
     {
          if (stopME.WaitOne(beginProcessTime - DateTime.Now.TimeOfDay))
           {
               return;
           }
           try
           {
               DoSomething();
           }
           catch (ThreadAbortException)
           {

           }
           catch (Exception e)
           {
              LogError(e);
           }
        }
        else
        {
            break;
        }
    }
}

    这就给我们提了一个醒,那就是程序如果需要依赖外部变量,比如计算机系统时间,那么这个时间就有可能不准确,或者被人为修改。我想一些破解软件有一种方法会不会就是通过修改系统时间来骗过系统的校验呢 。

    总而言之,还是自己写的代码不够严谨,对于一些关键逻辑,比如这里的只能运行一次,没有严格保证,没有考虑到对外部时间的依赖这个变量,需要反思一下。