Re: [Proposal] Updating levels for verbose logging

[Benjamin Mahler]

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  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 
> 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
>>> 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 :
>>
>> > 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 > >
>> > 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= ./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
>> > >

Re: [Proposal] Updating levels for verbose logging

[Alex Rukletsov]

Ben, I understand why you question that libprocess should log starting from
a specific level. I think it is not quite illogical for a library to use
lower priority levels. I can see this change being helpful for any user of
libprocess, not just Mesos.

On Mon, Oct 9, 2017 at 6:34 PM, Benjamin Mahler  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 
> 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
> > fa6ffdfcd22136c171b43aed2e7949
> > a07fd263d7>
> > 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 :
> >
> > > 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= ./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? 

Re: [Proposal] Updating levels for verbose logging

[Armand Grillet]

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
   

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 :

> 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 
> 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= ./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

Re: [Proposal] Updating levels for verbose logging

[Benjamin Mahler]

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 
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= ./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
>

Re: [Proposal] Updating levels for verbose logging

[Alex Rukletsov]

I support the effort, Armand.

On Wed, Oct 4, 2017 at 3:59 PM, Armand Grillet 
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= ./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
>

[Proposal] Updating levels for verbose logging

[Armand Grillet]

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= ./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