一个不太容易定位的简单bug

总结一下最近线上测试出现的已知问题，因为当时解决这些问题真的很曲折的，有时候因为某一项配置问题，就需要花一点时间去查，之前的工作总结中也记录相关的经历，虽然平时写代码测试的没问题，可是到了线上，总会出一些小问题，或跟配置有关，或跟临界状态有关等。

今天记录一个很简单的bug，不算是bug，是没写日志文件问题，会影响到排查问题等。日志模块我之前重构过，在本地测试的没问题，后来另外的同事添加了热更新功能，本地测试很多次了，没问题，也写日志。后来昨天把代码更新到线上后，发现不写日志了，lsof看了进程，没有打开文件，然后日志文件确实创建了，而且也在info文件中写了start up信息，仅四行，其他的debug/warn/error包括跟业务相关的info都不写了，然后每小时滚动日志功能也失效了，此时是在临时下班时才发现的，当时已经十点多了，而且自己正好下楼回家，后来又回去排查。

我先用同一套分支代码，跟线上代码一致，仅配置不同，然后在本地测试了几次没问题，正常写日志文件，然后让同事在线上环境起同一套代码，仅配置不同，没出现问题。一开始以为是初始化失败(这里不应该会，因为lua层用了assert，有问题肯定是打印堆栈信息，但是并没有)，但是我添加了打印信息，确实创建了文件和初始化成功，这一步是没问题的。后来才发现开发环境下的配置是program，线上的product，然后对比下两个配置文件，并没有影响到log的因素，然后把配置调整到了product后，发现不打日志了，开始慢慢定位为什么。

此时再次怀疑，是不是在其他服务发log消息到日志服务过程中，被过滤了？我在发日志消息和接收那边加了打印，接收那边没收到，那很可能是发送问题。但是，为什么program模式下没问题，而product下就有问题，且没有字段会决定发不发日志消息，不大可能会出现这种问题，却偏偏出现了。

带着这个问题，开始查下源码，发日志时用的是skynet.error接口，然后定位到lerror接口，部分代码如下：

 13 void 
 14 skynet_error(struct skynet_context * context, const char *msg, ...) {
 15     static uint32_t logger = 0;
 16     if (logger == 0) {
 17         logger = skynet_handle_findname("logger");
 18     }   
 19     if (logger == 0) {
 20         return;
 21     }
        //more code
 54     struct skynet_message smsg;
 55     if (context == NULL) {
 56         smsg.source = 0;
 57     } else {
 58         smsg.source = skynet_context_handle(context);
 59     }
 60     smsg.session = 0;
 61     smsg.data = data;
 62     smsg.sz = len | ((size_t)PTYPE_TEXT << MESSAGE_TYPE_SHIFT);
 63     skynet_context_push(logger, &smsg);
 64 }

229 int     
230 skynet_context_push(uint32_t handle, struct skynet_message *message) {
231     struct skynet_context * ctx = skynet_handle_grab(handle);
232     if (ctx == NULL) {
233         return -1;
234     }   
235     skynet_mq_push(ctx->queue, message);
236     skynet_context_release(ctx);
237 
238     return 0;
239 }

从lua层push一条消息到logger服务的消息队列，此时会找到logger服务的handle，为1，但push到消息队列时却获取不到ctx，导致不会把消息压入到队列中，问题就出现在这里，为什么会有这现象？

我在register和retire接口中，和skynet_error中可能会返回null和-1的地方，打印了相应的信息，发现在注册的时候，handle为1，然后init时报错了(lua层的)，但并没有在控制台打印，这点比较奇怪，况且在product模式下出现的 ，然后进行了retire操作，部分代码如下：

125 struct skynet_context *
126 skynet_context_new(const char * name, const char *param) {
132     void *inst = skynet_module_instance_create(mod);
133     if (inst == NULL)
134         return NULL;
135     struct skynet_context * ctx = skynet_malloc(sizeof(*ctx));
136     CHECKCALLING_INIT(ctx)
154     ctx->handle = 0;
155     ctx->handle = skynet_handle_register(ctx);
156     struct message_queue * queue = ctx->queue = skynet_mq_create(ctx->handle);
157     // init function maybe use ctx->handle, so it must init at last
158     context_inc();
159 
160     CHECKCALLING_BEGIN(ctx)
161     int r = skynet_module_instance_init(mod, inst, ctx, param);
162     CHECKCALLING_END(ctx)
163     if (r == 0) {
172         //code...
173     } else {
174         skynet_error(ctx, "FAILED launch %s", name);
175         uint32_t handle = ctx->handle;
176         skynet_context_release(ctx);
177         skynet_handle_retire(handle);
178         struct drop_t d = { handle };
179         skynet_mq_release(queue, drop_message, &d);
180         return NULL;
181     }
182 }

这里出错后，又调用了skynet_error，虽然有个static变量，找到handle后，但写不了该错误日志，所以反馈到上层，查不了，然后被retire掉，后续的lua日志一直是handle为1，只初始化了一次，但每次的ctx为null。

为什么初始化会失败的？这个问题也比较奇怪，c层初始化服务的时候，调用lua层的start接口，此时并没有用xpcall或者pcall这种保护模式，虽然报错，但没有打印出来，后来定位到是热更新，具体在gsub时的nil串，这里没有加判断。

大致过程是c层启动logger服务，创建logger服务时，加载logger的lua文件，此时进行start，start中创建日志文件信息，然后初始化，也没问题，这一步打开了文件，写了四行info日志，然后调用了热更新功能，这时报错了，但没打印出错信息，不知道是不是skynet代码问题，然后控制权回到c层后，处理了异常错误，lua虚拟机创建失败，包括后续的关闭文件等操作(lsof 看不到进程打开的日志文件)，并且后续业务写日志失败。

然后还有几个比较奇怪的问题是，既然代码一样，为什么在program下没问题，在product下有问题，即热更新出错不打栈错误信息，难道跟时序有关系？这个还要回去分析下具体原因。第二个问题既然在lua层的start出错了，为什么没有报错，却是通过在c层自行添加了几行debug信息，进而在lua层报了热更新的相关错误栈信息？这个特别奇怪。

然后我把热更新功能给注释了，一方面日志模块不需要此功能，另一方面注释后确实也解决了问题。报错出在热更新功能中(对一个nil字符串调用string.gsub，而这个nil字符串是通过call 查询一个服务名字出现的)。虽然问题暂时解决了，但并不完美，还有一些疑问等着去分析。