Debug logging enabled by default since 2.2

[Alexander Dejanovski <al...@thelastpickle.com>]

Hi folks,

we've been upgrading clusters from 2.0 to 2.2 recently and we've noticed
that debug logging was causing serious performance issues in some cases,
specifically because of its use in the query pager.

I've opened a ticket with some benchmarks and flame graphs :
https://issues.apache.org/jira/browse/CASSANDRA-14318

The problem should be less serious in the read path with Cassandra 3.0 and
above as the query pager code has been reworked and doesn't log at debug
level.
I think that debug logging shouldn't be turned on by default though, since
we see it doesn't come for free and that it lowers read performance in 2.2.

Was there any specific reason why it was enabled by default in 2.2 ?

Is anyone opposed to disabling debug logging by default in all branches ?

-- 
-----------------
Alexander Dejanovski
France
@alexanderdeja

Consultant
Apache Cassandra Consulting
http://www.thelastpickle.com

Re: Debug logging enabled by default since 2.2

[Mick Semb Wever <mi...@thelastpickle.com>]

> For this reason I'm more in favor of converting the debug.log into
async/verbose_system.log as suggested by Jeremiah and use a marker to
direct these logs (former DEBUG level logs) to that log instead.


+1

Thanks for the inclusive and considerate summary Paulo, and for the
suggestion that moves us forward Jeremiah.


> From the discussion here it seems that many would like to change how this
works.  Rather
than just turning off the debug.log I would propose that we switch to using
the SLF4J
MARKER[1] ability to move the messages back to INFO but tag them as
belonging to
the asynchronous_system.log rather than the normal system.log.


>  In a way the real issue might be that we don’t have nightly performance
runs that would make an accidentally introduced debug statement obvious.
> A log statement that runs once or more per read or write should be easy
to spot.


+1
Could we not put in an assertion into the dtests that fails if any
query-path DEBUG statements appear?
This would enforce the Logging Guidelines.

And those Logging Guidelines should be moved to the in-tree docs.

Mick


On 20 March 2018 at 05:51, Paulo Motta <pa...@gmail.com> wrote:

> Thanks for the constructive input and feedback! From this discussion
> it seems like overloading the DEBUG level to signify
> async-verbose-INFO on CASSANDRA-10241 is leading to some confusion and
> we should fix this.
>
> However, we cannot simply turn debug.log off as during CASSANDRA-10241
> some verbose-but-useful-info-logs, such as flush information were
> changed from INFO to DEBUG, and since the patch has been in for nearly
> 3 years it's probably non-revertable. Furthermore, the practice of
> using the DEBUG level for logging non-debug stuff has been in our
> Logging Guidelines
> (https://wiki.apache.org/cassandra/LoggingGuidelines) since then, so
> there is probably useful DEBUG stuff that would need to be turned into
> INFO if we get rid of debug.log.
>
> For this reason I'm more in favor of converting the debug.log into
> async/verbose_system.log as suggested by Jeremiah and use a marker to
> direct these logs (former DEBUG level logs) to that log instead.
> Nevertheless, if the majority prefers to get back to a single
> system.log file and get rid of debug.log/verbose_system.log altogether
> then we would need to go through all log usages and readjust them to
> use the proper logging levels and update our logging guidelines to
> reflect whatever new policy is decided, not only disabling debug.log
> and call it a day.
>
> 2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <je...@datastax.com>:
> > People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
> > to clean up the system.log so that it a very high “signal” in terms of
> what was logged
> > to it synchronously, but without reducing the ability of the logs to
> allow people to
> > solve problems and perform post mortem analysis of issues.  We have
> informational
> > log messages that are very useful to understanding the state of things,
> like compaction
> > status, repair status, flushing, or the state of gossip in the system
> that are very useful to
> > operators, but if they are all in the system.log make said log file
> harder to look over for
> > issues.  In 10241 the method chosen for how to keep these log messages
> around by
> > default, but get them out of the system.log was that these messages were
> changed from
> > INFO to DEBUG and the new debug.log was created.
> >
> > From the discussion here it seems that many would like to change how
> this works.  Rather
> > than just turning off the debug.log I would propose that we switch to
> using the SLF4J
> > MARKER[1] ability to move the messages back to INFO but tag them as
> belonging to
> > the asynchronous_system.log rather than the normal system.log.
> >
> > [1] https://logback.qos.ch/manual/layouts.html#marker <
> https://logback.qos.ch/manual/layouts.html#marker>
> > https://www.slf4j.org/faq.html#fatal <https://www.slf4j.org/faq.
> html#fatal>
> >
> >
> >> On Mar 19, 2018, at 9:01 AM, Stefan Podkowinski <sp...@apache.org>
> wrote:
> >>
> >> I'd agree that INFO should be the default. Turning on the DEBUG logging
> >> can cause notable performance issues and I would not enable it on
> >> production systems unless I really have to. That's why I created
> >> CASSANDRA-12696 for 4.0, so you'll be able to at least only partially
> >> enable DEBUG based on what's relevant to look at, e.g. `nodetool
> >> setlogginglevel bootstrap DEBUG`.
> >>
> >> But small improvements like that won't change the fact that log files
> >> suck in general for more complex analysis, except for trivial tailing
> >> and grepping. You have to make sure that logging is enabled and old
> >> records you're interested in will not be rotated out. Then you have to
> >> gather log files from individual nodes somehow. Eventually I end up with
> >> a local tarball with logs in that situation and the fun starts creating
> >> hacky, regex loaded Python scripts to parse them. As each log message is
> >> limited to a single line of text, it's often missing out relevant
> >> details. You also got to create different parsers for different messages
> >> of course. It's just inefficient and too time consuming to gather
> >> information that way. Let alone implementing more advanced monitoring
> >> solutions on top of that.
> >>
> >> That's exactly why I started working on the "diagnostic events"
> >> (CASSANDRA-12944) idea more than a year ago. There's also support for
> >> persistency (CASSANDRA-13460) that would implement storing important but
> >> infrequent events as rich json objects in a local keyspace and allows
> >> retrieving them by using CQL. I still like the idea and think it's worth
> >> pursuing.
> >>
> >>
> >> On 19.03.18 09:53, Alain RODRIGUEZ wrote:
> >>> Hello,
> >>>
> >>> I am not developing Cassandra, but I am using it actively and helping
> >>> people to work with it. My perspective might be missing some code
> >>> considerations and history as I did not go through the ticket where
> this
> >>> 'debug' level was added by default. But here is a feedback after
> upgrading
> >>> a few clusters to Cassandra 2.2:
> >>>
> >>> When upgrading a cluster to Cassandra 2.2, 'disable the debug logs' is
> in
> >>> my runbook. I mean, very often, when some cluster is upgraded to
> Cassandra
> >>> 2.2 and has problems with performances, the 2 most frequent issues are:
> >>>
> >>> - DEBUG level being turned on
> >>> - and / or dynamic snitching being enabled
> >>>
> >>> This is especially true for high percentile (very clear on p99). Let's
> put
> >>> the dynamic snitch aside as it is not our topic here.
> >>>
> >>> From an operational perspective, I prefer to set the debug level to
> 'DEBUG'
> >>> when I need it than having, out of the box, something that is
> unexpected
> >>> and impact performances. Plus the debug level can be changed without
> >>> restarting the node, through 'JMX' or even using 'nodetool' now.
> >>>
> >>> Also in most cases, the 'INFO' level is good enough for me to detect
> most
> >>> of the issues. I was even able to recreate a detailed history of
> events for
> >>> a customer recently, 'INFO' logs are already very powerful and
> complete I
> >>> believe (nice work on this by the way). Then monitoring is helping a
> lot
> >>> too. I did not have to use debug logs for a long time. It might
> happen, but
> >>> I will find my way to enable them.
> >>>
> >>> Even though it feels great to be able to help people with that easily
> >>> because the cause is often the same and turning off the logs is a
> >>> low hanging fruit in C*2.2 clusters that have very nice results and is
> easy
> >>> to achieve, I would prefer people not to fall into these performances
> traps
> >>> in the first place. In my head, 'Debug' logs should be for debug
> purposes
> >>> (by opposition to 'always on'). It seems legit. I am surprised this
> brings
> >>> so many discussions I thought this was a common standard widely
> accepted,
> >>> and beyond Cassandra. That being said, it is good to see those
> exchanges
> >>> are happening, so the decision that will be taken will be a good one,
> I am
> >>> sure. I hope this comment will help, I have no other goal, for sure I
> am
> >>> not willing to feed a conflict but a talk and I hope no one felt
> offended
> >>> by this feedback. I believe this change was made aiming at
> >>> helping/improving things, but it turns out it is more of an annoyance
> than
> >>> truly helpful (my personal perspective).
> >>>
> >>> I would +1 on making 'INFO' default again, but if someone is missing
> >>> information that should be in 'INFO'. If some informations are missing
> at
> >>> the 'INFO' level, why not add informations that should be at the 'INFO'
> >>> level there directly and keep log levels meaningful? Making sure we do
> not
> >>> bring the logs degrading performances from 'Debug' to 'Info' as much
> as we
> >>> can.
> >>>
> >>> Hope this is useful,
> >>>
> >>> C*heers,
> >>>
> >>> -----------------------
> >>> Alain Rodriguez - @arodream - alain@thelastpickle.com
> >>> France / Spain
> >>>
> >>> The Last Pickle - Apache Cassandra Consulting
> >>> http://www.thelastpickle.com
> >>>
> >>> 2018-03-19 2:18 GMT+00:00 kurt greaves <ku...@instaclustr.com>:
> >>>
> >>>> On the same page as Michael here. We disable debug logs in production
> due
> >>>> to the performance impact. Personally I think if debug logging is
> necessary
> >>>> for users to use the software we're doing something wrong. Also in my
> >>>> experience, if something doesn't reproduce it will not get fixed.
> Debug
> >>>> logging helps, but I've never seen a case where an actual bug simply
> >>>> *doesn't* reproduce eventually, and I'm sure if this issue appears
> debug
> >>>> logging could be enabled after the fact for the relevant classes and
> >>>> eventually it will reoccur and we could solve the problem. I've never
> seen
> >>>> a user say no to helping debug a problem with patched jars/changes to
> their
> >>>> system (like logging). I'd much prefer we pushed that harder rather
> than
> >>>> just saying "Everyone gets debug logging!". I'm also really not sold
> that
> >>>> debug logging saves the day. To me it mostly just speeds up the
> >>>> identification process, it generally doesn't expose magical
> information
> >>>> that wasn't available before, you just had to think about it a bit
> more.
> >>>>
> >>>>
> >>>> In a way the real issue might be that we don’t have nightly
> performance
> >>>>> runs that would make an accidentally introduced debug statement
> obvious.
> >>>> This is an issue, but I don't think it's the *real* issue. As already
> >>>> noted, debug logging is for debugging, which normal users shouldn't
> have to
> >>>> think about when they are just operating the software. We shouldn't
> risk
> >>>> performance regressions just for developer convenience.
> >>>>
> >>>> On 19 March 2018 at 00:55, Ariel Weisberg <ad...@fastmail.fm>
> wrote:
> >>>>
> >>>>> Hi,
> >>>>>
> >>>>> In a way the real issue might be that we don’t have nightly
> performance
> >>>>> runs that would make an accidentally introduced debug statement
> obvious.
> >>>>>
> >>>>> A log statement that runs once or more per read or write should be
> easy
> >>>> to
> >>>>> spot. I haven’t measured the impact though. And as a bonus by having
> this
> >>>>> we can spot a variety of performance issues introduced by all kinds
> of
> >>>>> changes.
> >>>>>
> >>>>> Ariel
> >>>>>
> >>>>>> On Mar 18, 2018, at 3:46 PM, Jeff Jirsa <jj...@gmail.com> wrote:
> >>>>>>
> >>>>>> In Cassandra-10241 I said I was torn on this whole ticket, since
> most
> >>>>> people would end up turning it off if it had a negative impact. You
> said:
> >>>>>> “I'd like to emphasize that we're not talking about turning debug or
> >>>>> trace on for client-generated request paths. There's way too much
> data
> >>>>> generated and it's unlikely to be useful.
> >>>>>> What we're proposing is enabling debug logging ONLY for cluster
> state
> >>>>> changes like gossip and schema, and infrequent activities like
> repair. “
> >>>>>> Clearly there’s a disconnect here - we’ve turned debug logging on
> for
> >>>>> everything and shuffled some stuff to trace, which is a one time
> action
> >>>> but
> >>>>> is hard to protect against regression. In fact, just looking at the
> read
> >>>>> callback shows two instances of debug log in the client request path
> >>>>> (exercise for the reader to “git blame”).
> >>>>>> Either we can go clean up all the surprises that leaked through, or
> we
> >>>>> can turn off debug and start backing out some of the changes in
> 10241.
> >>>>> Putting stuff like compaction in the same bucket as digest mismatch
> and
> >>>>> gossip state doesn’t make life materially better for most people.
> >>>>>> --
> >>>>>> Jeff Jirsa
> >>>>>>
> >>>>>>
> >>>>>>> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com>
> >>>> wrote:
> >>>>>>> That really depends on whether you're judicious in deciding what to
> >>>> log
> >>>>> at
> >>>>>>> debug, doesn't it?
> >>>>>>>
> >>>>>>> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <
> >>>> kjellman@apple.com>
> >>>>>>> wrote:
> >>>>>>>
> >>>>>>>> +1. this is how it works.
> >>>>>>>>
> >>>>>>>> your computer doesn’t run at debug logging by default. your phone
> >>>>> doesn’t
> >>>>>>>> either. neither does your smart tv. your database can’t be
> running at
> >>>>> debug
> >>>>>>>> just because it makes our lives as engineers easier.
> >>>>>>>>
> >>>>>>>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
> >>>>>>>> alex@thelastpickle.com> wrote:
> >>>>>>>>> It's a tiny bit unusual to turn on debug logging for all users by
> >>>>> default
> >>>>>>>>> though, and there should be occasions to turn it on when facing
> >>>> issues
> >>>>>>>> that
> >>>>>>>>> you want to debug (if they can be easily reproduced).
> >>>>>>>
> >>>>>>> --
> >>>>>>> Jonathan Ellis
> >>>>>>> co-founder, http://www.datastax.com
> >>>>>>> @spyced
> >>>>> ------------------------------------------------------------
> ---------
> >>>>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> >>>>> For additional commands, e-mail: dev-help@cassandra.apache.org
> >>>>>
> >>>>>
> >>
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> >> For additional commands, e-mail: dev-help@cassandra.apache.org
> >>
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
>
>


-- 
Mick Semb Wever
Australia

The Last Pickle
Apache Cassandra Consulting
http://www.thelastpickle.com

Re: Debug logging enabled by default since 2.2

["J. D. Jordan" <je...@gmail.com>]

Ariel can we move discussion to the ticket now that we have one open?  That way we can keep all thoughts in one place. Thanks.
https://issues.apache.org/jira/browse/CASSANDRA-14326


> On Mar 20, 2018, at 12:42 PM, Ariel Weisberg <ar...@weisberg.ws> wrote:
> 
> Hi,
> 
> That's good to hear.
> 
> What's the difference between DEBUG and TRACE? Obviously we decide ourselves. I don't have a good answer because right now we are in the process of eliminating the distinction we used to make which is that DEBUG is safe to turn on in production and TRACE is not.
> 
> Ariel
> 
>> On Tue, Mar 20, 2018, at 12:36 PM, Alexander Dejanovski wrote:
>> Ariel,
>> 
>> the current plan that's discussed on the ticket (
>> https://issues.apache.org/jira/browse/CASSANDRA-14326) is to maintain the
>> separation and keep the debug.log for "real" DEBUG level logging, which
>> would be disabled by default.
>> A new intermediate marker would be created to have VERBOSE_INFO logging
>> (some current debug loggings must be changed to that new level/marker),
>> which would be enabled by default, and "standard" INFO logging would go to
>> system.log.
>> 
>> I guess in that configuration, some/most TRACE level loggings would then be
>> eligible to graduate to DEBUG...?
>> 
>> 
>> 
>> 
>>> On Tue, Mar 20, 2018 at 4:19 PM Ariel Weisberg <ar...@weisberg.ws> wrote:
>>> 
>>> Hi,
>>> 
>>> Signal to noise ratio matters for logs. Things that we log at DEBUG aren't
>>> at all bound by constraints of human readability or being particularly
>>> relevant most of the time. I don't want to see most of this stuff unless I
>>> have already not found what I am looking for at INFO and above.
>>> 
>>> Can we at least maintain the separation of what is effectively debug
>>> logging (switching to an annotation aside) from INFO and above? I want to
>>> avoid two steps forward one step back.
>>> 
>>> Ariel
>>>> On Tue, Mar 20, 2018, at 9:23 AM, Paulo Motta wrote:
>>>> That sounds like a good plan, Alexander! Thanks!
>>>> 
>>>> Stefan, someone needs to go through all messages being logged at DEBUG
>>>> and reclassify important ones as INFO. I suggest continuing discussion
>>>> on specifics on CASSANDRA-14326.
>>>> 
>>>> 2018-03-20 6:46 GMT-03:00 Stefan Podkowinski <sp...@apache.org>:
>>>>> Are you suggesting to move all messages currently logged via debug() to
>>>>> info() with the additional marker set, or only particular messages?
>>>>> 
>>>>> 
>>>>>> On 19.03.2018 19:51, Paulo Motta wrote:
>>>>>> Thanks for the constructive input and feedback! From this discussion
>>>>>> it seems like overloading the DEBUG level to signify
>>>>>> async-verbose-INFO on CASSANDRA-10241 is leading to some confusion and
>>>>>> we should fix this.
>>>>>> 
>>>>>> However, we cannot simply turn debug.log off as during CASSANDRA-10241
>>>>>> some verbose-but-useful-info-logs, such as flush information were
>>>>>> changed from INFO to DEBUG, and since the patch has been in for nearly
>>>>>> 3 years it's probably non-revertable. Furthermore, the practice of
>>>>>> using the DEBUG level for logging non-debug stuff has been in our
>>>>>> Logging Guidelines
>>>>>> (https://wiki.apache.org/cassandra/LoggingGuidelines) since then, so
>>>>>> there is probably useful DEBUG stuff that would need to be turned into
>>>>>> INFO if we get rid of debug.log.
>>>>>> 
>>>>>> For this reason I'm more in favor of converting the debug.log into
>>>>>> async/verbose_system.log as suggested by Jeremiah and use a marker to
>>>>>> direct these logs (former DEBUG level logs) to that log instead.
>>>>>> Nevertheless, if the majority prefers to get back to a single
>>>>>> system.log file and get rid of debug.log/verbose_system.log altogether
>>>>>> then we would need to go through all log usages and readjust them to
>>>>>> use the proper logging levels and update our logging guidelines to
>>>>>> reflect whatever new policy is decided, not only disabling debug.log
>>>>>> and call it a day.
>>>>>> 
>>>>>> 2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <je...@datastax.com>:
>>>>>>> People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
>>>>>>> to clean up the system.log so that it a very high “signal” in terms
>>> of what was logged
>>>>>>> to it synchronously, but without reducing the ability of the logs to
>>> allow people to
>>>>>>> solve problems and perform post mortem analysis of issues.  We have
>>> informational
>>>>>>> log messages that are very useful to understanding the state of
>>> things, like compaction
>>>>>>> status, repair status, flushing, or the state of gossip in the
>>> system that are very useful to
>>>>>>> operators, but if they are all in the system.log make said log file
>>> harder to look over for
>>>>>>> issues.  In 10241 the method chosen for how to keep these log
>>> messages around by
>>>>>>> default, but get them out of the system.log was that these messages
>>> were changed from
>>>>>>> INFO to DEBUG and the new debug.log was created.
>>>>>>> 
>>>>>>> From the discussion here it seems that many would like to change how
>>> this works.  Rather
>>>>>>> than just turning off the debug.log I would propose that we switch
>>> to using the SLF4J
>>>>>>> MARKER[1] ability to move the messages back to INFO but tag them as
>>> belonging to
>>>>>>> the asynchronous_system.log rather than the normal system.log.
>>>>>>> 
>>>>>>> [1] https://logback.qos.ch/manual/layouts.html#marker <
>>> https://logback.qos.ch/manual/layouts.html#marker>
>>>>>>> https://www.slf4j.org/faq.html#fatal <
>>> https://www.slf4j.org/faq.html#fatal>
>>>>>>> 
>>>>>>> 
>>>>> 
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>>>>> For additional commands, e-mail: dev-help@cassandra.apache.org
>>>>> 
>>>> 
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>>>> For additional commands, e-mail: dev-help@cassandra.apache.org
>>>> 
>>> 
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>>> For additional commands, e-mail: dev-help@cassandra.apache.org
>>> 
>>> --
>> -----------------
>> Alexander Dejanovski
>> France
>> @alexanderdeja
>> 
>> Consultant
>> Apache Cassandra Consulting
>> http://www.thelastpickle.com
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
> 

Re: Debug logging enabled by default since 2.2

[Alexander Dejanovski <al...@thelastpickle.com>]

That's a good question.

At this point ¯\_(ツ)_/¯

On Tue, Mar 20, 2018 at 4:42 PM Ariel Weisberg <ar...@weisberg.ws> wrote:

> Hi,
>
> That's good to hear.
>
> What's the difference between DEBUG and TRACE? Obviously we decide
> ourselves. I don't have a good answer because right now we are in the
> process of eliminating the distinction we used to make which is that DEBUG
> is safe to turn on in production and TRACE is not.
>
> Ariel
>
> On Tue, Mar 20, 2018, at 12:36 PM, Alexander Dejanovski wrote:
> > Ariel,
> >
> > the current plan that's discussed on the ticket (
> > https://issues.apache.org/jira/browse/CASSANDRA-14326) is to maintain
> the
> > separation and keep the debug.log for "real" DEBUG level logging, which
> > would be disabled by default.
> > A new intermediate marker would be created to have VERBOSE_INFO logging
> > (some current debug loggings must be changed to that new level/marker),
> > which would be enabled by default, and "standard" INFO logging would go
> to
> > system.log.
> >
> > I guess in that configuration, some/most TRACE level loggings would then
> be
> > eligible to graduate to DEBUG...?
> >
> >
> >
> >
> > On Tue, Mar 20, 2018 at 4:19 PM Ariel Weisberg <ar...@weisberg.ws>
> wrote:
> >
> > > Hi,
> > >
> > > Signal to noise ratio matters for logs. Things that we log at DEBUG
> aren't
> > > at all bound by constraints of human readability or being particularly
> > > relevant most of the time. I don't want to see most of this stuff
> unless I
> > > have already not found what I am looking for at INFO and above.
> > >
> > > Can we at least maintain the separation of what is effectively debug
> > > logging (switching to an annotation aside) from INFO and above? I want
> to
> > > avoid two steps forward one step back.
> > >
> > > Ariel
> > > On Tue, Mar 20, 2018, at 9:23 AM, Paulo Motta wrote:
> > > > That sounds like a good plan, Alexander! Thanks!
> > > >
> > > > Stefan, someone needs to go through all messages being logged at
> DEBUG
> > > > and reclassify important ones as INFO. I suggest continuing
> discussion
> > > > on specifics on CASSANDRA-14326.
> > > >
> > > > 2018-03-20 6:46 GMT-03:00 Stefan Podkowinski <sp...@apache.org>:
> > > > > Are you suggesting to move all messages currently logged via
> debug() to
> > > > > info() with the additional marker set, or only particular messages?
> > > > >
> > > > >
> > > > > On 19.03.2018 19:51, Paulo Motta wrote:
> > > > >> Thanks for the constructive input and feedback! From this
> discussion
> > > > >> it seems like overloading the DEBUG level to signify
> > > > >> async-verbose-INFO on CASSANDRA-10241 is leading to some
> confusion and
> > > > >> we should fix this.
> > > > >>
> > > > >> However, we cannot simply turn debug.log off as during
> CASSANDRA-10241
> > > > >> some verbose-but-useful-info-logs, such as flush information were
> > > > >> changed from INFO to DEBUG, and since the patch has been in for
> nearly
> > > > >> 3 years it's probably non-revertable. Furthermore, the practice of
> > > > >> using the DEBUG level for logging non-debug stuff has been in our
> > > > >> Logging Guidelines
> > > > >> (https://wiki.apache.org/cassandra/LoggingGuidelines) since
> then, so
> > > > >> there is probably useful DEBUG stuff that would need to be turned
> into
> > > > >> INFO if we get rid of debug.log.
> > > > >>
> > > > >> For this reason I'm more in favor of converting the debug.log into
> > > > >> async/verbose_system.log as suggested by Jeremiah and use a
> marker to
> > > > >> direct these logs (former DEBUG level logs) to that log instead.
> > > > >> Nevertheless, if the majority prefers to get back to a single
> > > > >> system.log file and get rid of debug.log/verbose_system.log
> altogether
> > > > >> then we would need to go through all log usages and readjust them
> to
> > > > >> use the proper logging levels and update our logging guidelines to
> > > > >> reflect whatever new policy is decided, not only disabling
> debug.log
> > > > >> and call it a day.
> > > > >>
> > > > >> 2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <
> jeremiah@datastax.com>:
> > > > >>> People seem hung up on DEBUG here.  The goal of CASSANDRA-10241
> was
> > > > >>> to clean up the system.log so that it a very high “signal” in
> terms
> > > of what was logged
> > > > >>> to it synchronously, but without reducing the ability of the
> logs to
> > > allow people to
> > > > >>> solve problems and perform post mortem analysis of issues.  We
> have
> > > informational
> > > > >>> log messages that are very useful to understanding the state of
> > > things, like compaction
> > > > >>> status, repair status, flushing, or the state of gossip in the
> > > system that are very useful to
> > > > >>> operators, but if they are all in the system.log make said log
> file
> > > harder to look over for
> > > > >>> issues.  In 10241 the method chosen for how to keep these log
> > > messages around by
> > > > >>> default, but get them out of the system.log was that these
> messages
> > > were changed from
> > > > >>> INFO to DEBUG and the new debug.log was created.
> > > > >>>
> > > > >>> From the discussion here it seems that many would like to change
> how
> > > this works.  Rather
> > > > >>> than just turning off the debug.log I would propose that we
> switch
> > > to using the SLF4J
> > > > >>> MARKER[1] ability to move the messages back to INFO but tag them
> as
> > > belonging to
> > > > >>> the asynchronous_system.log rather than the normal system.log.
> > > > >>>
> > > > >>> [1] https://logback.qos.ch/manual/layouts.html#marker <
> > > https://logback.qos.ch/manual/layouts.html#marker>
> > > > >>> https://www.slf4j.org/faq.html#fatal <
> > > https://www.slf4j.org/faq.html#fatal>
> > > > >>>
> > > > >>>
> > > > >
> > > > >
> ---------------------------------------------------------------------
> > > > > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > > > > For additional commands, e-mail: dev-help@cassandra.apache.org
> > > > >
> > > >
> > > > ---------------------------------------------------------------------
> > > > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > > > For additional commands, e-mail: dev-help@cassandra.apache.org
> > > >
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > > For additional commands, e-mail: dev-help@cassandra.apache.org
> > >
> > > --
> > -----------------
> > Alexander Dejanovski
> > France
> > @alexanderdeja
> >
> > Consultant
> > Apache Cassandra Consulting
> > http://www.thelastpickle.com
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
>
> --
-----------------
Alexander Dejanovski
France
@alexanderdeja

Consultant
Apache Cassandra Consulting
http://www.thelastpickle.com

Re: Debug logging enabled by default since 2.2

[Ariel Weisberg <ar...@weisberg.ws>]

Hi,

That's good to hear.

What's the difference between DEBUG and TRACE? Obviously we decide ourselves. I don't have a good answer because right now we are in the process of eliminating the distinction we used to make which is that DEBUG is safe to turn on in production and TRACE is not.

Ariel

On Tue, Mar 20, 2018, at 12:36 PM, Alexander Dejanovski wrote:
> Ariel,
> 
> the current plan that's discussed on the ticket (
> https://issues.apache.org/jira/browse/CASSANDRA-14326) is to maintain the
> separation and keep the debug.log for "real" DEBUG level logging, which
> would be disabled by default.
> A new intermediate marker would be created to have VERBOSE_INFO logging
> (some current debug loggings must be changed to that new level/marker),
> which would be enabled by default, and "standard" INFO logging would go to
> system.log.
> 
> I guess in that configuration, some/most TRACE level loggings would then be
> eligible to graduate to DEBUG...?
> 
> 
> 
> 
> On Tue, Mar 20, 2018 at 4:19 PM Ariel Weisberg <ar...@weisberg.ws> wrote:
> 
> > Hi,
> >
> > Signal to noise ratio matters for logs. Things that we log at DEBUG aren't
> > at all bound by constraints of human readability or being particularly
> > relevant most of the time. I don't want to see most of this stuff unless I
> > have already not found what I am looking for at INFO and above.
> >
> > Can we at least maintain the separation of what is effectively debug
> > logging (switching to an annotation aside) from INFO and above? I want to
> > avoid two steps forward one step back.
> >
> > Ariel
> > On Tue, Mar 20, 2018, at 9:23 AM, Paulo Motta wrote:
> > > That sounds like a good plan, Alexander! Thanks!
> > >
> > > Stefan, someone needs to go through all messages being logged at DEBUG
> > > and reclassify important ones as INFO. I suggest continuing discussion
> > > on specifics on CASSANDRA-14326.
> > >
> > > 2018-03-20 6:46 GMT-03:00 Stefan Podkowinski <sp...@apache.org>:
> > > > Are you suggesting to move all messages currently logged via debug() to
> > > > info() with the additional marker set, or only particular messages?
> > > >
> > > >
> > > > On 19.03.2018 19:51, Paulo Motta wrote:
> > > >> Thanks for the constructive input and feedback! From this discussion
> > > >> it seems like overloading the DEBUG level to signify
> > > >> async-verbose-INFO on CASSANDRA-10241 is leading to some confusion and
> > > >> we should fix this.
> > > >>
> > > >> However, we cannot simply turn debug.log off as during CASSANDRA-10241
> > > >> some verbose-but-useful-info-logs, such as flush information were
> > > >> changed from INFO to DEBUG, and since the patch has been in for nearly
> > > >> 3 years it's probably non-revertable. Furthermore, the practice of
> > > >> using the DEBUG level for logging non-debug stuff has been in our
> > > >> Logging Guidelines
> > > >> (https://wiki.apache.org/cassandra/LoggingGuidelines) since then, so
> > > >> there is probably useful DEBUG stuff that would need to be turned into
> > > >> INFO if we get rid of debug.log.
> > > >>
> > > >> For this reason I'm more in favor of converting the debug.log into
> > > >> async/verbose_system.log as suggested by Jeremiah and use a marker to
> > > >> direct these logs (former DEBUG level logs) to that log instead.
> > > >> Nevertheless, if the majority prefers to get back to a single
> > > >> system.log file and get rid of debug.log/verbose_system.log altogether
> > > >> then we would need to go through all log usages and readjust them to
> > > >> use the proper logging levels and update our logging guidelines to
> > > >> reflect whatever new policy is decided, not only disabling debug.log
> > > >> and call it a day.
> > > >>
> > > >> 2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <je...@datastax.com>:
> > > >>> People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
> > > >>> to clean up the system.log so that it a very high “signal” in terms
> > of what was logged
> > > >>> to it synchronously, but without reducing the ability of the logs to
> > allow people to
> > > >>> solve problems and perform post mortem analysis of issues.  We have
> > informational
> > > >>> log messages that are very useful to understanding the state of
> > things, like compaction
> > > >>> status, repair status, flushing, or the state of gossip in the
> > system that are very useful to
> > > >>> operators, but if they are all in the system.log make said log file
> > harder to look over for
> > > >>> issues.  In 10241 the method chosen for how to keep these log
> > messages around by
> > > >>> default, but get them out of the system.log was that these messages
> > were changed from
> > > >>> INFO to DEBUG and the new debug.log was created.
> > > >>>
> > > >>> From the discussion here it seems that many would like to change how
> > this works.  Rather
> > > >>> than just turning off the debug.log I would propose that we switch
> > to using the SLF4J
> > > >>> MARKER[1] ability to move the messages back to INFO but tag them as
> > belonging to
> > > >>> the asynchronous_system.log rather than the normal system.log.
> > > >>>
> > > >>> [1] https://logback.qos.ch/manual/layouts.html#marker <
> > https://logback.qos.ch/manual/layouts.html#marker>
> > > >>> https://www.slf4j.org/faq.html#fatal <
> > https://www.slf4j.org/faq.html#fatal>
> > > >>>
> > > >>>
> > > >
> > > > ---------------------------------------------------------------------
> > > > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > > > For additional commands, e-mail: dev-help@cassandra.apache.org
> > > >
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > > For additional commands, e-mail: dev-help@cassandra.apache.org
> > >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > For additional commands, e-mail: dev-help@cassandra.apache.org
> >
> > --
> -----------------
> Alexander Dejanovski
> France
> @alexanderdeja
> 
> Consultant
> Apache Cassandra Consulting
> http://www.thelastpickle.com

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Alexander Dejanovski <al...@thelastpickle.com>]

Ariel,

the current plan that's discussed on the ticket (
https://issues.apache.org/jira/browse/CASSANDRA-14326) is to maintain the
separation and keep the debug.log for "real" DEBUG level logging, which
would be disabled by default.
A new intermediate marker would be created to have VERBOSE_INFO logging
(some current debug loggings must be changed to that new level/marker),
which would be enabled by default, and "standard" INFO logging would go to
system.log.

I guess in that configuration, some/most TRACE level loggings would then be
eligible to graduate to DEBUG...?




On Tue, Mar 20, 2018 at 4:19 PM Ariel Weisberg <ar...@weisberg.ws> wrote:

> Hi,
>
> Signal to noise ratio matters for logs. Things that we log at DEBUG aren't
> at all bound by constraints of human readability or being particularly
> relevant most of the time. I don't want to see most of this stuff unless I
> have already not found what I am looking for at INFO and above.
>
> Can we at least maintain the separation of what is effectively debug
> logging (switching to an annotation aside) from INFO and above? I want to
> avoid two steps forward one step back.
>
> Ariel
> On Tue, Mar 20, 2018, at 9:23 AM, Paulo Motta wrote:
> > That sounds like a good plan, Alexander! Thanks!
> >
> > Stefan, someone needs to go through all messages being logged at DEBUG
> > and reclassify important ones as INFO. I suggest continuing discussion
> > on specifics on CASSANDRA-14326.
> >
> > 2018-03-20 6:46 GMT-03:00 Stefan Podkowinski <sp...@apache.org>:
> > > Are you suggesting to move all messages currently logged via debug() to
> > > info() with the additional marker set, or only particular messages?
> > >
> > >
> > > On 19.03.2018 19:51, Paulo Motta wrote:
> > >> Thanks for the constructive input and feedback! From this discussion
> > >> it seems like overloading the DEBUG level to signify
> > >> async-verbose-INFO on CASSANDRA-10241 is leading to some confusion and
> > >> we should fix this.
> > >>
> > >> However, we cannot simply turn debug.log off as during CASSANDRA-10241
> > >> some verbose-but-useful-info-logs, such as flush information were
> > >> changed from INFO to DEBUG, and since the patch has been in for nearly
> > >> 3 years it's probably non-revertable. Furthermore, the practice of
> > >> using the DEBUG level for logging non-debug stuff has been in our
> > >> Logging Guidelines
> > >> (https://wiki.apache.org/cassandra/LoggingGuidelines) since then, so
> > >> there is probably useful DEBUG stuff that would need to be turned into
> > >> INFO if we get rid of debug.log.
> > >>
> > >> For this reason I'm more in favor of converting the debug.log into
> > >> async/verbose_system.log as suggested by Jeremiah and use a marker to
> > >> direct these logs (former DEBUG level logs) to that log instead.
> > >> Nevertheless, if the majority prefers to get back to a single
> > >> system.log file and get rid of debug.log/verbose_system.log altogether
> > >> then we would need to go through all log usages and readjust them to
> > >> use the proper logging levels and update our logging guidelines to
> > >> reflect whatever new policy is decided, not only disabling debug.log
> > >> and call it a day.
> > >>
> > >> 2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <je...@datastax.com>:
> > >>> People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
> > >>> to clean up the system.log so that it a very high “signal” in terms
> of what was logged
> > >>> to it synchronously, but without reducing the ability of the logs to
> allow people to
> > >>> solve problems and perform post mortem analysis of issues.  We have
> informational
> > >>> log messages that are very useful to understanding the state of
> things, like compaction
> > >>> status, repair status, flushing, or the state of gossip in the
> system that are very useful to
> > >>> operators, but if they are all in the system.log make said log file
> harder to look over for
> > >>> issues.  In 10241 the method chosen for how to keep these log
> messages around by
> > >>> default, but get them out of the system.log was that these messages
> were changed from
> > >>> INFO to DEBUG and the new debug.log was created.
> > >>>
> > >>> From the discussion here it seems that many would like to change how
> this works.  Rather
> > >>> than just turning off the debug.log I would propose that we switch
> to using the SLF4J
> > >>> MARKER[1] ability to move the messages back to INFO but tag them as
> belonging to
> > >>> the asynchronous_system.log rather than the normal system.log.
> > >>>
> > >>> [1] https://logback.qos.ch/manual/layouts.html#marker <
> https://logback.qos.ch/manual/layouts.html#marker>
> > >>> https://www.slf4j.org/faq.html#fatal <
> https://www.slf4j.org/faq.html#fatal>
> > >>>
> > >>>
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > > For additional commands, e-mail: dev-help@cassandra.apache.org
> > >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > For additional commands, e-mail: dev-help@cassandra.apache.org
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
>
> --
-----------------
Alexander Dejanovski
France
@alexanderdeja

Consultant
Apache Cassandra Consulting
http://www.thelastpickle.com

Re: Debug logging enabled by default since 2.2

[Ariel Weisberg <ar...@weisberg.ws>]

Hi,

Another point I want to mention. Another reason we separate the files is that they can then use separate log rolling policies. A verbose debug log no longer rolls the INFO level system.log.

Ariel

On Tue, Mar 20, 2018, at 12:19 PM, Ariel Weisberg wrote:
> Hi,
> 
> Signal to noise ratio matters for logs. Things that we log at DEBUG 
> aren't at all bound by constraints of human readability or being 
> particularly relevant most of the time. I don't want to see most of this 
> stuff unless I have already not found what I am looking for at INFO and 
> above.
> 
> Can we at least maintain the separation of what is effectively debug 
> logging (switching to an annotation aside) from INFO and above? I want 
> to avoid two steps forward one step back.
> 
> Ariel
> On Tue, Mar 20, 2018, at 9:23 AM, Paulo Motta wrote:
> > That sounds like a good plan, Alexander! Thanks!
> > 
> > Stefan, someone needs to go through all messages being logged at DEBUG
> > and reclassify important ones as INFO. I suggest continuing discussion
> > on specifics on CASSANDRA-14326.
> > 
> > 2018-03-20 6:46 GMT-03:00 Stefan Podkowinski <sp...@apache.org>:
> > > Are you suggesting to move all messages currently logged via debug() to
> > > info() with the additional marker set, or only particular messages?
> > >
> > >
> > > On 19.03.2018 19:51, Paulo Motta wrote:
> > >> Thanks for the constructive input and feedback! From this discussion
> > >> it seems like overloading the DEBUG level to signify
> > >> async-verbose-INFO on CASSANDRA-10241 is leading to some confusion and
> > >> we should fix this.
> > >>
> > >> However, we cannot simply turn debug.log off as during CASSANDRA-10241
> > >> some verbose-but-useful-info-logs, such as flush information were
> > >> changed from INFO to DEBUG, and since the patch has been in for nearly
> > >> 3 years it's probably non-revertable. Furthermore, the practice of
> > >> using the DEBUG level for logging non-debug stuff has been in our
> > >> Logging Guidelines
> > >> (https://wiki.apache.org/cassandra/LoggingGuidelines) since then, so
> > >> there is probably useful DEBUG stuff that would need to be turned into
> > >> INFO if we get rid of debug.log.
> > >>
> > >> For this reason I'm more in favor of converting the debug.log into
> > >> async/verbose_system.log as suggested by Jeremiah and use a marker to
> > >> direct these logs (former DEBUG level logs) to that log instead.
> > >> Nevertheless, if the majority prefers to get back to a single
> > >> system.log file and get rid of debug.log/verbose_system.log altogether
> > >> then we would need to go through all log usages and readjust them to
> > >> use the proper logging levels and update our logging guidelines to
> > >> reflect whatever new policy is decided, not only disabling debug.log
> > >> and call it a day.
> > >>
> > >> 2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <je...@datastax.com>:
> > >>> People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
> > >>> to clean up the system.log so that it a very high “signal” in terms of what was logged
> > >>> to it synchronously, but without reducing the ability of the logs to allow people to
> > >>> solve problems and perform post mortem analysis of issues.  We have informational
> > >>> log messages that are very useful to understanding the state of things, like compaction
> > >>> status, repair status, flushing, or the state of gossip in the system that are very useful to
> > >>> operators, but if they are all in the system.log make said log file harder to look over for
> > >>> issues.  In 10241 the method chosen for how to keep these log messages around by
> > >>> default, but get them out of the system.log was that these messages were changed from
> > >>> INFO to DEBUG and the new debug.log was created.
> > >>>
> > >>> From the discussion here it seems that many would like to change how this works.  Rather
> > >>> than just turning off the debug.log I would propose that we switch to using the SLF4J
> > >>> MARKER[1] ability to move the messages back to INFO but tag them as belonging to
> > >>> the asynchronous_system.log rather than the normal system.log.
> > >>>
> > >>> [1] https://logback.qos.ch/manual/layouts.html#marker <https://logback.qos.ch/manual/layouts.html#marker>
> > >>> https://www.slf4j.org/faq.html#fatal <https://www.slf4j.org/faq.html#fatal>
> > >>>
> > >>>
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > > For additional commands, e-mail: dev-help@cassandra.apache.org
> > >
> > 
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > For additional commands, e-mail: dev-help@cassandra.apache.org
> > 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
> 

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Ariel Weisberg <ar...@weisberg.ws>]

Hi,

Signal to noise ratio matters for logs. Things that we log at DEBUG aren't at all bound by constraints of human readability or being particularly relevant most of the time. I don't want to see most of this stuff unless I have already not found what I am looking for at INFO and above.

Can we at least maintain the separation of what is effectively debug logging (switching to an annotation aside) from INFO and above? I want to avoid two steps forward one step back.

Ariel
On Tue, Mar 20, 2018, at 9:23 AM, Paulo Motta wrote:
> That sounds like a good plan, Alexander! Thanks!
> 
> Stefan, someone needs to go through all messages being logged at DEBUG
> and reclassify important ones as INFO. I suggest continuing discussion
> on specifics on CASSANDRA-14326.
> 
> 2018-03-20 6:46 GMT-03:00 Stefan Podkowinski <sp...@apache.org>:
> > Are you suggesting to move all messages currently logged via debug() to
> > info() with the additional marker set, or only particular messages?
> >
> >
> > On 19.03.2018 19:51, Paulo Motta wrote:
> >> Thanks for the constructive input and feedback! From this discussion
> >> it seems like overloading the DEBUG level to signify
> >> async-verbose-INFO on CASSANDRA-10241 is leading to some confusion and
> >> we should fix this.
> >>
> >> However, we cannot simply turn debug.log off as during CASSANDRA-10241
> >> some verbose-but-useful-info-logs, such as flush information were
> >> changed from INFO to DEBUG, and since the patch has been in for nearly
> >> 3 years it's probably non-revertable. Furthermore, the practice of
> >> using the DEBUG level for logging non-debug stuff has been in our
> >> Logging Guidelines
> >> (https://wiki.apache.org/cassandra/LoggingGuidelines) since then, so
> >> there is probably useful DEBUG stuff that would need to be turned into
> >> INFO if we get rid of debug.log.
> >>
> >> For this reason I'm more in favor of converting the debug.log into
> >> async/verbose_system.log as suggested by Jeremiah and use a marker to
> >> direct these logs (former DEBUG level logs) to that log instead.
> >> Nevertheless, if the majority prefers to get back to a single
> >> system.log file and get rid of debug.log/verbose_system.log altogether
> >> then we would need to go through all log usages and readjust them to
> >> use the proper logging levels and update our logging guidelines to
> >> reflect whatever new policy is decided, not only disabling debug.log
> >> and call it a day.
> >>
> >> 2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <je...@datastax.com>:
> >>> People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
> >>> to clean up the system.log so that it a very high “signal” in terms of what was logged
> >>> to it synchronously, but without reducing the ability of the logs to allow people to
> >>> solve problems and perform post mortem analysis of issues.  We have informational
> >>> log messages that are very useful to understanding the state of things, like compaction
> >>> status, repair status, flushing, or the state of gossip in the system that are very useful to
> >>> operators, but if they are all in the system.log make said log file harder to look over for
> >>> issues.  In 10241 the method chosen for how to keep these log messages around by
> >>> default, but get them out of the system.log was that these messages were changed from
> >>> INFO to DEBUG and the new debug.log was created.
> >>>
> >>> From the discussion here it seems that many would like to change how this works.  Rather
> >>> than just turning off the debug.log I would propose that we switch to using the SLF4J
> >>> MARKER[1] ability to move the messages back to INFO but tag them as belonging to
> >>> the asynchronous_system.log rather than the normal system.log.
> >>>
> >>> [1] https://logback.qos.ch/manual/layouts.html#marker <https://logback.qos.ch/manual/layouts.html#marker>
> >>> https://www.slf4j.org/faq.html#fatal <https://www.slf4j.org/faq.html#fatal>
> >>>
> >>>
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > For additional commands, e-mail: dev-help@cassandra.apache.org
> >
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
> 

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Paulo Motta <pa...@gmail.com>]

That sounds like a good plan, Alexander! Thanks!

Stefan, someone needs to go through all messages being logged at DEBUG
and reclassify important ones as INFO. I suggest continuing discussion
on specifics on CASSANDRA-14326.

2018-03-20 6:46 GMT-03:00 Stefan Podkowinski <sp...@apache.org>:
> Are you suggesting to move all messages currently logged via debug() to
> info() with the additional marker set, or only particular messages?
>
>
> On 19.03.2018 19:51, Paulo Motta wrote:
>> Thanks for the constructive input and feedback! From this discussion
>> it seems like overloading the DEBUG level to signify
>> async-verbose-INFO on CASSANDRA-10241 is leading to some confusion and
>> we should fix this.
>>
>> However, we cannot simply turn debug.log off as during CASSANDRA-10241
>> some verbose-but-useful-info-logs, such as flush information were
>> changed from INFO to DEBUG, and since the patch has been in for nearly
>> 3 years it's probably non-revertable. Furthermore, the practice of
>> using the DEBUG level for logging non-debug stuff has been in our
>> Logging Guidelines
>> (https://wiki.apache.org/cassandra/LoggingGuidelines) since then, so
>> there is probably useful DEBUG stuff that would need to be turned into
>> INFO if we get rid of debug.log.
>>
>> For this reason I'm more in favor of converting the debug.log into
>> async/verbose_system.log as suggested by Jeremiah and use a marker to
>> direct these logs (former DEBUG level logs) to that log instead.
>> Nevertheless, if the majority prefers to get back to a single
>> system.log file and get rid of debug.log/verbose_system.log altogether
>> then we would need to go through all log usages and readjust them to
>> use the proper logging levels and update our logging guidelines to
>> reflect whatever new policy is decided, not only disabling debug.log
>> and call it a day.
>>
>> 2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <je...@datastax.com>:
>>> People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
>>> to clean up the system.log so that it a very high “signal” in terms of what was logged
>>> to it synchronously, but without reducing the ability of the logs to allow people to
>>> solve problems and perform post mortem analysis of issues.  We have informational
>>> log messages that are very useful to understanding the state of things, like compaction
>>> status, repair status, flushing, or the state of gossip in the system that are very useful to
>>> operators, but if they are all in the system.log make said log file harder to look over for
>>> issues.  In 10241 the method chosen for how to keep these log messages around by
>>> default, but get them out of the system.log was that these messages were changed from
>>> INFO to DEBUG and the new debug.log was created.
>>>
>>> From the discussion here it seems that many would like to change how this works.  Rather
>>> than just turning off the debug.log I would propose that we switch to using the SLF4J
>>> MARKER[1] ability to move the messages back to INFO but tag them as belonging to
>>> the asynchronous_system.log rather than the normal system.log.
>>>
>>> [1] https://logback.qos.ch/manual/layouts.html#marker <https://logback.qos.ch/manual/layouts.html#marker>
>>> https://www.slf4j.org/faq.html#fatal <https://www.slf4j.org/faq.html#fatal>
>>>
>>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
>

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Stefan Podkowinski <sp...@apache.org>]

Are you suggesting to move all messages currently logged via debug() to
info() with the additional marker set, or only particular messages?


On 19.03.2018 19:51, Paulo Motta wrote:
> Thanks for the constructive input and feedback! From this discussion
> it seems like overloading the DEBUG level to signify
> async-verbose-INFO on CASSANDRA-10241 is leading to some confusion and
> we should fix this.
> 
> However, we cannot simply turn debug.log off as during CASSANDRA-10241
> some verbose-but-useful-info-logs, such as flush information were
> changed from INFO to DEBUG, and since the patch has been in for nearly
> 3 years it's probably non-revertable. Furthermore, the practice of
> using the DEBUG level for logging non-debug stuff has been in our
> Logging Guidelines
> (https://wiki.apache.org/cassandra/LoggingGuidelines) since then, so
> there is probably useful DEBUG stuff that would need to be turned into
> INFO if we get rid of debug.log.
> 
> For this reason I'm more in favor of converting the debug.log into
> async/verbose_system.log as suggested by Jeremiah and use a marker to
> direct these logs (former DEBUG level logs) to that log instead.
> Nevertheless, if the majority prefers to get back to a single
> system.log file and get rid of debug.log/verbose_system.log altogether
> then we would need to go through all log usages and readjust them to
> use the proper logging levels and update our logging guidelines to
> reflect whatever new policy is decided, not only disabling debug.log
> and call it a day.
> 
> 2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <je...@datastax.com>:
>> People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
>> to clean up the system.log so that it a very high “signal” in terms of what was logged
>> to it synchronously, but without reducing the ability of the logs to allow people to
>> solve problems and perform post mortem analysis of issues.  We have informational
>> log messages that are very useful to understanding the state of things, like compaction
>> status, repair status, flushing, or the state of gossip in the system that are very useful to
>> operators, but if they are all in the system.log make said log file harder to look over for
>> issues.  In 10241 the method chosen for how to keep these log messages around by
>> default, but get them out of the system.log was that these messages were changed from
>> INFO to DEBUG and the new debug.log was created.
>>
>> From the discussion here it seems that many would like to change how this works.  Rather
>> than just turning off the debug.log I would propose that we switch to using the SLF4J
>> MARKER[1] ability to move the messages back to INFO but tag them as belonging to
>> the asynchronous_system.log rather than the normal system.log.
>>
>> [1] https://logback.qos.ch/manual/layouts.html#marker <https://logback.qos.ch/manual/layouts.html#marker>
>> https://www.slf4j.org/faq.html#fatal <https://www.slf4j.org/faq.html#fatal>
>>
>>

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Alexander Dejanovski <al...@thelastpickle.com>]

Hi Paulo,

I agree that CASSANDRA-10241 prevents from simply turning off debug logging
and there's more work to do (we need compaction and flush traces among
others).

My 2 cents on the other points :

   - I was happy with a single log file for 99.5% of my ops needs and
   verbosity was never an issue in system.log, but don't mind having 2 if the
   naming is less confusing and performance isn't affected.
   - Nightly performance testing is a must have for a (community) database.
   Injecting perf regressions is way too easy. It's probably not easy to setup
   though in a way that each run has the exact same conditions and we don't
   get false alarms.
   - There has been mentions of more lightweight logging frameworks :
   that's definitely something we should look at.

In the scope of https://issues.apache.org/jira/browse/CASSANDRA-14318, I'll
start by fixing the identified performance issue that seems to affect C*
2.2 only, by lowering read path DEBUG loggings to TRACE level and run new
benchmarks.
I'll also check to what extent debug logging affects performance in 3.0.16
and 3.11.2.

Some changes apparently need to be done, may it be to rename the debug log
to system-verbose.log (or whatever) and use custom levels, or move back all
required verbose logs to the original system.log.
I've created a follow up ticket to continue this conversation :
https://issues.apache.org/jira/browse/CASSANDRA-14326

Thanks all for this very interesting discussion !

Cheers,


On Mon, Mar 19, 2018 at 7:52 PM Paulo Motta <pa...@gmail.com>
wrote:

> Thanks for the constructive input and feedback! From this discussion
> it seems like overloading the DEBUG level to signify
> async-verbose-INFO on CASSANDRA-10241 is leading to some confusion and
> we should fix this.
>
> However, we cannot simply turn debug.log off as during CASSANDRA-10241
> some verbose-but-useful-info-logs, such as flush information were
> changed from INFO to DEBUG, and since the patch has been in for nearly
> 3 years it's probably non-revertable. Furthermore, the practice of
> using the DEBUG level for logging non-debug stuff has been in our
> Logging Guidelines
> (https://wiki.apache.org/cassandra/LoggingGuidelines) since then, so
> there is probably useful DEBUG stuff that would need to be turned into
> INFO if we get rid of debug.log.
>
> For this reason I'm more in favor of converting the debug.log into
> async/verbose_system.log as suggested by Jeremiah and use a marker to
> direct these logs (former DEBUG level logs) to that log instead.
> Nevertheless, if the majority prefers to get back to a single
> system.log file and get rid of debug.log/verbose_system.log altogether
> then we would need to go through all log usages and readjust them to
> use the proper logging levels and update our logging guidelines to
> reflect whatever new policy is decided, not only disabling debug.log
> and call it a day.
>
> 2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <je...@datastax.com>:
> > People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
> > to clean up the system.log so that it a very high “signal” in terms of
> what was logged
> > to it synchronously, but without reducing the ability of the logs to
> allow people to
> > solve problems and perform post mortem analysis of issues.  We have
> informational
> > log messages that are very useful to understanding the state of things,
> like compaction
> > status, repair status, flushing, or the state of gossip in the system
> that are very useful to
> > operators, but if they are all in the system.log make said log file
> harder to look over for
> > issues.  In 10241 the method chosen for how to keep these log messages
> around by
> > default, but get them out of the system.log was that these messages were
> changed from
> > INFO to DEBUG and the new debug.log was created.
> >
> > From the discussion here it seems that many would like to change how
> this works.  Rather
> > than just turning off the debug.log I would propose that we switch to
> using the SLF4J
> > MARKER[1] ability to move the messages back to INFO but tag them as
> belonging to
> > the asynchronous_system.log rather than the normal system.log.
> >
> > [1] https://logback.qos.ch/manual/layouts.html#marker <
> https://logback.qos.ch/manual/layouts.html#marker>
> > https://www.slf4j.org/faq.html#fatal <
> https://www.slf4j.org/faq.html#fatal>
> >
> >
> >> On Mar 19, 2018, at 9:01 AM, Stefan Podkowinski <sp...@apache.org>
> wrote:
> >>
> >> I'd agree that INFO should be the default. Turning on the DEBUG logging
> >> can cause notable performance issues and I would not enable it on
> >> production systems unless I really have to. That's why I created
> >> CASSANDRA-12696 for 4.0, so you'll be able to at least only partially
> >> enable DEBUG based on what's relevant to look at, e.g. `nodetool
> >> setlogginglevel bootstrap DEBUG`.
> >>
> >> But small improvements like that won't change the fact that log files
> >> suck in general for more complex analysis, except for trivial tailing
> >> and grepping. You have to make sure that logging is enabled and old
> >> records you're interested in will not be rotated out. Then you have to
> >> gather log files from individual nodes somehow. Eventually I end up with
> >> a local tarball with logs in that situation and the fun starts creating
> >> hacky, regex loaded Python scripts to parse them. As each log message is
> >> limited to a single line of text, it's often missing out relevant
> >> details. You also got to create different parsers for different messages
> >> of course. It's just inefficient and too time consuming to gather
> >> information that way. Let alone implementing more advanced monitoring
> >> solutions on top of that.
> >>
> >> That's exactly why I started working on the "diagnostic events"
> >> (CASSANDRA-12944) idea more than a year ago. There's also support for
> >> persistency (CASSANDRA-13460) that would implement storing important but
> >> infrequent events as rich json objects in a local keyspace and allows
> >> retrieving them by using CQL. I still like the idea and think it's worth
> >> pursuing.
> >>
> >>
> >> On 19.03.18 09:53, Alain RODRIGUEZ wrote:
> >>> Hello,
> >>>
> >>> I am not developing Cassandra, but I am using it actively and helping
> >>> people to work with it. My perspective might be missing some code
> >>> considerations and history as I did not go through the ticket where
> this
> >>> 'debug' level was added by default. But here is a feedback after
> upgrading
> >>> a few clusters to Cassandra 2.2:
> >>>
> >>> When upgrading a cluster to Cassandra 2.2, 'disable the debug logs' is
> in
> >>> my runbook. I mean, very often, when some cluster is upgraded to
> Cassandra
> >>> 2.2 and has problems with performances, the 2 most frequent issues are:
> >>>
> >>> - DEBUG level being turned on
> >>> - and / or dynamic snitching being enabled
> >>>
> >>> This is especially true for high percentile (very clear on p99). Let's
> put
> >>> the dynamic snitch aside as it is not our topic here.
> >>>
> >>> From an operational perspective, I prefer to set the debug level to
> 'DEBUG'
> >>> when I need it than having, out of the box, something that is
> unexpected
> >>> and impact performances. Plus the debug level can be changed without
> >>> restarting the node, through 'JMX' or even using 'nodetool' now.
> >>>
> >>> Also in most cases, the 'INFO' level is good enough for me to detect
> most
> >>> of the issues. I was even able to recreate a detailed history of
> events for
> >>> a customer recently, 'INFO' logs are already very powerful and
> complete I
> >>> believe (nice work on this by the way). Then monitoring is helping a
> lot
> >>> too. I did not have to use debug logs for a long time. It might
> happen, but
> >>> I will find my way to enable them.
> >>>
> >>> Even though it feels great to be able to help people with that easily
> >>> because the cause is often the same and turning off the logs is a
> >>> low hanging fruit in C*2.2 clusters that have very nice results and is
> easy
> >>> to achieve, I would prefer people not to fall into these performances
> traps
> >>> in the first place. In my head, 'Debug' logs should be for debug
> purposes
> >>> (by opposition to 'always on'). It seems legit. I am surprised this
> brings
> >>> so many discussions I thought this was a common standard widely
> accepted,
> >>> and beyond Cassandra. That being said, it is good to see those
> exchanges
> >>> are happening, so the decision that will be taken will be a good one,
> I am
> >>> sure. I hope this comment will help, I have no other goal, for sure I
> am
> >>> not willing to feed a conflict but a talk and I hope no one felt
> offended
> >>> by this feedback. I believe this change was made aiming at
> >>> helping/improving things, but it turns out it is more of an annoyance
> than
> >>> truly helpful (my personal perspective).
> >>>
> >>> I would +1 on making 'INFO' default again, but if someone is missing
> >>> information that should be in 'INFO'. If some informations are missing
> at
> >>> the 'INFO' level, why not add informations that should be at the 'INFO'
> >>> level there directly and keep log levels meaningful? Making sure we do
> not
> >>> bring the logs degrading performances from 'Debug' to 'Info' as much
> as we
> >>> can.
> >>>
> >>> Hope this is useful,
> >>>
> >>> C*heers,
> >>>
> >>> -----------------------
> >>> Alain Rodriguez - @arodream - alain@thelastpickle.com
> >>> France / Spain
> >>>
> >>> The Last Pickle - Apache Cassandra Consulting
> >>> http://www.thelastpickle.com
> >>>
> >>> 2018-03-19 2:18 GMT+00:00 kurt greaves <ku...@instaclustr.com>:
> >>>
> >>>> On the same page as Michael here. We disable debug logs in production
> due
> >>>> to the performance impact. Personally I think if debug logging is
> necessary
> >>>> for users to use the software we're doing something wrong. Also in my
> >>>> experience, if something doesn't reproduce it will not get fixed.
> Debug
> >>>> logging helps, but I've never seen a case where an actual bug simply
> >>>> *doesn't* reproduce eventually, and I'm sure if this issue appears
> debug
> >>>> logging could be enabled after the fact for the relevant classes and
> >>>> eventually it will reoccur and we could solve the problem. I've never
> seen
> >>>> a user say no to helping debug a problem with patched jars/changes to
> their
> >>>> system (like logging). I'd much prefer we pushed that harder rather
> than
> >>>> just saying "Everyone gets debug logging!". I'm also really not sold
> that
> >>>> debug logging saves the day. To me it mostly just speeds up the
> >>>> identification process, it generally doesn't expose magical
> information
> >>>> that wasn't available before, you just had to think about it a bit
> more.
> >>>>
> >>>>
> >>>> In a way the real issue might be that we don’t have nightly
> performance
> >>>>> runs that would make an accidentally introduced debug statement
> obvious.
> >>>> This is an issue, but I don't think it's the *real* issue. As already
> >>>> noted, debug logging is for debugging, which normal users shouldn't
> have to
> >>>> think about when they are just operating the software. We shouldn't
> risk
> >>>> performance regressions just for developer convenience.
> >>>>
> >>>> On 19 March 2018 at 00:55, Ariel Weisberg <ad...@fastmail.fm>
> wrote:
> >>>>
> >>>>> Hi,
> >>>>>
> >>>>> In a way the real issue might be that we don’t have nightly
> performance
> >>>>> runs that would make an accidentally introduced debug statement
> obvious.
> >>>>>
> >>>>> A log statement that runs once or more per read or write should be
> easy
> >>>> to
> >>>>> spot. I haven’t measured the impact though. And as a bonus by having
> this
> >>>>> we can spot a variety of performance issues introduced by all kinds
> of
> >>>>> changes.
> >>>>>
> >>>>> Ariel
> >>>>>
> >>>>>> On Mar 18, 2018, at 3:46 PM, Jeff Jirsa <jj...@gmail.com> wrote:
> >>>>>>
> >>>>>> In Cassandra-10241 I said I was torn on this whole ticket, since
> most
> >>>>> people would end up turning it off if it had a negative impact. You
> said:
> >>>>>> “I'd like to emphasize that we're not talking about turning debug or
> >>>>> trace on for client-generated request paths. There's way too much
> data
> >>>>> generated and it's unlikely to be useful.
> >>>>>> What we're proposing is enabling debug logging ONLY for cluster
> state
> >>>>> changes like gossip and schema, and infrequent activities like
> repair. “
> >>>>>> Clearly there’s a disconnect here - we’ve turned debug logging on
> for
> >>>>> everything and shuffled some stuff to trace, which is a one time
> action
> >>>> but
> >>>>> is hard to protect against regression. In fact, just looking at the
> read
> >>>>> callback shows two instances of debug log in the client request path
> >>>>> (exercise for the reader to “git blame”).
> >>>>>> Either we can go clean up all the surprises that leaked through, or
> we
> >>>>> can turn off debug and start backing out some of the changes in
> 10241.
> >>>>> Putting stuff like compaction in the same bucket as digest mismatch
> and
> >>>>> gossip state doesn’t make life materially better for most people.
> >>>>>> --
> >>>>>> Jeff Jirsa
> >>>>>>
> >>>>>>
> >>>>>>> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com>
> >>>> wrote:
> >>>>>>> That really depends on whether you're judicious in deciding what to
> >>>> log
> >>>>> at
> >>>>>>> debug, doesn't it?
> >>>>>>>
> >>>>>>> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <
> >>>> kjellman@apple.com>
> >>>>>>> wrote:
> >>>>>>>
> >>>>>>>> +1. this is how it works.
> >>>>>>>>
> >>>>>>>> your computer doesn’t run at debug logging by default. your phone
> >>>>> doesn’t
> >>>>>>>> either. neither does your smart tv. your database can’t be
> running at
> >>>>> debug
> >>>>>>>> just because it makes our lives as engineers easier.
> >>>>>>>>
> >>>>>>>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
> >>>>>>>> alex@thelastpickle.com> wrote:
> >>>>>>>>> It's a tiny bit unusual to turn on debug logging for all users by
> >>>>> default
> >>>>>>>>> though, and there should be occasions to turn it on when facing
> >>>> issues
> >>>>>>>> that
> >>>>>>>>> you want to debug (if they can be easily reproduced).
> >>>>>>>
> >>>>>>> --
> >>>>>>> Jonathan Ellis
> >>>>>>> co-founder, http://www.datastax.com
> >>>>>>> @spyced
> >>>>> ---------------------------------------------------------------------
> >>>>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> >>>>> For additional commands, e-mail: dev-help@cassandra.apache.org
> >>>>>
> >>>>>
> >>
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> >> For additional commands, e-mail: dev-help@cassandra.apache.org
> >>
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
>
> --
-----------------
Alexander Dejanovski
France
@alexanderdeja

Consultant
Apache Cassandra Consulting
http://www.thelastpickle.com

Re: Debug logging enabled by default since 2.2

[Paulo Motta <pa...@gmail.com>]

Thanks for the constructive input and feedback! From this discussion
it seems like overloading the DEBUG level to signify
async-verbose-INFO on CASSANDRA-10241 is leading to some confusion and
we should fix this.

However, we cannot simply turn debug.log off as during CASSANDRA-10241
some verbose-but-useful-info-logs, such as flush information were
changed from INFO to DEBUG, and since the patch has been in for nearly
3 years it's probably non-revertable. Furthermore, the practice of
using the DEBUG level for logging non-debug stuff has been in our
Logging Guidelines
(https://wiki.apache.org/cassandra/LoggingGuidelines) since then, so
there is probably useful DEBUG stuff that would need to be turned into
INFO if we get rid of debug.log.

For this reason I'm more in favor of converting the debug.log into
async/verbose_system.log as suggested by Jeremiah and use a marker to
direct these logs (former DEBUG level logs) to that log instead.
Nevertheless, if the majority prefers to get back to a single
system.log file and get rid of debug.log/verbose_system.log altogether
then we would need to go through all log usages and readjust them to
use the proper logging levels and update our logging guidelines to
reflect whatever new policy is decided, not only disabling debug.log
and call it a day.

2018-03-19 12:02 GMT-03:00 Jeremiah D Jordan <je...@datastax.com>:
> People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
> to clean up the system.log so that it a very high “signal” in terms of what was logged
> to it synchronously, but without reducing the ability of the logs to allow people to
> solve problems and perform post mortem analysis of issues.  We have informational
> log messages that are very useful to understanding the state of things, like compaction
> status, repair status, flushing, or the state of gossip in the system that are very useful to
> operators, but if they are all in the system.log make said log file harder to look over for
> issues.  In 10241 the method chosen for how to keep these log messages around by
> default, but get them out of the system.log was that these messages were changed from
> INFO to DEBUG and the new debug.log was created.
>
> From the discussion here it seems that many would like to change how this works.  Rather
> than just turning off the debug.log I would propose that we switch to using the SLF4J
> MARKER[1] ability to move the messages back to INFO but tag them as belonging to
> the asynchronous_system.log rather than the normal system.log.
>
> [1] https://logback.qos.ch/manual/layouts.html#marker <https://logback.qos.ch/manual/layouts.html#marker>
> https://www.slf4j.org/faq.html#fatal <https://www.slf4j.org/faq.html#fatal>
>
>
>> On Mar 19, 2018, at 9:01 AM, Stefan Podkowinski <sp...@apache.org> wrote:
>>
>> I'd agree that INFO should be the default. Turning on the DEBUG logging
>> can cause notable performance issues and I would not enable it on
>> production systems unless I really have to. That's why I created
>> CASSANDRA-12696 for 4.0, so you'll be able to at least only partially
>> enable DEBUG based on what's relevant to look at, e.g. `nodetool
>> setlogginglevel bootstrap DEBUG`.
>>
>> But small improvements like that won't change the fact that log files
>> suck in general for more complex analysis, except for trivial tailing
>> and grepping. You have to make sure that logging is enabled and old
>> records you're interested in will not be rotated out. Then you have to
>> gather log files from individual nodes somehow. Eventually I end up with
>> a local tarball with logs in that situation and the fun starts creating
>> hacky, regex loaded Python scripts to parse them. As each log message is
>> limited to a single line of text, it's often missing out relevant
>> details. You also got to create different parsers for different messages
>> of course. It's just inefficient and too time consuming to gather
>> information that way. Let alone implementing more advanced monitoring
>> solutions on top of that.
>>
>> That's exactly why I started working on the "diagnostic events"
>> (CASSANDRA-12944) idea more than a year ago. There's also support for
>> persistency (CASSANDRA-13460) that would implement storing important but
>> infrequent events as rich json objects in a local keyspace and allows
>> retrieving them by using CQL. I still like the idea and think it's worth
>> pursuing.
>>
>>
>> On 19.03.18 09:53, Alain RODRIGUEZ wrote:
>>> Hello,
>>>
>>> I am not developing Cassandra, but I am using it actively and helping
>>> people to work with it. My perspective might be missing some code
>>> considerations and history as I did not go through the ticket where this
>>> 'debug' level was added by default. But here is a feedback after upgrading
>>> a few clusters to Cassandra 2.2:
>>>
>>> When upgrading a cluster to Cassandra 2.2, 'disable the debug logs' is in
>>> my runbook. I mean, very often, when some cluster is upgraded to Cassandra
>>> 2.2 and has problems with performances, the 2 most frequent issues are:
>>>
>>> - DEBUG level being turned on
>>> - and / or dynamic snitching being enabled
>>>
>>> This is especially true for high percentile (very clear on p99). Let's put
>>> the dynamic snitch aside as it is not our topic here.
>>>
>>> From an operational perspective, I prefer to set the debug level to 'DEBUG'
>>> when I need it than having, out of the box, something that is unexpected
>>> and impact performances. Plus the debug level can be changed without
>>> restarting the node, through 'JMX' or even using 'nodetool' now.
>>>
>>> Also in most cases, the 'INFO' level is good enough for me to detect most
>>> of the issues. I was even able to recreate a detailed history of events for
>>> a customer recently, 'INFO' logs are already very powerful and complete I
>>> believe (nice work on this by the way). Then monitoring is helping a lot
>>> too. I did not have to use debug logs for a long time. It might happen, but
>>> I will find my way to enable them.
>>>
>>> Even though it feels great to be able to help people with that easily
>>> because the cause is often the same and turning off the logs is a
>>> low hanging fruit in C*2.2 clusters that have very nice results and is easy
>>> to achieve, I would prefer people not to fall into these performances traps
>>> in the first place. In my head, 'Debug' logs should be for debug purposes
>>> (by opposition to 'always on'). It seems legit. I am surprised this brings
>>> so many discussions I thought this was a common standard widely accepted,
>>> and beyond Cassandra. That being said, it is good to see those exchanges
>>> are happening, so the decision that will be taken will be a good one, I am
>>> sure. I hope this comment will help, I have no other goal, for sure I am
>>> not willing to feed a conflict but a talk and I hope no one felt offended
>>> by this feedback. I believe this change was made aiming at
>>> helping/improving things, but it turns out it is more of an annoyance than
>>> truly helpful (my personal perspective).
>>>
>>> I would +1 on making 'INFO' default again, but if someone is missing
>>> information that should be in 'INFO'. If some informations are missing at
>>> the 'INFO' level, why not add informations that should be at the 'INFO'
>>> level there directly and keep log levels meaningful? Making sure we do not
>>> bring the logs degrading performances from 'Debug' to 'Info' as much as we
>>> can.
>>>
>>> Hope this is useful,
>>>
>>> C*heers,
>>>
>>> -----------------------
>>> Alain Rodriguez - @arodream - alain@thelastpickle.com
>>> France / Spain
>>>
>>> The Last Pickle - Apache Cassandra Consulting
>>> http://www.thelastpickle.com
>>>
>>> 2018-03-19 2:18 GMT+00:00 kurt greaves <ku...@instaclustr.com>:
>>>
>>>> On the same page as Michael here. We disable debug logs in production due
>>>> to the performance impact. Personally I think if debug logging is necessary
>>>> for users to use the software we're doing something wrong. Also in my
>>>> experience, if something doesn't reproduce it will not get fixed. Debug
>>>> logging helps, but I've never seen a case where an actual bug simply
>>>> *doesn't* reproduce eventually, and I'm sure if this issue appears debug
>>>> logging could be enabled after the fact for the relevant classes and
>>>> eventually it will reoccur and we could solve the problem. I've never seen
>>>> a user say no to helping debug a problem with patched jars/changes to their
>>>> system (like logging). I'd much prefer we pushed that harder rather than
>>>> just saying "Everyone gets debug logging!". I'm also really not sold that
>>>> debug logging saves the day. To me it mostly just speeds up the
>>>> identification process, it generally doesn't expose magical information
>>>> that wasn't available before, you just had to think about it a bit more.
>>>>
>>>>
>>>> In a way the real issue might be that we don’t have nightly performance
>>>>> runs that would make an accidentally introduced debug statement obvious.
>>>> This is an issue, but I don't think it's the *real* issue. As already
>>>> noted, debug logging is for debugging, which normal users shouldn't have to
>>>> think about when they are just operating the software. We shouldn't risk
>>>> performance regressions just for developer convenience.
>>>>
>>>> On 19 March 2018 at 00:55, Ariel Weisberg <ad...@fastmail.fm> wrote:
>>>>
>>>>> Hi,
>>>>>
>>>>> In a way the real issue might be that we don’t have nightly performance
>>>>> runs that would make an accidentally introduced debug statement obvious.
>>>>>
>>>>> A log statement that runs once or more per read or write should be easy
>>>> to
>>>>> spot. I haven’t measured the impact though. And as a bonus by having this
>>>>> we can spot a variety of performance issues introduced by all kinds of
>>>>> changes.
>>>>>
>>>>> Ariel
>>>>>
>>>>>> On Mar 18, 2018, at 3:46 PM, Jeff Jirsa <jj...@gmail.com> wrote:
>>>>>>
>>>>>> In Cassandra-10241 I said I was torn on this whole ticket, since most
>>>>> people would end up turning it off if it had a negative impact. You said:
>>>>>> “I'd like to emphasize that we're not talking about turning debug or
>>>>> trace on for client-generated request paths. There's way too much data
>>>>> generated and it's unlikely to be useful.
>>>>>> What we're proposing is enabling debug logging ONLY for cluster state
>>>>> changes like gossip and schema, and infrequent activities like repair. “
>>>>>> Clearly there’s a disconnect here - we’ve turned debug logging on for
>>>>> everything and shuffled some stuff to trace, which is a one time action
>>>> but
>>>>> is hard to protect against regression. In fact, just looking at the read
>>>>> callback shows two instances of debug log in the client request path
>>>>> (exercise for the reader to “git blame”).
>>>>>> Either we can go clean up all the surprises that leaked through, or we
>>>>> can turn off debug and start backing out some of the changes in 10241.
>>>>> Putting stuff like compaction in the same bucket as digest mismatch and
>>>>> gossip state doesn’t make life materially better for most people.
>>>>>> --
>>>>>> Jeff Jirsa
>>>>>>
>>>>>>
>>>>>>> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com>
>>>> wrote:
>>>>>>> That really depends on whether you're judicious in deciding what to
>>>> log
>>>>> at
>>>>>>> debug, doesn't it?
>>>>>>>
>>>>>>> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <
>>>> kjellman@apple.com>
>>>>>>> wrote:
>>>>>>>
>>>>>>>> +1. this is how it works.
>>>>>>>>
>>>>>>>> your computer doesn’t run at debug logging by default. your phone
>>>>> doesn’t
>>>>>>>> either. neither does your smart tv. your database can’t be running at
>>>>> debug
>>>>>>>> just because it makes our lives as engineers easier.
>>>>>>>>
>>>>>>>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
>>>>>>>> alex@thelastpickle.com> wrote:
>>>>>>>>> It's a tiny bit unusual to turn on debug logging for all users by
>>>>> default
>>>>>>>>> though, and there should be occasions to turn it on when facing
>>>> issues
>>>>>>>> that
>>>>>>>>> you want to debug (if they can be easily reproduced).
>>>>>>>
>>>>>>> --
>>>>>>> Jonathan Ellis
>>>>>>> co-founder, http://www.datastax.com
>>>>>>> @spyced
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>>>>> For additional commands, e-mail: dev-help@cassandra.apache.org
>>>>>
>>>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>> For additional commands, e-mail: dev-help@cassandra.apache.org
>>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Jeremiah D Jordan <je...@datastax.com>]

People seem hung up on DEBUG here.  The goal of CASSANDRA-10241 was
to clean up the system.log so that it a very high “signal” in terms of what was logged
to it synchronously, but without reducing the ability of the logs to allow people to
solve problems and perform post mortem analysis of issues.  We have informational
log messages that are very useful to understanding the state of things, like compaction
status, repair status, flushing, or the state of gossip in the system that are very useful to
operators, but if they are all in the system.log make said log file harder to look over for
issues.  In 10241 the method chosen for how to keep these log messages around by
default, but get them out of the system.log was that these messages were changed from
INFO to DEBUG and the new debug.log was created.

From the discussion here it seems that many would like to change how this works.  Rather
than just turning off the debug.log I would propose that we switch to using the SLF4J
MARKER[1] ability to move the messages back to INFO but tag them as belonging to
the asynchronous_system.log rather than the normal system.log.

[1] https://logback.qos.ch/manual/layouts.html#marker <https://logback.qos.ch/manual/layouts.html#marker>
https://www.slf4j.org/faq.html#fatal <https://www.slf4j.org/faq.html#fatal>


> On Mar 19, 2018, at 9:01 AM, Stefan Podkowinski <sp...@apache.org> wrote:
> 
> I'd agree that INFO should be the default. Turning on the DEBUG logging
> can cause notable performance issues and I would not enable it on
> production systems unless I really have to. That's why I created 
> CASSANDRA-12696 for 4.0, so you'll be able to at least only partially
> enable DEBUG based on what's relevant to look at, e.g. `nodetool
> setlogginglevel bootstrap DEBUG`.
> 
> But small improvements like that won't change the fact that log files
> suck in general for more complex analysis, except for trivial tailing
> and grepping. You have to make sure that logging is enabled and old
> records you're interested in will not be rotated out. Then you have to
> gather log files from individual nodes somehow. Eventually I end up with
> a local tarball with logs in that situation and the fun starts creating
> hacky, regex loaded Python scripts to parse them. As each log message is
> limited to a single line of text, it's often missing out relevant
> details. You also got to create different parsers for different messages
> of course. It's just inefficient and too time consuming to gather
> information that way. Let alone implementing more advanced monitoring
> solutions on top of that.
> 
> That's exactly why I started working on the "diagnostic events"
> (CASSANDRA-12944) idea more than a year ago. There's also support for
> persistency (CASSANDRA-13460) that would implement storing important but
> infrequent events as rich json objects in a local keyspace and allows
> retrieving them by using CQL. I still like the idea and think it's worth
> pursuing.
> 
> 
> On 19.03.18 09:53, Alain RODRIGUEZ wrote:
>> Hello,
>> 
>> I am not developing Cassandra, but I am using it actively and helping
>> people to work with it. My perspective might be missing some code
>> considerations and history as I did not go through the ticket where this
>> 'debug' level was added by default. But here is a feedback after upgrading
>> a few clusters to Cassandra 2.2:
>> 
>> When upgrading a cluster to Cassandra 2.2, 'disable the debug logs' is in
>> my runbook. I mean, very often, when some cluster is upgraded to Cassandra
>> 2.2 and has problems with performances, the 2 most frequent issues are:
>> 
>> - DEBUG level being turned on
>> - and / or dynamic snitching being enabled
>> 
>> This is especially true for high percentile (very clear on p99). Let's put
>> the dynamic snitch aside as it is not our topic here.
>> 
>> From an operational perspective, I prefer to set the debug level to 'DEBUG'
>> when I need it than having, out of the box, something that is unexpected
>> and impact performances. Plus the debug level can be changed without
>> restarting the node, through 'JMX' or even using 'nodetool' now.
>> 
>> Also in most cases, the 'INFO' level is good enough for me to detect most
>> of the issues. I was even able to recreate a detailed history of events for
>> a customer recently, 'INFO' logs are already very powerful and complete I
>> believe (nice work on this by the way). Then monitoring is helping a lot
>> too. I did not have to use debug logs for a long time. It might happen, but
>> I will find my way to enable them.
>> 
>> Even though it feels great to be able to help people with that easily
>> because the cause is often the same and turning off the logs is a
>> low hanging fruit in C*2.2 clusters that have very nice results and is easy
>> to achieve, I would prefer people not to fall into these performances traps
>> in the first place. In my head, 'Debug' logs should be for debug purposes
>> (by opposition to 'always on'). It seems legit. I am surprised this brings
>> so many discussions I thought this was a common standard widely accepted,
>> and beyond Cassandra. That being said, it is good to see those exchanges
>> are happening, so the decision that will be taken will be a good one, I am
>> sure. I hope this comment will help, I have no other goal, for sure I am
>> not willing to feed a conflict but a talk and I hope no one felt offended
>> by this feedback. I believe this change was made aiming at
>> helping/improving things, but it turns out it is more of an annoyance than
>> truly helpful (my personal perspective).
>> 
>> I would +1 on making 'INFO' default again, but if someone is missing
>> information that should be in 'INFO'. If some informations are missing at
>> the 'INFO' level, why not add informations that should be at the 'INFO'
>> level there directly and keep log levels meaningful? Making sure we do not
>> bring the logs degrading performances from 'Debug' to 'Info' as much as we
>> can.
>> 
>> Hope this is useful,
>> 
>> C*heers,
>> 
>> -----------------------
>> Alain Rodriguez - @arodream - alain@thelastpickle.com
>> France / Spain
>> 
>> The Last Pickle - Apache Cassandra Consulting
>> http://www.thelastpickle.com
>> 
>> 2018-03-19 2:18 GMT+00:00 kurt greaves <ku...@instaclustr.com>:
>> 
>>> On the same page as Michael here. We disable debug logs in production due
>>> to the performance impact. Personally I think if debug logging is necessary
>>> for users to use the software we're doing something wrong. Also in my
>>> experience, if something doesn't reproduce it will not get fixed. Debug
>>> logging helps, but I've never seen a case where an actual bug simply
>>> *doesn't* reproduce eventually, and I'm sure if this issue appears debug
>>> logging could be enabled after the fact for the relevant classes and
>>> eventually it will reoccur and we could solve the problem. I've never seen
>>> a user say no to helping debug a problem with patched jars/changes to their
>>> system (like logging). I'd much prefer we pushed that harder rather than
>>> just saying "Everyone gets debug logging!". I'm also really not sold that
>>> debug logging saves the day. To me it mostly just speeds up the
>>> identification process, it generally doesn't expose magical information
>>> that wasn't available before, you just had to think about it a bit more.
>>> 
>>> 
>>> In a way the real issue might be that we don’t have nightly performance
>>>> runs that would make an accidentally introduced debug statement obvious.
>>> This is an issue, but I don't think it's the *real* issue. As already
>>> noted, debug logging is for debugging, which normal users shouldn't have to
>>> think about when they are just operating the software. We shouldn't risk
>>> performance regressions just for developer convenience.
>>> 
>>> On 19 March 2018 at 00:55, Ariel Weisberg <ad...@fastmail.fm> wrote:
>>> 
>>>> Hi,
>>>> 
>>>> In a way the real issue might be that we don’t have nightly performance
>>>> runs that would make an accidentally introduced debug statement obvious.
>>>> 
>>>> A log statement that runs once or more per read or write should be easy
>>> to
>>>> spot. I haven’t measured the impact though. And as a bonus by having this
>>>> we can spot a variety of performance issues introduced by all kinds of
>>>> changes.
>>>> 
>>>> Ariel
>>>> 
>>>>> On Mar 18, 2018, at 3:46 PM, Jeff Jirsa <jj...@gmail.com> wrote:
>>>>> 
>>>>> In Cassandra-10241 I said I was torn on this whole ticket, since most
>>>> people would end up turning it off if it had a negative impact. You said:
>>>>> “I'd like to emphasize that we're not talking about turning debug or
>>>> trace on for client-generated request paths. There's way too much data
>>>> generated and it's unlikely to be useful.
>>>>> What we're proposing is enabling debug logging ONLY for cluster state
>>>> changes like gossip and schema, and infrequent activities like repair. “
>>>>> Clearly there’s a disconnect here - we’ve turned debug logging on for
>>>> everything and shuffled some stuff to trace, which is a one time action
>>> but
>>>> is hard to protect against regression. In fact, just looking at the read
>>>> callback shows two instances of debug log in the client request path
>>>> (exercise for the reader to “git blame”).
>>>>> Either we can go clean up all the surprises that leaked through, or we
>>>> can turn off debug and start backing out some of the changes in 10241.
>>>> Putting stuff like compaction in the same bucket as digest mismatch and
>>>> gossip state doesn’t make life materially better for most people.
>>>>> --
>>>>> Jeff Jirsa
>>>>> 
>>>>> 
>>>>>> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com>
>>> wrote:
>>>>>> That really depends on whether you're judicious in deciding what to
>>> log
>>>> at
>>>>>> debug, doesn't it?
>>>>>> 
>>>>>> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <
>>> kjellman@apple.com>
>>>>>> wrote:
>>>>>> 
>>>>>>> +1. this is how it works.
>>>>>>> 
>>>>>>> your computer doesn’t run at debug logging by default. your phone
>>>> doesn’t
>>>>>>> either. neither does your smart tv. your database can’t be running at
>>>> debug
>>>>>>> just because it makes our lives as engineers easier.
>>>>>>> 
>>>>>>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
>>>>>>> alex@thelastpickle.com> wrote:
>>>>>>>> It's a tiny bit unusual to turn on debug logging for all users by
>>>> default
>>>>>>>> though, and there should be occasions to turn it on when facing
>>> issues
>>>>>>> that
>>>>>>>> you want to debug (if they can be easily reproduced).
>>>>>> 
>>>>>> --
>>>>>> Jonathan Ellis
>>>>>> co-founder, http://www.datastax.com
>>>>>> @spyced
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>>>> For additional commands, e-mail: dev-help@cassandra.apache.org
>>>> 
>>>> 
> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
> 

Re: Debug logging enabled by default since 2.2

[Stefan Podkowinski <sp...@apache.org>]

I'd agree that INFO should be the default. Turning on the DEBUG logging
can cause notable performance issues and I would not enable it on
production systems unless I really have to. That's why I created 
CASSANDRA-12696 for 4.0, so you'll be able to at least only partially
enable DEBUG based on what's relevant to look at, e.g. `nodetool
setlogginglevel bootstrap DEBUG`.

But small improvements like that won't change the fact that log files
suck in general for more complex analysis, except for trivial tailing
and grepping. You have to make sure that logging is enabled and old
records you're interested in will not be rotated out. Then you have to
gather log files from individual nodes somehow. Eventually I end up with
a local tarball with logs in that situation and the fun starts creating
hacky, regex loaded Python scripts to parse them. As each log message is
limited to a single line of text, it's often missing out relevant
details. You also got to create different parsers for different messages
of course. It's just inefficient and too time consuming to gather
information that way. Let alone implementing more advanced monitoring
solutions on top of that.

That's exactly why I started working on the "diagnostic events"
(CASSANDRA-12944) idea more than a year ago. There's also support for
persistency (CASSANDRA-13460) that would implement storing important but
infrequent events as rich json objects in a local keyspace and allows
retrieving them by using CQL. I still like the idea and think it's worth
pursuing.


On 19.03.18 09:53, Alain RODRIGUEZ wrote:
> Hello,
>
> I am not developing Cassandra, but I am using it actively and helping
> people to work with it. My perspective might be missing some code
> considerations and history as I did not go through the ticket where this
> 'debug' level was added by default. But here is a feedback after upgrading
> a few clusters to Cassandra 2.2:
>
> When upgrading a cluster to Cassandra 2.2, 'disable the debug logs' is in
> my runbook. I mean, very often, when some cluster is upgraded to Cassandra
> 2.2 and has problems with performances, the 2 most frequent issues are:
>
> - DEBUG level being turned on
> - and / or dynamic snitching being enabled
>
> This is especially true for high percentile (very clear on p99). Let's put
> the dynamic snitch aside as it is not our topic here.
>
> From an operational perspective, I prefer to set the debug level to 'DEBUG'
> when I need it than having, out of the box, something that is unexpected
> and impact performances. Plus the debug level can be changed without
> restarting the node, through 'JMX' or even using 'nodetool' now.
>
> Also in most cases, the 'INFO' level is good enough for me to detect most
> of the issues. I was even able to recreate a detailed history of events for
> a customer recently, 'INFO' logs are already very powerful and complete I
> believe (nice work on this by the way). Then monitoring is helping a lot
> too. I did not have to use debug logs for a long time. It might happen, but
> I will find my way to enable them.
>
> Even though it feels great to be able to help people with that easily
> because the cause is often the same and turning off the logs is a
> low hanging fruit in C*2.2 clusters that have very nice results and is easy
> to achieve, I would prefer people not to fall into these performances traps
> in the first place. In my head, 'Debug' logs should be for debug purposes
> (by opposition to 'always on'). It seems legit. I am surprised this brings
> so many discussions I thought this was a common standard widely accepted,
> and beyond Cassandra. That being said, it is good to see those exchanges
> are happening, so the decision that will be taken will be a good one, I am
> sure. I hope this comment will help, I have no other goal, for sure I am
> not willing to feed a conflict but a talk and I hope no one felt offended
> by this feedback. I believe this change was made aiming at
> helping/improving things, but it turns out it is more of an annoyance than
> truly helpful (my personal perspective).
>
> I would +1 on making 'INFO' default again, but if someone is missing
> information that should be in 'INFO'. If some informations are missing at
> the 'INFO' level, why not add informations that should be at the 'INFO'
> level there directly and keep log levels meaningful? Making sure we do not
> bring the logs degrading performances from 'Debug' to 'Info' as much as we
> can.
>
> Hope this is useful,
>
> C*heers,
>
> -----------------------
> Alain Rodriguez - @arodream - alain@thelastpickle.com
> France / Spain
>
> The Last Pickle - Apache Cassandra Consulting
> http://www.thelastpickle.com
>
> 2018-03-19 2:18 GMT+00:00 kurt greaves <ku...@instaclustr.com>:
>
>> On the same page as Michael here. We disable debug logs in production due
>> to the performance impact. Personally I think if debug logging is necessary
>> for users to use the software we're doing something wrong. Also in my
>> experience, if something doesn't reproduce it will not get fixed. Debug
>> logging helps, but I've never seen a case where an actual bug simply
>> *doesn't* reproduce eventually, and I'm sure if this issue appears debug
>> logging could be enabled after the fact for the relevant classes and
>> eventually it will reoccur and we could solve the problem. I've never seen
>> a user say no to helping debug a problem with patched jars/changes to their
>> system (like logging). I'd much prefer we pushed that harder rather than
>> just saying "Everyone gets debug logging!". I'm also really not sold that
>> debug logging saves the day. To me it mostly just speeds up the
>> identification process, it generally doesn't expose magical information
>> that wasn't available before, you just had to think about it a bit more.
>>
>>
>> In a way the real issue might be that we don’t have nightly performance
>>> runs that would make an accidentally introduced debug statement obvious.
>> This is an issue, but I don't think it's the *real* issue. As already
>> noted, debug logging is for debugging, which normal users shouldn't have to
>> think about when they are just operating the software. We shouldn't risk
>> performance regressions just for developer convenience.
>>
>> On 19 March 2018 at 00:55, Ariel Weisberg <ad...@fastmail.fm> wrote:
>>
>>> Hi,
>>>
>>> In a way the real issue might be that we don’t have nightly performance
>>> runs that would make an accidentally introduced debug statement obvious.
>>>
>>> A log statement that runs once or more per read or write should be easy
>> to
>>> spot. I haven’t measured the impact though. And as a bonus by having this
>>> we can spot a variety of performance issues introduced by all kinds of
>>> changes.
>>>
>>> Ariel
>>>
>>>> On Mar 18, 2018, at 3:46 PM, Jeff Jirsa <jj...@gmail.com> wrote:
>>>>
>>>> In Cassandra-10241 I said I was torn on this whole ticket, since most
>>> people would end up turning it off if it had a negative impact. You said:
>>>> “I'd like to emphasize that we're not talking about turning debug or
>>> trace on for client-generated request paths. There's way too much data
>>> generated and it's unlikely to be useful.
>>>> What we're proposing is enabling debug logging ONLY for cluster state
>>> changes like gossip and schema, and infrequent activities like repair. “
>>>> Clearly there’s a disconnect here - we’ve turned debug logging on for
>>> everything and shuffled some stuff to trace, which is a one time action
>> but
>>> is hard to protect against regression. In fact, just looking at the read
>>> callback shows two instances of debug log in the client request path
>>> (exercise for the reader to “git blame”).
>>>> Either we can go clean up all the surprises that leaked through, or we
>>> can turn off debug and start backing out some of the changes in 10241.
>>> Putting stuff like compaction in the same bucket as digest mismatch and
>>> gossip state doesn’t make life materially better for most people.
>>>> --
>>>> Jeff Jirsa
>>>>
>>>>
>>>>> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com>
>> wrote:
>>>>> That really depends on whether you're judicious in deciding what to
>> log
>>> at
>>>>> debug, doesn't it?
>>>>>
>>>>> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <
>> kjellman@apple.com>
>>>>> wrote:
>>>>>
>>>>>> +1. this is how it works.
>>>>>>
>>>>>> your computer doesn’t run at debug logging by default. your phone
>>> doesn’t
>>>>>> either. neither does your smart tv. your database can’t be running at
>>> debug
>>>>>> just because it makes our lives as engineers easier.
>>>>>>
>>>>>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
>>>>>> alex@thelastpickle.com> wrote:
>>>>>>> It's a tiny bit unusual to turn on debug logging for all users by
>>> default
>>>>>>> though, and there should be occasions to turn it on when facing
>> issues
>>>>>> that
>>>>>>> you want to debug (if they can be easily reproduced).
>>>>>
>>>>> --
>>>>> Jonathan Ellis
>>>>> co-founder, http://www.datastax.com
>>>>> @spyced
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>>> For additional commands, e-mail: dev-help@cassandra.apache.org
>>>
>>>


---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Josh McKenzie <jm...@apache.org>]

>
> In a way the real issue might be that we don’t have nightly performance
> runs that would make an accidentally introduced debug statement obvious.

First off, very much this.

Secondly, IMO it's inconsistent to leave / use assertions in a code-base as
a mix of preconditions and assertions but then disable debug logging as
it's currently used post C-10241. Either we trust our code-base to work and
protect itself against bad inputs or we don't, and our current collective
lack of trust (or rather conflation of concerns under single tools (asserts
/ debug logs)) has performance implications. Seems like adding a log level
not named DEBUG + perf regression testing + running latest version of 2.2
would make all this a non-issue.

Also, let me quote Brandon here:

It seems to me the power user who wants to eek out that last bit of
> performance can do so.  It also seems like the user who doesn't even know
> about that is the exact kind of user that's going to need the debug log in
> the future.


With where things are right now, sure seems like a "if it ain't broke" type
scenario.

On Mon, Mar 19, 2018 at 4:53 AM, Alain RODRIGUEZ <ar...@gmail.com> wrote:

> Hello,
>
> I am not developing Cassandra, but I am using it actively and helping
> people to work with it. My perspective might be missing some code
> considerations and history as I did not go through the ticket where this
> 'debug' level was added by default. But here is a feedback after upgrading
> a few clusters to Cassandra 2.2:
>
> When upgrading a cluster to Cassandra 2.2, 'disable the debug logs' is in
> my runbook. I mean, very often, when some cluster is upgraded to Cassandra
> 2.2 and has problems with performances, the 2 most frequent issues are:
>
> - DEBUG level being turned on
> - and / or dynamic snitching being enabled
>
> This is especially true for high percentile (very clear on p99). Let's put
> the dynamic snitch aside as it is not our topic here.
>
> From an operational perspective, I prefer to set the debug level to 'DEBUG'
> when I need it than having, out of the box, something that is unexpected
> and impact performances. Plus the debug level can be changed without
> restarting the node, through 'JMX' or even using 'nodetool' now.
>
> Also in most cases, the 'INFO' level is good enough for me to detect most
> of the issues. I was even able to recreate a detailed history of events for
> a customer recently, 'INFO' logs are already very powerful and complete I
> believe (nice work on this by the way). Then monitoring is helping a lot
> too. I did not have to use debug logs for a long time. It might happen, but
> I will find my way to enable them.
>
> Even though it feels great to be able to help people with that easily
> because the cause is often the same and turning off the logs is a
> low hanging fruit in C*2.2 clusters that have very nice results and is easy
> to achieve, I would prefer people not to fall into these performances traps
> in the first place. In my head, 'Debug' logs should be for debug purposes
> (by opposition to 'always on'). It seems legit. I am surprised this brings
> so many discussions I thought this was a common standard widely accepted,
> and beyond Cassandra. That being said, it is good to see those exchanges
> are happening, so the decision that will be taken will be a good one, I am
> sure. I hope this comment will help, I have no other goal, for sure I am
> not willing to feed a conflict but a talk and I hope no one felt offended
> by this feedback. I believe this change was made aiming at
> helping/improving things, but it turns out it is more of an annoyance than
> truly helpful (my personal perspective).
>
> I would +1 on making 'INFO' default again, but if someone is missing
> information that should be in 'INFO'. If some informations are missing at
> the 'INFO' level, why not add informations that should be at the 'INFO'
> level there directly and keep log levels meaningful? Making sure we do not
> bring the logs degrading performances from 'Debug' to 'Info' as much as we
> can.
>
> Hope this is useful,
>
> C*heers,
>
> -----------------------
> Alain Rodriguez - @arodream - alain@thelastpickle.com
> France / Spain
>
> The Last Pickle - Apache Cassandra Consulting
> http://www.thelastpickle.com
>
> 2018-03-19 2:18 GMT+00:00 kurt greaves <ku...@instaclustr.com>:
>
> > On the same page as Michael here. We disable debug logs in production due
> > to the performance impact. Personally I think if debug logging is
> necessary
> > for users to use the software we're doing something wrong. Also in my
> > experience, if something doesn't reproduce it will not get fixed. Debug
> > logging helps, but I've never seen a case where an actual bug simply
> > *doesn't* reproduce eventually, and I'm sure if this issue appears debug
> > logging could be enabled after the fact for the relevant classes and
> > eventually it will reoccur and we could solve the problem. I've never
> seen
> > a user say no to helping debug a problem with patched jars/changes to
> their
> > system (like logging). I'd much prefer we pushed that harder rather than
> > just saying "Everyone gets debug logging!". I'm also really not sold that
> > debug logging saves the day. To me it mostly just speeds up the
> > identification process, it generally doesn't expose magical information
> > that wasn't available before, you just had to think about it a bit more.
> >
> >
> > In a way the real issue might be that we don’t have nightly performance
> > > runs that would make an accidentally introduced debug statement
> obvious.
> >
> > This is an issue, but I don't think it's the *real* issue. As already
> > noted, debug logging is for debugging, which normal users shouldn't have
> to
> > think about when they are just operating the software. We shouldn't risk
> > performance regressions just for developer convenience.
> >
> > On 19 March 2018 at 00:55, Ariel Weisberg <ad...@fastmail.fm> wrote:
> >
> > > Hi,
> > >
> > > In a way the real issue might be that we don’t have nightly performance
> > > runs that would make an accidentally introduced debug statement
> obvious.
> > >
> > > A log statement that runs once or more per read or write should be easy
> > to
> > > spot. I haven’t measured the impact though. And as a bonus by having
> this
> > > we can spot a variety of performance issues introduced by all kinds of
> > > changes.
> > >
> > > Ariel
> > >
> > > > On Mar 18, 2018, at 3:46 PM, Jeff Jirsa <jj...@gmail.com> wrote:
> > > >
> > > > In Cassandra-10241 I said I was torn on this whole ticket, since most
> > > people would end up turning it off if it had a negative impact. You
> said:
> > > >
> > > > “I'd like to emphasize that we're not talking about turning debug or
> > > trace on for client-generated request paths. There's way too much data
> > > generated and it's unlikely to be useful.
> > > > What we're proposing is enabling debug logging ONLY for cluster state
> > > changes like gossip and schema, and infrequent activities like repair.
> “
> > > >
> > > > Clearly there’s a disconnect here - we’ve turned debug logging on for
> > > everything and shuffled some stuff to trace, which is a one time action
> > but
> > > is hard to protect against regression. In fact, just looking at the
> read
> > > callback shows two instances of debug log in the client request path
> > > (exercise for the reader to “git blame”).
> > > >
> > > > Either we can go clean up all the surprises that leaked through, or
> we
> > > can turn off debug and start backing out some of the changes in 10241.
> > > Putting stuff like compaction in the same bucket as digest mismatch and
> > > gossip state doesn’t make life materially better for most people.
> > > >
> > > >
> > > > --
> > > > Jeff Jirsa
> > > >
> > > >
> > > >> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com>
> > wrote:
> > > >>
> > > >> That really depends on whether you're judicious in deciding what to
> > log
> > > at
> > > >> debug, doesn't it?
> > > >>
> > > >> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <
> > kjellman@apple.com>
> > > >> wrote:
> > > >>
> > > >>> +1. this is how it works.
> > > >>>
> > > >>> your computer doesn’t run at debug logging by default. your phone
> > > doesn’t
> > > >>> either. neither does your smart tv. your database can’t be running
> at
> > > debug
> > > >>> just because it makes our lives as engineers easier.
> > > >>>
> > > >>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
> > > >>> alex@thelastpickle.com> wrote:
> > > >>>>
> > > >>>> It's a tiny bit unusual to turn on debug logging for all users by
> > > default
> > > >>>> though, and there should be occasions to turn it on when facing
> > issues
> > > >>> that
> > > >>>> you want to debug (if they can be easily reproduced).
> > > >>>
> > > >>
> > > >>
> > > >>
> > > >> --
> > > >> Jonathan Ellis
> > > >> co-founder, http://www.datastax.com
> > > >> @spyced
> > >
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > > For additional commands, e-mail: dev-help@cassandra.apache.org
> > >
> > >
> >
>

Re: Debug logging enabled by default since 2.2

[Alain RODRIGUEZ <ar...@gmail.com>]

Hello,

I am not developing Cassandra, but I am using it actively and helping
people to work with it. My perspective might be missing some code
considerations and history as I did not go through the ticket where this
'debug' level was added by default. But here is a feedback after upgrading
a few clusters to Cassandra 2.2:

When upgrading a cluster to Cassandra 2.2, 'disable the debug logs' is in
my runbook. I mean, very often, when some cluster is upgraded to Cassandra
2.2 and has problems with performances, the 2 most frequent issues are:

- DEBUG level being turned on
- and / or dynamic snitching being enabled

This is especially true for high percentile (very clear on p99). Let's put
the dynamic snitch aside as it is not our topic here.

From an operational perspective, I prefer to set the debug level to 'DEBUG'
when I need it than having, out of the box, something that is unexpected
and impact performances. Plus the debug level can be changed without
restarting the node, through 'JMX' or even using 'nodetool' now.

Also in most cases, the 'INFO' level is good enough for me to detect most
of the issues. I was even able to recreate a detailed history of events for
a customer recently, 'INFO' logs are already very powerful and complete I
believe (nice work on this by the way). Then monitoring is helping a lot
too. I did not have to use debug logs for a long time. It might happen, but
I will find my way to enable them.

Even though it feels great to be able to help people with that easily
because the cause is often the same and turning off the logs is a
low hanging fruit in C*2.2 clusters that have very nice results and is easy
to achieve, I would prefer people not to fall into these performances traps
in the first place. In my head, 'Debug' logs should be for debug purposes
(by opposition to 'always on'). It seems legit. I am surprised this brings
so many discussions I thought this was a common standard widely accepted,
and beyond Cassandra. That being said, it is good to see those exchanges
are happening, so the decision that will be taken will be a good one, I am
sure. I hope this comment will help, I have no other goal, for sure I am
not willing to feed a conflict but a talk and I hope no one felt offended
by this feedback. I believe this change was made aiming at
helping/improving things, but it turns out it is more of an annoyance than
truly helpful (my personal perspective).

I would +1 on making 'INFO' default again, but if someone is missing
information that should be in 'INFO'. If some informations are missing at
the 'INFO' level, why not add informations that should be at the 'INFO'
level there directly and keep log levels meaningful? Making sure we do not
bring the logs degrading performances from 'Debug' to 'Info' as much as we
can.

Hope this is useful,

C*heers,

-----------------------
Alain Rodriguez - @arodream - alain@thelastpickle.com
France / Spain

The Last Pickle - Apache Cassandra Consulting
http://www.thelastpickle.com

2018-03-19 2:18 GMT+00:00 kurt greaves <ku...@instaclustr.com>:

> On the same page as Michael here. We disable debug logs in production due
> to the performance impact. Personally I think if debug logging is necessary
> for users to use the software we're doing something wrong. Also in my
> experience, if something doesn't reproduce it will not get fixed. Debug
> logging helps, but I've never seen a case where an actual bug simply
> *doesn't* reproduce eventually, and I'm sure if this issue appears debug
> logging could be enabled after the fact for the relevant classes and
> eventually it will reoccur and we could solve the problem. I've never seen
> a user say no to helping debug a problem with patched jars/changes to their
> system (like logging). I'd much prefer we pushed that harder rather than
> just saying "Everyone gets debug logging!". I'm also really not sold that
> debug logging saves the day. To me it mostly just speeds up the
> identification process, it generally doesn't expose magical information
> that wasn't available before, you just had to think about it a bit more.
>
>
> In a way the real issue might be that we don’t have nightly performance
> > runs that would make an accidentally introduced debug statement obvious.
>
> This is an issue, but I don't think it's the *real* issue. As already
> noted, debug logging is for debugging, which normal users shouldn't have to
> think about when they are just operating the software. We shouldn't risk
> performance regressions just for developer convenience.
>
> On 19 March 2018 at 00:55, Ariel Weisberg <ad...@fastmail.fm> wrote:
>
> > Hi,
> >
> > In a way the real issue might be that we don’t have nightly performance
> > runs that would make an accidentally introduced debug statement obvious.
> >
> > A log statement that runs once or more per read or write should be easy
> to
> > spot. I haven’t measured the impact though. And as a bonus by having this
> > we can spot a variety of performance issues introduced by all kinds of
> > changes.
> >
> > Ariel
> >
> > > On Mar 18, 2018, at 3:46 PM, Jeff Jirsa <jj...@gmail.com> wrote:
> > >
> > > In Cassandra-10241 I said I was torn on this whole ticket, since most
> > people would end up turning it off if it had a negative impact. You said:
> > >
> > > “I'd like to emphasize that we're not talking about turning debug or
> > trace on for client-generated request paths. There's way too much data
> > generated and it's unlikely to be useful.
> > > What we're proposing is enabling debug logging ONLY for cluster state
> > changes like gossip and schema, and infrequent activities like repair. “
> > >
> > > Clearly there’s a disconnect here - we’ve turned debug logging on for
> > everything and shuffled some stuff to trace, which is a one time action
> but
> > is hard to protect against regression. In fact, just looking at the read
> > callback shows two instances of debug log in the client request path
> > (exercise for the reader to “git blame”).
> > >
> > > Either we can go clean up all the surprises that leaked through, or we
> > can turn off debug and start backing out some of the changes in 10241.
> > Putting stuff like compaction in the same bucket as digest mismatch and
> > gossip state doesn’t make life materially better for most people.
> > >
> > >
> > > --
> > > Jeff Jirsa
> > >
> > >
> > >> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com>
> wrote:
> > >>
> > >> That really depends on whether you're judicious in deciding what to
> log
> > at
> > >> debug, doesn't it?
> > >>
> > >> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <
> kjellman@apple.com>
> > >> wrote:
> > >>
> > >>> +1. this is how it works.
> > >>>
> > >>> your computer doesn’t run at debug logging by default. your phone
> > doesn’t
> > >>> either. neither does your smart tv. your database can’t be running at
> > debug
> > >>> just because it makes our lives as engineers easier.
> > >>>
> > >>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
> > >>> alex@thelastpickle.com> wrote:
> > >>>>
> > >>>> It's a tiny bit unusual to turn on debug logging for all users by
> > default
> > >>>> though, and there should be occasions to turn it on when facing
> issues
> > >>> that
> > >>>> you want to debug (if they can be easily reproduced).
> > >>>
> > >>
> > >>
> > >>
> > >> --
> > >> Jonathan Ellis
> > >> co-founder, http://www.datastax.com
> > >> @spyced
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > For additional commands, e-mail: dev-help@cassandra.apache.org
> >
> >
>

RE: Debug logging enabled by default since 2.2

[Jacques-Henri Berthemet <ja...@genesys.com>]

If debug log is not a real debug then you should rename it to something else, maybe production.log. Also, I have the impression that all logs in system.log are also contained in debug.log so it's not really useful.

I feel that be moving all verbose debug logs to trace we're losing the good info in debug logs. I've been trying to troubleshoot issues from our QA and debug.log didn't really help me.

From my point of view there should be a single log file, defaults to info. Debug level should contain all useful info even if it means lower performance, trace should contain all possible relevant info. If some loggers (or groups) are known to cause huge performance hits they should be disabled by default.
--
Jacques-Henri Berthemet

-----Original Message-----
From: kurt greaves [mailto:kurt@instaclustr.com] 
Sent: Monday, March 19, 2018 3:18 AM
To: dev@cassandra.apache.org
Subject: Re: Debug logging enabled by default since 2.2

On the same page as Michael here. We disable debug logs in production due to the performance impact. Personally I think if debug logging is necessary for users to use the software we're doing something wrong. Also in my experience, if something doesn't reproduce it will not get fixed. Debug logging helps, but I've never seen a case where an actual bug simply
*doesn't* reproduce eventually, and I'm sure if this issue appears debug logging could be enabled after the fact for the relevant classes and eventually it will reoccur and we could solve the problem. I've never seen a user say no to helping debug a problem with patched jars/changes to their system (like logging). I'd much prefer we pushed that harder rather than just saying "Everyone gets debug logging!". I'm also really not sold that debug logging saves the day. To me it mostly just speeds up the identification process, it generally doesn't expose magical information that wasn't available before, you just had to think about it a bit more.


In a way the real issue might be that we don’t have nightly performance
> runs that would make an accidentally introduced debug statement obvious.

This is an issue, but I don't think it's the *real* issue. As already noted, debug logging is for debugging, which normal users shouldn't have to think about when they are just operating the software. We shouldn't risk performance regressions just for developer convenience.

On 19 March 2018 at 00:55, Ariel Weisberg <ad...@fastmail.fm> wrote:

> Hi,
>
> In a way the real issue might be that we don’t have nightly 
> performance runs that would make an accidentally introduced debug statement obvious.
>
> A log statement that runs once or more per read or write should be 
> easy to spot. I haven’t measured the impact though. And as a bonus by 
> having this we can spot a variety of performance issues introduced by 
> all kinds of changes.
>
> Ariel
>
> > On Mar 18, 2018, at 3:46 PM, Jeff Jirsa <jj...@gmail.com> wrote:
> >
> > In Cassandra-10241 I said I was torn on this whole ticket, since 
> > most
> people would end up turning it off if it had a negative impact. You said:
> >
> > “I'd like to emphasize that we're not talking about turning debug or
> trace on for client-generated request paths. There's way too much data 
> generated and it's unlikely to be useful.
> > What we're proposing is enabling debug logging ONLY for cluster 
> > state
> changes like gossip and schema, and infrequent activities like repair. 
> “
> >
> > Clearly there’s a disconnect here - we’ve turned debug logging on 
> > for
> everything and shuffled some stuff to trace, which is a one time 
> action but is hard to protect against regression. In fact, just 
> looking at the read callback shows two instances of debug log in the 
> client request path (exercise for the reader to “git blame”).
> >
> > Either we can go clean up all the surprises that leaked through, or 
> > we
> can turn off debug and start backing out some of the changes in 10241.
> Putting stuff like compaction in the same bucket as digest mismatch 
> and gossip state doesn’t make life materially better for most people.
> >
> >
> > --
> > Jeff Jirsa
> >
> >
> >> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com> wrote:
> >>
> >> That really depends on whether you're judicious in deciding what to 
> >> log
> at
> >> debug, doesn't it?
> >>
> >> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman 
> >> <kj...@apple.com>
> >> wrote:
> >>
> >>> +1. this is how it works.
> >>>
> >>> your computer doesn’t run at debug logging by default. your phone
> doesn’t
> >>> either. neither does your smart tv. your database can’t be running 
> >>> at
> debug
> >>> just because it makes our lives as engineers easier.
> >>>
> >>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
> >>> alex@thelastpickle.com> wrote:
> >>>>
> >>>> It's a tiny bit unusual to turn on debug logging for all users by
> default
> >>>> though, and there should be occasions to turn it on when facing 
> >>>> issues
> >>> that
> >>>> you want to debug (if they can be easily reproduced).
> >>>
> >>
> >>
> >>
> >> --
> >> Jonathan Ellis
> >> co-founder, 
> >> http://www.datastax.com
> >> astax.com
> >> @spyced
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
>
>

Re: Debug logging enabled by default since 2.2

[kurt greaves <ku...@instaclustr.com>]

On the same page as Michael here. We disable debug logs in production due
to the performance impact. Personally I think if debug logging is necessary
for users to use the software we're doing something wrong. Also in my
experience, if something doesn't reproduce it will not get fixed. Debug
logging helps, but I've never seen a case where an actual bug simply
*doesn't* reproduce eventually, and I'm sure if this issue appears debug
logging could be enabled after the fact for the relevant classes and
eventually it will reoccur and we could solve the problem. I've never seen
a user say no to helping debug a problem with patched jars/changes to their
system (like logging). I'd much prefer we pushed that harder rather than
just saying "Everyone gets debug logging!". I'm also really not sold that
debug logging saves the day. To me it mostly just speeds up the
identification process, it generally doesn't expose magical information
that wasn't available before, you just had to think about it a bit more.


In a way the real issue might be that we don’t have nightly performance
> runs that would make an accidentally introduced debug statement obvious.

This is an issue, but I don't think it's the *real* issue. As already
noted, debug logging is for debugging, which normal users shouldn't have to
think about when they are just operating the software. We shouldn't risk
performance regressions just for developer convenience.

On 19 March 2018 at 00:55, Ariel Weisberg <ad...@fastmail.fm> wrote:

> Hi,
>
> In a way the real issue might be that we don’t have nightly performance
> runs that would make an accidentally introduced debug statement obvious.
>
> A log statement that runs once or more per read or write should be easy to
> spot. I haven’t measured the impact though. And as a bonus by having this
> we can spot a variety of performance issues introduced by all kinds of
> changes.
>
> Ariel
>
> > On Mar 18, 2018, at 3:46 PM, Jeff Jirsa <jj...@gmail.com> wrote:
> >
> > In Cassandra-10241 I said I was torn on this whole ticket, since most
> people would end up turning it off if it had a negative impact. You said:
> >
> > “I'd like to emphasize that we're not talking about turning debug or
> trace on for client-generated request paths. There's way too much data
> generated and it's unlikely to be useful.
> > What we're proposing is enabling debug logging ONLY for cluster state
> changes like gossip and schema, and infrequent activities like repair. “
> >
> > Clearly there’s a disconnect here - we’ve turned debug logging on for
> everything and shuffled some stuff to trace, which is a one time action but
> is hard to protect against regression. In fact, just looking at the read
> callback shows two instances of debug log in the client request path
> (exercise for the reader to “git blame”).
> >
> > Either we can go clean up all the surprises that leaked through, or we
> can turn off debug and start backing out some of the changes in 10241.
> Putting stuff like compaction in the same bucket as digest mismatch and
> gossip state doesn’t make life materially better for most people.
> >
> >
> > --
> > Jeff Jirsa
> >
> >
> >> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com> wrote:
> >>
> >> That really depends on whether you're judicious in deciding what to log
> at
> >> debug, doesn't it?
> >>
> >> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <kj...@apple.com>
> >> wrote:
> >>
> >>> +1. this is how it works.
> >>>
> >>> your computer doesn’t run at debug logging by default. your phone
> doesn’t
> >>> either. neither does your smart tv. your database can’t be running at
> debug
> >>> just because it makes our lives as engineers easier.
> >>>
> >>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
> >>> alex@thelastpickle.com> wrote:
> >>>>
> >>>> It's a tiny bit unusual to turn on debug logging for all users by
> default
> >>>> though, and there should be occasions to turn it on when facing issues
> >>> that
> >>>> you want to debug (if they can be easily reproduced).
> >>>
> >>
> >>
> >>
> >> --
> >> Jonathan Ellis
> >> co-founder, http://www.datastax.com
> >> @spyced
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
>
>

Re: Debug logging enabled by default since 2.2

[Ariel Weisberg <ad...@fastmail.fm>]

Hi,

In a way the real issue might be that we don’t have nightly performance runs that would make an accidentally introduced debug statement obvious.

A log statement that runs once or more per read or write should be easy to spot. I haven’t measured the impact though. And as a bonus by having this we can spot a variety of performance issues introduced by all kinds of changes.

Ariel

> On Mar 18, 2018, at 3:46 PM, Jeff Jirsa <jj...@gmail.com> wrote:
> 
> In Cassandra-10241 I said I was torn on this whole ticket, since most people would end up turning it off if it had a negative impact. You said:
> 
> “I'd like to emphasize that we're not talking about turning debug or trace on for client-generated request paths. There's way too much data generated and it's unlikely to be useful.
> What we're proposing is enabling debug logging ONLY for cluster state changes like gossip and schema, and infrequent activities like repair. “
> 
> Clearly there’s a disconnect here - we’ve turned debug logging on for everything and shuffled some stuff to trace, which is a one time action but is hard to protect against regression. In fact, just looking at the read callback shows two instances of debug log in the client request path (exercise for the reader to “git blame”).
> 
> Either we can go clean up all the surprises that leaked through, or we can turn off debug and start backing out some of the changes in 10241. Putting stuff like compaction in the same bucket as digest mismatch and gossip state doesn’t make life materially better for most people.
> 
> 
> -- 
> Jeff Jirsa
> 
> 
>> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com> wrote:
>> 
>> That really depends on whether you're judicious in deciding what to log at
>> debug, doesn't it?
>> 
>> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <kj...@apple.com>
>> wrote:
>> 
>>> +1. this is how it works.
>>> 
>>> your computer doesn’t run at debug logging by default. your phone doesn’t
>>> either. neither does your smart tv. your database can’t be running at debug
>>> just because it makes our lives as engineers easier.
>>> 
>>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
>>> alex@thelastpickle.com> wrote:
>>>> 
>>>> It's a tiny bit unusual to turn on debug logging for all users by default
>>>> though, and there should be occasions to turn it on when facing issues
>>> that
>>>> you want to debug (if they can be easily reproduced).
>>> 
>> 
>> 
>> 
>> -- 
>> Jonathan Ellis
>> co-founder, http://www.datastax.com
>> @spyced


---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Jeff Jirsa <jj...@gmail.com>]

In Cassandra-10241 I said I was torn on this whole ticket, since most people would end up turning it off if it had a negative impact. You said:

“I'd like to emphasize that we're not talking about turning debug or trace on for client-generated request paths. There's way too much data generated and it's unlikely to be useful.
What we're proposing is enabling debug logging ONLY for cluster state changes like gossip and schema, and infrequent activities like repair. “

Clearly there’s a disconnect here - we’ve turned debug logging on for everything and shuffled some stuff to trace, which is a one time action but is hard to protect against regression. In fact, just looking at the read callback shows two instances of debug log in the client request path (exercise for the reader to “git blame”).

Either we can go clean up all the surprises that leaked through, or we can turn off debug and start backing out some of the changes in 10241. Putting stuff like compaction in the same bucket as digest mismatch and gossip state doesn’t make life materially better for most people.


-- 
Jeff Jirsa


> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com> wrote:
> 
> That really depends on whether you're judicious in deciding what to log at
> debug, doesn't it?
> 
> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <kj...@apple.com>
> wrote:
> 
>> +1. this is how it works.
>> 
>> your computer doesn’t run at debug logging by default. your phone doesn’t
>> either. neither does your smart tv. your database can’t be running at debug
>> just because it makes our lives as engineers easier.
>> 
>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
>> alex@thelastpickle.com> wrote:
>>> 
>>> It's a tiny bit unusual to turn on debug logging for all users by default
>>> though, and there should be occasions to turn it on when facing issues
>> that
>>> you want to debug (if they can be easily reproduced).
>> 
> 
> 
> 
> -- 
> Jonathan Ellis
> co-founder, http://www.datastax.com
> @spyced

Re: Debug logging enabled by default since 2.2

[Brandon Williams <dr...@gmail.com>]

It seems to me the power user who wants to eek out that last bit of
performance can do so.  It also seems like the user who doesn't even know
about that is the exact kind of user that's going to need the debug log in
the future.

On Sun, Mar 18, 2018 at 1:45 PM, Michael Kjellman <kj...@apple.com>
wrote:

> i’m not trying to get into a fight here jeremiah. and this will be my last
> reply on this as i’ve made my opinion pretty clear. but ask yourself: would
> you run c* in idea debugger and then do performance testing? no. because
> it’s a DEBUGger.
>
> > On Mar 18, 2018, at 11:43 AM, J. D. Jordan <je...@gmail.com>
> wrote:
> >
> > If there are some log messages you think should be improved to make them
> more useful please do so.  Saying things are “crap” is not productive.
> >
> > I have seen having the extra information from the debug.log be very
> helpful in debugging production issues after the fact on operational
> clusters many times.
> >
> > Also if you think there are things logged at DEBUG, since it was cleaned
> it up, that are not useful, then please improve them or change their
> logging level.
> >
> > You are also free to change the logging level on clusters you run if you
> don’t want the extra information.
> >
> > And again we are only talking about versions where DEBUG has been
> cleaned up. When running 2.1 or earlier, yes there is a ton of stuff at
> DEBUG and you would not want that on by default, even asynchronously.
> >
> > It is up to reviewers and committers to understand the impact of and
> rules around the use of different log levels. Said reviewers and committers
> should teach new contributors those rules during reviews if they are
> violated.
> >
> > -Jeremiah
> >
> >> On Mar 18, 2018, at 2:31 PM, Michael Kjellman <kj...@apple.com>
> wrote:
> >>
> >> what really baffles me with this entire thing is as a project we
> don’t even log things like partition keys along with the tombstone
> overwhelming or batch to large log messages.. this would immediately be
> helpful to thousands and thousands of people... yet somehow we think it’s
> okay to log tons of crap at debug to users drives that will shorten their
> ssds and objectively reduce the performance of the actual database due to
> logging overhead for some possible day in the future when we might need
> them to debug a problem really we should have figured out and reproduced
> ourselves in the first place.
> >>
> >>> On Mar 18, 2018, at 11:24 AM, Michael Kjellman <kj...@apple.com>
> wrote:
> >>>
> >>> it’s too easy to make a regression there. and does anyone even have
> a splunk (or equivalent) infrastructure to actually keep debug logs around
> for a long enough retention period to even have them be helpful?
> >>>
> >>> again: this is something engineers for the project want. it’s not in
> the best interest for our users.
> >>>
> >>>
> >>>> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com>
> wrote:
> >>>>
> >>>> That really depends on whether you're judicious in deciding what to
> log at
> >>>> debug, doesn't it?
> >>>>
> >>>> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <
> kjellman@apple.com>
> >>>> wrote:
> >>>>
> >>>>> +1. this is how it works.
> >>>>>
> >>>>> your computer doesn’t run at debug logging by default. your phone
> doesn’t
> >>>>> either. neither does your smart tv. your database can’t be running
> at debug
> >>>>> just because it makes our lives as engineers easier.
> >>>>>
> >>>>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
> >>>>> alex@thelastpickle.com> wrote:
> >>>>>>
> >>>>>> It's a tiny bit unusual to turn on debug logging for all users by
> default
> >>>>>> though, and there should be occasions to turn it on when facing
> issues
> >>>>> that
> >>>>>> you want to debug (if they can be easily reproduced).
> >>>>>
> >>>>
> >>>>
> >>>>
> >>>> --
> >>>> Jonathan Ellis
> >>>> co-founder, http://www.datastax.com
> >>>> @spyced
> >>>
> >>> ---------------------------------------------------------------------
> >>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> >>> For additional commands, e-mail: dev-help@cassandra.apache.org
> >>>
> >> ТÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÐÐ¥Fò
> Vç7V'67&–&R RÖÖ –â FWb×Vç7V'67&–&T 6 76 æG& æ   6†Ræ÷&pФf÷"  FF—F–öæ Â
> 6öÖÖ æG2 RÖÖ –â FWbÖ†VÇ  6 76 æG& æ   6†Ræ÷&pÐ Ð
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > For additional commands, e-mail: dev-help@cassandra.apache.org
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
>
>

Re: Debug logging enabled by default since 2.2

[Michael Kjellman <kj...@apple.com>]

i’m not trying to get into a fight here jeremiah. and this will be my last reply on this as i’ve made my opinion pretty clear. but ask yourself: would you run c* in idea debugger and then do performance testing? no. because it’s a DEBUGger.

> On Mar 18, 2018, at 11:43 AM, J. D. Jordan <je...@gmail.com> wrote:
> 
> If there are some log messages you think should be improved to make them more useful please do so.  Saying things are “crap” is not productive.
> 
> I have seen having the extra information from the debug.log be very helpful in debugging production issues after the fact on operational clusters many times.
> 
> Also if you think there are things logged at DEBUG, since it was cleaned it up, that are not useful, then please improve them or change their logging level.
> 
> You are also free to change the logging level on clusters you run if you don’t want the extra information.
> 
> And again we are only talking about versions where DEBUG has been cleaned up. When running 2.1 or earlier, yes there is a ton of stuff at DEBUG and you would not want that on by default, even asynchronously.
> 
> It is up to reviewers and committers to understand the impact of and rules around the use of different log levels. Said reviewers and committers should teach new contributors those rules during reviews if they are violated.
> 
> -Jeremiah
> 
>> On Mar 18, 2018, at 2:31 PM, Michael Kjellman <kj...@apple.com> wrote:
>> 
>> what really baffles me with this entire thing is as a project we don’t even log things like partition keys along with the tombstone overwhelming or batch to large log messages.. this would immediately be helpful to thousands and thousands of people... yet somehow we think it’s okay to log tons of crap at debug to users drives that will shorten their ssds and objectively reduce the performance of the actual database due to logging overhead for some possible day in the future when we might need them to debug a problem really we should have figured out and reproduced ourselves in the first place.
>> 
>>> On Mar 18, 2018, at 11:24 AM, Michael Kjellman <kj...@apple.com> wrote:
>>> 
>>> it’s too easy to make a regression there. and does anyone even have a splunk (or equivalent) infrastructure to actually keep debug logs around for a long enough retention period to even have them be helpful?
>>> 
>>> again: this is something engineers for the project want. it’s not in the best interest for our users. 
>>> 
>>> 
>>>> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com> wrote:
>>>> 
>>>> That really depends on whether you're judicious in deciding what to log at
>>>> debug, doesn't it?
>>>> 
>>>> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <kj...@apple.com>
>>>> wrote:
>>>> 
>>>>> +1. this is how it works.
>>>>> 
>>>>> your computer doesn’t run at debug logging by default. your phone doesn’t
>>>>> either. neither does your smart tv. your database can’t be running at debug
>>>>> just because it makes our lives as engineers easier.
>>>>> 
>>>>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
>>>>> alex@thelastpickle.com> wrote:
>>>>>> 
>>>>>> It's a tiny bit unusual to turn on debug logging for all users by default
>>>>>> though, and there should be occasions to turn it on when facing issues
>>>>> that
>>>>>> you want to debug (if they can be easily reproduced).
>>>>> 
>>>> 
>>>> 
>>>> 
>>>> -- 
>>>> Jonathan Ellis
>>>> co-founder, http://www.datastax.com
>>>> @spyced
>>> 
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>>> For additional commands, e-mail: dev-help@cassandra.apache.org
>>> 
>> ТÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÐÐ¥FòVç7V'67&–&RÂRÖÖ–âFWb×Vç7V'67&–&T676æG&æ6†Ræ÷&pФf÷"FF—F–öæÂ6öÖÖæG2ÂRÖÖ–âFWbÖ†VÇ676æG&æ6†Ræ÷&pÐ Ð
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
> 

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

["J. D. Jordan" <je...@gmail.com>]

If there are some log messages you think should be improved to make them more useful please do so.  Saying things are “crap” is not productive.

I have seen having the extra information from the debug.log be very helpful in debugging production issues after the fact on operational clusters many times.

Also if you think there are things logged at DEBUG, since it was cleaned it up, that are not useful, then please improve them or change their logging level.

You are also free to change the logging level on clusters you run if you don’t want the extra information.

And again we are only talking about versions where DEBUG has been cleaned up. When running 2.1 or earlier, yes there is a ton of stuff at DEBUG and you would not want that on by default, even asynchronously.

It is up to reviewers and committers to understand the impact of and rules around the use of different log levels. Said reviewers and committers should teach new contributors those rules during reviews if they are violated.

-Jeremiah

> On Mar 18, 2018, at 2:31 PM, Michael Kjellman <kj...@apple.com> wrote:
> 
> what really baffles me with this entire thing is as a project we don’t even log things like partition keys along with the tombstone overwhelming or batch to large log messages.. this would immediately be helpful to thousands and thousands of people... yet somehow we think it’s okay to log tons of crap at debug to users drives that will shorten their ssds and objectively reduce the performance of the actual database due to logging overhead for some possible day in the future when we might need them to debug a problem really we should have figured out and reproduced ourselves in the first place.
> 
>> On Mar 18, 2018, at 11:24 AM, Michael Kjellman <kj...@apple.com> wrote:
>> 
>> it’s too easy to make a regression there. and does anyone even have a splunk (or equivalent) infrastructure to actually keep debug logs around for a long enough retention period to even have them be helpful?
>> 
>> again: this is something engineers for the project want. it’s not in the best interest for our users. 
>> 
>> 
>>> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com> wrote:
>>> 
>>> That really depends on whether you're judicious in deciding what to log at
>>> debug, doesn't it?
>>> 
>>> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <kj...@apple.com>
>>> wrote:
>>> 
>>>> +1. this is how it works.
>>>> 
>>>> your computer doesn’t run at debug logging by default. your phone doesn’t
>>>> either. neither does your smart tv. your database can’t be running at debug
>>>> just because it makes our lives as engineers easier.
>>>> 
>>>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
>>>> alex@thelastpickle.com> wrote:
>>>>> 
>>>>> It's a tiny bit unusual to turn on debug logging for all users by default
>>>>> though, and there should be occasions to turn it on when facing issues
>>>> that
>>>>> you want to debug (if they can be easily reproduced).
>>>> 
>>> 
>>> 
>>> 
>>> -- 
>>> Jonathan Ellis
>>> co-founder, http://www.datastax.com
>>> @spyced
>> 
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>> For additional commands, e-mail: dev-help@cassandra.apache.org
>> 
> ТÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÒÐÐ¥FòVç7V'67&–&RÂRÖÖ–âFWb×Vç7V'67&–&T676æG&æ6†Ræ÷&pФf÷"FF—F–öæÂ6öÖÖæG2ÂRÖÖ–âFWbÖ†VÇ676æG&æ6†Ræ÷&pÐ Ð

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Michael Kjellman <kj...@apple.com>]

what really baffles me with this entire thing is as a project we don’t even log things like partition keys along with the tombstone overwhelming or batch to large log messages.. this would immediately be helpful to thousands and thousands of people... yet somehow we think it’s okay to log tons of crap at debug to users drives that will shorten their ssds and objectively reduce the performance of the actual database due to logging overhead for some possible day in the future when we might need them to debug a problem really we should have figured out and reproduced ourselves in the first place.

> On Mar 18, 2018, at 11:24 AM, Michael Kjellman <kj...@apple.com> wrote:
> 
> it’s too easy to make a regression there. and does anyone even have a splunk (or equivalent) infrastructure to actually keep debug logs around for a long enough retention period to even have them be helpful?
> 
> again: this is something engineers for the project want. it’s not in the best interest for our users. 
> 
> 
>> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com> wrote:
>> 
>> That really depends on whether you're judicious in deciding what to log at
>> debug, doesn't it?
>> 
>> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <kj...@apple.com>
>> wrote:
>> 
>>> +1. this is how it works.
>>> 
>>> your computer doesn’t run at debug logging by default. your phone doesn’t
>>> either. neither does your smart tv. your database can’t be running at debug
>>> just because it makes our lives as engineers easier.
>>> 
>>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
>>> alex@thelastpickle.com> wrote:
>>>> 
>>>> It's a tiny bit unusual to turn on debug logging for all users by default
>>>> though, and there should be occasions to turn it on when facing issues
>>> that
>>>> you want to debug (if they can be easily reproduced).
>>> 
>> 
>> 
>> 
>> -- 
>> Jonathan Ellis
>> co-founder, http://www.datastax.com
>> @spyced
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
> 

Re: Debug logging enabled by default since 2.2

[Michael Kjellman <kj...@apple.com>]

it’s too easy to make a regression there. and does anyone even have a splunk (or equivalent) infrastructure to actually keep debug logs around for a long enough retention period to even have them be helpful?

again: this is something engineers for the project want. it’s not in the best interest for our users. 


> On Mar 18, 2018, at 11:21 AM, Jonathan Ellis <jb...@gmail.com> wrote:
> 
> That really depends on whether you're judicious in deciding what to log at
> debug, doesn't it?
> 
> On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <kj...@apple.com>
> wrote:
> 
>> +1. this is how it works.
>> 
>> your computer doesn’t run at debug logging by default. your phone doesn’t
>> either. neither does your smart tv. your database can’t be running at debug
>> just because it makes our lives as engineers easier.
>> 
>>> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
>> alex@thelastpickle.com> wrote:
>>> 
>>> It's a tiny bit unusual to turn on debug logging for all users by default
>>> though, and there should be occasions to turn it on when facing issues
>> that
>>> you want to debug (if they can be easily reproduced).
>> 
> 
> 
> 
> -- 
> Jonathan Ellis
> co-founder, http://www.datastax.com
> @spyced

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Jonathan Ellis <jb...@gmail.com>]

That really depends on whether you're judicious in deciding what to log at
debug, doesn't it?

On Sun, Mar 18, 2018 at 12:57 PM, Michael Kjellman <kj...@apple.com>
wrote:

> +1. this is how it works.
>
> your computer doesn’t run at debug logging by default. your phone doesn’t
> either. neither does your smart tv. your database can’t be running at debug
> just because it makes our lives as engineers easier.
>
> > On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <
> alex@thelastpickle.com> wrote:
> >
> > It's a tiny bit unusual to turn on debug logging for all users by default
> > though, and there should be occasions to turn it on when facing issues
> that
> > you want to debug (if they can be easily reproduced).
>



-- 
Jonathan Ellis
co-founder, http://www.datastax.com
@spyced

Re: Debug logging enabled by default since 2.2

[Michael Kjellman <kj...@apple.com>]

+1. this is how it works.

your computer doesn’t run at debug logging by default. your phone doesn’t either. neither does your smart tv. your database can’t be running at debug just because it makes our lives as engineers easier. 

> On Mar 18, 2018, at 5:14 AM, Alexander Dejanovski <al...@thelastpickle.com> wrote:
> 
> It's a tiny bit unusual to turn on debug logging for all users by default
> though, and there should be occasions to turn it on when facing issues that
> you want to debug (if they can be easily reproduced).

Re: Debug logging enabled by default since 2.2

[Paulo Motta <pa...@gmail.com>]

First of all thanks for raising this ticket and important discussion
Alexander! See answers inline below:

> It's a tiny bit unusual to turn on debug logging for all users by default
> though, and there should be occasions to turn it on when facing issues that
> you want to debug (if they can be easily reproduced).
>

This is not supposed to be "debugging" log in the strict sense of the
word used for development purposes, but rather a "verbose system log"
- which is verbose enough to difficult human reading of "system.log"
but not enough to affect performance and could aid in troubleshooting.
Perhaps this is not so clear so we should definitely improve
communication in that front for committers and reviewers, but this has
been very useful to troubleshoot and investigate hard to reproduce
issues in production environments. Advanced operators can still
disable it if they have automated log analysis, but it's useful to the
beginner operator to understand system.log and "escalate" to debug.log
if/when they are facing problems.


> There's a danger that contributors might add debug loggings in the future
> though, with the idea that it comes for free since the appender is
> asynchronous (I would think so), and create new performance issues.
>

It's up to the committer and reviewer to ensure the log statements do
not affect performance, as per our review guidelines
(http://cassandra.apache.org/doc/latest/development/how_to_review.html#review-checklist):

Logging
- Are logging statements logged at the correct level?
- Are there logs in the critical path that could affect performance?
- Is there any log that could be added to communicate status or
troubleshoot potential problems in this feature?
- Can any unnecessary logging statement be removed?

This is a subjective area and we can definitely try to quantify this
and make this guideline more explicit if we start seeing more problems
like this in the future.

> Can someone assign the ticket to me?

Assigned!

>
> Thanks!
>
> Le dim. 18 mars 2018 à 04:33, Paulo Motta <pa...@gmail.com> a
> écrit :
>
>> The reasoning to have debug.log enabled by default after
>> CASSANDRA-10241 is to have a "safety log" that you can use when you
>> want to troubleshoot issues after the fact, that is verbose enough
>> that you can reconstruct events that may have caused a problem, but
>> should have negligible performance impact. The way we found to
>> implement this was the following:
>> - INFO: Human-readable operator log.
>> - DEBUG: Safety-log to be used for troubleshooting and bug reporting.
>> - TRACE: C* Programmer Debugging.
>>
>> If debug.log is causing performance problems we should definitely fix
>> it, but this has been very useful to troubleshoot complex production
>> issues since it has been added.
>>
>> 2018-03-17 16:35 GMT-03:00 Michael Kjellman <kj...@apple.com>:
>> > ive never understood this change. and it’s been explained to me multiple
>> times.
>> >
>> > DEBUG shouldn’t run by default in prod. and it certainly shouldn’t be
>> enabled by default for users.
>> >
>> > but hey, what do i know! just my 2 cents.
>> >
>> >> On Mar 17, 2018, at 10:55 AM, J. D. Jordan <je...@gmail.com>
>> wrote:
>> >>
>> >> We went through an exercise of setting things up so that DEBUG logging
>> was asynchronous would give people a “production” debug log.
>> https://issues.apache.org/jira/browse/CASSANDRA-10241
>> >> If there are some things going out at DEBUG that cause performance
>> issues then most likely those should be moved to TRACE so that debug
>> logging can stay enabled for all the useful information found there.
>> >>
>> >> -Jeremiah
>> >>
>> >>> On Mar 17, 2018, at 1:49 PM, Alexander Dejanovski <
>> alex@thelastpickle.com> wrote:
>> >>>
>> >>> Hi folks,
>> >>>
>> >>> we've been upgrading clusters from 2.0 to 2.2 recently and we've
>> noticed
>> >>> that debug logging was causing serious performance issues in some
>> cases,
>> >>> specifically because of its use in the query pager.
>> >>>
>> >>> I've opened a ticket with some benchmarks and flame graphs :
>> >>> https://issues.apache.org/jira/browse/CASSANDRA-14318
>> >>>
>> >>> The problem should be less serious in the read path with Cassandra 3.0
>> and
>> >>> above as the query pager code has been reworked and doesn't log at
>> debug
>> >>> level.
>> >>> I think that debug logging shouldn't be turned on by default though,
>> since
>> >>> we see it doesn't come for free and that it lowers read performance in
>> 2.2.
>> >>>
>> >>> Was there any specific reason why it was enabled by default in 2.2 ?
>> >>>
>> >>> Is anyone opposed to disabling debug logging by default in all
>> branches ?
>> >>>
>> >>> --
>> >>> -----------------
>> >>> Alexander Dejanovski
>> >>> France
>> >>> @alexanderdeja
>> >>>
>> >>> Consultant
>> >>> Apache Cassandra Consulting
>> >>> http://www.thelastpickle.com
>> >
>> > ---------------------------------------------------------------------
>> > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>> > For additional commands, e-mail: dev-help@cassandra.apache.org
>> >
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
>> For additional commands, e-mail: dev-help@cassandra.apache.org
>>
>> --
> -----------------
> Alexander Dejanovski
> France
> @alexanderdeja
>
> Consultant
> Apache Cassandra Consulting
> http://www.thelastpickle.com

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Alexander Dejanovski <al...@thelastpickle.com>]

Hi Paulo,

I understand the intent and Jeremiah suggested on the ticket that logging
causing performance issues should be switched to TRACE level.

It's a tiny bit unusual to turn on debug logging for all users by default
though, and there should be occasions to turn it on when facing issues that
you want to debug (if they can be easily reproduced).

I'll go down the read and write path to make a patch that turns debug
logging into trace logging and will run new benchmarks with debug logging
activated.

There's a danger that contributors might add debug loggings in the future
though, with the idea that it comes for free since the appender is
asynchronous (I would think so), and create new performance issues.

Can someone assign the ticket to me?

Thanks!

Le dim. 18 mars 2018 à 04:33, Paulo Motta <pa...@gmail.com> a
écrit :

> The reasoning to have debug.log enabled by default after
> CASSANDRA-10241 is to have a "safety log" that you can use when you
> want to troubleshoot issues after the fact, that is verbose enough
> that you can reconstruct events that may have caused a problem, but
> should have negligible performance impact. The way we found to
> implement this was the following:
> - INFO: Human-readable operator log.
> - DEBUG: Safety-log to be used for troubleshooting and bug reporting.
> - TRACE: C* Programmer Debugging.
>
> If debug.log is causing performance problems we should definitely fix
> it, but this has been very useful to troubleshoot complex production
> issues since it has been added.
>
> 2018-03-17 16:35 GMT-03:00 Michael Kjellman <kj...@apple.com>:
> > ive never understood this change. and it’s been explained to me multiple
> times.
> >
> > DEBUG shouldn’t run by default in prod. and it certainly shouldn’t be
> enabled by default for users.
> >
> > but hey, what do i know! just my 2 cents.
> >
> >> On Mar 17, 2018, at 10:55 AM, J. D. Jordan <je...@gmail.com>
> wrote:
> >>
> >> We went through an exercise of setting things up so that DEBUG logging
> was asynchronous would give people a “production” debug log.
> https://issues.apache.org/jira/browse/CASSANDRA-10241
> >> If there are some things going out at DEBUG that cause performance
> issues then most likely those should be moved to TRACE so that debug
> logging can stay enabled for all the useful information found there.
> >>
> >> -Jeremiah
> >>
> >>> On Mar 17, 2018, at 1:49 PM, Alexander Dejanovski <
> alex@thelastpickle.com> wrote:
> >>>
> >>> Hi folks,
> >>>
> >>> we've been upgrading clusters from 2.0 to 2.2 recently and we've
> noticed
> >>> that debug logging was causing serious performance issues in some
> cases,
> >>> specifically because of its use in the query pager.
> >>>
> >>> I've opened a ticket with some benchmarks and flame graphs :
> >>> https://issues.apache.org/jira/browse/CASSANDRA-14318
> >>>
> >>> The problem should be less serious in the read path with Cassandra 3.0
> and
> >>> above as the query pager code has been reworked and doesn't log at
> debug
> >>> level.
> >>> I think that debug logging shouldn't be turned on by default though,
> since
> >>> we see it doesn't come for free and that it lowers read performance in
> 2.2.
> >>>
> >>> Was there any specific reason why it was enabled by default in 2.2 ?
> >>>
> >>> Is anyone opposed to disabling debug logging by default in all
> branches ?
> >>>
> >>> --
> >>> -----------------
> >>> Alexander Dejanovski
> >>> France
> >>> @alexanderdeja
> >>>
> >>> Consultant
> >>> Apache Cassandra Consulting
> >>> http://www.thelastpickle.com
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> > For additional commands, e-mail: dev-help@cassandra.apache.org
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
>
> --
-----------------
Alexander Dejanovski
France
@alexanderdeja

Consultant
Apache Cassandra Consulting
http://www.thelastpickle.com

Re: Debug logging enabled by default since 2.2

[Paulo Motta <pa...@gmail.com>]

The reasoning to have debug.log enabled by default after
CASSANDRA-10241 is to have a "safety log" that you can use when you
want to troubleshoot issues after the fact, that is verbose enough
that you can reconstruct events that may have caused a problem, but
should have negligible performance impact. The way we found to
implement this was the following:
- INFO: Human-readable operator log.
- DEBUG: Safety-log to be used for troubleshooting and bug reporting.
- TRACE: C* Programmer Debugging.

If debug.log is causing performance problems we should definitely fix
it, but this has been very useful to troubleshoot complex production
issues since it has been added.

2018-03-17 16:35 GMT-03:00 Michael Kjellman <kj...@apple.com>:
> ive never understood this change. and it’s been explained to me multiple times.
>
> DEBUG shouldn’t run by default in prod. and it certainly shouldn’t be enabled by default for users.
>
> but hey, what do i know! just my 2 cents.
>
>> On Mar 17, 2018, at 10:55 AM, J. D. Jordan <je...@gmail.com> wrote:
>>
>> We went through an exercise of setting things up so that DEBUG logging was asynchronous would give people a “production” debug log. https://issues.apache.org/jira/browse/CASSANDRA-10241
>> If there are some things going out at DEBUG that cause performance issues then most likely those should be moved to TRACE so that debug logging can stay enabled for all the useful information found there.
>>
>> -Jeremiah
>>
>>> On Mar 17, 2018, at 1:49 PM, Alexander Dejanovski <al...@thelastpickle.com> wrote:
>>>
>>> Hi folks,
>>>
>>> we've been upgrading clusters from 2.0 to 2.2 recently and we've noticed
>>> that debug logging was causing serious performance issues in some cases,
>>> specifically because of its use in the query pager.
>>>
>>> I've opened a ticket with some benchmarks and flame graphs :
>>> https://issues.apache.org/jira/browse/CASSANDRA-14318
>>>
>>> The problem should be less serious in the read path with Cassandra 3.0 and
>>> above as the query pager code has been reworked and doesn't log at debug
>>> level.
>>> I think that debug logging shouldn't be turned on by default though, since
>>> we see it doesn't come for free and that it lowers read performance in 2.2.
>>>
>>> Was there any specific reason why it was enabled by default in 2.2 ?
>>>
>>> Is anyone opposed to disabling debug logging by default in all branches ?
>>>
>>> --
>>> -----------------
>>> Alexander Dejanovski
>>> France
>>> @alexanderdeja
>>>
>>> Consultant
>>> Apache Cassandra Consulting
>>> http://www.thelastpickle.com
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: dev-help@cassandra.apache.org
>

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

[Michael Kjellman <kj...@apple.com>]

ive never understood this change. and it’s been explained to me multiple times.

DEBUG shouldn’t run by default in prod. and it certainly shouldn’t be enabled by default for users.

but hey, what do i know! just my 2 cents. 

> On Mar 17, 2018, at 10:55 AM, J. D. Jordan <je...@gmail.com> wrote:
> 
> We went through an exercise of setting things up so that DEBUG logging was asynchronous would give people a “production” debug log. https://issues.apache.org/jira/browse/CASSANDRA-10241
> If there are some things going out at DEBUG that cause performance issues then most likely those should be moved to TRACE so that debug logging can stay enabled for all the useful information found there.
> 
> -Jeremiah
> 
>> On Mar 17, 2018, at 1:49 PM, Alexander Dejanovski <al...@thelastpickle.com> wrote:
>> 
>> Hi folks,
>> 
>> we've been upgrading clusters from 2.0 to 2.2 recently and we've noticed
>> that debug logging was causing serious performance issues in some cases,
>> specifically because of its use in the query pager.
>> 
>> I've opened a ticket with some benchmarks and flame graphs :
>> https://issues.apache.org/jira/browse/CASSANDRA-14318
>> 
>> The problem should be less serious in the read path with Cassandra 3.0 and
>> above as the query pager code has been reworked and doesn't log at debug
>> level.
>> I think that debug logging shouldn't be turned on by default though, since
>> we see it doesn't come for free and that it lowers read performance in 2.2.
>> 
>> Was there any specific reason why it was enabled by default in 2.2 ?
>> 
>> Is anyone opposed to disabling debug logging by default in all branches ?
>> 
>> -- 
>> -----------------
>> Alexander Dejanovski
>> France
>> @alexanderdeja
>> 
>> Consultant
>> Apache Cassandra Consulting
>> http://www.thelastpickle.com

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cassandra.apache.org
For additional commands, e-mail: dev-help@cassandra.apache.org

Re: Debug logging enabled by default since 2.2

["J. D. Jordan" <je...@gmail.com>]

We went through an exercise of setting things up so that DEBUG logging was asynchronous would give people a “production” debug log. https://issues.apache.org/jira/browse/CASSANDRA-10241
If there are some things going out at DEBUG that cause performance issues then most likely those should be moved to TRACE so that debug logging can stay enabled for all the useful information found there.

-Jeremiah

> On Mar 17, 2018, at 1:49 PM, Alexander Dejanovski <al...@thelastpickle.com> wrote:
> 
> Hi folks,
> 
> we've been upgrading clusters from 2.0 to 2.2 recently and we've noticed
> that debug logging was causing serious performance issues in some cases,
> specifically because of its use in the query pager.
> 
> I've opened a ticket with some benchmarks and flame graphs :
> https://issues.apache.org/jira/browse/CASSANDRA-14318
> 
> The problem should be less serious in the read path with Cassandra 3.0 and
> above as the query pager code has been reworked and doesn't log at debug
> level.
> I think that debug logging shouldn't be turned on by default though, since
> we see it doesn't come for free and that it lowers read performance in 2.2.
> 
> Was there any specific reason why it was enabled by default in 2.2 ?
> 
> Is anyone opposed to disabling debug logging by default in all branches ?
> 
> -- 
> -----------------
> Alexander Dejanovski
> France
> @alexanderdeja
> 
> Consultant
> Apache Cassandra Consulting
> http://www.thelastpickle.com