Question about system logs
felix91gr opened this issue · 88 comments
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 😅
Hi @felix91gr, langserver-swift looks like a very cool project.
So on logging and TraceLog, yes, TraceLog was designed for use-cases like this, it allows multiple pluggable Writers that write the low-level information to various logging systems, databases, sockets, or whatever you'd like. You can install multiple so it can write the say the console and a file log at the same time. If you install your own writer, this removes the default writer.
The writer interface is straightforward, you basically just have to write the init code (if there is any ) and implement this method.
func log(_ timestamp: Double, level: LogLevel, tag: String, message: String, runtimeContext: RuntimeContext, staticContext: StaticContext)
For os_log you would use the os_log(_:dso:log:type:_:) method directly. The minor complication I see with this (and this would be with all loggers, not just TraceLog) is the #dsohandle, this is an opaque pointer that Apple uses to get the file, line, and func information for the calling context (TraceLog currently uses #file, #func, #line for capturing that). This would need to be passed in from the origin. TraceLog could easily be modified in a non-breaking fashion to capture this. I could do that for you.
The Writer for os_log would be straightforward, really, aside from the method and class declaration itself, just a one-liner. It also would be a worthy addition to TraceLog.
On the systemd journal. This should also be easy also I think there would be a little more to the writer since you would have to set up the address and ports to log to in the init method of your Writer, in the end, the write method would be very simple again. I believe in the shell you would use systemd-cat to log messages, not sure if that or another method is exposed in swift yet, would have to look into this. If it's not it would be a simple matter of creating a modulemap file to expose the C interface to Swift.
Both seem like worthy additions to TraceLog.
Update: I took a few moments to write an os_log writer (OSLogWriter) for TraceLog.
Take a look at branch os-log-writer.
Still need to figure out how to write tests for it and also may need a little cleanup.
This would need to be passed in from the origin. TraceLog could easily be modified in a non-breaking fashion to capture this. I could do that for you.
The Writer for os_log would be straightforward, really, aside from the method and class declaration itself, just a one-liner. It also would be a worthy addition to TraceLog.
Oh my gosh, that would be awesome! Please do 🙏
On the
systemdjournal. This should also be easy also I think there would be a little more to the writer since you would have to set up the address and ports to log to in the init method of your Writer, in the end, the write method would be very simple again. I believe in the shell you would usesystemd-catto log messages, not sure if that or another method is exposed in swift yet, would have to look into this. If it's not it would be a simple matter of creating amodulemapfile to expose the C interface to Swift.Both seem like worthy additions to TraceLog.
I'll look it up too. Let's see what we can find. If you need one, I could lend you a hand for testing this, since I have my Swift sat up on Linux :)
Again. thank you so much for your help 🙇♂️
@felix91gr, would you want to contribute to the systemd Writer? We could work on it together. You have your environment setup, and you are familiar with your particular requirements, so that is a huge plus.
Sure 👍 I'd love to
Useful info for this:
Here's the documentation for logging into systemd.
I'm almost certain that we can't import it directly from Swift like we can import GLibc, but I need to read more on it to be sure. If not, we should make the modulemap.
Edit:
In the future, we might not even need modulemaps, so that'll be a cool day ^^. I don't think that's included in Swift 4.1, but it should be coming up for 4.2 or 5.0 :)
PS: I've had success in writing a logger that outputs logs into a file. Now that I understand that, I see why you chose such a design. Adding the canonical system logs would only require adding like 50 lines or less of Swift code in a new file :)
That does indeed look like the correct calls. In addition, I found this helpful guide "systemd for Developers III", by Pid Eins.
Note that syslog can also be used (syslog is included in GLibc on Linux, see the modulemap for Glibc). The biggest issue I see with this is we would be missing the code file, func, line information which I believe is a show stopper for syslog.
From the sd_journal.h file I believe that the prefered calls for us would be:
int sd_journal_print_with_location(int priority, const char *file, const char *line, const char *func, const char *format, ...)
Since this call contains the priority, file, line, and func which we would like to maintain.
P.S. TraceLog can certainly use a file writer so if you want to make your file work generic and contribute that, it would be a great addition. I could see it requiring the ability to choose a file location and name as well as file rotation and possibly some kind of max space it can take up before it starts to delete files.
I think that syslog is a variadic function. And last time I checked variadic functions are not supported by Swift without some sort of wrapper.
And last time I checked variadic functions are not supported by Swift without some sort of wrapper.
Ah, dammit. That may be why my attempts at making a Swift wrapper aren't working.
We'll need a C wrapper, then. That's not so hard to provide :)
Gimme 10 minutes, I think I know what my code is missing now.
Okay, it's ready. But it still fails. I think it may be because I need to specify a pkgConfig command such that SPM can find the C header in my system.
But for using pkgConfig, the wrapper has to be a System Module package... Anyone here knows how to make one of those? I've tried the official documentation but the exact code posted there doesn't work 🤔
Btw, for accessing systemd on Debian-based Linuxes, this might be necessary:
sudo apt-get install libsystemd-dev
I now just realized that you were talking about syslog. We're trying to work with sd_journal_print, which seems to be the modern replacement for syslog. But nevertheless the problem you pointed at (variadic functions not being accessible) is there. The sd_journal_print function is variadic as well.
And, last answer because I feel like I'm spamming y'all:
From the sd_journal.h file I believe that the prefered calls for us would be:
int sd_journal_print_with_location(int priority, const char *file, const char *line, const char *func, const char *format, ...)Since this call contains the priority, file, line, and func which we would like to maintain.
I'd tend to agree, but I don't think that's the intended usage of that function. If you take a look at the headers, it says: "Used by the macros below. You probably don't want to call this directly.". Can we make-do with sd_journal_print? Since it's part of the official API, we would be better off if we could use it instead.
P.S. TraceLog can certainly use a file writer so if you want to make your file work generic and contribute that, it would be a great addition.
Thanks for the offer! I'd like to do it, but maybe not right now. I have winter holidays in July, and with the break from uni I should be able to dedicate myself to that feature mindfully :)
Otherwise, please feel free to take the current implementation at traceLog-usage and make it complete with things like what you mentioned:
I could see it requiring the ability to choose a file location and name as well as file rotation and possibly some kind of max space it can take up before it starts to delete files.
To which btw, I agree :)
In my opinion, sd_journal_print is insufficient.
For example, let's say you make an executable called example. The only thing it does is log "Hello World".
import Clibsystemd
sd_journal_print_ryan(LOG_NOTICE, "Hello World");Assuming sd_journal_print_ryan is just a wrapped sd_journal_print like so:
#include <systemd/sd-journal.h>
extern inline
int sd_journal_print_ryan(int priority, const char *format) {
return sd_journal_print(priority, format);
}In the log you'll see:
{
"__CURSOR": "s=8f3c919c4ad74561ae7ff7f600b0c2c7;i=12b6a;b=d3f758437aad4cc29fb3a4bd9d25e7e2;m=55739513f8;t=56d2259da3a90;x=23d968a990554398",
"__REALTIME_TIMESTAMP": "1527369187342992",
"__MONOTONIC_TIMESTAMP": "367011369976",
"_BOOT_ID": "d3f758437aad4cc29fb3a4bd9d25e7e2",
"_TRANSPORT": "journal",
"_UID": "1000",
"_GID": "1000",
"_CAP_EFFECTIVE": "0",
"_SELINUX_CONTEXT": "unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023",
"_AUDIT_SESSION": "3",
"_AUDIT_LOGINUID": "1000",
"_SYSTEMD_OWNER_UID": "1000",
"_SYSTEMD_UNIT": "user@1000.service",
"_SYSTEMD_SLICE": "user-1000.slice",
"_SYSTEMD_USER_SLICE": "-.slice",
"_MACHINE_ID": "f039efa85fea4717ab5f8d0fbd83198e",
"_HOSTNAME": "plex.local",
"_SYSTEMD_CGROUP": "/user.slice/user-1000.slice/user@1000.service/dbus.service",
"_SYSTEMD_USER_UNIT": "dbus.service",
"PRIORITY": "5",
"_SYSTEMD_INVOCATION_ID": "f306c6217fa144199a2904e1cd1fe86f",
"MESSAGE": "Hello World",
"CODE_FILE": "/home/rlovelett/Source/example/Packages/Clibsystemd/sd-journal.h",
"CODE_LINE": "5",
"CODE_FUNC": "sd_journal_print_ryan",
"SYSLOG_IDENTIFIER": "example",
"_COMM": "example",
"_PID": "29947",
"_EXE": "/home/rlovelett/Source/example/.build/x86_64-unknown-linux/debug/example",
"_CMDLINE": ".build/debug/example",
"_SOURCE_REALTIME_TIMESTAMP": "1527369187342964"
}Pay attention to CODE_FILE, CODE_LINE and CODE_FUNC none of those are what I would want to see in a Swift program. Perhaps that is just me though.
You're right. We should be using sd_journal_print_with_location or sd_journal_printv_with_location then.
Also, I just realized that sd_journal_printv and sd_journal_printv_with_location are non-variadic. We could call sd_journal_printv directly from Swift and maybe get the CODE_FILE and such parameters correctly captured, or we could use a wrapper around sd_journal_print_with_location that asks por those parameters, like this:
#include <systemd/sd-journal.h>
extern inline
int csd_journal_printv_for_swift(int priority, const char *file, const char *line, const char *func, const char *format) {
return sd_journal_printv_with_location(priority, file, line, func, format);
}And then in Swift we'd then use the compile-time macros, but somehow we'd make them point to the caller's lines and files*:
// Here, I log...
sd_journal_printv_with_location(convertToSystemD(priority), #file, #line, #function, message)* Possibly we'd make that happen with cross-module inlining? I have no idea.
@felix91gr, TraceLog captures #file, #line and #function at the calling object, they simply need to be passed on to sd_journal_printv_with_location. See the StaticContext object. Also look at any one of the method declarations for logging. Tracelog captures the static context of the caller. Btw, the dynamic context is also captured which is the thread and other information about the calling line of code. The basic architecture of TraceLog is TraceLog core captures everything that is needed for logging and trace functionality, the Writers format and write that out to any service that needs them.
Ohhh, I see now. That is awesome :D
Then we just need this System Module to work... I'll investigate a bit more and ask at the forums if I don't manage to make it work.
I'm gonna try and base it off of what IBM has done here: CCurl.
They:
- Made a system module package
- Added code (directly in the
.hfile of the package) to have the API they wanted
(1) is of course what we're trying to have, and (2) allows us to solve the variadic arguments problem.
Okay, I'm done for today. I made it work almost all the way, I think.
Here's the project.
If you want to test it, use the tag 0.6.1
As I put in the release notes, what's missing is basically entering the logs to the system journal.
It compiles, and the same function, when used in a C program, logged my input into the journal with no problem.
So if you guys want to help find what's missing... I'd really appreciate it :)
For now tho, I'm going to sleep ^^
@felix91gr, I was trying this out and received the following, any thoughts?
Compile Swift Module 'TraceLogJournalWriter' (1 sources)
/vagrant/Sources/TraceLogJournalWriter/main.swift:26:1: error: use of unresolved identifier 'csd_journal_print'
csd_journal_print(0, #file, &line, #function, "Test message.")
^~~~~~~~~~~~~~~~~
Csdjournal.sd_journal_print:2:13: note: did you mean 'sd_journal_print'?
public func sd_journal_print(_ priority: Int32, _ format: UnsafePointer<Int8>!, _ varargs: Any...) -> Int32
^
Csdjournal.sd_journal_printv:1:13: note: did you mean 'sd_journal_printv'?
public func sd_journal_printv(_ priority: Int32, _ format: UnsafePointer<Int8>!, _ ap: CVaListPointer) -> Int32
^
error: terminated(1): /home/vagrant/swift-4.1-RELEASE-ubuntu16.04/usr/bin/swift-build-tool -f /vagrant/.build/debug.yaml main output:
What tag are you using? It must be one of the (many, oh so many) that didn't link properly.
Gimme a couple minutes, I've made a new tag and I'm making a dummy swift project that imports it, to demonstrate the current missing functionality.
0.6.1
Try the 0.9.0, that's the last one I've put on GH. That should work
Same issue on that. Hmm, let me upload this test project. You can take a look. btw: I'm running Ubuntu 16.04 (only version that supports libsystemd-dev) and Swift 4.1.
Cool!
Okay, I've finished the setup. This is the project that shows how the wrapper fails.
In your project, I think this might be an unrelated problem?
You have csd_journal_print(0, #file, &line, #function, "Test message.").
And &line is a pointer to an int. That's technically a valid input to the function (since int pointers and char pointers are the same for C), but semantically you should be sending a string :)
Yes, I knew about that, was simply focusing on getting it to compile first.
I'm running Ubuntu 16.04 (only version that supports libsystemd-dev) and Swift 4.1.
Me too, so that's awesome. We must have almost identical setups (modulo installed apt-get packages)
Yes, I knew about that, was simply focusing on getting it to compile first.
🤔
Maybe there's a package that your setup is missing, and that I didn't note down as a provider on the Package Manifest. Let's see: can you run the dummy project? It should give you an output like this:
felix@felix-X550LD ~/D/P/t/csd_proof> swift run csd_proof
Compile Swift Module 'csd_proof' (1 sources)
Linking ./.build/x86_64-unknown-linux/debug/csd_proof
I'm sending This is what I want to log to the system log, from myFile, at myFunc : myLine
Log has been sent!
I've recieved -22 out of the system call.Yes, the dummy project works, save the -22 return code.
Ok, I figured it out. The Package.resolved was still pointing to a fork I made of your repo. Just had to delete it.
Looks good so far 👍
@felix91gr, not sure if this would be useful to you but this is a script I wrote to startup a dev environment to any of the supported Linux and swift versions. I used it to quickly build environments. It's not perfect but it encapsulates a lot of work.
For instance, this is the command I used to create a vm for your tests.
vagrant --platform-version=16.04 --swift-release=4.1 up
You simply create a directory to work in and create a soft link to the Vagrant file.
# mkdir Csdjournal-proof-of-bug
# cd Csdjournal-proof-of-bug
# ln -s ../vagrant-swift/Vagrantfile Vagrantfile
@felix91gr, we'll need to create a new repo for the sd-journal writer. With the dependencies on the system library, I don't believe there is a way to isolate that from other platforms if it's in the main repo. If you know of a way, I'm open to that as well.
You can create a new repo in your account or you can have it live with mine, it's totally up to you of course. I think a good name to keep with the naming conventions I had in mind would be tracelog-sdjournal-writer or tracelog-journal-writer.
We can modify TreaceLog's readme to reference the new repo where ever it lives.
@felix91gr, not sure if this would be useful to you but this is a script I wrote to startup a dev environment to any of the supported Linux and swift versions. I used it to quickly build environments. It's not perfect but it encapsulates a lot of work.
It should be, for when I want to test how to set up something from scratch. I work using Linux; it's my main OS. But since I have almost everything I could need already installed, it's hard to test a tutorial in my pc as-is. I'll take a look, thank you! :)
we'll need to create a new repo for the sd-journal writer. With the dependencies on the system library, I don't believe there is a way to isolate that from other platforms if it's in the main repo.
That is correct. Afaik, there is no way to have nested packages yet, and the only (supported) way to access system modules is the way I'm using, which requires a dedicated Swift package for the wrapped library.
Regarding naming, the most common way to name C wrappers for Swift is to use the original name and precede it with the letter C:
Now. As it stands right now, the wrapper opens the <systemd/sd-journal.h> function namespace to Swift. It also includes a little shim that helps with usage of the variadic print_with_location function. The name should probably be something like CSDJournal or Csdjournal.
That said, if we're only gonna use it (at least for the moment) to help TraceLog write to the sdjournal, then it's not a project that we would actively support. Therefore, the standard naming doesn't make all that sense.
tl;dr I think the name should indeed be something like what you said. tracelog-sdjournal-writer or tracelog-sdjournal-shim sounds about right.
Okay, wait. I'm having a breakthrough. I think I know what's wrong with the wrapper. Brb
IT WORKS.
I'LL POST IT IN A BIT :D STAY TUNED
Regarding naming, the most common way to name C wrappers for Swift is to use the original name and precede it with the letter C:
CLibAVUtil
CCurl
CEpollNow. As it stands right now, the wrapper opens the <systemd/sd-journal.h> function namespace to Swift. It also includes a little shim that helps with usage of the variadic print_with_location function. The name should probably be something like CSDJournal or Csdjournal.
That said, if we're only gonna use it (at least for the moment) to help TraceLog write to the sdjournal, then it's not a project that we would actively support. Therefore, the standard naming doesn't make all that sense.
Ah no, I wasn't saying rename the wrapper around systemd, my thought was the TraceLog.Writer implementation. I didn't think we could make TraceLog itself depend on Csdjournal as that would not compile on iOS, macOS, tvOS, and watchOS but I was just doing some testing and it seems as long as we surround the import CSDJournal and all code with #if os(Linux) it does compile. Even though the Package lists a depedency that can only be compiled on Linux.
I'll need to do some more confirmation on this though.
@tonystone @RLovelett
It's complete: https://github.com/felix91gr/Csdjournal/releases/tag/1.0.0 ✨
Check out the shim.h: the problem was in that we had to prepend the strings with things like CODE_FILE.
(That was not mentioned in the API, and that makes sense: it's a function that was intended for internal usage. I checked out how some of the macros worked, and indeed we were missing these strings. By adding them, everything worked out as if it always did ❤️ )
Ah no, I wasn't saying rename the wrapper around systemd, my thought was the TraceLog.Writer implementation. I didn't think we could make TraceLog itself depend on Csdjournal as that would not compile on iOS, macOS, tvOS, and watchOS but I was just doing some testing and it seems as long as we surround the import CSDJournal and all code with #if os(Linux) it does compile. Even though the Package lists a depedency that can only be compiled on Linux.
I'll need to do some more confirmation on this though.
Yup, with #ifs you can pretty much have OS-exclusive dependencies. That's one of the perks of the Package Manifest being written in Swift itself.
Take a look at this for inspiration: SKD dependencies
It's complete: https://github.com/felix91gr/Csdjournal/releases/tag/1.0.0 ✨
Check out the shim.h: the problem was in that we had to prepend the strings with things like CODE_FILE.
Glad you figured out the prepending of the strings. I do see an issue we are going to have with the implementation as is though. The buffers used are fixed length, file and function from Swift are going to be larger than the 60 allocated on the stack. The file comes back as the entire path on Linux.
The function can also be quiet large.
Okay, I think I've convinced myself that we should indeed use dynamic allocation.
- Buffer-overflow attacks shouldn't be possible if we're calling this from Swift, as Strings are nil-terminated by construction. A user of the wrapper would expose themselves only if they were doing something like manipulating the String buffers of the message to be logged, directly. And I don't see why we'd ever want to do that.
- C is faster than Swift. A couple of
mallocandfrees underclang's optimizer shouldn't make a noticeable hitch in performance, specially if on the Swift side we're working with much more expensive operations.
So, release 1.0.1 now has dynamic allocation:
- Since all the input comes from Swift, I can call
strlenand not worry about unfinished strings. - By the same card, I can directly give the
sd_journal_print_with_locationthecharbuffers I've received from Swift without worrying about unfinished strings.
Thanks for the feedback, @tonystone ^^
Last update: I've updated the dummy project so that it uses the latest version of the wrapper. You can see how to use the 8 levels of logging in there.
One of the nicest things about how Swift imports C is that you can use the int constants directly. No need to keep a copy of the value table in code; you can just write LOG_NOTICE and you'll get the right int constant for that priority.
And, now I'm going to bed. Have a great week, you two 🙂
Second update: @RLovelett found a bug that made it hard to use the library in more than one source file at a time. That's now been fixed on version 1.2.0:
- New release
- Dummy project has also been updated to test against this bug in the future (update is in
master).
Nice work @felix91gr @RLovelett 👍
No problem!
Guys, I'll be stepping out for the week. I've got an assignment to finish for Friday and I'm quite behind 😅
Please feel free to fork the wrapper if you need to make changes.
I hope to be back around Saturday-Sunday. Til' then! :)
@felix91gr @RLovelett, just want to throw this out there since I spent a little time checking out an alternative to the shim wrapper. My thought was that sd_journal_sendv was the lowest level method that all the other methods eventually call (and I validated that with the source). This call allows Swift to call it directly and also provides for all the various fields we would need plus any custom ones such as TraceLogs tags, etc.
The calling code is a bit more complicated but it does move all the code into Swift (literally there is no C code, just a reference to the header file.
I see advantages to both the csd_journal_print and the sd_journal_sendv direct call.
Please see:
Note that the header in the system module now only contains:
#import <systemd/sd-journal.h>There is an explanation of why that is in comments.
Calling code is more complicated but much more flexible and allows any of the params that sd-journal allows plus custom fields.
var utf8Text = ["MESSAGE=Test Message".utf8CString,
"CODE_FILE=\(#file)".utf8CString,
"CODE_LINE=\(#line)".utf8CString,
"CODE_FUNC=\(#function)".utf8CString,
"PRIORITY=\(LOG_INFO)".utf8CString
]
var array: [iovec] = []
for i in 0..<utf8Text.count {
let count = utf8Text[i].count - 1
utf8Text[i].withUnsafeMutableBytes { (bytes) -> Void in
if let address = bytes.baseAddress {
array.append(iovec(iov_base: address, iov_len: count))
}
}
}
sd_journal_sendv(&array, Int32(array.count))Happy to use either, just wanted to offer you guys this so I didn't feel like I waisted the research :-)
Btw: you can find the source for all the calls in discussion here journal-send.c
Okay, I managed to solve one third of this assignment quickly (phew). I'll give my two cents right away, because I don't want you guys to wait on me or this :)
@tonystone, I think this is key:
allows any of the params that sd-journal allows plus custom fields.
What extra parameters does it allow? How could we make use of that? That sounds interesting.
Comparing the two solutions, this is what I think:
The shim.h is clearer for me to read. That might be because the whole pointer arithmetic and memory manipulation thing is first-class there. Therefore, it feels like an easier code to debug and maintain. And given that we're working with C, that's pretty nice to have.
I still think both solutions are pretty close. If the extra flexibility of the Swift-side wrapping seems worth it, that would tip the scales.
Take me with a grain of salt here as well, because (1) I made the shim.h and I can't 100% take away my bias ^^. Also (2) I find that level of C code fairly easy to read because I had to work with C a lot in the last couple of years. That might not be all that common.
What do you think?
@felix91gr, so my philosophy of combining languages for the last 30+ years has been to always stick to the primary language the system, tool, app, etc is being written in and only go to a lower level language for speed or if it just can't be done in the primary language. This keeps the code more maintainable by others who may not be as adept at mixing languages as us.
I believe your C implementation is very nicely written, understandable and maintainable. It is hard to beat a single language module though.
So you got me thinking again when I was answering this question about simple ways to do this and I came up with a simpler no C option directly calling sd_journal_printv_with_location since it's a va_list function and not variadic. Here's the call to that which is very simple indeed.
withVaList([]) { vaList -> Void in
sd_journal_printv_with_location(LOG_INFO, "CODE_FILE=\(#file)", "CODE_LINE=\(#line)", #function, "Test Message", vaList)
}Note: In the above, we do lose the ability to send extra params, but the only one I can think of after reviewing the list of params that are already present(see list here) is the declared Tag in TraceLog.
So in the end, even though I love C and your implementation, the simplicity of not having C and the above call drives me toward the no C direct option.
Btw: I finally figured out why function did not require a prefix and investigating it I found this.
/* func is initialized from __func__ which is not a macro, but
* a static const char[], hence cannot easily be prefixed with
* CODE_FUNC=, hence let's do it manually here. */
ALLOCA_CODE_FUNC(f, func);All the higher level functions handle prefixing that for you, the only one that does not of course is sd_journal_sendv which is the lowest call in the stack.
I believe your C implementation is very nicely written, understandable and maintainable.
Thank you <3
My philosophy of combining languages for the last 30+ years has been to always stick to the primary language the system, tool, app, etc is being written in and only go to a lower level language for speed or if it just can't be done in the primary language. This keeps the code more maintainable by others who may not be as adept at mixing languages as us.
Okay you raise a fair point here. I didn't think of this, but it makes much more sense for this to be written as much in Swift as it is feasible (i.e. possible and performant). I believe there's nothing much C can do against the performance of the Swift-C interop APIs, at least not in a noticeable way by our users. Therefore, just for maintainability and ergonomics sake, we should keep this logging interface at the Swift layer whenever possible. I agree with you.
(...) and I came up with a simpler no C option directly calling
sd_journal_printv_with_locationsince it's ava_listfunction and not variadic. Here's the call to that which is very simple indeed.
It is! The other day I took a look at those functions, but gave up as I don't quite understand how to use va_lists. Can we create one of those from Swift? If so, that would be fantastic! So much easier to use :)
Btw: I finally figured out why function did not require a prefix and investigating it I found this.
Ohh, that's very interesting indeed.
It is! The other day I took a look at those functions, but gave up as I don't quite understand how to use va_lists. Can we create one of those from Swift? If so, that would be fantastic! So much easier to use :)
See the previous comment, the first piece of code is Swift creating a va_list although in this case its an empty list. Could just as easily of had a few params. Here it is again:
///
/// Swift code creating a va_list or technically a `CVaListPointer` which is a wrapper
/// around a C `va_list`.
///
/// Note the empty array in `withVaList`, that is where any args would go that are in the va_list.
///
withVaList([]) { vaList -> Void in
sd_journal_printv_with_location(LOG_INFO, "CODE_FILE=\(#file)", "CODE_LINE=\(#line)", #function, "Test Message", vaList)
}I updated my example so you can try it out.
I actually works. Holy shit, this was so easy!
What are va_list from Swift? Are they arrays of strings? Arrays of.... Anything?
@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.
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 :)
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?
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?
@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=?
@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.
Sorry for the delayed response. 😞
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. 😄 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
🎉 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).
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.
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.
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_IDENTIFIERthat 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.
I posted an issue at the tracelog-journal-writer repo about some tests that are failing :)
@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:
- Use TraceLog to abstract all logging but on Apple using Unified Logging, you lose the file, line, function.
logTrace { "My message" }- Use direct calls everywhere in the code to
os_logbut 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" }
#endifI'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.
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? 🤷♂️
@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.
@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 ^^.
Not that anyone asked. 😄
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.
@felix91gr and @RLovelett ,
Ah, good idea but I don't think it will work for several reasons.
- TraceLog gets compiled as a module, once it's a module, the dso handle of the module will be passed to the
os_logfunction negating anything we do with inline. - TraceLog has several layers of calls before actually calling the Writer log method.
- 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?
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.
Does that still allow us to make the internal calls "internal" visibility?
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 🙂
Awesome, I love that feature.
I'll put together a little test later this can help us.
I love that feature
Me too! I think it's very clever :)
Kudos to Slava for making it.
@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.
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.
@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.
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 😍 thank you for making it 🙂
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.
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.
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.
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.
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 :)
I'm getting a little confused by the names by OSLogger you mean the Systemd Journal Writer?
I mean the "unified" system writer:
UnifiedLoggingWriterunder Darwin,SDJournalWriterunder Linux
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.
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?
Agreed! Refer to this one in it.