Why do I need to wait half an hour for INFO: found new file?

[summerance]

you can see I started at 2022-09-27T06:58:56,the first INFO about "Found new file to watch" is at 2022-09-27T07:21:23.

2022-09-27T06:58:56.292414Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.011948470014872512
2022-09-27T06:59:01.292041Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0011950196332200598
2022-09-27T06:59:06.292266Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00011966161615416054
2022-09-27T06:59:11.292703Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.000012125088649249184
2022-09-27T06:59:16.292812Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0000013469674660780495
2022-09-27T06:59:21.292293Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.0000002783504350525164
2022-09-27T06:59:26.292669Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00000018658386359462327
2022-09-27T06:59:31.292388Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00000020280995875050707
.......
2022-09-27T07:21:21.292625Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.00000004221577949292724
2022-09-27T07:21:23.965736Z DEBUG source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}:file_server: file_source::file_watcher: Not reading gzipped file older than `ignore_older`. path="/onlinelogs/..../requests.log.2022-09-25-23.msps-t1-na-02-1e-m54-df006168.us-east-1.gz"
2022-09-27T07:21:23.965819Z  INFO source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}:file_server: vector::internal_events::file::source: Found new file to watch. file=/onlinelogs/..../requests.log.2022-09-25-23.msps-t1-na-02-1e-m54-df006168.us-east-1.gz
2022-09-27T07:21:23.970066Z DEBUG source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}:file_server: file_source::file_watcher: Not reading gzipped file older than `ignore_older`. path="/onlinelogs/..../requests.log.2022-09-25-23.msps-t1-na-02-1e-m54-d484253c.us-east-1.gz"
........

