Apple系统日志捕获方案

Posted by 开不了口的猫 on September 6, 2017

前言

之前公司有个项目,需要跟工联对接微信支付和清算,对接过程中遇到了一个大坑。因为iOS版本的微信SDK有支付参数timestamp的类型为UInt32,也就是只支持十位,而工联给的时间戳是十三位的,这就导致两边生成的token秘钥不一致,导致最终不能调起支付页面。而我们封装的统一支付组件输出的支付日志在真机上也无法查看,只能真机连接Mac去调试,这在一定程度上影响了对接效率。还有一些诸如此类的情景,需要我们在真机上查看系统日志。

本文只探讨捕获Apple系统日志的方案与原理。我实现的系统日志查阅器作为子工具组件已被集成到iOS真机桌面级调试工具中,可以直接clone或通过Cocoapods集成,欢迎Star🤓

Apple System Logger

我们可以通过官方文档了解到,oc中最常见的NSLog操作会同时将标准的Error输出到控制台和系统日志(syslog)中(c的printf系列函数并不会,swift的printf为了保证性能也只会在模拟器环境中输出)。其内部是使用Apple System Logger(简称ASL)去实现的,ASL是苹果自己实现的用于输出日志到系统日志库的一套API接口,有点类似于SQL操作。在iOS真机设备上,使用ASL记录的log被缓存在沙盒文件中,直到设备被重启。

那么我们如何通过ASL去获取到存放在系统日志中的系统日志呢?一开始我想的是创建一个定时器,然后定时地通过ASL接口去查询所有的日志,但是始终觉得这样定时获取日志的频率太快的话会影响性能,而太慢的话又不能达到如期的效果。无奈只能去查阅一些资料,最终在大名鼎鼎的CocoaLumberjack源码中找到了想要的答案。我们可以通过注册进程之间的系统通知来达到及时捕获系统日志,这个我会在下文中详细说明。接下来我讲一下大致的实现过程。

首先我们导入asl.h头文件,

#import <asl.h>

并且创建一个query对象用于条件查询日志库,

asl_object_t query = asl_new(ASL_TYPE_QUERY);

除了我们当前App进程产生的日志,在系统日志中肯定还存在别的进程不断生成的日志,不过这种行为只可能发生在多进程环境下(Xcode模拟器上),而iOS的真机设备并不存在这种情况。但为了兼容这两种使用情景,我们需要像下面这样通过当前进程的id来过滤掉其他进程产生的系统日志。

NSString *pidString = [NSString stringWithFormat:@"%d", [[NSProcessInfo processInfo] processIdentifier]];
asl_set_query(query, ASL_KEY_PID, [pidString UTF8String], ASL_QUERY_OP_EQUAL | ASL_QUERY_OP_NUMERIC);

然后为了提高查询的性能,我们借鉴了CocoaLumberjack的做法,希望系统只从上一次查询到的最后一条日志开始往后查询,所以我们需要创建一个变量来记录上一次捕获的最后一条日志的id。

__block unsigned long long lastSeenID  =  0;

重点来了。我们需要注册进程通知kNotifyASLDBUpdate,这是苹果在更新ASL数据库完成后会发出的跨进程的通知,这恰好符合我们实时更新的需求。我们需要额外导入<notify.h><notify_keys.h>这两个头文件。然后我们去注册这个通知,并且为了不影响主线程的事务和体验,我们必须在并发队列中异步执行这些查询事务,不过为了更及时地获取这些日志,我们可以将优先度调整为DISPATCH_QUEUE_PRIORITY_HIGH

