search

rjeczalik / notify

File system event notification library on steroids.
MIT License
900 stars 128 forks source link

Recursive dir watching on Linux seems unreliable #227

Open andrewmoise opened 6 months ago

andrewmoise commented 6 months ago

The self tests don't pass on Linux (Debian bookworm, 12.5, with Go 1.19.8 on kernel 6.1.0-18). I started getting into this because it seems like create events for files in newly-created subdirectories in my application were sometimes getting dropped, but it was a little hard to come up with a minimal repro case for it, so I grabbed the source (main from 2024-03-03) and the self tests sometimes pass and sometimes not.

Here's debug output from a successful run:

2024/03/03 17:36:15.811494 [D] received: path="/home/moise/notify/testdata/1326860591/src/github.com/rjeczalik/fs/cmd/gotree/main.go", event=notify.Remove, sys=&{9 512 0 0} (i=3, j=0)
2024/03/03 17:36:15.972497 [D] dispatching notify.Create on "/tmp/TestRenameInRoot2861869223/001/bar"
2024/03/03 17:36:15.972670 [D] dispatching notify.Rename on "/tmp/TestRenameInRoot2861869223/001/foo"
2024/03/03 17:36:15.972698 [D] dispatching notify.Rename on "/tmp/TestRenameInRoot2861869223/001/foo"    
2024/03/03 17:36:16.023304 [D] dispatching notify.Create on "/tmp/TestRenameInRoot2861869223/001/bar/file"
2024/03/03 17:36:16.023754 [D] Stop(0xc00107d9e0) error: <nil>
2024/03/03 17:36:16.024748 [D] dispatching notify.Create on "/tmp/TestRecreated357106433/001/folder"
2024/03/03 17:36:16.125288 [D] dispatching notify.Create on "/tmp/TestRecreated357106433/001/folder/file" 
2024/03/03 17:36:16.125556 [D] dispatching notify.Remove on "/tmp/TestRecreated357106433/001/folder/file" 
2024/03/03 17:36:16.125567 [D] dispatching notify.Remove on "/tmp/TestRecreated357106433/001/folder"
2024/03/03 17:36:16.125572 [D] dispatching notify.Remove on "/tmp/TestRecreated357106433/001/folder"
2024/03/03 17:36:16.125579 [D] dispatching notify.Write on "/tmp/TestRecreated357106433/001/folder/file"
2024/03/03 17:36:16.125602 [D] dispatching notify.Create on "/tmp/TestRecreated357106433/001/folder"
2024/03/03 17:36:16.226253 [D] dispatching notify.Create on "/tmp/TestRecreated357106433/001/folder/file" 
2024/03/03 17:36:16.226561 [D] dispatching notify.Remove on "/tmp/TestRecreated357106433/001/folder/file" 
2024/03/03 17:36:16.226574 [D] dispatching notify.Remove on "/tmp/TestRecreated357106433/001/folder"
2024/03/03 17:36:16.226611 [D] dispatching notify.Remove on "/tmp/TestRecreated357106433/001/folder"
2024/03/03 17:36:16.226622 [D] dispatching notify.Write on "/tmp/TestRecreated357106433/001/folder/file"
2024/03/03 17:36:16.226654 [D] dispatching notify.Create on "/tmp/TestRecreated357106433/001/folder"
2024/03/03 17:36:16.327541 [D] dispatching notify.Create on "/tmp/TestRecreated357106433/001/folder/file" 
2024/03/03 17:36:16.327564 [D] dispatching notify.Write on "/tmp/TestRecreated357106433/001/folder/file"
2024/03/03 17:36:16.327664 [D] Stop(0xc000fc4ea0) error: <nil>

... and then, some from runs where the self tests failed:

