Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bad requests from spaces saved object client during kibana startup #120422

Closed
liza-mae opened this issue Dec 3, 2021 · 21 comments
Closed

Bad requests from spaces saved object client during kibana startup #120422

liza-mae opened this issue Dec 3, 2021 · 21 comments
Labels
bug Fixes for quality problems that affect the customer experience Feature:Telemetry impact:needs-assessment Product and/or Engineering needs to evaluate the impact of the change. loe:small Small Level of Effort Team:Core Core services & architecture: plugins, logging, config, saved objects, http, ES client, i18n, etc

Comments

@liza-mae
Copy link
Contributor

liza-mae commented Dec 3, 2021

Kibana version: 7.16.0

Elasticsearch version: 7.16.0

Server OS version: Cloud

Original install method (e.g. download page, yum, from source, etc.):
Staging

Describe the bug:
Upon Kibana startup we see multiple bad request errors in the log.

Steps to reproduce:

  1. Create 7.16.0 deployment on cloud
  2. Retrieve Kibana logs and observe errors with spaces saved object client

Expected behavior:
No errors in logs

Provide logs and/or server output (if relevant):

Error: Bad Request
    at Function.createBadRequestError (/usr/share/kibana/src/core/server/saved_objects/service/lib/errors.js:80:36)
    at SpacesSavedObjectsClient.openPointInTimeForType (/usr/share/kibana/x-pack/plugins/spaces/server/saved_objects/spaces_saved_objects_client.js:257:48)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at PointInTimeFinder.open (/usr/share/kibana/src/core/server/saved_objects/service/lib/point_in_time_finder.js:144:11)
    at PointInTimeFinder.find (/usr/share/kibana/src/core/server/saved_objects/service/lib/point_in_time_finder.js:99:5)
    at getStats (/usr/share/kibana/src/plugins/vis_types/table/server/usage_collector/get_stats.js:57:20)
    at /usr/share/kibana/src/plugins/usage_collection/server/collector/collector_set.js:104:21
    at async Promise.all (index 31)
    at CollectorSet.bulkFetch (/usr/share/kibana/src/plugins/usage_collection/server/collector/collector_set.js:91:25)
    at CollectorSet.bulkFetchUsage (/usr/share/kibana/src/plugins/usage_collection/server/collector/collector_set.js:119:14)
    at getUsage (/usr/share/kibana/src/plugins/usage_collection/server/routes/stats/stats.js:41:19)
    at async Promise.all (index 0)
    at /usr/share/kibana/src/plugins/usage_collection/server/routes/stats/stats.js:103:36
    at Router.handle (/usr/share/kibana/src/core/server/http/router/router.js:163:30)
    at handler (/usr/share/kibana/src/core/server/http/router/router.js:124:50) {
  isBoom: true,
  isServer: false,
  data: null,
  output: {
    statusCode: 400,
    payload: { statusCode: 400, error: 'Bad Request', message: 'Bad Request' },
    headers: {}
  },
  [Symbol(SavedObjectsClientErrorCode)]: 'SavedObjectsClient/badRequest'
}

Error: Bad Request
    at Function.createBadRequestError (/usr/share/kibana/src/core/server/saved_objects/service/lib/errors.js:80:36)
    at SpacesSavedObjectsClient.openPointInTimeForType (/usr/share/kibana/x-pack/plugins/spaces/server/saved_objects/spaces_saved_objects_client.js:257:48)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at PointInTimeFinder.open (/usr/share/kibana/src/core/server/saved_objects/service/lib/point_in_time_finder.js:144:11)
    at PointInTimeFinder.find (/usr/share/kibana/src/core/server/saved_objects/service/lib/point_in_time_finder.js:99:5)
    at doTelemetryFoVisualizations (/usr/share/kibana/src/plugins/vis_types/timeseries/server/usage_collector/get_usage_collector.js:26:20)
    at async Promise.all (index 0)
    at getStats (/usr/share/kibana/src/plugins/vis_types/timeseries/server/usage_collector/get_usage_collector.js:73:3)
    at UsageCollector.fetch (/usr/share/kibana/src/plugins/vis_types/timeseries/server/usage_collector/register_timeseries_collector.js:37:11)
    at /usr/share/kibana/src/plugins/usage_collection/server/collector/collector_set.js:104:21
    at async Promise.all (index 36)
    at Object.bulkFetch (/usr/share/kibana/src/plugins/usage_collection/server/collector/collector_set.js:91:25)
    at getKibana (/usr/share/kibana/src/plugins/telemetry/server/telemetry_collection/get_kibana.js:68:17)
    at async Promise.all (index 3)
    at /usr/share/kibana/src/plugins/telemetry/server/telemetry_collection/get_local_stats.js:79:76 {
  isBoom: true,
  isServer: false,
  data: null,
  output: {
    statusCode: 400,
    payload: { statusCode: 400, error: 'Bad Request', message: 'Bad Request' },
    headers: {}
  },
  [Symbol(SavedObjectsClientErrorCode)]: 'SavedObjectsClient/badRequest'
}

