To elaborate on this, ideally libprocess logging is configurable by the user in a flexible manner that gives them control.
For example, in LevelDB you can pass in the info 'Logger' that it will use for logging: https://github.com/google/leveldb/blob/v1.20/include/leveldb/options.h#L64-L68 I'm not sure what the best approach is here for us, but you can imagine passing in the error, warning, info 'Logger's that libprocess should use. Maybe also a verbose offset for info level logging. What I've usually seen is that we want the libprocess warnings and errors in the logs from the mesos perspective, the libprocess info logging usually only for debugging, and the libprocess verbose logging definitely only for debugging. On Mon, Oct 9, 2017 at 3:34 PM, Benjamin Mahler <bmah...@apache.org> wrote: > 2. Changing the libprocess verbose logs to start at level 3. Not just >> due to an ordering between Mesos and libprocess logs, but also because >> libprocess is a low-level library. > > > 2. is the part that is concerning. It seems arbitrary to me to have > libprocess start at a particular level since it's a library. Can you make > it a configuration option as I mentioned earlier? > > The /logging integration for per-module logging sounds great! > > On Mon, Oct 9, 2017 at 11:02 AM, Armand Grillet <agril...@mesosphere.io> > wrote: > >> Thanks for your input Benjamin. After having looked at per-module verbose >> level, here are the changes I would like to apply: >> >> 1. Changing the Mesos common events verbose logs so that they use >> VLOG(2) instead of 1. The original commit >> https://github.com/apache/meso >> s/commit/fa6ffdfcd22136c171b43aed2e7949a07fd263d7 >> <https://github.com/apache/mesos/commit/fa6ffdfcd22136c171b >> 43aed2e7949a07fd263d7> >> that >> started using VLOG(1) for the allocator does not state why this level >> was >> chosen and the periodic messages such as "No allocations performed" >> should >> be displayed at a higher level to simplify debugging. >> 2. Changing the libprocess verbose logs to start at level 3. Not just >> due to an ordering between Mesos and libprocess logs, but also because >> libprocess is a low-level library. >> 3. Adding support for the GLOG vmodule flag and add it as an option in >> /toggle/logging (as suggested in https://issues.apache.org/j >> ira/browse/MESOS-5784). However, this would not allow us to have a >> per-component logging verbosity control that should be added >> afterwards. >> >> >> 2017-10-07 1:47 GMT+02:00 Benjamin Mahler <bmah...@apache.org>: >> >> > It seems unfortunate to establish an ordering between different >> component's >> > verbosity levels, how is libprocess to know which level to start at? I >> > suppose you can tell it, but it's not clear that the first level of >> > verbosity in libprocess should come after the max level of verbosity in >> > mesos. >> > >> > This seems to surface a need for per-module logging verbosity control. >> Have >> > you looked into the '--vmodule' flag? >> > >> > On Wed, Oct 4, 2017 at 12:59 PM, Armand Grillet <agril...@mesosphere.io >> > >> > wrote: >> > >> > > Hi all, >> > > >> > > We currently use three levels of verbose logging via the VLOG macro. I >> > > propose to add two levels and change how we use the current ones to >> make >> > > debugging easier for Mesos developers. >> > > >> > > The current situation is: >> > > >> > > - VLOG(1) is used for Mesos and libprocess events such as the >> > > admission of an agent by a master. It is also used for a few Mesos >> > > common >> > > events, e.g. the allocation of resources on an agent. >> > > - VLOG(2) is used for Mesos and libprocess common events, e.g. the >> > > reception of an offer by a Mesos scheduler. >> > > - VLOG(3) is used when a Mesos scheduler process saves the PID >> > > associated with each slave and for libprocess events related to >> > timers, >> > > clocks, and waiter processes. >> > > >> > > As an example, running GLOG_v=<level> ./mesos-tests --gtest_filter=" >> > > OversubscriptionTest.UpdateAllocatorOnSchedulerFailover" --verbose >> > > returns: >> > > >> > > - 212 lines of logs with level = 1. >> > > - 695 lines of logs with level = 2. >> > > - 782 lines of logs with level = 3. >> > > >> > > The logs at level 2 are quite noisy. This is mainly due to the number >> of >> > > messages regarding libprocess recurring events such as process >> > resumptions: >> > > https://github.com/apache/mesos/blob/d863620e5cb82b7f22cade0da0a0d1 >> > > 8afbdf9136/3rdparty/libprocess/src/process.cpp#L3245 >> > > >> > > To improve the situation, I suggest having five levels: >> > > >> > > - VLOG(1), used for Mesos events. >> > > - VLOG(2), used for Mesos common/recurring events. >> > > - VLOG(3), used for libprocess events. >> > > - VLOG(4), used for libprocess common/recurring events. >> > > - VLOG(5), used for libprocess events related to timers, clocks, >> and >> > > waiter processes. >> > > >> > > This change would allow us to read the Mesos verbose logs without >> having >> > to >> > > see the ones concerning libprocess, a use case that seems reasonable >> for >> > > Mesos developers. The new log levels would make it possible to have >> the >> > > same logs as before when necessary. >> > > >> > > What do you think about this? Please feel free to share your thoughts >> and >> > > comments. >> > > >> > > -- >> > > Armand Grillet >> > > Software Engineer, Mesosphere >> > > >> > >> >> >> >> -- >> Armand Grillet >> Software Engineer, Mesosphere >> > >
