add source for log messages #135

weissi · 2020-06-05T15:53:18Z

Motivation:

We noticed that we need log source information, which is a stable and greppable identifier for where a log message originated from. But less precise than file/function but about as or slightly more precise than the current module.
Some folks used label for this purpose but instantiating new loggers everywhere just to get a good label means the following sub-optimal things:

metadata propagation more complicated than necessary
setting logLevel for a called library not possible (unless extra parameter passed)
controlling the logging backend for a called library not possible (unless yet another parameter passed)
the loss of label as an identifier for a part of an application (eg. if your binary contains two independent services ServiceA and ServiceB but both use a library such as AsyncHTTPClient. Then ideally you'd have label: "MyApp.ServiceA" and label: "MyApp.ServiceB" to separate messages originating from AHC.

All of these things are solved and behave very nicely if you pass a "root logger" around to all sub-systems. The problem however is if you cannot use label as source information, where do you get source information from?

Modification:

introduce a new source field for every log message that defaults to the calling module (currently parsing #file until SR-12920 is resolved)
introduce LoggerWithSource which wraps a Logger always attaching a non-standard source. For example in AHC you may want to make a LoggerWithSource(obtainedLogger, source: "AHC.ConnectionPool") for logs in the connection pool.

Result:

Proper source identifier.

avolokhov · 2020-06-05T17:37:14Z

Do we want to provide a default factory? E.g. var logger = logger.withSource(source: source).

ktoso · 2020-06-08T05:35:06Z

Checking this out today in a project; I have some concerns but let's see how it goes.

avolokhov · 2020-06-08T11:00:38Z

Sources/Logging/LoggerWithSource.swift

+    @inlinable
+    public func debug(_ message: @autoclosure () -> Logger.Message,
+                      metadata: @autoclosure () -> Logger.Metadata? = nil,
+                      source: @autoclosure () -> String? = nil,


I think it's some copy/paste leftover: we use self.source, and not the one provided here.

Same for all other methods.

These signatures are wrong in one or another way I guess indeed:

a) We want to keep exact same method signatures as Logger:

so we keep source: @autoclosure () -> String? = nil,

impl has to source: source() ?? self.source

it must allow `sourcelogger.info("", source: "actually-more-specific-ad-hoc")

if we want to keep this parameter here indeed

or

b) Like Anton mentions, this parameter should go away on all functions on LoggerWithSource

b) seems to make more sense, as Anton says. Either's fine tbh, but the current impl is not consistent with what the signature advertises we're able to do with these functions (override the source anyway)

avolokhov · 2020-06-08T11:06:45Z

Sources/Logging/LoggerWithSource.swift

+    public func trace(_ message: @autoclosure () -> Logger.Message,
+                      metadata: @autoclosure () -> Logger.Metadata? = nil,
+                      file: String = #file, function: String = #function, line: UInt = #line) {
+        self.logger.trace(message(),


I'm not sure about this, but I think LoggerWithSource.trace should delegate to LoggerWithSource.log, and not to Logger.trace. Otherwise LoggerWithSource seems inconsistent with Logger, and the reason for LoggerWithSource.log is unclear. WDYT? Same for other methods.

@avolokhov From the generated code's perspective this is indistinguishable so we can change at any point in time.

The reason I did add log with LoggerWithSource is that some people may be using log(level: .trace, ...) instead of .trace and I want it to be compatible.

ktoso · 2020-06-09T02:38:56Z

Quoting @weissi from #133 (comment)
(my bad, replied in wrong PR there)

Status update — I think this likely will be fine but I’ve ran out of time in the day to get it to completion in my project to really see it work out end to end.
It makes the label pretty useless but I guess we’ll agree that’s what it is. I’ll post a review tomorrow

I thought about label more and I actually now think it's useful. It's basically orthogonal to source.

Let's consider a whole system and let's assume the system offers 2 services, let's call them service A and service B. Services A & B both use a multitude of sub-subsystems. Then everything that belongs to Service A gets label=MyApp.ServiceA and B gets label=MyApp.ServiceB. If now both A & B use say AsyncHTTPClient, then the label suddenly becomes useful.

source=AHC gives us AHC calls from both A & B which might be annoying if I'm a developer working only on A

source=AHC & label=MyApp.ServiceA however gives me exactly what I want.

That's a good point, it actually works out well there 👍

ktoso

I tried it out "in action" and do think it'll work well enough 👍
Glad we talked through the use-cases and I think this now can serve all patterns.

I'm a bit worried about the string parsing module workaround... but otherwise looks good; just minor comments on API consistency and some docs 👍

Sources/Logging/LoggerWithSource.swift

ktoso · 2020-06-09T05:47:16Z

Tests/LoggingTests/LoggingTest.swift

+        logger.critical("yes: critical")
+
+        testLogging.history.assertExist(level: .critical, message: "yes: critical", source: "source")
+    }


ktoso · 2020-06-09T05:58:12Z

Sources/Logging/LoggerWithSource.swift

+    @inlinable
+    public func debug(_ message: @autoclosure () -> Logger.Message,
+                      metadata: @autoclosure () -> Logger.Metadata? = nil,
+                      source: @autoclosure () -> String? = nil,


These signatures are wrong in one or another way I guess indeed:

a) We want to keep exact same method signatures as Logger:

so we keep source: @autoclosure () -> String? = nil,

impl has to source: source() ?? self.source

it must allow `sourcelogger.info("", source: "actually-more-specific-ad-hoc")

if we want to keep this parameter here indeed

or

b) Like Anton mentions, this parameter should go away on all functions on LoggerWithSource

b) seems to make more sense, as Anton says. Either's fine tbh, but the current impl is not consistent with what the signature advertises we're able to do with these functions (override the source anyway)