cc: @jportner @TinaHeiligers

@liza-mae liza-mae added bug Fixes for quality problems that affect the customer experience Team:Security Team focused on: Auth, Users, Roles, Spaces, Audit Logging, and more! labels Dec 3, 2021
@elasticmachine
Copy link
Contributor

Pinging @elastic/kibana-security (Team:Security)

@exalate-issue-sync exalate-issue-sync bot added impact:needs-assessment Product and/or Engineering needs to evaluate the impact of the change. loe:small Small Level of Effort labels Dec 8, 2021
@asazallesmilner
Copy link

asazallesmilner commented Jan 12, 2022

We are seeing the exact same issue log error when we try to import dashboards/visualizations into the cloud on 7.16.2...
Any idea what causes it?

@thomheymann
Copy link
Contributor

The error seems to occur when Metricbeat is trying to collect usage stats from the /api/stats route.

For some reason Elasticsearch responds with a 403 when Kibana is trying to list all available spaces:

Screenshot 2022-01-12 at 23 09 44

It looks like it's a permission problem. Do you have any logs from Elasticsearch for the error?

@asazallesmilner
Copy link

We see it when we try and use the saved objects import API with object exported with the export API.
We see that error in the kibana log.

@thomheymann
Copy link
Contributor

Is there a way to reproduce this issue? I don't get the error when importing and exporting saved objects on 7.16.0 so finding it quite difficult to try and work out what the problem could be.

The issue is definitely usage stats related. We'd need to understand which user is making the request to /api/stats and what their permissions are. Can you provide me with the permissions for the user this is happening with?

@TinaHeiligers
Copy link
Contributor

We see it when we try and use the saved objects import API with object exported with the export API.

@asazallesmilner are you importing the saved objects into the same space as they were exported from?

The logs given in the issue's description don't give us much to go on here, we ideally need verbose logs.

The steps to reproduce also don't mention exporting an importing saved objects so we need more info on how you came across the bug please.
For example:

  • Does the new cluster have any data already?
  • Which space are you trying to import the saved objects into?
  • Is the kibana you've exported the SO from on the same version as the one you're trying to import data into?
  • Does the user have the same permissions in both clusters (assuming they are different clusters that is?)
  • Are the licenses the same?
  • Are the same plugins enabled?
    etc...

@TinaHeiligers TinaHeiligers added the Team:Core Core services & architecture: plugins, logging, config, saved objects, http, ES client, i18n, etc label Jan 13, 2022
@elasticmachine
Copy link
Contributor

Pinging @elastic/kibana-core (Team:Core)

@jportner
Copy link
Contributor

jportner commented Jan 13, 2022

Closing the loop on this issue based on an offline discussion we had a month ago.

This error can occur when a consumer uses openPointInTimeForType or createPointInTimeFinder (which uses the former under the hood).

In a nutshell: in this issue (and likely the separate problem that @asazallesmilner is experiencing), the Spaces SOC wrapper is probably throwing the 400 Bad Request error based on the second error condition that Thom mentioned above:

try {
namespaces = await this.getSearchableSpaces(options.namespaces);
} catch (err) {
if (Boom.isBoom(err) && err.output.payload.statusCode === 403) {
// throw bad request since the user is unauthorized in any space
throw SavedObjectsErrorHelpers.createBadRequestError();
}
throw err;
}
if (namespaces.length === 0) {
// throw bad request if no valid spaces were found.
throw SavedObjectsErrorHelpers.createBadRequestError();
}

This can happen if the user is trying to search across multiple spaces, and the Spaces SOC wrapper finds 0 spaces that the user is authorized to see for this purpose:

private async getSearchableSpaces(namespaces?: string[]): Promise<string[]> {
if (namespaces) {
const availableSpaces = await this.spacesClient.getAll({ purpose: 'findSavedObjects' });
if (namespaces.includes(ALL_SPACES_ID)) {
return availableSpaces.map((space) => space.id);
} else {
return namespaces.filter((namespace) =>
availableSpaces.some((space) => space.id === namespace)
);
}
} else {
return [this.spaceId];
}
}
}

The user needs to be authorized to use the Saved Objects Management feature to be able to use the import API.

findSavedObjects: (authorization) => {
return [authorization.actions.login, authorization.actions.savedObject.get('config', 'find')];
},


The problem in this issue appears to be happening because a usage data collector is attempting to use the current user's credentials to search for visualizations across all spaces, but if the current user is not authorized to access the Saved Objects Management feature in any space, this error will happen.

fetch: async ({ soClient }) => await getStats(soClient),

