In the latest Mojave public beta, I noticed a foreboding warning in the console when I build and run FastScripts, my macOS scripting utility:

FastScripts [...] is calling TIS/TSM in non-main thread environment, ERROR : This is NOT allowed. Please call TIS/TSM in main thread!!!

Ruh-roh, that doesn’t sound good. Particularly with the emphasis of three, count them three, exclamation points! I better figure out what’s going on here. But how?

Sometimes when Apple adds a log message like this, they are kind enough to offer advice about what to do to alleviate the problem. Sometimes the advice implores that we stop using a deprecated method, or in a scenario like this, offers a symbolic breakpoint we might set to zero in on exactly where the offending code lies. For example, a quick survey of my open Console app reveals:

default	11:54:18.482226 -0400	com.apple.WebKit.WebContent	Set a breakpoint at SLSLogBreak to catch errors/faults as they are logged.

This particular warning doesn’t seem to apply to my app, but if it did, I would have something good to go on if I wanted to learn more. With the TIS/TSM warning, however, I have no idea where to go. Do I even use TIS/TSM? What is TSM?

I’ve worked on Apple platforms for long enough to know that TSM stands for Text Services Manager. However, I have also worked on these platforms long enough to forget whether I’ve actually used, or am still using, such a framework in my apps! When these kinds of warnings appear in the console, as many times as not they reflect imperfections in Apple’s own framework code. Is it something Apple’s doing, or something I’m doing, that’s triggering this message?

Ideally we could set a breakpoint on the very line of code that causes this console message to be printed. This can be surprisingly difficult though. There have always been a variety of logging mechanisms. Should you set the breakpoint on NSLog, os_log, printf, fprintf, or write? I could probably figure out a comprehensive method for catching anything that might write to the console, but am I even sure this console method is being generated in my app’s main process? There are a lot of variables here. (Hah! In this particular case, I ended up digging deeper and discovering it calls “CFLog”).

This is a scenario where combining lldb’s powerful “regular expression breakpoints” and “breakpoint commands” can help a great deal. Early in my app’s launch, before the warning messages are logged, I break in lldb and add a breakpoint:

(lldb) break set -r TIS|TSM.*

I’m banking on the likelihood that whatever function is leading to this warning contains the pertinent framework prefixes. It turns out to be a good bet:

Breakpoint 5: 634 locations.

I hit continue and let my app continue launching. Here’s the problem, though: those 634 breakpoint locations include quite a few that are getting hit on a regular basis, and for several consecutive breaks, none of them is triggering the warning message I’m concerned about. This is a situation where I prefer to “let it rip” and sort out the details later:

(lldb) break command add 5
Enter your debugger command(s).  Type 'DONE' to end.
> bt
> c
> DONE
(lldb) c
Process 16022 resuming

What this does is add a series of commands that will be run automatically by lldb whenever breakpoint 5 (the one I just set) is hit. This applies to any of the 634 locations that are associated with the regular expression I provided. When the breakpoint is hit, it will first invoke the “bt” command to print a backtrace of all the calls leading up to this call, and then it will invoke the “continue” command to keep running the app. After the app has run for a bit, I search the debugger console for “!!!” which I remembered from the original warning. Locating it, I simply scroll up to see the backtrace command that had most recently been invoked:

  thread #7, stop reason = breakpoint 5.568
    frame #0: 0x00007fff2cd520fd HIToolbox`TSMGetInputSourceProperty
    frame #1: 0x00000001003faef2 RSFoundation`-[RSKeyboardStatus update](self=0x00006000002b8c00, _cmd="update") at RSKeyboardStatus.m:56
    [...]

Command #2 'c' continued the target.
2018-08-14 12:15:40.326538-0400 FastScripts[16022:624168] pid(16022)/euid(501) is calling TIS/TSM in non-main thread environment, ERROR : This is NOT allowed. Please call TIS/TSM in main thread!!! 

Sure enough, that’s my code. I’m calling TSM framework functions to handle key translation for FastScripts’s keyboard shortcut functionality, and I’m doing it (gasp!) from thread #7, which is certainly not the main thread. I oughta be ashamed…

But I’m proud, because I tracked down the root of the problem pretty efficiently using lldb’s fantastic breakpoint commands. Next time you’re at a loss for how or where something could possibly be happening, consider the possibility of setting a broad, regular expression based breakpoint, and a series of commands to help clarify what’s happening when those breakpoints are hit. Then? Let it rip!