[Task Manager] Log at different levels based on the state #101751
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -18,6 +18,7 @@ export const DEFAULT_VERSION_CONFLICT_THRESHOLD = 80; | |
| // Refresh aggregated monitored stats at a default rate of once a minute | ||
| export const DEFAULT_MONITORING_REFRESH_RATE = 60 * 1000; | ||
| export const DEFAULT_MONITORING_STATS_RUNNING_AVERGAE_WINDOW = 50; | ||
| export const DEFAULT_MONITORING_STATS_WARN_DRIFT_IN_SECONDS = 60; | ||
|
|
||
| export const taskExecutionFailureThresholdSchema = schema.object( | ||
| { | ||
|
|
@@ -109,6 +110,9 @@ export const configSchema = schema.object( | |
| defaultValue: {}, | ||
| }), | ||
| }), | ||
| monitored_stats_warn_drift_in_seconds: schema.number({ | ||
|
There was a problem hiding this comment. Do we want to doc this, here? https://www.elastic.co/guide/en/kibana/current/task-manager-settings-kb.html I don't think we doc all the config options, but maybe this is one that we do? Also implies that we need to add this to the cloud whitelist, and to the docker whitelist. Also wondering if we want to add anything to the health monitor doc - https://www.elastic.co/guide/en/kibana/current/task-manager-health-monitoring.html - specifically, I wondering if users will be able to search the docs for the message this produces, to try to understand it. I feel like we need to define "drift", because we don't seem to. There was a problem hiding this comment. I added it there and also renamed it to avoid needing to define a new term for users! I'm not sure how to add things to the docker/cloud whitelist - is that a file in the Kibana repo? There was a problem hiding this comment. the docker whitelist is in this repo, and is listed in the PR template (at least when I create new PRs) - https://github.com/elastic/kibana/blob/master/src/dev/build/tasks/os_packages/docker_generator/resources/base/bin/kibana-docker the cloud whitelist is in a private repo; I'll DM you the info ... |
||
| defaultValue: DEFAULT_MONITORING_STATS_WARN_DRIFT_IN_SECONDS, | ||
| }), | ||
| }, | ||
| { | ||
| validate: (config) => { | ||
|
|
||
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,207 @@ | ||
| /* | ||
| * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one | ||
| * or more contributor license agreements. Licensed under the Elastic License | ||
| * 2.0; you may not use this file except in compliance with the Elastic License | ||
| * 2.0. | ||
| */ | ||
| import { merge } from 'lodash'; | ||
| import { loggingSystemMock } from 'src/core/server/mocks'; | ||
| import { configSchema, TaskManagerConfig } from '../config'; | ||
| import { HealthStatus } from '../monitoring'; | ||
| import { TaskPersistence } from '../monitoring/task_run_statistics'; | ||
| import { MonitoredHealth } from '../routes/health'; | ||
| import { logHealthMetrics } from './log_health_metrics'; | ||
| import { Logger } from '../../../../../src/core/server'; | ||
|
|
||
| describe('logHealthMetrics', () => { | ||
| it('should log as debug if there the status is OK', () => { | ||
chrisronline marked this conversation as resolved.
Show resolved
Hide resolved
|
||
| const logger = loggingSystemMock.create().get(); | ||
| const config = getTaskManagerConfig({ | ||
| monitored_stats_warn_drift_in_seconds: 60, | ||
| }); | ||
| const health = getMockMonitoredHealth(); | ||
|
|
||
| logHealthMetrics(health, logger, config); | ||
|
|
||
| const firstDebug = JSON.parse( | ||
| (logger as jest.Mocked<Logger>).debug.mock.calls[0][0].replace('Latest Monitored Stats: ', '') | ||
| ); | ||
| expect(firstDebug).toMatchObject(health); | ||
| }); | ||
|
|
||
| it('should log as warn if there the status is Warn', () => { | ||
| const logger = loggingSystemMock.create().get(); | ||
| const config = getTaskManagerConfig({ | ||
| monitored_stats_warn_drift_in_seconds: 60, | ||
| }); | ||
| const health = getMockMonitoredHealth({ | ||
| status: HealthStatus.Warning, | ||
| }); | ||
|
|
||
| logHealthMetrics(health, logger, config); | ||
|
|
||
| const logMessage = JSON.parse( | ||
| ((logger as jest.Mocked<Logger>).warn.mock.calls[0][0] as string).replace( | ||
| 'Latest Monitored Stats (warning status): ', | ||
| '' | ||
| ) | ||
| ); | ||
| expect(logMessage).toMatchObject(health); | ||
| }); | ||
|
|
||
| it('should log as error if there the status is Error', () => { | ||
| const logger = loggingSystemMock.create().get(); | ||
| const config = getTaskManagerConfig({ | ||
| monitored_stats_warn_drift_in_seconds: 60, | ||
| }); | ||
| const health = getMockMonitoredHealth({ | ||
| status: HealthStatus.Error, | ||
| }); | ||
|
|
||
| logHealthMetrics(health, logger, config); | ||
|
|
||
| const logMessage = JSON.parse( | ||
| ((logger as jest.Mocked<Logger>).error.mock.calls[0][0] as string).replace( | ||
| 'Latest Monitored Stats (error status): ', | ||
| '' | ||
| ) | ||
| ); | ||
| expect(logMessage).toMatchObject(health); | ||
| }); | ||
|
|
||
| it('should log as warn if there the drift exceeds the threshold', () => { | ||
| const logger = loggingSystemMock.create().get(); | ||
| const config = getTaskManagerConfig({ | ||
| monitored_stats_warn_drift_in_seconds: 60, | ||
| }); | ||
| const health = getMockMonitoredHealth({ | ||
| stats: { | ||
| runtime: { | ||
| value: { | ||
| drift: { | ||
| p99: 60000, | ||
| }, | ||
| }, | ||
| }, | ||
| }, | ||
| }); | ||
|
|
||
| logHealthMetrics(health, logger, config); | ||
|
|
||
| const logMessage = JSON.parse( | ||
| ((logger as jest.Mocked<Logger>).warn.mock.calls[0][0] as string).replace( | ||
| `Latest Monitored Stats (Detected drift of 60s): `, | ||
| '' | ||
| ) | ||
| ); | ||
| expect(logMessage).toMatchObject(health); | ||
| }); | ||
| }); | ||
|
|
||
| function getMockMonitoredHealth(overrides = {}): MonitoredHealth { | ||
| const stub: MonitoredHealth = { | ||
| id: '1', | ||
| status: HealthStatus.OK, | ||
| timestamp: new Date().toISOString(), | ||
| last_update: new Date().toISOString(), | ||
| stats: { | ||
| configuration: { | ||
| timestamp: new Date().toISOString(), | ||
| status: HealthStatus.OK, | ||
| value: { | ||
| max_workers: 10, | ||
| poll_interval: 3000, | ||
| max_poll_inactivity_cycles: 10, | ||
| request_capacity: 1000, | ||
| monitored_aggregated_stats_refresh_rate: 5000, | ||
| monitored_stats_running_average_window: 50, | ||
| monitored_task_execution_thresholds: { | ||
| default: { | ||
| error_threshold: 90, | ||
| warn_threshold: 80, | ||
| }, | ||
| custom: {}, | ||
| }, | ||
| }, | ||
| }, | ||
| workload: { | ||
| timestamp: new Date().toISOString(), | ||
| status: HealthStatus.OK, | ||
| value: { | ||
| count: 4, | ||
| task_types: { | ||
| actions_telemetry: { count: 2, status: { idle: 2 } }, | ||
| alerting_telemetry: { count: 1, status: { idle: 1 } }, | ||
| session_cleanup: { count: 1, status: { idle: 1 } }, | ||
| }, | ||
| schedule: [], | ||
| overdue: 0, | ||
| overdue_non_recurring: 0, | ||
| estimatedScheduleDensity: [], | ||
| non_recurring: 20, | ||
| owner_ids: 2, | ||
| estimated_schedule_density: [], | ||
| capacity_requirments: { | ||
| per_minute: 150, | ||
| per_hour: 360, | ||
| per_day: 820, | ||
| }, | ||
| }, | ||
| }, | ||
| runtime: { | ||
| timestamp: new Date().toISOString(), | ||
| status: HealthStatus.OK, | ||
| value: { | ||
| drift: { | ||
| p50: 1000, | ||
| p90: 2000, | ||
| p95: 2500, | ||
| p99: 3000, | ||
| }, | ||
| drift_by_type: {}, | ||
| load: { | ||
| p50: 1000, | ||
| p90: 2000, | ||
| p95: 2500, | ||
| p99: 3000, | ||
| }, | ||
| execution: { | ||
| duration: {}, | ||
| duration_by_persistence: {}, | ||
| persistence: { | ||
| [TaskPersistence.Recurring]: 10, | ||
| [TaskPersistence.NonRecurring]: 10, | ||
| [TaskPersistence.Ephemeral]: 10, | ||
| }, | ||
| result_frequency_percent_as_number: {}, | ||
| }, | ||
| polling: { | ||
| last_successful_poll: new Date().toISOString(), | ||
| duration: [500, 400, 3000], | ||
| claim_conflicts: [0, 100, 75], | ||
| claim_mismatches: [0, 100, 75], | ||
| result_frequency_percent_as_number: [ | ||
| 'NoTasksClaimed', | ||
| 'NoTasksClaimed', | ||
| 'NoTasksClaimed', | ||
| ], | ||
| }, | ||
| }, | ||
| }, | ||
| }, | ||
| }; | ||
| return (merge(stub, overrides) as unknown) as MonitoredHealth; | ||
| } | ||
|
|
||
| function getTaskManagerConfig(overrides: Partial<TaskManagerConfig> = {}) { | ||
| return configSchema.validate( | ||
| overrides.monitored_stats_required_freshness | ||
| ? { | ||
| // use `monitored_stats_required_freshness` as poll interval otherwise we might | ||
| // fail validation as it must be greather than the poll interval | ||
| poll_interval: overrides.monitored_stats_required_freshness, | ||
| ...overrides, | ||
| } | ||
| : overrides | ||
| ); | ||
| } | ||
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,44 @@ | ||
| /* | ||
| * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one | ||
| * or more contributor license agreements. Licensed under the Elastic License | ||
| * 2.0; you may not use this file except in compliance with the Elastic License | ||
| * 2.0. | ||
| */ | ||
|
|
||
| import { Logger } from '../../../../../src/core/server'; | ||
| import { HealthStatus } from '../monitoring'; | ||
| import { TaskManagerConfig } from '../config'; | ||
| import { MonitoredHealth } from '../routes/health'; | ||
|
|
||
| export function logHealthMetrics( | ||
| monitoredHealth: MonitoredHealth, | ||
| logger: Logger, | ||
| config: TaskManagerConfig | ||
| ) { | ||
| let contextMessage; | ||
|
|
||
| let logAsWarn = monitoredHealth.status === HealthStatus.Warning; | ||
| const logAsError = monitoredHealth.status === HealthStatus.Error; | ||
| const driftInSeconds = (monitoredHealth.stats.runtime?.value.drift.p99 ?? 0) / 1000; | ||
|
|
||
| if (driftInSeconds >= config.monitored_stats_warn_drift_in_seconds) { | ||
| contextMessage = `Detected drift of ${driftInSeconds}s`; | ||
chrisronline marked this conversation as resolved.
Show resolved
Hide resolved
|
||
| logAsWarn = true; | ||
| } | ||
|
|
||
| if (logAsError) { | ||
| logger.error( | ||
| `Latest Monitored Stats (${contextMessage ?? `error status`}): ${JSON.stringify( | ||
| monitoredHealth | ||
| )}` | ||
| ); | ||
| } else if (logAsWarn) { | ||
| logger.warn( | ||
| `Latest Monitored Stats (${contextMessage ?? `warning status`}): ${JSON.stringify( | ||
| monitoredHealth | ||
| )}` | ||
| ); | ||
|
There was a problem hiding this comment. When testing locally, I started a fresh Kibana and got this "warning status" log message right away. After investigating, I found out the capacity estimation caused the health status to be "warning" (see below). It sounds like a bug in the capacity estimation API? and exposed more severely in this PR? The second log I saw was "error status" while all the sub-elements being "OK" 🤔 These don't seem related to this PR but definitely expose a couple of potential bugs. cc @gmmorris Health output on start-upSecond health logThere was a problem hiding this comment. @mikecote I'm not sure. Perhaps we don't consider capacity estimation as a factor for the logging here? I'm assuming capacity estimation is more of a planning reference rather than "I need to know these metrics when something isn't working right"? There was a problem hiding this comment. On a fresh ES/Kibana launch, I saw this on startup: After adding an alert with actions and getting everything firing, then killing Kibana and restarting, saw the exact same message. Nothing like Mike's ^^^ though There was a problem hiding this comment.
My guess here is the stats are stale which triggers a warning/error state. There was a problem hiding this comment.
You're totally right, and like this PR states, it should only log when runtime, configuration, and workload are not "ok". But, seems to still log when everything is "ok" except capacity estimation. It may be because this code here looks at the overall status? but should look within There was a problem hiding this comment. I agree, makes sense. I think, in a future PR, we should consider changing this logic and this logic so they are represented in the overall status for the If I change this code to just look at the overall status for each bucket, then we'll need to move around the freshness checks to ensure those are properly accounted for when determining overall status There was a problem hiding this comment. @mikecote I just pushed up some changes around this. LMK There was a problem hiding this comment. Thanks, I ran it locally and the startup error logs no longer showed. 👍 |
||
| } else { | ||
| logger.debug(`Latest Monitored Stats: ${JSON.stringify(monitoredHealth)}`); | ||
| } | ||
| } | ||
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I don't have a great sense for a good value here - presumably 60 seconds means it missed 20 (potential) poll requests, which seems like ... plenty to have a warning on. At the same time, it feels kinda short, like this could happen every now and again. I think I feel like 60 seconds is workable if it's warning not an error, and isn't super-scary if you see them every now and again, and obvious that something's wrong if you see it a lot.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Neither do I. I feel we should attempt to be less conservative here, as the point of this change is to ensure these logs are available when there is an issue with TM/Alerting. As long as the messaging is clear on how to avoid the logs, we should be all set.