CLI could not see Helidon version

[tomas-langer]

During HOL session, a user had a problem that CLI could not see version 2.3.2.
Using maven archetype worked just fine.

Worked OK from my own environment with the exact same command (my output below).

Environment:

mvn --version
Apache Maven 3.6.3 (cecedd343002696d0abb50b32b541b8a6ba2883f)
Maven home: C:\Program Files\JetBrains\IntelliJ IDEA 2020.3.1\plugins\maven\lib\maven3\bin\..
Java version: 15.0.1, vendor: Oracle Corporation, runtime: c:\Java\jdk-15.0.1
Default locale: pl_PL, platform encoding: Cp1250
OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

Dev output with debug:

helidon init --debug --version 2.3.2
Found maven executable C:\Program Files\JetBrains\IntelliJ IDEA 2020.3.1\plugins\maven\lib\maven3\bin\mvn.cmd
stale check forced (not found) for C:\Users\user\.helidon\cache\latest
Looking up latest Helidon version
executing [java, -XX:TieredStopAtLevel=1, -XX:CICompilerCount=2, -jar, C:\Users\user\.helidon\plugins\cli-plugins-d4b7bb55.jar, UpdateMetadata, --debug, --baseUrl, https://helidon.io/cli-data, --cacheDir, C:\Users\user\.helidon\cache, --cliVersion, 2.2.3, --maxAttempts, 1]
Executing command: java -XX:TieredStopAtLevel=1 -XX:CICompilerCount=2 -jar C:\Users\user\.helidon\plugins\cli-plugins-d4b7bb55.jar UpdateMetadata --debug --baseUrl https://helidon.io/cli-data --cacheDir C:\Users\user\.helidon\cache --cliVersion 2.2.3 --maxAttempts 1
Using Helidon version 2.3.2
Helidon flavor
  (1) SE
  (2) MP
Enter selection (Default: 1): 2
stale check forced (not found) for C:\Users\user\.helidon\cache\2.3.2\.lastUpdate
Updating metadata for Helidon version 2.3.2
executing [java, -XX:TieredStopAtLevel=1, -XX:CICompilerCount=2, -jar, C:\Users\user\.helidon\plugins\cli-plugins-d4b7bb55.jar, UpdateMetadata, --debug, --baseUrl, https://helidon.io/cli-data, --cacheDir, C:\Users\user\.helidon\cache, --version, 2.3.2, --cliVersion, 2.2.3, --maxAttempts, 3]
Executing command: java -XX:TieredStopAtLevel=1 -XX:CICompilerCount=2 -jar C:\Users\user\.helidon\plugins\cli-plugins-d4b7bb55.jar UpdateMetadata --debug --baseUrl https://helidon.io/cli-data --cacheDir C:\Users\user\.helidon\cache --version 2.3.2 --cliVersion 2.2.3 --maxAttempts 3

Helidon version 2.3.2 not found.

Dev output with debug on a working machine:

helidon init --debug --version 2.3.2
Found maven executable /Users/tomas/bin/apache-maven-3.6.3/bin/mvn
stale check is false for /Users/tomas/.helidon/cache/latest (last: 09-16-2021 14:35:56 CEST, now: 09-16-2021 14:38:40 CEST, elapsed: 0 days 00:02:43, remain: 0 days 11:57:16)
stale check is false for /Users/tomas/.helidon/cache/2.3.3/.lastUpdate (last: 09-16-2021 14:35:54 CEST, now: 09-16-2021 14:38:40 CEST, elapsed: 0 days 00:02:45, remain: 0 days 11:57:14)
stale check is false (retry) for /Users/tomas/.helidon/cache/latest
stale check is false (retry) for /Users/tomas/.helidon/cache/2.3.3/.lastUpdate

Version 2.2.3 of this CLI is now available.
Please see https://github.com/oracle/helidon-build-tools/blob/master/helidon-cli/CHANGELOG.md to update.

Using Helidon version 2.3.2
Helidon flavor
  (1) SE
  (2) MP
Enter selection (Default: 1): 2
stale check forced (not found) for /Users/tomas/.helidon/cache/2.3.2/.lastUpdate
Updating metadata for Helidon version 2.3.2
executing [java, -XX:TieredStopAtLevel=1, -XX:CICompilerCount=2, -jar, /Users/tomas/.helidon/plugins/cli-plugins-17f7cba0.jar, UpdateMetadata, --debug, --baseUrl, https://helidon.io/cli-data, --cacheDir, /Users/tomas/.helidon/cache, --version, 2.3.2, --cliVersion, 2.2.0, --maxAttempts, 3]
Executing command: java -XX:TieredStopAtLevel=1 -XX:CICompilerCount=2 -jar /Users/tomas/.helidon/plugins/cli-plugins-17f7cba0.jar UpdateMetadata --debug --baseUrl https://helidon.io/cli-data --cacheDir /Users/tomas/.helidon/cache --version 2.3.2 --cliVersion 2.2.0 --maxAttempts 3
Process ID: 82005
Waiting for completion, pid=82005, timeout=30, unit=SECONDS
Select archetype
  (1) bare | Minimal Helidon MP project suitable to start from scratch
  (2) quickstart | Sample Helidon MP project that includes multiple REST operations
  (3) database | Helidon MP application that uses JPA with an in-memory H2 database

[tomas-langer]

Also the link in my output does not exist:
https://github.com/oracle/helidon-build-tools/blob/master/helidon-cli/CHANGELOG.md

[tomas-langer]

Tried with latest CLI version, works good. Output:

helidon init --debug --version 2.3.2
Found maven executable /Users/tomas/bin/apache-maven-3.6.3/bin/mvn
stale check is false for /Users/tomas/.helidon/cache/latest (last: 09-16-2021 14:38:42 CEST, now: 09-16-2021 15:08:42 CEST, elapsed: 0 days 00:30:00, remain: 0 days 11:29:59)
stale check is false for /Users/tomas/.helidon/cache/2.3.3/.lastUpdate (last: 09-16-2021 14:35:54 CEST, now: 09-16-2021 15:08:42 CEST, elapsed: 0 days 00:32:47, remain: 0 days 11:27:12)
no update available
Using Helidon version 2.3.2
Helidon flavor
  (1) SE
  (2) MP
Enter selection (Default: 1): 2
stale check forced (not found) for /Users/tomas/.helidon/cache/2.3.2/.lastUpdate
Updating metadata for Helidon version 2.3.2
unpacked /Users/tomas/.helidon/plugins/cli-plugins-d4b7bb55.jar
executing [java, -XX:TieredStopAtLevel=1, -XX:CICompilerCount=2, -jar, /Users/tomas/.helidon/plugins/cli-plugins-d4b7bb55.jar, UpdateMetadata, --debug, --baseUrl, https://helidon.io/cli-data, --cacheDir, /Users/tomas/.helidon/cache, --version, 2.3.2, --cliVersion, 2.2.3, --maxAttempts, 3]
Executing command: java -XX:TieredStopAtLevel=1 -XX:CICompilerCount=2 -jar /Users/tomas/.helidon/plugins/cli-plugins-d4b7bb55.jar UpdateMetadata --debug --baseUrl https://helidon.io/cli-data --cacheDir /Users/tomas/.helidon/cache --version 2.3.2 --cliVersion 2.2.3 --maxAttempts 3
Process ID: 82878
Waiting for completion, pid=82878, timeout=30, unit=SECONDS
Select archetype
  (1) bare | Minimal Helidon MP project suitable to start from scratch
  (2) quickstart | Sample Helidon MP project that includes multiple REST operations
  (3) database | Helidon MP application that uses JPA with an in-memory H2 database

[dalexandrov]

local settings.xml issue?

[romain-grecourt]

Seems like it gave up without an error message, I'm not too familiar with the code that does this.

@tomas-langer the URL has been fixed in the latest release, but it's only going to take effect in the next upgrade.
@dalexandrov settings.xml is not involved in the metadata check.

[tomas-langer]

I can see that when I run UpdateMetadata in IDE, it prints nice debug messages. The output is lost when running within CLI.
We should at least make sure the output is visible when we run cli with --debug to be able to troubleshoot such issues

[tomas-langer]

This is my output when I connect through VPN:

stale check forced (not found) for /Users/tomas/.helidon/cache/2.3.2/.lastUpdate
Updating metadata for Helidon version 2.3.2
executing [java, -XX:TieredStopAtLevel=1, -XX:CICompilerCount=2, -jar, /Users/tomas/.helidon/plugins/cli-plugins-d4b7bb55.jar, UpdateMetadata, --debug, --baseUrl, https://helidon.io/cli-data, --cacheDir, /Users/tomas/.helidon/cache, --version, 2.3.2, --cliVersion, 2.2.3, --maxAttempts, 3]
Executing command: java -XX:TieredStopAtLevel=1 -XX:CICompilerCount=2 -jar /Users/tomas/.helidon/plugins/cli-plugins-d4b7bb55.jar UpdateMetadata --debug --baseUrl https://helidon.io/cli-data --cacheDir /Users/tomas/.helidon/cache --version 2.3.2 --cliVersion 2.2.3 --maxAttempts 3
Process ID: 16819
Waiting for completion, pid=16819, timeout=30, unit=SECONDS

Helidon version 2.3.2 not found.

[romain-grecourt]

Is the VPN output with the CLI or IDE ?

[tomas-langer]

CLI

[tomas-langer]

Identified where we throw away the debug output of the plugins:
Class Plugins, line 113 - method execute - the message consumer is set to Plugins::devNull

[romain-grecourt]

Looks like this variant of the execute method is designed to throw await the output.

Usages in Metadata shows that the other variant is used and output shouldn't be thrown away:

if (debugPlugin) {
    args.add("--debug");
    Plugins.execute(PLUGIN_NAME, args, PLUGIN_MAX_WAIT_SECONDS, Metadata::info);
} else {
    Plugins.execute(PLUGIN_NAME, args, PLUGIN_MAX_WAIT_SECONDS);
}

debugPlugin is set by calling Metadata.builder().debugPlugin(), see this

The usage of Metadata.builder() is in CommonOptions:

metadata = Metadata.builder()
     .url(metadataUrl)
     .updateFrequency(config.checkForUpdatesIntervalHours())
     .build();

I'm thinking the problem might be that It doesn't call .debugPlugin() with the value of --debug, also the log level used should probably be debug instead of info.