Question about system logs

[felix91gr]

Hi Tony and others (if there are) ^^

I'm helping at the langserver-swift project and we'd like to have some cross-platform logging. And since I know for a fact that TraceLog does work on both Darwin and Linux, I'm thinking it might be the perfect tool for the job.

Yesterday when we were talking about this, Ryan said that we should be outputting the log messages to Unified logging on Darwin and to the systemd logging journal on Linux. I think that's reasonable. Is is possible to configure TraceLog to do that? I know close to nothing about system logs so please forgive me if I'm noobing too much here. I know I probably am :sweat_smile:

[tonystone]

@felix91gr CVaListPointer is actually a wrapper around an actual va_list pointer. The swift function withVaList handles turning an array of types that are convertible to Swift CVarArgs into a va_list and returning a pointer to it. This is why it's in a function, withVaList holds onto the va_list until the block completes execution.

See VaArgs.swift for a list of types that are convertible. They are all the types you may expect.

[felix91gr]

I see. Wow, that's actually real nice. I like the fact that the va_lists are generated from the language itself. Generating them by hand seems real hard, not to say prone to errors.

I'd say it's settled, then. We should use your solution with va_lists, using exclusively Swift. It looks like it will be very elegant as well :)

I really shouldn't be programming (until I hand in my assignment), so should I leave the rest to you? I can however answer your questions regarding SPM cross-platform features. We shouldn't need to create a special Swift Package for the Linux's OSWriter. If you need help with the details, @.me here :)

[tonystone]

I actually have to get some paid work done as well @felix91gr but I'll jump on it when I have a few minutes. This is actually going to be nearly identical to the OSLogWriter I just wrote except for replacing the actual line that logs with the 2 lines above. What I could really use your help on though is writing tests for both of the writers. Not sure how we're going to approach that given we have outside systems to deal with.

Thoughts on testing?

[felix91gr]

What I could really use your help on though is writing tests for both of the writers. Not sure how we're going to approach that given we have outside systems to deal with.

