Log level cleanup

classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

Log level cleanup

Jan Høydahl / Cominvent
Hi,

I think Solr is too verbose on default INFO logging.
Time to do a major cleanup and move a bunch of INFO --> DEBUG and probably ERROR-->WARN, WARN-->INFO too...

What we need on INFO is mostly major things, like
* Solr/Lucene version, JRE version
* Echo startup params and java opts
* SOLR_HOME location
* Core x (re)loaded with X documents
* Whether in ZK mode or local mode, name of zkHosts
* plus some more


There's a whole lot of stuff printed on INFO which could go to DEBUG if you need it:

Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
INFO: makePath: /configs/lab/addresssynonyms.txt
Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
INFO: makePath: /configs/lab/admin-extra.html
Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
INFO: makePath: /configs/lab/admin-extra.menu-bottom.html
Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
INFO: makePath: /configs/lab/admin-extra.menu-top.html
...
...
Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
INFO: Setting socketTimeout to: 0
Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
INFO: Setting urlScheme to: http://
Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
INFO: Setting connTimeout to: 0
Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
INFO: Setting maxConnectionsPerHost to: 20
Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
INFO: Setting corePoolSize to: 0
...
...
Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
INFO: Server environment:java.io.tmpdir=/var/folders/sg/zdchfvbs7k5c4hcg374z45_40000gp/T/
Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
INFO: Server environment:java.compiler=<NA>
Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
INFO: Server environment:os.name=Mac OS X
Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
INFO: Server environment:os.arch=x86_64
...


--
Jan Høydahl, search solution architect
Cominvent AS - www.cominvent.com
Solr Training - www.solrtraining.com


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Log level cleanup

Mark Miller-3
I think we do too much logging on doc adds by default, but that a lot of the other stuff is much less frequent and much the information more useful than not when people run into trouble and can't just reproduce after turning on debug logging.

I'm for removing stuff that's too chatty, but it sounds like you probably have a more minimalist stance than I do. I prefer somewhat verbose logs for the user mailing list when the events are not common. There is a risk of that being too much for sure, but I see a risk in it being too little as well.

And we need to move the query logging to it's own structured log :)

- Mark

On Mar 19, 2013, at 7:43 PM, Jan Høydahl <[hidden email]> wrote:

> Hi,
>
> I think Solr is too verbose on default INFO logging.
> Time to do a major cleanup and move a bunch of INFO --> DEBUG and probably ERROR-->WARN, WARN-->INFO too...
>
> What we need on INFO is mostly major things, like
> * Solr/Lucene version, JRE version
> * Echo startup params and java opts
> * SOLR_HOME location
> * Core x (re)loaded with X documents
> * Whether in ZK mode or local mode, name of zkHosts
> * plus some more
>
>
> There's a whole lot of stuff printed on INFO which could go to DEBUG if you need it:
>
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/addresssynonyms.txt
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/admin-extra.html
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/admin-extra.menu-bottom.html
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/admin-extra.menu-top.html
> ...
> ...
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting socketTimeout to: 0
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting urlScheme to: http://
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting connTimeout to: 0
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting maxConnectionsPerHost to: 20
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting corePoolSize to: 0
> ...
> ...
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:java.io.tmpdir=/var/folders/sg/zdchfvbs7k5c4hcg374z45_40000gp/T/
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:java.compiler=<NA>
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:os.name=Mac OS X
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:os.arch=x86_64
> ...
>
>
> --
> Jan Høydahl, search solution architect
> Cominvent AS - www.cominvent.com
> Solr Training - www.solrtraining.com
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Log level cleanup

Jack Krupansky-2
In reply to this post by Jan Høydahl / Cominvent
I agree, but I think startup is a bit special. What I would like to see is a
way to ask for info/debug for startup, and then revert to WARN for normal
operation.

-- Jack Krupansky

-----Original Message-----
From: Jan Høydahl
Sent: Tuesday, March 19, 2013 7:43 PM
To: [hidden email]
Subject: Log level cleanup

Hi,

I think Solr is too verbose on default INFO logging.
Time to do a major cleanup and move a bunch of INFO --> DEBUG and probably
ERROR-->WARN, WARN-->INFO too...

What we need on INFO is mostly major things, like
* Solr/Lucene version, JRE version
* Echo startup params and java opts
* SOLR_HOME location
* Core x (re)loaded with X documents
* Whether in ZK mode or local mode, name of zkHosts
* plus some more


