Unable to print the proper package and method name

[GangadharanS]

Hi ,

I am using ESAPI 2.2.0.0 with slf4j logger..

I am getting log like below..

INFO [2020-08-18 07:41:38,398] [XXXXX-XXXX] [http-nio-8080-exec-8] org.owasp.esapi.logging.slf4j.Slf4JLogLevelHandlers$3.log.65 - >>> Entering Method>>>

Instead of logging slf4j package name.. I should be getting my application packagename and class name.
Any immediate help would really be appreciable.

[jeremiahjstacey]

@GangadharanS can you provide more information on your configuration and implementation please?

It would be very helpful to know what your current ESAPI.properties configuration values are:

• Logger.ApplicationName
• Logger.LogEncodingRequired
• Logger.LogApplicationName
• Logger.LogServerIP
• Logger.UserInfo
• Logger.ClientInfo

These are used in the SLF4JLogFactory for determining what the prefix information will be.

Next, can you offer a code snippet for how you are instantiating the Logger instance in your code? The parameter supplied to the method is used as the base logger name.
IE:

org.owasp.esapi.Logger myLogger = ESAPI.getLogger("SomeModuleName");
myLogger.info(EventType.EVENT_UNSPECIFIED, "Some Message to log");

Last, are you backing SLF4J with Log4j2, Logback, or other? Can you provide the configuration you're setting for the log output for that tool as well?

Using this information I believe we should be able to replicate your results and hopefully provide more insight and assistance.

[GangadharanS]

Hi @jeremiahjstacey ,
Thanks for your response.
Please find below the details,

Logger.ApplicationName=ObjectRegistry
Logger.LogEncodingRequired=false
Logger.LogApplicationName=true
Logger.LogServerIP=true
Logger.UserInfo=true
Logger.ClientInfo=true

org.owasp.esapi.Logger logger = ESAPI.getLogger(AccountService.class);

logger.info(logger.EVENT_UNSPECIFIED, ">>> Entering Method >>>");

AND inlogback.xml
%5p [%d{ISO8601}] [%X{requestId}] [%t] %C.%M.%L - %m %n

[jeremiahjstacey]

@GangadharanS Thanks for the information! I will try to get something setup to emulate this configuration and get back with you as soon as I can.

[GangadharanS]

Thanks a lot @jeremiahjstacey. for your help.

[jeremiahjstacey]

What I have done:

1. Updated my src/test/resources/esapi/ESAPI.properties to use the SLF4J Logger
2. Updated my src/test/resources/esapi/ESAPI.properties to reflect the configurations you've offered above
3. Added the logback-classic maven dependency to my test scope

<dependency>
	<groupId>ch.qos.logback</groupId>
	<artifactId>logback-classic</artifactId>
	<version>1.2.3</version>
	<scope>test</scope>
</dependency>

4. added src/test/resources/logback.xml configuration

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%5p [%d{ISO8601}] [%X{requestId}] [%t] %C.%M.%L - %m %n</pattern>
    </encoder>
  </appender>
 
  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

5. Created a new test file src/test/java/org/owasp/esapi/logging/slf4j/SimpleLogbackTest.java

package org.owasp.esapi.logging.slf4j;

import org.junit.Test;
import org.owasp.esapi.ESAPI;
import org.owasp.esapi.Logger;

public class SimpleLogbackTest {
    @Test
    public void doTest() {
        Logger logger = ESAPI.getLogger(SimpleLogbackTest.class);       
        logger.warning(Logger.EVENT_UNSPECIFIED, "DATA");       
    }   
}

Running the test in this configuration appears to reflect your findings.
WARN [2020-08-18 18:09:07,534] [] [main] org.owasp.esapi.logging.slf4j.Slf4JLogLevelHandlers$2.log.49 - [EVENT UNSPECIFIED Anonymous:@unknown -> /ObjectRegistry/org.owasp.esapi.logging.slf4j.SimpleLogbackTest] DATA

I am not overly familar with the logback syntax, and so I did some general "getting started" searches for some alternative output patterns. I found one that offers a different result:
%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n

Updating my logback.xml file to the following content:

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <!-- 
         ORIGINAL
         %5p [%d{ISO8601}] [%X{requestId}] [%t] %C.%M.%L - %m %n 
      -->
      <pattern>%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>
 
  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

I get output more aligned with what I think you're wanting. Please note the absence of the slf4j class references below.

18:11:51.639 [main] WARN o.o.e.l.slf4j.SimpleLogbackTest - [EVENT UNSPECIFIED Anonymous:@unknown -> /ObjectRegistry/org.owasp.esapi.logging.slf4j.SimpleLogbackTest] DATA

Unfortunately, I do not believe there is anything that the ESAPI baseline can offer to address the concern, as I currently understand it.

I believe that the output you're seeing is a result of the pattern being applied in your logback.xml configuration. If it were a result of the ESAPI baseline I would have expected the problematic SLF4J file references to persist.

Please let me know if I've misunderstood the request intention and I can take another look.

[GangadharanS]

thanks @jeremiahjstacey. am just getting this
WARN [2020-08-18 18:09:07,534] [] [main] org.owasp.esapi.logging.slf4j.Slf4JLogLevelHandlers$2.log.49 - DATA

Not the one u mentioned. ("[EVENT UNSPECIFIED Anonymous:@unknown -> /ObjectRegistry/org.owasp.esapi.logging.slf4j.SimpleLogbackTest]" - this is missing in my log)
Please let me know, if am missing any thing here.

Also i need the method and line number to be printed.
when i try the pattern - %5p [%d{ISO8601}] [%t] %logger.%method.%line - %m %n

it prints - WARN [2020-08-19 06:08:44,625] [http-nio-8080-exec-12] com.trimble.oculus.core.services.account.AccountService.log.49 - >>> Entering Method >>>

where as methodname and line number are wrong.

[jeremiahjstacey]

Initial investigation suggests that logback is using the first reference from the call stack to determine the line information to write to the log. Based on what I'm seeing, I think that clients will need to customize the pattern layouts used to inspect farther back in the stack to see the base class information rather than the ESAPI support classes.

This can be illustrated by applying my configuration from my comment above, and updating the pattern to use the caller attribute as identified in the Layouts Section of Logback's documentation.

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} %caller{5} - %msg%n</pattern>
    </encoder>
  </appender>
 
  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

Running the listed test with this configuration shows:

03:22:26.924 [main] WARN  o.o.e.l.slf4j.SimpleLogbackTest Caller+0	 at org.owasp.esapi.logging.slf4j.Slf4JLogLevelHandlers$2.log(Slf4JLogLevelHandlers.java:49)
Caller+1	 at org.owasp.esapi.logging.slf4j.Slf4JLogBridgeImpl.log(Slf4JLogBridgeImpl.java:65)
Caller+2	 at org.owasp.esapi.logging.slf4j.Slf4JLogger.log(Slf4JLogger.java:43)
Caller+3	 at org.owasp.esapi.logging.slf4j.Slf4JLogger.warning(Slf4JLogger.java:101)
Caller+4	 at org.owasp.esapi.logging.slf4j.SimpleLogbackTest.doTest(SimpleLogbackTest.java:13)
 - [EVENT UNSPECIFIED Anonymous:@unknown -> /ObjectRegistry/org.owasp.esapi.logging.slf4j.SimpleLogbackTest] DATA

It seems like the information is available, but may require more customized parsing/formatting options to extract the data. The last four calls of the stack should be consistent with uses of SLF4J and Logback.

@kwwall @xeno6696 - Do either of you have more experience with the configuration for logback, or suggestions on how to move forward? This configuration should be consistent for uses of ESAPI and logback, but I don't think it belongs in the ESAPI baseline. The code is acting as intended, but appears to have a side effect with an assumption in the Logback implementation - which appears to be the logger is called directly from the source code with no intermediaries.

@GangadharanS I'll keep looking, but the short answer I see is to write your own LayoutBase implementation and rip the information you care about. I will try to look closer at the logback content this week and see if I can find any more elegant solutions.

[GangadharanS]

thanks @jeremiahjstacey but "[EVENT UNSPECIFIED Anonymous:@unknown -> /ObjectRegistry/org.owasp.esapi.logging.slf4j.SimpleLogbackTest]" -

ESAPI.Logger.EVENT TYPE and application name info is also missing in my log.
Please let me know if any configuration to be done for this.

