Large amounts of debug output resulting in massive log files in AWS Elastic Beanstalk

Description

I initially brought up this issue on the dev forums: https://dev.lucee.org/t/massive-amounts-of-debug-logging-in-5-3-5-92/6921

To sum it up, we run our lucee application in AWS's Elastic Beanstalk service. After upgrading from 5.2.8.50 to 5.3.5.92, huge log files are being created on the EC2 instance, outside of the docker container. Logging levels are set to ERROR level in the lucee admin console, and none of the tomcat or lucee log files are bloating. Debugging is also turned off in the lucee admin console.

All we do to upgrade Lucee versions is modify the FROM line in our Docker file. This was not an issue with: "FROM lucee/lucee52:5.2.8.50". It only became an issue with "FROM lucee/lucee:5.3.5.92". My last test with "FROM lucee/lucee:5.3.7.11-SNAPSHOT" still contained this logging issue.

The contents of the log files appear to be debug level logging related to the application making external HTTP and/or S3 requests. The reason the files are so large is because they contain the entire file content (images, pdfs, etc) that have been uploaded to the server by users. I have included a sample of a log that has been redacted for senstive info. If you need to see some of the full (very large) logs, let me know and I'll work on cleaning one up.

For now, we have turned the logging off entirely by adding `--log-driver=none` to the `docker run` command in /opt/elasticbeanstalk/hooks/appdeploy/enacts/00run.sh. This is just a temporary solution because we have to keep adding it manually every time Elastic Beanstalk spawns a new EC2.

If I had to guess, there is some sort of console output that Elastic Beanstalk is picking up and logging. We've run into similar issues in a separate Node.js application where every `console.log()` left behind in the application code was being picked up in log files and eventually eating up all of the disk space of the EC2 instance.

Sample log file, named something like /var/log/eb-docker/containers/eb-current-app/eb-063d69495c9f-stdouterr.log:

DEBUG - Pooling connection [{s}->https://[BUCKET_NAME].s3.amazonaws.com:443][null]; keep alive indefinitely
DEBUG - Notifying no-one, there are no waiting threads
DEBUG - Released HttpMethod as its response data stream is fully consumed
DEBUG - Parsing XML response document with handler: class org.jets3t.service.impl.rest.XmlResponsesSaxParser$ListBucketHandler
DEBUG - Examining listing for bucket: [BUCKET_NAME]
DEBUG - Found 0 objects in one batch
DEBUG - Found 0 common prefixes in one batch
DEBUG - File name has no extension, mime type cannot be recognised for: aws-s317783892662367369622tmp
DEBUG - Creating Object with key dev-a-s/10k.txt in bucket [BUCKET_NAME]
DEBUG - Uploading object data with Content-Length: 10000
DEBUG - Setting maximal read-ahead mark limit for markable input stream org.jets3t.service.io.RepeatableFileInputStream assuming it doesn't use in-memory storage: 10000
DEBUG - Input stream marked at 0 bytes
DEBUG - httpclient.read-throttle=0
DEBUG - s3service.s3-endpoint=null
DEBUG - s3service.enable-storage-classes=true
DEBUG - s3service.s3-endpoint=null
DEBUG - Creating object bucketName=[BUCKET_NAME], objectKey=dev-a-s/10k.txt, storageClass=null. Content-Type=text/plain Including data? true Metadata: {x-amz-content-sha256=6e904788d0eb0feee634f4738163b34a2f63dd921e5c6583de081c975dd4d16c, x-amz-acl=public-read, md5-hash=9aaee861df25d65d6d5a40869379caa2, Content-Length=10000, Content-MD5=mq7oYd8l1l1tWkCGk3nKog==, Content-Type=text/plain} ACL: AccessControlList [owner=null, grants=[]]
DEBUG - s3service.disable-dns-buckets=false
DEBUG - s3service.s3-endpoint=s3.amazonaws.com
DEBUG - s3service.s3-endpoint-virtual-path=
DEBUG - s3service.s3-endpoint-https-port=443
DEBUG - S3 URL: https://[BUCKET_NAME].s3.amazonaws.com:443/dev-a-s/10k.txt
DEBUG - Performing PUT request for 'https://[BUCKET_NAME].s3.amazonaws.com:443/dev-a-s/10k.txt', expecting response codes: [200,204]
DEBUG - Headers: [Date: Thu, 23 Apr 2020 09:08:27 GMT, x-amz-content-sha256: 6e904788d0eb0feee634f4738163b34a2f63dd921e5c6583de081c975dd4d16c, x-amz-acl: public-read, x-amz-meta-md5-hash: 9aaee861df25d65d6d5a40869379caa2, Content-MD5: mq7oYd8l1l1tWkCGk3nKog==, Content-Type: text/plain]
DEBUG - httpclient.retry-max=5
DEBUG - Adding authorization for Access Key '[AWS_KEY]'.
DEBUG - s3service.s3-endpoint=s3.amazonaws.com
DEBUG - storage-service.request-signature-version=AWS2
DEBUG - s3service.s3-endpoint=s3.amazonaws.com
DEBUG - Canonical string ('|' is a newline): PUT|mq7oYd8l1l1tWkCGk3nKog==|text/plain|Thu, 23 Apr 2020 09:08:27 GMT|x-amz-acl:public-read|x-amz-content-sha256:6e904788d0eb0feee634f4738163b34a2f63dd921e5c6583de081c975dd4d16c|x-amz-meta-md5-hash:9aaee861df25d65d6d5a40869379caa2|/[BUCKET_NAME]/dev-a-s/10k.txt
DEBUG - Get connection: {s}->https://[BUCKET_NAME].s3.amazonaws.com:443, timeout = 0
DEBUG - [{s}->https://[BUCKET_NAME].s3.amazonaws.com:443] total kept alive: 3, total issued: 0, total allocated: 3 out of 20
DEBUG - Getting free connection [{s}->https://[BUCKET_NAME].s3.amazonaws.com:443][null]
DEBUG - Stale connection check
DEBUG - CookieSpec selected: default
DEBUG - Auth cache not set in the context
DEBUG - Proxy auth state: UNCHALLENGED
DEBUG - Attempt 1 to execute request
DEBUG - Sending request: PUT /dev-a-s/10k.txt HTTP/1.1
DEBUG -  >> "PUT /dev-a-s/10k.txt HTTP/1.1[\r][\n]"
DEBUG -  >> "Date: Thu, 23 Apr 2020 09:08:27 GMT[\r][\n]"
DEBUG -  >> "x-amz-content-sha256: 6e904788d0eb0feee634f4738163b34a2f63dd921e5c6583de081c975dd4d16c[\r][\n]"
DEBUG -  >> "x-amz-acl: public-read[\r][\n]"
DEBUG -  >> "x-amz-meta-md5-hash: 9aaee861df25d65d6d5a40869379caa2[\r][\n]"
DEBUG -  >> "Content-MD5: mq7oYd8l1l1tWkCGk3nKog==[\r][\n]"
DEBUG -  >> "Content-Type: text/plain[\r][\n]"
DEBUG -  >> "Authorization: AWS [AWS_KEY]:[AWS_SECRET][\r][\n]"
DEBUG -  >> "Content-Length: 10000[\r][\n]"
DEBUG -  >> "Host: [BUCKET_NAME].s3.amazonaws.com:443[\r][\n]"
DEBUG -  >> "Connection: Keep-Alive[\r][\n]"
DEBUG -  >> "User-Agent: JetS3t/0.9.4 (Linux/4.14.171-105.231.amzn1.x86_64; amd64; en; JVM 11.0.6)[\r][\n]"
DEBUG -  >> "Expect: 100-continue[\r][\n]"
DEBUG -  >> "[\r][\n]"
DEBUG - >> PUT /dev-a-s/10k.txt HTTP/1.1
DEBUG - >> Date: Thu, 23 Apr 2020 09:08:27 GMT
DEBUG - >> x-amz-content-sha256: 6e904788d0eb0feee634f4738163b34a2f63dd921e5c6583de081c975dd4d16c
DEBUG - >> x-amz-acl: public-read
DEBUG - >> x-amz-meta-md5-hash: 9aaee861df25d65d6d5a40869379caa2
DEBUG - >> Content-MD5: mq7oYd8l1l1tWkCGk3nKog==
DEBUG - >> Content-Type: text/plain
DEBUG - >> Authorization: AWS [AWS_KEY]:[AWS_SECRET]
DEBUG - >> Content-Length: 10000
DEBUG - >> Host: [BUCKET_NAME].s3.amazonaws.com:443
DEBUG - >> Connection: Keep-Alive
DEBUG - >> User-Agent: JetS3t/0.9.4 (Linux/4.14.171-105.231.amzn1.x86_64; amd64; en; JVM 11.0.6)
DEBUG - >> Expect: 100-continue
DEBUG -  << "HTTP/1.1 100 Continue[\r][\n]"
DEBUG -  << "[\r][\n]"
DEBUG - Receiving response: HTTP/1.1 100 Continue
DEBUG - << HTTP/1.1 100 Continue

[THIS LINE CONTAINS THE FULL CONTENTS OF THE UPLOADED FILE AND HAS BEEN MANUALLY TRUNCATED]
DEBUG -  >> "1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 
[THIS LINE CONTAINS THE FULL CONTENTS OF THE UPLOADED FILE AND HAS BEEN MANUALLY TRUNCATED]

DEBUG -  << "HTTP/1.1 200 OK[\r][\n]"
DEBUG -  << "x-amz-id-2: [LOOKS_SENSITIVE][\r][\n]"
DEBUG -  << "x-amz-request-id: 98D012D910ADE495[\r][\n]"
DEBUG -  << "Date: Thu, 23 Apr 2020 09:08:28 GMT[\r][\n]"
DEBUG -  << "ETag: "9aaee861df25d65d6d5a40869379caa2"[\r][\n]"
DEBUG -  << "Content-Length: 0[\r][\n]"
DEBUG -  << "Server: AmazonS3[\r][\n]"
DEBUG -  << "[\r][\n]"
DEBUG - Receiving response: HTTP/1.1 200 OK
DEBUG - << HTTP/1.1 200 OK
DEBUG - << x-amz-id-2: [LOOKS_SENSITIVE]
DEBUG - << x-amz-request-id: 98D012D910ADE495
DEBUG - << Date: Thu, 23 Apr 2020 09:08:28 GMT
DEBUG - << ETag: "9aaee861df25d65d6d5a40869379caa2"
DEBUG - << Content-Length: 0
DEBUG - << Server: AmazonS3
DEBUG - Connection can be kept alive indefinitely
DEBUG - Response for 'PUT'. Content-Type: , Headers: [x-amz-id-2: [LOOKS_SENSITIVE], x-amz-request-id: 98D012D910ADE495, Date: Thu, 23 Apr 2020 09:08:28 GMT, ETag: "9aaee861df25d65d6d5a40869379caa2", Content-Length: 0, Server: AmazonS3]
DEBUG - Response entity: org.apache.http.conn.BasicManagedEntity@19cb4b9
DEBUG - Entity length: 0
DEBUG - Received response code 200; matches one of expected set ([200, 204])? true
DEBUG - Released connection is reusable.
DEBUG - Releasing connection [{s}->https://[BUCKET_NAME].s3.amazonaws.com:443][null]
DEBUG - Pooling connection [{s}->https://[BUCKET_NAME].s3.amazonaws.com:443][null]; keep alive indefinitely
DEBUG - Notifying no-one, there are no waiting threads
DEBUG - Processing REST metadata items
DEBUG - Removed header prefix x-amz- from key: x-amz-content-sha256=>content-sha256
DEBUG - Removed header prefix x-amz- from key: x-amz-acl=>acl
DEBUG - Ignoring metadata item: Server=AmazonS3
DEBUG - Leaving header item unchanged: ETag="9aaee861df25d65d6d5a40869379caa2"
DEBUG - Ignoring metadata item: md5-hash=9aaee861df25d65d6d5a40869379caa2
DEBUG - Removed header prefix x-amz- from key: x-amz-request-id=>request-id
DEBUG - Leaving HTTP header item unchanged: Content-Length=10000
DEBUG - Removed header prefix x-amz- from key: x-amz-id-2=>id-2
DEBUG - Parsing date string 'Thu, 23 Apr 2020 09:08:28 GMT' into Date object for key: Date
DEBUG - Leaving header item unchanged: Date=Thu Apr 23 09:08:28 UTC 2020
DEBUG - Leaving HTTP header item unchanged: Content-MD5=mq7oYd8l1l1tWkCGk3nKog==
DEBUG - Leaving HTTP header item unchanged: Content-Type=text/plain
DEBUG - s3service.disable-dns-buckets=false
DEBUG - s3service.s3-endpoint=s3.amazonaws.com
DEBUG - s3service.s3-endpoint-virtual-path=
DEBUG - s3service.s3-endpoint-https-port=443
DEBUG - S3 URL: https://[BUCKET_NAME].s3.amazonaws.com:443/
DEBUG - Added request parameter: max-keys=10
DEBUG - Added request parameter: prefix=dev-a-s/10k.txt
DEBUG - Added request parameter: delimiter=,
DEBUG - Performing GET request for 'https://[BUCKET_NAME].s3.amazonaws.com:443/?max-keys=10&prefix=dev-a-s%2F10k.txt&delimiter=%2C', expecting response codes: [200]
DEBUG - Headers: [Date: Thu, 23 Apr 2020 09:08:27 GMT]
DEBUG - httpclient.retry-max=5
DEBUG - Adding authorization for Access Key '[AWS_KEY]'.
DEBUG - s3service.s3-endpoint=s3.amazonaws.com
DEBUG - storage-service.request-signature-version=AWS2
DEBUG - s3service.s3-endpoint=s3.amazonaws.com
DEBUG - Canonical string ('|' is a newline): GET|||Thu, 23 Apr 2020 09:08:27 GMT|/[BUCKET_NAME]/
DEBUG - Get connection: {s}->https://[BUCKET_NAME].s3.amazonaws.com:443, timeout = 0
DEBUG - [{s}->https://[BUCKET_NAME].s3.amazonaws.com:443] total kept alive: 3, total issued: 0, total allocated: 3 out of 20
DEBUG - Getting free connection [{s}->https://[BUCKET_NAME].s3.amazonaws.com:443][null]
DEBUG - Stale connection check
DEBUG - CookieSpec selected: default
DEBUG - Auth cache not set in the context
DEBUG - Proxy auth state: UNCHALLENGED
DEBUG - Attempt 1 to execute request
DEBUG - Sending request: GET /?max-keys=10&prefix=dev-a-s%2F10k.txt&delimiter=%2C HTTP/1.1
DEBUG -  >> "GET /?max-keys=10&prefix=dev-a-s%2F10k.txt&delimiter=%2C HTTP/1.1[\r][\n]"
DEBUG -  >> "Date: Thu, 23 Apr 2020 09:08:27 GMT[\r][\n]"
DEBUG -  >> "Authorization: AWS [AWS_KEY]:XtD5Ov/zIglrhtQNUikb/QxTVCg=[\r][\n]"
DEBUG -  >> "Host: [BUCKET_NAME].s3.amazonaws.com:443[\r][\n]"
DEBUG -  >> "Connection: Keep-Alive[\r][\n]"
DEBUG -  >> "User-Agent: JetS3t/0.9.4 (Linux/4.14.171-105.231.amzn1.x86_64; amd64; en; JVM 11.0.6)[\r][\n]"
DEBUG -  >> "[\r][\n]"
DEBUG - >> GET /?max-keys=10&prefix=dev-a-s%2F10k.txt&delimiter=%2C HTTP/1.1
DEBUG - >> Date: Thu, 23 Apr 2020 09:08:27 GMT
DEBUG - >> Authorization: AWS [AWS_KEY]:XtD5Ov/zIglrhtQNUikb/QxTVCg=
DEBUG - >> Host: [BUCKET_NAME].s3.amazonaws.com:443
DEBUG - >> Connection: Keep-Alive
DEBUG - >> User-Agent: JetS3t/0.9.4 (Linux/4.14.171-105.231.amzn1.x86_64; amd64; en; JVM 11.0.6)
DEBUG -  << "HTTP/1.1 200 OK[\r][\n]"
DEBUG -  << "x-amz-id-2: [LOOKS_SENSITIVE][\r][\n]"
DEBUG -  << "x-amz-request-id: 744F56DBFC15E855[\r][\n]"
DEBUG -  << "Date: Thu, 23 Apr 2020 09:08:28 GMT[\r][\n]"
DEBUG -  << "x-amz-bucket-region: us-east-1[\r][\n]"
DEBUG -  << "Content-Type: application/xml[\r][\n]"
DEBUG -  << "Transfer-Encoding: chunked[\r][\n]"
DEBUG -  << "Server: AmazonS3[\r][\n]"
DEBUG -  << "[\r][\n]"
DEBUG - Receiving response: HTTP/1.1 200 OK
DEBUG - << HTTP/1.1 200 OK
DEBUG - << x-amz-id-2: [LOOKS_SENSITIVE]
DEBUG - << x-amz-request-id: 744F56DBFC15E855
DEBUG - << Date: Thu, 23 Apr 2020 09:08:28 GMT
DEBUG - << x-amz-bucket-region: us-east-1
DEBUG - << Content-Type: application/xml
DEBUG - << Transfer-Encoding: chunked
DEBUG - << Server: AmazonS3
DEBUG - Connection can be kept alive indefinitely
DEBUG - Response for 'GET'. Content-Type: application/xml, Headers: [x-amz-id-2: [LOOKS_SENSITIVE], x-amz-request-id: 744F56DBFC15E855, Date: Thu, 23 Apr 2020 09:08:28 GMT, x-amz-bucket-region: us-east-1, Content-Type: application/xml, Transfer-Encoding: chunked, Server: AmazonS3]
DEBUG - Response entity: org.apache.http.conn.BasicManagedEntity@6ea70871
DEBUG - Entity length: -1
DEBUG - Received response code 200; matches one of expected set ([200])? true
DEBUG - xmlparser.sanitize-listings=true
DEBUG - Sanitizing XML document destined for handler class org.jets3t.service.impl.rest.XmlResponsesSaxParser$ListBucketHandler
DEBUG -  << "26a[\r][\n]"
DEBUG -  << "<?xml version="1.0" encoding="UTF-8"?>[\n]"
DEBUG -  << "<ListBucketResult xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>[BUCKET_NAME]</Name><Prefix>dev-a-s/10k.txt</Prefix><Marker></Marker><MaxKeys>10</MaxKeys><Delimiter>,</Delimiter><IsTruncated>false</IsTruncated><Contents><Key>dev-a-s/10k.txt</Key><LastModified>2020-04-23T09:08:28.000Z</LastModified><ETag>&quot;9aaee861df25d65d6d5a40869379caa2&quot;</ETag><Size>10000</Size><Owner><ID>b02bbd08bc9bcff8972392ceb9f9f7bb965b038f624f2544f6099a6b3839b017</ID><DisplayName>[OWNER]</DisplayName></Owner><StorageClass>STANDARD</StorageClass></Contents></ListBucketResult>"
DEBUG -  << "[\r][\n]"
DEBUG -  << "0[\r][\n]"
DEBUG -  << "[\r][\n]"
DEBUG - Released connection is reusable.
DEBUG - Releasing connection [{s}->https://[BUCKET_NAME].s3.amazonaws.com:443][null]
DEBUG - Pooling connection [{s}->https://[BUCKET_NAME].s3.amazonaws.com:443][null]; keep alive indefinitely
DEBUG - Notifying no-one, there are no waiting threads
DEBUG - Released HttpMethod as its response data stream is fully consumed
DEBUG - Parsing XML response document with handler: class org.jets3t.service.impl.rest.XmlResponsesSaxParser$ListBucketHandler
DEBUG - Examining listing for bucket: [BUCKET_NAME]
DEBUG - Created new object from listing: S3Object [key=dev-a-s/10k.txt, bucket=[BUCKET_NAME], lastModified=Thu Apr 23 09:08:28 UTC 2020, dataInputStream=null, storageClass=STANDARD, Metadata={ETag="9aaee861df25d65d6d5a40869379caa2", Last-Modified=Thu Apr 23 09:08:28 UTC 2020, Content-Length=10000}]
DEBUG - Found 1 objects in one batch
DEBUG - Found 0 common prefixes in one batch

Environment

OS: Docker running on 64bit Amazon Linux/2.14.3
Java Version: 11.0.6
Tomcat Version: 9.0.33
Lucee Version: 5.3.5.92

Attachments

08 May 2020, 07:01 pm

Activity

Show:

Zac Spitzer 8 January 2021 at 18:59

Deleted

Ricky Potash 8 January 2021 at 05:26
Edited

@Michael Offner Please delete the alpha-deploy-master.zip attachment from this issue.

Ricky 8 May 2020 at 19:02

@Michael Offner I’ve uploaded the jar and the source to the original post on this ticket.

Michael Offner 8 May 2020 at 14:42

@Ricky could you please attacj your jar here for testing.

we should make sure that this never happens in Lucee.

Ricky 5 May 2020 at 20:34

So, I’m no java expert, but here’s what I’ve gathered from the source of our custom jar. Compiled within the jar is a log4j.properties file. Within that file contains the line:

log4j.appender.APP=org.apache.log4j.ConsoleAppender

ConsoleAppender explains why the logs were only being created outside of docker. By default, Elastic Beanstalk collects all console output and logs it.

What I don’t understand is how simply having this jar file in the project (deployed to /usr/local/tomcat/lucee) is causing lucee to inherit the log4j settings. Luckily, we can just remove this jar from the project since we don’t need it anymore. But this crossing of wires is a tiny bit concerning should we ever need to implement logging in a custom jar in the future. Admittedly, that concern is probably rooted in my lack of understanding of the java ecosystem. I imagine there’s a way to encapsulate the logging directives.

Details
Assignee
Unassigned
Reporter
Ricky
Priority
New
Labels
loggingregression
New Issue warning screen
Before you create a new Issue, please post to the mailing list first https://dev.lucee.org
Once the issue has been verified, one of the Lucee team will ask you to file an issue
Affects versions
5.3.5.92
5.3.7.11

Created 28 April 2020 at 11:07

Updated 8 January 2021 at 18:59

Large amounts of debug output resulting in massive log files in AWS Elastic Beanstalk

Description

Environment

Attachments

Activity

Zac Spitzer 8 January 2021 at 18:59

Ricky Potash 8 January 2021 at 05:26
Edited

Ricky 8 May 2020 at 19:02

Michael Offner 8 May 2020 at 14:42

Ricky 5 May 2020 at 20:34

Details

Assignee

Reporter

Priority

Labels

New Issue warning screen

Affects versions

Flag notifications

Something's gone wrong

Something's gone wrong

Large amounts of debug output resulting in massive log files in AWS Elastic Beanstalk

Description

Environment

Attachments

Activity

Zac Spitzer 8 January 2021 at 18:59

Ricky Potash 8 January 2021 at 05:26Edited

Ricky 8 May 2020 at 19:02

Michael Offner 8 May 2020 at 14:42

Ricky 5 May 2020 at 20:34

Details

Assignee

Reporter

Priority

Labels

New Issue warning screen

Affects versions

Flag notifications

Something's gone wrong

Something's gone wrong

Ricky Potash 8 January 2021 at 05:26
Edited