-
Notifications
You must be signed in to change notification settings - Fork 486
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Logging: Verbose debug logging in server log happening on some machines post 4.10.1 release #5534
Comments
It looks like Apache httpClient logging is turned on in some way? |
I'm snooping through our closed PRs now to see what may be indicative of this issue. |
@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... |
Things I've found:
|
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 Obviously, any other fix would be better than this. |
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 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? |
I would like to know what is actually being logged, even if we quiet it. Is our network traffic being piped into this library? |
@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? |
@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. |
@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. |
@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: |
I see this:
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... |
@qqmyers perhaps. Thanks. Here's a diff that shows all the dependencies that were added with the Duracloud/Chronopolis feature:
deptree-remove-duracloud-40bc99e60.txt |
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. |
I tried messing around with a new file at |
Would this have anything to do with SLF4J in DuraCloud? |
@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... |
Looks like excluding logback fixes this - a PR on the way... |
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... |
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. |
@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] [[ |
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:
#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?
The text was updated successfully, but these errors were encountered: