Error on successive removal of directories being watched

[mauricioabreu]

First of all, thanks for this library.

I have a problem here but I don't know how to fix it. I am watching a directory recursively, for example: /home/foo/.... There is a process (I don't control) that removes the directories being watched under the foo. I noticed the following behaviours:

• When I do it once, it recovers and continues to watch after folders and files of this folder are reinserted;
• When I do it for the second time, it stops to watch that folders.

Do you have any idea of what is the source of this problem? I used inotify-tools to check if it was an inotify bug but I continue to receive the events of these removed directories there.

[rjeczalik]

When I do it for the second time, it stops to watch that folders.

You may run out of fd, that's why this may happen - you can try bumping the limit with e.g. ulimit -n 4096. You can build your code with debug tag (go build -tag debug), and see notify's output for any hint.

[mauricioabreu]

@rjeczalik thank you for showing me how to see the debugging output.

I ran my program with debug enabled and from the logs I can just read notify.Create, notify.InCloseWrite, notify.InMovedTo

I literally ran rm -rf <subdirectories> and the same thing happened.

Should I see an event notify.InDelete for these folders?

[rjeczalik]

@mauricioabreu It's hard to say without seeing the full output, there are a lot of events logged by notify, which are just ignored if not watched y a user.

Ideally a repro program would be helpful, or a test event more - if you think there's wrong behaviour somewhere please add a test for it, it'd be really helpful (see watcher_inotify_test.go).

[mauricioabreu]

@rjeczalik of course. Sorry for not providing examples with code. I will do it, I did not mean to be rude or lazy.

there are a lot of events logged by notify, which are just ignored if not watched y a user.

I asked that question because my notify initalization does not cover Create unix.IN_CREATE and it was listed in the log output. Code:

func NewFileWatcher(rootPath string, files chan string, isRecursive bool) (*Watcher, error) {
    if isRecursive {
        rootPath = filepath.Join(rootPath, "...")
    }
    watcher := &Watcher{
        eventStream: make(chan notify.EventInfo, 1),
        Files:       files,
        rootPath:    filepath.Clean(rootPath),
    }

    if err := notify.Watch(rootPath, watcher.eventStream, notify.InCloseWrite, notify.InMovedTo); err != nil {
        logrus.Fatal(err)
    }
    return watcher, nil
}