export async function getStats(
soClient: SavedObjectsClientContract
): Promise<VisualizationUsage | undefined> {
const finder = await soClient.createPointInTimeFinder({
type: 'visualization',
perPage: 1000,
namespaces: ['*'],
});

I believe the solution for this problem is to make sure that consumers of the usage collector use a saved objects client that uses the system user's credentials, not the end user's credentials.


@asazallesmilner I'm not sure why you're experiencing the same problem on import, we don't use the openPointInTimeForType or createPointInTimeFinder during import. I'd say that likely you're experiencing a privileges problem. If you have checked your user's privileges and you think you found a bug with the import feature, feel free to open a separate GitHub issue to report it, and include the information that Tina asked for above.

Otherwise if you're having trouble with setting up your environment/roles/privileges/etc and you have a question, feel free to ask for support in our Discuss forum: https://discuss.elastic.co/c/elastic-stack/kibana/7

But let's please keep this issue on-topic, it is focused on Cloud deployments that run into this error because of usage collection 👍

@jportner
Copy link
Contributor

jportner commented Jan 13, 2022

@TinaHeiligers I can replicate this error in the 7.17 branch by hitting /api/stats?extended without the appropriate privileges. I haven't tested 7.16, 8.0, or main, but I believe all of them will behave the same way.

One way to easily reproduce this.

  1. Start ES and Kibana
  2. Try to get extended stats from Kibana using the kibana_system user: curl http://localhost:5601/api/stats\?extended -u kibana_system:changeme
    Unintuitively, the kibana_system user has privileges to access the .kibana* indices, but it does not itself hold Kibana privileges (e.g., to access the Saved Objects Management feature)
  3. The call will succeed, but the Kibana server will produce these four errors:
Click to expand and see Kibana server logs
server    log   [14:37:00.577] [error][point-in-time-finder][repository][savedobjects-service] Failed to open PIT for types [visualization]
server    log   [14:37:00.577] [warning][collector-set][plugins][usage-collection][usageCollection] Error: Bad Request
    at Function.createBadRequestError (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/errors.ts:82:36)
    at SpacesSavedObjectsClient.openPointInTimeForType (/Users/joe/GitHub/kibana-4/x-pack/plugins/spaces/server/saved_objects/spaces_saved_objects_client.ts:331:40)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at PointInTimeFinder.open (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/point_in_time_finder.ts:143:22)
    at PointInTimeFinder.response [as find] (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/point_in_time_finder.ts:98:5)
    at doTelemetryFoVisualizations (/Users/joe/GitHub/kibana-4/src/plugins/vis_types/timeseries/server/usage_collector/get_usage_collector.ts:35:20)
    at async Promise.all (index 0)
    at getStats (/Users/joe/GitHub/kibana-4/src/plugins/vis_types/timeseries/server/usage_collector/get_usage_collector.ts:97:3)
    at UsageCollector.fetch (/Users/joe/GitHub/kibana-4/src/plugins/vis_types/timeseries/server/usage_collector/register_timeseries_collector.ts:26:36)
    at /Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:188:21
    at async Promise.all (index 35)
    at CollectorSet.bulkFetch (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:177:23)
    at CollectorSet.bulkFetchUsage (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:216:12)
    at getUsage (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/routes/stats/stats.ts:61:19)
    at async Promise.all (index 0) {
  isBoom: true,
  isServer: false,
  data: null,
  output: {
    statusCode: 400,
    payload: { statusCode: 400, error: 'Bad Request', message: 'Bad Request' },
    headers: {}
  },
  [Symbol(SavedObjectsClientErrorCode)]: 'SavedObjectsClient/badRequest'
}
server    log   [14:37:00.578] [warning][collector-set][plugins][usage-collection][usageCollection] Unable to fetch data from vis_type_timeseries collector
server    log   [14:37:00.579] [error][point-in-time-finder][repository][savedobjects-service] Failed to open PIT for types [visualization]
server    log   [14:37:00.579] [warning][collector-set][plugins][usage-collection][usageCollection] Error: Bad Request
    at Function.createBadRequestError (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/errors.ts:82:36)
    at SpacesSavedObjectsClient.openPointInTimeForType (/Users/joe/GitHub/kibana-4/x-pack/plugins/spaces/server/saved_objects/spaces_saved_objects_client.ts:331:40)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at PointInTimeFinder.open (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/point_in_time_finder.ts:143:22)
    at PointInTimeFinder.response [as find] (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/point_in_time_finder.ts:98:5)
    at getStats (/Users/joe/GitHub/kibana-4/src/plugins/visualizations/server/usage_collector/get_usage_collector.ts:47:20)
    at UsageCollector.fetch (/Users/joe/GitHub/kibana-4/src/plugins/visualizations/server/usage_collector/register_visualizations_collector.ts:27:36)
    at /Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:188:21
    at async Promise.all (index 29)
    at CollectorSet.bulkFetch (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:177:23)
    at CollectorSet.bulkFetchUsage (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:216:12)
    at getUsage (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/routes/stats/stats.ts:61:19)
    at async Promise.all (index 0)
    at /Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/routes/stats/stats.ts:98:38
    at Router.handle (/Users/joe/GitHub/kibana-4/src/core/server/http/router/router.ts:275:30) {
  isBoom: true,
  isServer: false,
  data: null,
  output: {
    statusCode: 400,
    payload: { statusCode: 400, error: 'Bad Request', message: 'Bad Request' },
    headers: {}
  },
  [Symbol(SavedObjectsClientErrorCode)]: 'SavedObjectsClient/badRequest'
}
server    log   [14:37:00.580] [warning][collector-set][plugins][usage-collection][usageCollection] Unable to fetch data from visualization_types collector
server    log   [14:37:00.581] [error][point-in-time-finder][repository][savedobjects-service] Failed to open PIT for types [visualization]
server    log   [14:37:00.582] [error][point-in-time-finder][repository][savedobjects-service] Failed to open PIT for types [visualization]
server    log   [14:37:00.583] [warning][collector-set][plugins][usage-collection][usageCollection] Error: Bad Request
    at Function.createBadRequestError (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/errors.ts:82:36)
    at SpacesSavedObjectsClient.openPointInTimeForType (/Users/joe/GitHub/kibana-4/x-pack/plugins/spaces/server/saved_objects/spaces_saved_objects_client.ts:331:40)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at PointInTimeFinder.open (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/point_in_time_finder.ts:143:22)
    at PointInTimeFinder.response [as find] (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/point_in_time_finder.ts:98:5)
    at getStats (/Users/joe/GitHub/kibana-4/src/plugins/vis_types/vega/server/usage_collector/get_usage_collector.ts:101:20)
    at UsageCollector.fetch (/Users/joe/GitHub/kibana-4/src/plugins/vis_types/vega/server/usage_collector/register_vega_collector.ts:26:36)
    at /Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:188:21
    at async Promise.all (index 30)
    at CollectorSet.bulkFetch (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:177:23)
    at CollectorSet.bulkFetchUsage (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:216:12)
    at getUsage (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/routes/stats/stats.ts:61:19)
    at async Promise.all (index 0)
    at /Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/routes/stats/stats.ts:98:38
    at Router.handle (/Users/joe/GitHub/kibana-4/src/core/server/http/router/router.ts:275:30) {
  isBoom: true,
  isServer: false,
  data: null,
  output: {
    statusCode: 400,
    payload: { statusCode: 400, error: 'Bad Request', message: 'Bad Request' },
    headers: {}
  },
  [Symbol(SavedObjectsClientErrorCode)]: 'SavedObjectsClient/badRequest'
}
server    log   [14:37:00.583] [warning][collector-set][plugins][usage-collection][usageCollection] Unable to fetch data from vis_type_vega collector
server    log   [14:37:00.585] [error][point-in-time-finder][repository][savedobjects-service] Failed to open PIT for types [visualization]
server    log   [14:37:00.585] [warning][collector-set][plugins][usage-collection][usageCollection] Error: Bad Request
    at Function.createBadRequestError (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/errors.ts:82:36)
    at SpacesSavedObjectsClient.openPointInTimeForType (/Users/joe/GitHub/kibana-4/x-pack/plugins/spaces/server/saved_objects/spaces_saved_objects_client.ts:331:40)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at PointInTimeFinder.open (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/point_in_time_finder.ts:143:22)
    at PointInTimeFinder.response [as find] (/Users/joe/GitHub/kibana-4/src/core/server/saved_objects/service/lib/point_in_time_finder.ts:98:5)
    at getStats (/Users/joe/GitHub/kibana-4/src/plugins/vis_types/table/server/usage_collector/get_stats.ts:85:20)
    at /Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:188:21
    at async Promise.all (index 31)
    at CollectorSet.bulkFetch (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:177:23)
    at CollectorSet.bulkFetchUsage (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/collector/collector_set.ts:216:12)
    at getUsage (/Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/routes/stats/stats.ts:61:19)
    at async Promise.all (index 0)
    at /Users/joe/GitHub/kibana-4/src/plugins/usage_collection/server/routes/stats/stats.ts:98:38
    at Router.handle (/Users/joe/GitHub/kibana-4/src/core/server/http/router/router.ts:275:30)
    at handler (/Users/joe/GitHub/kibana-4/src/core/server/http/router/router.ts:230:13) {
  isBoom: true,
  isServer: false,
  data: null,
  output: {
    statusCode: 400,
    payload: { statusCode: 400, error: 'Bad Request', message: 'Bad Request' },
    headers: {}
  },
  [Symbol(SavedObjectsClientErrorCode)]: 'SavedObjectsClient/badRequest'
}
server    log   [14:37:00.586] [warning][collector-set][plugins][usage-collection][usageCollection] Unable to fetch data from vis_type_table collector

If I start a fresh Kibana deployment on Cloud and check the server logs, without interacting with Kibana at all, I see the same four errors (repeated 3x):

image

Interestingly, if I check the Cloud proxy logs, they are completely empty. I suspect that if we have an internal service that is hitting the stats API, it won't get routed through the Cloud proxy, so it won't show up in the logs there.

So maybe there is something in Cloud that is hitting this endpoint with the kibana_system user credentials?


Then I had the bright idea to restart my instance with debug logs enabled, and this is what I found (filtering out ES query logs):

Jan 13, 2022 @ 19:50:20.311	DEBUG	http.server.response	GET / 302 3ms
Jan 13, 2022 @ 19:50:20.310	DEBUG	plugins.security.authenticator	Redirecting request to Login Selector (provider hint: n/a).
Jan 13, 2022 @ 19:50:20.309	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:18.922	DEBUG	plugins.dataEnhanced.data_enhanced	search_sessions_monitor Fetching sessions from page 1
Jan 13, 2022 @ 19:50:18.921	DEBUG	plugins.taskManager	Running task search_sessions_monitor "data_enhanced_search_sessions_monitor"
Jan 13, 2022 @ 19:50:18.481	DEBUG	metrics.ops	memory: 339.5MB uptime: 0:02:49 load: [0.80,0.74,0.92] mean delay: 12.658 delay histogram: { 50: 10.158; 95: 12.517; 99: 55.476 }
Jan 13, 2022 @ 19:50:18.347	DEBUG	http.server.response	POST /api/telemetry/v2/clusters/_stats 200 1548ms - 55.3KB
Jan 13, 2022 @ 19:50:18.341	DEBUG	plugins.telemetryCollectionManager	Received Usage using local_xpack collection.
Jan 13, 2022 @ 19:50:18.179	DEBUG	elasticsearch.query.monitoring	200
GET /_xpack
Jan 13, 2022 @ 19:50:17.075	WARN	plugins.usageCollection.usage-collection.collector-set	Unable to fetch data from vis_type_table collector
Jan 13, 2022 @ 19:50:17.074	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:17.074	WARN	plugins.usageCollection.usage-collection.collector-set	Bad Request
Jan 13, 2022 @ 19:50:17.073	ERROR	savedobjects-service.repository.point-in-time-finder	Failed to open PIT for types [visualization]
Jan 13, 2022 @ 19:50:17.071	ERROR	savedobjects-service.repository.point-in-time-finder	Failed to open PIT for types [visualization]
Jan 13, 2022 @ 19:50:17.071	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:17.062	DEBUG	core-usage-stats-service	getUsageStats() called
Jan 13, 2022 @ 19:50:17.044	DEBUG	plugins.spaces	SpacesClient.getAll(). Found 1 spaces.
Jan 13, 2022 @ 19:50:17.042	DEBUG	plugins.spaces	SpacesClient.getAll(). Found 1 spaces.
Jan 13, 2022 @ 19:50:17.035	DEBUG	elasticsearch.query.monitoring	200
POST /.monitoring-es-*%2C*%3A.monitoring-es-*/_search?filter_path=hits.hits._source.cluster_settings.cluster.metadata.display_name%2Chits.hits._source.cluster_uuid%2Chits.hits._source.cluster_name
{"size":1000,"query":{"bool":{"filter":[{"term":{"type":"cluster_stats"}},{"range":{"timestamp":{"gte":"now-2m"}}}]}},"collapse":{"field":"cluster_uuid"}}
Jan 13, 2022 @ 19:50:17.032	INFO	elasticsearch.deprecation	Elasticsearch deprecation: 299 Elasticsearch-8.0.0-801c2ac52575b00aabc6d7e9763a74f189b2eea9 "[cluster.routing.allocation.disk.watermark.enable_for_single_data_node] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.", 299 Elasticsearch-8.0.0-801c2ac52575b00aabc6d7e9763a74f189b2eea9 "[xpack.monitoring.history.duration] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.", 299 Elasticsearch-8.0.0-801c2ac52575b00aabc6d7e9763a74f189b2eea9 "[xpack.monitoring.collection.enabled] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version."
Origin:kibana
Stack trace:
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at Cluster.getSettings (/usr/share/kibana/node_modules/@elastic/elasticsearch/lib/api/api/cluster.js:158:16)
    at getDeprecationLoggingStatusValue (/usr/share/kibana/x-pack/plugins/upgrade_assistant/server/lib/telemetry/usage_collector.js:22:9)
    at fetchUpgradeAssistantMetrics (/usr/share/kibana/x-pack/plugins/upgrade_assistant/server/lib/telemetry/usage_collector.js:34:41)
    at /usr/share/kibana/src/plugins/usage_collection/server/collector/collector_set.js:125:21
    at async Promise.all (index 49)
    at Object.bulkFetch (/usr/share/kibana/src/plugins/usage_collection/server/collector/collector_set.js:112:25)
    at getKibana (/usr/share/kibana/src/plugins/telemetry/server/telemetry_collection/get_kibana.js:68:17)
    at async Promise.all (index 3)
    at /usr/share/kibana/src/plugins/telemetry/server/telemetry_collection/get_local_stats.js:79:76
    at async Promise.all (index 0)
    at getLocalStats (/usr/share/kibana/src/plugins/telemetry/server/telemetry_collection/get_local_stats.js:78:10)
Query:
200
GET /_cluster/settings?include_defaults=true
Jan 13, 2022 @ 19:50:17.027	WARN	plugins.usageCollection.usage-collection.collector-set	Unable to fetch data from visualization_types collector
Jan 13, 2022 @ 19:50:17.026	ERROR	savedobjects-service.repository.point-in-time-finder	Failed to open PIT for types [visualization]
Jan 13, 2022 @ 19:50:17.026	WARN	plugins.usageCollection.usage-collection.collector-set	Bad Request
Jan 13, 2022 @ 19:50:17.026	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:17.023	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:17.017	WARN	plugins.usageCollection.usage-collection.collector-set	Unable to fetch data from vis_type_timeseries collector
Jan 13, 2022 @ 19:50:17.013	ERROR	savedobjects-service.repository.point-in-time-finder	Failed to open PIT for types [visualization]
Jan 13, 2022 @ 19:50:17.013	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:17.013	WARN	plugins.usageCollection.usage-collection.collector-set	Bad Request
Jan 13, 2022 @ 19:50:17.008	DEBUG	plugins.spaces	getUsageStats() called
Jan 13, 2022 @ 19:50:17.005	DEBUG	plugins.spaces	SpacesClient.getAll(). Found 1 spaces.
Jan 13, 2022 @ 19:50:17.004	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:16.999	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:16.986	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:16.982	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:16.973	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:16.969	DEBUG	plugins.spaces	SpacesClient.getAll(). Found 1 spaces.
Jan 13, 2022 @ 19:50:16.967	WARN	plugins.usageCollection.usage-collection.collector-set	Unable to fetch data from vis_type_vega collector
Jan 13, 2022 @ 19:50:16.964	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:16.964	WARN	plugins.usageCollection.usage-collection.collector-set	Bad Request
Jan 13, 2022 @ 19:50:16.963	ERROR	savedobjects-service.repository.point-in-time-finder	Failed to open PIT for types [visualization]
Jan 13, 2022 @ 19:50:16.950	DEBUG	plugins.spaces	SpacesClient.getAll(). Found 1 spaces.
Jan 13, 2022 @ 19:50:16.907	DEBUG	plugins.usageCollection.usage-collection.collector-set	not sending [kibana_settings] monitoring document because [undefined] is null or invalid.
Jan 13, 2022 @ 19:50:16.896	DEBUG	plugins.spaces	SpacesClient.getAll(). querying all spaces
Jan 13, 2022 @ 19:50:16.895	DEBUG	plugins.spaces	SpacesClient.getAll(). querying all spaces
Jan 13, 2022 @ 19:50:16.894	DEBUG	plugins.spaces	SpacesClient.getAll(). querying all spaces
Jan 13, 2022 @ 19:50:16.893	DEBUG	plugins.spaces	SpacesClient.getAll(). querying all spaces
Jan 13, 2022 @ 19:50:16.892	DEBUG	plugins.spaces	SpacesClient.getAll(). querying all spaces
Jan 13, 2022 @ 19:50:16.885	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from apm collector
Jan 13, 2022 @ 19:50:16.884	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from workplace_search collector
Jan 13, 2022 @ 19:50:16.881	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from app_search collector
Jan 13, 2022 @ 19:50:16.880	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from enterprise_search collector
Jan 13, 2022 @ 19:50:16.880	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from upgrade-assistant-telemetry collector
Jan 13, 2022 @ 19:50:16.877	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from monitoringTelemetry collector
Jan 13, 2022 @ 19:50:16.876	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from monitoring collector
Jan 13, 2022 @ 19:50:16.875	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from infraops collector
Jan 13, 2022 @ 19:50:16.875	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from kibana_settings collector
Jan 13, 2022 @ 19:50:16.874	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from security_solution collector
Jan 13, 2022 @ 19:50:16.873	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from uptime collector
Jan 13, 2022 @ 19:50:16.872	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from ml collector
Jan 13, 2022 @ 19:50:16.872	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from discoverEnhanced collector
Jan 13, 2022 @ 19:50:16.871	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from osquery collector
Jan 13, 2022 @ 19:50:16.870	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from lens collector
Jan 13, 2022 @ 19:50:16.869	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from rollups collector
Jan 13, 2022 @ 19:50:16.869	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from vis_type_timeseries collector
Jan 13, 2022 @ 19:50:16.868	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from maps collector
Jan 13, 2022 @ 19:50:16.867	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from fleet collector
Jan 13, 2022 @ 19:50:16.867	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from dashboard collector
Jan 13, 2022 @ 19:50:16.866	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from vis_type_table collector
Jan 13, 2022 @ 19:50:16.865	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from vis_type_vega collector
Jan 13, 2022 @ 19:50:16.863	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from visualization_types collector
Jan 13, 2022 @ 19:50:16.863	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from canvas collector
Jan 13, 2022 @ 19:50:16.862	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from actions collector
Jan 13, 2022 @ 19:50:16.862	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from alerts collector
Jan 13, 2022 @ 19:50:16.861	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from search-session collector
Jan 13, 2022 @ 19:50:16.861	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from cloud collector
Jan 13, 2022 @ 19:50:16.860	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from fileUpload collector
Jan 13, 2022 @ 19:50:16.859	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from saved_objects_tagging collector
Jan 13, 2022 @ 19:50:16.859	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from reporting collector
Jan 13, 2022 @ 19:50:16.858	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from security collector
Jan 13, 2022 @ 19:50:16.857	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from sample-data collector
Jan 13, 2022 @ 19:50:16.857	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from spaces collector
Jan 13, 2022 @ 19:50:16.856	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from search collector
Jan 13, 2022 @ 19:50:16.855	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from kql collector
Jan 13, 2022 @ 19:50:16.854	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from static_telemetry collector
Jan 13, 2022 @ 19:50:16.854	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from telemetry collector
Jan 13, 2022 @ 19:50:16.854	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from index-patterns collector
Jan 13, 2022 @ 19:50:16.853	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from event_loop_delays collector
Jan 13, 2022 @ 19:50:16.852	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from localization collector
Jan 13, 2022 @ 19:50:16.852	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from kibana_config_usage collector
Jan 13, 2022 @ 19:50:16.849	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from csp collector
Jan 13, 2022 @ 19:50:16.849	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from cloud_provider collector
Jan 13, 2022 @ 19:50:16.849	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from core collector
Jan 13, 2022 @ 19:50:16.847	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from application_usage collector
Jan 13, 2022 @ 19:50:16.847	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from ui_metric collector
Jan 13, 2022 @ 19:50:16.846	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from stack_management collector
Jan 13, 2022 @ 19:50:16.844	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from saved_objects_counts collector
Jan 13, 2022 @ 19:50:16.843	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from kibana collector
Jan 13, 2022 @ 19:50:16.842	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from kibana_stats collector
Jan 13, 2022 @ 19:50:16.842	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from usage_counters collector
Jan 13, 2022 @ 19:50:16.841	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from ui_counters collector
Jan 13, 2022 @ 19:50:16.841	DEBUG	plugins.usageCollection.usage-collection.collector-set	Fetching data from task_manager collector
Jan 13, 2022 @ 19:50:16.835	DEBUG	plugins.usageCollection.usage-collection.collector-set	Getting ready collectors
Jan 13, 2022 @ 19:50:16.810	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:16.804	DEBUG	plugins.security.http	Request to /api/telemetry/v2/clusters/_stats has been authenticated via authorization header with "Basic" scheme.
Jan 13, 2022 @ 19:50:16.800	DEBUG	plugins.security.basic.cloud-basic	Cannot authenticate requests with `Authorization` header.
Jan 13, 2022 @ 19:50:16.800	DEBUG	plugins.security.http	Trying to authenticate user request to /api/telemetry/v2/clusters/_stats.
Jan 13, 2022 @ 19:50:16.800	DEBUG	plugins.security.saml.cloud-saml-kibana	Trying to authenticate user request to /api/telemetry/v2/clusters/_stats
Jan 13, 2022 @ 19:50:16.800	DEBUG	plugins.security.saml.cloud-saml-kibana	Cannot authenticate requests with `Authorization` header.
Jan 13, 2022 @ 19:50:16.799	DEBUG	plugins.security.basic.cloud-basic	Trying to authenticate user request to /api/telemetry/v2/clusters/_stats.
Jan 13, 2022 @ 19:50:16.799	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:16.797	DEBUG	http.server.response	GET /api/status 200 16ms - 12.0KB
Jan 13, 2022 @ 19:50:16.794	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized
Jan 13, 2022 @ 19:50:16.793	DEBUG	plugins.security.http	Request to /api/status has been authenticated via authorization header with "Basic" scheme.
Jan 13, 2022 @ 19:50:16.784	DEBUG	plugins.security.saml.cloud-saml-kibana	Trying to authenticate user request to /api/status
Jan 13, 2022 @ 19:50:16.784	DEBUG	plugins.security.saml.cloud-saml-kibana	Cannot authenticate requests with `Authorization` header.
Jan 13, 2022 @ 19:50:16.784	DEBUG	plugins.security.http	Trying to authenticate user request to /api/status.
Jan 13, 2022 @ 19:50:16.783	DEBUG	plugins.security.basic.cloud-basic	Cannot authenticate requests with `Authorization` header.
Jan 13, 2022 @ 19:50:16.783	DEBUG	plugins.security.basic.cloud-basic	Trying to authenticate user request to /api/status.
Jan 13, 2022 @ 19:50:16.782	DEBUG	http.server.Kibana.cookie-session-storage	Error: Unauthorized

So it seems like some internal service is calling /api/telemetry/v2/clusters/_stats and that's what is causing the calls that result in PIT errors; looking at the details of that response log, I noticed that the consumer is using kbn-xsrf: true in that request (another confirmation this is not coming from the Kibana client)

I can reproduce these errors on the Kibana server one time after a restart by calling:
curl -X POST -u kibana_system:changeme "http://localhost:5601/api/telemetry/v2/clusters/_stats" -H 'kbn-xsrf: true' -H 'Content-Type: application/json' -d'{"unencrypted": true}'

Subsequent calls don't generate the errors.

@TinaHeiligers
Copy link
Contributor

So maybe there is something in Cloud that is hitting this endpoint with the kibana_system user credentials?

Def something we should look into. @afharo this is another issue we need to investigate.

@afharo
Copy link
Member

afharo commented Jan 14, 2022

@jportner thanks for finding what the underlying issue is. It makes perfect sense!

FYI, we've been planning to run these requests using the kibana_system user for a long time. However, #96538 is needed to allow that because we don't want to expose stats to users that are not supposed to see/know that those features are enabled.


I can reproduce these errors on the Kibana server one time after a restart by calling: curl -X POST -u kibana_system:changeme "http://localhost:5601/api/telemetry/v2/clusters/_stats" -H 'kbn-xsrf: true' -H 'Content-Type: application/json' -d'{"unencrypted": true}'

Subsequent calls don't generate the errors.

The fact that the subsequent calls don't generate the errors makes me worry... I think it's a bug introduced by #117084. @Bamieh what do you think?

@jportner
Copy link
Contributor

jportner commented Jan 14, 2022

FYI, we've been planning to run these requests using the kibana_system user for a long time. However, #96538 is needed to allow that because we don't want to expose stats to users that are not supposed to see/know that those features are enabled.

By that I assume you mean you've been meaning to run those requests using the internal saved objects client (without the Security SOC wrapper / without checking the end user's privileges)?

