logging improvements
Closed this issue · 7 comments
domsj commented
- log "writing to fd" less frequently (summary at the end like "reading from fd in steps"
- display a bit more context ... which fd is it, what is it used for
- we also see plenty of "reading from fd in steps" messages (although not as much as writing to fd) - how useful are these really? can we display a summary once each minute?
dejonghb commented
The "writing to fd" is logged as info; for example:
Mar 30 11:15:28 ftcmp04 alba[32596]: 2017-03-30 11:15:28 199845 +0200 - ftcmp04 - 32596/0 - alba/proxy - 372114 - info - writing to fd: written 1309660, requested 3543283
Mar 30 11:15:28 ftcmp04 alba[32596]: 2017-03-30 11:15:28 201589 +0200 - ftcmp04 - 32596/0 - alba/proxy - 372115 - info - writing to fd: written 4184720, requested 8389025
Mar 30 11:15:28 ftcmp04 alba[32596]: 2017-03-30 11:15:28 203686 +0200 - ftcmp04 - 32596/0 - alba/proxy - 372116 - info - writing to fd: written 4184720, requested 8389025
Mar 30 11:15:28 ftcmp04 alba[32596]: 2017-03-30 11:15:28 204231 +0200 - ftcmp04 - 32596/0 - alba/proxy - 372117 - info - writing to fd: written 2215440, requested 4204305
Mar 30 11:15:28 ftcmp04 alba[32596]: 2017-03-30 11:15:28 205785 +0200 - ftcmp04 - 32596/0 - alba/proxy - 372118 - info - writing to fd: written 4170240, requested 4204305
Mar 30 11:15:28 ftcmp04 alba[32596]: 2017-03-30 11:15:28 207203 +0200 - ftcmp04 - 32596/0 - alba/proxy - 372119 - info - writing to fd: written 4170240, requested 4204305
whilst "reading" is logged as warning; for example:
Mar 30 11:13:23 ftcmp03 alba[11130]: 2017-03-30 11:13:23 61860 +0200 - ftcmp03 - 11130/0 - alba/asd - 43343 - warning - reading from fd: 8384979B in 183 steps
Mar 30 11:13:23 ftcmp03 alba[11130]: 2017-03-30 11:13:23 217060 +0200 - ftcmp03 - 11130/0 - alba/asd - 43344 - warning - reading from fd: 439014B in 9 steps
Mar 30 11:13:23 ftcmp03 alba[11130]: 2017-03-30 11:13:23 587739 +0200 - ftcmp03 - 11130/0 - alba/asd - 43345 - warning - reading from fd: 8376634B in 239 steps
Mar 30 11:13:24 ftcmp03 alba[11130]: 2017-03-30 11:13:24 820576 +0200 - ftcmp03 - 11130/0 - alba/asd - 43346 - warning - reading from fd: 8384976B in 249 steps
Mar 30 11:13:25 ftcmp03 alba[11130]: 2017-03-30 11:13:25 113359 +0200 - ftcmp03 - 11130/0 - alba/asd - 43347 - warning - reading from fd: 3029361B in 80 steps
Mar 30 11:13:25 ftcmp03 alba[11130]: 2017-03-30 11:13:25 838376 +0200 - ftcmp03 - 11130/0 - alba/asd - 43348 - warning - reading from fd: 8374520B in 188 steps
Currently not much else gets logged; but (at least for me) it's unclear what to look at to get rid of it...
dejonghb commented
When logging the fd value as well, it's possible to get a more detailed view as to where a problem might be located via /proc/<pid>/<fd> (and the contents of /proc/net/tcp file in case of sockets) .
domsj commented
on connect/disconnnect/open/close we should also log the fd
dejonghb commented
Afaik not all of
on connect/disconnnect/open/close we should also log the fd
are covered currently
domsj commented
I don't see anything left to do here, so closing