getappmap / appmap-js

Client libraries for AppMap
48 stars 17 forks source link

FSWatcher fails in an unrecoverable way #881

Closed dustinbyrne closed 1 year ago

dustinbyrne commented 1 year ago

There are three different observed cases in which this happens. This will ultimately result in the indexer exiting with code 1.

Error: UNKNOWN: unknown error, lstat 'c:\Users\User\Dev\MyProject'
Emitted 'error' event on FSWatcher instance at:
at FSWatcher._handleError (c:\Users\User\AppData\Roaming\Code\User\globalStorage\appland.appmap\node_modules\chokidar\index.js:647:10)
at NodeFsHandler._boundHandleError (c:\Users\User\AppData\Roaming\Code\User\globalStorage\appland.appmap\node_modules\chokidar\lib\nodefs-handler.js:303:43)
at ReaddirpStream.emit (node:events:526:28)
at emitErrorNT (node:internal/streams/destroy:157:8)
at emitErrorCloseNT (node:internal/streams/destroy:122:3)
at process.processTicksAndRejections (node:internal/process/task_queues:83:21) {
errno: -4094,
code: 'UNKNOWN',
syscall: 'lstat',
path: 'c:\\Users\\User\\Dev\\MyProject'
}
Error: EMFILE: too many open files, watch '.'
at FSWatcher.<computed> (node:internal/fs/watchers:244:19)
at Object.watch (node:fs:2251:34)
at createFsWatchInstance (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:119:15)
at setFsWatchListener (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:166:15)
at NodeFsHandler._watchWithNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:331:14)
at NodeFsHandler._handleDir (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:567:19)
at NodeFsHandler._addToNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:617:27)
at process.processTicksAndRejections (node:internal/process/task_queues:96:5)
at async /home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/index.js:451:21
at async Promise.all (index 0)
Emitted 'error' event on FSWatcher instance at:
at FSWatcher._handleError (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/index.js:647:10)
at NodeFsHandler._addToNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:645:18)
at process.processTicksAndRejections (node:internal/process/task_queues:96:5)
at async /home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/index.js:451:21
at async Promise.all (index 0) {
errno: -24,
syscall: 'watch',
code: 'EMFILE',
path: '.',
filename: '.'
}
Error: ENOSPC: System limit for number of file watchers reached, watch 'venv/lib/python3.10/site-packages/plotly/validators/isosurface/lighting/__pycache__'
at FSWatcher.<computed> (node:internal/fs/watchers:244:19)
at Object.watch (node:fs:2251:34)
at createFsWatchInstance (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:119:15)
at setFsWatchListener (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:166:15)
at NodeFsHandler._watchWithNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:331:14)
at NodeFsHandler._handleDir (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:567:19)
at process.processTicksAndRejections (node:internal/process/task_queues:96:5)
at async NodeFsHandler._addToNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:617:16)
Emitted 'error' event on FSWatcher instance at:
at FSWatcher._handleError (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/index.js:647:10)
at NodeFsHandler._addToNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:645:18)
at process.processTicksAndRejections (node:internal/process/task_queues:96:5) {
errno: -28,
syscall: 'watch',
code: 'ENOSPC',
path: 'venv/lib/python3.10/site-packages/plotly/validators/isosurface/lighting/__pycache__',
filename: 'venv/lib/python3.10/site-packages/plotly/validators/isosurface/lighting/__pycache__'
}
kgilpin commented 1 year ago

Error: EMFILE: too many open files, watch '.'

This is why we want to watch $appmap_dir and not '.'

On Fri, Dec 2, 2022 at 12:30 PM Dustin Byrne @.***> wrote:

There are three different observed cases in which this happens. This will ultimately result in the indexer exiting with code 1.

Error: UNKNOWN: unknown error, lstat 'c:\Users\User\Dev\MyProject' Emitted 'error' event on FSWatcher instance at: at FSWatcher._handleError (c:\Users\User\AppData\Roaming\Code\User\globalStorage\appland.appmap\node_modules\chokidar\index.js:647:10) at NodeFsHandler._boundHandleError (c:\Users\User\AppData\Roaming\Code\User\globalStorage\appland.appmap\node_modules\chokidar\lib\nodefs-handler.js:303:43) at ReaddirpStream.emit (node:events:526:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at process.processTicksAndRejections (node:internal/process/task_queues:83:21) { errno: -4094, code: 'UNKNOWN', syscall: 'lstat', path: 'c:\Users\User\Dev\MyProject' }

Error: EMFILE: too many open files, watch '.' at FSWatcher. (node:internal/fs/watchers:244:19) at Object.watch (node:fs:2251:34) at createFsWatchInstance (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:119:15) at setFsWatchListener (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:166:15) at NodeFsHandler._watchWithNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:331:14) at NodeFsHandler._handleDir (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:567:19) at NodeFsHandler._addToNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:617:27) at process.processTicksAndRejections (node:internal/process/task_queues:96:5) at async /home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/index.js:451:21 at async Promise.all (index 0) Emitted 'error' event on FSWatcher instance at: at FSWatcher._handleError (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/index.js:647:10) at NodeFsHandler._addToNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:645:18) at process.processTicksAndRejections (node:internal/process/task_queues:96:5) at async /home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/index.js:451:21 at async Promise.all (index 0) { errno: -24, syscall: 'watch', code: 'EMFILE', path: '.', filename: '.' }

