NSLog and print source code reading and capture scheme

preface

As a common debugging and log printing method for iOS development, NSLog is familiar to everyone. The open source community has also contributed many excellent log frameworks to us, such as CocoaLumberjack in OC. If you are interested, you can go to github.com/CocoaLumber… In Swift we have another option, which is print

If you want to do log monitoring yourself, you need to redirect the NSLog and print methods yourself

There are probably several methods on the network

Asl reads logs (deprecated after iOS10) NSLog outputs logs to /var/log/syslog by default. Asl framework can read logs from syslogs. This method does not invade the system
In the dup2 redirection mode, the last redirection handle of NSLog is STDERR. The log content output by NSLog is finally recorded through the STDERR handle. Using the dup2 redirection to the STDERR handle, the content can be redirected to the specified location
Adopt the Fishhook approach to Facebook’s open source frameworkfishhookTo dynamically replaceNSLogandprintmethods

This article selects the fishhook based method to capture NSLog and print method benefits: github.com/madaoCN/Sup… Lightweight log printing has been implemented using fishhook hook NSLog and print methods

preparation

There are many well-written articles on the Web, so you can Google them
Swift source code has been open source, we can read the source code to see the project address github.com/apple/swift compilation is also very simple, but relatively time-consuming

brew install cmake ninja
mkdir swift-source
cd swift-source
git clone https://github.com/apple/swift.git
./swift/utils/update-checkout --clone
cd swift
utils/build-script --release-debuginfo
Copy the code

The final compiled file may be quite large, mine is about 44.18GB, please reserve enough space before compiling

If you’re done, you can feed the dog

NSLog source code to read

The source for NSLog is in your Build project directory/swift-build /swift-corelibs-foundation

/* Output from NSLogv is serialized, in that only one thread in a process can be doing * the writing/logging described above at a time. All attempts at writing/logging a * message complete before the next thread can begin its attempts. The format specification * allowed by these functions is that which is understood by NSString's formatting capabilities. * CFLog1() uses writev/fprintf to write to stderr. Both these functions ensure atomic writes. */

public func NSLogv(_ format: String, _ args: CVaListPointer) {
    let message = NSString(format: format, arguments: args)
    CFLog1(CFLogLevel(kCFLogLevelWarning), message._cfObject)
}

public func NSLog(_ format: String, _ args: CVarArg...) {
    withVaList(args) { 
        NSLogv(format, $0)}}Copy the code

We can see the NSLog call

NSLog ------> NSLogv ------> CFLog1
Copy the code

CFLog1() uses writev/fprintf to write to stderr. NSLog calls writev and fprintf

void CFLog1(CFLogLevel lev, CFStringRef message) {
#if TARGET_OS_ANDROID
    if (message == NULL) message = CFSTR("NULL"); .CFStringEncoding encoding = kCFStringEncodingUTF8;
    CFIndex maxLength = CFStringGetMaximumSizeForEncoding(CFStringGetLength(message), encoding) + 1; .if (maxLength == 1) {
        // was crashing with zero length strings
        // https://bugs.swift.org/browse/SR-2666
        strcpy(buffer, ""); // log empty string
    }
    else
        CFStringGetCString(message, buffer, maxLength, encoding);
    
        __android_log_print(priority, tag, "%s", buffer);
        // ======= note here =======
        fprintf(stderr, "%s\n", buffer);
    
    if(buffer ! = &stack_buffer[0]) free(buffer);
#else
    // ======= note here =======
    CFLog(lev, CFSTR("% @"), message);
#endif
}
Copy the code

You can see that fprintf is called if it is an Android environment, and CFLog is called otherwise

  NSLog 
    ↓
  NSLogv
    ↓
  CFLog1
    ↓
  CFLog
Copy the code

Now the order of the calls is like this, and then as we go down, let’s look at CFLog

void CFLog(int32_t lev, CFStringRef format, ...) {
    va_list args;
    va_start(args, format); 
    _CFLogvEx3(NULL.NULL.NULL.NULL, lev, format, args, __builtin_return_address(0));
    va_end(args);
}

