Logging from NetworkExtension

It’s hard to say what’s going on here, but the example you posted shows a couple of things that I don’t recommend:

• Rather than tag your log entries within the format string, it’s better to create a custom log object and tag them via its subsystem and category properties.

• os_log (and Logger) work best if you use them directly. Your String(describing: msg) construct suggests that you’ve wrapped it, which undermines the optimisations it does behind the scenes [1].

As to why your log entries aren’t being collected, my suggestions are:

• Use a custom log object rather than OSLog.default. The latter is heavily used and it’s easy to imagine the system purging those log entries sooner.

• Make sure you log entry’s use an appropriate type.

The system should then give your log entries the same priority as those from the other subsystems you mentioned.

Can I make it log all the time without exceptions?

On macOS you can configure logging from both the command line (using log config) and via a configuration profile (via the com.apple.system.logging payload). The former is a non-starter on iOS. The latter works on iOS but I’ve only tried it using profiles that were signed by Apple (downloaded from Bug Reporting > Profiles and Logs). I’m not aware of any way to make it work with non-Apple profiles.

Share and Enjoy
—
Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

[1] When you log a string like this:

logger.log("did receive \(123) bytes")

the resulting log entry doesn’t include the format string [2]. Rather, the logging system records:

• The UUID of the Mach-O image doing the logging.

• An short identifier for the format string within that image.

• The parameters, that is, the 123.

This helps to keep log entries small.

In contrast, if you log like this:

let message = "did receive \(123) bytes"
logger.log("\(message)")

The log entry includes a copy of message, which is much bigger.

[2] I’m using the new Logger API here but the the same logic applies to the older APIs.

but not my custom logs made with os_log. My logs appear only around the time I unlock the phone. Is it expected behaviour? Can I make it log all the time without exceptions?

What OSLogType are you using here? Are you using .info or .debug? If you are using .info then I would try .debug for development only debug scenarios. In an example, I created a NEDNSProxyProvider in iOS and created a log that looked like this:

os_log("[NEDNSProxyProvider] provider will handle new flow, flow: %{public}@", type: .debug, flow.description)

Then moved into the background without Xcode attached and put the device to sleep. I watched the logs slowly trickle in from the Console.app when using .debug.

Matt Eaton
DTS Engineering, CoreOS
meaton3@apple.com

I was using .info, now changed to .debug. But I have found another "interesting" thing - some messages are visible when looking at them in real-time in console app, but then disappear when I get logs using sudo log collect --device-name .... The only difference is that they are thrown using additional abstraction in code. Example:

func log1(message) {
 os_log(...)
}

func log2(message) {
  log1(message)
}

log1("message") // Is visible on-line and after retrieving log from device
log2("message") // Is visible only while looking at it on-line, through console app connected to the phone, but NOT when using log collect

PS. I know it's better to use os_log directly, but there are 3rd party libraries and other stuff involved, so we have what we have.

I’m not aware of any way to make it work with non-Apple profiles.

I wasn’t happy with that response so I raised this issue with the OSLog team. They pointed me to something I didn’t know about, namely the OSLogPreferences property for your Info.plist. You can read more about this in the os_log(5) man page.

Just to be sure that this works on iOS, I created a tiny test project to exercise it. In my code I set up two log objects:

let logWaffle  = Logger(subsystem: "com.example.apple-samplecode.Test702941", category: "waffle")
let logVarnish = Logger(subsystem: "com.example.apple-samplecode.Test702941", category: "varnish")

Note I’m using the new Logger API but that doesn’t change things. This feature works with all the other APIs that funnel through the unified logging system.

I then added a button that logs to each log object:

let nowStr = "\(Date.now)"
logWaffle.log(  "waffle default: \(nowStr), private: \(nowStr, privacy: .private), public: \(nowStr, privacy: .public)")
logVarnish.log("varnish default: \(nowStr), private: \(nowStr, privacy: .private), public: \(nowStr, privacy: .public)")

Note how I’m exercising three privacy settings: .auto, .private, and .public.

At this point I ran the app and clicked the button to generate some log entries.

IMPORTANT To run the app:

1. Choose Product > Run.

2. Then Product > Stop.

3. Then run the app from the iOS device’s Home screen.

This is necessary because Xcode customises the system log environment for apps that it runs, but you want to see the standard behaviour.

On clicking my test button I see the following in Console:

type: default
time: 12:26:55.027220+0000
process: Test702941
subsystem: com.example.apple-samplecode.Test702941
category: waffle
message: waffle default: <private>, private: <private>, public: 2022-03-25 12:26:55 +0000

type: default
time: 12:26:55.027328+0000
process: Test702941
subsystem: com.example.apple-samplecode.Test702941
category: varnish
message: varnish default: <private>, private: <private>, public: 2022-03-25 12:26:55 +0000

Both log objects display the same info, with the string redacted in the .auto and the .private cases, which is what you’d expect.

I then added this to my app’s Info.plist file:

<key>OSLogPreferences</key>
<dict>
	<key>com.example.apple-samplecode.Test702941</key>
	<dict>
		<key>waffle</key>
		<dict>
			<key>Enable-Private-Data</key>
			<true/>
		</dict>
	</dict>
</dict>

This unredacts the private data, but only for the waffle category. I ran the test again (using the run-stop-run dance, of course) and now I see this:

type: default
time: 12:11:03.947032+0000
process: Test702941
subsystem: com.example.apple-samplecode.Test702941
category: waffle
message: waffle default: 2022-03-25 12:11:03 +0000, private: 2022-03-25 12:11:03 +0000, public: 2022-03-25 12:11:03 +0000

type: default
time: 12:11:03.947115+0000
process: Test702941
subsystem: com.example.apple-samplecode.Test702941
category: varnish
message: varnish default: <private>, private: <private>, public: 2022-03-25 12:11:03 +0000

As you can see, in the waffle category the string is no longer redacted at all.

In the above I’ve used private data redaction as an example but this property list item gives you access to all the configuration options supported by the unified logging system. The os_log(5) man page has all the details.

Finally, I’ve filed a bug (r. 90831886) to get this info added to the Customizing Logging Behavior While Debugging page, where folks are more likely to find it.

I didn’t test this with an NE provider but I believe it’ll work there as well. Add the property to the provider’s Info.plist, not that of the container app.

Share and Enjoy
—
Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

Can you please take a look at my message right above yours?

I don’t have immediate answers to those questions, and finding them would take more time that I have available for DevForums. I recommend that you open a DTS tech support incident and we can dig into this further in that context.

Share and Enjoy
—
Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"