Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Verbose logging #1027

Merged
merged 17 commits into from Mar 10, 2020
Merged

Verbose logging #1027

merged 17 commits into from Mar 10, 2020

Conversation

ollieatkinson
Copy link
Collaborator

@ollieatkinson ollieatkinson commented Feb 21, 2020

Resolves #39

Short description πŸ“

Replace Printer for swift-log and expose a command line argument for --verbose allowing for more logs to be printed to the console.

Solution πŸ“¦

swift-log is the official swift logging framework, it was originally developed to remove the descrepency between all of the different server-side logging frameworks. Even though we are not a server-side application we do take logging seriously, and it makes sense for us to be able to integrate with the standard tools provided by apple.

swift-log provides a really nice abstraction away from logging so that the thing logging is agnostic of where the log is output. Currently I have written three implementations:

  • StandardLogHandler: This is typically what users of tuist will always see, the default level of this logger will be notice and it will provide colorisation and a minimalistic view of the log - no time, no file, no metadata.
  • DetailedLogHandler: A more detailed version of the above log, providing lots of extra information - this logger might be useful if you are running Tuist on CI and want more information about metadata or time.
  • OSLogHandler: Implementation of the os.log API, useful if you want to trace the logs using Console.app

Each Tuist module will have an internal logger variable which can be used to log, the label is used in the detailed log so that you have more information about which module the log message was generated.

import TuistSupport
let logger = Logger(label: "io.tuist.generator")

All logs are collected and dispatched to the handler which has been bootstrapped, this can either be one of the handlers I have defined, or multiple of them at once. We may in the future decide we want to have a handler which writes to disk, which might help you track metrics of the tool over time.

At the call-site when wanting to create a log you would use the standard swift-log API, the function name is the same as the level of the log. For example this is a log with level warning:

logger.warning("Version \(version) already installed, skipping")

In the StandardLogHandler some assumptions have been made when it comes to colourising your message.

switch logLevel {
case .critical:
    return [ .red, .bold ]
case .error:
    return [ .red ]
case .warning:
    return [ .yellow ]
case .notice:
    return [ .bold ]
case .debug, .trace, .info:
    return .none
}

These colours can however be overriden if you want by using one of the following API's:

logger.info("File generated at path \(tuistVersionPath.pathString)".success())
logger.info("File generated at path \(tuistVersionPath.pathString)".green().bold())
let message = "File generated at path \(tuistVersionPath.pathString)"
logger.info("\(message, .green, .bold)")

↑ I would appriciate feedback because the colourisation I am least precious about and I do not have a strong opinion on.

TODO πŸ‘©β€πŸ’»πŸ‘¨β€πŸ’»

  • Change default logging level for items printed to console to notice
  • Create a mocked logging handler during unit testing to check the log contains some string
  • Gather feedback from @tuist/core

@pepicrft
Copy link
Contributor

Each Tuist module will have an internal logger variable which can be used to log, the label is used in the detailed log so that you have more information about which module the log message was generated.

This is a brilliant idea @ollieatkinson

@pepicrft
Copy link
Contributor

↑ I would appriciate feedback because the colourisation I am least precious about and I do not have a strong opinion on.

What about hiding color and formatting from users. You might wonder why? If we allow colouring and formatting things from the API, we might end up with inconsistent formatting, and that's a bad experience for the user.

I think we can compare this to design systems. The reason why they exist is because they ensure we can create consistent design experiences across all the products that we build with them. The same applies here. We could have a consistent styling experience by providing a set of formatting tokens/components for users to use.

But if we hide colours and styles, how do users highlight things in the messages that they are logging? What I'd do is try to recognise patterns in the messages that we output. For example, we might find that developers very often include command suggestions in their outputs:

  • Run tuist generate to run the generate the project before building it.
  • Try running tuist up to configure your environment before interacting with the project.

We could define how a command should be formatted (e.g. in white and bold), and then do it internally. The API could be something along the lines of:

logger.info("Run \(.command("tuist generate")) to run the generate the project before building it.")

@pepicrft
Copy link
Contributor

Dumping another idea here. What about adding a guidelines to the contributors documentation about the grammar that we should use when logging information to the user?

  • Should messages start with capital letter?
  • Should we end the log with a dot?
  • What tense should we use?

This is a bit picky, but consistent styling with our messages is also a great experience for the users.

@@ -4,7 +4,7 @@ import PackageDescription

