Skynet源码之:日志打印(13)

JavenLaw

在几乎所有部分都准备好了之后(除了skynet_socket.c),只剩下一个部分还没有分析,就是日志打印部分

原先计划是写在《Skynet源码之:service_logger》的,但是后来发现写在一起太勉强了

并且Skynet有独立的skynet_log.c文件,另外skynet的debug_console控制台的也用到了日志打印部分

因此有了这篇独立的日志打印部分


日志打印从哪里开始

日志打印不像之前的部分,有个明显的入口函数,它更像是一堆函数,等待着别的部分来调用

因此我先从Skynet的一个配置字段 logpath = “.” 讲起

原文:cloudwu/skynet · Discussions · GitHub

问题:请问开启daemon后,日志写到哪里了

第一:配置为 “./log” ,你需要在 skynet 项目下先建立一个名为 log 的文件夹

第二:执行 nc 127.0.0.1 8000 进入 skynet 后台控制 debug console,执行list,显示所有服务的地址

第三:输入:logon 服务地址,例如:logon 8

第四:在 skynet/log/00000008.log 文件,就是这个服务的打印日志(main服务的地址是00000008)

第五:建议 example/main.lua 后面增加:

local function my_timeout()
	print("timer=======", skynet.now())
	skynet.timeout(200, my_timeout)
end

my_timeout()

-- skynet.exit()  -- main服务不要退出

最后执行 tail -f 00000008.log 就可以查看到 main 服务的日志输出

第六:输入:logoff 服务地址,例如:logoff 8,关闭日志输出


logon命令

skynet在收到debug_console中logon命令的时候,会调用

​ core.command(“LOGON”, skynet.address(address))

从而进入到lua-c层面的函数调用,如下

​ lua_skynet.c文件中的 lcommand() 函数

最后进入c层的函数,如下

​ skynet_server.c文件中的 cmd_logon(address) 函数

最终调用

​ skynet_log.c文件中的 skynet_log_open(address) 函数

原型如下

FILE * 
skynet_log_open(struct skynet_context * ctx, uint32_t handle) {
	const char * logpath = skynet_getenv("logpath"); // 这里就会使用 配置字段 logpath = "." 
	if (logpath == NULL)
		return NULL;
	size_t sz = strlen(logpath);
	char tmp[sz + 16];
	sprintf(tmp, "%s/%08x.log", logpath, handle);
	FILE *f = fopen(tmp, "ab"); // 打开一个日志文件
	if (f) {
		uint32_t starttime = skynet_starttime();
		uint64_t currenttime = skynet_now();
		time_t ti = starttime + currenttime/100;
		skynet_error(ctx, "Open log file %s", tmp); // 给 service_logger 服务发个消息,内容是 open log 
		fprintf(f, "open time: %u %s", (uint32_t)currenttime, ctime(&ti));
		fflush(f); // 正式把刚才的 open time 这条日志输入到新文件
	} else {
		skynet_error(ctx, "Open log file %s fail", tmp);
	}
	return f;
}


与service_logger的关系

在《Skynet源码之:service_logger》中知道,如果开启了日志输出和守护进程,需要配置config中的logger和daemon字段

service_logger服务就会把日志输出到指定的日志文件中

那这里的logon又和service_logger有什么关联呢?

我们可以回顾一下《Skynet源码之:服务实现》中,服务结构体中有一个字段:logfile

这就是用来标记服务的日志输出的

那它最终是如何生效的呢?请接着看下面


与skynet_error的关联

这一切的源头还是得从skynet.error() 的调用说起

在lua层

skynet.error = c.error -- 即调用c层的error函数

在c层

static int
lerror(lua_State *L) {
	struct skynet_context * context = lua_touserdata(L, lua_upvalueindex(1));
	int n = lua_gettop(L);
	if (n <= 1) {
		lua_settop(L, 1);
		const char * s = luaL_tolstring(L, 1, NULL);
		skynet_error(context, "%s", s);
		return 0;
	}
	luaL_Buffer b;
	luaL_buffinit(L, &b);
	int i;
	for (i=1; i<=n; i++) {
		luaL_tolstring(L, i, NULL);
		luaL_addvalue(&b);
		if (i<n) {
			luaL_addchar(&b, ' ');
		}
	}
	luaL_pushresult(&b);
    
    // 最终调用c层的skynet_error()函数
    // 在skynet_error.c文件中定义
	skynet_error(context, "%s", lua_tostring(L, -1)); 
	return 0;
}

