[Filebeat] Test test_registrar.test_clean_removed fails #7690

kvch · 2018-07-24T09:57:43Z

Job: https://beats-ci.elastic.co/job/elastic+beats+master+multijob-linux/1249/beat=filebeat,label=linux/
Platform: linux

Message:

Traceback (most recent call last):
  File "/usr/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/go/src/github.com/elastic/beats/filebeat/tests/system/test_registrar.py", line 902, in test_clean_removed
    assert len(data) == 1
AssertionError

Logs (I have more if needed)

2018-07-21T00:51:58.364Z    DEBUG   [input] input/input.go:152  Run input
2018-07-21T00:51:58.364Z    DEBUG   [input] log/input.go:174    Start next scan
2018-07-21T00:51:58.364Z    DEBUG   [input] log/input.go:404    Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input1
2018-07-21T00:51:58.364Z    DEBUG   [input] log/input.go:555    Ignore file because ignore_older reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input1
2018-07-21T00:51:58.364Z    DEBUG   [input] log/input.go:567    Do not write state for ignore_older because clean_inactive reached
2018-07-21T00:51:58.364Z    DEBUG   [input] log/input.go:404    Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input2
2018-07-21T00:51:58.364Z    DEBUG   [input] log/input.go:555    Ignore file because ignore_older reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input2
2018-07-21T00:51:58.364Z    DEBUG   [input] log/input.go:567    Do not write state for ignore_older because clean_inactive reached
2018-07-21T00:51:58.364Z    DEBUG   [input] log/input.go:404    Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.364Z    DEBUG   [input] log/input.go:477    Start harvester for new file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.364Z    DEBUG   [harvester] log/harvester.go:486    Setting offset for file based on seek: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.364Z    DEBUG   [harvester] log/harvester.go:472    Setting offset for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3. Offset: 0
2018-07-21T00:51:58.364Z    DEBUG   [harvester] log/harvester.go:387    Update state: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3, offset: 0
2018-07-21T00:51:58.364Z    DEBUG   [input] file/states.go:68   New state added for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.364Z    DEBUG   [input] log/input.go:195    input states cleaned up. Before: 1, After: 1, Pending: 1
2018-07-21T00:51:58.364Z    DEBUG   [acker] beater/acker.go:64  stateful ack    {"count": 1}
2018-07-21T00:51:58.364Z    DEBUG   [registrar] registrar/registrar.go:345  Processing 1 events
2018-07-21T00:51:58.364Z    DEBUG   [input] file/states.go:68   New state added for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.364Z    DEBUG   [registrar] registrar/registrar.go:315  Registrar state updates processed. Count: 1
2018-07-21T00:51:58.364Z    DEBUG   [state] file/states.go:118  State removed for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input1 because of older: 4s
2018-07-21T00:51:58.364Z    DEBUG   [state] file/states.go:118  State removed for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input2 because of older: 4s
2018-07-21T00:51:58.364Z    DEBUG   [registrar] registrar/registrar.go:335  Registrar states cleaned up. Before: 3, After: 1, Pending: 1
2018-07-21T00:51:58.364Z    DEBUG   [registrar] registrar/registrar.go:400  Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/registry
2018-07-21T00:51:58.364Z    INFO    log/harvester.go:251    Harvester started for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.364Z    DEBUG   [publish]   pipeline/processor.go:308   Publish event: {
  "@timestamp": "2018-07-21T00:51:58.364Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0-alpha1"
  },
  "message": "2",
  "source": "/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3",
  "offset": 0,
  "prospector": {
    "type": "log"
  },
  "input": {
    "type": "log"
  },
  "beat": {
    "name": "79ecf000efcd",
    "hostname": "79ecf000efcd",
    "version": "7.0.0-alpha1"
  },
  "host": {
    "name": "79ecf000efcd"
  }
}
2018-07-21T00:51:58.364Z    DEBUG   [harvester] log/log.go:102  End of file reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3; Backoff now.
2018-07-21T00:51:58.367Z    DEBUG   [registrar] registrar/registrar.go:393  Registry file updated. 1 states written.
2018-07-21T00:51:58.464Z    DEBUG   [input] input/input.go:152  Run input
2018-07-21T00:51:58.464Z    DEBUG   [input] log/input.go:174    Start next scan
2018-07-21T00:51:58.464Z    DEBUG   [input] log/input.go:404    Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input1
2018-07-21T00:51:58.464Z    DEBUG   [input] log/input.go:555    Ignore file because ignore_older reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input1
2018-07-21T00:51:58.464Z    DEBUG   [input] log/input.go:567    Do not write state for ignore_older because clean_inactive reached
2018-07-21T00:51:58.464Z    DEBUG   [input] log/input.go:404    Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input2
2018-07-21T00:51:58.464Z    DEBUG   [input] log/input.go:555    Ignore file because ignore_older reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input2
2018-07-21T00:51:58.465Z    DEBUG   [input] log/input.go:567    Do not write state for ignore_older because clean_inactive reached
2018-07-21T00:51:58.465Z    DEBUG   [input] log/input.go:404    Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.465Z    DEBUG   [input] log/input.go:494    Update existing file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3, offset: 2
2018-07-21T00:51:58.465Z    DEBUG   [input] log/input.go:546    Harvester for file is still running: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.465Z    DEBUG   [input] log/input.go:195    input states cleaned up. Before: 1, After: 1, Pending: 1
2018-07-21T00:51:58.465Z    DEBUG   [harvester] log/log.go:102  End of file reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3; Backoff now.
2018-07-21T00:51:58.465Z    DEBUG   [memqueue]  memqueue/ackloop.go:160 ackloop: receive ack [1: 0, 1]
2018-07-21T00:51:58.465Z    DEBUG   [memqueue]  memqueue/eventloop.go:535   broker ACK events: count=1, start-seq=3, end-seq=3

2018-07-21T00:51:58.465Z    DEBUG   [memqueue]  memqueue/ackloop.go:128 ackloop: return ack to broker loop:1
2018-07-21T00:51:58.465Z    DEBUG   [memqueue]  memqueue/ackloop.go:131 ackloop:  done send ack
2018-07-21T00:51:58.465Z    DEBUG   [acker] beater/acker.go:64  stateful ack    {"count": 1}
2018-07-21T00:51:58.465Z    DEBUG   [registrar] registrar/registrar.go:345  Processing 1 events
2018-07-21T00:51:58.465Z    DEBUG   [registrar] registrar/registrar.go:315  Registrar state updates processed. Count: 1
2018-07-21T00:51:58.465Z    DEBUG   [registrar] registrar/registrar.go:335  Registrar states cleaned up. Before: 1, After: 1, Pending: 1
2018-07-21T00:51:58.465Z    DEBUG   [registrar] registrar/registrar.go:400  Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/registry
2018-07-21T00:51:58.468Z    DEBUG   [registrar] registrar/registrar.go:393  Registry file updated. 1 states written.
2018-07-21T00:51:58.546Z    DEBUG   [service]   service/service.go:51   Received sigterm/sigint, stopping
2018-07-21T00:51:58.546Z    INFO    beater/filebeat.go:437  Stopping filebeat
2018-07-21T00:51:58.546Z    INFO    crawler/crawler.go:139  Stopping Crawler
2018-07-21T00:51:58.546Z    INFO    crawler/crawler.go:149  Stopping 1 inputs
2018-07-21T00:51:58.546Z    INFO    input/input.go:149  input ticker stopped
2018-07-21T00:51:58.546Z    INFO    input/input.go:167  Stopping Input: 3186646878776396347
2018-07-21T00:51:58.546Z    INFO    log/harvester.go:272    Reader was closed: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3. Closing.
2018-07-21T00:51:58.546Z    DEBUG   [harvester] log/harvester.go:507    Stopping harvester for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.546Z    DEBUG   [harvester] log/harvester.go:517    Closing file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.546Z    DEBUG   [harvester] log/harvester.go:387    Update state: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3, offset: 2
2018-07-21T00:51:58.546Z    DEBUG   [harvester] log/harvester.go:528    harvester cleanup finished for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/log/input3
2018-07-21T00:51:58.546Z    DEBUG   [publish]   pipeline/client.go:148  client: closing acker
2018-07-21T00:51:58.546Z    DEBUG   [publish]   pipeline/client.go:150  client: done closing acker
2018-07-21T00:51:58.546Z    DEBUG   [publish]   pipeline/client.go:154  client: cancelled 0 events
2018-07-21T00:51:58.546Z    INFO    crawler/crawler.go:165  Crawler stopped
2018-07-21T00:51:58.546Z    INFO    registrar/registrar.go:356  Stopping Registrar
2018-07-21T00:51:58.546Z    INFO    registrar/registrar.go:282  Ending Registrar
2018-07-21T00:51:58.546Z    DEBUG   [registrar] registrar/registrar.go:400  Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_inactive/registry
2018-07-21T00:51:58.549Z    DEBUG   [registrar] registrar/registrar.go:393  Registry file updated. 1 states written.
2018-07-21T00:51:58.551Z    INFO    [monitoring]    log/log.go:149  Total non-zero metrics  {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":20,"time":{"ms":28}},"total":{"ticks":40,"time":{"ms":52},"value":40},"user":{"ticks":20,"time":{"ms":24}}},"info":{"ephemeral_id":"b952d3e2-00ca-44a0-ade8-c7c76d
b421de","uptime":{"ms":4520}},"memstats":{"gc_next":4194304,"memory_alloc":1527304,"memory_total":4595688,"rss":23306240}},"filebeat":{"events":{"added":8,"done":8},"harvester":{"closed":3,"open_files":0,"running":0,"started":3}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":3,"batches":
2,"total":3},"type":"file","write":{"bytes":1303}},"pipeline":{"clients":0,"events":{"active":0,"filtered":5,"published":3,"total":8},"queue":{"acked":3}}},"registrar":{"states":{"cleanup":2,"current":1,"update":8},"writes":{"success":8,"total":8}},"system":{"cpu":{"cores":4},"load":{"1":1.35,"15":3.35,"5":4.5,"no
rm":{"1":0.3375,"15":0.8375,"5":1.125}}}}}}
2018-07-21T00:51:58.551Z    INFO    [monitoring]    log/log.go:150  Uptime: 4.5217286s
2018-07-21T00:51:58.551Z    INFO    [monitoring]    log/log.go:127  Stopping metrics logging.
2018-07-21T00:51:58.551Z    INFO    instance/beat.go:373    filebeat stopped.

The text was updated successfully, but these errors were encountered:

ruflin · 2018-08-27T06:37:30Z

It seems in this test the clean_removed is not triggered as before. Before states were always cleaned up when a new state was added. Before shut down a last event is sent to trigger the removal of the clean_removed states. I assume with the gc introduction in the registry potentially this cleanup does not happen anymore on each write.

What I would expect in the above log is that after the event is sent that some states are cleaned up. The test needs to be modified to wait for the gc to happen I assume.

This is a potential fix for the flaky clean_removed test. The problem in the test seems to be that sometimes not all states are cleaned up yet. This is changing it by waiting for all pending cleanups to happen. Closes elastic#7690

This is a potential fix for the flaky clean_removed test. The problem in the test seems to be that sometimes not all states are cleaned up yet. This is changing it by waiting for all pending cleanups to happen. Closes #7690

This is a potential fix for the flaky clean_removed test. The problem in the test seems to be that sometimes not all states are cleaned up yet. This is changing it by waiting for all pending cleanups to happen. Closes elastic#7690 (cherry picked from commit e346293)

This is a potential fix for the flaky clean_removed test. The problem in the test seems to be that sometimes not all states are cleaned up yet. This is changing it by waiting for all pending cleanups to happen. Closes #7690 (cherry picked from commit e346293)

ruflin · 2018-11-22T15:37:14Z

Reopening this issue as it seems test still keeps failing and it seems to be on linux and mac.

Jenkins link: https://beats-ci.elastic.co/job/elastic+beats+pull-request+multijob-linux/1796/beat=filebeat,label=ubuntu/artifact/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/

Error message:

 Traceback (most recent call last):
  File "/usr/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/go/src/github.com/elastic/beats/filebeat/tests/system/test_registrar.py", line 904, in test_clean_removed
    assert len(data) == 1
AssertionError

Log file:

2018-11-21T20:20:30.873Z	INFO	instance/beat.go:587	Home path: [/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed] Config path: [/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed] Data path: [/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/data] Logs path: [/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/logs]
2018-11-21T20:20:30.873Z	DEBUG	[beat]	instance/beat.go:624	Beat metadata path: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/data/meta.json
2018-11-21T20:20:30.875Z	INFO	instance/beat.go:594	Beat UUID: 0de8495c-aa9b-4138-bcbd-5eb682963cce
2018-11-21T20:20:30.875Z	DEBUG	[seccomp]	seccomp/seccomp.go:109	Loading syscall filter	{"seccomp_filter": {"no_new_privs":true,"flag":"tsync","policy":{"default_action":"errno","syscalls":[{"names":["accept","accept4","access","arch_prctl","bind","brk","clock_gettime","clone","close","connect","dup","dup2","epoll_create","epoll_create1","epoll_ctl","epoll_pwait","epoll_wait","exit","exit_group","fchdir","fchmod","fchown","fcntl","fdatasync","flock","fstat","fsync","ftruncate","futex","getcwd","getdents","getdents64","geteuid","getgid","getpeername","getpid","getppid","getrandom","getrusage","getsockname","getsockopt","gettid","gettimeofday","getuid","inotify_add_watch","inotify_init1","inotify_rm_watch","ioctl","kill","listen","lseek","lstat","madvise","mincore","mkdirat","mmap","mprotect","munmap","nanosleep","newfstatat","open","openat","pipe","pipe2","poll","pread64","pselect6","pwrite64","read","readlink","readlinkat","recvfrom","recvmmsg","recvmsg","rename","renameat","rt_sigaction","rt_sigprocmask","rt_sigreturn","sched_getaffinity","sched_yield","sendfile","sendmmsg","sendmsg","sendto","set_robust_list","setitimer","setsockopt","shutdown","sigaltstack","socket","stat","statfs","sysinfo","tgkill","time","tkill","uname","unlink","unlinkat","wait4","waitid","write","writev"],"action":"allow"}]}}}
2018-11-21T20:20:30.876Z	INFO	[seccomp]	seccomp/seccomp.go:116	Syscall filter successfully installed
2018-11-21T20:20:30.876Z	INFO	[beat]	instance/beat.go:820	Beat info	{"system_info": {"beat": {"path": {"config": "/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed", "data": "/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/data", "home": "/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed", "logs": "/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/logs"}, "type": "filebeat", "uuid": "0de8495c-aa9b-4138-bcbd-5eb682963cce"}}}
2018-11-21T20:20:30.876Z	INFO	[beat]	instance/beat.go:829	Build info	{"system_info": {"build": {"commit": "unknown", "libbeat": "7.0.0", "time": "1754-08-30T22:43:41.128Z", "version": "7.0.0"}}}
2018-11-21T20:20:30.876Z	INFO	[beat]	instance/beat.go:832	Go runtime info	{"system_info": {"go": {"os":"linux","arch":"amd64","max_procs":4,"version":"go1.10.3"}}}
2018-11-21T20:20:30.877Z	INFO	[beat]	instance/beat.go:836	Host info	{"system_info": {"host": {"architecture":"x86_64","boot_time":"2018-11-21T20:08:38Z","containerized":true,"name":"b978bd034e42","ip":["127.0.0.1/8","172.18.0.5/16"],"kernel_version":"4.15.0-1024-gcp","mac":["02:42:ac:12:00:05"],"os":{"family":"debian","platform":"debian","name":"Debian GNU/Linux","version":"9 (stretch)","major":9,"minor":0,"patch":0,"codename":"stretch"},"timezone":"UTC","timezone_offset_sec":0,"id":"3e608929fbd39b959f388bf468c9f0b1"}}}
2018-11-21T20:20:30.877Z	INFO	[beat]	instance/beat.go:865	Process info	{"system_info": {"process": {"capabilities": {"inheritable":["chown","dac_override","fowner","fsetid","kill","setgid","setuid","setpcap","net_bind_service","net_raw","sys_chroot","mknod","audit_write","setfcap"],"permitted":["chown","dac_override","fowner","fsetid","kill","setgid","setuid","setpcap","net_bind_service","net_raw","sys_chroot","mknod","audit_write","setfcap"],"effective":["chown","dac_override","fowner","fsetid","kill","setgid","setuid","setpcap","net_bind_service","net_raw","sys_chroot","mknod","audit_write","setfcap"],"bounding":["chown","dac_override","fowner","fsetid","kill","setgid","setuid","setpcap","net_bind_service","net_raw","sys_chroot","mknod","audit_write","setfcap"],"ambient":null}, "cwd": "/go/src/github.com/elastic/beats/filebeat", "exe": "/go/src/github.com/elastic/beats/filebeat/filebeat.test", "name": "filebeat.test", "pid": 3531, "ppid": 2877, "seccomp": {"mode":"filter","no_new_privs":true}, "start_time": "2018-11-21T20:20:30.300Z"}}}
2018-11-21T20:20:30.877Z	INFO	instance/beat.go:278	Setup Beat: filebeat; Version: 7.0.0
2018-11-21T20:20:30.877Z	DEBUG	[beat]	instance/beat.go:299	Initializing output plugins
2018-11-21T20:20:30.877Z	DEBUG	[processors]	processors/processor.go:66	Processors: 
2018-11-21T20:20:30.877Z	DEBUG	[rotator]	file/rotator.go:165	Initialized file rotator	{"rotator": {"filename": "/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/output/filebeat", "max_size_bytes": 1024000, "max_backups": 7, "permissions": "-rw-------", "interval": 0}}
2018-11-21T20:20:30.878Z	INFO	fileout/file.go:97	Initialized file output. path=/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/output/filebeat max_size_bytes=1024000 max_backups=7 permissions=-rw-------
2018-11-21T20:20:30.878Z	DEBUG	[publish]	pipeline/consumer.go:137	start pipeline event consumer
2018-11-21T20:20:30.878Z	INFO	[publisher]	pipeline/module.go:114	Beat name: b978bd034e42
2018-11-21T20:20:30.878Z	ERROR	fileset/modules.go:118	Not loading modules. Module directory not found: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/module
2018-11-21T20:20:30.878Z	INFO	[monitoring]	log/log.go:117	Starting metrics logging every 30s
2018-11-21T20:20:30.878Z	INFO	instance/beat.go:400	filebeat start running.
2018-11-21T20:20:30.878Z	INFO	registrar/registrar.go:97	No registry file found under: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/registry. Creating a new registry file.
2018-11-21T20:20:30.878Z	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/registry
2018-11-21T20:20:30.882Z	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 0 states written.
2018-11-21T20:20:30.882Z	INFO	registrar/registrar.go:134	Loading registrar data from /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/registry
2018-11-21T20:20:30.882Z	INFO	registrar/registrar.go:141	States Loaded from registrar: 0
2018-11-21T20:20:30.882Z	WARN	beater/filebeat.go:361	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-11-21T20:20:30.882Z	INFO	crawler/crawler.go:72	Loading Inputs: 1
2018-11-21T20:20:30.882Z	DEBUG	[registrar]	registrar/registrar.go:267	Starting Registrar
2018-11-21T20:20:30.882Z	DEBUG	[processors]	processors/processor.go:66	Processors: 
2018-11-21T20:20:30.883Z	DEBUG	[input]	log/config.go:201	recursive glob enabled
2018-11-21T20:20:30.883Z	DEBUG	[input]	log/input.go:147	exclude_files: []. Number of stats: 0
2018-11-21T20:20:30.883Z	DEBUG	[input]	log/input.go:168	input with previous states loaded: 0
2018-11-21T20:20:30.883Z	INFO	log/input.go:138	Configured paths: [/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input*]
2018-11-21T20:20:30.883Z	INFO	input/input.go:114	Starting input of type: log; ID: 11305044345846620571 
2018-11-21T20:20:30.883Z	INFO	crawler/crawler.go:106	Loading and starting Inputs completed. Enabled inputs: 1
2018-11-21T20:20:30.883Z	DEBUG	[input]	log/input.go:174	Start next scan
2018-11-21T20:20:30.883Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:30.883Z	DEBUG	[input]	log/input.go:477	Start harvester for new file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:30.883Z	DEBUG	[harvester]	log/harvester.go:492	Setting offset for file based on seek: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:30.883Z	DEBUG	[harvester]	log/harvester.go:478	Setting offset for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1. Offset: 0 
2018-11-21T20:20:30.883Z	DEBUG	[harvester]	log/harvester.go:393	Update state: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1, offset: 0
2018-11-21T20:20:30.883Z	DEBUG	[input]	file/states.go:68	New state added for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:30.884Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:30.884Z	DEBUG	[input]	log/input.go:477	Start harvester for new file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:30.884Z	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-11-21T20:20:30.884Z	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-11-21T20:20:30.884Z	DEBUG	[input]	file/states.go:68	New state added for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:30.884Z	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-11-21T20:20:30.884Z	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/registry
2018-11-21T20:20:30.884Z	DEBUG	[harvester]	log/harvester.go:492	Setting offset for file based on seek: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:30.884Z	DEBUG	[harvester]	log/harvester.go:478	Setting offset for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2. Offset: 0 
2018-11-21T20:20:30.884Z	DEBUG	[harvester]	log/harvester.go:393	Update state: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2, offset: 0
2018-11-21T20:20:30.884Z	DEBUG	[input]	file/states.go:68	New state added for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:30.884Z	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2018-11-21T20:20:30.884Z	INFO	log/harvester.go:253	Harvester started for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:30.884Z	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-11-21T20:20:30.884Z	INFO	log/harvester.go:253	Harvester started for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:30.884Z	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
  "@timestamp": "2018-11-21T20:20:30.884Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0"
  },
  "agent": {
    "type": "filebeat",
    "hostname": "b978bd034e42",
    "version": "7.0.0"
  },
  "host": {
    "name": "b978bd034e42"
  },
  "log": {
    "offset": 0,
    "file": {
      "path": "/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1"
    }
  },
  "message": "file to be removed",
  "input": {
    "type": "log"
  }
}
2018-11-21T20:20:30.884Z	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
  "@timestamp": "2018-11-21T20:20:30.884Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0"
  },
  "host": {
    "name": "b978bd034e42"
  },
  "agent": {
    "type": "filebeat",
    "hostname": "b978bd034e42",
    "version": "7.0.0"
  },
  "message": "2",
  "log": {
    "offset": 0,
    "file": {
      "path": "/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2"
    }
  },
  "input": {
    "type": "log"
  }
}
2018-11-21T20:20:30.884Z	DEBUG	[harvester]	log/log.go:102	End of file reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1; Backoff now.
2018-11-21T20:20:30.884Z	DEBUG	[harvester]	log/log.go:102	End of file reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2; Backoff now.
2018-11-21T20:20:30.887Z	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 1 states written.
2018-11-21T20:20:30.887Z	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-11-21T20:20:30.887Z	DEBUG	[input]	file/states.go:68	New state added for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:30.887Z	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-11-21T20:20:30.887Z	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/registry
2018-11-21T20:20:30.891Z	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-11-21T20:20:30.984Z	DEBUG	[input]	input/input.go:152	Run input
2018-11-21T20:20:30.984Z	DEBUG	[input]	log/input.go:174	Start next scan
2018-11-21T20:20:30.984Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:30.984Z	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1, offset: 19
2018-11-21T20:20:30.985Z	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:30.985Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:30.985Z	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2, offset: 2
2018-11-21T20:20:30.985Z	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:30.985Z	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2018-11-21T20:20:30.985Z	DEBUG	[harvester]	log/log.go:102	End of file reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1; Backoff now.
2018-11-21T20:20:30.985Z	DEBUG	[publisher]	memqueue/ackloop.go:160	ackloop: receive ack [0: 0, 2]
2018-11-21T20:20:30.985Z	DEBUG	[publisher]	memqueue/eventloop.go:535	broker ACK events: count=2, start-seq=1, end-seq=2

2018-11-21T20:20:30.985Z	DEBUG	[publisher]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:2
2018-11-21T20:20:30.985Z	DEBUG	[publisher]	memqueue/ackloop.go:131	ackloop:  done send ack
2018-11-21T20:20:30.985Z	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 2}
2018-11-21T20:20:30.985Z	DEBUG	[registrar]	registrar/registrar.go:345	Processing 2 events
2018-11-21T20:20:30.985Z	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 2
2018-11-21T20:20:30.985Z	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/registry
2018-11-21T20:20:30.985Z	DEBUG	[harvester]	log/log.go:102	End of file reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2; Backoff now.
2018-11-21T20:20:30.989Z	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-11-21T20:20:31.085Z	DEBUG	[input]	input/input.go:152	Run input
2018-11-21T20:20:31.085Z	DEBUG	[input]	log/input.go:174	Start next scan
2018-11-21T20:20:31.085Z	INFO	log/harvester.go:270	File was removed: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1. Closing because close_removed is enabled.
2018-11-21T20:20:31.085Z	DEBUG	[harvester]	log/harvester.go:513	Stopping harvester for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:31.085Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:31.085Z	DEBUG	[harvester]	log/harvester.go:523	Closing file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:31.085Z	DEBUG	[harvester]	log/harvester.go:393	Update state: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1, offset: 19
2018-11-21T20:20:31.085Z	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2, offset: 2
2018-11-21T20:20:31.085Z	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:31.085Z	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2018-11-21T20:20:31.085Z	DEBUG	[input]	log/input.go:207	Remove state for file as file removed: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:31.085Z	DEBUG	[harvester]	log/harvester.go:534	harvester cleanup finished for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:31.085Z	DEBUG	[harvester]	log/log.go:102	End of file reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2; Backoff now.
2018-11-21T20:20:31.085Z	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-11-21T20:20:31.085Z	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-11-21T20:20:31.085Z	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-11-21T20:20:31.085Z	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-11-21T20:20:31.086Z	DEBUG	[state]	file/states.go:118	State removed for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1 because of older: 0s
2018-11-21T20:20:31.086Z	DEBUG	[registrar]	registrar/registrar.go:335	Registrar states cleaned up. Before: 2, After: 1, Pending: 0
2018-11-21T20:20:31.086Z	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/registry
2018-11-21T20:20:31.090Z	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 1 states written.
2018-11-21T20:20:31.090Z	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-11-21T20:20:31.090Z	DEBUG	[input]	file/states.go:68	New state added for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1
2018-11-21T20:20:31.090Z	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-11-21T20:20:31.090Z	DEBUG	[registrar]	registrar/registrar.go:335	Registrar states cleaned up. Before: 2, After: 2, Pending: 0
2018-11-21T20:20:31.090Z	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/registry
2018-11-21T20:20:31.093Z	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-11-21T20:20:31.185Z	DEBUG	[input]	input/input.go:152	Run input
2018-11-21T20:20:31.186Z	DEBUG	[input]	log/input.go:174	Start next scan
2018-11-21T20:20:31.186Z	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
  "@timestamp": "2018-11-21T20:20:31.186Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "7.0.0"
  },
  "log": {
    "offset": 2,
    "file": {
      "path": "/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2"
    }
  },
  "message": "make sure registry is written",
  "input": {
    "type": "log"
  },
  "agent": {
    "type": "filebeat",
    "hostname": "b978bd034e42",
    "version": "7.0.0"
  },
  "host": {
    "name": "b978bd034e42"
  }
}
2018-11-21T20:20:31.186Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:31.186Z	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2, offset: 32
2018-11-21T20:20:31.186Z	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:31.186Z	DEBUG	[harvester]	log/log.go:102	End of file reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2; Backoff now.
2018-11-21T20:20:31.186Z	DEBUG	[state]	file/states.go:118	State removed for /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1 because of older: 0s
2018-11-21T20:20:31.186Z	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 1, Pending: 0
2018-11-21T20:20:31.286Z	DEBUG	[input]	input/input.go:152	Run input
2018-11-21T20:20:31.286Z	DEBUG	[input]	log/input.go:174	Start next scan
2018-11-21T20:20:31.286Z	DEBUG	[publisher]	memqueue/ackloop.go:160	ackloop: receive ack [1: 0, 1]
2018-11-21T20:20:31.286Z	DEBUG	[publisher]	memqueue/eventloop.go:535	broker ACK events: count=1, start-seq=3, end-seq=3

