日志写爆后引发的一个潜在Bug

这周遇到一个有点意思的bug，记录一下，以示效仿。由于是公司内网环境下的，所以只能用拙劣的文字来做个记录。

在开发的一个程序，因为在测试中，打开了debug日志，然后50M一个的日志文件大概10s就刷爆了。（插入一个题外话，关于大日志的问题，最近看了一篇文章：Linux下日志文件过大解决方案，有兴趣可以看一下）我司的日志系统大概是这样的写满足50M，就重命名为xxx_1.log，再写满50M，就有xxx_1.log及xxx_2.log，从而保证xxx.log是当前正在写入的日志文件。

对端是客户端，我负责的的服务端。抓包看，一堆：tcp zeroWindow，这是因为狂刷日志的原因（这个是我猜的），导致机器处理不过来。客户端的逻辑应该是遇到缓洪区满（长时间发不了数据）后就重新连接。bug在于新的连接进来后，服务端没有效应了。

要复现这个现象得打开debug日志，然后面对10秒就刷满50M的日志，其实日志也没有什么大的参考价值。尝试用pstack看各个线程是否还活着，发现接收数据的线程一直还在select，在线程中加日志可以看得线程还是活着的。gdb attach也可以进到正在跑的程序中。

最后周三晚上加班的时候，梳理了整个流程，分析关键日志，查看代码等找到了这个Bug的原因。因为每次的连接处理，服务端这边都有一组状态机（针对不同IP的连入）进行处理，比如0表示准备好了，可以连入，1表示已经连接成功，准备发送数据，2表示发送成功，准备收数据。每次处理完一个连接后会把状态值置为0，这样下一个连接就不受影响。但是因为缓冲区满的原因，在服务端这边还是处于数据处理过程（因为机器负荷满了，所以从缓冲区读数据慢），此时又有一个新的相同IP的连接进来，因为发现上一次的连接还在处理中，所以本次的连接没有进行处理。

//以下是伪代码 表示对于连接进行一个简单的判断
status[MAX_NUM_OF_CLIENT]  //每个客户端的ip对应一个状态表示
//开始的做法是
if(status[i] == INIT_CONNECT)
{
      //允许连入 并将状态改变
      status[i] = READY_SEND_MSG_TO_CLIENT;
      return true;
}

//修改后的做法
if(status[i] == INIT_CONNECT)
{
      //允许连入 并将状态改变
      status[i] = READY_SEND_MSG_TO_CLIENT;
      return true;
}
else
{
       return false; //拒绝连入
}

因为同一IP连进来的是相的SOCKETFD，所以上一次未处理完的数据也没有继续处理。解决方法也很简单，在新的连接连入的时候，如果状态机的值是0，就允许连入，如果非0就拒绝连入（closeSocket)，当客户端发现服务端拒绝连入的时候，就会一直重连，这个过程中，服务端有时间处理上一次未处理完的数据，再处理新的连入。

此问题暴露我写代码时还是没有考虑到异常情况，就是当已经在进行数据传输时，同一个IP的再次连入会导致异常（理论上，应该是上一次断链后，再发起新的连接），之前的测试，因为没有遇到缓冲区满了，客户端未断链就重连的情况所以也就没发现此问题。后来和客户端交流的时候，他们的开发信誓旦旦的表示他们一定是断开连接后再发起新的连接，但抓包好像没看到FIN包这是有点诡异了！

后面的工作就是梳理这些复杂的日志，分级，以及应该保留哪些日志等，又是一体力活= =