看看skynet_error()函数的实现

void 
skynet_error(struct skynet_context * context, const char *msg, ...) {
	static uint32_t logger = 0;
	if (logger == 0) {
		logger = skynet_handle_findname("logger");
	}
	if (logger == 0) {
		return;
	}
    
    // 代码省略
    
    struct skynet_message smsg;
    if (context == NULL) {
        smsg.source = 0;
    } else {
        smsg.source = skynet_context_handle(context);
    }
    smsg.session = 0;
    smsg.data = data;
    smsg.sz = len | ((size_t)PTYPE_TEXT << MESSAGE_TYPE_SHIFT);
    skynet_context_push(logger, &smsg); // skynet.error()最终的本质就是给service_logger发个消息
}

流程总结:

skynet.error()(lua层)—> lerror()(c层,lua-c的交互以及命令分发)—> skynet_error()(c层,命令的具体实现)—> service_log()(log服务)


与service_logger服务的关系

可以看到,最终所有的打印都是由log服务处理的

但我们之前不是把日志输出到指定的日志文件了吗?

例如:

// service_logger.c文件
static int
logger_cb(struct skynet_context * context, void *ud, int type, int session, uint32_t source, const void * msg, size_t sz) {
	struct logger * inst = ud;
	switch (type) {
	case PTYPE_SYSTEM:
		if (inst->filename) {
			inst->handle = freopen(inst->filename, "a", inst->handle);
		}
		break;
	case PTYPE_TEXT:
        // ******************************************************日志输出在此打印
		if (inst->filename) {
			char tmp[SIZETIMEFMT];
			int csec = timestring(ud, tmp);
			fprintf(inst->handle, "%s.%02d ", tmp, csec);
		}
		fprintf(inst->handle, "[:%08x] ", source);
		fwrite(msg, sz , 1, inst->handle);
		fprintf(inst->handle, "\n");
		fflush(inst->handle);
		break;
        // ******************************************************日志输出在此打印
	}

	return 0;
}

那logon又是如何把日志转换到新文件当中的呢?

答案就是这个logon的日志输出本身并不跟service_logger有任何关系

logon打印的是,发给某个不定服务的消息的打印,例如logon address,就是打印address服务的消息队列

service_logger打印的是,某个服务通过skynet.error()的一系列调用,发给service_logger()的一个skynet内部消息


skynet_log_output()函数

刚才logon命令和skynet_log_open()函数并没有真正做什么事

只不过是打开了一个日志文件,准备接受日志的打印而已

真正干活的是skynet_log_output()函数

因此我们只需要知道哪里调用了此函数,就可以日志是由谁打印的

调用地方如下:

// 在skynet_server.c文件中
static void
dispatch_message(struct skynet_context *ctx, struct skynet_message *msg) {
	
    // 代码省略
    
    // 其中ctx->logfile是在服务创建时候初始化的
    // 详细请看《Skynet源码之:服务实现》
	FILE *f = (FILE *)ATOM_LOAD(&ctx->logfile); // 假如服务有标记logfile字段
	if (f) {
		skynet_log_output(f, msg->source, type, msg->session, msg->data, sz);
	}
}
// 对于ATOM_LOAD()的作用,请看《Skynet专题之:原子操作》

可以看到,在每个服务处理消息的地方dispatch_message(),会判断一下这个服务是否带有logfile

如果带有logfile,则需要打印


logfile的原子性

有个特别需要注意的地方是,在debug_console获取logon命令的时候

logon命令

// skynet_server.c文件
static const char *
cmd_logon(struct skynet_context * context, const char * param) {
	printf("%s\n", param);
	uint32_t handle = tohandle(context, param);
	if (handle == 0)
		return NULL;
	struct skynet_context * ctx = skynet_handle_grab(handle);
	if (ctx == NULL)
		return NULL;
	FILE *f = NULL;
	FILE * lastf = (FILE *)ATOM_LOAD(&ctx->logfile);// 注意这行代码
	if (lastf == NULL) {
		f = skynet_log_open(context, handle);
		if (f) {
			if (!ATOM_CAS_POINTER(&ctx->logfile, 0, (uintptr_t)f)) {
				// logfile opens in other thread, close this one.
				fclose(f);
			}
		}
	}
	skynet_context_release(ctx);
	return NULL;
}

