Too many mach ports?

We have a customer reporting a bunch of problems with our (Transparent Proxy Provider-based) suite. Looking at a sysdiagnose, I see that our GUI applet was killed:

Termination Reason: Namespace PORT_SPACE, Code 14123288431434181290 (Limit 305834 ports) Exceeded system-wide per-process Port Limit

Looking at the top.txt file from it, I see that it has 193,086 ports -- compared to about ~250 on one of my test systems.

So, let me just say that crashing like this is the BEST possible outcome for an issue like this. Mach port communication is so fundamental to the system’s function that Mach port leaks can basically break "anything" in your app. Crashing is the "good" failure here, as that is much easier to investigate than "hangs randomly in different places for no apparent reason".

Has anyone run into this?

Yes, I've seen Mach port leaks before. Historically, they were a consistent long-standing source of bugs through the entire system. Indeed, one of the major reasons XPC exists was to provide a slightly higher-level interface which would do a better job of "not leaking".

Any idea what might be causing it?

Are you calling ANY Mach API directly? Most Mach port leaks I've seen were ultimately caused by using low-level Mach APIs, generally in an attempt to gather some kind of diagnostic data. You'll note that I said "using" and not "using incorrectly". While it is theoretically possible to use these APIs correctly, my own experience indicates that this is not possible in practice. Beyond that, it is possible to leak using just XPC (it's just harder).

Shifting to the investigation side:

(I'm still poring over the sysdiagnose, but I don't see any kernel logs around that time -- except that our process does close a dozen or so ports because of cancellation.)

Unfortunately, I wouldn't expect the sysdiagnose to help all that much. The system relies so heavily on Mach ports that there simply can't be any kind of "generic" logging about them, as it would generate far too much noise.

The main diagnostic tool I'd actually start with is Activity Monitor, as it allows you to passively monitor your process's port usage (look for the "port" field). Depending on what your process is doing, that number will oscillate over time, but it should stabilize around "some" number. The key here is that 300,000 is a LOT of ports, so it's possible to leak for a VERY long time without anything bad actually happening.

Beyond that, we do have a VERY old sample that lets you print diagnostic data about "yourself". You're welcome to use that code, but I'd highlight the warning at the top of the code:

// Apple strongly recommends that developers avoid using Mach APIs 
// directly.  Mach APIs represent the lowest-level interface to 
// the kernel, and thus they are the most likely to change (or 
// become unsupportable) as the kernel evolves.
...
// This sample uses Mach APIs directly, and thus seems to contravene 
// the above recommendations.  However, this is justified by the last 
// sentence of the previous paragraph: the job this sample does, 
// displaying information about a Mach task's port right name space, 
// is only possible via the use of Mach APIs.
//
// It might make sense for you to copy the techniques used by 
// MachPortDump into your application, to help detect port right 
// leaks and so on.  However, I strongly recommend that you include 
// this code only in your debug build.

Take that warning seriously. It's there not just because it’s a difficult API to use correctly (which it is), but because the bugs it will create are all but guaranteed to be a huge pain to investigate and fix.

Lastly, one final thought here:

We have a customer reporting a bunch of problems with our (Transparent Proxy Provider-based) suite.

One thing I would look closely at here is what ELSE is on their system, particularly any kind of Endpoint Security client. IF we assume that your code is entirely correct under "normal" conditions, then the question becomes "what makes this machine/configuration different". Endpoint Security is the one API on the system that could "directly" disrupt your apps normal logic in a ways you wouldn't normally expect.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Just woke up, so truncated responses:

No, not doing any Mach IPC directly -- everything is done via ObjC XPC objects in the GUI app (and Swift ones in the extension). I did notice something else happening, which is that the attempt to load/store the VPN configuration is failing with "wrong type of configuration" or something like that. This causes our GUI app to exit, in the hope that this might cause it to work the 2nd time around, although that doesn't seem to be the case. (So, basically, the GUI app is running for about 40 seconds, and then dying.)

No, not doing any Mach IPC directly -- everything is done via ObjC XPC objects in the GUI app (and Swift ones in the extension). I did notice something else happening, which is that the attempt to load/store the VPN configuration is failing with "wrong type of configuration" or something like that.

That could certainly be causing leaks on the other side of the connection; however, Quinn reminded me of another tool which will be very useful for this, which is "lsmp". The man page has the full details, but lsmp will print detailed diagnostic information about any process (or even the entire system) you point it at. Even better, it's a standard command line tool (not a developer tool), so you can run it on the end user system, and it can output as standard text or JSON (which can be better if you're dealing with a large-scale leak).