Sources/Logging/Logging.swift

Tests/LoggingTests/LoggingTest.swift

Sources/Logging/Logging.swift

Sources/Logging/LogHandler.swift

avolokhov · 2020-06-09T10:50:16Z

Let's consider a whole system and let's assume the system offers 2 services, let's call them service A and service B. Services A & B both use a multitude of sub-subsystems. Then everything that belongs to Service A gets label=MyApp.ServiceA and B gets label=MyApp.ServiceB. If now both A & B use say AsyncHTTPClient, then the label suddenly becomes useful.

source=AHC gives us AHC calls from both A & B which might be annoying if I'm a developer working only on A

@ktoso To this point, wouldn't it make label just a required metadata field? We can achieve this with metadata only, why give multiple ways to do the same?

weissi · 2020-06-09T14:07:24Z

@ktoso To this point, wouldn't it make label just a required metadata field? We can achieve this with metadata only, why give multiple ways to do the same?

Well, it's unchangable. So if you implemented metadata swapping, the label would not be swapped. Also we don't have required metadata fields right now. But I agree it's kinda similar.

avolokhov · 2020-06-09T14:18:51Z

I'm a bit worried that source fully relies on a library developer being a good citizen, we don't enforce it anywhere. In a perfect world of ultimate tyranny, I'd just remove all logging methods from logger and keep them in only in loggerWithSource so that a developer is forced to add source to be able to log something. Sad we can't do it.

weissi · 2020-06-09T14:21:03Z

I'm a bit worried that source fully relies on a library developer being a good citizen, we don't enforce it anywhere. In a perfect world of ultimate tyranny, I'd just remove all logging methods from logger and keep them in only in loggerWithSource so that a developer is forced to add source to be able to log something. Sad we can't do it.

Yes, we can't enforce this at this point in time anymore.

ktoso · 2020-06-09T15:30:13Z

[...] remove all logging methods from logger and keep them in only in loggerWithSource so that a developer is forced to add source to be able to log something. Sad we can't do it.

I'm not sure that's the answer either, there's much to say for "I really don't care, I'm just a simple app" use cases where the default = #module really is kind of good enough already anyway. The source is really something usable that label today isn't for libraries which do have fine grained opinions about log sources, not sure forcing everyone into it is strictly necessary;

