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.

Sign up for GitHub

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

Jump to bottom

[Filebeat] Flaky test_rotating_close_inactive_larger_write_rate test in Filebeat #7725

Closed
ruflin opened this issue Jul 25, 2018 · 3 comments
Closed

[Filebeat] Flaky test_rotating_close_inactive_larger_write_rate test in Filebeat #7725

ruflin opened this issue Jul 25, 2018 · 3 comments
Assignees
@andrewvc
Labels
bug Filebeat Filebeat flaky-test Unstable or unreliable test cases.

Comments

@ruflin
Copy link
Member

ruflin commented Jul 25, 2018

Error:

20:54:56 ======================================================================
20:54:56 FAIL: test_rotating_close_inactive_larger_write_rate (test_input.Test)
20:54:56 ----------------------------------------------------------------------
20:54:56 Traceback (most recent call last):
20:54:56   File "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/tests/system/test_input.py", line 108, in test_rotating_close_inactive_larger_write_rate
20:54:56     proc.check_kill_and_wait()
20:54:56   File "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/tests/system/../../../libbeat/tests/system/beat/beat.py", line 94, in check_kill_and_wait
20:54:56     return self.check_wait(exit_code=exit_code)
20:54:56   File "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/tests/system/../../../libbeat/tests/system/beat/beat.py", line 83, in check_wait
20:54:56     exit_code, actual_exit_code)
20:54:56 AssertionError: Expected exit code to be 0, but it was 1
20:54:56 
20:54:56 ----------------------------------------------------------------------
20:54:56 XML: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/TEST-system.xml

Log

