Normal view

There are new articles available, click to refresh the page.
Before yesterdayMain stream

Writing a third-generation log browser using SwiftUI: 3 Lost memory

By: hoakley
19 July 2024 at 14:30

With a working demo of what I hope will form the basis of a third-generation log browser, it was time to turn that into something useful. My next step with LogUI was to equip it with controls to browse excerpts of any section of the active log on your Mac. In particular, this means setting a time in the past, a period over which to collect and display log entries in its SwiftUI List view, and writing them out to a Rich Text file.

loguiwindow1

This uses a SwiftUI DatePicker to set the date and time of the start of the excerpt, which I’ll consider in detail on Sunday, adds an option to display just a selection of the fields, buttons to get the log extract and to save it to RTF, and moves all the other settings apart from the predicate into the top of the window. It’s already starting to look more like Ulbow.

Time and memory

As I realised in my initial explorations of the OSLog API in macOS, there are only three ways of specifying the starting point of any log extract: relative to the last boot, relative to the latest log entry (thus ‘now’), or at an arbitrary time point between the start and end of the log. There’s no way to specify an end point, and when working forward through the log, that defaults to the latest log entry, which could be days later. Thus, to collect entries between two arbitrary points, you can only specify the start, and stop collecting entries once their timestamp is more recent than the end point. As I pointed out in my initial assessment of using OSLog, you also need to keep a running total of entries, lest they overwhelm the app by the million.

Once I had developed LogUI to collect entries for set time periods after an arbitrary starting point in the past, I used that to estimate the amount of memory required for sample collections of all log entries over a period of one second, for which I also set a maximum of 2,000 entries. When collected in the very recent past, just a few seconds before the latest log entry, that amounted to an average of 30 MB, but from an hour earlier it rose alarmingly to 176 MB.

Using a predicate to restrict the entries collected was highly effective: in one test, using a predicate to include only entries from XProtect Remediator as an example, a 24 hour extract required only 40 MB. Although that might appear impressive in comparison with the results above, my current XProCheck, relying on log show rather than OSLog, uses just over 35 MB total memory to display four full days of log extracts.

With the existing OSLog API, it thus appears that only two use cases work well:

  • all log entries for periods of a few seconds in the very recent past, or
  • a narrow group of log entries, filtered using a suitable predicate, for periods up to many hours.

Even imposing a tight limit on the total number of log entries to be displayed, capturing all log entries just a few minutes into the past results in excessive memory use. In this respect, my original method using the log show command is far superior, as that imposes no memory overhead for extracts obtained from any time in the past, and doesn’t require narrow predicate filtering to control the memory it requires.

Memory not released

Memory limitations of using OSLog are compounded by the observation that the memory that it uses isn’t freed after use. Indeed, it isn’t even released when all the app’s windows are closed. This functions as a memory leak, and my more capable test app quickly consumed more than 1 GB of memory, after starting at only 16.9 MB before obtaining any log extracts.

To assess this further, I used the Memory Leaks feature in Xcode Instruments. Although that surprisingly failed to warn of any memory leak, the chart below shows a typical result.

loguimemoryleak1

For this test, I opened four windows and left them without log extracts. I set each to capture and display a different log extract of 1.0 seconds duration, or a maximum of 500 entries, from about an hour earlier. I then fetched the log extract for each window in quick succession. Each extract resulted in memory allocation by OSLog of more than 210 MB, rising in steps until the app was using just over 1 GB in total.

I then closed each window in turn, releasing just a few MB each time, to a final memory use of just under 1 GB without any open windows. Leaving the app in that state for an hour didn’t result in any further reduction in its memory use, which was only released when the app was quit.

I therefore believe that memory used by the logging system in OSLog isn’t currently being released after use, and will shortly be reporting this to Apple in Feedback.

Conclusions

  • OSLog needs an additional means of setting a time window for log collections.
  • Currently, OSLog only supports a narrow range of use cases.
  • The log show command remains far superior to OSLog in its capabilities and resource use.
  • The logging system fails to release memory correctly, resulting in a memory leak that severely limits its usefulness.
  • Nearly five years after its introduction, OSLog is still not suitable as a replacement for log show.

As a result, I have put this project on hold pending solutions to these problems. Ulbow already performs better than LogUI ever could.

Previous articles

Writing a third-generation log browser using SwiftUI: 1 Getting log entries
Writing a third-generation log browser using SwiftUI: 2 Displaying log entries

