search

testdriven / psi-probe

Advanced manager and monitor for Apache Tomcat, forked from Lambda Probe
8 stars 1 forks source link

log4j root log not found #293

Open padcom opened 10 years ago

padcom commented 10 years ago

From edwardqu...@gmail.com on May 21, 2012 23:00:47

What steps will reproduce the problem? 1.Go to logs and click on catalina.out 2. 3. What is the expected result? View of Catalina.out log What happens instead? Under File Information it says "The page you requested does not exist on this server. Please use the navigation bar to locate the area you require. "

In probe.log it reports: 21 May 2012 21:55:18 [http-10500-1] ERROR com.googlecode.psiprobe.controllers.logs.LogHandlerController - log4j root log not found What version of Probe are you using? 2.3.1 What environment (browser version, Tomcat version, JVM version, server OS)? IE8, Tomcat 6.0.35, java version "1.6.0_16", RHEL4 Please provide any additional information below. (Attach logs or stack traces as files instead of pasting the contents here.) The problem seems similar to https://code.google.com/p/psi-probe/issues/detail?id=49 I can view JULI logs, but not log4j. The error only happens if a particular war file is deployed. If I remove the war file I can then view the catalina.out in probe.

Original issue: http://code.google.com/p/psi-probe/issues/detail?id=293

padcom commented 10 years ago

From MALfunct...@gmail.com on May 23, 2012 08:01:15

Can you provide the full URL that gave you this error? You can leave off everything before /probe/.

Status: NeedInfo

padcom commented 10 years ago

From edwardqu...@gmail.com on May 24, 2012 02:36:21

Hi, yes it is /probe/logs/follow.htm?logType=log4j&root=true&logIndex=A1

padcom commented 10 years ago

From edwardqu...@gmail.com on May 24, 2012 02:37:50

Also I have reproduced the same problem in Version 2.4.0-SNAPSHOT ( r680 2012-05-24 10:03 +0100).

padcom commented 10 years ago

From MALfunct...@gmail.com on June 05, 2012 13:24:39

Can you provide your log4j config file for Tomcat? Tomcat 6 uses JDK logging by default, so it appears you've customized yours a bit.

padcom commented 10 years ago

From MALfunct...@gmail.com on June 05, 2012 13:29:51

Also, please edit the log4j.properties file in probe.war so that the first line reads:

log4j.rootLogger=DEBUG, R

Then try accessing your catalina.log file again and let me know if there's a stack trace in probe's log. Thanks.

Owner: MALfunct...@gmail.com

padcom commented 10 years ago

From edwardqu...@gmail.com on June 11, 2012 04:04:49

Sorry for the slow reply. I have attached the stacktrace and this is the tomcat log4j.properties:

$ cat log4j.properties log4j.rootLogger=INFO, A1 log4j.appender.A1=org.apache.log4j.ConsoleAppender log4j.appender.A1.layout=org.apache.log4j.PatternLayout

log4j.appender.BEST=org.apache.log4j.RollingFileAppender log4j.appender.BEST.maxFileSize=100KB log4j.appender.BEST.maxBackupIndex=5 log4j.appender.BEST.File=../logs/best.log log4j.appender.BEST.layout=org.apache.log4j.PatternLayout log4j.appender.BEST.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

log4j.category.com.mycompany.best=DEBUG, BEST

Attachment: stacktrace.txt

padcom commented 10 years ago

From edwardqu...@gmail.com on June 14, 2012 01:41:48

The ticket status still says NeedInfo. Do you need anymore information? Ed.

padcom commented 10 years ago

From MALfunct...@gmail.com on June 14, 2012 02:28:46

Not sure. I haven't yet had a chance to evaluate the info you've given me.

padcom commented 10 years ago

From edwardqu...@gmail.com on June 14, 2012 11:26:55

No problem, the status still said NeedInfo so I was just checking you weren't waiting for my reply. Thanks for your help.

padcom commented 10 years ago

From edwardqu...@gmail.com on July 02, 2012 05:48:39

Still really keen to get this fixed if you have a chance to look at it. Let me know if you need anymore info. Thanks,Ed.

padcom commented 10 years ago

From MALfunct...@gmail.com on July 06, 2012 12:09:56

