Cocoalumberjack: [Error]Crash at '__CFStringAppendFormatCore'

[Jason-Chan]

I have some literal string to be logged like this, '@"%2525252hs.blizzard.cn%2525252touch"', and when using DDLog (and actually the NSLog and printf... ,etc.), it crashed!
Anybody any idea? ... :(

In Console, Xcode prints a warning message:
warning: could not load any Objective-C class information. This will significantly reduce the quality of type information available.
As can be found out from bt, it crashed at __CFStringAppendFormatCore, originally called from
NSString *message = [[NSString alloc] initWithFormat:format arguments:args];

and bt:

* thread #1: tid = 0x12ee7, 0x00000001818296c4 CoreFoundation`__CFStringAppendFormatCore + 12704, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x16fb47030)
    frame #0: 0x00000001818296c4 CoreFoundation`__CFStringAppendFormatCore + 12704
    frame #1: 0x00000001818264ec CoreFoundation`_CFStringCreateWithFormatAndArgumentsAux2 + 244
    frame #2: 0x00000001821423b0 Foundation`-[NSPlaceholderString initWithFormat:locale:arguments:] + 168
  * frame #3: 0x000000010005af18 TestSearchController`-[IMPLuaManager log:](self=0x000000015ede90f0, _cmd="log:", format=0x00000001000d2c50) + 148 at IMPLuaManager.m:49
    frame #21: 0x000000010003d190 TestSearchController`-[AppDelegate application:didFinishLaunchingWithOptions:](self=0x000000015ee06fa0, _cmd="application:didFinishLaunchingWithOptions:", application=0x000000015ed11570, launchOptions=0x0000000000000000) + 448 at AppDelegate.m:27
    frame #22: 0x0000000186a1e8a8 UIKit`-[UIApplication _handleDelegateCallbacksWithOptions:isSuspended:restoreState:] + 400
    frame #23: 0x0000000186c4e094 UIKit`-[UIApplication _callInitializationDelegatesForMainScene:transitionContext:] + 2904
    frame #24: 0x0000000186c52500 UIKit`-[UIApplication _runWithMainScene:transitionContext:completion:] + 1684
    frame #25: 0x0000000186c4f674 UIKit`-[UIApplication workspaceDidEndTransaction:] + 168
    frame #26: 0x00000001831ff7ac FrontBoardServices`__FBSSERIALQUEUE_IS_CALLING_OUT_TO_A_BLOCK__ + 36
    frame #27: 0x00000001831ff618 FrontBoardServices`-[FBSSerialQueue _performNext] + 168
    frame #28: 0x00000001831ff9c8 FrontBoardServices`-[FBSSerialQueue _performNextFromRunLoopSource] + 56
    frame #29: 0x0000000181815124 CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 24
    frame #30: 0x0000000181814bb8 CoreFoundation`__CFRunLoopDoSources0 + 540
    frame #31: 0x00000001818128b8 CoreFoundation`__CFRunLoopRun + 724
    frame #32: 0x000000018173cd10 CoreFoundation`CFRunLoopRunSpecific + 384
    frame #33: 0x0000000186a17834 UIKit`-[UIApplication _run] + 460
    frame #34: 0x0000000186a11f70 UIKit`UIApplicationMain + 204
    frame #35: 0x000000010005b030 TestSearchController`main(argc=1, argv=0x000000016fdcbae0) + 124 at main.m:14
    frame #36: 0x00000001812da8b8 libdyld.dylib`start + 4

register read:

General Purpose Registers:
       x19 = 0x000000015edea170
       x20 = 0x000000015edd6cf0
       x21 = 0x0000000180ed5b80  libobjc.A.dylib`objc_msgSend
       x22 = 0x000000015edea1b0
       x23 = 0x000000015edea2f0
       x24 = 0x0000000000000018
       x25 = 0x0000000000000008
       x26 = 0x00000001873b34ea  "application:didFinishLaunchingWithOptions:"
       x27 = 0x000000016fdb0338
       x28 = 0x000000016fdb02f8
        fp = 0x000000016fdb0f40
        lr = 0x000000010005af18  TestSearchController`-[IMPLuaManager log:] + 148 at IMPLuaManager.m:49
        sp = 0x000000016fdb0f00
        pc = 0x000000010005af18  TestSearchController`-[IMPLuaManager log:] + 148 at IMPLuaManager.m:49
20 registers were unavailable.

and the asm:
0x18182970c <+12776>: b 0x181829714 ; <+12784>
-> 0x181829710 <+12780>: str d0, [sp]
0x181829714 <+12784>: orr w1, wzr, #0x1ff
0x181829718 <+12788>: add x3, x19, #560 ; =560
0x18182971c <+12792>: mov x23, x0
0x181829720 <+12796>: movz x2, #0
0x181829724 <+12800>: bl 0x18130a698 ; snprintf_l

As can be seen in the source, ddlog use va_args for formatting args. And in this problem we have no args but

- (void)log:(NSString *)format, ...
{
            va_list args = NULL;
            va_start(args, format);
            NSString *message = [[NSString alloc] initWithFormat:format arguments:args];
            va_end(args);
  }

[carllindberg]

If you have any literal '%' characters in the format string, they have to be escaped by being '%%'. Such as:

NSLog(@"%%2525252hs.blizzard.cn%%2525252touch")

In general, when you do not know the content of strings, it's much better to not use them as format strings directly:

NSLog(@"%@", stringWhichMightContainPercentChars);

Same goes for DDLog, printf(), etc.

In your case, %2525252hs is actually a valid printf token, which is a %s with a 'h' modifier, padded to 2525252 characters long, and expects a c-string argument. It will crash if it doesn't have that argument (and will be a very long printout if it does).

[bpoplauschi]

This looks like an issue with [NSString stringWithFormat] rather than Lumberjack

[Jason-Chan]

got an idea from

NSLog(@"%@", stringWhichMightContainPercentChars);

and for DDLog, if no extra args provided, I use

[DDLog log:NO level:DYLogLevelALL flag:type context:0 file:file function:function line:lineNumber tag:nil format:@"%@",logMsg,nil];

instead of

[DDLog log:NO level:DYLogLevelALL flag:type context:0 file:file function:function line:lineNumber tag:nil format:logMsg,nil];

to avoid the formatting
AND IT WORKS! :)
Many Thanks @carllindberg

[rivera-ernesto]

Could you pull request your solution?

[Jason-Chan]

I make no change to DDLog, but actually writing a lightweight wrapper of DDLog.

codes like

- (void)log:(NSString *)format, ...
{
            va_list args = NULL;
            va_start(args, format);
            NSString *message = [[NSString alloc] initWithFormat:format arguments:args];
            va_end(args);
  }

won't work for log-messages like @"%%2525252hs.blizzard.cn%%2525252touch", it's the bug of [[NSString alloc] initWithFormat:format arguments:args];;

My solution is kind of tricky. We don't wrap it with a method, but a MACRO with DDLog doing the formatting jobs(args can be passed correctly).
If we do want to use a METHOD and if we just know there's no extra args(found no sulution for other cases...), we call this

[DDLog log:NO level:DYLogLevelALL flag:type context:0 file:file function:function line:lineNumber tag:nil format:@"%@",logMsg,nil];

@rivera-ernesto

[rivera-ernesto]

Your solution above (https://github.com/CocoaLumberjack/CocoaLumberjack/issues/735#issuecomment-219973052) makes a lot of sense.

Actually NSLog does warn you when you don't use a proper formatter, with @"%@" as the bare minimum. We should use that I think.

[carllindberg]

This does sound like a bug in the wrapper, not CocoaLumberjack. If you don't know the contents of a given string -- i.e. it's not meant to be used as a format string -- then you need to use %@ to log it. This could be a bug in a particular log statement -- you can't just call DDLog() (or wrappers) with arbitrary strings; those calls should all use %@ with the string as an argument. DDLog wrappers are fine but the argument has to be a real format string. The compiler won't necessarily complain since in rare situations it might make sense to pass a variable as a format string (such as getting a localized version of a format string) but usually the first argument to a string formatting call should be constant strings (even if just "%@").

[xingheng]

Since we have got the root cause and the above solutions including wrappers, could we fix it in CocoaLumberjack inner implementation with an optional switch to create a more wrapper for string format?

Just like this:

@interface DDLog

@property (nonamtic, assign) BOOL additionalStringFormat; // Default is NO

@end

We knew it's a bug in NSLog, but don't expect the string format crash when printing a log message, shall we?

[carllindberg]

The above was not a bug in NSLog, nor DDLog. It was a bug in the code which called them. If you have an arbitrary string, don't pass it directly to DDLog -- use DDLogInfo(@"%@", arbitraryString). It always takes a format string, always, and it's easier to just call it that way in the first place (where you have the knowledge if the value is a format string or not) than trying to solve it in any other place.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If this is still an issue, please make sure it is up to date and if so, add a comment that this is still an issue to keep it open. Thank you for your contributions.