2018-11-21T20:20:31.286Z	DEBUG	[publisher]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:1
2018-11-21T20:20:31.286Z	DEBUG	[publisher]	memqueue/ackloop.go:131	ackloop:  done send ack
2018-11-21T20:20:31.286Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:31.286Z	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2018-11-21T20:20:31.286Z	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2, offset: 32
2018-11-21T20:20:31.286Z	DEBUG	[input]	log/input.go:546	Harvester for file is still running: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:31.286Z	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 1, After: 1, Pending: 0
2018-11-21T20:20:31.286Z	DEBUG	[registrar]	registrar/registrar.go:345	Processing 1 events
2018-11-21T20:20:31.286Z	DEBUG	[registrar]	registrar/registrar.go:315	Registrar state updates processed. Count: 1
2018-11-21T20:20:31.286Z	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/registry
2018-11-21T20:20:31.286Z	DEBUG	[harvester]	log/log.go:102	End of file reached: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2; Backoff now.
2018-11-21T20:20:31.290Z	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-11-21T20:20:31.358Z	DEBUG	[service]	service/service.go:50	Received sigterm/sigint, stopping
2018-11-21T20:20:31.358Z	INFO	beater/filebeat.go:436	Stopping filebeat
2018-11-21T20:20:31.358Z	INFO	crawler/crawler.go:139	Stopping Crawler
2018-11-21T20:20:31.358Z	INFO	crawler/crawler.go:149	Stopping 1 inputs
2018-11-21T20:20:31.358Z	INFO	input/input.go:149	input ticker stopped
2018-11-21T20:20:31.358Z	INFO	input/input.go:167	Stopping Input: 11305044345846620571
2018-11-21T20:20:31.358Z	INFO	log/harvester.go:274	Reader was closed: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2. Closing.
2018-11-21T20:20:31.359Z	DEBUG	[harvester]	log/harvester.go:513	Stopping harvester for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:31.359Z	DEBUG	[harvester]	log/harvester.go:523	Closing file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:31.359Z	DEBUG	[harvester]	log/harvester.go:393	Update state: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2, offset: 32
2018-11-21T20:20:31.359Z	DEBUG	[harvester]	log/harvester.go:534	harvester cleanup finished for file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2
2018-11-21T20:20:31.359Z	DEBUG	[publish]	pipeline/client.go:148	client: closing acker
2018-11-21T20:20:31.359Z	DEBUG	[publish]	pipeline/client.go:150	client: done closing acker
2018-11-21T20:20:31.359Z	DEBUG	[publish]	pipeline/client.go:154	client: cancelled 0 events
2018-11-21T20:20:31.359Z	INFO	crawler/crawler.go:165	Crawler stopped
2018-11-21T20:20:31.359Z	INFO	registrar/registrar.go:356	Stopping Registrar
2018-11-21T20:20:31.359Z	INFO	registrar/registrar.go:282	Ending Registrar
2018-11-21T20:20:31.359Z	DEBUG	[registrar]	registrar/registrar.go:400	Write registry file: /go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/registry
2018-11-21T20:20:31.363Z	DEBUG	[registrar]	registrar/registrar.go:393	Registry file updated. 2 states written.
2018-11-21T20:20:31.368Z	INFO	[monitoring]	log/log.go:152	Total non-zero metrics	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":10,"time":{"ms":12}},"total":{"ticks":40,"time":{"ms":52},"value":40},"user":{"ticks":30,"time":{"ms":40}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":70},"info":{"ephemeral_id":"9cf6d0ec-366e-4271-9578-b5022c555d0a","uptime":{"ms":501}},"memstats":{"gc_next":4194304,"memory_alloc":2525936,"memory_total":4106312,"rss":24244224}},"filebeat":{"events":{"added":7,"done":7},"harvester":{"closed":2,"open_files":0,"running":0,"started":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":3,"batches":2,"total":3},"type":"file","write":{"bytes":1236}},"pipeline":{"clients":0,"events":{"active":0,"filtered":4,"published":3,"total":7},"queue":{"acked":3}}},"registrar":{"states":{"cleanup":1,"current":2,"update":7},"writes":{"success":8,"total":8}},"system":{"cpu":{"cores":4},"load":{"1":1.87,"15":2.71,"5":3.79,"norm":{"1":0.4675,"15":0.6775,"5":0.9475}}}}}}
2018-11-21T20:20:31.369Z	INFO	[monitoring]	log/log.go:153	Uptime: 506.771448ms
2018-11-21T20:20:31.369Z	INFO	[monitoring]	log/log.go:130	Stopping metrics logging.
2018-11-21T20:20:31.369Z	INFO	instance/beat.go:410	filebeat stopped.
PASS
coverage: 23.2% 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/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

Registry:

[{"source":"/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input2","offset":32,"timestamp":"2018-11-21T20:20:31.286812831Z","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":1033811,"device":2049}},{"source":"/go/src/github.com/elastic/beats/filebeat/build/system-tests/run/test_registrar.Test.test_clean_removed/log/input1","offset":19,"timestamp":"2018-11-21T20:20:31.090231254Z","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":1033810,"device":2049}}]

