Test uistuck logs

[sahusanket]

No description provided.

[gemini-code-assist]

Code Review

This pull request introduces logging across several components, including ProgramLifecycleHttpHandler, ProgramLifecycleService, HttpRequestRouter, InternalServiceRequestHandler, and DefaultAccessEnforcer, to improve request and authorization observability. While these additions are valuable, logging high-frequency operations at the INFO level will cause severe log flooding and performance issues in production; these logs should be demoted to DEBUG or TRACE. Additionally, the feedback highlights a potential NullPointerException in InternalServiceRequestHandler when handling a null future cause, recommends using System.nanoTime() for monotonic elapsed time measurements, and suggests guarding verbose string operations with isDebugEnabled() to avoid unnecessary garbage collection.

[gemini-code-assist]

Logging at INFO level for every visibility check delegation will cause severe log flooding in production, as this is a high-frequency operation. It is highly recommended to use DEBUG or TRACE level instead.

Suggested change

	LOG.info("DefaultAccessEnforcer: delegating visibility check of {} entities to the authorization extension for principal: {}", difference.size(), principal.getName());
	LOG.debug("DefaultAccessEnforcer: delegating visibility check of {} entities to the authorization extension for principal: {}", difference.size(), principal.getName());

[gemini-code-assist]

Unconditionally logging the completion of visibility checks at INFO level will flood the logs. We should preserve the threshold-based warning logic (logTimeTakenAsWarn) and use DEBUG or TRACE for normal cases.

      String logLine = "DefaultAccessEnforcer: completed visibility check of {} entities for principal: {}. Time spent: {}ms";
      if (timeTaken > logTimeTakenAsWarn) {
        LOG.warn(logLine, difference.size(), principal.getName(), timeTaken);
      } else {
        LOG.debug(logLine, difference.size(), principal.getName(), timeTaken);
      }

References

1. When adding logging or observability improvements to existing code, avoid introducing unrelated logic changes or control flow alterations to ensure that the primary behavior of the system remains unchanged and to minimize the risk of regressions.

[gemini-code-assist]

If future.cause() is null, calling future.cause().getMessage() will throw a NullPointerException. We should safely handle a null cause, similar to the pattern used in HttpRequestRouter.java.

Suggested change

	LOG.error("Router [ClientCh:{}]: Failed to write response bytes to client TCP socket! Error: {}", clientChId, future.cause().getMessage());
	LOG.error("Router [ClientCh:{}]: Failed to write response bytes to client TCP socket! Error: {}", clientChId, future.cause() == null ? "unknown" : future.cause().getMessage());

[gemini-code-assist]

Logging every incoming HTTP request at INFO level in the router will cause severe log flooding and performance degradation under production workloads. This should be logged at DEBUG or TRACE level.

Suggested change

	LOG.info("Router [ClientCh:{}]: Received incoming request from client {} for uri: {} {}", clientChId, httpRequestChannel.remoteAddress(), request.method(), request.uri());
	LOG.debug("Router [ClientCh:{}]: Received incoming request from client {} for uri: {} {}", clientChId, httpRequestChannel.remoteAddress(), request.method(), request.uri());

[gemini-code-assist]

Logging successful forwarding of request bytes at INFO level for every request is extremely verbose and should be logged at DEBUG or TRACE level.

Suggested change

	LOG.info("Router [ClientCh:{}]: Successfully forwarded request bytes to backend service (AppFabric) channel.", clientChId);
	LOG.debug("Router [ClientCh:{}]: Successfully forwarded request bytes to backend service (AppFabric) channel.", clientChId);

[gemini-code-assist]

Logging request forwarding at INFO level for every request is too verbose. This should be logged at DEBUG or TRACE level.

Suggested change

	LOG.info("Router [ClientCh:{}]: Forwarding request to service endpoint: {} {}", httpRequestChannel.id().asShortText(), request.method(), request.uri());
	LOG.debug("Router [ClientCh:{}]: Forwarding request to service endpoint: {} {}", httpRequestChannel.id().asShortText(), request.method(), request.uri());

[gemini-code-assist]

This unconditionally maps, collects, and converts the program names to a string, which creates unnecessary garbage objects and can result in extremely large log messages if the batch size is large. Furthermore, logging this at INFO level can be very verbose. We should guard this with LOG.isDebugEnabled() and log it at DEBUG level instead.

    if (LOG.isDebugEnabled()) {
      String programNames = programs.stream().map(ProgramReference::getApplication).collect(Collectors.toList()).toString();
      LOG.debug("addProgramHistory: Executing accessEnforcer.isVisible checks for batch of {} programs: {}...", programs.size(), programNames);
    }

[gemini-code-assist]

Using System.currentTimeMillis() to measure elapsed time is not safe against system clock adjustments (e.g., NTP syncs). It is highly recommended to use System.nanoTime() for measuring durations, as it is monotonic. Also, consider logging this at DEBUG level to avoid log pollution.

Suggested change

	long startTime = System.currentTimeMillis();
	Set<? extends EntityId> visibleEntities = accessEnforcer.isVisible(new HashSet<>(programs),
	authenticationContext.getPrincipal());
	long duration = System.currentTimeMillis() - startTime;
	LOG.info("addProgramHistory: isVisible checks completed in {}ms. Visible entities count: {}/{}", duration, visibleEntities.size(), programs.size());
	long startTime = System.nanoTime();
	Set<? extends EntityId> visibleEntities = accessEnforcer.isVisible(new HashSet<>(programs), authenticationContext.getPrincipal());
	long duration = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTime);
	LOG.debug("addProgramHistory: isVisible checks completed in {}ms. Visible entities count: {}/{}", duration, visibleEntities.size(), programs.size());

[gemini-code-assist]

Logging every hit of the POST /runs endpoint at INFO level can cause significant log flooding in busy clusters, as this endpoint is frequently polled by the UI. This should be logged at DEBUG level instead.

Suggested change

	LOG.info("POST /runs endpoint hit in namespace {}. Batch request contains {} programs.", namespaceId, programs.size());
	LOG.debug("POST /runs endpoint hit in namespace {}. Batch request contains {} programs.", namespaceId, programs.size());

[gemini-code-assist]

Logging the completion of POST /runs at INFO level is also very verbose. This should be logged at DEBUG level.

Suggested change

	LOG.info("POST /runs completed: successfully returned runs history response for {} programs in namespace {}.", response.size(), namespaceId);
	LOG.debug("POST /runs completed: successfully returned runs history response for {} programs in namespace {}.", response.size(), namespaceId);