when include = [ "/onlinelogs/.../2022/09/25/00/request*.gz” ] ,it can INFO:found new file immediately.There are 24 matched gzip files at /onlinelogs/.../2022/09/25/00/.
when include = [ "/onlinelogs/.../2022/09/25/**/request*.gz” ] ,I need to wait about half an hour for INFO: found new file.There are 24*24 matched gzip files at /onlinelogs/.../2022/09/25/**/.
when include = [ "/onlinelogs/.../2022/09/**/request*.gz” ],there is no INFO:found new file though I have waited for 1 hour.There are 24*24*30 matched gzip files at /onlinelogs/.../2022/09/**/.
each matched gzip file is 3GB.

[spencergilbert]

Please share your configuration as part of the question.

[spencergilbert]

What didn't work, and what logs did Vector emit.

[summerance]

What didn't work, and what logs did Vector emit.

uesd fingerprint.strategy = "device_and_inode",still no INFO log for finding a new file
the DEBUG seems like a loop：

2022-09-29T15:22:03.339415Z  INFO vector::app: Log level is enabled. level="vector=debug,codec=debug,vrl=debug,file_source=debug,tower_limit=trace,rdkafka=debug,buffers=debug,kube=debug"
2022-09-29T15:22:03.339540Z  INFO vector::app: Loading configs. paths=["/local/.vector/config/vector_temp.toml"]
2022-09-29T15:22:03.340518Z DEBUG vector::config::loading: No secret placeholder found, skipping secret resolution.
2022-09-29T15:22:03.342097Z DEBUG vector::topology::builder: Building new source. component=gz_logs
2022-09-29T15:22:03.342683Z DEBUG vector::topology::builder: Building new transform. component=parse_logs
2022-09-29T15:22:03.343204Z DEBUG vector::topology::builder: Building new sink component=print
2022-09-29T15:22:03.344472Z  INFO vector::topology::running: Running healthchecks.
2022-09-29T15:22:03.344514Z DEBUG vector::topology::running: Connecting changed/added component(s).
2022-09-29T15:22:03.344538Z DEBUG vector::topology::running: Configuring outputs for source. component=gz_logs
2022-09-29T15:22:03.344574Z DEBUG vector::topology::running: Configuring output for component. component=gz_logs output_id=None
2022-09-29T15:22:03.344597Z DEBUG vector::topology::running: Configuring outputs for transform. component=parse_logs
2022-09-29T15:22:03.344617Z DEBUG vector::topology::running: Configuring output for component. component=parse_logs output_id=None
2022-09-29T15:22:03.344644Z DEBUG vector::topology::running: Connecting inputs for transform. component=parse_logs
2022-09-29T15:22:03.344685Z DEBUG vector::topology::running: Adding component input to fanout. component=parse_logs fanout_id=gz_logs
2022-09-29T15:22:03.344774Z DEBUG vector::topology::running: Connecting inputs for sink. component=print
2022-09-29T15:22:03.344799Z DEBUG vector::topology::running: Adding component input to fanout. component=print fanout_id=parse_logs
2022-09-29T15:22:03.344822Z DEBUG vector::topology::running: Spawning new source. key=gz_logs
2022-09-29T15:22:03.344876Z DEBUG vector::topology::running: Spawning new transform. key=parse_logs
2022-09-29T15:22:03.345687Z  INFO vector: Vector has started. debug="false" version="0.23.3" arch="x86_64" build_id="af8c9e1 2022-08-10"
2022-09-29T15:22:03.345742Z  INFO vector::app: API is disabled, enable by setting `api.enabled` to `true` and use commands like `vector top`.
2022-09-29T15:22:03.345742Z  INFO source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}: vector::sources::file: Starting file server. include=["/onlinelog
s/MerchantShippingPluginService/NA/Tier1/Prod/09/**/request*.gz"] exclude=[]
2022-09-29T15:22:03.346032Z DEBUG source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}: vector::topology::builder: Source pump starting.
2022-09-29T15:22:03.347161Z  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-29T15:22:03.347232Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.14754096909435999
2022-09-29T15:22:03.351006Z  INFO vector::topology::builder: Healthcheck: Passed.
2022-09-29T15:22:04.349714Z DEBUG vector::internal_events::file::source: Files checkpointed. count=37 duration_ms=1
2022-09-29T15:22:04.380135Z DEBUG source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}:file_server: file_source::file_server: event_throughput=0.000/sec 
bytes_throughput=0.000/sec ratios={"discovery": 3.925611e-5, "other": 8.863102e-5, "sending": 0.000115167466, "sleeping": 0.99975795}
2022-09-29T15:22:05.350756Z DEBUG vector::internal_events::file::source: Files checkpointed. count=37 duration_ms=0
2022-09-29T15:22:05.406140Z DEBUG source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}:file_server: file_source::file_server: event_throughput=0.000/sec 
bytes_throughput=0.000/sec ratios={"discovery": 4.853883e-5, "other": 8.6092805e-5, "sending": 7.3230585e-5, "sleeping": 0.9997927}
2022-09-29T15:22:06.351518Z DEBUG vector::internal_events::file::source: Files checkpointed. count=37 duration_ms=0
2022-09-29T15:22:07.352974Z DEBUG vector::internal_events::file::source: Files checkpointed. count=37 duration_ms=0
2022-09-29T15:22:07.455377Z DEBUG source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}:file_server: file_source::file_server: event_throughput=0.000/sec 
bytes_throughput=0.000/sec ratios={"discovery": 3.919735e-5, "other": 6.214244e-5, "sending": 4.714529e-5, "sleeping": 0.99985176}
2022-09-29T15:22:08.346653Z DEBUG sink{component_kind="sink" component_id=print component_type=kafka component_name=print}: vector::utilization: utilization=0.014754193039027782
2022-09-29T15:22:08.353831Z DEBUG vector::internal_events::file::source: Files checkpointed. count=37 duration_ms=0
2022-09-29T15:22:09.354328Z DEBUG vector::internal_events::file::source: Files checkpointed. count=37 duration_ms=0
2022-09-29T15:22:09.504757Z DEBUG source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}:file_server: file_source::file_server: event_throughput=0.000/sec 
bytes_throughput=0.000/sec ratios={"discovery": 3.5944133e-5, "other": 5.606769e-5, "sending": 3.3784116e-5, "sleeping": 0.9998745}

[spencergilbert]

How many files are included in /onlinelog s/MerchantShippingPluginService/NA/Tier1/Prod/09/**/request*.gz? Vector has logged Files checkpointed. count=37 and as stated in the docs previously checkpointed, compressed files will not be reread.

[syzcch]

How many files are included in /onlinelog s/MerchantShippingPluginService/NA/Tier1/Prod/09/**/request*.gz? Vector has logged Files checkpointed. count=37 and as stated in the docs previously checkpointed, compressed files will not be reread.

The number of files is about 17280. 24 files are generated per hour(576 files are generated per day) and there are around 30days in Sept so the number should be 17280.

We started Vector and waiting for about 5-6 hours but still no new file found. But actually we generate 24 new files per hour. Maybe the number 17280 is too big for Vector?

@spencergilbert Could you please help us to check it? Thank you so much.

[syzcch]

@spencergilbert @jszwedko Could you please help us to check this question? Thank you so much.