前言
之前公司有个项目,需要跟工联对接微信支付和清算,对接过程中遇到了一个大坑。因为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, ¬ifyToken, 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的控制台中输出,方便调试。