search

IQSS / dataverse

Open source research data repository software
http://dataverse.org
Other
878 stars 485 forks source link

Logging: Verbose debug logging in server log happening on some machines post 4.10.1 release #5534

Closed kcondon closed 5 years ago

kcondon commented 5 years ago

Several developer machines and at least one test box are showing verbose debug logging in the server log, for example when loading the homepage or where dataset cards are rendered. It appears in other places too but we have not enumerated them. They seem to be lower-level HTTP messages and message within message.

Testing indicates they may have started appearing with this merge: https://github.com/IQSS/dataverse/pull/5484 5483-netbeans-code-coverage

Here are some examples:

[2019-02-13T12:14:58.355-0500] [glassfish 4.1] [INFO] [] [] [tid: _ThreadID=83 _ThreadName=Thread-8] [timeMillis: 1550078098355] [levelValue: 800] [[ 12:14:58.355 [http-listener-1(51)] DEBUG org.apache.http.wire - http-outgoing-0 << "Fralin_Greek_Vases_20151120-kantharos.stl[0xff]"?[\n]"]]

[2019-02-13T12:14:58.354-0500] [glassfish 4.1] [INFO] [] [] [tid: _ThreadID=83 _ThreadName=Thread-8] [timeMillis: 1550078098354] [levelValue: 800] [[ 12:14:58.354 [http-listener-1(51)] DEBUG o.a.h.impl.execchain.MainClientExec - Connection can be kept alive indefinitely]]

[2019-02-13T12:14:58.222-0500] [glassfish 4.1] [INFO] [] [] [tid: _ThreadID=83 _ThreadName=Thread-8] [timeMillis: 1550078098222] [levelValue: 800] [[ 12:14:58.222 [http-listener-1(51)] DEBUG o.a.h.i.c.DefaultManagedHttpClientConnection - http-outgoing-0: set socket timeout to 600000]]

@qqmyers Any thoughts on this?

kcondon commented 5 years ago

It looks like Apache httpClient logging is turned on in some way? https://hc.apache.org/ https://hc.apache.org/httpcomponents-client-ga/logging.html https://stackoverflow.com/questions/4915414/disable-httpclient-logging

matthew-a-dunlap commented 5 years ago

I'm snooping through our closed PRs now to see what may be indicative of this issue.

qqmyers commented 5 years ago

@kcondon - I see this on one of our 3 machines at QDR and not the other two, even running the same code. I've looked through our config and haven't been able to find out why its occurring. I recall trying to look at wire logging during development but didn't get it to work - so it's possible I added and forgot to remove some code or a jar via maven that didn't work for me but is popping up on some machines(some load order aspect?)

I think a key clue is that the apache debug statements are getting wrapped in a glassfish info-level log entry. I don't know what that means except that the log isn't directly allowing debug level entries from apache...

matthew-a-dunlap commented 5 years ago

Things I've found:

pdurbin commented 5 years ago

While brainstorming for solutions during standup we touched on the idea of simply reducing the logging. As I was saying, there is precedence for this. As part of #643 we ultimately added the following to http://guides.dataverse.org/en/4.10.1/installation/shibboleth.html#sslengine-warning-workaround

screen shot 2019-02-13 at 1 55 04 pm

Obviously, any other fix would be better than this.

matthew-a-dunlap commented 5 years ago

I'm pretty sure I've identified a factor in this issue, it being related to #4706 OAI-ORE and BagIT development. I removed the the pom dependencies to duracloud and deleted the DuraCloudSubmitToArchiveCommand.java for the application to compile. Doing this the log messages disappeared when loading the search page.

I'm not really sure what is actually going on though, maybe duracloud is pulling in some library that maven is choosing that has these log messages on?

matthew-a-dunlap commented 5 years ago

I would like to know what is actually being logged, even if we quiet it. Is our network traffic being piped into this library?

pdurbin commented 5 years ago

@qqmyers it looks like @matthew-a-dunlap is right. In pull request #5556 I ripped out the DuraCloud/Chronopolis feature entirely and the logs are back to normal. Obviously, I don't want that pull request to go into QA but I want us to have some options. Do you have any insight into this?

qqmyers commented 5 years ago

@pdurbin - the only clue I have is that there are web reports that having logback classes involved can trigger this unless you add a logback.xml file to explicitly turn off the wire logging. I haven't yet gone back to see if those classes are coming in as duracloud dependencies but I wouldn't be surprised. I'll look but if we need a fix faster than I can get to it, I think the PR would work. I'll try dropping a logback file later today to see if that is a work-around that doesn't just remove the feature.

pdurbin commented 5 years ago

@qqmyers sounds good. I appreciate you taking a look. The extra logging is bad enough that we don't want to ship a release until we do something about it. I'll add a 4.11 milestone to reflect this.

I'm trying to make sense of the dependency graph below that @matthew-a-dunlap showed me how to see in Netbeans by clicking "Graph" after you open pom.xml. I know the screenshot below is illegible but in Netbeans I can zoom and scroll around. If you know of other tools in this space, please advise. Thanks.

dependency-graph-e9cfb6fdd

qqmyers commented 5 years ago

@pdurbin - yeah, I've been looking here but with only one of three machines affected, I was focusing on config rather than code. In any case, running maven directly with a "dependency:tree" target will get you a list: mvn dependency:tree (I've got maven 3.5.4 - v3.1.1 was too early to have this feature.

qqmyers commented 5 years ago

I see this:

[INFO] +- org.duracloud:common:jar:4.4.6:compile
[INFO] |  +- com.thoughtworks.xstream:xstream:jar:1.4.7:compile
[INFO] |  |  +- xmlpull:xmlpull:jar:1.1.3.1:compile
[INFO] |  |  \- xpp3:xpp3_min:jar:1.1.4c:compile
[INFO] |  +- org.springframework:spring-core:jar:4.2.5.RELEASE:compile
[INFO] |  \- ch.qos.logback:logback-classic:jar:1.1.2:compile
[INFO] |     \- ch.qos.logback:logback-core:jar:1.1.2:compile

So perhaps excluding logback will work. If it is required (and not just another plugin to java logging) we may need a logback.xml file. If it is just another framework plugging in, that could explain why some machines are affected - only if it gets loaded at the right time relative the the other loggers does it cause trouble...

pdurbin commented 5 years ago

@qqmyers perhaps. Thanks. Here's a diff that shows all the dependencies that were added with the Duracloud/Chronopolis feature:

murphy:dataverse pdurbin$ diff -u /tmp/deptree-remove-duracloud-40bc99e60.txt /tmp/deptree-develop-e9cfb6fdd.txt 
--- /tmp/deptree-remove-duracloud-40bc99e60.txt 2019-02-15 09:43:25.000000000 -0500
+++ /tmp/deptree-develop-e9cfb6fdd.txt  2019-02-15 09:42:49.000000000 -0500
@@ -94,7 +94,6 @@
 [INFO] +- org.apache.poi:poi-ooxml:jar:4.0.0:compile
 [INFO] |  +- org.apache.poi:poi-ooxml-schemas:jar:4.0.0:compile
 [INFO] |  |  \- org.apache.xmlbeans:xmlbeans:jar:3.0.1:compile
-[INFO] |  +- org.apache.commons:commons-compress:jar:1.18:compile
 [INFO] |  \- com.github.virtuald:curvesapi:jar:1.04:compile
 [INFO] +- org.apache.poi:poi-examples:jar:4.0.0:compile
 [INFO] |  \- org.apache.poi:poi-scratchpad:jar:4.0.0:compile
@@ -177,6 +176,33 @@
 [INFO] +- org.glassfish.jersey.media:jersey-media-multipart:jar:2.23.2:compile
 [INFO] |  \- org.jvnet.mimepull:mimepull:jar:1.9.6:compile
 [INFO] +- com.mashape.unirest:unirest-java:jar:1.4.9:compile
+[INFO] +- org.apache.commons:commons-compress:jar:1.18:compile
+[INFO] +- org.duracloud:common:jar:4.4.6:compile
+[INFO] |  +- com.thoughtworks.xstream:xstream:jar:1.4.7:compile
+[INFO] |  |  +- xmlpull:xmlpull:jar:1.1.3.1:compile
+[INFO] |  |  \- xpp3:xpp3_min:jar:1.1.4c:compile
+[INFO] |  +- org.springframework:spring-core:jar:4.2.5.RELEASE:compile
+[INFO] |  \- ch.qos.logback:logback-classic:jar:1.1.2:compile
+[INFO] |     \- ch.qos.logback:logback-core:jar:1.1.2:compile
+[INFO] +- org.duracloud:storeclient:jar:4.4.6:compile
+[INFO] |  +- org.duracloud:storageprovider:jar:4.4.6:compile
+[INFO] |  |  \- org.duracloud:common-queue:jar:4.4.6:compile
+[INFO] |  +- org.duracloud:storageproviderdata:jar:4.4.6:compile
+[INFO] |  |  \- org.duracloud:common-json:jar:4.4.6:compile
+[INFO] |  |     \- org.codehaus.jackson:jackson-xc:jar:1.9.5:compile
+[INFO] |  +- org.duracloud:reportdata:jar:4.4.6:compile
+[INFO] |  |  \- org.duracloud:common-xml:jar:4.4.6:compile
+[INFO] |  +- org.duracloud:snapshotdata:jar:4.4.6:compile
+[INFO] |  +- org.duracloud.db:account-management-db-model:jar:4.1.1:compile
+[INFO] |  |  +- org.hibernate.javax.persistence:hibernate-jpa-2.1-api:jar:1.0.0.Final:compile
+[INFO] |  |  \- org.springframework.security:spring-security-core:jar:4.0.4.RELEASE:compile
+[INFO] |  |     +- aopalliance:aopalliance:jar:1.0:compile
+[INFO] |  |     +- org.springframework:spring-aop:jar:4.2.5.RELEASE:compile
+[INFO] |  |     +- org.springframework:spring-beans:jar:4.2.5.RELEASE:compile
+[INFO] |  |     +- org.springframework:spring-context:jar:4.2.5.RELEASE:compile
+[INFO] |  |     \- org.springframework:spring-expression:jar:4.2.5.RELEASE:compile
+[INFO] |  \- org.jdom:jdom:jar:1.1:compile
+[INFO] +- commons-cli:commons-cli:jar:1.2:compile
 [INFO] \- org.apache.tika:tika-parsers:jar:1.19:compile
 [INFO]    +- org.apache.tika:tika-core:jar:1.19:compile
 [INFO]    +- javax.xml.bind:jaxb-api:jar:2.3.0:compile
@@ -252,7 +278,7 @@
 [INFO] ------------------------------------------------------------------------
 [INFO] BUILD SUCCESS
 [INFO] ------------------------------------------------------------------------
-[INFO] Total time: 1.826 s
-[INFO] Finished at: 2019-02-15T09:43:25-05:00
-[INFO] Final Memory: 26M/437M
+[INFO] Total time: 2.416 s
+[INFO] Finished at: 2019-02-15T09:42:49-05:00
+[INFO] Final Memory: 27M/437M
 [INFO] ------------------------------------------------------------------------
murphy:dataverse pdurbin$

deptree-remove-duracloud-40bc99e60.txt deptree-develop-e9cfb6fdd.txt

pdurbin commented 5 years ago

Over at http://irclog.iq.harvard.edu/dataverse/2019-01-31#i_86114 @poikilotherm was wondering when springframework was added as a dependency. Please above.

pdurbin commented 5 years ago

I tried messing around with a new file at src/main/java/logback.xml but couldn't quickly figure out how to quell the logging. I guess I'll move this to code review to offer my "5534-remove-duracloud-chronopolis-feature" branch in pull request #5556 since at https://github.com/IQSS/dataverse/pull/5556#issuecomment-464067177 @qqmyers seemed ok with dropping the DuraCloud/Chronopolis feature for now. I'm hoping we find a better solution, though. I'm out next week, by the way (school vacation week).

kcondon commented 5 years ago

Would this have anything to do with SLF4J in DuraCloud?

qqmyers commented 5 years ago

@kcondon - anything is possible, but that duracloud dependency should be being excluded in the pom at this point (due to the earlier conflicts that were causing issues only in some cases). The fact that logback is in there as well, we haven't yet tried to exclude it, and there's some connection between logback and apache wire logging on the web is why I'm focusing there for now...

qqmyers commented 5 years ago

Looks like excluding logback fixes this - a PR on the way...

qqmyers commented 5 years ago

Hopefully this solves the issue. FWIW, I plan to report back to DuraCloud and/or submit a PR(s) there to see if these dependencies can be removed and to see whether spring/others belong in code that nominally a library for people to use the API...

qqmyers commented 5 years ago

FWIW - I've verified that removing the logback*.jar files from WEB-INF/lib stops the verbose logging on our production machine and that the pom changes in the pull result in the logback files not being included (on machines that weren't showing the extra logging). So - should work, but I haven't redeployed our production server to test everything end-to-end.

pdurbin commented 5 years ago

@qqmyers thanks for pull request #5558! The logs seem to be back to normal. I'm curious about the upstream fix so please do feel free to link to the issue you create on the DuraCloud side.

@kcondon "back to normal" but I still do see a lot of these "autoUpdate" messages but these are known and were discussed in #4220:

[2019-02-15T13:29:50.144-0500] [glassfish 4.1] [INFO] [] [org.primefaces.component.outputpanel.OutputPanelRenderer] [tid: _ThreadID=33 _ThreadName=http-listener-1(5)] [timeMillis: 1550255390144] [levelValue: 800] [[ autoUpdate attribute is deprecated and will be removed in a future version, use p:autoUpdate component instead.]]