Highlighted
2 Bronze

Object content being dumped to logs

Let me start with apologizing for the lengthy post. Just want to make sure all the details are provided in one go...

We use com.emc.atmos.api.jersey.AtmosApiClient class to call getObjectMetadata and readObjectStream methods to retrieve the objects from the storage. Functionality is working absolutely fine and we don't have any issue with that. However, on the catalina.out log file we see below log debug information for getObjectMetadata:

DEBUG: Connection request: [route: {}->http://<host>:<port>][total kept alive: 0; route allocated: 0 of 200; total allocated: 0 of 200]

DEBUG: Connection leased: [id: 1][route: {}->http://<host>:<port>][total kept alive: 0; route allocated: 1 of 200; total allocated: 1 of 200]

DEBUG: Connecting to <host>:<port>

DEBUG: CookieSpec selected: best-match

DEBUG: Target auth state: UNCHALLENGED

DEBUG: Proxy auth state: UNCHALLENGED

DEBUG: Attempt 1 to execute request

DEBUG: Sending request: HEAD /rest/objects/<object_ID> HTTP/1.1

DEBUG: >> "HEAD /rest/objects/<object_ID> HTTP/1.1[\r][\n]"

DEBUG: >> "x-emc-utf8: true[\r][\n]"

DEBUG: >> "Date: Mon, 9 Jul 2018 21:10:25 UTC[\r][\n]"

DEBUG: >> "x-emc-date: Mon, 9 Jul 2018 21:10:25 UTC[\r][\n]"

DEBUG: >> "x-emc-uid: <UID>[\r][\n]"

DEBUG: >> "x-emc-signature: <signature>[\r][\n]"

DEBUG: >> "Host: <host>:<port>[\r][\n]"

DEBUG: >> "Connection: Keep-Alive[\r][\n]"

DEBUG: >> "User-Agent: Apache-HttpClient/4.2.6 (java 1.5)[\r][\n]"

DEBUG: >> "[\r][\n]"

DEBUG: >> HEAD /rest/objects/<object_ID> HTTP/1.1

DEBUG: >> x-emc-utf8: true

DEBUG: >> Date: Mon, 9 Jul 2018 21:10:25 UTC

DEBUG: >> x-emc-date: Mon, 9 Jul 2018 21:10:25 UTC

DEBUG: >> x-emc-uid: <UID>

DEBUG: >> x-emc-signature: <signature>

DEBUG: >> Host: <host>:<port>

DEBUG: >> Connection: Keep-Alive

DEBUG: >> User-Agent: Apache-HttpClient/4.2.6 (java 1.5)

DEBUG: << "HTTP/1.1 200 OK[\r][\n]"

DEBUG: << "Date: Mon, 09 Jul 2018 21:10:19 GMT[\r][\n]"

DEBUG: << "x-emc-mtime: 1531164643814[\r][\n]"

DEBUG: << "x-emc-meta: <the_metadata>[\r][\n]"

DEBUG: << "x-emc-listable-meta: filename=Test%20New%20Download%20Cloud%20Storage.xlsx[\r][\n]"

DEBUG: << "x-emc-useracl: <uid>=FULL_CONTROL[\r][\n]"

DEBUG: << "x-emc-groupacl: other=READ[\r][\n]"

DEBUG: << "x-emc-policy: default[\r][\n]"

DEBUG: << "x-emc-utf8: true[\r][\n]"

DEBUG: << "x-emc-request-id: <request_id>[\r][\n]"

DEBUG: << "Content-Type: application/octet-stream[\r][\n]"

DEBUG: << "Content-Length: 1219856[\r][\n]"

DEBUG: << "[\r][\n]"

DEBUG: Receiving response: HTTP/1.1 200 OK

DEBUG: << HTTP/1.1 200 OK

DEBUG: << Date: Mon, 09 Jul 2018 21:10:19 GMT

DEBUG: << x-emc-mtime: 1531164643814

DEBUG: << x-emc-meta: <the_metadata>

DEBUG: << x-emc-listable-meta: filename=Test%20New%20Download%20Cloud%20Storage.xlsx

DEBUG: << x-emc-useracl: <uid>=FULL_CONTROL

DEBUG: << x-emc-groupacl: other=READ

DEBUG: << x-emc-policy: default

DEBUG: << x-emc-utf8: true

DEBUG: << x-emc-request-id: <request_id>

DEBUG: << Content-Type: application/octet-stream

DEBUG: << Content-Length: 1219856

DEBUG: Connection can be kept alive indefinitely

DEBUG: Connection [id: 1][route: {}->http://<host>:<port>] can be kept alive indefinitely

DEBUG: Connection released: [id: 1][route: {}->http://<host>:<port>][total kept alive: 1; route allocated: 1 of 200; total allocated: 1 of 200]

And for readObjectStream:

All of the above debug logs plus -

DEBUG: << Content-Type: application/octet-stream

DEBUG: << Content-Length: 1219856

DEBUG: Connection can be kept alive indefinitely

DEBUG: << "PK[0x3][0x4][0x14][0x0][0x8][0x8][0x8][0x0][0xd4]s[0xe9]L[0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x11][0x0][0x0][0x0]docProps/core.xml[0xad][0x91]MK[0xc4]0[0x10][0x86][0xef][0xfd][0x15]![0xf7]v[0xd2][0xad][0xe8][0x1a][0xda].[0xa2],[0x8][0x8a][0xb][0xae]([0xde]B:[0xb6][0xc5][0xe6][0x83]$[0xda][0xf5][0xdf][0x9b][0xed][0xae][0x15][0xc5][0xa3][0xc7][0xc9][0xfb][0xbc][0xf][0xc3][0xa4]\[0xed][0xd4]@[0xde][0xd1][0xf9][0xde][0xe8][0x8a][0xe6][0x19][0xa3][0x4][0xb5]4M[0xaf][0xdb][0x8a]>l[0xd7][0xe9][0x92][0xae][0xea]$)[0xa5]q[0xb8]q[0xc6][0xa2][0xb]=z[0x12][[0xda]W[0xb4][0xb][0xc1]r[0x0]/;T[0xc2]g1[0xd6]1y1N[0x89][0x10]G[0xd7][0x82][0x15][0xf2]U[0xb4][0x8][0xb][0xc6]NAa[0x10][0x8d][0x8][0x2][0xf6][0xb6][0xd4][0xce]:z[0xf0]qi[0xff]][0xd9][0xc8]Yi[0xdf][0xdc]0[0x9][0x1a][0x9]8[0xa0]B[0x1d]<[0xe4]Y[0xe][0xdf]l@[0xa7][0xfc][0x9f][0x85])[0x99][0xc9][0x9d][0xef]gj[0x1c][0xc7]l,&.n[0x94][0xc3][0xd3][0xed][0xcd][0xfd][0xb4]|[0xda]k[0x1f][0x84][0x96]H[0xeb][0x84][0x90][0xf2]h[0xe7][0xd2][0xa1][0x8][0xd8][0x90][0xe8][0xe0][0xe1][0xc3]bE[0xbf][0x92][0xc7][0xe2][0xf2]j[0xbb][0xa6][0xf5][0x82][0xe5][0xcb][0x94][0x9d][0xa5][0xec]|[0x9b][0x9f][0xf0][0x82]qV<[0x97][0xf0][0xab]t[0x1e]F[0xe3][0xea][0x8b]x[0x96][0xe][0xc9][0xe6][0xee]z[0x8f][0xce][0xcf]I[0x9]?[0xbf][0xae]N>[0x1]PK[0x7][0x8][0x9d][0xf0][0x7][0x1e][0x5][0x1][0x0][0x0][0xf4][0x1][0x0][0x0]PK[0x3][0x4][0x14][0x0][0x8][0x8][0x8][0x0][0xd4]s[0xe9]L[0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0xb][0x0][0x0][0x0]_rels/.rels[0xad][0x92][0xc1]N[0xc3]0[0xc][0x86][0xef]}[0x8a]([0xf7][0xd5][0xdd][0x90][0x10]BMwAH[0xbb]Mh<@H[0xdc]6j[0x13]G[0x89][0x7][0xe5][0xed][0x9][0x7][0x4]C[0xc]v[0xe0][0x18][0xe7][0xf7][0xe7]O[0xb2][0xdb][0xed][0xe2]g[0xf1][0x8c]);[\n]"

DEBUG: << "J[0xae][0xeb]F[\n]"

DEBUG: << "[0xc][0x86][0xac][0xb][0x83][0x92][0x8f][0x87][0xfb][0xd5][0x8d][0xdc]vU[0xd5]>[0xe0][0xac][0xb9]d[0xf2][0xe8]b[0x16][0xa5])d%G[0xe6]x[0xb][0x90][0xcd][0x88]^[0xe7][0x9a]"[0x86][0xf2][0xd3]S[0xf2][0x9a][0xcb]3[\r][0x10][0xb5][0x99][0xf4][0x80][0xb0]i[0x9a]kH_[0x19][0xb2][0xab][0x84]8[0xc1][0x8a][0x9d]U2[0xed][0xec]Z[0x8a][0xc3]k[0xc4]K[0xf0][0xd4][0xf7][0xce][0xe0][0x1d][0x99][0xa3][0xc7][0xc0]?L[0xf9][0x96](d[0x9d][0x6]d%[0x97][0x19]^(MODS][0xa0][0x12][0xce][0xea]l[0xfe]S[0x7][0x17][0xc6]`[0xd1][0xae]b*[0xfd][0x89][0x1d][0xe6]O'Kf_[0xca][0x19]t[0x8c]H]].u~[0x5][0xe0][0x91][0xb5][0xd5][0xac][0xc1]P[0xc2][0xdf][0x95][0xde][0x13][0x1f]N-[0x9c]\CW[0xbd][0x1]PK[0x7][0x8]W(^#[0xe3][0x0][0x0][0x0]F[0x2][0x0][0x0]PK[0x3][0x4][0x14][0x0][0x8][0x8][0x8][0x0][0xd4]s[0xe9]L[0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x13][0x0][0x0][0x0][Content_Types].xml[0xad][0x93][0xcb]N[0xc3]0[0x10]E[0xf7][0xf9][\n]"

So basically the API is dumping even the binary content of the file to logs. This debug log is what we want to avoid being written to logs.

In order to fix this we created a log4j.properties file with entries shown below, made sure that the file is getting read properly by removing the entry log4j.appender.A1.layout from the file and we got a warning indicating this entry is missing. When I debug just before calling readObjectStream method the Atmos Client object created was (com.emc.atmos.api.jersey.AtmosApiClient) - So we tried to set the logger level to ERROR for this package - but still we can see all the binary content being dumped to catalina.out!! Any hints to solve this is greatly appreciated!! Thanks in advance.

# Set root logger level to DEBUG and its only appender to A1.

log4j.rootLogger=ERROR, A1

# A1 is set to be a ConsoleAppender.

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

# A1 uses PatternLayout.

log4j.appender.A1.layout=org.apache.log4j.PatternLayout

log4j.appender.A1.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n

# Print only messages of level INFO or above in the package com.emc.

log4j.logger.com.emc=ERROR

log4j.logger.com.emc.atmos.api.AtmosApi=ERROR

log4j.logger.com.emc.atmos.api.jersey=ERROR

Jars being used: atmos-client-3.0.1.jar, commons-httpclient-3.0.1.jar, jersey-apache-httpclient4-1.18-CUSTOM.jar
, jersey-client-1.19.jar, jersey-core-1.18.jar

Labels (1)
0 Kudos
Reply
3 Replies
Highlighted
3 Argentum

Those log statements don't match the pattern you've set.  It seems you may have some other log configuration active (the Apache httpclient supports a few).  Read this, and see if perhaps you have some other log configuration that is setting the root logger to DEBUG level:

https://hc.apache.org/httpcomponents-client-ga/logging.html

0 Kudos
Reply
Highlighted
2 Bronze

Stu Arnett,

I think you are right that there is another log configuration active. We have a custom logging framework which is built on top of log4j which might be causing this. I tried to limit the logging level to ERROR in that configuration as well - which didn't help.

Is there a way we can force Atmos API to use a specific logging configuration? perhaps set some System properties or make sure a specific servlet is loaded first which sets the right logging configurations?

Thanks for taking time to go through this question.

0 Kudos
Reply
Highlighted
3 Argentum

The above logs are coming from the Apache httpclient library, which we use under the covers for our REST calls.  The link above is probably the most relevant to describe the options for configuring its log settings.

You might be able to differentiate the format used by your application log statements and the above statements to find which log framework is being initialized and where it is configured.  Maybe it's getting pulled in by a transitive dependency?  Maybe there is an environment variable triggering something in the app?  Unfortunately, these types of issues are not easy to track down.

0 Kudos
Reply