There's a whole lot of stuff printed on INFO which could go to DEBUG if you
need it:

Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
INFO: makePath: /configs/lab/addresssynonyms.txt
Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
INFO: makePath: /configs/lab/admin-extra.html
Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
INFO: makePath: /configs/lab/admin-extra.menu-bottom.html
Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
INFO: makePath: /configs/lab/admin-extra.menu-top.html
...
...
Mar 20, 2013 12:25:30 AM
org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
INFO: Setting socketTimeout to: 0
Mar 20, 2013 12:25:30 AM
org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
INFO: Setting urlScheme to: http://
Mar 20, 2013 12:25:30 AM
org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
INFO: Setting connTimeout to: 0
Mar 20, 2013 12:25:30 AM
org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
INFO: Setting maxConnectionsPerHost to: 20
Mar 20, 2013 12:25:30 AM
org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
INFO: Setting corePoolSize to: 0
...
...
Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
INFO: Server
environment:java.io.tmpdir=/var/folders/sg/zdchfvbs7k5c4hcg374z45_40000gp/T/
Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
INFO: Server environment:java.compiler=<NA>
Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
INFO: Server environment:os.name=Mac OS X
Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
INFO: Server environment:os.arch=x86_64
...


--
Jan Høydahl, search solution architect
Cominvent AS - www.cominvent.com
Solr Training - www.solrtraining.com


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Log level cleanup

Ryan McKinley
In reply to this post by Mark Miller-3
And we need to move the query logging to it's own structured log :)

What are your thoughts here?  This is something I have toyed with at the application level -- actually indexing each query+result count.  Do you think this is appropriate infrastructure in solr?



On Tue, Mar 19, 2013 at 4:57 PM, Mark Miller <[hidden email]> wrote:
I think we do too much logging on doc adds by default, but that a lot of the other stuff is much less frequent and much the information more useful than not when people run into trouble and can't just reproduce after turning on debug logging.

I'm for removing stuff that's too chatty, but it sounds like you probably have a more minimalist stance than I do. I prefer somewhat verbose logs for the user mailing list when the events are not common. There is a risk of that being too much for sure, but I see a risk in it being too little as well.

And we need to move the query logging to it's own structured log :)

- Mark

On Mar 19, 2013, at 7:43 PM, Jan Høydahl <[hidden email]> wrote:

> Hi,
>
> I think Solr is too verbose on default INFO logging.
> Time to do a major cleanup and move a bunch of INFO --> DEBUG and probably ERROR-->WARN, WARN-->INFO too...
>
> What we need on INFO is mostly major things, like
> * Solr/Lucene version, JRE version
> * Echo startup params and java opts
> * SOLR_HOME location
> * Core x (re)loaded with X documents
> * Whether in ZK mode or local mode, name of zkHosts
> * plus some more
>
>
> There's a whole lot of stuff printed on INFO which could go to DEBUG if you need it:
>
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/addresssynonyms.txt
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/admin-extra.html
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/admin-extra.menu-bottom.html
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/admin-extra.menu-top.html
> ...
> ...
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting socketTimeout to: 0
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting urlScheme to: http://
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting connTimeout to: 0
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting maxConnectionsPerHost to: 20
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting corePoolSize to: 0
> ...
> ...
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:java.io.tmpdir=/var/folders/sg/zdchfvbs7k5c4hcg374z45_40000gp/T/
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:java.compiler=<NA>
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:os.name=Mac OS X
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:os.arch=x86_64
> ...
>
>
> --
> Jan Høydahl, search solution architect
> Cominvent AS - www.cominvent.com
> Solr Training - www.solrtraining.com
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]


Reply | Threaded
Open this post in threaded view
|

Re: Log level cleanup

Jan Høydahl / Cominvent
Definitely a separate query log. solrconfig.xml could have a tag <queryLog format="plain">${solr.query.log}</queryLog>
For me the one-line request-log format with Solr extensions works well enough. But perhaps have a way to specify what IP address to log in the file. It's not that useful to log the web frontend's address, so an option to pick up the X-Forwarded-For header or similar would be nice.

By default the query logs could end up in ${solr.data.dir} with name <core>-querylog-YYMMDD.log and auto rotate daily. For back compat there should be a way to continue logging queries through slf4j as today, but that should be off by default.

--
Jan Høydahl, search solution architect
Cominvent AS - www.cominvent.com
Solr Training - www.solrtraining.com

20. mars 2013 kl. 01:03 skrev Ryan McKinley <[hidden email]>:

And we need to move the query logging to it's own structured log :)

What are your thoughts here?  This is something I have toyed with at the application level -- actually indexing each query+result count.  Do you think this is appropriate infrastructure in solr?



On Tue, Mar 19, 2013 at 4:57 PM, Mark Miller <[hidden email]> wrote:
I think we do too much logging on doc adds by default, but that a lot of the other stuff is much less frequent and much the information more useful than not when people run into trouble and can't just reproduce after turning on debug logging.

I'm for removing stuff that's too chatty, but it sounds like you probably have a more minimalist stance than I do. I prefer somewhat verbose logs for the user mailing list when the events are not common. There is a risk of that being too much for sure, but I see a risk in it being too little as well.

And we need to move the query logging to it's own structured log :)

- Mark

On Mar 19, 2013, at 7:43 PM, Jan Høydahl <[hidden email]> wrote:

> Hi,
>
> I think Solr is too verbose on default INFO logging.
> Time to do a major cleanup and move a bunch of INFO --> DEBUG and probably ERROR-->WARN, WARN-->INFO too...
>
> What we need on INFO is mostly major things, like
> * Solr/Lucene version, JRE version
> * Echo startup params and java opts
> * SOLR_HOME location
> * Core x (re)loaded with X documents
> * Whether in ZK mode or local mode, name of zkHosts
> * plus some more
>
>
> There's a whole lot of stuff printed on INFO which could go to DEBUG if you need it:
>
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/addresssynonyms.txt
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/admin-extra.html
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/admin-extra.menu-bottom.html
> Mar 20, 2013 12:25:37 AM org.apache.solr.common.cloud.SolrZkClient makePath
> INFO: makePath: /configs/lab/admin-extra.menu-top.html
> ...
> ...
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting socketTimeout to: 0
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting urlScheme to: http://
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting connTimeout to: 0
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting maxConnectionsPerHost to: 20
> Mar 20, 2013 12:25:30 AM org.apache.solr.handler.component.HttpShardHandlerFactory getParameter
> INFO: Setting corePoolSize to: 0
> ...
> ...
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:java.io.tmpdir=/var/folders/sg/zdchfvbs7k5c4hcg374z45_40000gp/T/
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:java.compiler=<NA>
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:os.name=Mac OS X
> Mar 20, 2013 12:25:30 AM org.apache.zookeeper.Environment logEnv
> INFO: Server environment:os.arch=x86_64
> ...
>
>
> --
> Jan Høydahl, search solution architect
> Cominvent AS - www.cominvent.com
> Solr Training - www.solrtraining.com
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]



Reply | Threaded
Open this post in threaded view
|

Re: Log level cleanup

Toke Eskildsen
On Wed, 2013-03-20 at 01:52 +0100, Jan Høydahl wrote:
> By default the query logs could end up in ${solr.data.dir} with name
> <core>-querylog-YYMMDD.log and auto rotate daily. For back compat
> there should be a way to continue logging queries through slf4j as
> today, but that should be off by default.

What is gained by logging queries outside of the standard logging
framework? Wouldn't it be better to create a logger with an agreed-upon
name, such as "queries" or "interaction"?

- Toke Eskildsen



---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Log level cleanup

Shawn Heisey-4
On 3/20/2013 7:39 AM, Toke Eskildsen wrote:
> On Wed, 2013-03-20 at 01:52 +0100, Jan Høydahl wrote:
>> By default the query logs could end up in ${solr.data.dir} with name
>> <core>-querylog-YYMMDD.log and auto rotate daily. For back compat
>> there should be a way to continue logging queries through slf4j as
>> today, but that should be off by default.
>
> What is gained by logging queries outside of the standard logging
> framework? Wouldn't it be better to create a logger with an agreed-upon
> name, such as "queries" or "interaction"?

When I review logs to see queries and Solr's response, I generally want
to see those queries in context with the other INFO logs.  The only way
I can imagine that a separate query log would be useful is if each full
query logged had a unique identifier and a log entry with that
identifier were to go into the main log at INFO.  This would not reduce
the number of lines in the main log, but it might reduce the *size* of
the main log.

Most of my queries are longer than the 1024 characters that jetty's
request log can show, and therefore they take up a lot of space in the
main log.  That's one thing in favor of separating them, but I would
require the ability to map them back to their relative position in the
main log.

A "best of everything" approach would be to let the admin decide whether
they want queries in the main log or in a query log.  If they want them
separate, there should be an option to use unique identifiers to link
the two logs.


Finding the right balance for WARN, INFO, and DEBUG is a tricky problem,
and different people will have different opinions about what goes where.

It's been my experience that when I put the level at WARN, very little
gets logged outside of exceptions for client timeouts and malformed
queries.  Is this a good thing, or an indication that the warn level is
not used enough?

I have the sense that when I choose between INFO and WARN, I'm basically
choosing between logging and not logging.  The shift should be more
gradual than that.  It could be that my Solr install is just running so
well that there's nothing to report at WARN, so ERROR is all I really get.

When I put it at INFO, it's extremely chatty.  My main concern with INFO
logging is that certain individual log entries are important, but
display too much information.  This is why I filed SOLR-4547.

There is probably some logging that's currently at INFO that should be
moved to DEBUG, but I think that a lot of what's currently at INFO is
useful.  I would have to research more to say for sure.  I have not
looked into whether any of the DEBUG logging should be moved to TRACE.

Thanks,
Shawn


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Log level cleanup

Mark Miller-3
In reply to this post by Toke Eskildsen

On Mar 20, 2013, at 9:39 AM, Toke Eskildsen <[hidden email]> wrote:

> What is gained by logging queries outside of the standard logging
> framework? Wouldn't it be better to create a logger with an agreed-upon
> name, such as "queries" or "interaction"?

The key is a standard format. I don't care what logs the queries as long as a std format is written no matter the logging framework or logging config file you have plugged in. There should be a Solr queries log file that you can build and anyones tools are going to be able to parse it and we can always count on being able to parse it.

We can then easily feed it into things like suggest or other consumers.

- Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]