2024/03/03 17:36:53.882575 [D] dispatching notify.Rename on "/tmp/TestRenameInRoot1459564899/001/foo"                                                                                                              
2024/03/03 17:36:53.882699 [D] dispatching notify.Create on "/tmp/TestRenameInRoot1459564899/001/bar"                                                                                                              
2024/03/03 17:36:53.882726 [D] dispatching notify.Rename on "/tmp/TestRenameInRoot1459564899/001/foo"                                                                                                              
2024/03/03 17:36:53.933185 [D] dispatching notify.Create on "/tmp/TestRenameInRoot1459564899/001/bar/file"                                                                                                         
2024/03/03 17:36:53.933269 [D] Stop(0xc000905020) error: <nil>                                                                                                                                                     
2024/03/03 17:36:53.934419 [D] dispatching notify.Create on "/tmp/TestRecreated139528610/001/folder"                                                                                                               
2024/03/03 17:36:54.035003 [D] dispatching notify.Create on "/tmp/TestRecreated139528610/001/folder/file"                                                                                                          
2024/03/03 17:36:54.035314 [D] dispatching notify.Remove on "/tmp/TestRecreated139528610/001/folder/file"                                                                                                          
2024/03/03 17:36:54.035324 [D] dispatching notify.Remove on "/tmp/TestRecreated139528610/001/folder"                                                                                                               
2024/03/03 17:36:54.035333 [D] dispatching notify.Write on "/tmp/TestRecreated139528610/001/folder/file"                                                                                                           
2024/03/03 17:36:54.035348 [D] dispatching notify.Remove on "/tmp/TestRecreated139528610/001/folder"                                                                                                               
2024/03/03 17:36:54.035375 [D] dispatching notify.Create on "/tmp/TestRecreated139528610/001/folder"                                                                                                               
2024/03/03 17:36:54.136571 [D] dispatching notify.Create on "/tmp/TestRecreated139528610/001/folder/file"                                                                                                          
2024/03/03 17:36:54.136596 [D] dispatching notify.Write on "/tmp/TestRecreated139528610/001/folder/file"                                                                                                           
2024/03/03 17:36:54.137062 [D] dispatching notify.Remove on "/tmp/TestRecreated139528610/001/folder"                                                                                                               
2024/03/03 17:36:54.137140 [D] dispatching notify.Remove on "/tmp/TestRecreated139528610/001/folder"                                                                                                               
2024/03/03 17:36:54.137166 [D] dispatching notify.Remove on "/tmp/TestRecreated139528610/001/folder/file"                                                                                                          
2024/03/03 17:36:54.137219 [D] dispatching notify.Create on "/tmp/TestRecreated139528610/001/folder"                                                                                                               
2024/03/03 17:36:58.935406 [D] Stop(0xc0008f77a0) error: <nil>                                                                                                                                                     
--- FAIL: TestRecreated (5.00s)                                                                                                                                                                                    
    notify_test.go:184: ######## First ########                                                                                                                                                                    
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder notify.Create                                                                                                                                       
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder/file notify.Create                                                                                                                                  
    notify_test.go:191: ######## Second ########                                                                                                                                                                   
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder/file notify.Write                                                                                                                                   
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder/file notify.Remove                                                                                                                                  
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder notify.Remove                                                                                                                                       
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder notify.Remove                                                                                                                                       
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder notify.Create                                                                                                                                       
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder/file notify.Write                                                                                                                                   
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder/file notify.Create                                                                                                                                  
    notify_test.go:199: ######## Third ########                                                                                                                                                                    
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder notify.Create                                                                                                                                       
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder/file notify.Remove                                                                                                                                  
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder notify.Remove                                                                                                                                       
    notify_test.go:171: /tmp/TestRecreated139528610/001/folder notify.Remove                                                                                                                                       
    notify_test.go:176: timed out before receiving event                                                                                                                                                           
2024/03/03 17:36:59.135079 [D] ExpectRecordedCalls: i=0

or

