[rust] Support different output types (logger, json, shell) in Selenium Manager (#11365)

[bonigarcia]

Description

This PR implements the flag --output for Selenium Manager. The accepted values for this flag are:

• LOGGER : Usual log traces (INFO, WARN, etc.) used in the CLI. Default value.
• JSON : Custom JSON notation (see below).
• SHELL : Minimal Unix-like output (i.e., only full path when the driver is resolved or an error message if not).

To simplify things, the implemented JSON notation in this PR is simpler than proposed in #11365. The JSON basically contains the logs (level, timestamp, and message) displayed by Selenium Manager.

The bindings can invoke Selenium Manager using --output json and try parse its output. Then, the protocol to interpret the parsed JSON is as follows:

• When the return code is 0: The last (and only) INFO message contains the driver path (when in future releases Selenium Manager also manages browsers, this message can be the browser path).
• When the return code is different than 0: The last (and only) ERROR message contains the error message to throw an exception to the user.

In both cases, the WARN messages can be displayed to the user, since they contain some warning to the users (e.g., when a fallback is used to resolve the driver). In principle, the DEBUG and TRACE logs can safely ignored in the bindings.

Does it make sense?

An example of the JSON output is as follows (running Selenium Manager from the source code with Cargo):

> cargo run -- --browser chrome --output json
{
  "logs": [
    {
      "level": "TRACE",
      "timestamp": 1673373731,
      "message": "Reading metadata from C:\\Users\\boni\\.cache\\selenium\\selenium-manager.json"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673373731,
      "message": "Using shell command to find out chrome version"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673373731,
      "message": "Running cmd command: \"wmic datafile where name='%PROGRAMFILES:\\\\=\\\\\\\\%\\\\\\\\Google\\\\\\\\Chrome\\\\\\\\Application\\\\\\\\chrome.exe' get Version /value\""
    },
    {
      "level": "DEBUG",
      "timestamp": 1673373731,
      "message": "Output { status: ExitStatus(ExitStatus(0)), stdout: \"\\r\\r\\n\\r\\r\\nVersion=108.0.5359.125\\r\\r\\n\\r\\r\\n\\r\\r\\n\\r\\r\\n\", stderr: \"\" }"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673373731,
      "message": "The version of chrome is 108.0.5359.125"
    },
    {
      "level": "TRACE",
      "timestamp": 1673373731,
      "message": "Writing metadata to C:\\Users\\boni\\.cache\\selenium\\selenium-manager.json"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673373731,
      "message": "Detected browser: chrome 108"
    },
    {
      "level": "TRACE",
      "timestamp": 1673373731,
      "message": "Reading metadata from C:\\Users\\boni\\.cache\\selenium\\selenium-manager.json"
    },
    {
      "level": "TRACE",
      "timestamp": 1673373731,
      "message": "Driver TTL is valid. Getting chromedriver version from metadata"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673373731,
      "message": "Required driver: chromedriver 108.0.5359.71"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673373731,
      "message": "chromedriver 108.0.5359.71 already in the cache"
    },
    {
      "level": "INFO",
      "timestamp": 1673373731,
      "message": "C:\\Users\\boni\\.cache\\selenium\\chromedriver\\win32\\108.0.5359.71\\chromedriver.exe"
    }
  ]
}

Motivation and Context

Feature requested on #11365. Discussed at the Selenium TLC Meeting.

Types of changes

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Breaking change (fix or feature that would cause existing functionality to change)

Checklist

• I have read the contributing document.
• My change requires a change to the documentation.
• I have updated the documentation accordingly.
• I have added tests to cover my changes.
• All new and existing tests passed.

[titusfortner]

The consumer of the json output should be the bindings. As such, we should be able to get the information we want to provide the user without iteration or heavy lifting outside of the binary (the point of having a separate binary is so we don't have to have to create identical logic in each of the bindings).

You mentioned that DEBUG and TRACE can be ignored in bindings, but then the example shows them. Perhaps we can do similar to what we do now and only show them if --debug is passed?

This is the kind of logic the bindings need:

if logging.debug
  args.add('--debug')
result = execute(selenium-manager, args)
if result.code > 0
  throw result.error

log result.logs
return result.value

I also think logs should be formatted as a string (similar to how webdriver spec does stack traces instead of a nested array.

So I'd prefer to see this structure:

{"value": "/path/to/driver",
"code": 0,
"logs": "Error getting version of chromedriver 110. Retrying with chromedriver 109 (attempt 1/5)"
}

or

{"value": "Error Message",
"code": 1,
}

Then if --debug is turned on, then the logs would include each line of DEBUG info (do not need the level or the timestamp, just the message):

"Line 1\nLine 2\nLine 3\nLine 4"

[diemol]

You mentioned that DEBUG and TRACE can be ignored in bindings, but then the example shows them. Perhaps we can do similar to what we do now and only show them if --debug is passed?

I assume that was merely informative, as the bindings will get that information back. Right, @bonigarcia?

[bonigarcia]

I assume that was merely informative, as the bindings will get that information back. Right, @bonigarcia?

@diemol Yes, that info is informative. I am not sure if the bindings are going to require that info. As @titusfortner suggested, I have just committed a second patch to this PR to flush these logs (DEBUG and TRACE) in the JSON only when the flags --debug and --trace are specified.

[diemol]

A minor comment from my side.

[bonigarcia]

@titusfortner To simplify things in the bindings, I have just added another patch to include the result code and message. See some examples:

% cargo run -- --browser chrome --output json

{
  "logs": [
    {
      "level": "INFO",
      "timestamp": 1673435421,
      "message": "/Users/bonigarcia/.cache/selenium/chromedriver/mac-arm64/108.0.5359.71/chromedriver"
    }
  ],
  "result": {
    "code": 0,
    "message": "/Users/bonigarcia/.cache/selenium/chromedriver/mac-arm64/108.0.5359.71/chromedriver"
  }
}

% cargo run -- --browser chrome --output json --debug

{
  "logs": [
    {
      "level": "DEBUG",
      "timestamp": 1673435452,
      "message": "Using shell command to find out chrome version"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673435452,
      "message": "Running sh command: \"/Applications/Google\\\\ Chrome.app/Contents/MacOS/Google\\\\ Chrome --version\""
    },
    {
      "level": "DEBUG",
      "timestamp": 1673435452,
      "message": "Output { status: ExitStatus(unix_wait_status(0)), stdout: \"Google Chrome 108.0.5359.124 \\n\", stderr: \"\" }"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673435452,
      "message": "The version of chrome is 108.0.5359.124"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673435452,
      "message": "Detected browser: chrome 108"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673435452,
      "message": "Required driver: chromedriver 108.0.5359.71"
    },
    {
      "level": "DEBUG",
      "timestamp": 1673435452,
      "message": "chromedriver 108.0.5359.71 already in the cache"
    },
    {
      "level": "INFO",
      "timestamp": 1673435452,
      "message": "/Users/bonigarcia/.cache/selenium/chromedriver/mac-arm64/108.0.5359.71/chromedriver"
    }
  ],
  "result": {
    "code": 0,
    "message": "/Users/bonigarcia/.cache/selenium/chromedriver/mac-arm64/108.0.5359.71/chromedriver"
  }
}

% cargo run -- --browser chrome --output json --browser-version canary

{
  "logs": [
    {
      "level": "WARN",
      "timestamp": 1673435485,
      "message": "Error getting version of chromedriver 110. Retrying with chromedriver 109 (attempt 1/5)"
    },
    {
      "level": "INFO",
      "timestamp": 1673435487,
      "message": "/Users/bonigarcia/.cache/selenium/chromedriver/mac-arm64/109.0.5414.74/chromedriver"
    }
  ],
  "result": {
    "code": 0,
    "message": "/Users/bonigarcia/.cache/selenium/chromedriver/mac-arm64/109.0.5414.74/chromedriver"
  }
}

% cargo run -- --browser wrong --output json

{
  "logs": [
    {
      "level": "ERROR",
      "timestamp": 1673436121,
      "message": "Invalid browser name: wrong"
    }
  ],
  "result": {
    "code": 65,
    "message": "Invalid browser name: wrong"
  }
}

[bonigarcia]

This PR contains a couple of tests to assess this feature. I think something similar to this should be done in the bindings (i.e., checking result.code and result.message from the parsed JSON).

[titusfortner]

I get we shouldn't optimize for what we haven't implemented yet, but if we know we're going to be returning browser location at some point, then we know just having a single message line is insufficient. In logger mode it can just be another info line, and for shell most likely it's going to actually need to be two subsequent calls, once for browser and once for driver. In json mode, though we can use a different key name instead of a common message key.

The logging focus still makes it hard to parse. The user doesn't care about timestamps or levels, they just want the result and to see any important caveats (warnings). We shouldn't need to write the same method in 5 different languages in order to parse an array of objects to pull out and reformat the info the user wants to see.

How about by default we have an array of warning strings without the duplicated info string and without the timestamps?

{
  "logs": ["Error getting version of chromedriver 110. Retrying with chromedriver 109 (attempt 1/5)"],
  "result": {
    "code": 0,
    "driver_path": "/Users/bonigarcia/.cache/selenium/chromedriver/mac-arm64/109.0.5414.74/chromedriver"
  }
}

[diemol]

I think the timestamp is important since Selenium Manager is used in the Grid as well. And eventually it could help to debug issues on tests executed in CI or similar.

Which duplicated info string do you mean?

[titusfortner]

Grid should be logging it with Java timestamps, and it's not like each microsecond step needs its own stamp here.
The only thing logged as info shows up in log and in output. Making the log not usable without a lot of parsing.

[bonigarcia]

Removing the timestamp in Rust is straightforward. Ignoring that info from the bindings is also straightforward, IMO. If there is a chance that that info can be helpful in some scenario (e.g., Grid or other third-party), my bet is to leave the JSON as it is now. It is a tiny detail, IMO.

[diemol]

I think if we want Selenium Manager to be used in the future by third parties, we should have a structured log (which includes a time stamp), and discarding information is easier than adding it when a wide audience is using the tool.

[titusfortner]

Selenium has a history of trying to support lots of theoretical use cases instead instead of making the primary known case straightforward. I guess I'm not going to be the one implementing it, so I'll leave the parsing logic to you.

[diemol]

Sounds good, so we can leave it there and a client using Selenium Manager can ignore the values if desired.