Limit logging

Hi,

I'm still trying to figure out how I can limit the log level of youtrack if it runs inside of a standalone Jetty 6 Servlet container on an default ubuntu server 10.04 installation.

The method described in the youtrack documentation seems to only apply to some "log files" that aren't even present on my installation. What jetty does is that it takes all stdout and stderr output and writes this to its own log file. For some reason youtrack outputs enourmus amounts of logging on the "INFO" level via stdout and I'm not able to change this.

Logs like this are logged multiple times every second:

221040 [http request: /_events?window_id=2 [l.I.sb.s.countIssuesTicker:tick]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Finish processing request /_events?window_id=2 [l.I.sb.s.countIssuesTicker:tick] in 1ms

I do not need this logs and all it does is that it kills cpu and disk performance...
17 comments
Comment actions Permalink
Official comment

This discussion mentions logging configuration file. Please mind that as of YouTrack 2018.1 the correct location is WEB-INF/lib/youtrack-webapp-xxxx.jar!/log4j.xml

Comment actions Permalink
Yes after the last discussion I tried the way that is described in the YouTRACK manual. It does nothing for me.

Could you please explain to me where these log files normally should turn up? You are configuring FileAppenders in Log4J so there must be files created somewhere, am I right? I don't have these files. Additionally YouTRACK seems to log on level INFO to it's standard output stream (stdout) regardles of any configuration. Jetty takes all stdout and stderr output and writes it to its own log file. This file is growing fast without any decent reason...

I deployed YouTRACK as a .WAR in a default Jetty on Ubuntu 10.04. i.e. I'm not using the .JAR distribution with it's embedded jetty.
0
Comment actions Permalink
So apparently no one at JetBRAINS knows why their own product outputs enormous amounts of logging data to stdout on a non configurable INFO logging level?... :(
0
Comment actions Permalink
Hello a.e.

To disable the described output please do following steps:
Go to Jetty webapps directory (default path is /usr/share/jetty/webapps).
Find YouTrack's WAR file and unpack it (you can use Midnight Commander if you want).
Edit file WEB-INF/classes/jetbrains/charisma/main/log4j.xml
To disable stdout logging find appender ASYNC and comment string <appender-ref ref="CONSOLE"></appender-ref>
So, ASYNC appender's section should be like this:
<appender name="ASYNC" class="org.apache.log4j.AsyncAppender">
<param name="BufferSize" value="2098"></param>
<param name="Blocking" value="false"></param>
<appender-ref ref="FILE"></appender-ref>
<!--<appender-ref ref="CONSOLE"></appender-ref>-->
<appender-ref ref="ERRORS"></appender-ref>
</appender>
prettyPrint();
To disable messages from jetbrains.mps.webr.runtime.servlet.MainServlet you need to add new category section:
<category name="jetbrains.mps.webr.runtime.servlet.MainServlet">
  <priority value="WARN"></priority>
</category>
prettyPrint();
Then save file and pack all early unpacked data back to WAR file.
Restart Jetty server.

P.S. You can find YouTrack log files in /var/log/jetty (this is default path).
0
Comment actions Permalink
Thank you Alexander for the explanation. I tried this new configuration steps but to no avail. Still everything is logged to stdout and "jetbrains.mps.webr.runtime.servlet.MainServlet" is still logging multiple lines per second...
0
Comment actions Permalink
a.e.

Could you please show me your log4j.xml. I'd like to see the file from Jetty's cache.
You can find it at path like this /var/cache/jetty/data/Jetty__8080_youtrack.war__youtrack__.gc13wk/webapp/WEB-INF/classes/jetbrains/charisma/main/log4j.xml
0
Comment actions Permalink
Hello Alexander,

sorry for the long wait. Here is the log4j.xml right from the Jetty cache:

http://pastebin.com/Yqzk4h04
0
Comment actions Permalink
Hello a.e.
Your configuration file log4j.xml is correct.
I've just placed it in my war file and restarted application.
So, I don't see described messages neither in out.log nor in youtrack.log.
Maybe you see old messages?
BTW after these manipulations with log4j.xml you can still see messages like these in jetty's request.log:
127.0.0.1 -  -  [22/Oct/2012:10:52:38 +0000] "POST /_events?window_id=12 HTTP/1.1" 404 1372
127.0.0.1 -  -  [22/Oct/2012:10:53:00 +0000] "POST /youtrack/_events?window_id=8 HTTP/1.1" 200 83

But to disable it you need to configure Jetty.
Or I'm not right and you continue see these messages in out.log and youtrack.log?
0
Comment actions Permalink
You are right the out.log is clean but I'm refering to the default jetty log file stderrout*.log. I don't refer to the request log. The file stderrout_2012_10_22.log (for today) gets a lot of entries every second like this:

589302184 [http request: /_events?window_id=1656 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Start processing request /_events?window_id=1656 [_heart_beat]
589302185 [http request: /_events?window_id=1656 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Finish processing request /_events?window_id=1656 [_heart_beat] in 1ms
589305698 [http request: /_events?window_id=2005 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Start processing request /_events?window_id=2005 [_heart_beat]
589305700 [http request: /_events?window_id=2005 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Finish processing request /_events?window_id=2005 [_heart_beat] in 2ms
589308918 [http request: /_events?window_id=1998 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Start processing request /_events?window_id=1998 [_heart_beat]
589308918 [http request: /_events?window_id=1998 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Finish processing request /_events?window_id=1998 [_heart_beat] in 1ms
589311820 [http request: /_events?window_id=1963 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Start processing request /_events?window_id=1963 [_heart_beat]
589311822 [http request: /_events?window_id=1963 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Finish processing request /_events?window_id=1963 [_heart_beat] in 2ms
589315819 [http request: /_events?window_id=1893 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Start processing request /_events?window_id=1893 [_heart_beat]
589315820 [http request: /_events?window_id=1893 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Finish processing request /_events?window_id=1893 [_heart_beat] in 1ms
589316343 [http request: /_events?window_id=1995 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Start processing request /_events?window_id=1995 [_heart_beat]
589316344 [http request: /_events?window_id=1995 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Finish processing request /_events?window_id=1995 [_heart_beat] in 1ms
589321497 [http request: /_events?window_id=1971 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Start processing request /_events?window_id=1971 [_heart_beat]
589321498 [http request: /_events?window_id=1971 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Finish processing request /_events?window_id=1971 [_heart_beat] in 1ms
589323378 [http request: /_events?window_id=1877 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Start processing request /_events?window_id=1877 [_heart_beat]
589323379 [http request: /_events?window_id=1877 [_heart_beat]] INFO jetbrains.mps.webr.runtime.servlet.MainServlet - Finish processing request /_events?window_id=1877 [_heart_beat] in 1ms
prettyPrint();

We host all our applications via Jetty around here and I've always been under the impression that stderrout*.log holds the stdout and stderr of all deployed web applications. I do not know why it seems to be a lot trickier with YouTRACK.
0
Comment actions Permalink
It's very strange. I see in my stderrout_2012_10_22.log now (I'm using config you posted) and there are no such messages.
Could you please stop Jetty, clean cache directory and start Jetty again?
0
Comment actions Permalink
I just stopped Jetty (sudo /etc/init.d/jetty stop), removed the cache (sudo rm -rf /var/cache/jetty/data) and started Jetty again. Still the all the heart_beat etc. stuff gets logged to the stderrout file... :(
0
Comment actions Permalink
What Jetty version do you use? Did you make any changes in Jetty's default configuration files?
I'm using version 6.1.24-6ubuntu0.11.10.1 with default configs on Ubuntu 11.10.
If you have any custom changes in your configs then please provide me them.
And it would be great to get your version of war file. You can upload archive to ftp://ftp.intellij.net/.uploads/ (it's accessible for write only).
0
Comment actions Permalink
The server in question is based on Ubuntu Server 10.04 LTS. The jetty version is "Version: 6.1.22-1ubuntu1.1". I made no changes to the jetty configuration. I uploaded our youtrack.war to the ftp server.
0
Comment actions Permalink
Hello a.e.,

I've set up environment as you have Ubuntu 10.04 / Jetty=6.1.22-1ubuntu1.1 / YouTrack (your youtrack.war)
And I cannot reproduce the problem.
After running YouTrack I have following content in stderrout.log:

$ cat /var/log/jetty/2012_10_23.stderrout.log
2012-10-23 18:45:31.330:INFO::jetty-6.1.22
2012-10-23 18:45:31.362:INFO::Deploy /etc/jetty/contexts/javadoc.xml -> org.mortbay.jetty.handler.ContextHandler@17bd6a1{/javadoc,file:/usr/share/doc/libjetty-java/api/}
2012-10-23 18:45:31.399:INFO::Extract file:/var/lib/jetty/webapps/youtrack.war to /var/cache/jetty/data/Jetty_0_0_0_0_8080_youtrack.war__youtrack__50vvgb/webapp
2012-10-23 18:45:33.332:INFO::NO JSP Support for /youtrack, did not find org.apache.jasper.servlet.JspServlet
2012-10-23 18:45:35.093:INFO::NO JSP Support for , did not find org.apache.jasper.servlet.JspServlet
2012-10-23 18:45:35.102:INFO::Opened /var/log/jetty/2012_10_23.request.log
2012-10-23 18:45:35.111:INFO::Started SelectChannelConnector@0.0.0.0:8080
Init web application log4j location: jetbrains/charisma/main/log4j.xml


That's all.
So, it seems the problem in your configuration.

P.S. Maybe there is other YouTrack instance deployed on your server?
0
Comment actions Permalink
Hello Alexander,

thanks for your investigation. This is pretty strange then. The only difference between our two setups is that I additionally host the .war distribution of sonatype nexus in this jetty. Can two separate webapps influence their logging configuration? But then I remember that the issue with too much logging although appeared back when our admin hosted youtrack on a separate machine in its own dedicated Jetty.
0
Comment actions Permalink
Alexander, thanks for the .war unpack/fix-log4j.xml/repack instructions to disable the excessive logging; it worked for me.
0

Please sign in to leave a comment.