int notifyToken = 0;
dispatch_queue_t highPriorityGlobalQueue = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_HIGH, 0);
notify_register_dispatch(kNotifyASLDBUpdate, &notifyToken, highPriorityGlobalQueue, ^(int token) {
    // 回调会自动传入注册时传递的通知token,我们将其保存下来,方便我们随时注销这个通知
    self.notifyToken = token;
   
    // 下面执行一系列query事务...
}

然后我们继续给query增加筛选条件,我们需要查询的是asl message id大于之前记录的lastSeenID的那些日志信息。

char queryContext[64];
snprintf(queryContext, sizeof queryContext, "%llu", lastSeenID);
asl_set_query(query, ASL_KEY_MSG_ID, queryContext, ASL_QUERY_OP_GREATER | ASL_QUERY_OP_NUMERIC);

query的筛选条件已经添加完了,我们就可以使用asl_search函数查询日志数据库了,值得一提的是,查询到的结果 — aslresponse并不直接携带日志信息,需要再通过asl_next函数将其遍历获取日志信息,直到asl_next函数取出的信息为NULL为止。

aslresponse response = asl_search(NULL, query);
aslmsg aslMessage = NULL;
                    
NSMutableArray *newLogs = [NSMutableArray array];
                    
while ((aslMessage = asl_next(response))) {                        
    const char *timeInterval = asl_get(aslMessage, ASL_KEY_TIME);
    const char *messageId = asl_get(aslMessage, ASL_KEY_MSG_ID);
    const char *message = asl_get(aslMessage, ASL_KEY_MSG);

    TDFSDLVLogModel *log = [[TDFSDLVLogModel alloc] init];
    // 这里可以给自定义模型赋值...
    [newLogs addObject:log];

    if (messageId) {
        lastSeenID = atoll(asl_get(aslMessage, ASL_KEY_MSG_ID));
    }
}

其中

lastSeenID = atoll(asl_get(aslMessage, ASL_KEY_MSG_ID));

是为了记录下查询到的最后一条日志信息的ID。

最后记得在获取完符合条件的日志之后,通过ASL自带的内存释放函数释放responsequery变量。

asl_release(response);
asl_free(query);

ASL在iOS10后被弃用

很不幸的是,苹果爸爸因为想减弱ASL对于日志方面的侵入性,在iOS10之后,将由os_log相关的API全面替代ASL。我们可以通过Logging API或者这里得知这一消息。因而我们不得不在iOS10之后寻找一种版本兼容的解决方案。

pipe、dup2与GCD的完美协作

首先我们来了解一下输出重定向的概念。
NSLog能输出到文件syslog中,靠的是文件IO的API的调用,那么在这些IO操作中,一定存在文件句柄。
在C语言中,存在默认的三个文件句柄。

#define stdin __stdinp

#define stdout __stdoutp

#define stderr __stderrp

其对应的三个iOS版本的文件句柄是

  #define STDIN_FILENO 0 /* standard input file descriptor */

  #define STDOUT_FILENO 1 /* standard output file descriptor */

  #define STDERR_FILENO 2 /* standard error file descriptor */

NSLog方法默认操纵的是STDERR_FILENO句柄。

我们可以通过C函数

FILE * freopen(const char * filename, const char * mode, FILE * stream);

进行重定向,其中filename为存放日志的路径,mode为读写模式,stream为文件句柄。

有一个问题跟随而来,那么我们如何将重定向还原呢?Unix的dupdup2函数恰逢其时。

int dup(int oldfd);
int dup2(int oldfd, int newfd);

dup函数可以为我们复制一个文件描述符,传给该函数一个既有的描述符,它就会返回一个新的描述符,这个新的描述符是传给它的描述符的拷贝。这意味着,这两个描述符共享同一个数据结构。
dup2函数跟dup函数相似,但dup2函数允许调用者规定一个有效描述符和目标描述符的id。dup2函数成功返回时,目标描述符(dup2函数的第二个参数)将变成源描述符(dup2函数的第一个参数)的复制品,换句话说,两个文件描述符现在都指向同一个文件,并且是函数第一个参数指向的文件。
那么我们可以利用dupdup2帮我们实现重定向的还原。

int originLogPath = dup(STDERR_FILENO);
dup2(originLogPath, STDERR_FILENO);

但是问题又来了,使用freopen函数并不能解决我们如何高效实时获取日志的问题。因为一旦通过freopen将stderr输出重定向到某一指定的文件后,我们需要手动在读取文件的同时检测变化,这将让我们的实现变得复杂,且一直对文件进行IO操作也极耗性能。无奈之下只能放弃freopen函数。

最后在这里找到了答案,pipe就是我们的答案。pipe是Linux管道编程中非常重要的一个函数,具体参见这里。因为pipe所实现的是存在于内存当中的读写机制,所以无论从实现还是性能都优于freopen的方案。

int fd = STDERR_FILENO;
int origianlFD = fd;
int originalStdHandle = dup(fd);

int fildes[2];
pipe(fildes);  
dup2(fildes[1], fd);
close(fildes[1]);
fd = fildes[0]; 

一开始通过dup函数保存了STDERR_FILENO的输出文件描述,然后将创建的fildes传入pipe函数,fildes[0]就是读末端,而fildes[1]就成了写末端。然后调用dup2函数将STDERR_FILENO的输出重定向到pipe管道流的写入端,即达到了将系统日志重定向到pipe的操作。接着将fd指向fildes[0]即pipe的读末端,然后配合GCD的source监听就可以达到我们的效果了,直接看完整代码。

if (self.source_t) {
    dispatch_cancel(self.source_t);
}

int fd = STDERR_FILENO;
int origianlFD = fd;
int originalStdHandle = dup(fd); // save the original for reset

int fildes[2];
pipe(fildes);  // [0] is read end of pipe while [1] is write end
dup2(fildes[1], fd);  // duplicate write end of pipe "onto" fd (this closes fd)
close(fildes[1]);  // close original write end of pipe
fd = fildes[0];  // we can now monitor the read end of the pipe

NSMutableData* receivedData = [[NSMutableData alloc] init];
fcntl(fd, F_SETFL, O_NONBLOCK);// set the reading of this file descriptor without delay

dispatch_queue_t highPriorityGlobalQueue = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_HIGH, 0);
dispatch_source_t source_t = dispatch_source_create(DISPATCH_SOURCE_TYPE_READ, fd, 0, highPriorityGlobalQueue);