[jeremiahjstacey]

The message you posted starts with

EVENT UNSPECIFIED which is the Event type's toString representation.

(see line 133 of the Logger.java class below)
https://github.com/ESAPI/esapi-java-legacy/blob/develop/src/main/java/org/owasp/esapi/Logger.java

It also contains your application name in the server information segment

/ObjectRegistry/org.owasp.esapi.logging.slf4j.SimpleLogbackTest

This output is working as intended, unless I'm misunderstanding.

[GangadharanS]

Yes, @jeremiahjstacey. Seems working fine for you.
but I could not get that event type in log.

can u please share your ESPAI.properties what you have tried to reproduce this.

[jeremiahjstacey]

This is the base file I'm using.
https://github.com/ESAPI/esapi-java-legacy/blob/develop/src/test/resources/esapi/ESAPI.properties

I have set the LogFactory to the slf4J configuration
(around line 129)

#ESAPI.Logger=org.owasp.esapi.logging.java.JavaLogFactory
# To use the new SLF4J logger in ESAPI (see GitHub issue #129), set
ESAPI.Logger=org.owasp.esapi.logging.slf4j.Slf4JLogFactory

I have matched the configuration you provided in your comment above
(around line 412)

#===========================================================================
# ESAPI Logging
# Set the application name if these logs are combined with other applications
Logger.ApplicationName=ObjectRegistry
# If you use an HTML log viewer that does not properly HTML escape log data, you can set LogEncodingRequired to true
Logger.LogEncodingRequired=false
# Determines whether ESAPI should log the application name. This might be clutter in some single-server/single-app environments.
Logger.LogApplicationName=true
# Determines whether ESAPI should log the server IP and port. This might be clutter in some single-server environments.
Logger.LogServerIP=true
# Determines whether ESAPI should log the user info.
Logger.UserInfo=true
# Determines whether ESAPI should log the session id and client IP.
Logger.ClientInfo=true

The rest of the configuration is still using the content I outlined in my previous comment

[GangadharanS]

@jeremiahjstacey Am doing the same but in my log EVENT TYPE and application name info are missing..

WARN [2020-08-19 15:02:21,477] [http-nio-8080-exec-14] Caller+4 at com.trimble.oculus.core.services.account.AccountService.createAccounts(AccountService.java:190) - >>> Entering Method >>>

Not sure, what i am missing in configuration.

[kwwall]

@jeremiahjstacey wrote:

@kwwall @xeno6696 - Do either of you have more experience with the configuration for logback, or suggestions on how to move forward? This configuration should be consistent for uses of ESAPI and logback, but I don't think it belongs in the ESAPI baseline. The code is acting as intended, but appears to have a side effect with an assumption in the Logback implementation - which appears to be the logger is called directly from the source code with no intermediaries.

I have reviewed logback configurations to look for potential security issues, but not for anything like this. What I suggest once we figure out a way this ought to look for logback, is that we create a new GitHub wiki page on this repository to document it. But beyond that, I agree, I don't think we should be in the business of making various logging configuration files part of the ESAPI (configuration) distribution.

[kwwall]

@jeremiahjstacey - Are you also using the ESAPI 2.2.0.0 release or some other later version? We should rule that out as well in case there were minor fixes to 2.2.1.0 or 2.2.1.1 that is causing this. Also, are you and @GangadharanS both using the same version of logback? That might matter as well.

Also, @GangadharanS, are yiou using the ESAPI Logger directly, or do you have it "wrapped" in some additional layers? If it is as @jeremiahjstacey says with logback that is looking at the callstack, the logback.xml file may need further tweaks if you are wrapping the calls to the ESAPI logger in additional layers.

[GangadharanS]

@kwwall yes am using the logback version 1.2.3 what @jeremiahjstacey tried. and I am using ESAPI logger directly. I can do tweaks in logback to get the pattern. But my question is EVENTTYPE itself not printed in log. I understand this doesnot have anything to do with logback.xml

[jeremiahjstacey]

@kwwall, I have been adding unit tests to the latest develop branch updates locally. I'm probably closer to the 2.2.1.1 content.

@GangadharanS would it be possible to for you update to the latest ESAPI release and see if that changes the output?
https://mvnrepository.com/artifact/org.owasp.esapi/esapi/2.2.1.1

