"tags":["info","savedobjects-service"],"pid":X,"message":"Starting saved objects migrations"}

Elastic Stack Kibana
1

Hello World!

As I start Kibana, it takes kinda long to start and in logs I see "Starting saved objects migrations":

kibana  | {"type":"log","@timestamp":"2022-08-04T04:10:47+00:00","tags":["info","savedobjects-service"],"pid":6,"message":"Starting saved objects migrations"}
...
kibana  | {"type":"log","@timestamp":"2022-08-04T04:12:29+00:00","tags":["info","savedobjects-service"],"pid":6,"message":"[.kibana] Migration completed after 101772ms"}
kibana  | {"type":"log","@timestamp":"2022-08-04T04:12:29+00:00","tags":["info","status"],"pid":6,"message":"Kibana is now unavailable"}

Why is this happening every time I start Kibana? shouldn't be enough to migrate saved object once?)

Please advise)
Thank you!

2

Kibana reads all documents from the outdated index and then writes these into the target index in batches. may be this is causing latency and you are seeing repeated messages like this. I think it depends on the batch size.

[Discuss] Too many saved-objects + migrations == 馃挜 路 Issue #92933 路 elastic/kibana 路 GitHub has more information.

tagging @rudolf for more insights into this .

Thanks
Rashmi

3

@alexus Plugins register saved object types and migrations for those types. Because plugins can be enabled any time Kibana is restarted Kibana runs the migration code to check for any outdated documents.

You can read more details about the algorithm and design trade offs here kibana/0013_saved_object_migrations.md at 4fe8605c7b50e4a94e99fc63f64f05870ad449eb 路 elastic/kibana 路 GitHub

Having said that the time it takes to complete this startup migration seems quite long on your cluster. Could you share all the Kibana server logs?

4

What exactly are you looking to see? Kibana is being used, so there are a lot of log entries...

kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:51+00:00","tags":["info","plugins-service"],"pid":7,"message":"Plugin \"newsfeed\" is disabled."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:51+00:00","tags":["info","plugins-service"],"pid":7,"message":"Plugin \"metricsEntities\" is disabled."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["info","http","server","Preboot"],"pid":7,"message":"http server running at https://0.0.0.0:5601"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["warning","config","deprecation"],"pid":7,"message":"Starting in 8.0, the Kibana logging format will be changing. This may affect you if you are doing any special handling of your Kibana logs, such as ingesting logs into Elasticsearch for further analysis. If you are using the new logging configuration, you are already receiving logs in both old and new formats, and the old format will simply be going away. If you are not yet using the new logging configuration, the log format will change upon upgrade to 8.0. Beginning in 8.0, the format of JSON logs will be ECS-compatible JSON, and the default pattern log format will be configurable with our new logging system. Please refer to the documentation for more information about the new logging format."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["warning","config","deprecation"],"pid":7,"message":"Kibana is configured to authenticate to Elasticsearch with the \"elastic\" user. Use a service account token instead."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["warning","config","deprecation"],"pid":7,"message":"\"kibana.index\" is deprecated. Multitenancy by changing \"kibana.index\" will not be supported starting in 8.0. See https://ela.st/kbn-remove-legacy-multitenancy for more details"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["warning","config","deprecation"],"pid":7,"message":"Configuring \"xpack.infra.enabled\" is deprecated and will be removed in 8.0.0."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["warning","config","deprecation"],"pid":7,"message":"The default mechanism for Reporting privileges will work differently in future versions, which will affect the behavior of this cluster. Set \"xpack.reporting.roles.enabled\" to \"false\" to adopt the future behavior before upgrading."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["warning","config","deprecation"],"pid":7,"message":"Use the new ECS-compliant audit logger."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["warning","config","deprecation"],"pid":7,"message":"Use the new object format instead of an array of provider types."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["warning","config","deprecation"],"pid":7,"message":"User sessions will automatically time out after 8 hours of inactivity starting in 8.0. Override this value to change the timeout."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["warning","config","deprecation"],"pid":7,"message":"Users are automatically required to log in again after 30 days starting in 8.0. Override this value to change the timeout."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["info","plugins-system","standard"],"pid":7,"message":"Setting up [112] plugins: [translations,licensing,globalSearch,globalSearchProviders,features,licenseApiGuard,code,usageCollection,xpackLegacy,taskManager,telemetryCollectionManager,telemetryCollectionXpack,kibanaUsageCollection,share,embeddable,uiActionsEnhanced,screenshotMode,banners,telemetry,mapsEms,mapsLegacy,kibanaLegacy,fieldFormats,expressions,dataViews,charts,esUiShared,bfetch,data,savedObjects,presentationUtil,expressionShape,expressionRevealImage,expressionRepeatImage,expressionMetric,expressionImage,customIntegrations,home,searchprofiler,painlessLab,grokdebugger,management,watcher,licenseManagement,advancedSettings,spaces,security,savedObjectsTagging,reporting,canvas,lists,ingestPipelines,fileUpload,encryptedSavedObjects,dataEnhanced,cloud,snapshotRestore,eventLog,actions,alerting,triggersActionsUi,transform,stackAlerts,ruleRegistry,visualizations,visTypeXy,visTypeVislib,visTypeVega,visTypeTimelion,visTypeTagcloud,visTypeTable,visTypePie,visTypeMetric,visTypeMarkdown,tileMap,regionMap,expressionTagcloud,expressionMetricVis,console,graph,fleet,indexManagement,remoteClusters,crossClusterReplication,indexLifecycleManagement,dashboard,maps,dashboardMode,dashboardEnhanced,visualize,visTypeTimeseries,rollup,indexPatternFieldEditor,lens,cases,timelines,discover,osquery,observability,discoverEnhanced,dataVisualizer,ml,uptime,securitySolution,infra,upgradeAssistant,monitoring,logstash,enterpriseSearch,apm,savedObjectsManagement,indexPatternManagement]"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["info","plugins","taskManager"],"pid":7,"message":"TaskManager is identified by the Kibana UUID: d0ea5b96-1e4a-4a50-a3f3-6e64ec922034"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:52+00:00","tags":["info","plugins","ruleRegistry"],"pid":7,"message":"Installing common resources shared between all indices"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"Waiting until all Elasticsearch nodes are compatible with Kibana before starting saved objects migrations..."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"Starting saved objects migrations"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana_task_manager] INIT -> OUTDATED_DOCUMENTS_SEARCH_OPEN_PIT. took: 26ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana] INIT -> OUTDATED_DOCUMENTS_SEARCH_OPEN_PIT. took: 35ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana] OUTDATED_DOCUMENTS_SEARCH_OPEN_PIT -> OUTDATED_DOCUMENTS_SEARCH_READ. took: 21ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana_task_manager] OUTDATED_DOCUMENTS_SEARCH_OPEN_PIT -> OUTDATED_DOCUMENTS_SEARCH_READ. took: 36ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana_task_manager] OUTDATED_DOCUMENTS_SEARCH_READ -> OUTDATED_DOCUMENTS_SEARCH_CLOSE_PIT. took: 29ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana] OUTDATED_DOCUMENTS_SEARCH_READ -> OUTDATED_DOCUMENTS_SEARCH_CLOSE_PIT. took: 52ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana_task_manager] OUTDATED_DOCUMENTS_SEARCH_CLOSE_PIT -> UPDATE_TARGET_MAPPINGS. took: 19ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana] OUTDATED_DOCUMENTS_SEARCH_CLOSE_PIT -> UPDATE_TARGET_MAPPINGS. took: 20ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana_task_manager] UPDATE_TARGET_MAPPINGS -> UPDATE_TARGET_MAPPINGS_WAIT_FOR_TASK. took: 47ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana] UPDATE_TARGET_MAPPINGS -> UPDATE_TARGET_MAPPINGS_WAIT_FOR_TASK. took: 80ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana_task_manager] UPDATE_TARGET_MAPPINGS_WAIT_FOR_TASK -> DONE. took: 224ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:25:54+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana_task_manager] Migration completed after 382ms"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:15+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana] UPDATE_TARGET_MAPPINGS_WAIT_FOR_TASK -> DONE. took: 81676ms."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:15+00:00","tags":["info","savedobjects-service"],"pid":7,"message":"[.kibana] Migration completed after 81886ms"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:16+00:00","tags":["info","status"],"pid":7,"message":"Kibana is now unavailable"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:16+00:00","tags":["info","plugins-system","standard"],"pid":7,"message":"Starting [112] plugins: [translations,licensing,globalSearch,globalSearchProviders,features,licenseApiGuard,code,usageCollection,xpackLegacy,taskManager,telemetryCollectionManager,telemetryCollectionXpack,kibanaUsageCollection,share,embeddable,uiActionsEnhanced,screenshotMode,banners,telemetry,mapsEms,mapsLegacy,kibanaLegacy,fieldFormats,expressions,dataViews,charts,esUiShared,bfetch,data,savedObjects,presentationUtil,expressionShape,expressionRevealImage,expressionRepeatImage,expressionMetric,expressionImage,customIntegrations,home,searchprofiler,painlessLab,grokdebugger,management,watcher,licenseManagement,advancedSettings,spaces,security,savedObjectsTagging,reporting,canvas,lists,ingestPipelines,fileUpload,encryptedSavedObjects,dataEnhanced,cloud,snapshotRestore,eventLog,actions,alerting,triggersActionsUi,transform,stackAlerts,ruleRegistry,visualizations,visTypeXy,visTypeVislib,visTypeVega,visTypeTimelion,visTypeTagcloud,visTypeTable,visTypePie,visTypeMetric,visTypeMarkdown,tileMap,regionMap,expressionTagcloud,expressionMetricVis,console,graph,fleet,indexManagement,remoteClusters,crossClusterReplication,indexLifecycleManagement,dashboard,maps,dashboardMode,dashboardEnhanced,visualize,visTypeTimeseries,rollup,indexPatternFieldEditor,lens,cases,timelines,discover,osquery,observability,discoverEnhanced,dataVisualizer,ml,uptime,securitySolution,infra,upgradeAssistant,monitoring,logstash,enterpriseSearch,apm,savedObjectsManagement,indexPatternManagement]"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","monitoring","monitoring"],"pid":7,"message":"config sourced from: production cluster"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","status"],"pid":7,"message":"Kibana is now degraded (was unavailable)"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","monitoring","monitoring","kibana-monitoring"],"pid":7,"message":"Starting monitoring stats collection"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","ruleRegistry"],"pid":7,"message":"Installed common resources shared between all indices"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","ruleRegistry"],"pid":7,"message":"Installing resources for index .alerts-observability.uptime.alerts"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","ruleRegistry"],"pid":7,"message":"Installing resources for index .alerts-observability.logs.alerts"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","ruleRegistry"],"pid":7,"message":"Installing resources for index .alerts-observability.metrics.alerts"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","ruleRegistry"],"pid":7,"message":"Installing resources for index .alerts-observability.apm.alerts"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","ruleRegistry"],"pid":7,"message":"Installed resources for index .alerts-observability.apm.alerts"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","ruleRegistry"],"pid":7,"message":"Installed resources for index .alerts-observability.metrics.alerts"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","ruleRegistry"],"pid":7,"message":"Installed resources for index .alerts-observability.logs.alerts"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:17+00:00","tags":["info","plugins","ruleRegistry"],"pid":7,"message":"Installed resources for index .alerts-observability.uptime.alerts"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:18+00:00","tags":["info","plugins","securitySolution"],"pid":7,"message":"Dependent plugin setup complete - Starting ManifestTask"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:19+00:00","tags":["info","plugins","reporting","chromium"],"pid":7,"message":"Browser executable: /usr/share/kibana/x-pack/plugins/reporting/chromium/headless_shell-linux_x64/headless_shell"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:19+00:00","tags":["warning","plugins","reporting","chromium"],"pid":7,"message":"Enabling the Chromium sandbox provides an additional layer of protection."}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:27:24+00:00","tags":["info","http","server","Kibana"],"pid":7,"message":"http server running at https://0.0.0.0:5601"}
kibana11-re  | {"type":"response","@timestamp":"2022-08-10T17:27:28+00:00","tags":[],"pid":7,"method":"head","statusCode":200,"req":{"url":"/login","method":"head","headers":{"host":"localhost:5601","user-agent":"curl/7.68.0","accept":"*/*"},"remoteAddress":"127.0.0.1","userAgent":"curl/7.68.0"},"res":{"statusCode":200,"responseTime":45,"contentLength":82970},"message":"HEAD /login 200 45ms - 81.0KB"}
kibana11-re  | {"type":"response","@timestamp":"2022-08-10T17:27:58+00:00","tags":[],"pid":7,"method":"head","statusCode":200,"req":{"url":"/login","method":"head","headers":{"host":"localhost:5601","user-agent":"curl/7.68.0","accept":"*/*"},"remoteAddress":"127.0.0.1","userAgent":"curl/7.68.0"},"res":{"statusCode":200,"responseTime":22,"contentLength":82970},"message":"HEAD /login 200 22ms - 81.0KB"}
kibana11-re  | {"type":"log","@timestamp":"2022-08-10T17:28:07+00:00","tags":["info","status"],"pid":7,"message":"Kibana is now available (was degraded)"}
5

"message":"[.kibana] UPDATE_TARGET_MAPPINGS_WAIT_FOR_TASK -> DONE. took: 81676ms."}

So the majority of the time is spent in this step where we update the mappings of the index and run an updateByQuery on the index.

How many saved objects do you have, could you run GET /.kibana/_count ?

Also is there any operational impact because Kibana takes a few minutes to start?

6

about ~34k

#! this request accesses system indices: [.kibana_7.17.4_001], but in a future major version, direct access to system indices will be prevented by default
{
  "count" : 33817,
  "_shards" : {
    "total" : 1,
    "successful" : 1,
    "skipped" : 0,
    "failed" : 0
  }
}

It's not end of the world.. however it does take fairly long time to restart Kibana whenever is required.. I'm confused why is it keep doing every time I restart Kibana? assuming that the saved objects were already update/migrate..

7

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.