Mm, that's a good point. I think that as a start we could query the console output of consulting the OS' log journal. For example, in Linux that command is `journalctl -n '. Then some regex matching or so could help finding exactly what you're looking for. But I think there are better, less brute-forcy methods and APIs, to do that.

I don't know of any APIs (should investigate), but @RLovelett seems to know of this topic. I think you can, at the very least, ask for a JSON representation of the data stored in a particular log entry. Ryan, how callable would that be from Swift?

[tonystone]

@RLovelett, I have a rough version of the writer complete and was implementing tests and now have a question that you may be able to help with.

For the test in XCTest I currently get the following which is indicating the SYSLOG_IDENTIFIER.

{
    "__CURSOR" : "s=1ebc898cc600435393df9b5d0c7b05d9;i=3c0;b=6791071bedd5489a9ff327ece2ac78c0;m=c1f676922;t=56d73908ed02b;x=67a148272268275b",
    "__REALTIME_TIMESTAMP" : "1527717997498411",
    "__MONOTONIC_TIMESTAMP" : "52066478370",
    "_BOOT_ID" : "6791071bedd5489a9ff327ece2ac78c0",
    "_TRANSPORT" : "journal",
    "_MACHINE_ID" : "8d4eadeb9ee9f4632342b055599cdf6b",
    "_HOSTNAME" : "vagrant",
    "_AUDIT_LOGINUID" : "1000",
    "_GID" : "1000",
    "_CAP_EFFECTIVE" : "0",
    "_SYSTEMD_OWNER_UID" : "1000",
    "_SYSTEMD_SLICE" : "user-1000.slice",
    "_UID" : "1000",
    "MESSAGE" : "Test Message",
    "PRIORITY" : "3",
    "_AUDIT_SESSION" : "18",
    "CODE_FILE" : "TestFile",
    "CODE_LINE" : "10",
    "CODE_FUNC" : "TestFunction",
    "SYSLOG_IDENTIFIER" : "TraceLogJournalWriterPackageTests.xctest",
    "_COMM" : "TraceLogJournal",
    "_EXE" : "/vagrant/.build/x86_64-unknown-linux/debug/TraceLogJournalWriterPackageTests.xctest",
    "_CMDLINE" : "/vagrant/.build/x86_64-unknown-linux/debug/TraceLogJournalWriterPackageTests.xctest",
    "_SYSTEMD_CGROUP" : "/user.slice/user-1000.slice/session-18.scope",
    "_SYSTEMD_SESSION" : "18",
    "_SYSTEMD_UNIT" : "session-18.scope",
    "_PID" : "3658",
    "_SOURCE_REALTIME_TIMESTAMP" : "1527717997498263"
}

This field can be user defined and it may make sense to use something like:

"SYSLOG_IDENTIFIER" : "Users-tag-passed-to-tracelog"

Is it helpful/required to set the SYSLOG_IDENTIFIER=?

[tonystone]

@felix91gr and @RLovelett, the systemd journal writer is essentially done and tested.

You can find it in tracelog-journal-writer.

It can be used in beta form to test if you link to the master branch. I still have to create documentation and the readme though and it may need a few refinements.

Note: I chose to keep it out of the main repo because I didn't want to force Linux users who may not want the journal writer to have to install libsystemd-dev.

[RLovelett]

Sorry for the delayed response. :disappointed:

Is it helpful/required to set the SYSLOG_IDENTIFIER=?

I've never explicitly set had to set the identifier before. It's always been one of those things that seems to be correctly set for me. Usually, that identifier is just the executable's name.

Is it helpful? Immensely. :smile: Or at least, to me in my workflow. The way I typically use it is in filtering the logs. Something like, journalctl --identifier=STRING where STRING are the entries with the specified syslog identifier.

The tl;dr is that in my experience the identifier is automatically set and that the identifier is the executable's name. If at all possible we should probably keep that the default.

WARNING: This next bit is off the cuff, stream of consciousness thought here. Though I've never done it before, having the ability to manually configure the syslog identifier could have a benefit. os_log has a cool feature where you can specify a subsystem and category. So you can filter for, lets say all langserver-swift (subsystem) messages that have to do with SourceKit (category). Perhaps by allowing explicit setting of the syslog identifier we could achieve a similar API.

systemd journal writer is essentially done and tested

:tada: Amazing stuff. I've recently fallen into this issue and am working through it on the lldb-dev mailing lists.

Hopefully sometime tomorrow or this weekend I'll get to integrate this to langserver-swift (if @felix91gr does not beat me to it).

[tonystone]

WARNING: This next bit is off the cuff, stream of consciousness thought here. Though I've never done it before, having the ability to manually configure the syslog identifier could have a benefit. os_log has a cool feature where you can specify a subsystem and category. So you can filter for, lets say all langserver-swift (subsystem) messages that have to do with SourceKit (category). Perhaps by allowing explicit setting of the syslog identifier we could achieve a similar API.

@RLovelett take a look at the syslog-identifier branch. If you believe this is the correct implementation I'll merge it to master.

Note: I still need to add tests for it.

I also added TraceLogs tag as a custom field.

[tonystone]

Just tagged 2 releases of tracelog-journal-writer for you guys:

• 1.0.0-beta.1 is the original release without the SYSLOG_IDENTIFIER.
• 1.0.0-beta.2 Contains the identifier and the extra TraceLog TAG.

Just an update on the Unified Logging writer, it is done as well but I'm having an issue testing. Apple's log show command which I need for testing, can't seem to read the message correctly although on the Console, the message displays fine. It also can't seem to always see the file, line, and func.

Here is the output from the first and second test statements. Note the first is perfect, the second is missing the file, line, and func information as well as having the message return <decode: mismatch for [%s] got [OBJECT public sz:52]>. All subsequent messages after the first are like that in the output of log show but the same messages are fine in the console so I know the messages are correctly sent (or I think I know).

Note: I'm using the correct format specifier of "%{public}@", see radar.

{
"traceID" : 486426555318276,
"messageType" : "Default",
"eventType" : "logEvent",
"signpostID" : 0,
"source" : {
"symbol" : "OSLogWriter.log(_:level:tag:message:runtimeContext:staticContext:)",
"line" : 75,
"image" : "TraceLog",
"file" : "OSLogWriter.swift"
},
"activityIdentifier" : 0,
"subsystem" : "tracelog",
"category" : "TraceLog",
"threadID" : 5564306,
"senderImageUUID" : "139D171A-4575-3F80-AD23-53BE99AFFFAF",
"processImagePath" : "\/Users\/tony\/Library\/Developer\/Xcode\/DerivedData\/TraceLog-czvmcvbporozzmdszsiflqutdobk\/Build\/Products\/Debug\/TraceLog-OSX.app\/Contents\/MacOS\/TraceLog-OSX",
"senderImagePath" : "\/Users\/tony\/Library\/Developer\/Xcode\/DerivedData\/TraceLog-czvmcvbporozzmdszsiflqutdobk\/Build\/Products\/Debug\/TraceLog-OSX.app\/Contents\/Frameworks\/TraceLog.framework\/Versions\/A\/TraceLog",
"timestamp" : "2018-05-31 09:23:05.877593-0700",
"machTimestamp" : 356862417521976,
"eventMessage" : "TraceLog Configured using: {\n\tglobal: {\n\n\t\tALL = TRACE4\n\t}\n}",
"processImageUUID" : "3AC1E373-6E88-37C1-A876-229B3634C24D",
"processID" : 3477,
"senderProgramCounter" : 82132,
"parentActivityIdentifier" : 0,
"timezoneName" : ""
},{
"traceID" : 18198987162992115716,
"messageType" : "Default",
"eventType" : "logEvent",
"signpostID" : 0,
"source" : {
"symbol" : "",
"line" : 0,
"image" : "",
"file" : ""
},
"activityIdentifier" : 0,
"subsystem" : "tracelog",
"category" : "OSLogWriterTests",
"threadID" : 5564295,
"senderImageUUID" : "D05BF0B9-A097-30A2-9755-2CACDF1F7028",
"processImagePath" : "\/Users\/tony\/Library\/Developer\/Xcode\/DerivedData\/TraceLog-czvmcvbporozzmdszsiflqutdobk\/Build\/Products\/Debug\/TraceLog-OSX.app\/Contents\/MacOS\/TraceLog-OSX",
"senderImagePath" : "\/Users\/tony\/Library\/Developer\/Xcode\/DerivedData\/TraceLog-czvmcvbporozzmdszsiflqutdobk\/Build\/Products\/Debug\/TraceLog-OSX.app\/Contents\/PlugIns\/TraceLog-OSX-Tests.xctest\/Contents\/MacOS\/TraceLog-OSX-Tests",
"timestamp" : "2018-05-31 09:23:06.172104-0700",
"machTimestamp" : 356862712032552,
"eventMessage" : "<decode: mismatch for [%s] got [OBJECT public sz:52]>",
"processImageUUID" : "3AC1E373-6E88-37C1-A876-229B3634C24D",
"processID" : 3477,
"senderProgramCounter" : 4237250772,
"parentActivityIdentifier" : 0,
"timezoneName" : ""
}

Perhaps I have some kind of issue with my machine.

---

Update: I found that log stream displays the json correctly, unfortunately, I don't think I can use the stream version to test with.

[felix91gr]

Edit: nevermind the following, I answered thinking that you were having problems with the tracelog-journal-writer

Update: I found that log stream displays the json correctly,

Hum. Lemme think. Have you tried logging the exact same SYSLOG_IDENTIFIER that is logged by default? Maybe there's some sort of issue with the encoding, like a missing "\0" somewhere or something like that.

I will see if I can test it.

unfortunately, I don't think I can use the stream version to test with.

You mean that this is untestable from Swift? Yeah, that's probably right (or maybe it's doable, but very hard). I think that as a plan B or C we could just have a testing python or bash script for the OSLoggers, if we ultimately don't figure out a way of testing it on Swift. That's not great, but better than nothing.

[felix91gr]

I posted an issue at the tracelog-journal-writer repo about some tests that are failing :)

[tonystone]

@felix91gr & @RLovelett, I have good and bad news about a Unified Logger.

The good news: I worked through the issue of not being able to see the messages in the logs using log show. We have a writer.

The bad: os_log, at the moment, cannot capture source, line, and function if wrapped in any type of wrapper. This means no logging system can capture that information if wrapping os_log.

os_log is currently written so it uses the #dsohandle and locates the direct calling method and will always report that information.

I discovered this through various methods including testing myself, radar bugs requesting this be opened up, and the code itself. If you look at the code for os_log.m you notice an _os_log_pack_fill call which actually uses the dsohandle to get the information for source, line, and function.

So the bottom line, we have a Unified Logger implementation but it won't capture the file, line, and function and no implementation will be able to at the moment unless Apple opens that up. There is at least one open radar (35958308) requesting this that I know of.

So the options I see for langserver-swift are:

1. Use TraceLog to abstract all logging but on Apple using Unified Logging, you lose the file, line, function.

   logTrace { "My message" }

2. Use direct calls everywhere in the code to os_log but surround them in #if os() statements.

   #if os(maxOS)
       os_log("%{public}@", log: log, type: OSLogType.default, "My message")
   #else
       // Log to TraceLog for all other platforms or log to specific loggers for each.
      logTrace { "My message" }
   #endif

[felix91gr]

I'm the one who has used logs the least of us, so this is definitely Ryan's call.

Whichever you choose @RLovelett, I can start getting the TraceLog calls in there and then if in the end you prefer the #if, #else, #endif mechanism, we can start putting those in after the right call places have been decided and put in practice :)

---

Also, and this is just off the cuff... maybe not fully possible or feasible: what if we use Sourcery? Sourcery isn't yet fully ported to Linux, but on MacOS, where we'd need it, we could use it to replace the TraceLog calls by os_log calls. That would give us a seamless system logging experience.

I haven't used Sourcery myself (I want that Linux port T-T) but many people really like it for metaprogramming. Since it runs before compilation, it could be used to generate the right calls depending on the OS - without the need of an #if, #else, #endif triplet every time you'd want to do a syslog.

Lastly: I originally thought of this as an idea for the langserver-Swift repo, but... maybe it makes more sense in TraceLog? It is, though, something I can't help in (unless you know of a way to get a Darwin VM?), so I don't want to impose my idea on you guys either :)

---

But all in all, it kinda sucks that the os_log API isn't more open >.> Maybe we'll get changes on this announced at WWDC. It would be ideal to be there, to get a word in about this at the labs.

[RLovelett]

Wow. This is a real bummer.

I think we should probably not do the #if #else route at this point. If we do that then we have already lost the nice consistent API that tracelog provides. Which then begs the question what is the point? I have never really made use of the line information from os_log in the language server so it probably won't be a huge loss.

I wonder if this is an issue that should be provided as a Radar to Apple? :man_shrugging:

[tonystone]

@RLovelett, it is a bummer that Apple hasn't opened that up yet. It's definitely not out of the question that they will open it up someday but for now, they seem to be driving you to use their stuff directly.

There is already an open radar (35958308) requesting it be opened up. When I have some free time I will open another as well to show more support for it.

[felix91gr]

@tonystone I have an idea. What if we make the log function @inlinable? Like this:

///
/// Required log function for the `Writer`.
///
@inlinable public func log(_ timestamp: Double, level: LogLevel, tag: String, message: String, runtimeContext: RuntimeContext, staticContext: StaticContext) {
    let log = OSLog(subsystem: self.sybsystem, category: tag)

    os_log("%@", dso: staticContext.dso, log: log, type: convertLogLevel(for: level), message)
}

This is made possible by SE-0193, and seeing this wrapper for SPM I was reminded of it. This should do nothing on Swift 4.1, but from 4.2 onwards, it should work.

I'm thinking that inlining the call to log could make os_log find the correct file, function and line parameters. Maybe it doesn't work; depends on if the inlining happens before or after the evaluation of the system macro.

But regardless, this would also help in general with performance in TraceLog. Being able to inline the logging is actually fantastic, because it helps thin out the module boundary.

Wanna give it a try? With a 4.2 snapshot we can know how it behaves ^^.

[RLovelett]

Not that anyone asked. :smile:

But if that works, I personally would be OK with it. For me, I'm basically assuming that everything before Swift 4.2 is unsupported moving forward. There are just so many language improvements in 4.2 and beyond it's just too much work to support anything older.

That's just one person's opinion though.

[tonystone]

@felix91gr and @RLovelett ,

Ah, good idea but I don't think it will work for several reasons.

1) TraceLog gets compiled as a module, once it's a module, the dso handle of the module will be passed to the os_log function negating anything we do with inline. 2) TraceLog has several layers of calls before actually calling the Writer log method. 3) The loggers get called on background threads and I would expect once it crosses a thread boundary, the func could not be inlined.

That's my initial thoughts, I could put together a quick test module to show this if we still think there is a chance that inlining could work?

[felix91gr]

Those are fair points 🤔. I think I know how to solve at least this one, though:

TraceLog has several layers of calls before actually calling the Writer log method.

We can propagate inlinability. @inlinable public functions together with @usableFromInline internal ones can make inlinability work even through multiple call steps.

[tonystone]

Does that still allow us to make the internal calls "internal" visibility?

[felix91gr]

Yup, that's exactly what it does.

They're still internal (and therefore not visible from outside the module), but they can be inlined if an @inlinable public function that calls them gets inlined 🙂

[tonystone]

Awesome, I love that feature.

I'll put together a little test later this can help us.

[felix91gr]

I love that feature

Me too! I think it's very clever :) Kudos to Slava for making it.

[tonystone]

@felix91gr @RLovelett, it's a no go on using @inlinable to solve the os_log issue. Os_log will capture the immediate caller despite inlining. Here's a little test program you can run to try it out.

Btw: I also tested using #sourceLocation but that only allows literal constents to be passed for file and line. Even with constents passed, os_log still captures the immdiate callers file and line.

[felix91gr]

Oh, well. At least we tried ^^ On second thought, offering this as part of the API's contract would've been unstable: since inlining would've changed the behavior of the os_log function, we would've been using something like a bug, as a feature. So in a way this is actually better.

[tonystone]

@felix91gr @RLovelett, just published release 4.0.0-beta.1 which includes the UnifiedLoggingWriter. It should be ready to go and well tested, I just need documentation at this point. I won't take it out of beta until that is written.

@felix91gr, also added the ability to set the concurrency mode either globally or per writer to allow it to be used in scripts or applications that require real-time logging. To set globally for scripts, just do the following at the top of your main.swift in tracelog-usage.

   TraceLog.configure(mode: .direct, writers: [FileWriter(forFile: "./wololo.txt")!], environment: ["LOG_ALL": "TRACE4"])

   /// Or use

   TraceLog.configure(writers: [.direct(FileWriter(forFile: "./wololo.txt")!)], environment: ["LOG_ALL": "TRACE4"])

You can remove the sleep(1) from the end as well.

[felix91gr]

just published release 4.0.0-beta.1 which includes the UnifiedLoggingWriter. It should be ready to go and well tested,

That's awesome!

I just noticed something: the OS logger for Linux seems to not be there. Do you want me to try to unify them? I can test it here in my machine.

Also, and I remember this was one of your concerns: we can make it so that the sdjournal Writer package only gets downloaded and compiled under Linux. That's something SPM is capable of doing - I can write that if you want :)

also added the ability to set the concurrency mode either globally or per writer to allow it to be used in scripts or applications that require real-time logging.

That looks suuuuper awesoooome :heart_eyes: thank you for making it :slightly_smiling_face:

[tonystone]

I just noticed something: the OS logger for Linux seems to not be there. Do you want me to try to unify them? I can test it here in my machine.

I chose to keep it separate for one primary reason which is that I don't want to force all Linux users to have to install systemd-dev just to use TraceLog. There are many applications that do not have a need for that Writer and just want to link to TraceLog and go.

We can definitely relook at that but I think its a compelling reason to keep it in its own repo.

[felix91gr]

Hmm 🤔 that's a good point.

I still think a common API is worth something. I'm going to think about it for a while, maybe there's some way to use #if canImport(sdjournal) to conditionally compile the OS Writer under Linux. If it can't be imported, I would issue a compile-time #warning or so.

It could also be done with a compile flag. Something like --compile-os-logger=true, which would then let the user know that they're missing that dependency and that they should run apt-get install systemd-dev to have it.

[felix91gr]

I still think a common API is worth something

In this case, if the sdjournal-writer isn't available in the system, TraceLog would issue a compile-time warning and log into a file instead of the OS journal.

[tonystone]

In this case, if the sdjournal-writer isn't available in the system, TraceLog would issue a compile-time warning and log into a file instead of the OS journal.

I don't think that is what people would expect from the library, they would expect the JournalWriter to not to be available if the systemd-dev package is not installed (meaning it was not compiled at all and the symbols to use it are not present). I think that is the preferred behaviour if we are to combine them.

[felix91gr]

Hmm. You're right. I think that's the behavior I'd prefer.

What if the (universal) OSLogger was included by default, but could be omitted with an option? That way, users that don't care about logging to the OS journal could (a) not install systemd-dev if they're on Linux and (b) get a smaller binary everywhere.

---

Edit: I have to leave very soon for a test, I'll be back much later if not tomorrow. Until then :)

[tonystone]

I'm getting a little confused by the names by OSLogger you mean the Systemd Journal Writer?

[felix91gr]

I mean the "unified" system writer:

• UnifiedLoggingWriter under Darwin,
• SDJournalWriter under Linux

[tonystone]

What if the (universal) OSLogger was included by default, but could be omitted with an option? That way, users that don't care about logging to the OS journal could (a) not install systemd-dev if they're on Linux and (b) get a smaller binary everywhere.

Interesting idea let me think about it some more. The Linux users who don't need Journal writer still pay a price for those who do. It just seems more in line to make the excpetion case (using the journal) the one you have to take extra steps for.

[felix91gr]

I was just writing a new issue to discuss this topic. Since this one's already shifted topics at least once, and its original purpose has been fulfilled already (to have cross-platform os logging support from TraceLog), I was thinking that opening a new one and closing this one would be justified. What do you think?

[tonystone]

Agreed! Refer to this one in it.

[felix91gr]

Opened #49, therefore closing this one ^^