2018-07-24T13:50:54.933-0700	INFO	instance/beat.go:544	Home path: [/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate] Config path: [/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate] Data path: [/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/data] Logs path: [/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/logs]
2018-07-24T13:50:54.933-0700	DEBUG	[beat]	instance/beat.go:571	Beat metadata path: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/data/meta.json
2018-07-24T13:50:54.934-0700	INFO	instance/beat.go:551	Beat UUID: 33478cac-dbdb-4c8e-aa0f-19fa1a5dbd23
2018-07-24T13:50:54.934-0700	DEBUG	[seccomp]	seccomp/seccomp.go:88	Syscall filtering is only supported on Linux
2018-07-24T13:50:54.934-0700	INFO	[beat]	instance/beat.go:768	Beat info	{"system_info": {"beat": {"path": {"config": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate", "data": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/data", "home": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate", "logs": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/logs"}, "type": "filebeat", "uuid": "33478cac-dbdb-4c8e-aa0f-19fa1a5dbd23"}}}
2018-07-24T13:50:54.934-0700	INFO	[beat]	instance/beat.go:777	Build info	{"system_info": {"build": {"commit": "unknown", "libbeat": "7.0.0-alpha1", "time": "1754-08-30T22:43:41.128Z", "version": "7.0.0-alpha1"}}}
2018-07-24T13:50:54.934-0700	INFO	[beat]	instance/beat.go:780	Go runtime info	{"system_info": {"go": {"os":"darwin","arch":"amd64","max_procs":4,"version":"go1.10.3"}}}
2018-07-24T13:50:54.936-0700	INFO	[beat]	instance/beat.go:784	Host info	{"system_info": {"host": {"architecture":"x86_64","boot_time":"2018-04-05T05:30:55.444321-07:00","hostname":"worker-agbo6zasds2.build.macstadium.elasticnet.co","ips":["127.0.0.1/8","::1/128","fe80::1/64","fe80::85d:6259:965c:2787/64","207.254.45.97/23"],"kernel_version":"16.7.0","mac_addresses":["10:dd:b1:c9:1c:0f","28:cf:e9:07:70:73","32:00:14:8c:df:80","44:fb:42:ff:fe:48:cd:f8","0a:cf:e9:07:70:73","ea:af:d4:79:e6:2c","32:00:14:8c:df:80"],"os":{"family":"darwin","platform":"darwin","name":"Mac OS X","version":"10.12.6","major":10,"minor":12,"patch":6,"build":"16G1314"},"timezone":"PDT","timezone_offset_sec":-25200}}}
2018-07-24T13:50:54.937-0700	INFO	[beat]	instance/beat.go:813	Process info	{"system_info": {"process": {"cwd": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat", "exe": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/filebeat.test", "name": "filebeat.test", "pid": 42301, "ppid": 41802, "start_time": "2018-07-24T13:50:54.853-0700"}}}
2018-07-24T13:50:54.938-0700	INFO	instance/beat.go:273	Setup Beat: filebeat; Version: 7.0.0-alpha1
2018-07-24T13:50:54.938-0700	DEBUG	[beat]	instance/beat.go:290	Initializing output plugins
2018-07-24T13:50:54.938-0700	DEBUG	[processors]	processors/processor.go:66	Processors: 
2018-07-24T13:50:54.938-0700	DEBUG	[rotator]	file/rotator.go:135	Initialized file rotator	{"rotator": {"filename": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/output/filebeat", "max_size_bytes": 1024000, "max_backups": 7, "permissions": "-rw-------"}}
2018-07-24T13:50:54.939-0700	INFO	fileout/file.go:94	Initialized file output. path=/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/output/filebeat max_size_bytes=1024000 max_backups=7 permissions=-rw-------
2018-07-24T13:50:54.940-0700	DEBUG	[publish]	pipeline/consumer.go:137	start pipeline event consumer
2018-07-24T13:50:54.940-0700	INFO	pipeline/module.go:98	Beat name: worker-agbo6zasds2.build.macstadium.elasticnet.co
2018-07-24T13:50:54.940-0700	ERROR	fileset/modules.go:118	Not loading modules. Module directory not found: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/module
2018-07-24T13:50:54.941-0700	INFO	[monitoring]	log/log.go:114	Starting metrics logging every 30s
2018-07-24T13:50:54.941-0700	INFO	instance/beat.go:367	filebeat start running.
2018-07-24T13:50:54.941-0700	INFO	registrar/registrar.go:97	No registry file found under: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry. Creating a new registry file.
2018-07-24T13:50:54.942-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:54.942-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 0 states written.
2018-07-24T13:50:54.943-0700	INFO	registrar/registrar.go:134	Loading registrar data from /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:54.943-0700	INFO	registrar/registrar.go:141	States Loaded from registrar: 0
2018-07-24T13:50:54.943-0700	WARN	beater/filebeat.go:371	Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2018-07-24T13:50:54.943-0700	DEBUG	[registrar]	registrar/registrar.go:267	Starting Registrar
2018-07-24T13:50:54.943-0700	INFO	crawler/crawler.go:72	Loading Inputs: 1
2018-07-24T13:50:54.944-0700	DEBUG	[processors]	processors/processor.go:66	Processors: 
2018-07-24T13:50:54.945-0700	DEBUG	[input]	log/config.go:201	recursive glob enabled
2018-07-24T13:50:54.947-0700	DEBUG	[input]	log/input.go:147	exclude_files: []. Number of stats: 0
2018-07-24T13:50:54.947-0700	DEBUG	[input]	log/input.go:168	input with previous states loaded: 0
2018-07-24T13:50:54.947-0700	INFO	log/input.go:138	Configured paths: [/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/*]
2018-07-24T13:50:54.947-0700	INFO	input/input.go:114	Starting input of type: log; ID: 89240916616959135 
2018-07-24T13:50:54.947-0700	INFO	crawler/crawler.go:106	Loading and starting Inputs completed. Enabled inputs: 1
2018-07-24T13:50:54.947-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:54.947-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 0, After: 0, Pending: 0
2018-07-24T13:50:55.111-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:55.111-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:55.111-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 0, After: 0, Pending: 0
2018-07-24T13:50:55.212-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:55.212-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:55.212-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 0, After: 0, Pending: 0
2018-07-24T13:50:55.318-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:55.318-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:55.318-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 0, After: 0, Pending: 0
2018-07-24T13:50:55.444-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:55.444-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:55.444-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 0, After: 0, Pending: 0
2018-07-24T13:50:55.597-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:55.597-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:55.597-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 0, After: 0, Pending: 0
2018-07-24T13:50:55.740-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:55.740-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:55.740-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 0, After: 0, Pending: 0
2018-07-24T13:50:55.876-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:55.876-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:55.876-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 0, After: 0, Pending: 0
2018-07-24T13:50:55.988-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:55.988-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:55.988-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:55.988-0700	DEBUG	[input]	log/input.go:477	Start harvester for new file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:55.989-0700	DEBUG	[harvester]	log/harvester.go:486	Setting offset for file based on seek: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:55.990-0700	DEBUG	[harvester]	log/harvester.go:472	Setting offset for file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log. Offset: 0 
2018-07-24T13:50:55.990-0700	DEBUG	[harvester]	log/harvester.go:387	Update state: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log, offset: 0
2018-07-24T13:50:55.990-0700	DEBUG	[input]	file/states.go:68	New state added for /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:55.991-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 1, After: 1, Pending: 0
2018-07-24T13:50:55.990-0700	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-07-24T13:50:55.991-0700	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-07-24T13:50:55.991-0700	DEBUG	[input]	file/states.go:68	New state added for /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:55.991-0700	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-07-24T13:50:55.991-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:55.992-0700	INFO	log/harvester.go:251	Harvester started for file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:55.993-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 1 states written.
2018-07-24T13:50:55.993-0700	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
  "@timestamp": "2018-07-24T20:50:55.992Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0-alpha1"
  },
  "offset": 0,
  "prospector": {
    "type": "log"
  },
  "input": {
    "type": "log"
  },
  "host": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co"
  },
  "beat": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "hostname": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "version": "7.0.0-alpha1"
  },
  "message": "hello world 0",
  "source": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log"
}
2018-07-24T13:50:55.994-0700	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
  "@timestamp": "2018-07-24T20:50:55.993Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0-alpha1"
  },
  "source": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log",
  "offset": 14,
  "message": "hello world 1",
  "prospector": {
    "type": "log"
  },
  "input": {
    "type": "log"
  },
  "host": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co"
  },
  "beat": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "hostname": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "version": "7.0.0-alpha1"
  }
}
2018-07-24T13:50:55.995-0700	DEBUG	[harvester]	log/log.go:102	End of file reached: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log; Backoff now.
2018-07-24T13:50:56.091-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:56.092-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:56.092-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.092-0700	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log, offset: 28
2018-07-24T13:50:56.092-0700	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.092-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 1, After: 1, Pending: 0
2018-07-24T13:50:56.105-0700	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
  "@timestamp": "2018-07-24T20:50:56.104Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0-alpha1"
  },
  "message": "hello world 2",
  "input": {
    "type": "log"
  },
  "prospector": {
    "type": "log"
  },
  "host": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co"
  },
  "beat": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "hostname": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "version": "7.0.0-alpha1"
  },
  "source": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log",
  "offset": 28
}
2018-07-24T13:50:56.105-0700	DEBUG	[harvester]	log/log.go:102	End of file reached: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log; Backoff now.
2018-07-24T13:50:56.105-0700	DEBUG	[memqueue]	memqueue/ackloop.go:160	ackloop: receive ack [0: 0, 2]
2018-07-24T13:50:56.105-0700	DEBUG	[memqueue]	memqueue/eventloop.go:535	broker ACK events: count=2, start-seq=1, end-seq=2

2018-07-24T13:50:56.105-0700	DEBUG	[memqueue]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:2
2018-07-24T13:50:56.105-0700	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 2}
2018-07-24T13:50:56.106-0700	DEBUG	[memqueue]	memqueue/ackloop.go:131	ackloop:  done send ack
2018-07-24T13:50:56.106-0700	DEBUG	[registrar]	registrar/registrar.go:345	Processing 2 events
2018-07-24T13:50:56.106-0700	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 2
2018-07-24T13:50:56.106-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:56.107-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 1 states written.
2018-07-24T13:50:56.232-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:56.232-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:56.232-0700	DEBUG	[harvester]	log/log.go:102	End of file reached: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log; Backoff now.
2018-07-24T13:50:56.232-0700	DEBUG	[memqueue]	memqueue/ackloop.go:160	ackloop: receive ack [1: 0, 1]
2018-07-24T13:50:56.233-0700	DEBUG	[memqueue]	memqueue/eventloop.go:535	broker ACK events: count=1, start-seq=3, end-seq=3

2018-07-24T13:50:56.233-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.233-0700	DEBUG	[memqueue]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:1
2018-07-24T13:50:56.233-0700	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-07-24T13:50:56.233-0700	DEBUG	[input]	log/input.go:477	Start harvester for new file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.233-0700	DEBUG	[memqueue]	memqueue/ackloop.go:131	ackloop:  done send ack
2018-07-24T13:50:56.233-0700	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-07-24T13:50:56.233-0700	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-07-24T13:50:56.233-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:56.234-0700	DEBUG	[harvester]	log/harvester.go:486	Setting offset for file based on seek: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.234-0700	DEBUG	[harvester]	log/harvester.go:472	Setting offset for file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log. Offset: 0 
2018-07-24T13:50:56.234-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 1 states written.
2018-07-24T13:50:56.234-0700	DEBUG	[harvester]	log/harvester.go:387	Update state: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log, offset: 0
2018-07-24T13:50:56.234-0700	DEBUG	[input]	file/states.go:68	New state added for /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.235-0700	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-07-24T13:50:56.235-0700	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-07-24T13:50:56.235-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23
2018-07-24T13:50:56.235-0700	DEBUG	[input]	file/states.go:68	New state added for /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.235-0700	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, offset: 42
2018-07-24T13:50:56.235-0700	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-07-24T13:50:56.235-0700	DEBUG	[input]	log/input.go:527	File rename was detected: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log -> /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, Current offset: 42
2018-07-24T13:50:56.235-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:56.235-0700	DEBUG	[input]	log/input.go:540	File rename detected but harvester not finished yet.
2018-07-24T13:50:56.235-0700	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23
2018-07-24T13:50:56.235-0700	INFO	log/harvester.go:251	Harvester started for file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.236-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2018-07-24T13:50:56.236-0700	DEBUG	[input]	log/input.go:226	State for file not removed because harvester not finished: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.236-0700	DEBUG	[input]	log/input.go:216	Remove state for file as file removed or renamed: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.236-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-07-24T13:50:56.237-0700	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
  "@timestamp": "2018-07-24T20:50:56.236Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0-alpha1"
  },
  "beat": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "hostname": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "version": "7.0.0-alpha1"
  },
  "host": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co"
  },
  "source": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log",
  "offset": 0,
  "message": "hello world 3",
  "prospector": {
    "type": "log"
  },
  "input": {
    "type": "log"
  }
}
2018-07-24T13:50:56.237-0700	DEBUG	[harvester]	log/log.go:102	End of file reached: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log; Backoff now.
2018-07-24T13:50:56.351-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:56.352-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:56.352-0700	DEBUG	[memqueue]	memqueue/ackloop.go:160	ackloop: receive ack [2: 0, 1]
2018-07-24T13:50:56.352-0700	DEBUG	[memqueue]	memqueue/eventloop.go:535	broker ACK events: count=1, start-seq=4, end-seq=4

2018-07-24T13:50:56.352-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.352-0700	DEBUG	[memqueue]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:1
2018-07-24T13:50:56.352-0700	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log, offset: 28
2018-07-24T13:50:56.352-0700	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
  "@timestamp": "2018-07-24T20:50:56.351Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0-alpha1"
  },
  "host": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co"
  },
  "source": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log",
  "offset": 14,
  "message": "hello world 4",
  "prospector": {
    "type": "log"
  },
  "input": {
    "type": "log"
  },
  "beat": {
    "hostname": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "version": "7.0.0-alpha1",
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co"
  }
}
2018-07-24T13:50:56.352-0700	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.352-0700	DEBUG	[memqueue]	memqueue/ackloop.go:131	ackloop:  done send ack
2018-07-24T13:50:56.352-0700	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-07-24T13:50:56.352-0700	DEBUG	[harvester]	log/log.go:102	End of file reached: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log; Backoff now.
2018-07-24T13:50:56.352-0700	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-07-24T13:50:56.352-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23
2018-07-24T13:50:56.352-0700	DEBUG	[harvester]	log/log.go:102	End of file reached: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log; Backoff now.
2018-07-24T13:50:56.353-0700	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-07-24T13:50:56.353-0700	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, offset: 42
2018-07-24T13:50:56.353-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:56.353-0700	DEBUG	[input]	log/input.go:527	File rename was detected: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log -> /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, Current offset: 42
2018-07-24T13:50:56.353-0700	DEBUG	[input]	log/input.go:540	File rename detected but harvester not finished yet.
2018-07-24T13:50:56.353-0700	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23
2018-07-24T13:50:56.353-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2018-07-24T13:50:56.353-0700	DEBUG	[input]	log/input.go:226	State for file not removed because harvester not finished: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.353-0700	DEBUG	[input]	log/input.go:216	Remove state for file as file removed or renamed: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.354-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-07-24T13:50:56.466-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:56.466-0700	DEBUG	[harvester]	log/log.go:102	End of file reached: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log; Backoff now.
2018-07-24T13:50:56.466-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:56.466-0700	DEBUG	[memqueue]	memqueue/ackloop.go:160	ackloop: receive ack [3: 0, 1]
2018-07-24T13:50:56.466-0700	DEBUG	[memqueue]	memqueue/eventloop.go:535	broker ACK events: count=1, start-seq=5, end-seq=5

2018-07-24T13:50:56.466-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.466-0700	DEBUG	[memqueue]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:1
2018-07-24T13:50:56.466-0700	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log, offset: 42
2018-07-24T13:50:56.466-0700	DEBUG	[memqueue]	memqueue/ackloop.go:131	ackloop:  done send ack
2018-07-24T13:50:56.466-0700	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.466-0700	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
  "@timestamp": "2018-07-24T20:50:56.466Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0-alpha1"
  },
  "beat": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "hostname": "worker-agbo6zasds2.build.macstadium.elasticnet.co",
    "version": "7.0.0-alpha1"
  },
  "message": "hello world 5",
  "source": "/private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log",
  "offset": 28,
  "prospector": {
    "type": "log"
  },
  "input": {
    "type": "log"
  },
  "host": {
    "name": "worker-agbo6zasds2.build.macstadium.elasticnet.co"
  }
}
2018-07-24T13:50:56.466-0700	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-07-24T13:50:56.467-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23
2018-07-24T13:50:56.467-0700	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-07-24T13:50:56.467-0700	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, offset: 42
2018-07-24T13:50:56.467-0700	DEBUG	[harvester]	log/log.go:102	End of file reached: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log; Backoff now.
2018-07-24T13:50:56.467-0700	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-07-24T13:50:56.467-0700	DEBUG	[input]	log/input.go:527	File rename was detected: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log -> /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, Current offset: 42
2018-07-24T13:50:56.467-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:56.467-0700	DEBUG	[input]	log/input.go:540	File rename detected but harvester not finished yet.
2018-07-24T13:50:56.467-0700	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23
2018-07-24T13:50:56.467-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2018-07-24T13:50:56.467-0700	DEBUG	[input]	log/input.go:226	State for file not removed because harvester not finished: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.467-0700	DEBUG	[input]	log/input.go:216	Remove state for file as file removed or renamed: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.468-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-07-24T13:50:56.580-0700	DEBUG	[harvester]	log/log.go:102	End of file reached: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log; Backoff now.
2018-07-24T13:50:56.580-0700	DEBUG	[harvester]	log/log.go:102	End of file reached: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log; Backoff now.
2018-07-24T13:50:56.580-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:56.580-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:56.580-0700	DEBUG	[memqueue]	memqueue/ackloop.go:160	ackloop: receive ack [4: 0, 1]
2018-07-24T13:50:56.580-0700	DEBUG	[memqueue]	memqueue/eventloop.go:535	broker ACK events: count=1, start-seq=6, end-seq=6

2018-07-24T13:50:56.581-0700	DEBUG	[memqueue]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:1
2018-07-24T13:50:56.581-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23
2018-07-24T13:50:56.581-0700	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-07-24T13:50:56.581-0700	DEBUG	[memqueue]	memqueue/ackloop.go:131	ackloop:  done send ack
2018-07-24T13:50:56.581-0700	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, offset: 42
2018-07-24T13:50:56.581-0700	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-07-24T13:50:56.581-0700	DEBUG	[input]	log/input.go:527	File rename was detected: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log -> /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, Current offset: 42
2018-07-24T13:50:56.581-0700	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-07-24T13:50:56.581-0700	DEBUG	[input]	log/input.go:540	File rename detected but harvester not finished yet.
2018-07-24T13:50:56.581-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:56.581-0700	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23
2018-07-24T13:50:56.581-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.58
2018-07-24T13:50:56.581-0700	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.58, offset: 42
2018-07-24T13:50:56.581-0700	DEBUG	[input]	log/input.go:527	File rename was detected: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log -> /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.58, Current offset: 42
2018-07-24T13:50:56.581-0700	DEBUG	[input]	log/input.go:540	File rename detected but harvester not finished yet.
2018-07-24T13:50:56.582-0700	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.58
2018-07-24T13:50:56.582-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2018-07-24T13:50:56.582-0700	DEBUG	[input]	log/input.go:226	State for file not removed because harvester not finished: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.582-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-07-24T13:50:56.582-0700	DEBUG	[input]	log/input.go:207	Remove state for file as file removed: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.582-0700	DEBUG	[input]	log/input.go:226	State for file not removed because harvester not finished: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.582-0700	DEBUG	[input]	log/input.go:207	Remove state for file as file removed: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.753-0700	INFO	log/harvester.go:268	File was removed: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log. Closing because close_removed is enabled.
2018-07-24T13:50:56.753-0700	INFO	log/harvester.go:268	File was removed: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log. Closing because close_removed is enabled.
2018-07-24T13:50:56.753-0700	DEBUG	[harvester]	log/harvester.go:507	Stopping harvester for file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.753-0700	DEBUG	[input]	input/input.go:152	Run input
2018-07-24T13:50:56.753-0700	DEBUG	[harvester]	log/harvester.go:507	Stopping harvester for file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.753-0700	DEBUG	[input]	log/input.go:174	Start next scan
2018-07-24T13:50:56.753-0700	DEBUG	[harvester]	log/harvester.go:517	Closing file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.753-0700	DEBUG	[harvester]	log/harvester.go:517	Closing file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.753-0700	DEBUG	[service]	service/service.go:51	Received sigterm/sigint, stopping
2018-07-24T13:50:56.753-0700	DEBUG	[harvester]	log/harvester.go:387	Update state: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log, offset: 42
2018-07-24T13:50:56.753-0700	DEBUG	[harvester]	log/harvester.go:387	Update state: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log, offset: 42
2018-07-24T13:50:56.754-0700	INFO	beater/filebeat.go:437	Stopping filebeat
2018-07-24T13:50:56.754-0700	INFO	crawler/crawler.go:139	Stopping Crawler
2018-07-24T13:50:56.754-0700	DEBUG	[input]	log/input.go:404	Check file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23
==================
2018-07-24T13:50:56.754-0700	INFO	crawler/crawler.go:149	Stopping 1 inputs
WARNING: DATA RACE
Write at 0x00c4203104e0 by goroutine 50:
  runtime.closechan()
      /var/lib/jenkins/.gvm/versions/go1.10.3.darwin.amd64/src/runtime/chan.go:325 +0x0
  github.com/elastic/beats/filebeat/channel.(*subOutlet).OnEvent()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/channel/util.go:75 +0x36f
  github.com/elastic/beats/filebeat/input/log.(*Input).createHarvester.func1()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/input.go:641 +0x95
  github.com/elastic/beats/filebeat/input/log.(*Harvester).SendStateUpdate()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/harvester.go:392 +0x331
  github.com/elastic/beats/filebeat/input/log.(*Harvester).cleanup()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/harvester.go:522 +0x35d
  github.com/elastic/beats/filebeat/input/log.(*Harvester).Run.func1()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/harvester.go:218 +0x62
  github.com/elastic/beats/filebeat/input/log.(*Harvester).Run()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/harvester.go:280 +0x1483
  github.com/elastic/beats/filebeat/harvester.(*Registry).Start.func1()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/harvester/registry.go:96 +0xb0

Previous read at 0x00c4203104e0 by goroutine 55:
  runtime.chansend()
      /var/lib/jenkins/.gvm/versions/go1.10.3.darwin.amd64/src/runtime/chan.go:140 +0x0
  github.com/elastic/beats/filebeat/channel.(*subOutlet).OnEvent()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/channel/util.go:78 +0x175
  github.com/elastic/beats/filebeat/input/log.(*Input).createHarvester.func1()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/input.go:641 +0x95
  github.com/elastic/beats/filebeat/input/log.(*Harvester).SendStateUpdate()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/harvester.go:392 +0x331
2018-07-24T13:50:56.754-0700	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
  github.com/elastic/beats/filebeat/input/log.(*Harvester).cleanup()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/harvester.go:522 +0x35d
  github.com/elastic/beats/filebeat/input/log.(*Harvester).Run.func1()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/harvester.go:218 +0x62
  github.com/elastic/beats/filebeat/input/log.(*Harvester).Run()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/harvester.go:280 +0x1483
  github.com/elastic/beats/filebeat/harvester.(*Registry).Start.func1()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/harvester/registry.go:96 +0xb0

Goroutine 50 (running) created at:
  github.com/elastic/beats/filebeat/harvester.(*Registry).Start()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/harvester/registry.go:90 +0x191
  github.com/elastic/beats/filebeat/input/log.(*Input).startHarvester()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/input.go:681 +0x3db
  github.com/elastic/beats/filebeat/input/log.(*Input).scan()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/input.go:478 +0x824
  github.com/elastic/beats/filebeat/input/log.(*Input).Run()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/input.go:189 +0x113
  github.com/elastic/beats/filebeat/input.(*Runner).Run()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/input.go:153 +0x14d
  github.com/elastic/beats/filebeat/input.(*Runner).Start.func1()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/input.go:132 +0x9c

Goroutine 55 (running) created at:
  github.com/elastic/beats/filebeat/harvester.(*Registry).Start()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/harvester/registry.go:90 +0x191
2018-07-24T13:50:56.754-0700	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
  github.com/elastic/beats/filebeat/input/log.(*Input).startHarvester()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/input.go:681 +0x3db
  github.com/elastic/beats/filebeat/input/log.(*Input).scan()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/input.go:478 +0x824
  github.com/elastic/beats/filebeat/input/log.(*Input).Run()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/log/input.go:189 +0x113
  github.com/elastic/beats/filebeat/input.(*Runner).Run()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/input.go:153 +0x14d
  github.com/elastic/beats/filebeat/input.(*Runner).Start.func1()
      /var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/input/input.go:132 +0x9c
==================
2018-07-24T13:50:56.754-0700	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-07-24T13:50:56.754-0700	DEBUG	[harvester]	log/harvester.go:528	harvester cleanup finished for file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.754-0700	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, offset: 42
2018-07-24T13:50:56.754-0700	DEBUG	[registrar]	registrar/registrar.go:335	Registrar states cleaned up. Before: 2, After: 2, Pending: 0
2018-07-24T13:50:56.754-0700	DEBUG	[harvester]	log/harvester.go:528	harvester cleanup finished for file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.755-0700	DEBUG	[input]	log/input.go:527	File rename was detected: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log -> /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, Current offset: 42
2018-07-24T13:50:56.755-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:56.755-0700	DEBUG	[input]	log/input.go:530	Updating state for renamed file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log -> /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23, Current offset: 42
2018-07-24T13:50:56.755-0700	DEBUG	[input]	log/input.go:548	File didn't change: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log1532465456.23
2018-07-24T13:50:56.755-0700	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-07-24T13:50:56.755-0700	INFO	log/input.go:453	Scan aborted because input stopped.
2018-07-24T13:50:56.755-0700	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2018-07-24T13:50:56.755-0700	DEBUG	[input]	log/input.go:207	Remove state for file as file removed: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/log/test.log
2018-07-24T13:50:56.755-0700	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-07-24T13:50:56.755-0700	INFO	input/input.go:149	input ticker stopped
2018-07-24T13:50:56.755-0700	INFO	input/input.go:167	Stopping Input: 89240916616959135
2018-07-24T13:50:56.755-0700	DEBUG	[publish]	pipeline/client.go:148	client: closing acker
2018-07-24T13:50:56.756-0700	DEBUG	[publish]	pipeline/client.go:150	client: done closing acker
2018-07-24T13:50:56.756-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-07-24T13:50:56.756-0700	DEBUG	[publish]	pipeline/client.go:154	client: cancelled 0 events
2018-07-24T13:50:56.756-0700	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-07-24T13:50:56.756-0700	INFO	crawler/crawler.go:165	Crawler stopped
2018-07-24T13:50:56.756-0700	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-07-24T13:50:56.756-0700	INFO	registrar/registrar.go:356	Stopping Registrar
2018-07-24T13:50:56.756-0700	DEBUG	[registrar]	registrar/registrar.go:335	Registrar states cleaned up. Before: 2, After: 2, Pending: 0
2018-07-24T13:50:56.756-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:56.757-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-07-24T13:50:56.757-0700	INFO	registrar/registrar.go:282	Ending Registrar
2018-07-24T13:50:56.757-0700	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /private/var/lib/jenkins/workspace/elastic+beats+master+multijob-darwin/beat/filebeat/label/macosx/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_input.Test.test_rotating_close_inactive_larger_write_rate/registry
2018-07-24T13:50:56.758-0700	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-07-24T13:50:56.763-0700	INFO	[monitoring]	log/log.go:149	Total non-zero metrics	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":43,"time":{"ms":43}},"total":{"ticks":165,"time":{"ms":165},"value":165},"user":{"ticks":122,"time":{"ms":122}}},"info":{"ephemeral_id":"15c99c65-149c-46ea-9a81-e63fa366fc4c","uptime":{"ms":1876}},"memstats":{"gc_next":4194304,"memory_alloc":1874552,"memory_total":4957376,"rss":48570368}},"filebeat":{"events":{"active":1,"added":11,"done":10},"harvester":{"closed":2,"open_files":0,"running":0,"started":2},"input":{"log":{"files":{"renamed":1}}}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":6,"batches":5,"total":6},"type":"file","write":{"bytes":4030}},"pipeline":{"clients":0,"events":{"active":0,"filtered":5,"published":6,"total":11},"queue":{"acked":6}}},"registrar":{"states":{"current":2,"update":10},"writes":{"success":11,"total":11}},"system":{"cpu":{"cores":4},"load":{"1":2.709,"15":2.6157,"5":2.6875,"norm":{"1":0.6772,"15":0.6539,"5":0.6719}}}}}}
2018-07-24T13:50:56.764-0700	INFO	[monitoring]	log/log.go:150	Uptime: 1.881660616s
2018-07-24T13:50:56.764-0700	INFO	[monitoring]	log/log.go:127	Stopping metrics logging.
2018-07-24T13:50:56.764-0700	INFO	instance/beat.go:373	filebeat stopped.
--- FAIL: TestSystem (1.85s)
	testing.go:730: race detected during execution of test
FAIL
coverage: 23.0% of statements in github.com/elastic/beats/filebeat, github.com/elastic/beats/filebeat/autodiscover, github.com/elastic/beats/filebeat/autodiscover/builder/hints, github.com/elastic/beats/filebeat/beater, github.com/elastic/beats/filebeat/channel, github.com/elastic/beats/filebeat/cmd, github.com/elastic/beats/filebeat/config, github.com/elastic/beats/filebeat/crawler, github.com/elastic/beats/filebeat/fileset, github.com/elastic/beats/filebeat/harvester, github.com/elastic/beats/filebeat/include, github.com/elastic/beats/filebeat/input, github.com/elastic/beats/filebeat/input/docker, github.com/elastic/beats/filebeat/input/file, github.com/elastic/beats/filebeat/input/log, github.com/elastic/beats/filebeat/input/redis, github.com/elastic/beats/filebeat/input/stdin, github.com/elastic/beats/filebeat/input/syslog, github.com/elastic/beats/filebeat/input/tcp, github.com/elastic/beats/filebeat/input/udp, github.com/elastic/beats/filebeat/inputsource, github.com/elastic/beats/filebeat/inputsource/tcp, github.com/elastic/beats/filebeat/inputsource/udp, github.com/elastic/beats/filebeat/processor/add_kubernetes_metadata, github.com/elastic/beats/filebeat/prospector, github.com/elastic/beats/filebeat/reader, github.com/elastic/beats/filebeat/reader/docker_json, github.com/elastic/beats/filebeat/reader/encode, github.com/elastic/beats/filebeat/reader/encode/encoding, github.com/elastic/beats/filebeat/reader/json, github.com/elastic/beats/filebeat/reader/limit, github.com/elastic/beats/filebeat/reader/line, github.com/elastic/beats/filebeat/reader/multiline, github.com/elastic/beats/filebeat/reader/strip_newline, github.com/elastic/beats/filebeat/reader/timeout, github.com/elastic/beats/filebeat/registrar, github.com/elastic/beats/filebeat/scripts/generator, github.com/elastic/beats/filebeat/scripts/generator/fields, github.com/elastic/beats/filebeat/scripts/generator/fileset, github.com/elastic/beats/filebeat/scripts/generator/module, github.com/elastic/beats/filebeat/scripts/tester, github.com/elastic/beats/filebeat/util
@ruflin ruflin added bug Filebeat Filebeat flaky-test Unstable or unreliable test cases. labels Jul 25, 2018
@andrewkroh andrewkroh changed the title Flaky test_rotating_close_inactive_larger_write_rate test in Filebeat [Filebeat] Flaky test_rotating_close_inactive_larger_write_rate test in Filebeat Aug 17, 2018
@andrewvc andrewvc self-assigned this Sep 13, 2018
@andrewvc
Copy link
Contributor

@ruflin tracing this, I believe this was fixed in #7820 . The line numbers match up to before that commit in channel/util.go, and the addition of the mutex around those channel operations should fix this.

Are you good to close given that?

@andrewvc
Copy link
Contributor

@adriansr maybe you could just confirm or deny that this can be closed since @ruflin is out for a bit? I'm pretty sure we're good here, but would like another eye on it.

@adriansr
Copy link
Contributor

@andrewvc yes, it can be closed as the race was fixed by #7820

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@andrewvc andrewvc

Labels
bug Filebeat Filebeat flaky-test Unstable or unreliable test cases.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@andrewvc @ruflin @adriansr