Writing a third-generation log browser using SwiftUI: 2 Displaying log entries

By: hoakley
16 July 2024 at 14:30

In the first article explaining how I’m developing my third-generation log browser, I considered how it obtains its log entries using the OSLog API in macOS. Those end up in a structure containing the individual contents of each of the fields in a log entry. Here I explain how those entries are displayed to the user, with SwiftUI.

There are several options for displaying log entries. Console adopts a column view that really doesn’t work well even on a 27-inch display.

logui00

Experience developing Ulbow has shown that use of semantic colour to distinguish fields in log entries is superior.

ulbow1b103

Rather than confine fields to columns of even width, and leave several of them empty according to the fields used in that type of log entry, I have therefore opted for a display based on that in Ulbow.

logui01

This is most effective in Dark mode.

Styled text

It’s common for log browsers like Ulbow to be called on to display thousands of log entries, even when predicates are used by experts. Ulbow accomplishes that using the building block for Rich Text, NSAttributedString. Each field has a colour attribute applied to it, and those are appended to one another to build the line representing each log entry. Those lines are then appended to one another to assemble the full NSAttributedString to be displayed in the text scroller forming the lower section of Ulbow’s document window, using AppKit.

The equivalent using SwiftUI uses the almost identically named AttributedString, then displayed as a Text view in a SwiftUI Scroller.

My first experiment was therefore to repeat the same process using AttributedStrings instead of NSAttributedStrings. In code:
let theProcess = self.setAttrStr(string: (log.process + " "), color: NSColor.green)
theLineStr.append(theProcess)

becomes
var theProcess = AttributedString(log.process + " ")
theProcess[AttributeScopes.AppKitAttributes.ForegroundColorAttribute.self] = .green
theLineStr.append(theProcess)

to colour the Process name in green and append it to the log entry.

Working entirely using the newer AttributedString, this proved unusable. Even displaying just a couple of hundred log entries in a single AttributedString took several seconds, and when there were 1,000 or more the whole window was unusable after taking 15 seconds to open.

loguiTextASRun

When assessed using Instruments, a small test log excerpt took over 1.6 seconds to open, little of that taken by the view itself, but much of that period apparently being used by the CPU, presumably handling the AttributedString.

The code was refactored to compare the following variations:

  • creating the AttributedString one field at a time, appending those in a single entry into one Attributed String, then appending that to the whole AttributedString to be displayed;
  • creating an NSAttributedString for each entry, converting that to an AttributedString, then appending that to the whole AttributedString to be displayed;
  • creating each entry as an NSAttributedString, appending those into a single NSAttributedString, and converting that into an AttributedString for display.

There was no significant difference in their performance, so I abandoned further attempts to display log entries as styled text in a SwiftUI Text Scroller.

Styled list

The other obvious choice for display of log entries is SwiftUI’s List, as I had already used in less demanding lists such as that in Unhidden. This approach iterates through each log entry when building the view, styling each field as it goes, for example in:
if !line.process.isEmpty {
if #available(macOS 14.0, *) {
Text(line.process)
.foregroundStyle(.green)
} else {
Text(line.process)
.foregroundColor(.green)
}}

This has to contain two alternative calls to set the foreground colour of the text, as foregroundStyle() is required for macOS 14 and later, while foregroundColor() is required in older versions of macOS. Unfortunately, because of its rapid change, SwiftUI is riddled with such version conflicts.

To my surprise, this List approach performed much better than using AttributedString, and windows typically open in less than a second even when there are more than 1,000 log entries to be displayed.

loguiListRun

This is demonstrated again by Instruments, here opening a log window of the same size as shown above for the Text Scroller implementation. The whole process took 0.44 seconds, most of which was in handling the view. Memory use was also substantially less than for AttributedString. This scales well, with 10,000 log entries remaining brisk, and even 20,000 being perfectly usable.

This is how log entries are displayed in LogUI (to rhyme with doggy), available as a notarized app from here: logui01

Source code for the List view is given in the Appendix at the end of this article.

Copy and save

Unlike similar views in AppKit, List views have little or no intrinsic support for common features, such as selection and copying of content, or saving in Rich Text format, a feature that also appears to have been omitted from AttributedString, although there’s helpful support provided for NSAttributedString.

Having proved the concept of obtaining log entries using OSLog rather than the log show command, and displaying those entries in a SwiftUI List view, I’m now refactoring this into a document-based app, which should at least facilitate saving log extracts in Rich Text format.