Sorry for all the delays on this end. I'm hoping to devote some time to this soon. In the meantime, it turns out I do need a bit more info.

1.) You mentioned that you could still see JULI logs. Are you using both JULI and log4j together for Tomcat 6 logs, or do you have another app that logs with JULI? 2.) Can you provide some details about the logging configuration of the .war file that seems to cause this issue? Better yet, could you provide the .war file itself, or a trimmed-down version of it that still causes this error?

Labels: -Milestone-TBD Milestone-2.4.0 Component-Logging

padcom commented 10 years ago

From edwardqu...@gmail.com on August 13, 2012 08:36:36

1) No I meant the problem seemed to happen when deploying the app on to tomcat instances configured with log4j, but not on tomcat instances using JULI.

2) Unfortunately I'm unable to do this because it's not my code.

I have uploaded put some configuration from the application into the attached file, so not sure if this helps?

Attachment: log4j.txt

padcom commented 10 years ago

From MALfunct...@gmail.com on August 13, 2012 09:01:13

Thanks for the info. One thing I've noticed is that when you get the error, it's trying to display the contents of a ConsoleAppender, which has no corresponding file from which to read.

One more question... you said before that the URL where you get this error is: /probe/logs/follow.htm?logType=log4j&root=true&logIndex=A1 (Note: A1 is a ConsoleAppender.) Does the link to the catalina.out have the same URL when this other app is not deployed? What I mean is, is the link URL the same when you're able to successfully view the contents of catalina.out?

padcom commented 10 years ago

From edwardqu...@gmail.com on August 14, 2012 02:08:37

I couldn't fit the whole page into one screenshot so split it into two images above (psiprobe1.JPG and psiprobe2.JPG) . As an observation but I notice the problem happens only on those logs where the value is blank under the APP column in logging sources.

I tried changing A1 to RollingFileAppender just to see if it made any difference but it didn't help.

log4j.appender.A1=org.apache.log4j.ConsoleAppender

log4j.appender.A1=org.apache.log4j.RollingFileAppender

Also uploaded another screenshot, which shows this working after I delete the application war file. You can see the URLs are the same in both cases.

If I redeploy the application and add a corresponding file to A1, for example:

log4j.appender.A1.File=${catalina.base}/logs/tomcat.log

I can then view the catalina.out (see psiprobe4.JPG) but I can't view tomcat.log above (see psiprobe5.JPG)

Attachment: psiprobe1.JPG psiprobe2.JPG psiprobe3.JPG psiprobe4.JPG psiprobe5.JPG

padcom commented 10 years ago

From MALfunct...@gmail.com on August 28, 2012 12:57:39

Wow, this is truly baffling. It really seems to be something specific to that application.

Does this troublesome app include a .jar file for log4j in its WEB-INF/lib? Seeing as the server likely has a log4j.jar in its common libs already, there's no need for another log4j.jar in any of the apps deployed to it. If it's present in the app's WEB-INF/lib, can you remove it and see if that makes any difference?

I want to explore the circumstances surrounding psiprobe5.jpg. If I understand correctly, psiprobe5.jpg is a picture where the troublesome app has been changed so it's writing to another file besides catalina.out. Please correct me if I'm wrong.

If I'm right, the log file you're trying to view should be specific to that app. In that case, that picture should really include an "webapp=abc" (or whatever the path is) in the query string. Can you try adding that to the query string to see if it changes anything? (Out of curiosity, did you censor the app's name in the images, or is that column under Logging Sources just blank?)

I'm also curious what you see in the "File Name" column in the Logs list for each of these cases. I realize you can't reveal it all, but what I'd most like to see is what the File Name column contained for psiprobe5.jpg.

padcom commented 10 years ago

From edwardqu...@gmail.com on August 29, 2012 07:11:45

Does this troublesome app include a .jar file for log4j in its WEB-INF/lib? [Yes it includes WEB-INF/lib/log4j-1.2.14.jar. I tried removing this and restarting but it made no difference.]

Seeing as the server likely has a log4j.jar in its common libs already , there's no need for another log4j.jar in any of the apps deployed to it. If it's present in the app's WEB-INF/lib, can you remove it and see if that makes any difference? [Actually there wasn't a log4j.jar in the catalina_home or catalina_base lib directories. I added tomcat-juli-adapters.jar and log4j-1.2.13.jar to the catalina_base lib directory, and added the log4j tomcat-juli.jar to the catalina_home/bin but this made no difference either]