logoff命令

static const char *
cmd_logoff(struct skynet_context * context, const char * param) {
	uint32_t handle = tohandle(context, param);
	if (handle == 0)
		return NULL;
	struct skynet_context * ctx = skynet_handle_grab(handle);
	if (ctx == NULL)
		return NULL;
	FILE * f = (FILE *)ATOM_LOAD(&ctx->logfile);
	if (f) {
		// logfile may close in other thread
		if (ATOM_CAS_POINTER(&ctx->logfile, (uintptr_t)f, (uintptr_t)NULL)) { // 注意这行代码
			skynet_log_close(context, f, handle);
		}
	}
	skynet_context_release(ctx);
	return NULL;
}

实质上,有3处地方使用了ATOM_CAS_POINTER,详细见《Skynet专题之:原子操作》的内容

第一:《Skynet源码之:服务实现》中的 ATOM_POINTER logfile 初始化

第二:上面 cmd_logon() 函数中的对比赋值,由此开启日志打印

第三:上面 cmd_logoff() 函数中的对别赋值,游戏关闭日志打印

现在有一个问题:

debug_console是一个服务,通过logon命令给debug_console发送消息,命令应该是能保证顺序,也就是说

skynet应该保证debug_console的线程安全性,为什么还要加上ATOM_CAS_POINTER的原子操作呢?

答案就是debug_console虽然是个服务,但是logon&logoff命令并不是通过skyney内部的消息来实现的

在debug_console.lua文件中,服务开了一个socket监听,通过http来接受命令

我们也是通过nc 127.0.0.1 8000命令来连接控制台的

-- debug_console.lua文件
skynet.start(function()
	local listen_socket, ip, port = socket.listen (ip, port)
	skynet.error("Start debug console at " .. ip .. ":" .. port)
	socket.start(listen_socket , function(id, addr)
		local function print(...)
			local t = { ... }
			for k,v in ipairs(t) do
				t[k] = tostring(v)
			end
			socket.write(id, table.concat(t,"\t"))
			socket.write(id, "\n")
		end
		socket.start(id)
		skynet.fork(console_main_loop, id , print, addr) -- 新建了一个新协程来执行命令
	end)
end)

-- debug_console控制台更详细的内容,以后会写道《Skynet使用之:console控制台》
-- 这里不再叙述

这也就是说,假如开了2个console控制台,发送了相同的命令,skynet会fork协程出来执行

而在console_main_loop函数中,有些调用例如 httpd.read_request(sockethelper.readfunc(stdin, cmdline.. “\n”), 8192) 可能会阻塞

那么此时就没办法保证命令的执行顺序

因此我们需要ATOM_CAS_POINTER来判断一下

在代码注释中也写明:

// logfile opens in other thread, close this one.

// logfile may close in other thread


日志打印的是什么

其实根据刚才的函数就能知道

void 
skynet_log_output(FILE *f, uint32_t source, int type, int session, void * buffer, size_t sz) {
	if (type == PTYPE_SOCKET) {
		log_socket(f, buffer, sz);
	} else {
		uint32_t ti = (uint32_t)skynet_now();
		fprintf(f, ":%08x %d %d %u ", source, type, session, ti);
		log_blob(f, buffer, sz);
		fprintf(f,"\n");
		fflush(f);
	}
}

source就是发消息过来的服务handle

type就是消息类型

session就是本服务的消息session

ti就是时间

特别注意

如果你是采用 skynet.timeout() 的形式来给测试的服务发消息,你得到的将会是这样的内容

:00000000 1 49 9461

:00000000:表示的是系统服务,因为是定时器,所有值为0

1:为消息类型,1为回复消息。消息类型可见skynet.h

49:为本服务的session_id,是会自增的

9461:为此时的时间点,单位为skynet_now()返回的时间

重点在于:此时日志没有打印消息携带的参数,看起来很单调

这是因为消息是定时器触发的,因此没有携带数据

所以 buffer 和 sz 是空的,也就打不出任何日志了


剩余的内容

至于剩余的log_blob()函数,显而易见,就是打印消息的数据而已

还有log_socket()函数,就不先不说了

因为skynet_log主体的工作机制已经完成,剩余的都能理解了,等后面遇到了之后,再回来补充