See elastic#7690

See #7690

See elastic#7690 (cherry picked from commit be187b9)

See #7690 (cherry picked from commit be187b9)

kvch · 2019-03-13T10:26:42Z

The test failed again on Windows:
Job: https://beats-ci.elastic.co/job/elastic+beats+pull-request+multijob-windows/5947/beat=filebeat,label=windows/

 File "c:\python27\lib\unittest\case.py", line 329, in run
    testMethod()
  File "C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\tests\system\test_registrar.py", line 848, in test_clean_removed
    self.wait_until(lambda: self.registry.count() == 2)
  File "C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\tests\system\../../../libbeat/tests/system\beat\beat.py", line 348, in wait_until
    "Waited {} seconds.".format(max_timeout))
Timeout waiting for 'cond' to be true. Waited 10 seconds.

Logs

2019-03-13T09:50:04.865Z	INFO	instance/beat.go:567	Home path: [C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed] Config path: [C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed] Data path: [C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\data] Logs path: [C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\logs]
2019-03-13T09:50:04.866Z	DEBUG	[beat]	instance/beat.go:619	Beat metadata path: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\data\meta.json
2019-03-13T09:50:04.869Z	INFO	instance/beat.go:574	Beat ID: cc90beb4-69a7-4eeb-a9b1-85470f29c37f
2019-03-13T09:50:04.870Z	INFO	[index-management.ilm]	ilm/ilm.go:123	Policy name: filebeat-8.0.0
2019-03-13T09:50:04.870Z	DEBUG	[seccomp]	seccomp/seccomp.go:88	Syscall filtering is only supported on Linux
2019-03-13T09:50:04.871Z	INFO	[beat]	instance/beat.go:822	Beat info	{"system_info": {"beat": {"path": {"config": "C:\\Users\\jenkins\\workspace\\elastic+beats+pull-request+multijob-windows\\beat\\filebeat\\label\\windows\\src\\github.com\\elastic\\beats\\filebeat\\build\\system-tests\\run\\test_registrar.Test.test_clean_removed", "data": "C:\\Users\\jenkins\\workspace\\elastic+beats+pull-request+multijob-windows\\beat\\filebeat\\label\\windows\\src\\github.com\\elastic\\beats\\filebeat\\build\\system-tests\\run\\test_registrar.Test.test_clean_removed\\data", "home": "C:\\Users\\jenkins\\workspace\\elastic+beats+pull-request+multijob-windows\\beat\\filebeat\\label\\windows\\src\\github.com\\elastic\\beats\\filebeat\\build\\system-tests\\run\\test_registrar.Test.test_clean_removed", "logs": "C:\\Users\\jenkins\\workspace\\elastic+beats+pull-request+multijob-windows\\beat\\filebeat\\label\\windows\\src\\github.com\\elastic\\beats\\filebeat\\build\\system-tests\\run\\test_registrar.Test.test_clean_removed\\logs"}, "type": "filebeat", "uuid": "cc90beb4-69a7-4eeb-a9b1-85470f29c37f"}}}
2019-03-13T09:50:04.871Z	INFO	[beat]	instance/beat.go:831	Build info	{"system_info": {"build": {"commit": "unknown", "libbeat": "8.0.0", "time": "1754-08-30T22:43:41.128Z", "version": "8.0.0"}}}
2019-03-13T09:50:04.871Z	INFO	[beat]	instance/beat.go:834	Go runtime info	{"system_info": {"go": {"os":"windows","arch":"amd64","max_procs":4,"version":"go1.11.5"}}}
2019-03-13T09:50:04.876Z	INFO	[beat]	instance/beat.go:838	Host info	{"system_info": {"host": {"architecture":"x86_64","boot_time":"2019-02-15T04:09:37.01Z","name":"beats-ci-windows-2016-worker-x404","ip":["10.224.0.58/20","::1/128","127.0.0.1/8"],"kernel_version":"10.0.14393.2791 (rs1_release.190205-1511)","mac":["42:01:0a:e0:00:3a"],"os":{"family":"windows","platform":"windows","name":"Windows Server 2016 Datacenter","version":"10.0","major":10,"minor":0,"patch":0,"build":"14393.2791"},"timezone":"GMT","timezone_offset_sec":0,"id":"6842dd29-0e3c-4995-8486-4fa7fee5897f"}}}
2019-03-13T09:50:04.879Z	INFO	[beat]	instance/beat.go:867	Process info	{"system_info": {"process": {"cwd": "C:\\Users\\jenkins\\workspace\\elastic+beats+pull-request+multijob-windows\\beat\\filebeat\\label\\windows\\src\\github.com\\elastic\\beats\\filebeat\\tests\\system", "exe": "C:\\Users\\jenkins\\workspace\\elastic+beats+pull-request+multijob-windows\\beat\\filebeat\\label\\windows\\src\\github.com\\elastic\\beats\\filebeat\\filebeat.test.exe", "name": "filebeat.test.exe", "pid": 804, "ppid": 4972, "start_time": "2019-03-13T09:50:04.717Z"}}}
2019-03-13T09:50:04.880Z	INFO	instance/beat.go:276	Setup Beat: filebeat; Version: 8.0.0
2019-03-13T09:50:04.880Z	DEBUG	[beat]	instance/beat.go:297	Initializing output plugins
2019-03-13T09:50:04.881Z	DEBUG	[rotator]	file/rotator.go:165	Initialized file rotator	{"rotator": {"filename": "C:\\Users\\jenkins\\workspace\\elastic+beats+pull-request+multijob-windows\\beat\\filebeat\\label\\windows\\src\\github.com\\elastic\\beats\\filebeat\\build\\system-tests\\run\\test_registrar.Test.test_clean_removed\\output\\filebeat", "max_size_bytes": 1024000, "max_backups": 7, "permissions": "-rw-------", "interval": 0}}
2019-03-13T09:50:04.881Z	INFO	fileout/file.go:98	Initialized file output. path=C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\output\filebeat max_size_bytes=1024000 max_backups=7 permissions=-rw-------
2019-03-13T09:50:04.882Z	DEBUG	[publisher]	pipeline/consumer.go:137	start pipeline event consumer
2019-03-13T09:50:04.882Z	INFO	[publisher]	pipeline/module.go:97	Beat name: beats-ci-windows-2016-worker-x404
2019-03-13T09:50:04.883Z	ERROR	fileset/modules.go:125	Not loading modules. Module directory not found: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\module
2019-03-13T09:50:04.884Z	INFO	[monitoring]	log/log.go:117	Starting metrics logging every 30s
2019-03-13T09:50:04.884Z	INFO	instance/beat.go:387	filebeat start running.
2019-03-13T09:50:04.885Z	DEBUG	[test]	registrar/migrate.go:159	isFile(C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed/registry) -> false
2019-03-13T09:50:04.884Z	DEBUG	[service]	service/service_windows.go:72	Windows is interactive: false
2019-03-13T09:50:04.885Z	DEBUG	[test]	registrar/migrate.go:159	isFile() -> false
2019-03-13T09:50:04.885Z	DEBUG	[test]	registrar/migrate.go:152	isDir(C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat) -> false
2019-03-13T09:50:04.885Z	DEBUG	[registrar]	registrar/migrate.go:51	Registry type '' found
2019-03-13T09:50:04.885Z	DEBUG	[test]	registrar/migrate.go:159	isFile(.bak) -> false
2019-03-13T09:50:04.885Z	DEBUG	[test]	registrar/migrate.go:152	isDir(C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat) -> false
2019-03-13T09:50:04.885Z	INFO	service/service_windows.go:101	Attempted to register Windows service handlers, but this is not a service. No action necessary
2019-03-13T09:50:04.885Z	INFO	registrar/migrate.go:104	No registry home found. Create: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat
2019-03-13T09:50:04.886Z	DEBUG	[test]	registrar/migrate.go:159	isFile(C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat\meta.json) -> false
2019-03-13T09:50:04.886Z	INFO	registrar/migrate.go:112	Initialize registry meta file
2019-03-13T09:50:04.893Z	INFO	registrar/registrar.go:108	No registry file found under: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat\data.json. Creating a new registry file.
2019-03-13T09:50:04.894Z	DEBUG	[registrar]	registrar/registrar.go:411	Write registry file: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat\data.json (0)
2019-03-13T09:50:04.899Z	DEBUG	[registrar]	registrar/registrar.go:404	Registry file updated. 0 states written.
2019-03-13T09:50:04.900Z	INFO	registrar/registrar.go:145	Loading registrar data from C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat\data.json
2019-03-13T09:50:04.900Z	INFO	registrar/registrar.go:152	States Loaded from registrar: 0
2019-03-13T09:50:04.900Z	WARN	beater/filebeat.go:357	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.
2019-03-13T09:50:04.900Z	INFO	crawler/crawler.go:72	Loading Inputs: 1
2019-03-13T09:50:04.900Z	DEBUG	[registrar]	registrar/registrar.go:278	Starting Registrar
2019-03-13T09:50:04.903Z	DEBUG	[input]	log/config.go:201	recursive glob enabled
2019-03-13T09:50:04.904Z	DEBUG	[input]	log/input.go:147	exclude_files: []. Number of stats: 0
2019-03-13T09:50:04.905Z	DEBUG	[input]	log/input.go:168	input with previous states loaded: 0
2019-03-13T09:50:04.905Z	INFO	log/input.go:138	Configured paths: [C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input*]
2019-03-13T09:50:04.905Z	INFO	input/input.go:114	Starting input of type: log; ID: 17075841954629401310 
2019-03-13T09:50:04.905Z	INFO	crawler/crawler.go:106	Loading and starting Inputs completed. Enabled inputs: 1
2019-03-13T09:50:04.905Z	DEBUG	[input]	log/input.go:174	Start next scan
2019-03-13T09:50:04.906Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1
2019-03-13T09:50:04.907Z	DEBUG	[input]	log/input.go:477	Start harvester for new file: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1
2019-03-13T09:50:04.908Z	DEBUG	[harvester]	log/harvester.go:493	Setting offset for file based on seek: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1
2019-03-13T09:50:04.908Z	DEBUG	[harvester]	log/harvester.go:479	Setting offset for file: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1. Offset: 0 
2019-03-13T09:50:04.908Z	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 1}
2019-03-13T09:50:04.909Z	DEBUG	[publisher]	pipeline/client.go:200	Pipeline client receives callback 'onFilteredOut' for event: %+v{0001-01-01 00:00:00 +0000 UTC null null { false 0xc0002941c0 C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1 0 2019-03-13 09:50:04.9072258 +0000 GMT m=+0.172861001 -1ns log map[] 6291456-1526614-3634495929}}
2019-03-13T09:50:04.909Z	DEBUG	[harvester]	log/harvester.go:398	Update state: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1, offset: 0
2019-03-13T09:50:04.909Z	DEBUG	[input]	file/states.go:68	New state added for C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1
2019-03-13T09:50:04.909Z	DEBUG	[registrar]	registrar/registrar.go:356	Processing 1 events
2019-03-13T09:50:04.909Z	DEBUG	[input]	file/states.go:68	New state added for C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1
2019-03-13T09:50:04.909Z	DEBUG	[registrar]	registrar/registrar.go:326	Registrar state updates processed. Count: 1
2019-03-13T09:50:04.909Z	DEBUG	[registrar]	registrar/registrar.go:411	Write registry file: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat\data.json (1)
2019-03-13T09:50:04.910Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2
2019-03-13T09:50:04.910Z	DEBUG	[input]	log/input.go:477	Start harvester for new file: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2
2019-03-13T09:50:04.911Z	INFO	log/harvester.go:254	Harvester started for file: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1
2019-03-13T09:50:04.911Z	INFO	[detect_null_bytes]	debug/debug.go:95	Starting debug reader with a buffer size of 16384 and max failures of 100
2019-03-13T09:50:04.912Z	DEBUG	[harvester]	log/harvester.go:493	Setting offset for file based on seek: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2
2019-03-13T09:50:04.912Z	DEBUG	[harvester]	log/harvester.go:479	Setting offset for file: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2. Offset: 0 
2019-03-13T09:50:04.913Z	DEBUG	[processors]	processing/processors.go:183	Publish event: {
  "@timestamp": "2019-03-13T09:50:04.911Z",
  "@metadata": {
    "beat": "",
    "type": "_doc",
    "version": ""
  },
  "message": "file to be removed",
  "input": {
    "type": "log"
  },
  "ecs": {
    "version": "1.0.0-beta2"
  },
  "host": {
    "name": "beats-ci-windows-2016-worker-x404"
  },
  "agent": {
    "type": "filebeat",
    "ephemeral_id": "260057ff-c45e-407b-ac4e-30095155edca",
    "hostname": "beats-ci-windows-2016-worker-x404",
    "id": "cc90beb4-69a7-4eeb-a9b1-85470f29c37f",
    "version": "8.0.0"
  },
  "log": {
    "offset": 0,
    "file": {
      "path": "C:\\Users\\jenkins\\workspace\\elastic+beats+pull-request+multijob-windows\\beat\\filebeat\\label\\windows\\src\\github.com\\elastic\\beats\\filebeat\\build\\system-tests\\run\\test_registrar.Test.test_clean_removed\\log\\input1"
    }
  }
}
2019-03-13T09:50:04.913Z	DEBUG	[harvester]	log/log.go:102	End of file reached: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1; Backoff now.
2019-03-13T09:50:04.913Z	DEBUG	[publisher]	pipeline/client.go:200	Pipeline client receives callback 'onFilteredOut' for event: %+v{0001-01-01 00:00:00 +0000 UTC null null { false 0xc0002942a0 C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2 0 2019-03-13 09:50:04.9101461 +0000 GMT m=+0.175781301 -1ns log map[] 6291456-1526617-3634495929}}
2019-03-13T09:50:04.913Z	DEBUG	[harvester]	log/harvester.go:398	Update state: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2, offset: 0
2019-03-13T09:50:04.913Z	DEBUG	[input]	file/states.go:68	New state added for C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2
2019-03-13T09:50:04.914Z	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2019-03-13T09:50:04.915Z	INFO	log/harvester.go:254	Harvester started for file: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2
2019-03-13T09:50:04.915Z	INFO	[detect_null_bytes]	debug/debug.go:95	Starting debug reader with a buffer size of 16384 and max failures of 100
2019-03-13T09:50:04.915Z	DEBUG	[processors]	processing/processors.go:183	Publish event: {
  "@timestamp": "2019-03-13T09:50:04.915Z",
  "@metadata": {
    "beat": "",
    "type": "_doc",
    "version": ""
  },
  "input": {
    "type": "log"
  },
  "ecs": {
    "version": "1.0.0-beta2"
  },
  "host": {
    "name": "beats-ci-windows-2016-worker-x404"
  },
  "agent": {
    "type": "filebeat",
    "ephemeral_id": "260057ff-c45e-407b-ac4e-30095155edca",
    "hostname": "beats-ci-windows-2016-worker-x404",
    "id": "cc90beb4-69a7-4eeb-a9b1-85470f29c37f",
    "version": "8.0.0"
  },
  "log": {
    "offset": 0,
    "file": {
      "path": "C:\\Users\\jenkins\\workspace\\elastic+beats+pull-request+multijob-windows\\beat\\filebeat\\label\\windows\\src\\github.com\\elastic\\beats\\filebeat\\build\\system-tests\\run\\test_registrar.Test.test_clean_removed\\log\\input2"
    }
  },
  "message": "2"
}
2019-03-13T09:50:04.915Z	DEBUG	[harvester]	log/log.go:102	End of file reached: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2; Backoff now.
2019-03-13T09:50:04.915Z	DEBUG	[registrar]	registrar/registrar.go:404	Registry file updated. 1 states written.
2019-03-13T09:50:05.013Z	DEBUG	[harvester]	log/log.go:102	End of file reached: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1; Backoff now.
2019-03-13T09:50:05.014Z	DEBUG	[input]	input/input.go:152	Run input
2019-03-13T09:50:05.014Z	DEBUG	[input]	log/input.go:174	Start next scan
2019-03-13T09:50:05.015Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1
2019-03-13T09:50:05.015Z	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1, offset: 20
2019-03-13T09:50:05.015Z	DEBUG	[input]	log/input.go:546	Harvester for file is still running: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1
2019-03-13T09:50:05.015Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2
2019-03-13T09:50:05.015Z	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2, offset: 3
2019-03-13T09:50:05.015Z	DEBUG	[input]	log/input.go:546	Harvester for file is still running: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2
2019-03-13T09:50:05.015Z	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2019-03-13T09:50:05.016Z	DEBUG	[harvester]	log/log.go:102	End of file reached: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2; Backoff now.
2019-03-13T09:50:05.017Z	DEBUG	[publisher]	memqueue/ackloop.go:160	ackloop: receive ack [0: 0, 2]
2019-03-13T09:50:05.017Z	DEBUG	[publisher]	memqueue/eventloop.go:535	broker ACK events: count=2, start-seq=1, end-seq=2

