Log failing calls to health indicators

[ttddyy]

This is similar to #22509 to improve root cause analysis when probe endpoints returned non 200 response.

I am migrating k8s http probes to use readiness and liveness health group endpoints(/actuator/health/[readiness|liveness]).
When these endpoints return non UP status(other than 200 response), k8s stops traffic or shutdown the pod. When such event happens, k8s http probe only record the returned http status for the reason of its probe failure.
This makes hard to investigate WHY readiness/liveness probes returned non 200 response when somebody needs to investigate the failure reason later. Even if k8s could record body of probe response, it would be nicer to have such information in application log.

I wrote this implementation to our services to log information when health endpoints returns non UP response.

@Slf4j
public class LoggingHealthEndpointWebExtension extends HealthEndpointWebExtension {

	public LoggingHealthEndpointWebExtension(HealthContributorRegistry registry, HealthEndpointGroups groups) {
		super(registry, groups);
	}

	@Override
	public WebEndpointResponse<HealthComponent> health(ApiVersion apiVersion, SecurityContext securityContext,
			boolean showAll, String... path) {
		WebEndpointResponse<HealthComponent> response = super.health(apiVersion, securityContext, showAll, path);
		HealthComponent health = response.getBody();
		if (health == null) {
			return response;
		}

		Status status = health.getStatus();
		if (status != Status.UP) {
			Map<String, HealthComponent> components = new TreeMap<>();
			if (health instanceof CompositeHealth) {
				Map<String, HealthComponent> details = ((CompositeHealth) health).getComponents();
				if (details != null) {
					components.putAll(details);
				}
			}
			log.warn("Health endpoints {} returned {}. components={}", path, status, components);
		}

		return response;
	}

}

If HealthEndpointSupport could have logging capability (or HealthEndpointWebExtension and ReactiveHealthEndpointWebExtension for web only), then we don't need to have this custom implementation.

Something like:

boolean enableLogging;

if(this.enableLogging && health.getStatus() != Status.UP) {
  log.warn(...);
}

[wilkinsona]

Each indicator that subclasses AbstractHealthIndicator should already log a warning when a health check fails:

spring-boot/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/health/AbstractHealthIndicator.java

Lines 84 to 90 in c626e94

	catch (Exception ex) {
	if (this.logger.isWarnEnabled()) {
	String message = this.healthCheckFailedMessage.apply(ex);
	this.logger.warn(StringUtils.hasText(message) ? message : DEFAULT_MESSAGE, ex);
	}
	builder.down(ex);
	}

Does this existing logging not meet your needs? I don't think we should duplicate it, particularly in a manner that is web-specific.

[ttddyy]

@wilkinsona Thanks for the pointer.

The logging on the code above only happen when the actual health check logic throws an exception.
Some of the healthcheck implementation throws Exception and let here to set DOWN status, but some are constructing response health status in the logic without throwing exception.

The intention for my case is when health check(aggregated) returns non UP state(DOWN, OUT_OF_SERVICE, UNKNOWN), then perform logging.
This is because the response of liveness health group(/actuator/health/liveness) will trigger the restart of the application. When it happens, I would like to come back to see application log and find out which health indicator returned non-UP status as well as details if available.

[bclozel]

After discussing with the team, we've decided to log failing indicators individually at the WARN level in all cases, i.e. not just when an exception is thrown.

We've also decided to log ApplicationAvailability state changes in a separate issue, see #23098.