急求助maybe in an endless loop (version = 532435)

[ericzhanchina]

最近服务器随机出现了死循环的问题，但是阅读代码一直发现不了问题，而且对于服务的目标地址有些疑问，请求帮助。
[:00000072][DEBUG][18:02:16.36][msgagent.lua:568] >>[1014][pet_gene_random] userid = 1114616915952799744
[:0000001b][DEBUG][18:13:44.52][dbredis.lua:65] call pipeline of .mainredis.slave[3] from 114 cost 1 ms
[:00000000][DEBUG][18:13:44.52]A message from [ :0000001b ] to [ :00000001 ] maybe in an endless loop (version = 532435)
[:00000000][DEBUG][18:13:44.52]A message from [ :0000001b ] to [ :00000001 ] maybe in an endless loop (version = 532435)
[:00000000][DEBUG][18:13:44.53]A message from [ :0000001b ] to [ :00000001 ] maybe in an endless loop (version = 532435)
[:00000000][DEBUG][18:13:44.53]A message from [ :0000001b ] to [ :00000001 ] maybe in an endless loop (version = 532435)
[:00000000][DEBUG][18:13:44.53]A message from [ :0000001b ] to [ :00000001 ] maybe in an endless loop (version = 532435)
[:00000000][DEBUG][18:13:44.53]A message from [ :0000001b ] to [ :00000001 ] maybe in an endless loop (version = 532435)
[:00000000][DEBUG][18:13:44.53]A message from [ :0000001b ] to [ :00000001 ] maybe in an endless loop (version = 532435)
[:00000000][DEBUG][18:13:44.53]A message from [ :0000001b ] to [ :00000001 ] maybe in an endless loop (version = 532435)
[:00000000][DEBUG][18:13:44.53]A message from [ :0000001b ] to [ :00000001 ] maybe in an endless loop (version = 532435)

首先00000001这个服务是哪个呢，我到debug里面只有00000004开始的，0000001b是处理redis请求的一个服务，所有redis的处理都发给这个服务，这个服务有4个slave服务，dbredis会转发给子服务处理。看上去18:02的请求的请求，在18:13才处理完，但是从日志来看，说处理只花了1ms，但是日志差了11分钟去了。

请指点，谢谢。

[ericzhanchina]

看上去00000001是日志服务，使用lua写的一个logger，不断地将日志写到服务器文件系统，然后dbredis这个服务输出日志的时候卡住了，虽然redis的执行只花了1ms，但是这个日志调用返回的时候已经过了11分钟了。日志是一个单例的服务，debug_console里面，也没有看到mqlen有堆积，还是搞不清楚问题出在哪里。

                    -- msgagent always call the dbredis in the same connection
                    index = source % balance + 1
                    local t1 = util.millisecond()
                    local ret = skynet.call(slave[index], "lua", cmd, ...)
                    local t = { ... }
                    log.debug("redis parameter is %s",util.dump(t))
                    local t2 = util.millisecond()
                    log.info("call %s of %s.slave[%d] from %d cost %d ms", cmd, name, index, source, t2 - t1)
                    skynet.ret(skynet.pack(ret))

[terry8210]

通过在debug-console（用telnet连上）中输入signal :00000001（上述log的地址），可以强制结束lua死循环，并且可以根据堆栈找到死循环的地方。

[ericzhanchina]

今天一直没出现这种情况，我在想有没有可能这个logger并没有死循环，他现在是一个单例的，堆积了？但是看mqlen并没有。

[cloudwu]

mq 过长并不会输出这样的 log 。该 log 产生就是因为单条消息进去服务处理后，一直没有返回。而 mqlen 过长只会把进入的消息堆积在系统里，而并不会影响单条消息的处理时间。

既然是写日志，就不能排除 IO 阻塞过久的可能。

[ericzhanchina]

写日志的代码是调用的下面的代码
skynet.send(".logger", "lua", "logging", LOG_LEVEL_DESC[level], str)
直接send，不等返回，然后logger里面dispatch没有调用ret。 跟没有调用ret返回有关系吗？

logger服务收到之后会把这个消息写入到文件系统

function CMD.logging(source, type, str)
	local date = os.date("*t")
	str = string.format("[:%08x][%s][%s]%s", source, type, log_time(date), str)
	
	if not log_file or date.hour ~= last_hour then
		open_file(date)
	end

	log_file:write(str .. '\n')
	log_file:flush()
	
	if not is_daemon then
		print(str)
	end
end

skynet.start(function()
	skynet.register(".logger")
	
    skynet.dispatch("lua", function(_, source, cmd, ...)
		local f = assert(CMD[cmd], cmd .. " not found")
		f(source, ...)
	end)
end)

[253980289]

看你的代码结合前面你的日志，感觉好像是在输出你前面的第一条日志【[:00000072][DEBUG][18:02:16.36][msgagent.lua:568] >>[1014][pet_gene_random] userid = 1114616915952799744】执行到open_file时卡住了大概11分钟，后续才正常导致。

如果日志输出存在延时，我们的做法一般是在应用服那边就输入时间，这样输出时不会受日志服输出延迟影响日志发送的真实时间。

[sniper00]

是否使用了数组作为突击队列

[ericzhanchina]

应该没有，现在看就是dbredis服务里面发给logger记录日志的这里卡住了，不知道跟我logger里面没有调用ret有没有关系