I want to explore the circumstances surrounding psiprobe5.jpg. If I understand correctly, psiprobe5.jpg is a picture where the troublesome app has been changed so it's writing to another file besides catalina.out. Please correct me if I'm wrong. [yes this app has log4j configured to write its own logs. As standard we don't want apps to write to catalina.out]

If I'm right, the log file you're trying to view should be specific to that app. [no I'm trying to view the tomcat.log in psiprobe5.jpg. I can view the app logs fine apart from one called best.log which is a log from a security filter.]

In that case, that picture should really include an "webapp=abc" (or whatever the path is) in the query string. Can you try adding that to the query string to see if it changes anything? (Out of curiosity, did you censor the app's name in the images, or is that column under Logging Sources just blank?) [The column under Logging Sources is indeed blank, I didn't censor that. Also I tried http://10.88.51.115:8290/probe/logs/follow.htm?logType=log4j&root=true&logIndex=tomcat&webapp=%2f but got a 404. If I try http://10.88.51.115:8290/probe/logs/follow.htm?logType=log4j&root=true&logIndex=tomcat&webapp=troublesomeapp there's no difference i.e. the page hangs as in psiprobe5.jpg]

I'm also curious what you see in the "File Name" column in the Logs list for each of these cases. I realize you can't reveal it all, but what I'd most like to see is what the File Name column contained for psiprobe5.jpg. [these are the two file names I can't view /apps/bweb/apps/troublesomeapp/tomcat/logs/tomcat.log and /apps/bweb/apps/troublesomeapp/tomcat/logs/best.log ]

padcom commented 10 years ago

From MALfunct...@gmail.com on August 29, 2012 07:49:26

How is Tomcat writing its logs with log4j without having log4j in Tomcat libs? I am still trying to wrap my head around your configuration...

padcom commented 10 years ago

From edwardqu...@gmail.com on August 29, 2012 07:59:02

That confused me a bit as well! At a guess, I think it must be picking it up from one of these jar files:

$ find . -follow | grep log4j ./tomcat/webapps/probe/WEB-INF/classes/log4j.properties ./tomcat/webapps/probe/WEB-INF/lib/slf4j-log4j12-1.4.2.jar ./tomcat/webapps/probe/WEB-INF/lib/log4j-1.2.13.jar ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-SGPDEV3.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-NYKUAT.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-LDNDEV2.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-LDNDEV3.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-Integration.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-LDNDEV1.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-HKGDEV2.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-DEV1SGP.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-DR.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-LDNDEV5.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-UAT.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-SGSIT.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-SGPDEV2.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-SGPUAT.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-HKGDEV1.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j.dtd ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-SGPDEV1.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-SGUAT.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-LDNDEV4.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-NYKDEV1.xml ./tomcat/webapps/ROOT/WEB-INF/classes/com/companyx/invsol/web/log/log4j-Production.xml ./tomcat/webapps/ROOT/WEB-INF/lib/log4j-1.2.15.jar ./tomcat/lib/log4j.properties ./tomcat/lib/BESTFilter/ext/log4j-1.2.15.jar

padcom commented 10 years ago

From edwardqu...@gmail.com on August 30, 2012 09:14:14

We have this configured in catalina.properties so I think we must be using ./tomcat/lib/BESTFilter/ext/log4j-1.2.15.jar

common.loader=${catalina.base}/lib,${catalina.base}/lib/.jar,${catalina.base}/lib/BESTFilter/ext/.jar,${catalina.base}/lib/BESTFilter/lib/.jar,${catalina.home}/lib,${catalina.home}/lib/.jar

padcom commented 10 years ago

From MALfunct...@gmail.com on August 30, 2012 11:40:37

Ah yes. That sounds right.

Okay, so what appears to be happening is that the application is loading the BESTFilter from the server's classpath, which it inherits, and the log4j dependency is loaded with it.

I'm still trying to understand exactly the behavior you're seeing, so I've aggregated the different scenarios below. I think we may be dealing with two different bugs, but I want to verify all my information before I really start digging into the code to look for bugs.

Scenario 1: "Troublesome" app deployed, A1 is ConsoleAppender

* Images: psiprobe1.jpg, psiprobe2.jpg

* Images: -

Scenario 2: "Troublesome" app undeployed, A1 is ConsoleAppender

* Images: psiprobe3.jpg

* Images: -

Scenario 3: "Troublesome" app deployed, A1 is FileAppender writing to tomcat.log

* Images: psiprobe4.jpg

* Images: psiprobe5.jpg

* Images: -

Please fill in the question marks above and let me know if there are any mistakes. Don't worry about uploading images for missing logs if they all look the same.

Out of curiosity, if you are in Scenario 1 and you access the first URL from scenario 3 (probe/logs/follow.htm?logType=stdout&logName=catalina.out), what happens?

padcom commented 10 years ago

From edwardqu...@gmail.com on September 10, 2012 02:08:31

Answering your last question first. In scenario 1 if I use probe/logs/follow.htm?logType=stdout&logName=catalina.out in place of probe/logs/follow.htm?logType=log4j&root=true&logIndex=A1 I can see the catalina.out.

padcom commented 10 years ago

From edwardqu...@gmail.com on September 10, 2012 02:09:01

Scenario 1: "Troublesome" app deployed, A1 is ConsoleAppender

* Images: psiprobe1.jpg, psiprobe2.jpg

padcom commented 10 years ago

From edwardqu...@gmail.com on September 10, 2012 02:17:33

Scenario 2: "Troublesome" app undeployed, A1 is ConsoleAppender

* Images: psiprobe2.jpg

padcom commented 10 years ago

From edwardqu...@gmail.com on September 10, 2012 02:27:34

Scenario 3: "Troublesome" app deployed, A1 is FileAppender writing to tomcat.log

* Images: psiprobe4.jpg

* Images: psiprobe5.jpg

* Images: psiprobe5.jpg

padcom commented 10 years ago

From edwardqu...@gmail.com on September 10, 2012 06:12:55

Going back to scenerio 2, I was confused why the log wouldn't load when I undeployed the app. The reason I think is because I set up the BEST Filter on psi probe to authenticate users accessing psi probe.

padcom commented 10 years ago

From MALfunct...@gmail.com on September 10, 2012 11:33:16

Can you try Scenario 2 again with an unmodified copy of PSI Probe?

padcom commented 10 years ago

From edwardqu...@gmail.com on September 11, 2012 06:39:36

ok, I discovered the problem was /apps/bweb/apps/troublesomeapp/tomcat/conf/Catalina/localhost/ROOT.xml After I removed that both logs loaded fine.

Scenario 2: "Troublesome" app undeployed, A1 is ConsoleAppender

padcom commented 10 years ago

From MALfunct...@gmail.com on September 11, 2012 07:23:43

Ok, thanks. I think I have enough information to address this, but it may take a while.

Status: Accepted

padcom commented 10 years ago

From MALfunct...@gmail.com on September 11, 2012 08:08:35

Wait, I'm sorry. What was wrong with your ROOT context?

Status: NeedInfo

padcom commented 10 years ago

From edwardqu...@gmail.com on September 11, 2012 09:19:34

Thanks. Do you mean this:

$ cat tomcat/conf/Catalina/localhost/ROOT.xml <?xml version="1.0" encoding="UTF-8"?>

padcom commented 10 years ago

From MALfunct...@gmail.com on September 11, 2012 11:14:17

Not exactly. In comment 31, you said that the problem in Scenario 2 was that ROOT.xml file. I have some questions:

padcom commented 10 years ago

From edwardqu...@gmail.com on September 11, 2012 12:54:12

Oh I see the confusion. The troublesome app is deployed as ROOT.war.

padcom commented 10 years ago

From MALfunct...@gmail.com on September 11, 2012 13:33:39

Okay, I think I have enough to go on. I just know I'm going to have to re-read all the comments a few times. :)

Status: Accepted

padcom commented 10 years ago

From edwardqu...@gmail.com on September 12, 2012 06:42:53

Ha, thanks for persisting with this and let me know if you need anymore info :-)