Starting pants shows useless "Initializing Nailgun pool ..." log lines

[huonw]

Describe the bug

It seems that Pants recently (between 2.21 and 2.22) started always logging two log lines about initializing Nailgun. These seem of low interest in most circumstances, and thus not worth telling the user about.

Reproducer:

cd $(mktemp -d)
touch pants.toml

echo "OK: 2.21"
PANTS_VERSION=2.21.0 pants --no-pantsd version

echo
echo "OK: 2.22.0.dev3"
PANTS_VERSION=2.22.0.dev3 pants --no-pantsd version

echo
echo "BUG: 2.22.0a0"
PANTS_VERSION=2.22.0a0 pants --no-pantsd version

echo
echo "BUG: 2.22"
PANTS_VERSION=2.22.0 pants --no-pantsd version

Output:

OK: 2.21
2.21.0

OK: 2.22.0.dev3
2.22.0.dev3

BUG: 2.22.0a0
13:03:39.51 [INFO] Initializing Nailgun pool for 16 processes...
13:03:42.55 [INFO] Initializing Nailgun pool for 16 processes...
2.22.0a0

BUG: 2.22
13:03:45.59 [INFO] Initializing Nailgun pool for 16 processes...
13:03:48.71 [INFO] Initializing Nailgun pool for 16 processes...
2.22.0

Pants version

2.22.0a0 and newer

OS
macOS

Additional info
N/A

[huonw]

The relevant diff of releases is: release_2.22.0.dev3...release_2.22.0a0

Looks like #20946 introduced this line, after turning some other logs down.

[cburroughs]

I've also wondered, why does the same log message appear twice? Do we initialize twice?

[huonw]

I'm not sure yet.

Initial investigation:

Extra factor, with pantsd (i.e. no --no-pantsd flag) it only appears once:

cd $(mktemp -d)
touch pants.toml

echo "First"
PANTS_VERSION=2.22.0 pants version

echo
echo "Second"
PANTS_VERSION=2.22.0 pants version

First
09:12:21.26 [INFO] Initializing scheduler...
09:12:21.28 [INFO] Initializing Nailgun pool for 16 processes...
09:12:21.43 [INFO] Scheduler initialized.
2.22.0

Second
2.22.0

There's a few layers of functions from NailgunPool::new to EngineInitializer.setup_graph that are only called in one place (and not in a loop, AFAICT):

• NailgunPool::new in pe_nailgun::CommandRunner::new:

  pants/src/rust/engine/process_execution/pe_nailgun/src/lib.rs

  Line 108 in db9cf59

  nailgun_pool: NailgunPool::new(

• ... which is called in Core::make_leaf_runner:

  pants/src/rust/engine/src/context.rs

  Line 261 in db9cf59

  let nailgun_runner = pe_nailgun::CommandRunner::new(

• ... which is called in Core::make_command_runners:

  pants/src/rust/engine/src/context.rs

  Line 419 in db9cf59

  let leaf_runner = Self::make_leaf_runner(

• ... which is called in Core::new:

  pants/src/rust/engine/src/context.rs

  Line 625 in db9cf59

  let command_runners = Self::make_command_runners(

• ... which is called in scheduler_create:

  pants/src/rust/engine/src/externs/interface.rs

  Line 801 in db9cf59

  Core::new(

• ... which is called in Scheduler.__init__:

  pants/src/python/pants/engine/internals/scheduler.py

  Line 235 in db9cf59

  self._py_scheduler = native_engine.scheduler_create(

• ... which is called in EngineInitializer.setup_graph_extended:

  pants/src/python/pants/init/engine_initializer.py

  Line 340 in db9cf59

  scheduler = Scheduler(

• ... which is called in EngineInitializer.setup_graph:

  pants/src/python/pants/init/engine_initializer.py

  Line 197 in db9cf59

  return EngineInitializer.setup_graph_extended(

Finally, EngineInitializer.setup_graph is called in three places:

1. create_bootstrap_scheduler:

   pants/src/python/pants/init/options_initializer.py

   Line 118 in db9cf59

   EngineInitializer.setup_graph(

2. PantsDaemonCore._initialize:

   pants/src/python/pants/pantsd/pants_daemon_core.py

   Line 106 in db9cf59

   self._scheduler = EngineInitializer.setup_graph(

3. LocalPantsRunner.create:

   pants/src/python/pants/bin/local_pants_runner.py

   Line 123 in db9cf59

   scheduler = EngineInitializer.setup_graph(

Thus, for why things happen twice, the surface level is that the scheduler is initialised/graph is set-up for both bootstrapping (call site 1 is eventually also called in or before LocalPantsRunner.create too) and for "real" (call sites 2 and 3).

For why Pantsd behaves differently... my current hypothesises are:

1. turning off pantsd goes down an extra codepath??
2. initialising pantsd still does this twice, but the log line from one of them is hidden??