2019-03-13T09:50:05.017Z	DEBUG	[publisher]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:2
2019-03-13T09:50:05.017Z	DEBUG	[publisher]	memqueue/ackloop.go:131	ackloop:  done send ack
2019-03-13T09:50:05.017Z	DEBUG	[acker]	beater/acker.go:64	stateful ack	{"count": 3}
2019-03-13T09:50:05.017Z	DEBUG	[registrar]	registrar/registrar.go:356	Processing 3 events
2019-03-13T09:50:05.017Z	DEBUG	[input]	file/states.go:68	New state added for C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2
2019-03-13T09:50:05.018Z	DEBUG	[registrar]	registrar/registrar.go:326	Registrar state updates processed. Count: 3
2019-03-13T09:50:05.018Z	DEBUG	[registrar]	registrar/registrar.go:411	Write registry file: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat\data.json (2)
2019-03-13T09:50:05.025Z	ERROR	registrar/registrar.go:374	Writing of registry returned error: rename C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat\data.json.new C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\registry\filebeat\data.json: Access is denied.. Continuing...
2019-03-13T09:50:05.114Z	DEBUG	[harvester]	log/log.go:102	End of file reached: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1; Backoff now.
2019-03-13T09:50:05.117Z	DEBUG	[input]	input/input.go:152	Run input
2019-03-13T09:50:05.117Z	DEBUG	[harvester]	log/log.go:102	End of file reached: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2; Backoff now.
2019-03-13T09:50:05.117Z	DEBUG	[input]	log/input.go:174	Start next scan
2019-03-13T09:50:05.118Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1
2019-03-13T09:50:05.118Z	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1, offset: 20
2019-03-13T09:50:05.118Z	DEBUG	[input]	log/input.go:546	Harvester for file is still running: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1
2019-03-13T09:50:05.119Z	DEBUG	[input]	log/input.go:404	Check file for harvesting: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2
2019-03-13T09:50:05.119Z	DEBUG	[input]	log/input.go:494	Update existing file for harvesting: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2, offset: 3
2019-03-13T09:50:05.119Z	DEBUG	[input]	log/input.go:546	Harvester for file is still running: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2
2019-03-13T09:50:05.119Z	DEBUG	[input]	log/input.go:195	input states cleaned up. Before: 2, After: 2, Pending: 0
2019-03-13T09:50:05.214Z	DEBUG	[harvester]	log/log.go:102	End of file reached: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input1; Backoff now.
2019-03-13T09:50:05.217Z	DEBUG	[harvester]	log/log.go:102	End of file reached: C:\Users\jenkins\workspace\elastic+beats+pull-request+multijob-windows\beat\filebeat\label\windows\src\github.com\elastic\beats\filebeat\build\system-tests\run\test_registrar.Test.test_clean_removed\log\input2; Backoff now.

