Race condition with triggers
- Dominant language
- C++
- Stars
- 13.7k
- Forks
- 1.1k
- PR merge metrics
- No merged PRs in 30d
Description
## Description
I'm developing a trigger that is meant to `rsync` directory changes as responsively as possible while still being correct. The trigger invokes my shell script which wraps an `rsync` invocation. I see that Watchman tries to ensure that only one instance of each trigger's command is running at a time, which I like. As part of enforcing this, however, it sends SIGTERM to the currently running instance of a command when it's time to start the next, which I don't like. I don't want any of my `rsync` invocations to be aborted mid-transfer. As such, I changed by shell script to catch and ignore the SIGTERM. This fixed the aborted transfer problem, but exposed what looks to be a race condition in how Watchman spawns triggered commands.
## Environment
- OS: macOS 10.14.4
- Watchman version: repro with both latest `master` (commit `7bce6e959b`) and release `4.9.0`
- Watcher: FSEvents
## Repro
It crops up if multiple subsequent file change events occur at rate faster than Watchman's settling time but slower than the triggered command's run time. Repro case below.
In one terminal, run:
```
watchman shutdown-server && watchman -f --logfile=/dev/stdout --log-level=2
```
In another, run:
```
./trigger.sh
./test.sh
```
Observe the output in the first terminal (ignore anything related to the deletion of the temporary directories). You should see that not all five temporary directories were received and printed by `triggered_script.sh`. On my machine the missing directories are usually `2` and `4`, but it varies. Mess with the `sleep` times in `test.sh` and `triggered_script.sh` if none of the directories are missing for you. I think one rule is that the first (`1`) and last (`5`) directories are always printed, though:
```
[{"exists": true, "type": "d", "name": "1"}]
[{"exists": true, "type": "d", "name": "3"}]
[{"exists": true, "type": "d", "name": "5"}]
```
There should be other debug output which shows that those missing directories' events _were_ received by Watchman in some fashion, though:
```
2019-05-15T16:47:36,386: [notify 0x7fae51800818 /Users/ty/code/watchman_bug] add_pending: /Users/ty/code/watchman_bug/4 VIA_NOTIFY
2019-05-15T16:47:36,386: [io 0x7fae51800818 /Users/ty/code/watchman_bug] ... wake up (pinged=true)
2019-05-15T16:47:36,386: [io 0x7fae51800818 /Users/ty/code/watchman_bug] processing 1 events in /Users/ty/code/watchman_bug
2019-05-15T16:47:36,386: [io 0x7fae51800818 /Users/ty/code/watchman_bug] getFileInformation(/Users/ty/code/watchman_bug/4) file=0x7fae4fd00c80 dir=0x7fae4fd01340
2019-05-15T16:47:36,387: [io 0x7fae51800818 /Users/ty/code/watchman_bug] file changed exists=0 via_notify=1 stat-changed=0 isdir=1 /Users/ty/code/watchman_bug/4
2019-05-15T16:47:36,387: [io 0x7fae51800818 /Users/ty/code/watchman_bug] add_pending: /Users/ty/code/watchman_bug/4 CRAWL_ONLY RECURSIVE
```
### Repro scripts
`test.sh`:
```
#!/bin/bash
rm -rf 1 2 3 4 5
sleep 5 # wait for dir removal to clear
for f in {1..5}
do
mkdir "$f"
# ensure new directories aren't coalesced by settling logic
sleep 0.25
sync
done
```
`trigger.sh`:
```
#!/bin/bash
watchman -n -j <<-EOT
["trigger", "$(pwd -P)", {
"name": "watchman_bug",
"command": ["$(pwd -P)/triggered_script.sh"],
"append_files": false,
"stdin": [
"name",
"exists",
"type"
]
}]
EOT
```
`triggered_script.sh`:
```
#!/bin/bash
trap "echo \"triggered_script.sh PID $$: ignoring SIGTERM from Watchman.\"" SIGTERM
while read line
do
sleep 1 # simulate the triggered script run rate being slower than file change event rate
echo "$line"
done
```
Contributor guide
Assessment
This issue has not been assessed yet.