// _CFLogvEx3 was called
CF_EXPORT void _CFLogvEx3(CFLogFunc logit, CFStringRef (*copyDescFunc)(void *, const void *), CFStringRef (*contextDescFunc)(void *, const void *, const void *, bool, bool *), CFDictionaryRef formatOptions, int32_t lev, CFStringRef format, va_list args, void *addr) {
    _CFLogvEx2Predicate(logit, copyDescFunc, contextDescFunc, formatOptions, lev, format, args, _cf_logging_style_legacy);
    
}

// _CFLogvEx2Predicate is called
static void _CFLogvEx2Predicate(CFLogFunc logit, CFStringRef (*copyDescFunc)(void *, const void *), CFStringRef (*contextDescFunc)(void *, const void *, const void *, bool, bool *), CFDictionaryRef formatOptions, int32_t lev, CFStringRef format, va_list args, _cf_logging_style loggingStyle) {
#if TARGET_OS_MAC
    uintptr_t val = (uintptr_t)_CFGetTSD(__CFTSDKeyIsInCFLog);
    if (3 < val) return; // allow up to 4 nested invocations
    _CFSetTSD(__CFTSDKeyIsInCFLog, (void *)(val + 1), NULL);
#endif
    CFStringRef str = format ? _CFStringCreateWithFormatAndArgumentsAux2(kCFAllocatorSystemDefault, copyDescFunc, contextDescFunc, formatOptions, (CFStringRef)format, args) : 0;
    CFIndex blen = str ? CFStringGetMaximumSizeForEncoding(CFStringGetLength(str), kCFStringEncodingUTF8) + 1 : 0;
    char *buf = str ? (char *)malloc(blen) : 0;
    if (str && buf) {
	Boolean converted = CFStringGetCString(str, buf, blen, kCFStringEncodingUTF8);
	size_t len = strlen(buf);
	// silently ignore 0-length or really large messages, and levels outside the valid range
	if(converted && ! (len <=0| | -1 << 24) < len) && ! (lev <ASL_LEVEL_EMERG || ASL_LEVEL_DEBUG < lev)) {
            if (logit) {
                logit(lev, buf, len, 1);
            }
            else if (loggingStyle == _cf_logging_style_os_log) {
                // ======= note here =======
                __CFLogCString(lev, buf, len, 1);
            }
            else if (loggingStyle == _cf_logging_style_legacy) {
                // ======= note here =======
                __CFLogCStringLegacy(lev, buf, len, 1); }}}if (buf) free(buf);
    if (str) CFRelease(str);
#if TARGET_OS_MAC
    _CFSetTSD(__CFTSDKeyIsInCFLog, (void *)val, NULL);
#endif
}
Copy the code

The __CFLogCString and __CFLogCStringLegacy methods are called, so now the process is called like this

			  NSLog 
			    ↓
			  NSLogv
			    ↓
			  CFLog1
			    ↓
			  CFLogLeft _CFLogvEx3 left _CFLogvEx2Predicate | / \ \ / \ __CFLogCString __CFLogCStringLegacyCopy the code

__CFLogCString and __CFLogCStringLegacy both methods end up calling the _logToStderr method

