Java debugging error messages going to stderr when DEBUG is enabled for Java Buildpack Provider on Tanzu Application Service for VMs

Products

• VMware Tanzu Application Service for VMs

Issue/Introduction

If you are pushing an application with LOGGING_LEVEL_ORG_CLOUDFOUNDRY_SECURITY set to DEBUG, you may observe STG ERR or ERR INFO logs even though the logs don't point to a real error, and the application starts and functions as expected.

Example 1

2021-07-21T09:45:41.723-05:00 [STG/0] [ERR] [Buildpack] DEBUG Instantiating JavaBuildpack::Framework::ContrastSecurityAgent
2021-07-21T09:45:41.757-05:00 [STG/0] [ERR] [Buildpack] DEBUG Successfully required JavaBuildpack::Framework::ContrastSecurityAgent
2021-07-21T09:45:41.758-05:00 [STG/0] [ERR] [ConfigurationUtils] DEBUG Configuration from /tmp/buildpacks/42c4e116ef6e5968871a863f88c4c4db/config/contrast_security_agent.yml: {"version"=>"3.8.2_19262", "repository_root"=>"https://download.run.pivotal.io/contrast-security"}
2021-07-21T09:45:41.758-05:00 [STG/0] [ERR] [Droplet] DEBUG Droplet root: /tmp/app
2021-07-21T09:45:41.758-05:00 [STG/0] [ERR] [Droplet] DEBUG Buildpack root: /tmp/app/.java-buildpack
2021-07-21T09:45:41.758-05:00 [STG/0] [ERR] [Droplet] DEBUG Sandbox root: /tmp/app/.java-buildpack/contrast_security_agent

Example 2

2021-09-02T23:55:40.31+0200 [APP/PROC/WEB/0] ERR Sep 02, 2021 9:55:40 PM org.cloudfoundry.security.CloudFoundryContainerTrustManagerFactory getSystemTrustManager
2021-09-02T23:55:40.31+0200 [APP/PROC/WEB/0] ERR INFO: Adding System Trust Manager
2021-09-02T23:55:40.31+0200 [APP/PROC/WEB/0] ERR Sep 02, 2021 9:55:40 PM org.cloudfoundry.security.CloudFoundryContainerTrustManagerFactory getContainerTrustManager
2021-09-02T23:55:40.31+0200 [APP/PROC/WEB/0] ERR INFO: Adding TrustManager for /etc/ssl/certs/ca-certificates.crt
2021-09-02T23:55:40.43+0200 [APP/PROC/WEB/0] ERR Sep 02, 2021 9:55:40 PM org.cloudfoundry.security.FileWatcher run
2021-09-02T23:55:40.43+0200 [APP/PROC/WEB/0] ERR INFO: Start watching /etc/ssl/certs/ca-certificates.crt
2021-09-02T23:55:40.59+0200 [APP/PROC/WEB/0] ERR Sep 02, 2021 9:55:40 PM org.cloudfoundry.security.FileWatchingX509ExtendedTrustManager <init>
2021-09-02T23:55:40.59+0200 [APP/PROC/WEB/0] ERR INFO: Initialized TrustManager for /etc/ssl/certs/ca-certificates.crt

Resolution

This behavior is expected since the DEBUG is enabled for Java Buildpack Provider (JBP). These log messages are coming from the Java buildpack's security provider and starts when container identity certificates are present in the application container. These errors are being printed to stderr by default by Java Util Logging and this is why they are also at INFO level. As a result, the debug messages are getting marked with the channel ERR because of the enabled JBP.

ERR and OUT in cf logs pertains to the stream that the message was written to and not the level it was logged at. Unless configured by a user, either by configuring Java Util Logging or adding a shim, Java Util Logging has this two-line to stderr logging format. The error is a false clue, as it is highlighted in the absence of any actual errors on start.

Many frameworks write to an application log that is separate from stdout and stderr. This is not supported by Loggregator. Your application must write to stdout or stderr for its logs to be included in the Loggregator stream. Check which buildpack your application uses to determine whether it automatically ensures that your application correctly writes logs to stdout and stderr only. Some buildpacks do this, and some do not. As a result, Java debugging is going to stderr.

Note: We do not advise to leave Java debug enabled for extended periods of time due to the strain it puts on the Loggregator. It should only be used for troubleshooting purpose.