emits CREATE when it should have been REMOVE

[xibz]

Before reporting an issue, please ensure you are using the latest release of fsnotify.

Which operating system (GOOS) and version are you using?

> cat /etc/os-release
NAME="Alpine Linux"
ID=alpine
VERSION_ID=3.15.0
PRETTY_NAME="Alpine Linux v3.15"
HOME_URL="https://alpinelinux.org/"
BUG_REPORT_URL="https://bugs.alpinelinux.org/"

Please describe the issue that occurred.

Basically I am running an application that uses fsnotify in docker and I am manually creating and removing files just to see the events, and sometimes it reports CREATE when it should have been a REMOVE.

Are you able to reproduce the issue? Please provide steps to reproduce and a code sample if possible.

What I would do is make a Dockerfile with alpine:latest and copy the example you have in github. Mount a directory and watch that directory and just delete and create files on the host, not the container, and you'll see it. It happens pretty often, but not all the time.

I dont know if this is an issue with containers, mounting volumes, and deleting from the host or an issue just in general. In general, as in not using docker and being able to repo this since I've only tried it using docker and creating/deleting files on the host.

Okay looks to be an issue with potentially with either docker or alpine linux.

[fulviodenza]

I'm having this exact issue.
Removing files via terminal works, with both nautilus and dolphin file manager the issue occurs

cat /etc/os-release
NAME="Fedora Linux"
VERSION="35 (KDE Plasma)"
ID=fedora
VERSION_ID=35
VERSION_CODENAME=""
PLATFORM_ID="platform:f35"
PRETTY_NAME="Fedora Linux 35 (KDE Plasma)"
ANSI_COLOR="0;38;2;60;110;180"

[marklr]

I just tried spinning up a couple of Docker containers with alpine:latest and golang:1.17-alpine, both running the example watcher on /tmp/foo, which is exposed via docker run -v "/tmp/foo:/tmp/foo" ... on the (Pop_OS) host. I also added a simple map[fsnotify.Op]int counter that increments each op's key per received event.

In another tab, I ran a basic script to generate files sequentially, write a few bytes and remove them from the watcher dir:

for I in $(seq 1 5000);
do
touch tmp.$I
echo "foo" >> tmp.$I
rm -f tmp.$I
done

And indeed, we're ending up an inconsistent state at the end of the run:

map[CREATE:4519 WRITE:4518 REMOVE:5000 CHMOD:4519]

Where all counts should be 5000.

[horahoradev]

I'm able to reproduce this on an Alpine Linux docker container, with similar conditions to the above. It does not occur on my host installation of Ubuntu.

Interestingly, the issue occurs within the following fsnotify program:

import (
	"log"
	"time"

	"github.com/fsnotify/fsnotify"
)

func main() {
	watcher, err := fsnotify.NewWatcher()
	if err != nil {
		log.Fatal(err)
	}
	defer watcher.Close()

	finalMap := make(map[fsnotify.Op]int)

	go func() {
		for {
			select {
			case event, _ := <-watcher.Events:
				if event.Op&fsnotify.Chmod == fsnotify.Chmod {
					finalMap[fsnotify.Chmod] += 1
				}
				if event.Op&fsnotify.Write == fsnotify.Write {
					finalMap[fsnotify.Write] += 1
				}
				if event.Op&fsnotify.Create == fsnotify.Create {
					finalMap[fsnotify.Create] += 1
				}
				if event.Op&fsnotify.Remove == fsnotify.Remove {
					finalMap[fsnotify.Remove] += 1
				}
				if event.Op&fsnotify.Rename == fsnotify.Rename {
					finalMap[fsnotify.Rename] += 1
				}
			case err, ok := <-watcher.Errors:
				if !ok {
					return
				}
				log.Println("error:", err)
			}
		}
	}()

	err = watcher.Add("/tmp/foo")
	if err != nil {
		log.Fatal(err)
	}
	time.Sleep(time.Second * 30)
	log.Print(finalMap)

}

In one run, using docker run -v /tmp/foo:/tmp/foo 92d0b327e82c, I received the following output:
2022/02/21 22:34:04 map[CREATE:1543 WRITE:1543 REMOVE:1543]

However, it does NOT occur if I use inotify-wait (a CLI utilizing inotify) to count the number of operations. See following output:

  10000 CLOSE_WRITE,CLOSE
   5000 CREATE
   5000 DELETE
   5000 MODIFY
  10000 OPEN

I think this implies that the issue does not lie with inotify/Docker/Alpine, but rather with fsnotify.

[horahoradev]

Strangely, I'm not able to reproduce the above issue as well anymore; I modified my script to create, modify, and remove 20000 files per run, and I get some variation of the following:

2022/02/22 00:39:35 map[CREATE:19956 WRITE:19942 REMOVE:20000]

Clearly some events are being dropped, but it's not as egregious. After removing the following snippet from the ignoreLinux method (as follows) I was able to achieve the expected results.

	// If the event is not a DELETE or RENAME, the file must exist.
	// Otherwise the event is ignored.
	// *Note*: this was put in place because it was seen that a MODIFY
	// event was sent after the DELETE. This ignores that MODIFY and
	// assumes a DELETE will come or has come if the file doesn't exist.
	if !(e.Op&Remove == Remove || e.Op&Rename == Rename) {
		_, statErr := os.Lstat(e.Name)
		return os.IsNotExist(statErr)
	}

Essentially, if the event doesn't contain a remove or a rename, we check lstat every time to see if the file still exists, and drop the event if it doesn't, but that's no guarantee that the file still exists by the time the client receives it, or processes the event.

I think this snippet still guarantees the correct behavior (it would simply drop most events for which the corresponding file no longer existed), but we're not actually providing any guarantee to the clients that the file still exists by the time that they receive the event, so do we really need to be invoking lstat thousands of times?

The inotify man page indicates that events will be sent in order, and they are processed in fsnotify in order, so there shouldn't be any cases in which we've received a delete, and then later on receive a write event to the same file (unless a file with the same name has been created).

Could you please make this modification on your ends, and see if you can still reproduce the issue?

[arp242]

I think #470 should have fixed this; please let me know if you can still reproduce it with that change.