int writeEnd = fildes[1];
dispatch_source_set_cancel_handler(source_t, ^{
    close(writeEnd);
    // reset the original file descriptor
    dup2(originalStdHandle, origianlFD);
});

dispatch_source_set_event_handler(source_t, ^{
    @autoreleasepool {
        char buffer[[[TDFSDPersistenceSetting sharedInstance] limitSizeOfSingleSystemLogMessageData]];
        ssize_t size = read(fd, (void*)buffer, (size_t)(sizeof(buffer)));
        
        [receivedData setLength:0];
        [receivedData appendBytes:buffer length:size];
    
        NSString *logMessage = [[NSString alloc] initWithData:receivedData encoding:NSUTF8StringEncoding];
        if (logMessage) {
            TDFSDLVLogModel *log = [[TDFSDLVLogModel alloc] init];
            log.id = @"NO MSG ID";
            log.message = logMessage;
            log.time = [self.dateFormatter stringFromDate:[NSDate dateWithTimeIntervalSinceNow:0]];
            
            // logs prop is observed outside, for safety, we should update logs prop context in main thread
            dispatch_async(dispatch_get_main_queue(), ^{
                NSMutableArray *currentLogs = [self.logs mutableCopy];
                [currentLogs addObject:log];
                self.logs = currentLogs;
            });
            
            printf("\n%s\n",[logMessage UTF8String]);
        }
    }
});

dispatch_resume(source_t);

self.source_t = source_t;

其中

fcntl(fd, F_SETFL, O_NONBLOCK);

用于修改fd所对应的读末端的文件状态为没有延迟;

dispatch_source_set_cancel_handler(source_t, ^{
    // ...
});

用于设置取消source监听的回调事件;

dispatch_source_set_event_handler(source_t, ^{
    // ...
});

用于设置fd有新内容的回调;

printf("\n%s\n",[logMessage UTF8String]);

是为了让日志信息额外输出到STDOUT_FILENO,保证日志依然能在Xcode的控制台中输出,方便调试。

最终效果

参考