Given the scale of the leak involved, I suspect that having the customer run it anytime after the leak has "started" (but before you crash) should give you a hint as to what's going on.

Finally, one small question here:

This causes our GUI app to exit, in the hope that this might cause it to work the 2nd time around, although that doesn't seem to be the case. (So, basically, the GUI app is running for about 40 seconds, and then dying.)

I don't know enough about your architecture to know if/where this applies, but is there any part/component in your app where you have an unrestricted retry loop (try/fail/try... as fast as you can) involving XPC? All of the Mach APIs are EXTREMELY fast relative to real-world time, so retrying "as fast as possible" can end up cycling MUCH faster than you might expect. Even if this isn't a direct issue, it's generally worth adding some kind of rate limiter on retry simply to avoid unnecessarily wasting lots of cycles. There are very few situations where doing something 1000/sec is actually any better than doing the same thing 10/sec.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

there any part/component in your app where you have an unrestricted retry loop (try/fail/try... as fast as you can) involving XPC?

Hm, not really. We will retry activating the extension, but that's not us using XPC directly; in another case, we'll try talking with the extension using XPC, and if it times out, we deactivate and reactivate the extension. (But that takes 2-3 minutes before it'll get that far.)

We will retry activating the extension, but that's not us using XPC directly; in another case, we'll try talking with the extension using XPC, and if it times out, we deactivate and reactivate the extension. (But that takes 2-3 minutes before it'll get that far.)

Interesting. Going back to your original message here:

We have a customer reporting a bunch of problems with our (Transparent Proxy Provider-based) suite. Looking at a sysdiagnose, I see that our GUI applet was killed:

Do you have a crash log for this? And are you able to determine how long that process was running before it was terminated?

Leaking 300,000 ports means you had to do "something" 300,000 times, so knowing how long your process was alive can tell you the approximate leak rate. As a reference, "300,000s" is "~3 1/2 days", so even a relatively "fast" (in real-world time) leak won't actually kill your process all that quickly*. Other factors can quickly reduce that time (for example, leaking pairs of ports), but we're still talking about a lot of time unless you're leaking at a pretty high rate.

*One of the issues that often make Mach port issues difficult to debug is that the actual "problem" that ends up directly hurting the app often takes a significant amount of time. As my most extreme example, I once helped a developer whose iOS app was hanging after being in the foreground CONTINUOUSLY (it was an iPad kiosk app) for 6-8 months.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

There were .diag files in the sysdiagnose, which showed the crash message. The other one I was looking at, which was closer to 100k, had been alive for 40 seconds, based on top.txt.

There were .diag files in the sysdiagnose, which showed the crash message. The other one I was looking at, which was closer to 100k, had been alive for 40 seconds, based on top.txt.

The second sysdiagnose might actually be your best data point. Leaking at the kind of rate requires your app to have been doing "something" quite frequently, and if it was running when the sysdiagnose was captured, there's a good chance the spintrace captured it. Open the sysdiagnose and look for the file named "spindump-nosymbols.txt". If you're not familiar with the format, inside you'll find a long list of entries which look something like this (this is from an iOS, but the format is the same):

Process:          com.apple.WebKit.WebContent (WebContentExtension) [755]
UUID:             D36E12E9-BE53-345F-BA95-69ABE5388F5C
Path:             /private/preboot/Cryptexes/OS/System/Library/ExtensionKit/Extensions/WebContentExtension.appex/com.apple.WebKit.WebContent
Identifier:       com.apple.WebKit.WebContent
...
Memory Limit:     1536MB
Jetsam Priority:  100
Footprint:        194.63 MB
Time Since Fork:  807s
Num samples:      8 (1-8)
CPU Time:         0.003s (1895.2K cycles, 963.8K instructions, 1.97c/i)
Num threads:      3
Note:             1 idle work queue thread omitted

...

  Thread 0x9450    Thread name "JavaScriptCore libpas scavenger"    8 samples (1-8)    priority 37 (base 37)    cpu time 0.002s (1403.3K cycles, 784.7K instructions, 1.79c/i)
  8  ??? (libsystem_pthread.dylib + 2252) [0x1fb7228cc]
    8  ??? (libsystem_pthread.dylib + 17444) [0x1fb726424]
      6  ??? (JavaScriptCore + 55864) [0x1b54dea38]
        6  ??? (libsystem_kernel.dylib + 26068) [0x24833f5d4]
         *6  ??? (pthread + 18508) [0xfffffff00a75e17c]
      2  ??? (JavaScriptCore + 56084) [0x1b54deb14]
        2  ??? (libsystem_kernel.dylib + 26068) [0x24833f5d4]
         *2  ??? (pthread + 18508) [0xfffffff00a75e17c]

  Binary Images:
...

The stack above is a "spintrace". What's going on here is that the system captured the state of every process’s stack a fixed number of times (Num samples -> "8") and the spintrace format then consolidates those samples into a condensed format to show you what the thread was actually doing in those samples. So, this is the thread entry point:

  8  ??? (libsystem_pthread.dylib + 2252) [0x1fb7228cc]
    8  ??? (libsystem_pthread.dylib + 17444) [0x1fb726424]

...and the "8" means that function was present in 8 samples (in this case, "all" of them). Then the execution flow "split", so that in 6 samples the thread was doing this:

  6  ??? (JavaScriptCore + 55864) [0x1b54dea38]
	6  ??? (libsystem_kernel.dylib + 26068) [0x24833f5d4]
	 *6  ??? (pthread + 18508) [0xfffffff00a75e17c]

And in two samples it was doing this:

  2  ??? (JavaScriptCore + 56084) [0x1b54deb14]
	2  ??? (libsystem_kernel.dylib + 26068) [0x24833f5d4]
	 *2  ??? (pthread + 18508) [0xfffffff00a75e17c]

You'll note the "*" next to two numbers. That indicates that this thread was not actively executing at the time the spintrace was captured. That's actually the common case (there are a lot more threads than cores), but you can actually see two different variations at the "end" of the stack. The case above is the most common case, which indicates that the thread was blocked in the kernel waiting on "something". However, the other cases you might see are:

  *8  ??? (<94145C7E-F836-38C1-A6BA-1F2984CA2D7D> + 84104) [0xfffffff007f70888]
	*8  ??? (<94145C7E-F836-38C1-A6BA-1F2984CA2D7D> + 86648) [0xfffffff007f71278] (running)

...which means "this thread was CPU bound and eligible to run when the trace was captured, but wasn't actually running at the time it was captured.

And finally the least common, as there are lots of threads and only so many cores):

  *1  ??? (CoreSymbolication + 154068) [0x1f5db09d4]
	*1  ??? (CoreSymbolication + 157500) [0x1f5db173c] (running)

...which means that particular thread was actively executing when the trace occurred.

Finally, the "Binary Images" section has the list of libraries and load addresses, which mean you can symbolicate the data using the process described in "Adding identifiable symbol names to a crash report".

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

I worked in CoreOS for a while, I'm good with spindump files. 😄

It's almost 8pm here, so i'll look at it tomorrow.