static void _logToStderr(char *banner, const char *message, size_t length) {
#if TARGET_OS_MAC
    struct iovec v[3].v[0].iov_base = banner;
    v[0].iov_len = banner ? strlen(banner) : 0;
    v[1].iov_base = (char *)message;
    v[1].iov_len = length;
    v[2].iov_base = "\n";
    v[2].iov_len = (message[length1]! = '\n')? 1:0;int nv = (v[0].iov_base? 1:0) + 1 + (v[2].iov_len? 1:0);static CFLock_t lock = CFLockInit;
    __CFLock(&lock); // ======= note here =======writev(STDERR_FILENO.v[0].iov_base ? v : v + 1, nv);
    __CFUnlock(&lock);
#elif TARGET_OS_WIN32
    size_t bannerLen = strlen(banner);
    size_t bufLen = bannerLen + length + 1;
    char *buf = (char *)malloc(sizeof(char) * bufLen);
    if (banner) {
        // Copy the banner into the debug string
        memmove_s(buf, bufLen, banner, bannerLen);
        
        // Copy the message into the debug string
        strcpy_s(buf + bannerLen, bufLen - bannerLen, message);
    } else {
        strcpy_s(buf, bufLen, message);
    }
    buf[bufLen - 1= '\]0';
    fprintf_s(stderr, "%s\n", buf);
    // This Win32 API call only prints when a debugger is active
    // OutputDebugStringA(buf);
    free(buf);
#else
    size_t bannerLen = strlen(banner);
    size_t bufLen = bannerLen + length + 1;
    char *buf = (char *)malloc(sizeof(char) * bufLen);
    if (banner) {
        // Copy the banner into the debug string
        memmove(buf, banner, bannerLen);
        
        // Copy the message into the debug string
        strncpy(buf + bannerLen, message, bufLen - bannerLen);
    } else {
        strncpy(buf, message, bufLen);
    }
    buf[bufLen - 1= '\]0';

    // ======= note here =======

    fprintf(stderr, "%s\n", buf);
    free(buf);
#endif
}
Copy the code

You can see that NSLog ends up calling both writev and fprintf methods

					  NSLog 
					    ↓
					  NSLogv
					    ↓
					  CFLog1
					    ↓
					  CFLogLeft _CFLogvEx3 left _CFLogvEx2Predicate | / \ \ / \ __CFLogCString __CFLogCStringLegacy \ / \ \ / _logToStderr left writev/down  fprintfCopy the code

The result is consistent with the previous comment, so we only need to hook the writev/fprintf method with Fishhook to achieve our purpose, so we continue to look at the source code of the print function

Print function source read

Print source location in similar you compile the project directory/Swift – Build/Build/Xcode – RelWithDebInfoAssert/Swift – macosx – x86_64 specific names and compile related parameters and machine

We can easily find the source code

============ print method 1
public func print(
  _items: Any... , separator: String ="",
  terminator: String = "\n"
) {
  if let hook = _playgroundPrintHook {
     // ======= note here =======
    var output = _TeeStream(left: "".right: _Stdout())
    _print(items, separator: separator, terminator: terminator, to: &output)
    hook(output.left)}else {
   // ======= note here =======
    var output = _Stdout()
    _print(items, separator: separator, terminator: terminator, to: &output)
  }
}

// ============ print method 2
public func print<Target: TextOutputStream>(
  _items: Any... , separator: String ="",
  terminator: String = "\n",
  to output: inout Target
) {
  // ======= note here =======
  _print(items, separator: separator, terminator: terminator, to: &output)
}
Copy the code

The visible print method calls the _print method

internal func _print<Target: TextOutputStream>(
  _ items: [Any],
  separator: String = "",
  terminator: String = "\n",
  to output: inout Target
) {
  var prefix = ""
  output._lock()
  defer { output._unlock() }
  for item in items {
    output.write(prefix)

    // ======= note here =======
    _print_unlocked(item, &output)

    prefix = separator
  }
  output.write(terminator)
}

/ / _print_unlocked source code
@usableFromInline
@_semantics("optimize.sil.specialize.generic.never")
internal func _print_unlocked<T, TargetStream: TextOutputStream>(
  _ value: T, _ target: inout TargetStream
) {
  // Optional has no representation suitable for display; therefore,
  // values of optional type should be printed as a debug
  // string. Check for Optional first, before checking protocol
  // conformance below, because an Optional value is convertible to a
  // protocol if its wrapped type conforms to that protocol.
  // Note: _isOptional doesn't work here when T == Any, hence we
  // use a more elaborate formulation:
  if _openExistential(type(of: value as Any), do: _isOptional) {
    let debugPrintable = value as! CustomDebugStringConvertible
    debugPrintable.debugDescription.write(to: &target)
    return
  }
  if case let streamableObject as TextOutputStreamable = value {
    streamableObject.write(to: &target)
    return
  }

  if case let printableObject as CustomStringConvertible = value {
    printableObject.description.write(to: &target)
    return
  }

  if case let debugPrintableObject as CustomDebugStringConvertible = value {
    debugPrintableObject.debugDescription.write(to: &target)
    return
  }

  let mirror = Mirror(reflecting: value)

  _adHocPrint_unlocked(value, mirror, &target, isDebugPrint: false)}Copy the code

See the following invocation flow

print ------> _print ------> _print_unlocked
Copy the code

Here,

TextOutputStreamable
CustomDebugStringConvertible
CustomStringConvertible

//////////////////// CustomStringConvertible
public protocol CustomStringConvertible {
  var description: String { get}}//////////////////// CustomDebugStringConvertible
public protocol CustomDebugStringConvertible {
  var debugDescription: String { get}}//////////////////// TextOutputStreamable
public protocol TextOutputStreamable {
  /// Writes a textual representation of this instance into the given output
  /// stream.
  func write<Target: TextOutputStream>(to target: inout Target)
}
Copy the code

Etc are protocols that pass in Target and call Target’s write method

Unlocked

(_ value: T, _ target: inout TargetStream)
,>

A target is an object that follows the TextOutputStream protocol, the _Stdout () function we saw earlier


/ / / / / / / / / / / / / / TextOutputStream protocol
public protocol TextOutputStream {
  mutating func _lock(a)
  mutating func _unlock(a)

  /// Appends the given string to the stream.
  mutating func write(_ string: String)

  mutating func _writeASCII(_ buffer: UnsafeBufferPointer<UInt8>)
}

////////////// _Stdout 
internal struct _Stdout: TextOutputStream {
  internal init() {}

  internal mutating func _lock(a) {
    _swift_stdlib_flockfile_stdout()
  }

  internal mutating func _unlock(a) {
    _swift_stdlib_funlockfile_stdout()
  }

  internal mutating func write(_ string: String) {
    if string.isEmpty { return }

    var string = string
    _ = string.withUTF8 { utf8 in
      
       // ======= note here =======_swift_stdlib_fwrite_stdout(utf8.baseAddress! .1, utf8.count)}}}// =========== _swift_stdlib_fwrite_stdout source code
SWIFT_RUNTIME_STDLIB_INTERNAL
__swift_size_t swift::_swift_stdlib_fwrite_stdout(const void *ptr,
                                                  __swift_size_t size,
                                                  __swift_size_t nitems) {
    // ======= note here =======
    return fwrite(ptr, size, nitems, stdout);
}
Copy the code

We can see that

_Stdout -> _swift_stdlib_fwrite_stdout -> fwrite
Copy the code

In combination with the previous call method, the fwrite method is finally called as well

print -> _print -> _print_unlocked ->  (print items) -> (write/description.write/debugDescription.write)-> Stdout -> _swift_stdlib_fwrite_stdout -> fwrite
Copy the code

After all this detour, we conclude that the print function ends up calling fwrite

Intermission ~~~~

Ultimately, if we want log monitoring, we only need to hook the following three methods

NSLogCall writev/fprintfprintCall fwriteCopy the code

Hook code

First we hookwritev, function prototype

static ssize_t writev(int a, const struct iovec * v, int v_len);

/// struct iovec 类型
struct iovec {
	void *   iov_base;      /* [XSI] Base address of I/O memory region */
	size_t   iov_len;       /* [XSI] Size of region iov_base points to */
};
Copy the code

Specific hook code

//--------------------------------------------------------------------------
// MARK: hook NSLog
//--------------------------------------------------------------------------

// origin writev IMP
static ssize_t (*orig_writev)(int a, const struct iovec * v.int v_len);

// swizzle method
ssize_t asl_writev(int a.const struct iovec *v.int v_len) {
    
    NSMutableString *string = [NSMutableString string];
    for (int i = 0; i < v_len; i++) {
        char *c = (char *)v[i].iov_base;
        [string appendString:[NSString stringWithCString:c encoding:NSUTF8StringEncoding]];
    }
    
    ////////// do something The log string can be captured here
    
    // invoke origin mehtod
    ssize_t result = orig_writev(a, v, v_len);
    return result;
}
Copy the code

And then thefprintfFunction, here because fprintf is a variable parameter, the specific variable parameter is related to using the visible blogger’s other blogVa_list Overview of variable parameters

So I’m going to use at sign selector of NSString (initWithFormat: The origin_fprintf (arguments) method generates the string to output, instead of passing the variablearguments to origin_fprintf

//--------------------------------------------------------------------------
// MARK: hook fprintf
//--------------------------------------------------------------------------

// origin fprintf IMP
static int     (*origin_fprintf)(FILE* __restrict, const char * __restrict, ...) ;// swizzle method
int     asl_fprintf(FILE * __restrict file, const char * __restrict format, ...)
{
    /* typedef struct { unsigned int gp_offset; unsigned int fp_offset; void *overflow_arg_area; void *reg_save_area; } va_list[1]; * /
    va_list args;
    
    va_start(args, format);

    NSString *formatter = [NSString stringWithUTF8String:format];
    NSString *string = [[NSString alloc] initWithFormat:formatter arguments:args];
    
    ////////// do something logs can be captured here

    // invoke orign fprintf
    int result = origin_fprintf(file, [string UTF8String]);
    
    va_end(args);

    return result;
}
Copy the code

And then thefprintfmethods

Calls such as fprintf (“test”); The asl_fwrite method is called twice, once with test and once with \n, so the string is first put into __messageBuffer, and when \n is received, the __messageBuffer is converted into a string and read once

//--------------------------------------------------------------------------
// MARK: hook print for swift
//--------------------------------------------------------------------------

// origin fwrite IMP
static size_t (*orig_fwrite)(const void * __restrict, size_t, size_t, FILE * __restrict);

static char *__messageBuffer = {0};
static int __buffIdx = 0;
void reset_buffer()
{
    __messageBuffer = calloc(1.sizeof(char));
    __messageBuffer[0= '\]0';
    __buffIdx = 0;
}


// swizzle method
size_t asl_fwrite(const void * __restrict ptr, size_t size, size_t nitems, FILE * __restrict stream) {
        
    if (__messageBuffer == NULL) {
        // initial Buffer
        reset_buffer();
    }
    
    char *str = (char *)ptr;
    
    NSString *s = [NSString stringWithCString:str encoding:NSUTF8StringEncoding];
    
    if(__messageBuffer ! =NULL) {
        
        if (str[0] == '\n' && __messageBuffer[0] != '\0') {
            
            s = [[NSString stringWithCString:__messageBuffer encoding:NSUTF8StringEncoding] stringByAppendingString:s];
            
            // reset buffIdx
            reset_buffer();

            ////////// do something logs can be captured here
        }
        else {
            
            // append buffer
            __messageBuffer = realloc(__messageBuffer, sizeof(char) * (__buffIdx + nitems + 1));
            for (size_t i = __buffIdx; i < nitems; i++) {
                __messageBuffer[i] = str[i];
                __buffIdx ++;
            }
            __messageBuffer[__buffIdx + 1= '\]0'; __buffIdx ++; }}return orig_fwrite(ptr, size, nitems, stream);
}
Copy the code

Finally is the hook code, nothing to say

//--------------------------------------------------------------------------
// MARK: fishhook call
//--------------------------------------------------------------------------
// hook writev
rebind_symbols((struct rebinding[1]){{
    "writev",
    asl_writev,
    (void*)&orig_writev
}}, 1);

// hook fwrite
rebind_symbols((struct rebinding[1]){{
    "fwrite",
    asl_fwrite,
    (void *)&orig_fwrite}}, 1);

// hook fprintf
rebind_symbols((struct rebinding[1]){{
    "fprintf",
    asl_fprintf,
    (void *)&origin_fprintf}}, 1);
Copy the code

Now let’s look at the results

For the code, see github.com/madaoCN/Sup… The function is still in perfect, will update intermittently

reference

Print fishhook hook (NSLog, print)

Capture NSLog notes

GodEye log monitoring

IOS reverse engineering – Fishhook Principle

NSLog and print source code reading and capture scheme

preface

preparation

NSLog source code to read

Print function source read

Intermission ~~~~

Hook code

reference

Related Posts

In iOS UIApplication, delegate.window is different from.keyWindow

What does the Silicon Valley Swift interview question look like?

IOS horizontal pop-up menu (support to expand and fold)