Uploaded image for project: 'Solr'
  1. Solr
  2. SOLR-8186

Solr start scripts -- only log to console when running in foreground

    Details

    • Type: Improvement
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 5.3.1
    • Fix Version/s: 6.3, 7.0
    • Component/s: scripts and tools
    • Labels:

      Description

      Currently the log4j.properties file logs to the console, and the start scripts capture console output to a logfile that never rotates. This can fill up the disk, and when the logfile is removed, the user might be alarmed by the way their memory statistics behave – the "cached" memory might have a sudden and very large drop, making it appear to a novice that the huge logfile was hogging their memory.

      The logfile created by log4j is rotated when it gets big enough, so that logfile is unlikely to fill up the disk.

      I propose that we copy the current log4j.properties file to something like log4j-foreground.properties, remove CONSOLE logging in the log4j.properties file, and have the start script use the alternate config file when running in the foreground. This way users will see the logging output when running in the foreground, but it will be absent when running normally.

      1. SOLR-8186-robustness.patch
        6 kB
        Jan Høydahl
      2. SOLR-8186.patch
        9 kB
        Jan Høydahl
      3. SOLR-8186.patch
        9 kB
        Jan Høydahl

        Issue Links

          Activity

          Hide
          elyograg Shawn Heisey added a comment -

          The start script should continue to capture the console to a separate logfile when running in the background. That will capture startup errors and any stdout/stderr logging that Solr might do when debugging code changes.

          Show
          elyograg Shawn Heisey added a comment - The start script should continue to capture the console to a separate logfile when running in the background. That will capture startup errors and any stdout/stderr logging that Solr might do when debugging code changes.
          Hide
          erickerickson Erick Erickson added a comment -

          Yeah, it's surprising when your disk fills up!

          Show
          erickerickson Erick Erickson added a comment - Yeah, it's surprising when your disk fills up!
          Hide
          janhoy Jan Høydahl added a comment -

          Is this still the case?

          Do we even need to write to logs/solr.log when running in foreground mode? If not, the log4j-foreground.properties could do CONSOLE only.

          Also, why does the log format need to be different between console and file? I know some Windows users start Solr with NSSM in foreground mode and relies on NSSM to capture console logging and take care of persisting and rolling the logs. You would expect to find a timestamp in those logs!

          solr.log:
          2016-09-19 13:42:46.607 INFO  (main) [   ] o.e.j.u.log Logging initialized @361ms
          2016-09-19 13:42:46.772 INFO  (main) [   ] o.e.j.s.Server jetty-9.3.8.v20160314
          
          solr-8983-console.log:
          0    INFO  (main) [   ] o.e.j.u.log Logging initialized @361ms
          165  INFO  (main) [   ] o.e.j.s.Server jetty-9.3.8.v20160314
          
          Show
          janhoy Jan Høydahl added a comment - Is this still the case? Do we even need to write to logs/solr.log when running in foreground mode? If not, the log4j-foreground.properties could do CONSOLE only. Also, why does the log format need to be different between console and file? I know some Windows users start Solr with NSSM in foreground mode and relies on NSSM to capture console logging and take care of persisting and rolling the logs. You would expect to find a timestamp in those logs! solr.log: 2016-09-19 13:42:46.607 INFO (main) [ ] o.e.j.u.log Logging initialized @361ms 2016-09-19 13:42:46.772 INFO (main) [ ] o.e.j.s.Server jetty-9.3.8.v20160314 solr-8983-console.log: 0 INFO (main) [ ] o.e.j.u.log Logging initialized @361ms 165 INFO (main) [ ] o.e.j.s.Server jetty-9.3.8.v20160314
          Hide
          erickerickson Erick Erickson added a comment -

          Agreed, having the timestamp as ticks in the console rather than a human-readable format is disconcerting, +1 to change it to the same format as the rest of the log files.

          bq: Do we even need to write to logs/solr.log.....

          IMO absolutely we do. There is so much output that having the solr.log file is important to answer "what did I see go by?" when chasing down problems.....

          Show
          erickerickson Erick Erickson added a comment - Agreed, having the timestamp as ticks in the console rather than a human-readable format is disconcerting, +1 to change it to the same format as the rest of the log files. bq: Do we even need to write to logs/solr.log..... IMO absolutely we do. There is so much output that having the solr.log file is important to answer "what did I see go by?" when chasing down problems.....
          Hide
          janhoy Jan Høydahl added a comment - - edited

          Attached patch with the following:

          • New option -Dsolr.log.muteconsole which is passed when starting in foreground mode (-f). This will programatically disable the CONSOLE logger (in SolrDispatchFilter.init), causing the solr-8983-console.log to only contain stdout/stderr logs (except for the first few lines before the logger is disabled).
          • Removed some excess Jetty logging by setting default level for org.eclipse.jetty=WARN and org.eclipse.jetty.server=INFO
          • Removed annoying log line o.e.j.s.SecurityHandler ... has uncovered http methods for path: / by extending web.xml
          • Removed annoying log line o.a.s.c.CoreContainer Couldn't add files from /opt/solr/server/solr/lib to classpath: when libPath is the hardcoded lib
          • Now printing full date&time also for CONSOLE log

          I decided to do the dynamic disabling of CONSOLE logger instead of having multiple log4j.properties files floating around, meaning that the muting will work also for custom logger configs, as long as the console logger is named CONSOLE. This is more flexible.

          Show
          janhoy Jan Høydahl added a comment - - edited Attached patch with the following: New option -Dsolr.log.muteconsole which is passed when starting in foreground mode ( -f ). This will programatically disable the CONSOLE logger (in SolrDispatchFilter.init), causing the solr-8983-console.log to only contain stdout/stderr logs (except for the first few lines before the logger is disabled). Removed some excess Jetty logging by setting default level for org.eclipse.jetty=WARN and org.eclipse.jetty.server=INFO Removed annoying log line o.e.j.s.SecurityHandler ... has uncovered http methods for path: / by extending web.xml Removed annoying log line o.a.s.c.CoreContainer Couldn't add files from /opt/solr/server/solr/lib to classpath: when libPath is the hardcoded lib Now printing full date&time also for CONSOLE log I decided to do the dynamic disabling of CONSOLE logger instead of having multiple log4j.properties files floating around, meaning that the muting will work also for custom logger configs, as long as the console logger is named CONSOLE . This is more flexible.
          Hide
          janhoy Jan Høydahl added a comment -

          The only output in solr-8983-console.log when starting in backgorund is now these two lines:

          2016-09-19 22:40:45.836 INFO  (main) [   ] o.e.j.s.Server jetty-9.3.8.v20160314
          2016-09-19 22:40:46.120 INFO  (main) [   ] o.a.s.s.SolrDispatchFilter Property solr.log.muteconsole=true. Muting log appender named "CONSOLE".
          

          Please give it a spin and report your findings. I have not yet tested the solr.cmd changes, anyone on Windows who wants to test?

          Show
          janhoy Jan Høydahl added a comment - The only output in solr-8983-console.log when starting in backgorund is now these two lines: 2016-09-19 22:40:45.836 INFO (main) [ ] o.e.j.s.Server jetty-9.3.8.v20160314 2016-09-19 22:40:46.120 INFO (main) [ ] o.a.s.s.SolrDispatchFilter Property solr.log.muteconsole=true. Muting log appender named "CONSOLE". Please give it a spin and report your findings. I have not yet tested the solr.cmd changes, anyone on Windows who wants to test?
          Hide
          elyograg Shawn Heisey added a comment - - edited

          I like it! The console logfile is a persistent thorn when disk space is limited.

          I understand the desire to log to the actual console in foreground mode, but I'm not sure that we want to copy that output to a file in foreground mode, especially if we are still creating solr.log. I think logging to solr.log even in foreground mode is a good idea.

          Show
          elyograg Shawn Heisey added a comment - - edited I like it! The console logfile is a persistent thorn when disk space is limited. I understand the desire to log to the actual console in foreground mode, but I'm not sure that we want to copy that output to a file in foreground mode, especially if we are still creating solr.log. I think logging to solr.log even in foreground mode is a good idea.
          Hide
          janhoy Jan Høydahl added a comment -

          When in foreground mode, the CONSOLE logging goes to the console - logs/solr-8983-console.log is NOT written. Try it

          Show
          janhoy Jan Høydahl added a comment - When in foreground mode, the CONSOLE logging goes to the console - logs/solr-8983-console.log is NOT written. Try it
          Hide
          elyograg Shawn Heisey added a comment -

          Cool. Thanks. I hadn't actually looked at the script, I was just thinking out loud.

          Show
          elyograg Shawn Heisey added a comment - Cool. Thanks. I hadn't actually looked at the script, I was just thinking out loud.
          Hide
          janhoy Jan Høydahl added a comment -

          New patch

          • Now iterates through ALL log4j Appenders and removes those of class ConsoleAppender. This makes it more robust for custom log configs
          • Isolate only the log4j.properties changes related to this JIRA, to avoid merge conflict with SOLR-9534
          Show
          janhoy Jan Høydahl added a comment - New patch Now iterates through ALL log4j Appenders and removes those of class ConsoleAppender . This makes it more robust for custom log configs Isolate only the log4j.properties changes related to this JIRA, to avoid merge conflict with SOLR-9534
          Hide
          janhoy Jan Høydahl added a comment -

          I intend to commit this in a few days if lazy consensus

          Show
          janhoy Jan Høydahl added a comment - I intend to commit this in a few days if lazy consensus
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 2ef34e9e24ac2c0bd72de54c3edda9ba3aa43728 in lucene-solr's branch refs/heads/master from Jan Høydahl
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=2ef34e9 ]

          SOLR-8186: Solr start scripts, only log to console when running in foreground

          Show
          jira-bot ASF subversion and git services added a comment - Commit 2ef34e9e24ac2c0bd72de54c3edda9ba3aa43728 in lucene-solr's branch refs/heads/master from Jan Høydahl [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=2ef34e9 ] SOLR-8186 : Solr start scripts, only log to console when running in foreground
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit dfb8aff7394057e132c3b3ca0ef107f280cca8df in lucene-solr's branch refs/heads/branch_6x from Jan Høydahl
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=dfb8aff ]

          SOLR-8186: Solr start scripts, only log to console when running in foreground

          Show
          jira-bot ASF subversion and git services added a comment - Commit dfb8aff7394057e132c3b3ca0ef107f280cca8df in lucene-solr's branch refs/heads/branch_6x from Jan Høydahl [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=dfb8aff ] SOLR-8186 : Solr start scripts, only log to console when running in foreground
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 0a24afdc5b51fb0275a168ee502555bf06d91ff5 in lucene-solr's branch refs/heads/branch_6x from Dawid Weiss
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=0a24afd ]

          SOLR-8186: suppress log4j access warnings.

          Show
          jira-bot ASF subversion and git services added a comment - Commit 0a24afdc5b51fb0275a168ee502555bf06d91ff5 in lucene-solr's branch refs/heads/branch_6x from Dawid Weiss [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=0a24afd ] SOLR-8186 : suppress log4j access warnings.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 9e09045a4c61a8d35b994adadd8f283add10cba7 in lucene-solr's branch refs/heads/master from Dawid Weiss
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=9e09045 ]

          SOLR-8186: suppress log4j access warnings.

          Show
          jira-bot ASF subversion and git services added a comment - Commit 9e09045a4c61a8d35b994adadd8f283add10cba7 in lucene-solr's branch refs/heads/master from Dawid Weiss [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=9e09045 ] SOLR-8186 : suppress log4j access warnings.
          Hide
          janhoy Jan Høydahl added a comment -

          Thanks Dawid Weiss for stepping in on this - I obviously forgot to run ant precommit, sorry for breaking the build
          When switching to Log4j2 we'll have to revisit the way of doing things as this method will no longer work, hopefully there is a "cleaner" way...

          Show
          janhoy Jan Høydahl added a comment - Thanks Dawid Weiss for stepping in on this - I obviously forgot to run ant precommit, sorry for breaking the build When switching to Log4j2 we'll have to revisit the way of doing things as this method will no longer work, hopefully there is a "cleaner" way...
          Hide
          dweiss Dawid Weiss added a comment -

          No problem. I actually still can't get precommit to work, it fails with:

          -documentation-lint:
              [jtidy] Checking for broken html (such as invalid tags)...
             [delete] Deleting directory /mnt/storage/dweiss/work/lucene-solr/lucene/build/jtidy_tmp
               [echo] Checking for broken links...
               [exec]
               [exec] Crawl/parse...
               [exec]
               [exec] Verify...
               [exec]
               [exec] file:///mnt/storage/dweiss/work/lucene-solr/solr/build/docs/quickstart.html
               [exec]   BAD EXTERNAL LINK: http://lucene.apache.org/solr/downloads.html
               [exec]
               [exec] Broken javadocs links were found!
          

          So you can make up and fix this one instead

          Show
          dweiss Dawid Weiss added a comment - No problem. I actually still can't get precommit to work, it fails with: -documentation-lint: [jtidy] Checking for broken html (such as invalid tags)... [delete] Deleting directory /mnt/storage/dweiss/work/lucene-solr/lucene/build/jtidy_tmp [echo] Checking for broken links... [exec] [exec] Crawl/parse... [exec] [exec] Verify... [exec] [exec] file: ///mnt/storage/dweiss/work/lucene-solr/solr/build/docs/quickstart.html [exec] BAD EXTERNAL LINK: http: //lucene.apache.org/solr/downloads.html [exec] [exec] Broken javadocs links were found! So you can make up and fix this one instead
          Hide
          janhoy Jan Høydahl added a comment -

          Reopening to handle log4j access outside of SolrDispatchFilter and in a more robust way in case log4j is not the chosen log framework.

          Show
          janhoy Jan Høydahl added a comment - Reopening to handle log4j access outside of SolrDispatchFilter and in a more robust way in case log4j is not the chosen log framework.
          Hide
          janhoy Jan Høydahl added a comment -

          This SOLR-8186-robustness.patch factors out the logic to a new class "StartupLoggingUtils" which is only accessible from "servlet" package.

          • Checks that LogManager exists on classpath
          • Checks that log4j is actually bound by slf4j
          • Logs an informative warning if Console muting was not possible
          • Catches any other exception that may occur and logs, with the result that muting will not happen

          Uwe Schindler what do you think?

          Show
          janhoy Jan Høydahl added a comment - This SOLR-8186 -robustness.patch factors out the logic to a new class "StartupLoggingUtils" which is only accessible from "servlet" package. Checks that LogManager exists on classpath Checks that log4j is actually bound by slf4j Logs an informative warning if Console muting was not possible Catches any other exception that may occur and logs, with the result that muting will not happen Uwe Schindler what do you think?
          Hide
          thetaphi Uwe Schindler added a comment -

          +1
          Thanks, Uwe

          Show
          thetaphi Uwe Schindler added a comment - +1 Thanks, Uwe
          Hide
          thetaphi Uwe Schindler added a comment -

          Small thing. I would also catch NoClassDefFoundError (or Errors in general). See CheckLoggingConfiguration.

          I am not 100% sure if CheckLoggingConfiguration is still used anywhere. Maybe nuke it! You code is a kind of duplicate.

          Show
          thetaphi Uwe Schindler added a comment - Small thing. I would also catch NoClassDefFoundError (or Errors in general). See CheckLoggingConfiguration. I am not 100% sure if CheckLoggingConfiguration is still used anywhere. Maybe nuke it! You code is a kind of duplicate.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit eabb05f7fd52e9e9946160101607052b14b2cfe2 in lucene-solr's branch refs/heads/master from Jan Høydahl
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=eabb05f ]

          SOLR-8186: Added robustness to the dynamic log muting logic

          Show
          jira-bot ASF subversion and git services added a comment - Commit eabb05f7fd52e9e9946160101607052b14b2cfe2 in lucene-solr's branch refs/heads/master from Jan Høydahl [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=eabb05f ] SOLR-8186 : Added robustness to the dynamic log muting logic
          Hide
          janhoy Jan Høydahl added a comment -

          Regarding NoClassDefFoundError, we'll never get as far as calling any methods on LogManager since we first check for the existence with Class.forName. But I could change both catch clauses to catching Throwable to get both Errors and Exceptions?

          We still need CheckLoggingConfiguration as this new code is not always called, and it does not exit on error, but continue running.

          Show
          janhoy Jan Høydahl added a comment - Regarding NoClassDefFoundError, we'll never get as far as calling any methods on LogManager since we first check for the existence with Class.forName. But I could change both catch clauses to catching Throwable to get both Errors and Exceptions? We still need CheckLoggingConfiguration as this new code is not always called, and it does not exit on error, but continue running.
          Hide
          elyograg Shawn Heisey added a comment -

          Checks that log4j is actually bound by slf4j

          Would this mean that somebody who changes their logging jars on purpose gets a warning?

          Note that I am not actually opposed to assuming slf4j->log4j (and eventually log4j2) in what we incorporate into Solr, particularly as we move to making a standalone application. Taking away the user's choice of logging framework would allow us to control logging more effectively from the admin UI.

          Show
          elyograg Shawn Heisey added a comment - Checks that log4j is actually bound by slf4j Would this mean that somebody who changes their logging jars on purpose gets a warning? Note that I am not actually opposed to assuming slf4j->log4j (and eventually log4j2) in what we incorporate into Solr, particularly as we move to making a standalone application. Taking away the user's choice of logging framework would allow us to control logging more effectively from the admin UI.
          Hide
          janhoy Jan Høydahl added a comment -

          Yes, they will get a warning when running in solr-8983-console.log that we were not able to tune down logging.
          But then again, if they actually switched to Logback or some other backend, then they are on their own in configuring that framework, and they may not even configure any Console loggers at all, so then it is not really a problem that we were unable to mute log4j ConsoleAppenders...

          +1 to choosing one log backend and not officially support anything else.

          Show
          janhoy Jan Høydahl added a comment - Yes, they will get a warning when running in solr-8983-console.log that we were not able to tune down logging. But then again, if they actually switched to Logback or some other backend, then they are on their own in configuring that framework, and they may not even configure any Console loggers at all, so then it is not really a problem that we were unable to mute log4j ConsoleAppenders... +1 to choosing one log backend and not officially support anything else.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 7498ca9ad67b25e48e2ae182256864b06d82e186 in lucene-solr's branch refs/heads/branch_6x from Jan Høydahl
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=7498ca9 ]

          SOLR-8186: Added robustness to the dynamic log muting logic

          (cherry picked from commit eabb05f)

          Show
          jira-bot ASF subversion and git services added a comment - Commit 7498ca9ad67b25e48e2ae182256864b06d82e186 in lucene-solr's branch refs/heads/branch_6x from Jan Høydahl [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=7498ca9 ] SOLR-8186 : Added robustness to the dynamic log muting logic (cherry picked from commit eabb05f)
          Show
          janhoy Jan Høydahl added a comment - Documented auto console log muting in RefGuide: https://cwiki.apache.org/confluence/pages/diffpagesbyversion.action?pageId=32604193&selectedPageVersions=24&selectedPageVersions=23
          Hide
          shalinmangar Shalin Shekhar Mangar added a comment -

          Closing after 6.3.0 release.

          Show
          shalinmangar Shalin Shekhar Mangar added a comment - Closing after 6.3.0 release.

            People

            • Assignee:
              janhoy Jan Høydahl
              Reporter:
              elyograg Shawn Heisey
            • Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development