FWD » Core Development » Runtime Infrastructure

import com.goldencode.p2j.util.ConfigItem;

   /**

    * Smallest configured value not treated as a probable seconds-for-milliseconds mistake.  The

    * fastest client callback ever measured is over a second, so anything under this is far more

    * likely to be a unit error than a deliberate setting.

    */

   private static final long MIN_PLAUSIBLE_STARTUP_MS = 1000L;

   /** Largest configured value not treated as a probable unit mistake (one hour). */

   private static final long MAX_PLAUSIBLE_STARTUP_MS = 3_600_000L;

   /**

    * Effective client-startup timeout in MILLISECONDS, resolved once from the directory.  Volatile

    * because the first spawn to arrive resolves it and every later thread reads it.

    */

   private static volatile long clientStartupTimeoutMs = -1L;

   /**

    * Milliseconds to wait for a spawned client to report ready.

    * <p>

    * Read from the directory node {@code clientStartupTimeout} (web client section), in

    * MILLISECONDS for consistency with the sibling {@code pollTimeout} and

    * {@code connectionTestTimeout} nodes.  When the node is absent the built-in

    * {@link #CLIENT_STARTUP_TIMEOUT_SEC} seconds default applies.

    * </p>

    * <p>

    * Resolved once and reported at WARNING so the value in force is never in doubt, and a value

    * that looks like the wrong unit is called out rather than applied silently:  reading 120 as

    * milliseconds would destroy every client instantly, and 120000 as seconds would mean nothing

    * was ever reaped for 33 hours.  Both failures are near-impossible to diagnose from behaviour.

    * </p>

    *

    * @return   The timeout in milliseconds.

    */

   public static long getClientStartupTimeoutMs()

   {

      long cached = clientStartupTimeoutMs;

      if (cached > 0L)

      {

         return cached;

      }

      long resolved = CLIENT_STARTUP_TIMEOUT_SEC * 1000L;

      String source = "built-in default (directory node 'clientStartupTimeout' absent)";

      try

      {

         Integer configured = ConfigItem.CLIENT_STARTUP_TIMEOUT.read(null);

         if (configured != null && configured.intValue() > 0)

         {

            long ms = configured.longValue();

            if (ms < MIN_PLAUSIBLE_STARTUP_MS)

            {

               LOG.log(Level.SEVERE,

                       "[SPAWN-CFG] directory node 'clientStartupTimeout'=%d is in MILLISECONDS "

                       + "and %dms would destroy every client before it could start. This looks "

                       + "like seconds; did you mean %d? Using the built-in %ds default instead.",

                       configured,

                       configured,

                       Long.valueOf(ms * 1000L),

                       Integer.valueOf(CLIENT_STARTUP_TIMEOUT_SEC));

            }

            else if (ms > MAX_PLAUSIBLE_STARTUP_MS)

            {

               LOG.log(Level.SEVERE,

                       "[SPAWN-CFG] directory node 'clientStartupTimeout'=%dms is over an hour, so "

                       + "a client that never starts would never be reaped. Applying it as asked, "

                       + "but check the unit -- this node is MILLISECONDS.",

                       configured);

               resolved = ms;

               source = "directory node 'clientStartupTimeout' (implausibly large)";

            }

            else

            {

               resolved = ms;

               source = "directory node 'clientStartupTimeout'";

            }

         }

      }

      catch (Throwable t)

      {

         // A directory problem must not stop clients being spawned;  fall back and say so.

         LOG.log(Level.WARNING,

                 "[SPAWN-CFG] could not read 'clientStartupTimeout' from the directory, using "

                 + "the built-in %ds default",

                 Integer.valueOf(CLIENT_STARTUP_TIMEOUT_SEC),

                 t);

      }

      clientStartupTimeoutMs = resolved;

      LOG.log(Level.WARNING,

              "[SPAWN-CFG] client startup timeout = %dms (%.1fs)  (source: %s)",

              Long.valueOf(resolved),

              Double.valueOf(resolved / 1000.0),

              source);

      return resolved;

   }

   /**

    * Wait for the spawned client to report ready, and make an expiry impossible to miss.

    * <p>

    * {@code CountDownLatch.await(timeout, unit)} returns false when the wait expired rather than

    * the latch firing.  Both call sites used to discard that boolean, so a client that never

    * called back produced NO log at all -- the failure could only be inferred from a downstream

    * symptom such as the browser being handed a dead port.  It is now reported at SEVERE with the

    * timeout that was applied and where that value came from.

    * </p>

    *

    * @param    where

    *           Call site, so the two waits are distinguishable in the log.

    *

    * @return   {@code true} if the client reported ready, {@code false} if the wait expired.

    */

   private boolean awaitClientStartup(String where)

   {

      long timeoutMs = getClientStartupTimeoutMs();

      long start = System.nanoTime();

      boolean signalled = false;

      try

      {

         signalled = clientStartupCountDown.await(timeoutMs, TimeUnit.MILLISECONDS);

      }

      catch (InterruptedException ignored)

      {

         LOG.log(Level.WARNING,

                 "[SPAWN-TIMEOUT] %s: interrupted after %dms while waiting for client startup",

                 where,

                 Long.valueOf((System.nanoTime() - start) / 1_000_000L));

         return false;

      }

      if (!signalled)

      {

         // The event this whole investigation could not see.

         LOG.log(Level.SEVERE,

                 "[SPAWN-TIMEOUT] CLIENT STARTUP TIMEOUT at %s: no ready callback within %dms "

                 + "(waited %dms) for osUser=%s -- the client is being DESTROYED even though it "

                 + "may still be booting. Raise the directory node 'clientStartupTimeout' "

                 + "(MILLISECONDS) if the client simply needs longer under load.",

                 where,

                 Long.valueOf(timeoutMs),

                 Long.valueOf((System.nanoTime() - start) / 1_000_000L),

                 getBuildParams().getOsUser());

      }

      return signalled;

   }

    * System.nanoTime() at which the spawner process was forked, so clientIsReady() can report how

    * long the client took to call back.  Volatile: written by the spawning thread, read by the

    * network thread that delivers the callback.

    */

   private volatile long forkAtNanos = 0L;

   /**

      long tSpawnStart = System.nanoTime();

      long allocNanos = 0L;

         allocNanos = System.nanoTime() - tSpawnStart;

            // No free port.  This is the port pool being exhausted, NOT a client that failed to

            // start -- the two look identical from the browser and must not be conflated.

            LOG.log(Level.WARNING,

                    "[SPAWN] ALLOC_FAIL osUser=%s | alloc=%dms | no free port in the pool",

                    buildParams.getOsUser(),

                    Long.valueOf(allocNanos / 1_000_000L));

      long tFork = System.nanoTime();

      forkAtNanos = System.nanoTime();

      long forkNanos = forkAtNanos - tFork;

                                                           awaitClientStartup("spawnLocal");

      long waitNanos = System.nanoTime() - forkAtNanos;

      // The verdict line.  exit==0 with ready==false means the spawner did its job and the client

      // JVM never called back within CLIENT_STARTUP_TIMEOUT_SEC -- i.e. the failure is in client

      // start-up, not in spawning, port allocation or account creation.

      String outcome = ready ? "READY"

                             : (exitCode.intValue() == 0 ? "NOT_READY_CLIENT_SILENT" : "SPAWN_ERR");

      LOG.log(Level.WARNING,

              "[SPAWN] %s exit=%d ready=%b | alloc=%dms fork=%dms waitClient=%dms total=%dms "

              + "| clientStartupTimeoutMs=%d osUser=%s",

              outcome,

              exitCode,

              Boolean.valueOf(ready),

              Long.valueOf(allocNanos / 1_000_000L),

              Long.valueOf(forkNanos / 1_000_000L),

              Long.valueOf(waitNanos / 1_000_000L),

              Long.valueOf((System.nanoTime() - tSpawnStart) / 1_000_000L),

              Long.valueOf(getClientStartupTimeoutMs()),

              getBuildParams().getOsUser());

         awaitClientStartup("spawnRemote");

      long afterForkMs = forkAtNanos > 0L

         ? (System.nanoTime() - forkAtNanos) / 1_000_000L

         : -1L;

      // The exact moment the client became usable.  Paired with [SPAWN], this separates "client

      // was slow but arrived" from "client never arrived".

      LOG.log(Level.WARNING,

              "[SPAWN-CB] client called back afterForkMs=%d osUser=%s",

              Long.valueOf(afterForkMs),

              getBuildParams().getOsUser());

      long tAlloc = System.nanoTime();

      int probes = 0;

               probes++;

                  // Nothing is listening:  the port is free and this is the one we will use.

         LOG.log(Level.WARNING,

                 "[SPAWN-ALLOC] FAIL no free port after %d probe(s) in %dms (pool exhausted)",

                 Integer.valueOf(probes),

                 Long.valueOf((System.nanoTime() - tAlloc) / 1_000_000L));

      // Port secured.  `discarded` counts ports found already in use;  a large value means the

      // pool is filling up with clients that were allocated a port and never released it.

      LOG.log(Level.WARNING,

              "[SPAWN-ALLOC] port=%d probed=%d discarded=%d took=%dms",

              Integer.valueOf(webClientConfig.getPort()),

              Integer.valueOf(probes),

              Integer.valueOf(testedWebClientConfigs.size()),

              Long.valueOf((System.nanoTime() - tAlloc) / 1_000_000L));

      // Must track the CONFIGURED timeout, not the built-in default:  a raised startup timeout

      // with a fixed 30s cleaner would free the port out from under a client that is still

      // booting, and the next allocation would hand the same port to someone else.

      cleanerTimer.schedule(cleaner, ClientSpawner.getClientStartupTimeoutMs());

      if (fields == null)

      {

         // The caller passes CLIENT_UUID_LOGIN_PARAMS.remove(uuid), which is null when the entry

         // was never registered or has already been consumed -- e.g. a client calling back after

         // its spawn was abandoned.  This used to NPE and kill the session;  report it and carry

         // on with no login params, which is what an unregistered client should get anyway.

         LOG.log(Level.WARNING,

                 "[SPAWN-CB] login params missing for a client callback (spawn abandoned, or a "

                 + "duplicate callback for the same uuid) -- continuing with none");

         return validatedParams;

      }

      long tReq = System.nanoTime();

      // Outer boundary:  what the browser's POST /gui actually cost and how it ended.

      LOG.log(Level.WARNING,

              "[SPAWN-REQ] uuid=%s exit=%d totalMs=%d",

              clientUuid,

              Integer.valueOf(exitCode),

              Long.valueOf((System.nanoTime() - tReq) / 1_000_000L));

   public static final ConfigItem<Integer> POLL_TIMEOUT =

   /**

    * MILLISECONDS to wait for a freshly spawned web client to report itself ready, before the

    * server gives up and destroys it.  Absent from the directory, {@code ClientSpawner}'s built-in

    * default applies.

    * <p>

    * Milliseconds, for consistency with the sibling nodes in this section ({@link #POLL_TIMEOUT},

    * {@link #CONNECTION_TEST_TIMEOUT}).  A value that looks like seconds is reported as a probable

    * unit mistake rather than silently applied -- see

    * ClientSpawner.getClientStartupTimeoutMs().

    * <p>

    * This bounds CLIENT BOOT, which under load has a long tail:  a value below the tail destroys

    * healthy clients mid-start-up and makes the caller retry, which adds load and lengthens the

    * tail further.  See ClientSpawner.getClientStartupTimeoutSec().

    * </p>

    */

   public static final ConfigItem<Integer> CLIENT_STARTUP_TIMEOUT =

      new ConfigItem<>(Integer.class, "clientStartupTimeout", "", "", "", Type.WEB_CLIENT);