One last thing I noticed is the Bugs section in the documentation (https://godoc.org/github.com/rjeczalik/notify#pkg-note-bug)

Notify does not collect watchpoints, when underlying watches were removed by their os-specific watcher implementations. Instead users are advised to listen on persistent paths to have guarantee they receive events for the whole lifetime of their applications (to discuss see #69).

Not sure if these events are related.

Thanks again! I will provide a test case for it soon.

[mauricioabreu]

I created a repository demonstrating the problem: https://github.com/mauricioabreu/notify-issue-171

Here I paste the output of the program:

2019/01/12 23:31:09.779948 [D] dispatching notify.Create on "/go/example/foo/a.txt"
2019/01/12 23:31:09.780137 New event /go/example/foo/a.txt notify.Create
2019/01/12 23:31:09.781894 [D] dispatching notify.Create on "/go/example/bar/b.txt"
2019/01/12 23:31:09.782185 New event /go/example/bar/b.txt notify.Create
2019/01/12 23:31:09.785526 [D] dispatching notify.Remove on "/go/example/foo/a.txt"
2019/01/12 23:31:09.785940 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:09.787575 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:09.787937 New event /go/example/foo notify.Remove
2019/01/12 23:31:09.788673 New event /go/example/foo/a.txt notify.Remove
2019/01/12 23:31:09.789476 New event /go/example/foo notify.Remove
2019/01/12 23:31:09.789367 [D] dispatching notify.Remove on "/go/example/bar/b.txt"
2019/01/12 23:31:09.790496 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:09.790593 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:09.790627 New event /go/example/bar notify.Remove
2019/01/12 23:31:09.790653 New event /go/example/bar/b.txt notify.Remove
2019/01/12 23:31:09.790712 New event /go/example/bar notify.Remove
2019/01/12 23:31:10.792037 [D] dispatching notify.Create on "/go/example/foo"
2019/01/12 23:31:10.792136 [D] dispatching notify.Create on "/go/example/bar"
2019/01/12 23:31:10.793051 New event /go/example/bar notify.Create
2019/01/12 23:31:10.793631 New event /go/example/foo notify.Create
2019/01/12 23:31:10.796949 [D] dispatching notify.Create on "/go/example/foo/a.txt"
2019/01/12 23:31:10.797720 New event /go/example/foo/a.txt notify.Create
2019/01/12 23:31:10.800676 [D] dispatching notify.Create on "/go/example/bar/b.txt"
2019/01/12 23:31:10.801490 New event /go/example/bar/b.txt notify.Create
2019/01/12 23:31:10.804584 [D] dispatching notify.Remove on "/go/example/foo/a.txt"
2019/01/12 23:31:10.804651 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:10.806003 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:10.806138 [D] dispatching notify.Remove on "/go/example/bar/b.txt"
2019/01/12 23:31:10.806154 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:10.806692 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:10.806934 [D] dropped notify.Remove on "/go/example/bar": receiver too slow
2019/01/12 23:31:10.806996 [D] dropped notify.Remove on "/go/example/bar/b.txt": receiver too slow
2019/01/12 23:31:10.805974 New event /go/example/foo/a.txt notify.Remove
2019/01/12 23:31:10.807123 New event /go/example/foo notify.Remove
2019/01/12 23:31:10.807132 New event /go/example/bar notify.Remove
2019/01/12 23:31:10.808071 [D] dropped notify.Remove on "/go/example/foo": receiver too slow
2019/01/12 23:31:11.813234 [D] dispatching notify.Create on "/go/example/foo"
2019/01/12 23:31:11.813316 [D] dispatching notify.Create on "/go/example/bar"
2019/01/12 23:31:11.813390 New event /go/example/bar notify.Create
2019/01/12 23:31:11.813442 New event /go/example/foo notify.Create
2019/01/12 23:31:11.819074 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:11.819191 New event /go/example/foo notify.Remove
2019/01/12 23:31:11.819999 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:11.820109 New event /go/example/bar notify.Remove
2019/01/12 23:31:12.826456 [D] dispatching notify.Create on "/go/example/foo"
2019/01/12 23:31:12.826534 [D] dispatching notify.Create on "/go/example/bar"
2019/01/12 23:31:12.826826 New event /go/example/bar notify.Create
2019/01/12 23:31:12.826889 New event /go/example/foo notify.Create
2019/01/12 23:31:12.836677 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:12.836763 New event /go/example/foo notify.Remove
2019/01/12 23:31:12.837198 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:12.837243 New event /go/example/bar notify.Remove
2019/01/12 23:31:13.846223 [D] dispatching notify.Create on "/go/example/foo"
2019/01/12 23:31:13.846386 New event /go/example/foo notify.Create
2019/01/12 23:31:13.848026 [D] dispatching notify.Create on "/go/example/bar"
2019/01/12 23:31:13.848370 New event /go/example/bar notify.Create
2019/01/12 23:31:13.854950 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:13.855049 New event /go/example/foo notify.Remove
2019/01/12 23:31:13.856291 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:13.857272 New event /go/example/bar notify.Remove
2019/01/12 23:31:14.861805 [D] dispatching notify.Create on "/go/example/foo"
2019/01/12 23:31:14.861898 [D] dispatching notify.Create on "/go/example/bar"
2019/01/12 23:31:14.862589 New event /go/example/bar notify.Create
2019/01/12 23:31:14.863700 New event /go/example/foo notify.Create
2019/01/12 23:31:14.869514 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:14.869547 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:14.869567 New event /go/example/bar notify.Remove
2019/01/12 23:31:14.869581 New event /go/example/foo notify.Remove
2019/01/12 23:31:15.875036 [D] dispatching notify.Create on "/go/example/foo"
2019/01/12 23:31:15.875510 New event /go/example/foo notify.Create
2019/01/12 23:31:15.875875 [D] dispatching notify.Create on "/go/example/bar"
2019/01/12 23:31:15.876220 New event /go/example/bar notify.Create
2019/01/12 23:31:15.885062 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:15.886002 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:15.886551 New event /go/example/bar notify.Remove
2019/01/12 23:31:15.886946 New event /go/example/foo notify.Remove
2019/01/12 23:31:16.891939 [D] dispatching notify.Create on "/go/example/foo"
2019/01/12 23:31:16.892981 [D] dispatching notify.Create on "/go/example/bar"
2019/01/12 23:31:16.894072 New event /go/example/foo notify.Create
2019/01/12 23:31:16.894875 New event /go/example/bar notify.Create
2019/01/12 23:31:16.901495 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:16.902762 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:16.903351 New event /go/example/bar notify.Remove
2019/01/12 23:31:16.903970 New event /go/example/foo notify.Remove
2019/01/12 23:31:17.910139 [D] dispatching notify.Create on "/go/example/foo"
2019/01/12 23:31:17.911002 [D] dispatching notify.Create on "/go/example/bar"
2019/01/12 23:31:17.911753 New event /go/example/bar notify.Create
2019/01/12 23:31:17.913244 New event /go/example/foo notify.Create
2019/01/12 23:31:17.921562 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:17.922417 New event /go/example/foo notify.Remove
2019/01/12 23:31:17.923073 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:17.924265 New event /go/example/bar notify.Remove
2019/01/12 23:31:18.906830 [D] dispatching notify.Create on "/go/example/foo"
2019/01/12 23:31:18.906947 [D] dispatching notify.Create on "/go/example/bar"
2019/01/12 23:31:18.907202 New event /go/example/bar notify.Create
2019/01/12 23:31:18.907303 New event /go/example/foo notify.Create
2019/01/12 23:31:18.915407 [D] dispatching notify.Remove on "/go/example/foo"
2019/01/12 23:31:18.915546 New event /go/example/foo notify.Remove
2019/01/12 23:31:18.916539 [D] dispatching notify.Remove on "/go/example/bar"
2019/01/12 23:31:18.916624 New event /go/example/bar notify.Remove
2019/01/12 23:31:19.924494 [D] dispatching notify.Create on "/go/example/foo"
2019/01/12 23:31:19.924959 [D] dispatching notify.Create on "/go/example/bar"

As we can see, there is an error receiver too slow and the watcher was not receiving the Create events generated by the touch command.

[rjeczalik]

As we can see, there is an error receiver too slow and the watcher was not receiving the Create events generated by the touch command.

Usually increasing buffer size for the receiving buffer fixes the issue. Other question is do you really need to process that many events at that pace.

[mauricioabreu]

Thanks for the answer!

What do you mean by increasing the buffer size for the receiving buffer. Are you talking about the buffer we pass to notify.Watch? I am using 1 and 10240 and they have the same effect.

About the number of events, this problem also happens if you do it manually (slow or fast). So I guess it is not a performance issue, right?

Important information: my example runs on a CentOS image, but I tried it on my Mac (that uses FSEvents) and I see that all events for the files were received.

[rjeczalik]

About the number of events, this problem also happens if you do it manually (slow or fast). So I guess it is not a performance issue, right?

This is interesting, are you able to reproduce this issue from a docker container?

Does it drop events if you use QueuedWatch instead of notify.Watch?

[mauricioabreu]

Yes, here is the project/container I created to demonstrate this: https://github.com/mauricioabreu/notify-issue-171

The README file has instructions to build/execute the example.

I used QueuedWatch too and the problem is the same. too slow receiver does not always happen, but the original problem (successive removal/create of directories being watched) happens regardless of this error.

[mauricioabreu]

Reading the debug output, we can see that the directories being created/removed are being notified, but not their files (or even their subdirectories). With this information, I am debugging and reading the source code on how notify rewatches directories recursively. Also it is surprisingly weird that it works for the first removal/creation of already watched directories.

[mauricioabreu]

I am wondering if it is related to the way inotify works, using inodes.