Weirdly formatted text in log with wasm-init

[Mackiovello]

To reproduce:

$ pwd
/home/erlend/rust/wasm-pack
$ mkdir myproject
$ cd myproject/
$ cargo init --lib
     Created library project
$ cd ..
$ cargo run -- init myproject/
    Finished dev [unoptimized + debuginfo] target(s) in 0.09s
     Running `target/debug/wasm-pack init myproject/`

| [1/8] Checking crate configuration...
Ensure that you have "wasm-bindgen" as a dependency in your Cargo.toml file:
[dependencies]
wasm-bindgen = "0.2"

wasm-pack.log

Jul 14 07:43:53.737 ERRO Ensure that you have "�[1m�[2mwasm-bindgen�[0m" as a dependency in your Cargo.toml file:
[dependencies]
wasm-bindgen = "0.2"

There are two problems here: "ERRO" should be "ERROR" and there is some encoding issue with what should be "wasm-bindgen".

I'm on Ubuntu 16.04

Locale, if that matters:

$ locale
LANG=en_US.UTF-8
LANGUAGE=en_US

[ashleygwilliams]

Thanks for filing! Could you let me know what version of wasm-pack you are using and what command you ran? That will help us track down what the issue is. We are not currently localizing the log so this is almost certainly a bug!

[Mackiovello]

Sure:

$ pwd
/home/erlend/rust/wasm-pack
$ git show
commit b0470b08e008b55b6c0f249888918b114befee8d
Merge: faed391 81e5868
Author: Michael Gattozzi <[email protected]>
Date:   Tue Jun 26 14:37:22 2018 -0400

    Merge pull request #195 from steveklabnik/patch-1

    Fix code example in README

$ mkdir myproject
$ cd myproject/
$ cargo init --lib
     Created library project
$ cd ..
$ cargo run -- init myproject/
   Compiling wasm-pack v0.4.0 (file:///home/erlend/rust/wasm-pack)
    Finished dev [unoptimized + debuginfo] target(s) in 3.25s
     Running `target/debug/wasm-pack init myproject/`

| [1/8] Checking crate configuration...
Ensure that you have "wasm-bindgen" as a dependency in your Cargo.toml file:
[dependencies]
wasm-bindgen = "0.2"

This is the exact sequence as above but with git show included so you can see the exact git commit I'm on. It's the latest master right now.

The weird thing is that it works fine if I run cat wasm-pack.log but it's incorrect if I open it in both Vim and VSCode. It would be good if someone could execute the exact steps above and then open myproject/wasm-pack.log to see if they can reproduce.

[ashleygwilliams]

oh thanks for the details @Mackiovello ! particularly that cat works fine. i'll be honest, in my testing of it i've only viewed the log with cat so this is almost certainly why i've missed this. yay character encoding!! lolsob

[mgattozzi]

Oh boy character encoding issues! Will try this out soon to see if I can reproduce

[callahad]

Not an encoding issue; those are ECMA-48 SGR codes. [1m is set bold, [2m is set half-brightness, and [0m is reset to default. Raw terminal output is getting dumped into the log file, including the formatting control codes to print "wasm-bindgen" in bold:

Notice the difference between less wasm-pack.log and less -R wasm-pack.log:

The fix is making sure that whatever is doing the logging is treating the log file as a file, rather than as a terminal.

[porylporyl]

Hi! I've actually been working on this one since last week, after discussing it with Ashley and finding it'd be a good first issue. I meant to write an update post yesterday but it got away from me.

In any case, the simplest solution for this seems to be just removing the encoding before throwing the message to the log. The message gets formatted in manifest.rs at the check_wasm_bindgen function, in the line
Error::crate_config(&format!( "Ensure that you have \"{}\" as a dependency in your Cargo.toml file:\n[dependencies]\nwasm-bindgen = \"0.2\"", style("wasm-bindgen").bold().dim() ))

Of course, we could just remove the style formatting all together and it'd solve this, but we probably want to preserve that so the program still looks nice in CLI. :p

the same crate that contains style() also has a convenient function-- strip_ansi_codes()-- that removes the format tags from a string.

Currently, I think the issue has to do with where we can address this in the order of events. The error message is formatted in manifest.rs, then thrown to error.rs to form an Error enum before it's passed back up to command.rs, logged using error!, has extra formatted text appended using PBAR.error() and then passed to main.rs to print to the CLI. We still want the formatted message to reach the CLI but it needs to be stripped before being pushed to the log. This is a bit of an issue since it's pushed to the log before it is printed to the CLI. Once it hits the error! macro as well, it steps through a bunch of functions in the slog library which puts further formatting out of our hands until it's finished actually pushing it to log.

I have a few solutions in mind currently, but I haven't implemented them yet since this is my first open source project and I'm not sure how much I'm allowed to adjust in the code's structure, in addition to being unsure how to do certain things in Rust just yet.

The best solution I can think of currently is to have some sort of function that takes the value rather than the reference to the Error enum, takes the message and runs it through strip_ansi_codes(), then passes that to error! to be pushed to log; leaving the original Error enum alone so it can be returned to main and printed to CLI with the formatting still intact. I think implementing a solution like this would be good if we're intending to make style formatting for the CLI format a standard, since it'd future-proof any other formatted messages by running them through the stripping function.

I might be overcomplicating this since it's my first issue, so if anyone knows a simpler method I'm absolutely open to hearing. Otherwise, I am going to continue trying to tackle this with Ashley's help today. :)

EDIT: oh, and I'm not totally sure about why we get "ERRO" rather than "ERROR" but I'll continue looking into it.

[mgattozzi]

Thinking of it we could clone it and strip the ansi codes from the clone only and then pass back the other one like normal. I think that's the easiest solution if it's cloneable (which my guess is that it should be)

[danwilhelm]

EDIT: oh, and I'm not totally sure about why we get "ERRO" rather than "ERROR" but I'll continue looking into it.

@porylporyl "ERRO" appears to be the correct short-level name used by slog. I assume this is to make the error levels line up nicely in the log file:

/// Official capitalized logging (and logging filtering) short level names
pub static LOG_LEVEL_SHORT_NAMES: [&'static str; 7] =
["OFF", "CRIT", "ERRO", "WARN", "INFO", "DEBG", "TRCE"];

From: https://github.com/slog-rs/slog/blob/61cebb3ee575e72f28c23e92d3e250322601d826/src/lib.rs#L2056

[ashleygwilliams]

we are going to be working towards a fix for this as we approach solving #298. i am going to close this specific issue as we will track progress in the mini RFC