Reference

SwiftUI List view in Apple Developer Documentation

Appendix: Source code

struct ContentView: View {
    @State private var messageInfo = Logger()
    
    var body: some View {
        let _ = messageInfo.getMessages()
        if (self.messageInfo.logList.count > 0) {
            VStack {
                List(self.messageInfo.logList) { line in
                MessageRow(line: line)
                }
            }
            .frame(minWidth: 900, minHeight: 200, alignment: .center)
        } else {
            Text("No results returned from the log for your query.")
                .font(.largeTitle)
        }
    }
}

struct MessageRow: View {
    let line: LogEntry

    var body: some View {
        HStack {
            Text(line.date + "  ")
            if #available(macOS 14.0, *) {
                Text("\(line.type)")
                    .foregroundStyle(.red)
            } else {
                Text("\(line.type)")
                    .foregroundColor(.red)
            }
            if !line.activityIdentifier.isEmpty {
                Text(line.activityIdentifier)
            }
//          etc.
            Text(line.composedMessage)
            }
        }
    }

Writing a third-generation log browser using SwiftUI: 1 Getting log entries

By: hoakley
15 July 2024 at 14:30

The most difficult feature of macOS is getting to grips with its log. I know developers of the highest calibre and advanced users who simply can’t make any sense of it, and I’ve heard of researchers who’d rather disassemble code than try reading the log.

My first attempt to open access to the Unified log was an AppleScript-based app named LogLogger, released here a month after Apple unleashed the new log system on us in Sierra, nearly eight years ago.

loglogshot3

That developed into Consolation, written in Swift 3 and released in its first beta four months later.

consolscript20

With Consolation in version 3, at the end of 2019, I released the first beta of Ulbow, with its cleaner interface, filters and colour formatting of log entries, the second generation.

ulbow1b103

Over those years, each app has relied on calling the log show command and parsing resulting extracts in JSON. This is largely because Apple didn’t provide an API with direct access to read the Unified log until macOS Catalina five years ago. That API is Spartan in comparison with the riches of log show, and appears to be little-used or exemplified. The time has come now to switch from parsing JSON to grappling direct with macOS, in a third generation of log utilities based on OSLog.

Get log entries with OSLog

On the face of it, getting entries from the log is straightforward using OSLogStore.getEntries(). This takes two important parameters: an OSLogPosition indicating the starting point for the sequence of entries, and an NSPredicate to be used to filter those entries. An outline sequence of calls is:
let store = try OSLogStore.local()
to select the local active log store, rather than a logarchive saved previously.
entries = try store.getEntries(with: [], at: secsInterval, matching: pred)
where secsInterval is an OSLogPosition and pred is an NSPredicate, or nil to fetch all log entries. This returns a sequence of OSLogEntry entries.

A quick glance at the documentation for OSLogEntry, though, shows that it contains only three fields out of the many accessible in each log entry:

  • composedMessage, a string containing the message field for that entry
  • date, a Date containing the timestamp of that entry
  • storeCategory, an enumeration setting how long that entry should be retained in the log.

It looks as if OSLog provides only very basic access to the log, until you consider the other classes descended from OSLogEntry. Together with two protocols, these actually expand to support five different types of log entry, of which three contain many fields. This is because different classes of log entry contain different fields, as shown in the diagram below.

logentries1

In any sequence of entries, most will be OSLogEntryLog, with many Signposts of OSLogEntrySignpost class holding 15 fields in all. OSLogEntryBoundary are least frequent, and only likely to be encountered in the announcement at the start of the kernel boot process.

