ERROR vector_common::shutdown

[summerance]

Today when I tried it for the first time, everything was normal, and I ran part of the logs then killed the vector process but the second time I tried the same configuration:

2022-09-26T10:56:27.700249Z  INFO vector: Vector has started. debug="false" version="0.23.3" arch="x86_64" build_id="af8c9e1 2022-08-10"
2022-09-26T10:56:27.700300Z  INFO vector::app: API is disabled, enable by setting `api.enabled` to `true` and use commands like `vector top`.
2022-09-26T10:56:27.701532Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.03563312858561618
2022-09-26T10:56:27.706640Z  INFO vector::topology::builder: Healthcheck: Passed.
2022-09-26T10:56:27.707175Z  INFO source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}:file_server: file_source::checkpointer: Loaded checkpoint data.
2022-09-26T10:56:32.701949Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0035634098708080533
2022-09-26T10:56:37.701961Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0003564376470193585
2022-09-26T10:56:42.702257Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0000357492388535485
2022-09-26T10:56:47.701564Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0000037288444315635125
2022-09-26T10:56:52.701853Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0000005094966011423447
2022-09-26T10:56:57.702025Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0000001776653743357492
2022-09-26T10:57:02.701997Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0000001282872748954471
2022-09-26T10:57:07.701478Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00000018403047716643056
2022-09-26T10:57:12.701871Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00000029557445404319154
2022-09-26T10:57:17.702006Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00000035552820618820824
2022-09-26T10:57:22.701870Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0000002760394609204501
2022-09-26T10:57:27.701512Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0000002135572931125849
2022-09-26T10:57:32.701541Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00000021377695416511442
2022-09-26T10:57:37.701436Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00000018086280703363063
2022-09-26T10:57:42.701365Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0000004275835011360716

After waiting for a while, there was no INFO about " file_server: vector::internal_events::file::source: Found new file to watch."So I Ctrl + c to stop the vector
It showed these errors additionally:

2022-09-26T11:02:37.459970Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00000016625778030534048
2022-09-26T11:02:37.808384Z  INFO vector::topology::running: Shutting down... Waiting on running components. remaining_components="parse_logs, gz_logs, print" time_remaining="4 seconds left"
2022-09-26T11:02:42.460248Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00000011021953427571457
2022-09-26T11:02:42.807773Z ERROR vector_common::shutdown: Source 'gz_logs' failed to shutdown before deadline. Forcing shutdown.
2022-09-26T11:02:42.807847Z ERROR vector::topology::running: Failed to gracefully shut down in time. Killing components. components="parse_logs, gz_logs, print"
2022-09-26T11:02:42.807898Z DEBUG source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}: vector::topology::builder: Finished.

my vector version is 0.23.3.

[spencergilbert]

👋

2022-09-26T10:56:27.707175Z  INFO source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}:file_server: file_source::checkpointer: Loaded checkpoint data.

This implies it reloaded old data, and may not have discovered new files to tail at the time.

Forcing shutdown happens when we can gracefully exit the topology within 60 seconds, either due to still having lines to read from open files or having connections open to upstream clients.

I'd suggest monitoring Vector's activity either with the internal API:

2022-09-26T10:56:27.700300Z  INFO vector::app: API is disabled, enable by setting `api.enabled` to `true` and use commands like `vector top`.

Or using the internal_metrics source exposed to your preferred metrics sink.