Makes sense 👍

@Bamieh
Copy link
Member

Bamieh commented Jan 17, 2022

@afharo We are caching usage for 4 hours so any failed collectors will not be reported until the next caching cycle. This is not a bug but by how we've implemented the caching logic which worked at the top level of the service.

It makes sense to disable caching for unencrypted requests to resolve this.

@afharo
Copy link
Member

afharo commented Jan 19, 2022

I tried to replicate this scenario myself and I noticed something wrong with how Metricbeat is working:

Metricbeat is requesting GET /api/stats?extended=true and it's missing &exclude_usage=true. This happens for every poll EVERY 10 SECONDS! 🤯

IMO, it should always append that parameter if the version of Kibana supports it (m.isUsageExcludable is populated by checking that the version.number returned in the GET /api/status API is greater than 7.0.0). There are even tests that should ensure that it works that way.

cc @elastic/beats @elastic/cloud-applications-solutions can you help me with figuring out why this could happen.

@gigerdo
Copy link
Member

gigerdo commented Jan 19, 2022

I can help with debugging the cloud configs.

@afharo
Copy link
Member

afharo commented Jan 20, 2022

@gigerdo and I spent a good amount of time yesterday troubleshooting this! Thank you kindly for your support and invaluable insights from the Cloud POV 🧡 !

