By

Contents
  1. 1. 前言
  2. 2. 正文
    1. 2.1. 次序问题
    2. 2.2. 总结

前言

关于 printf 缓冲策略导致的日志次序等奇怪问题在 stdout printf 和它的缓存策略得到了比较完备的解释。

正文

大概十个月以前想做一个 libMainThreadChecker 一样的功能，当时想了两种方式一种是如前者一样中心化重定向 UIKit 相关类消息转发，另一种是分析前者在控制台输出的日志。第一种方式详见阿里大牛的文章 基于桥的全量方法Hook方案 - 探究苹果主线程检查实现。我先采用第二种方式试试水，第一种比较困难。

要想在 App 中拿到控制台的输出并分析，首先想到的是重定向 stdout（printf）/stderr（NSLog）。使用 freopen 函数就行。

    freopen("mylog", "a+", stdout);

这样就把 stdout 的流重定向到了 mylog 本地文件上。接下来写个定时任务分析 mylog 文件内容就行。

当用户离开我们频道时则恢复重定向。

如果使用 freopen 函数反过来写并不会起作用。

    freopen(stdout, "a+", "mylog");

要想恢复重定向则需要使用 dup2 函数。

    // 重定向 stdout 到本地文件
    FILE *my_file = freopen("mylog", "a+", stdout);

    // 恢复
    dup2(fileno(my_file), fileno(stdout));

这样一来就可以恢复了，但是跑起来发现控制台还是没有输出。

当 App（当前进程）描述表的 stdout 会在重定向完成之后被关闭。现在描述符 1、4 都指向了文件 B，文件 A 的文件表和 v-node 因为引用计数为零了所以被删除。

    // 恢复
    dup2(fileno(my_file), fileno(stdout));

所以这段代码是不生效的，因为通往控制台的路径已经丢失了。同时此时的 stdout 打开的是 mylog 文件的描述符。把自己重定向到自己身上是没有用的。

所以为了保留对控制台文件的描述符以及防止其引用计数为零被删除我们先 copy 一份出来。

    int my_copy = dup(fileno(stdout));

    // 重定向 stdout 到本地文件
    FILE *my_file = freopen("mylog", "a+", stdout);

    // 恢复
    dup2(fileno(my_copy), fileno(stdout));

这个时候文件描述符的情况如图所示

有了 fd 3 还连着文件 A，文件 A 就不会像之前那样被删除了。

我们来看下运行效果：

    int main(int argc, const char * argv[]) {
        printf("I am in stdout\n");
        int my_copy = dup(fileno(stdout));
        
        fprintf(stderr, "fd number my_copy is %d\n", my_copy);
        
        // 重定向 stdout 到本地文件
        FILE *my_file = freopen("/Users/sean/Desktop/mylog", "a+", stdout);
        
        fprintf(stderr, "fd number my_file is %d\n", fileno(my_file));
        fprintf(stderr, "fd number stdout is %d\n", fileno(stdout));
        
        printf("I am in mylog\n");
        
        // 恢复
        dup2(my_copy, fileno(my_file));
        
        printf("I am in stdout, reborn\n");
        
        fprintf(stderr, "after restore fd number my_file is %d\n", fileno(my_file));
        fprintf(stderr, "after restore fd number stdout is %d\n", fileno(stdout));
        return 0;
    }

对应日志输出为

    I am in stdout
    fd number my_copy is 3
    fd number my_file is 1
    fd number stdout is 1
    after restore fd number my_file is 1
    after restore fd number stdout is 1
    I am in mylog
    I am in stdout, reborn
    Program ended with exit code: 0
  1. I am in stdout 符合预期
  2. fd number my_copy is 3，stdout fd 本来是 1，它的副本是 3
  3. my_file 的 fd 是 1，跟 stdout 一样？这好像跟上图描述的情况不一样。网上说的也是返回 path 对应文件的指针。
  4. 符合预期
    接下来是恢复重定向
  5. 为什么是先打印 “after restore” 的语句？后面解释。
  6. 同上
  7. I am in mylog 怎么跑这里来了？不是应该很早就打印么？而且不应该输出到文件里吗？
  8. 符合预期

次序问题

把程序再改下

    int main(int argc, const char * argv[]) {
        printf("I am in stdout\n");
        int my_copy = dup(fileno(stdout));
        
        // 重定向 stdout 到本地文件
        FILE *my_file = freopen("/Users/sean/Desktop/mylog", "a+", stdout);
        
        for (int i = 0; i < 10; i++) {
            if (i == 5) {
                fflush(my_file);
            }
            printf("I am in mylog %d\n", i);
        }
        
        // 恢复
        dup2(my_copy, fileno(my_file));
        
        printf("I am in stdout, reborn\n");
        
        fprintf(stderr, "after restore fd number my_file is %d\n", fileno(my_file));
        fprintf(stderr, "after restore fd number stdout is %d\n", fileno(stdout));
        return 0;
    }

对应的输出为

    I am in stdout
    after restore fd number my_file is 1
    after restore fd number stdout is 1
    I am in mylog 5
    I am in mylog 6
    I am in mylog 7
    I am in mylog 8
    I am in mylog 9
    I am in stdout, reborn
    Program ended with exit code: 0

发现 I am in mylog 5 i < 5 之前的几条日志都没在控制台，它确实写到文件里去了。后面的又没写进去，所以证明 fflush(my_file); 起了作用。printf 是带缓冲的输出函数，提交给系统的语句并不是马上就写入的。至于 after 的语句为什么跑到前面去了，我猜测是重定向恢复之后还缺少了某个设置。因为重定向之后的 print 不是马上就有 fflush。

而在程序结束的时候系统调用了 fflush 函数，这才把 I am in stdout, reborn 输出了，所以之后在 stdout 流上写的数据全部跑后面来了。

给 fflush 打个符号断点就能看到程序在退出的时候调用了不止一次（实际上是因为需要 flush 的不止一个流），但是这里又有个问题了——线程 3 是干啥的？

重定向到文件的数据在程序没结束前不会写到文件里，继续在内存里，等到重定向恢复又被一口气 fflush 到了控制台。

总结

  1. 要恢复需要保留指向控制台文件的指针，虽然 fd 1 没变，但是指针指向的内存区域发生了改变
  2. 重定向之后改变了系统缓存的策略，所以要自己调用 fflush 保证日志顺序

有点乱，改天再优化下行文思路

Contents
  1. 1. 前言
  2. 2. 正文
    1. 2.1. 次序问题
    2. 2.2. 总结