iOS Apple日志

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自带的内存释放函数释放response和query变量。

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的dup和dup2函数恰逢其时。

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

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

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的控制台中输出，方便调试。

最终效果

参考

CATALOG
    FEATURED TAGS
    iOS 安全 Git 阅读笔记 官方文档 API Apple日志 崩溃 捕获 野指针 内存泄漏 旅行 生活 摄影 真机调试 Cocoapods Ruby
    FRIENDS