总结一下最近线上测试出现的已知问题，因为当时解决这些问题真的很曲折的，有时候因为某一项配置问题，就需要花一点时间去查，之前的工作总结中也记录相关的经历，虽然平时写代码测试的没问题，可是到了线上，总会出一些小问题，或跟配置有关，或跟临界状态有关等。
今天记录一个很简单的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 查询一个服务名字出现的)。虽然问题暂时解决了，但并不完美，还有一些疑问等着去分析。
网友评论