`test_clean_inactive` (elastic#8102) and `test_clean_removed` (elastic#7690) have been flaky recently again on Windows. Skipping these test for Windows.

`test_clean_inactive` (#8102) and `test_clean_removed` (#7690) have been flaky recently again on Windows. Skipping these test for Windows.

urso · 2020-01-03T18:37:33Z

We made some improvements to detect file removal. Time to have a look at test_registrar.py and unskip tests.

urso · 2020-04-30T12:48:59Z

Unfortunately the test still fails on windows.

jlind23 · 2022-04-05T08:42:02Z

Backlog grooming: Closing it for now until further activity.

This is a potential fix for the flaky clean_removed test. The problem in the test seems to be that sometimes not all states are cleaned up yet. This is changing it by waiting for all pending cleanups to happen. Closes elastic#7690 (cherry picked from commit 6625835)

kvch added Filebeat Filebeat flaky-test Unstable or unreliable test cases. labels Jul 24, 2018

andrewkroh changed the title ~~Test test_registrar.test_clean_removed fails~~ [Filebeat] Test test_registrar.test_clean_removed fails Aug 17, 2018

ruflin mentioned this issue Aug 27, 2018

[Filebeat] Flaky test_clean_removed_with_clean_inactive test #7842

Closed

ruflin mentioned this issue Aug 27, 2018

Fix flaky clean_removed test #8092

Merged

jsoriano closed this as completed in #8092 Aug 28, 2018

ruflin mentioned this issue Aug 28, 2018

Cherry-pick #8092 to 6.x: Fix flaky clean_removed test #8118

Merged

ruflin mentioned this issue Aug 28, 2018

Cherry-pick #8092 to 6.4: Fix flaky clean_removed test #8119

Merged

ruflin reopened this Nov 22, 2018

ruflin mentioned this issue Nov 22, 2018

Skip clean_removed test #9207

Merged

ruflin assigned urso Nov 22, 2018

ruflin added a commit to ruflin/beats that referenced this issue Nov 22, 2018

Skip clean_removed test

95c8c72

See elastic#7690

ruflin added a commit that referenced this issue Nov 22, 2018

Skip clean_removed test (#9207)

be187b9

See #7690

ruflin mentioned this issue Nov 22, 2018

Cherry-pick #9207 to 6.x: Skip clean_removed test #9211

Merged

ruflin added a commit to ruflin/beats that referenced this issue Nov 22, 2018

Skip clean_removed test (elastic#9207)

eabb2c0

See elastic#7690 (cherry picked from commit be187b9)

ph pushed a commit that referenced this issue Nov 26, 2018

Skip clean_removed test (#9207) (#9211)

58d1e81

See #7690 (cherry picked from commit be187b9)

urso mentioned this issue Feb 14, 2019

Fix Registrar not removing files when clean_removed is configured #10747

Merged

urso closed this as completed in #10747 Feb 18, 2019

kvch reopened this Mar 13, 2019

ruflin added a commit to ruflin/beats that referenced this issue Mar 29, 2019

[Filebeat] Skip flaky windows tests

46e0b62

`test_clean_inactive` (elastic#8102) and `test_clean_removed` (elastic#7690) have been flaky recently again on Windows. Skipping these test for Windows.

ruflin mentioned this issue Mar 29, 2019

[Filebeat] Skip flaky windows tests #11540

Merged

ruflin added a commit that referenced this issue Apr 1, 2019

[Filebeat] Skip flaky windows tests (#11540)

4d1b9ce

`test_clean_inactive` (#8102) and `test_clean_removed` (#7690) have been flaky recently again on Windows. Skipping these test for Windows.

urso mentioned this issue Oct 4, 2019

Check if file has disappeared sooner in Log reader #13907

Merged

urso added the Team:Beats label Jan 3, 2020

urso mentioned this issue Jan 23, 2020

Reenable removed tests in test_registrar #15790

Merged

8 tasks

urso closed this as completed in #15790 Jan 28, 2020

andresrc reopened this Jan 30, 2020

andresrc added the [zube]: Inbox label Jan 30, 2020

andresrc closed this as completed Jan 30, 2020

andresrc added [zube]: Done and removed [zube]: Inbox [zube]: Done labels Jan 30, 2020

andresrc added the Team:Integrations Label for the Integrations team label Mar 6, 2020

urso reopened this Apr 30, 2020

urso mentioned this issue Apr 30, 2020

Skip flaky clean_x tests in filebeat #18134

Merged

andresrc added the [zube]: Backlog label May 4, 2020

urso mentioned this issue May 4, 2020

Cherry-pick #18134 to 7.x: Skip flaky clean_x tests in filebeat #18190

Merged

jlind23 closed this as completed Apr 5, 2022

zube bot added [zube]: Done and removed [zube]: Backlog labels Apr 5, 2022

zube bot removed the [zube]: Done label Jul 4, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Filebeat] Test test_registrar.test_clean_removed fails #7690

[Filebeat] Test test_registrar.test_clean_removed fails #7690

kvch commented Jul 24, 2018

ruflin commented Aug 27, 2018

ruflin commented Nov 22, 2018

kvch commented Mar 13, 2019

urso commented Jan 3, 2020

urso commented Apr 30, 2020

jlind23 commented Apr 5, 2022

[Filebeat] Test test_registrar.test_clean_removed fails #7690

[Filebeat] Test test_registrar.test_clean_removed fails #7690

Comments

kvch commented Jul 24, 2018

ruflin commented Aug 27, 2018

ruflin commented Nov 22, 2018

kvch commented Mar 13, 2019

urso commented Jan 3, 2020

urso commented Apr 30, 2020

jlind23 commented Apr 5, 2022