We discussed options at length with Johannes but let me note down some of them here and why they break down and we're left with a source thing.

Strawman 1: What if... we allowed changing label

One could argue that "use label, make it changeable" which i think betrays intentions though, since Johannes wants to "create one logger and pass it to sub-systems" which e.g. would be one such library which has strong opinions about subsytems / sources.

If we just said, "just allow to change the source" the following API is kind of lying IMHO:

library.logger = Logger(label: "AwesomeApp")
// first thing library would do is...
// let subSystemLogger = library.logger.withLabel("subsystem-x")

so... when users passed AwesomeApp, they hare the reasonable expectation this label will show up in logs and can grep or search by it. But... if label is changeable they couldn't -- since that's the "one spot" for log sources...

That's very bad / confusing. So... making label changeable is not an answer.

❌

Strawman 2: label "IS" source

To be honest that's how I've seen it, but it requires libraries which have strong opinions about "what is logging right now" to create loggers in the library.

In order to avoid the global factory and allow swapping impls per library instance (that's a hard requirement IMO), one has to in the library then set a (String) -> Logger which defaults to Logger.init(label:)... That's what I've been doing, along with configuration what the loglevel and metadata for those "created inside the library" loggers should be.

This works if configuration suits people; and while it suits me, there are others which really like the "create a root logger and pass it into libraries" If we did this with the "label is the source of the entity that is logging" then it breaks down -- label can't be changed.

❌

Strawman 3: Just metadata

Also an option I guess... though we can't do the "please DO set a source" maybe it's harder to get right than the type at all...

It would be better (?) in the sense that it does not cause another type to be created for the "i know the source" cases. Though on the other hand when I ported my work to use this WIP PR the "I know i have a specific source" type was useful during library development... Though I kind of expect few developers to care about this? I do imagine it matter a lot through in very concurrent settings where one wants to log "which threadpool" or whatnot is performing the actions, so the log would contain these as sources perhaps... All in all, it's helpful if source is a "real" thing we talk about, and not just a pattern.

What convienced me was Johannes's point recently

Services A & B both use a multitude of sub-subsystems. Then everything that belongs to Service A gets label=MyApp.ServiceA and B gets label=MyApp.ServiceB. If now both A & B use say AsyncHTTPClient, then the label suddenly becomes useful.

❌

Strawman 4: "never use the create 1 root logger and pass it into libraries"

For the record that was my initial stance: all libs would have to make customization points for log level, "root" metadata, and "mocking" a logger out...

So libraries have to expose defaultLogLevel and defaultMetadata that they would use thenever they create a logger using Logger(label: ...) using the "global" convenience initializer. This does lead to global state though, so libraries also have to invent the (String) -> Logger configuration point I mentioned.

While I trust libraries we build could get this right and maybe even consistent if we try hard enough, it's a lot of specific things a lib has to expose, and it defeats a pattern some of us like (the "pass rootLogger into library". And I do agree it'd probably never happen that "random libraries" use the same specific pattern and ways to configure this...At-best they might develop the same customization points, but all in slightly different syles and names... or at worst ignore this completely ("global state? what's the problem!" :P) and we're back in global state land making logging when many instances of a lib in one process exist difficult.

❌

So... we ended up with "what if we add source" which is the library controlled "source" meaning "the entity that is logging". It's default being the module is good enough and kind of the right thing always for small libraries, and larger libraries with subsystems and background tasks, thread pools etc can control if it they want to. It's in the control of library authors, but really that's what we're after here -- the user controlled label "MyCoolSystem" is "label", and "source" is up to library internals. I.e. no "top level logger" should ever be the LoggerWithSource.

Uff, so yeah, that's pretty much a summary of the various takes we had on this I think. I've had my reservations but after many chats and also trying it out in action now I guess it's an okey tradeoff.

It does still mean setting that then passing "between" / "through" libraries the source is not really propagated... it's always the lib's "own" sources we'll see. So for execution contexts/thread pools I guess one has to set the metadata anyway always after all 🤔 Otherwise I would not know that I'm on pool X, and executing thingy library Y, since it accepted Logger and thus lost "my" source which i used to mark the pool...

So... perhaps source is not solving the problem after all, or is it...? 🤔

avolokhov · 2020-06-09T16:11:08Z

Oh, I think we should emphasise that source should be stable. I already imagine some library goes mad and set uuid as a source, making it impossible to filter it out by source.

ktoso · 2020-06-09T16:34:44Z

Yeah good point, likely we should document that hint.

ktoso · 2020-06-10T02:44:25Z

Minor additional point I just noticed, I seem to do a lot of

log.logger.withSource("serialization")

where log is a libraries "top level logger" (the one someone could set when they start my library). Would it make sense to also offer withSource on the LoggerWithSource? @weissi

ktoso · 2020-06-22T15:03:08Z

So in general this looks good to me. I remain worried about the "faking that we have #module" esp with longer module names... Will try to sanity check this soon.

Do you want to merge this soon or would we want to know what way forward wrt #module (or similar) is?

Context: I have plenty of logs on .trace level and I'm worried that that source workaround would actually allocate/slow-down runtime a lot in my lib. What if a real thing never lands etc... So I'd like to sanity check that before LGTMing. (or some benchmark in here etc)

ktoso · 2020-06-22T15:03:20Z

Minor, what about: #135 (comment)

ktoso

I just realized my main concern was not necessary in #135 (comment) thanks again @weissi

LGTM as far as I can tell 👍

weissi · 2020-06-22T16:11:04Z

@ktoso / @tomerd API digester is wrong: https://bugs.swift.org/browse/SR-11859

weissi · 2020-06-22T16:15:35Z

@avolokhov for some reason, Github's "request re-review" button doesn't seem to work for you so I'm @-ing you

avolokhov

Yes, I accidentally requested changes on the very first iteration. Looks good!

ktoso · 2020-06-22T16:49:30Z

Does the API check being wrong though mean we'll always have it fail when we merge this since it compares prev-release to current?

In Akka (the MiMa tool) we had "ignore these checks" if we indeed "broke" but knew the change is ok for some reason: https://github.com/akka/akka/blob/master/akka-actor/src/main/mima-filters/2.5.2.backwards.excludes do we need a similar thing to keep the api-digester being always wrong and highlighting such things?

weissi · 2020-06-22T16:54:02Z

@ktoso no, it'll only fail on this very PR. It always compares commit N vs. N+1.

ktoso · 2020-06-23T01:40:28Z

Okey, seems we're good then

weissi · 2020-06-23T13:55:44Z

@tomerd mind having a look here

tomerd · 2020-06-29T18:10:11Z

thanks for putting this together @weissi

As we discussed in the original pitch and proposal, there are many usage patterns for SwiftLog (propagation, local or global to name the main ones), and a key requirement from it is to be able use configuration [at the logger-backend level] to control logging verbosity of specific subsystems and libraries while troubleshooting.

I think the combination of label + source is a good way to drive such configuration, even better than just label + metadata that we have now, so +1 on adding this. I do think it would be beneficial to better document this concept to help guide logging-backend authors to offer such configuration options. As t stands this concept is buried in a test utility which is not used in practice, so hard to find.

With that said, I do not think we should expand the API surface area with LoggerWithSource, I feel most libraries won't need it and its trivial enough to add locally in those that do. If we see this is not the case, and many library authors request this feature we can add it at a later stage.

cc @ktoso

ktoso · 2020-06-30T01:22:38Z

I agree with the sentiment, let's take it slow with adding the new type.

I initially thought i'd need it but in reality only used it in 2 source files so it's not been as crucial as I thought initially, happy to make the wrapper myself.

We can make a ticket explaining what it is in case people will bump into it and +1 that ticket.

ktoso · 2020-07-06T09:35:39Z

Will rebase and merge this one. The LoggerWithSource I'll pull out as proposal / ticket for now.

The ticket with the LoggerWithSource for future reference: #143 it may die out if no interest, or it may get some interest -- we'll see. Currently I don't think we'll need it but let's see what other projects will feel after a while of real world usage.

ktoso · 2020-07-06T11:01:03Z

Removed the new LoggerWithSource type, see 8058ed5 and ticketified as #143
API validation fails but known issue and we took care about compatibility; see also #135 (comment)

Once we release we'll need to write up guidance about implementing 1.3.0 "new handler function", backends can do this "whenever they're ready to"

Motivation: - When `source:` was added in apple#135, the API was accidentally broken despite source compatability. Modifications: - Add back source-less API calls which defer to the decls with source. - Note we can't deprecate the calls we're adding back: `log.info("some message")` refers to the implementation we're adding back rather and would therefore require users to explicitly specify a source to suppress the deprecation warning message. Result: - API is no longer broken.

Motivation: - When `source:` was added in #135, the API was accidentally broken despite source compatability. Modifications: - Add back source-less API calls which defer to the decls with source. - Note we can't deprecate the calls we're adding back: `log.info("some message")` refers to the implementation we're adding back rather and would therefore require users to explicitly specify a source to suppress the deprecation warning message. Result: - API is no longer broken. Co-authored-by: Konrad `ktoso` Malawski <[email protected]>

weissi added the semver/minor Adds new public API. label Jun 5, 2020

weissi force-pushed the jw-source branch from 3402635 to b47af2e Compare June 5, 2020 16:01

ktoso self-requested a review June 8, 2020 01:15

ktoso mentioned this pull request Jun 8, 2020

logging support swift-server/async-http-client#227

Merged

weissi force-pushed the jw-source branch 2 times, most recently from 66b6c92 to e2889a2 Compare June 8, 2020 09:20

avolokhov suggested changes Jun 8, 2020

View reviewed changes

avolokhov reviewed Jun 8, 2020

View reviewed changes

ktoso mentioned this pull request Jun 9, 2020

silence #file to #filePath warnings #133

Merged

ktoso reviewed Jun 9, 2020

View reviewed changes

weissi force-pushed the jw-source branch 2 times, most recently from 2ba7a52 to 65d928b Compare June 22, 2020 14:25

weissi marked this pull request as ready for review June 22, 2020 14:25

weissi requested review from ktoso and tomerd June 22, 2020 14:25

weissi force-pushed the jw-source branch from 65d928b to 43b0993 Compare June 22, 2020 14:26

weissi force-pushed the jw-source branch from 43b0993 to fee41e9 Compare June 22, 2020 16:00

ktoso approved these changes Jun 22, 2020

View reviewed changes

avolokhov approved these changes Jun 22, 2020

View reviewed changes

ktoso mentioned this pull request Jul 6, 2020

For reference: LoggerWithSource #143

Open

add source for log messages

11a2ec7

ktoso force-pushed the jw-source branch from 2a654d6 to c917fc6 Compare July 6, 2020 10:40

-log remove the LoggerWithSource for the time being

8058ed5

ktoso force-pushed the jw-source branch from c917fc6 to 8058ed5 Compare July 6, 2020 10:42

ktoso merged commit 024f44d into apple:master Jul 6, 2020

ktoso added this to the 1.3.0 milestone Jul 6, 2020

glbrntt mentioned this pull request Aug 10, 2020

API break in #135 (1.3.0) #150

Closed

glbrntt mentioned this pull request Aug 13, 2020

Add back accidentally removed API #152

Merged

leisurehound mentioned this pull request Sep 1, 2020

Support SwiftLog 1.4 and the source log parameter google/swiftlogfirecloud#1

Open

slashmo mentioned this pull request May 2, 2021

Remove [Lifecycle] prefix from log messages swift-server/swift-service-lifecycle#95

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

add source for log messages #135

add source for log messages #135

weissi commented Jun 5, 2020

avolokhov commented Jun 5, 2020

ktoso commented Jun 8, 2020

avolokhov Jun 8, 2020

avolokhov Jun 8, 2020

ktoso Jun 9, 2020

avolokhov Jun 8, 2020 •

edited

Loading

weissi Jun 22, 2020

ktoso commented Jun 9, 2020 •

edited

Loading

ktoso left a comment

ktoso Jun 9, 2020

ktoso Jun 9, 2020

avolokhov commented Jun 9, 2020 •

edited

Loading

weissi commented Jun 9, 2020

avolokhov commented Jun 9, 2020

weissi commented Jun 9, 2020

ktoso commented Jun 9, 2020

avolokhov commented Jun 9, 2020

ktoso commented Jun 9, 2020 •

edited

Loading

ktoso commented Jun 10, 2020 •

edited

Loading

ktoso commented Jun 22, 2020 •

edited

Loading

ktoso commented Jun 22, 2020

ktoso left a comment •

edited

Loading

weissi commented Jun 22, 2020

weissi commented Jun 22, 2020

avolokhov left a comment

ktoso commented Jun 22, 2020 •

edited

Loading

weissi commented Jun 22, 2020

ktoso commented Jun 23, 2020

weissi commented Jun 23, 2020

tomerd commented Jun 29, 2020

ktoso commented Jun 30, 2020

ktoso commented Jul 6, 2020 •

edited

Loading

ktoso commented Jul 6, 2020

add source for log messages #135

add source for log messages #135

Conversation

weissi commented Jun 5, 2020

avolokhov commented Jun 5, 2020

ktoso commented Jun 8, 2020

avolokhov Jun 8, 2020

Choose a reason for hiding this comment

avolokhov Jun 8, 2020

Choose a reason for hiding this comment

ktoso Jun 9, 2020

Choose a reason for hiding this comment

avolokhov Jun 8, 2020 • edited Loading

Choose a reason for hiding this comment

weissi Jun 22, 2020

Choose a reason for hiding this comment

ktoso commented Jun 9, 2020 • edited Loading

ktoso left a comment

Choose a reason for hiding this comment

ktoso Jun 9, 2020

Choose a reason for hiding this comment

ktoso Jun 9, 2020

Choose a reason for hiding this comment

avolokhov commented Jun 9, 2020 • edited Loading

weissi commented Jun 9, 2020

avolokhov commented Jun 9, 2020

weissi commented Jun 9, 2020

ktoso commented Jun 9, 2020

Strawman 1: What if... we allowed changing label

Strawman 2: label "IS" source

Strawman 3: Just metadata

Strawman 4: "never use the create 1 root logger and pass it into libraries"

avolokhov commented Jun 9, 2020

ktoso commented Jun 9, 2020 • edited Loading

ktoso commented Jun 10, 2020 • edited Loading

ktoso commented Jun 22, 2020 • edited Loading

ktoso commented Jun 22, 2020

ktoso left a comment • edited Loading

Choose a reason for hiding this comment

weissi commented Jun 22, 2020

weissi commented Jun 22, 2020

avolokhov left a comment

Choose a reason for hiding this comment

ktoso commented Jun 22, 2020 • edited Loading

weissi commented Jun 22, 2020

ktoso commented Jun 23, 2020

weissi commented Jun 23, 2020

tomerd commented Jun 29, 2020

ktoso commented Jun 30, 2020

ktoso commented Jul 6, 2020 • edited Loading

ktoso commented Jul 6, 2020

avolokhov Jun 8, 2020 •

edited

Loading

ktoso commented Jun 9, 2020 •

edited

Loading

avolokhov commented Jun 9, 2020 •

edited

Loading

ktoso commented Jun 9, 2020 •

edited

Loading

ktoso commented Jun 10, 2020 •

edited

Loading

ktoso commented Jun 22, 2020 •

edited

Loading

ktoso left a comment •

edited

Loading

ktoso commented Jun 22, 2020 •

edited

Loading

ktoso commented Jul 6, 2020 •

edited

Loading