We confirmed that Metricbeat is reporting the URL without &exclude_usage=true because the defer statement reverts the URL after making the API call, so by the time Metricbeat appends it to the event, the parameter is gone (potential fix here). We also confirmed this behaviour by setting a local environment with the same roles as in Cloud.

The culprit for raising those errors is the internal metricbeat used by Cloud to monitor the deployments. It still runs 6.8.6. However, it was upgraded to 7.12.0 a few months ago and it's likely to hit production in the next couple of weeks.

I'll go ahead and close this issue. Feel free to reopen if there are any open questions I may have missed.

@nerophon
Copy link
Contributor

nerophon commented Apr 8, 2022

@afharo did the updated Metricbeat actually make it into production? We're still seeing the errors, though we're not sure if they are still caused by the old Metricbeat or by something else now.

@afharo
Copy link
Member

afharo commented Apr 21, 2022

@nerophon can you provide more info about where you're seeing this happening? I looked at the latest linked issue #129424 and the problem seems unrelated (it's happening on the UI).

@afharo
Copy link
Member

afharo commented Apr 21, 2022

@nerophon I ran a quick check to see the distribution of this error happening in Kibana and I noticed they are gone in the 8.x series. I think #96538 helped with that problem 😇

@legrego legrego removed the Team:Security Team focused on: Auth, Users, Roles, Spaces, Audit Logging, and more! label May 11, 2022
@afharo
Copy link
Member

afharo commented Jul 19, 2022

Closing this issue based on my last comment. Please, feel free to reopen if you think we should spend more time in it.

@afharo afharo closed this as completed Jul 19, 2022
@exalate-issue-sync exalate-issue-sync bot reopened this Sep 28, 2022
@afharo
Copy link
Member

afharo commented Sep 28, 2022

bad bot. Closing again.

@afharo afharo closed this as completed Sep 28, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Fixes for quality problems that affect the customer experience Feature:Telemetry impact:needs-assessment Product and/or Engineering needs to evaluate the impact of the change. loe:small Small Level of Effort Team:Core Core services & architecture: plugins, logging, config, saved objects, http, ES client, i18n, etc
Projects
None yet
Development

No branches or pull requests