To separate these out from the sequence of entries returned by OSLogStore.getEntries(), you therefore have to determine which class each entry belongs to, with code such as
for ent in entries {
if let log = ent as? OSLogEntryLog {

// process OSLogEntryLog class
} else if let log = ent as? OSLogEntryActivity {
// process OSLogEntryActivity (Activity) class
}
and so on.

To store extracted field data for each log entry, I thus create a LogEntry structure with a variable to contain data for each of the fields available, and each entry is used to complete one of those structures in a sequence. That and my code are provided in the Appendix at the end of this article.

Time period

The next challenge in accessing the log using OSLog is specifying the time period for which you want entries. This appears enigmatic as OSLogStore.getEntries() doesn’t allow you to specify two time points, merely a location in the log as an OSLogPosition, which comes in three flavours:

  • a specified date and time point
  • a time interval since the latest log entry
  • a time interval since the last boot

Using any of those three, passed as a parameter to OSLogStore.getEntries(), entries will continue until they reach the end of the log. To illustrate how to use these in practice, here are two examples.

If you want log entries between 04:31:15 and 04:32:30, you can obtain the OSLogPosition for 04:31:15, getEntries() using that, check the timestamp on each log entry until the first for 04:32:30 appears, then return out of the iteration. Alternatively, you could set the OSLogPosition at the end and use the OSLogEnumerator.Options to iterate in reverse (although others have reported that doesn’t work).

If you want the last 12 seconds of log entries, you can set the TimeInterval since the latest log entry to -12.0 seconds, and use the OSLogPosition to start iterations 12 seconds ago. Here you’ll want to keep track of the total entries returned and perhaps limit that to 1,000 or 10,000, or your code might blow up somewhere, and that’s simple to do using a loop count and return.

Predicates

Those difficulties pale in comparison to the last of the parameters to OSLogStore.getEntries(), the predicate. This is simplest when you want all entries, as you then pass nil. For this article, I’ll give the next simplest solution, a single predicate specifying the subsystem. This can be generated using
let pred = NSPredicate(format: "subsystem == %@", predicate)
where predicate is a String containing the name of the subsystem, such as com.apple.Bluetooth.

LogUI

I have now wrapped this in a simple SwiftUI interface as a demonstration, in LogUI (to rhyme with doggy), available as a notarized app from here: logui01

logui01

This gives you control over three parameters:

  • a subsystem to use as a predicate
  • the number of seconds to go back from the current end of the log, to start collecting from, as explained above
  • the maximum number of log entries to display

as configured in its Settings. Its single-page Help file explains the colour code used to display extracts.

In the next article I’ll consider how best to display log extracts using SwiftUI, and how I arrived at the solution in LogUI.

Reference

OSLog, Apple Developer Documentation

Appendix: Source code


struct LogEntry: Identifiable {
    let id = UUID()
    var type: Int = 0
    var activityIdentifier: String = ""
    var category: String = ""
    var composedMessage: String = ""
    var date: String = ""
    var level: String = ""
    var parentActivityIdentifier: String = ""
    var process: String = ""
    var processIdentifier: String = ""
    var sender: String = ""
    var signpostIdentifier: String = ""
    var signpostName: String = ""
    var signpostType: String = ""
    var storeCategory: String = ""
    var subsystem: String = ""
    var threadIdentifier: String = ""
}
    func getMessages() -> Bool {
       var predicate = UserDefaults.standard.string(forKey: "predicate") ?? ""
       let period = UserDefaults.standard.string(forKey: "period") ?? "-5.0"
       let maxCount = UserDefaults.standard.string(forKey: "maxCount") ?? "1000"
       let theMaxCount = Int(maxCount) ?? 1000
       var theSecs = Double(period) ?? -5.0
       if theSecs > 0.0 {
           theSecs = -theSecs
       }
       let dateFormatter = DateFormatter()
       dateFormatter.dateFormat = "yyyy-MM-dd HH:mm:ss.SSSZ"
       do {
            let store = try OSLogStore.local()
            var theCount = 0
            let secsInterval = store.position(timeIntervalSinceEnd: theSecs)
            var entries: AnySequence<OSLogEntry>
            logList = []
            if !predicate.isEmpty {
                let pred = NSPredicate(format: "subsystem == %@", predicate)
                entries = try store.getEntries(with: [], at: secsInterval, matching: pred)
            } else {
                entries = try store.getEntries(with: [], at: secsInterval, matching: nil)
            }
            for ent in entries {
                var theLineEntry = LogEntry()
                if let log = ent as? OSLogEntryLog {
                    theLineEntry.type = 1
                    theLineEntry.category = log.category
						 // etc.
                } else if let log = ent as? OSLogEntryActivity {
						 // etc.
                } else {
                    let log = ent as OSLogEntry
                    theLineEntry.type = 10
                    theLineEntry.composedMessage = log.composedMessage
                    theLineEntry.date = dateFormatter.string(from: log.date)
                    theLineEntry.storeCategory = "\(log.storeCategory.rawValue)"
                }
                if (theLineEntry.type != 4) && (theLineEntry.type != 0) {
                    logList.append(theLineEntry)
                    theCount += 1
                }
                if theCount > theMaxCount {
                    return true
                }
            }
            return true
        } catch {
            return false
        }
    }

❌
❌