2024/03/03 17:26:10.598743 [D] dispatching notify.Rename on "/tmp/TestRenameInRoot227291980/001/foo"                                                                                                               
2024/03/03 17:26:10.598840 [D] dispatching notify.Create on "/tmp/TestRenameInRoot227291980/001/bar"                                                                                                               
2024/03/03 17:26:10.598848 [D] dispatching notify.Rename on "/tmp/TestRenameInRoot227291980/001/foo"                                                                                                               
2024/03/03 17:26:10.649596 [D] dispatching notify.Create on "/tmp/TestRenameInRoot227291980/001/bar/file"                                                                                                          
2024/03/03 17:26:10.649712 [D] Stop(0xc0001c60c0) error: <nil>                                                                                                                                                     
2024/03/03 17:26:10.650461 [D] dispatching notify.Create on "/tmp/TestRecreated81199395/001/folder"                                                                                                                
2024/03/03 17:26:10.750864 [D] dispatching notify.Create on "/tmp/TestRecreated81199395/001/folder/file"                                                                                                           
2024/03/03 17:26:10.750980 [D] dispatching notify.Write on "/tmp/TestRecreated81199395/001/folder/file"                                                                                                            
2024/03/03 17:26:10.751393 [D] dispatching notify.Remove on "/tmp/TestRecreated81199395/001/folder/file"                                                                                                           
2024/03/03 17:26:10.751417 [D] dispatching notify.Create on "/tmp/TestRecreated81199395/001/folder"                                                                                                                
2024/03/03 17:26:10.751423 [D] dispatching notify.Remove on "/tmp/TestRecreated81199395/001/folder"                                                                                                                
2024/03/03 17:26:10.751434 [D] dispatching notify.Remove on "/tmp/TestRecreated81199395/001/folder"                                                                                                                
2024/03/03 17:26:10.751484 [D]  dispatch did not reach leaf: Node /tmp/TestRecreated81199395/001/folder: file does not exist                                                                                       
2024/03/03 17:26:10.852158 [D] dispatching notify.Create on "/tmp/TestRecreated81199395/001/folder/file"                                                                                                           
2024/03/03 17:26:10.852409 [D] dispatching notify.Write on "/tmp/TestRecreated81199395/001/folder/file"                                                                                                            
2024/03/03 17:26:10.852420 [D] dispatching notify.Remove on "/tmp/TestRecreated81199395/001/folder/file"                                                                                                           
2024/03/03 17:26:10.852425 [D] dispatching notify.Remove on "/tmp/TestRecreated81199395/001/folder"                                                                                                                
2024/03/03 17:26:10.852430 [D] dispatching notify.Remove on "/tmp/TestRecreated81199395/001/folder"                                                                                                                
2024/03/03 17:26:10.852436 [D] dispatching notify.Create on "/tmp/TestRecreated81199395/001/folder"                                                                                                                
2024/03/03 17:26:15.651386 [D] Stop(0xc0001c63c0) error: <nil>                                                                                                                                                     
--- FAIL: TestRecreated (5.00s)                                                                                                                                                                                    
    notify_test.go:184: ######## First ########                                                                                                                                                                    
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder notify.Create                                                                                                                                        
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder/file notify.Write                                                                                                                                    
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder/file notify.Create                                                                                                                                   
    notify_test.go:191: ######## Second ########                                                                                                                                                                   
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder notify.Remove                                                                                                                                        
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder/file notify.Remove                                                                                                                                   
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder notify.Create                                                                                                                                        
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder notify.Remove                                                                                                                                        
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder/file notify.Create                                                                                                                                   
    notify_test.go:199: ######## Third ########                                                                                                                                                                    
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder notify.Create                                                                                                                                        
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder/file notify.Write                                                                                                                                    
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder/file notify.Remove                                                                                                                                   
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder notify.Remove                                                                                                                                        
    notify_test.go:171: /tmp/TestRecreated81199395/001/folder notify.Remove                                                                                                                                        
    notify_test.go:176: timed out before receiving event

... but like I say it's not consistent. It seems to always fail within that same TestRecreated test, but not always at the same place, and sometimes it passes fine.

Let me know any other info that's useful to provide or anything else I can do.

tucari commented 1 month ago

Seeing the same, with Syncthing. Can reproduce with i.e:

Interestingly fsnotify does the same thing, with it's new recursive watcher. I'm running inotifywait in the background and it picks up all events fine.