[jeremiahjstacey]

I'm going to be a little pressed the next few days. I intend to set up another local project with my listed configurations and run that unit test with the last three ESAPI releases rather than through my current clone of the baseline. I'm hoping to be able to get that information nlt Sunday.

[jeremiahjstacey]

@GangadharanS, I was able to go through some preliminary testing. It appears that I have similar results when using v2.2.0.0. The issue regarding Event Type appears to be resolved as of 2.2.1.0 +

If you are using v2.2.0.0, please try to update and see if it changes what you're seeing. The results of my testing are listed below.

I am still using my test pattern in logback.xml
<pattern>%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n</pattern>

• 2.2.1.1
  02:56:44.271 [main] WARN esapi.logs.SimpleLogbackTest - [EVENT UNSPECIFIED Anonymous:@unknown -> /ObjectRegistry/esapi.logs.SimpleLogbackTest] DATA
• 2.2.1.0
  02:56:11.795 [main] WARN esapi.logs.SimpleLogbackTest - [EVENT UNSPECIFIED Anonymous:@unknown -> /ObjectRegistry/esapi.logs.SimpleLogbackTest] DATA
• 2.2.0.0
  02:55:22.917 [main] WARN esapi.logs.SimpleLogbackTest - DATA

[GangadharanS]

Thanks a lot @kwwall @jeremiahjstacey . let me try upgrading it.

[GangadharanS]

@jeremiahjstacey I am getting EVENTTYPE in log after upgrading ESAPI to 2.2.1.1.
If you do get the line number and method along with class name and EVENT TYPE, that would be great to have.

[jeremiahjstacey]

Without digging too deep, the %caller logback conversion can be limited to a single entry.
Given that the ESAPI class structure will be consistent, I was able to limit the caller to showing only the source line using the following pattern:
<pattern>%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} %caller{4..5} - %msg%n</pattern>

05:56:24.246 [main] WARN  esapi.logs.SimpleLogbackTest Caller+4	 at esapi.logs.SimpleLogbackTest.doTest(SimpleLogbackTest.java:13)
 - [EVENT UNSPECIFIED Anonymous:@unknown -> /ObjectRegistry/esapi.logs.SimpleLogbackTest] DATA

I know that's not quite as nice as the default logback configuration, but it should consistently provide both the method and line number of your source code.

[jeremiahjstacey]

Reading through the Logback Layout documentation, I found the instructions for a Custom Conversion Specifier

This lets you control specific formatting options.
Using this as a base, I was able to get something more aligned with what I think you're wanting.

First, you will need to create a Conversion class implementation. The API is all included in logback-classic dependency.

package esapi.logs;

import ch.qos.logback.classic.pattern.ClassicConverter;
import ch.qos.logback.classic.spi.ILoggingEvent;

public class ESAPILogbackSourceConverter extends ClassicConverter {
  @Override
  public String convert(ILoggingEvent event) {
    StackTraceElement origCall = event.getCallerData()[4];
    return String.format("%s.%s (%s)", origCall.getClassName(), origCall.getMethodName(), origCall.getLineNumber()); 
  }
}

Then you need to define your converter in your logback.xml

<conversionRule conversionWord="esapiSRC" 
                  converterClass="esapi.logs.ESAPILogbackSourceConverter" />

Here is my full logback.xml file. Note that I've updated the pattern to only use my converter in this example.

<configuration>
<conversionRule conversionWord="esapiSRC" 
                  converterClass="esapi.logs.ESAPILogbackSourceConverter" />

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <!-- 
       <pattern>%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%nOrigin Call: %caller{4..5}</pattern>
      -->
      <pattern>%-6esapiSRC</pattern>
    </encoder>
  </appender>
 
  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

Now when I run my same test I receive the following output:

esapi.logs.SimpleLogbackTest.doTest (13)

You should be able to use this premise to adjust the Method and line number information however you would desire.

[jeremiahjstacey]

• Upgrading from 2.2.0.0 to 2.2.1.1 resolves issue with missing log message information.
• Logback support for package, method, and line numbers are resolved with a combination of updated logback output patterns an customized Logback converters.

I believe all concerns of this issue have been discussed and mitigated.