cmd: templ generate with watch can generate corrupted Go files, because of race condition with fsnotify WRITE events

[stefanohrmann]

I used the following command:

templ generate -watch -v

to watch my template directory and to generate the Go files on changes. In the first place I used the command with the proxy and the cmd option to automatically update the displayed website, but the issue also occurs if I only use the the watch option. I got the following trace:

stefan@home:~/Projekte/go/watchlist$ templ generate -watch -v
(!) templ version check: generator v0.2.570 is newer than templ version v0.2.543 found in go.mod file, consider running `go get -u github.com/a-h/templ` to upgrade
(✓) Starting post-generation handler
(✓) Walking directory [ path=/home/stefan/Projekte/go/watchlist devMode=true ]
(✓) Starting event handler
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/index_templ.go op=CREATE fileSize=4238 ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/index.templ op=CREATE fileSize=1037 ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/index_templ.txt op=CREATE fileSize=675 ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout.templ op=CREATE fileSize=536 ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout_templ.txt op=CREATE fileSize=444 ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout_templ.go op=CREATE fileSize=1386 ]
(✓) Watching files
(✓) Waiting for context to be cancelled to stop watching files
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout_templ.go op=WRITE fileSize=1386 ]
(✓) Generated code [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout.templ in=1.693935ms ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout_templ.go op=WRITE fileSize=1386 ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout_templ.txt op=WRITE fileSize=444 ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/index_templ.go op=WRITE fileSize=4096 ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/index_templ.go op=WRITE fileSize=4238 ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/index_templ.txt op=WRITE fileSize=675 ]
(✓) Generated code [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/index.templ in=3.39407ms ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/index_templ.txt op=WRITE fileSize=675 ]
(✓) First post-generation event received, starting proxy
(✓) No proxy URL specified, not starting proxy
…
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout.templ op=WRITE fileSize=0 ]
(✓) Processing file [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout.templ op=WRITE fileSize=537 ]
(✓) Skipping file because it wasn't updated [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout.templ ]
(✓) Generated code [ file=/home/stefan/Projekte/go/watchlist/ui/web/templates/layout.templ in=280.205µs ]

I omitted the entries for the first several tries to reproduce the issue. For full disclosure I replaced the for following line in the source:

templ/cmd/templ/generatecmd/cmd.go

Line 171 in 753ba39

cmd.Log.Debug("Processing file", slog.String("file", event.Name))

with the following to investigate the issue (you see the result in the trace above)

// cmd.Log.Debug("Processing file", slog.String("file", event.Name))
if cmd.Log.Enabled(context.TODO(), slog.LevelDebug) {
	if stat, err := os.Stat(event.Name); err == nil {
		cmd.Log.Debug(
			"Processing file",
			slog.String("file", event.Name),
			slog.String("op", event.Op.String()),
			slog.Int64("fileSize", stat.Size()))
	} else {
		cmd.Log.Debug(
			"Processing file",
			slog.String("file", event.Name),
			slog.String("op", event.Op.String()))
	}
}

After the last change in the trace above the layout_templ.go file has the following content and isn't compilable:

// Code generated by templ - DO NOT EDIT.

// templ: version: v0.2.570

//lint:file-ignore SA4006 This context is only used if a nested component is present.

import "github.com/a-h/templ"

The issue is that the generate acts on the first WRITE notification for the layout.tmpl file, but in this case the file is empty and this produces the corrupted Go file. I don't know if there should be a warning.

As far as I know this is a known issue with fsnotify and they recommend to dedup the WRITE notifications.

I try to create a test for the issue:

generate_racecondition_test.zip

This is not 100% reliable, because this depends on the file system.

I suggest that whole watch functionality is moved to an own subcommand and that the generate subcommand only does the generation of the Go files. That would imho result in a straight forward (in the current implementation the collection of the template files is done by using a channel and fsnotify events even if no watch is selected) and faster implementation of the generate subcommand without any concurrency. A fast generate subcommand could be better for 3rd party tools like Air. But maybe I'm not fully understand all the implications of such a change.

If such a change would align with the vision of this project, then I would be happy to provide PRs for this in the following order:

1. Create a watch subcommand that uses the current generate subcommand.
2. Relay watch from the generate subcommand to the watch subcommand (add deprecation warnings).
3. Remove watch stuff from the generate subcommand.

[joerdav]

Thanks @stefanohrmann for the thorough bug report, and your time spent investigating. I've marked this as NeedsInvestigation because I think it could be worth looking into the viability of a fix which doesn't involve removing any commands. Such as ignoring events where the file is empty.

[stefanohrmann]

@joerdav You are right and I think it is totally possible to fix this issue in the current implementation if you apply the dedup stuff from fsnotify here:

templ/cmd/templ/generatecmd/watcher/watch.go

Lines 73 to 99 in 753ba39

	func (w *RecursiveWatcher) loop() {
	for {
	select {
	case <-w.ctx.Done():
	return
	case event, ok := <-w.w.Events:
	if !ok {
	return
	}
	if event.Has(fsnotify.Create) {
	if err := w.Add(event.Name); err != nil {
	w.Errors <- err
	}
	}
	// Only notify on templ related files.
	if !shouldIncludeFile(event.Name) {
	continue
	}
	w.Events <- event
	case err, ok := <-w.w.Errors:
	if !ok {
	return
	}
	w.Errors <- err
	}
	}
	}

And with my suggestion i didn't want to remove any subcommands. I wanted to add a dedicated one for watching. But it is ok if this doesn't fit in your structure.

Edit note: Changed the link to right place for the fix.

[joerdav]

Ah, not to dismiss your idea, just wanted to explore all options first, and I think minimal change to the outside API would be preferable.

[a-h]

Great find, and nice write up.

From reading the fsnotify dedup function, it looks like it's more of a debounce than a deduplication, because it doesn't look at the message content (e.g. by having a windowing function or ring buffer of previous messages). It just waits for a timer to elapse before allowing the processing.

I think the logic to handle either a true deduplication (i.e. within a window of 100ms, if there is more than one operation of the same time, discard the earlier ones, and emit the latest), or debounce would go here:

templ/cmd/templ/generatecmd/watcher/watch.go

Lines 73 to 99 in 753ba39

	func (w *RecursiveWatcher) loop() {
	for {
	select {
	case <-w.ctx.Done():
	return
	case event, ok := <-w.w.Events:
	if !ok {
	return
	}
	if event.Has(fsnotify.Create) {
	if err := w.Add(event.Name); err != nil {
	w.Errors <- err
	}
	}
	// Only notify on templ related files.
	if !shouldIncludeFile(event.Name) {
	continue
	}
	w.Events <- event
	case err, ok := <-w.w.Errors:
	if !ok {
	return
	}
	w.Errors <- err
	}
	}
	}

[stefanohrmann]

@a-h You are right about the dedup and debounce stuff. I didn't want to change the terminology of fsnotify and I marked the wrong place for the fix. I will correct it.

[joerdav]

I've created a debounce implementation, for now I've put the window at 100ms I'm hoping that this will be enough.