let package = Package(
name: "tuist",
platforms: [.macOS(.v10_11)],
platforms: [.macOS(.v10_12)],
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is a breaking change that we need to agree with. Since the latest version is 10.15, I think it's ok dropping support for 10.11. What do you think @tuist/core ?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

By upping from 10.11 to 10.12 we would loose support for Xcode 7

Sources/tuist/main.swift Outdated Show resolved Hide resolved
@pepicrft
Copy link
Contributor

Beautiful @ollieatkinson ❀️. Have you thought about a testing strategy that we could follow if we want to test that we get the right output? Having a global variable makes the API very convenient, but I think it complicates testing a bit.

@ollieatkinson
Copy link
Collaborator Author

ollieatkinson commented Feb 21, 2020

Have you thought about a testing strategy that we could follow if we want to test that we get the right output?

Yes, since we have decoupled logging and the output we would just need to register a logging handler which we are able to ciphen messages out of.

LoggingSystem.bootstrap(TestingLogHandler.init)
public struct TestingLogHandler: LogHandler {
    
    static var collected: [Logger.Level: [String]] = [:]
    
    public var logLevel: Logger.Level
    public let label: String
    
    public init(label: String) {
        self.label = label
        self.logLevel = .trace
    }
    
    public func log(
        level: Logger.Level,
        message: Logger.Message,
        metadata: Logger.Metadata?,
        file: String, function: String, line: UInt
    ) {
        Self.collected[level, default: []].append(message.description)
    }

    public var metadata = Logger.Metadata()

    public subscript(metadataKey key: String) -> Logger.Metadata.Value? {
        get { metadata[key] }
        set { metadata[key] = newValue }
    }

}

Copy link
Collaborator

@kwridan kwridan left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice work @ollieatkinson πŸ‘

Having standardised logging will be a great addition! I like the three loggers you included, they were handy to test out this branch.

Some thoughts about colours & printing ... β˜•οΈ

I think we can compare this to design systems. The reason why they exist is because they ensure we can create consistent design experiences across all the products that we build with them. The same applies here. We could have a consistent styling experience by providing a set of formatting tokens/components for users to use

Agree on this one.

I'd add, if we're to unify logging and printing, styling can be treated as metadata as opposed to getting applied to the message contents directly - for example when using the console app logger, the terminal styling characters aren't desired in the messages.

Screenshot 2020-02-22 at 18 55 35

Having it as independant metadata would enable outputting logs to multiple destination if needed (e.g. console, console app, and a file) where the styling is applied only where needed and using the appropriate format for the output.

One aspect I am going back and forth on is logging vs printing - I can see a lot of similarities but also some differences. Seeing Tuist is a command line tool, printing to the console is effectively its view layer so to speak where styling matters. There could even be instances where you'd always want to print to the console regardless of logger choice for example:

  • tuist --help
  • tuist version
  • tuist dump

Having looked at the changes in this pull request, for the majority of cases I can see trying to make the distinction of "should I print? or log? or do both?!" to be quite tricky 😞 - as such leaning more in favour of your approach of unifying the APIs as there aren't that many use cases where printing is distinctly required over logging.

Sources/tuist/main.swift Show resolved Hide resolved
@github-actions
Copy link
Contributor

github-actions bot commented Mar 5, 2020

@ollieatkinson your pull request is missing a changelog!

@codecov
Copy link

codecov bot commented Mar 5, 2020

Codecov Report

Merging #1027 into master will decrease coverage by 1.58%.
The diff coverage is 27.86%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #1027      +/-   ##
==========================================
- Coverage   78.84%   77.26%   -1.59%     
==========================================
  Files         238      242       +4     
  Lines       11346    11580     +234     
==========================================
+ Hits         8946     8947       +1     
- Misses       2400     2633     +233
Impacted Files Coverage Ξ”
Sources/TuistKit/Commands/BuildCommand.swift 0% <0%> (ΓΈ) ⬆️
Sources/TuistSupport/Errors/FatalError.swift 30% <0%> (-45%) ⬇️
...ation/Extensions/Observable+XcodeBuildOutput.swift 0% <0%> (ΓΈ) ⬆️
Sources/TuistKit/Commands/EditCommand.swift 0% <0%> (ΓΈ) ⬆️
Sources/TuistKit/Commands/VersionCommand.swift 0% <0%> (ΓΈ) ⬆️
Sources/TuistKit/Commands/InitCommand.swift 0% <0%> (ΓΈ) ⬆️
Sources/TuistSupport/Logging/OSLogHandler.swift 0% <0%> (ΓΈ)
...rces/TuistSupport/Logging/StandardLogHandler.swift 0% <0%> (ΓΈ)
Sources/TuistSupport/Logging/Logger.swift 0% <0%> (ΓΈ)
Sources/tuist/main.swift 0% <0%> (ΓΈ) ⬆️
... and 32 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Ξ” = absolute <relative> (impact), ΓΈ = not affected, ? = missing data
Powered by Codecov. Last update af7e75a...b07fa01. Read the comment docs.

@ollieatkinson ollieatkinson marked this pull request as ready for review March 5, 2020 22:10
Copy link
Collaborator

@kwridan kwridan left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks great overall - some minor comments. Thanks for pushing this through @ollieatkinson

One of the acceptance tests failed, I suspect its due to the error output format changing:

features/step_definitions/shared/fixtures.rb:5
Then tuist generate yields error "Error: Manifest not found at path ${ARG_PATH}"                 # features/step_definitions/shared/tuist.rb:29
The output error message:
Manifest not found at path /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/d20200305-5178-exn279
Does not contain the expected:
 Error: Manifest not found at path ${ARG_PATH}
(Minitest::Assertion)
 ./features/step_definitions/shared/tuist.rb:41:in `/tuist generate yields error "(.+)"/'
 features/generate.feature:41:in `Then tuist generate yields error "Error: Manifest not found at path ${ARG_PATH}"'

Sources/TuistSupport/Logging/DetailedLogHandler.swift Outdated Show resolved Hide resolved
Sources/TuistSupport/System/System.swift Outdated Show resolved Hide resolved
@ollieatkinson ollieatkinson merged commit c64ca73 into master Mar 10, 2020
@ollieatkinson ollieatkinson deleted the verbose-logging branch March 10, 2020 10:52
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Create verbose argument for all commands
3 participants