在几乎所有部分都准备好了之后(除了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主体的工作机制已经完成,剩余的都能理解了,等后面遇到了之后,再回来补充