Error: ENOSPC: System limit for number of file watchers reached, watch 'venv/lib/python3.10/site-packages/plotly/validators/isosurface/lighting/pycache' at FSWatcher. (node:internal/fs/watchers:244:19) at Object.watch (node:fs:2251:34) at createFsWatchInstance (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:119:15) at setFsWatchListener (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:166:15) at NodeFsHandler._watchWithNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:331:14) at NodeFsHandler._handleDir (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:567:19) at process.processTicksAndRejections (node:internal/process/task_queues:96:5) at async NodeFsHandler._addToNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:617:16) Emitted 'error' event on FSWatcher instance at: at FSWatcher._handleError (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/index.js:647:10) at NodeFsHandler._addToNodeFs (/home/user/.config/Code/User/globalStorage/appland.appmap/node_modules/chokidar/lib/nodefs-handler.js:645:18) at process.processTicksAndRejections (node:internal/process/task_queues:96:5) { errno: -28, syscall: 'watch', code: 'ENOSPC', path: 'venv/lib/python3.10/site-packages/plotly/validators/isosurface/lighting/pycache', filename: 'venv/lib/python3.10/site-packages/plotly/validators/isosurface/lighting/pycache' }

— Reply to this email directly, view it on GitHub https://github.com/getappmap/appmap-js/issues/881, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAAVC647OZ62623X3CWQJ4DWLIW2BANCNFSM6AAAAAASSEMQKI . You are receiving this because you are subscribed to this thread.Message ID: @.***>

symwell commented 1 year ago

Reproduced the ENOSPC error

~/src/appmap-js/packages/cli$ yarn start index --watch --appmap-dir ~/tmp/too_many_open_files
Error: ENOSPC: System limit for number of file watchers reached, watch '/home/test/tmp/too_many_open_files/requests1/1670337180_4783964_http_www_example_com.appmap.json'
    at FSWatcher.<computed> (node:internal/fs/watchers:244:19)
    at Object.watch (node:fs:2315:34)
    at createFsWatchInstance (/home/test/src/appmap-js/node_modules/chokidar/lib/nodefs-handler.js:119:15)
    at setFsWatchListener (/home/test/src/appmap-js/node_modules/chokidar/lib/nodefs-handler.js:166:15)
    at NodeFsHandler._watchWithNodeFs (/home/test/src/appmap-js/node_modules/chokidar/lib/nodefs-handler.js:331:14)
    at NodeFsHandler._handleFile (/home/test/src/appmap-js/node_modules/chokidar/lib/nodefs-handler.js:395:23)
    at NodeFsHandler._addToNodeFs (/home/test/src/appmap-js/node_modules/chokidar/lib/nodefs-handler.js:637:21) {
  errno: -28,
  syscall: 'watch',
  code: 'ENOSPC',
  path: '/home/test/tmp/too_many_open_files/requests1/1670337180_4783964_http_www_example_com.appmap.json',
  filename: '/home/test/tmp/too_many_open_files/requests1/1670337180_4783964_http_www_example_com.appmap.json'
}

To reproduce it I created the following directory structure

~/tmp/too_many_open_files$ ls -1
minitest
requests
requests1
requests2
requests3

by creating appmaps and indexing them

~/src/sample_app_6th_ed$ APPMAP=true DISABLE_SPRING=true bundle exec rails test
~/src/appmap-js/packages/cli$ yarn start index --watch --appmap-dir ~/src/sample_app_6th_ed/tmp/appmap

and then making a few copies of the requests directory, which is a big directory (1.4G).

~/tmp/too_many_open_files$ cp -Rp requests requests1
~/tmp/too_many_open_files$ cp -Rp requests requests2
~/tmp/too_many_open_files$ cp -Rp requests requests3

There were 80000 files in the queue while the limit of open files in the OS was 1024. On Darwin the limit is 256.

num in pending 80646
num in queue   80645

# Ubuntu 20
$ ulimit -a | grep 'open files'
open files                      (-n) 1024

# Darwin
$ ulimit -a  | grep 'file descriptors'
-n: file descriptors                256

I was able to increase the limit to 1048576 on Ubuntu 20 as an unprivileged user. It gave the same error until I also increased max_user_watches as root.

$ ulimit -n 1048576
$ ulimit -a | grep -i 'open files'
open files                      (-n) 1048576

# cat /proc/sys/fs/inotify/max_user_watches
65536
# echo 131072 > /proc/sys/fs/inotify/max_user_watches
# cat /proc/sys/fs/inotify/max_user_watches
131072

It's max_user_watches that is the limit that causes the ENOSPC error, not the number of file descriptors.

On Darwin the file descriptor limit is

$ sysctl -a | grep 'kern.maxfiles' 
kern.maxfiles: 245760
kern.maxfilesperproc: 122880

$ sysctl -a | grep 'kern.num_files' 
kern.num_files: 7506

# In another Darwin
$ sysctl -a | grep 'kern.maxfiles' 
kern.maxfiles: 122880
kern.maxfilesperproc: 61440

$ sysctl -a | grep 'kern.num_files' 
kern.num_files: 7206

Summary

Error: ENOSPC: System limit for number of file watchers reached occurs from a limit in the kernel. This limit can't be changed without root privileges.

EMFILE: too many open files probably (didn't verify; tried but didn't reproduce) occurs from the limit of file descriptors per user. This limit can be increased by the indexer when the indexer starts

symwell commented 1 year ago

Closing, since it was archived.