Skip to content

Conversation

@sbrossie
Copy link
Member

@sbrossie sbrossie commented Jan 19, 2024

For instance, given a plugin 'myplugin', one can add an SIFT entry in the logback.xml to have the plugin split logs about jdbc. The exact name of the logfile would be of the form myplugin-sqltiming.<something>.out where 'something' is based on the first stacktrace entry matching the pattern.

    <appender name="SIFT-myplugin-sqltiming" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator class="org.killbill.billing.server.log.ThreadNameBasedDiscriminator"/>
        <sift>
            <appender name="myplugin-sqltiming-${threadName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <file>${LOGS_DIR:-./logs}/myplugin-sqltiming.${threadName}.out</file>
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                    <!-- rollover daily -->
                    <fileNamePattern>${LOGS_DIR:-./logs}/myplugin-sqltiming-%d{yyyy-MM-dd}.%i.${threadName}.out.gz</fileNamePattern>
                    <maxHistory>3</maxHistory>
                    <cleanHistoryOnStart>true</cleanHistoryOnStart>
                    <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                        <!-- or whenever the file size reaches 100MB -->
                        <maxFileSize>100MB</maxFileSize>
                    </timeBasedFileNamingAndTriggeringPolicy>
                </rollingPolicy>
                <encoder>
                    <pattern>%date{"yyyy-MM-dd'T'HH:mm:ss,SSSZ", UTC} lvl='%level', log='%logger{0}', th='%thread', xff='%X{req.xForwardedFor}', rId='%X{req.requestId}', tok='%X{kb.userToken}', aRId='%X{kb.accountRecordId}', tRId='%X{kb.tenantRecordId}', %maskedMsg%n</pattern>
                </encoder>
            </appender>
        </sift>
    </appender>

    <logger name="com.killbill.billing.myplugin.dao" level="INFO" additivity="false">
        <appender-ref ref="SIFT-myplugin-sqltiming"/>
    </logger>

Notes:

  1. Another option would be have this discriminator class served from the plugin - an option I tried - but it adds logback dependency into plugin code, and tomcat is struggling to find the class (and throws NPE).
  2. I introduced small methods to make it easy with the pattern matching and did not refactor existing code to leverage those to minimize risk - but I certainly could upon request.

… usable from killbill plugins

For instance, given a plugin 'myplugin', one can add an SIFT entry in the logback.xml to have the plugin split logs about jdbc.
The exact name of the logfile would be of the form  `myplugin-sqltiming.<something>.out` where 'something' is based on the first
stacktrace entry matching the pattern.

```
    <appender name="SIFT-myplugin-sqltiming" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator class="org.killbill.billing.server.log.ThreadNameBasedDiscriminator"/>
        <sift>
            <appender name="myplugin-sqltiming-${threadName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <file>${LOGS_DIR:-./logs}/myplugin-sqltiming.${threadName}.out</file>
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                    <!-- rollover daily -->
                    <fileNamePattern>${LOGS_DIR:-./logs}/myplugin-sqltiming-%d{yyyy-MM-dd}.%i.${threadName}.out.gz</fileNamePattern>
                    <maxHistory>3</maxHistory>
                    <cleanHistoryOnStart>true</cleanHistoryOnStart>
                    <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                        <!-- or whenever the file size reaches 100MB -->
                        <maxFileSize>100MB</maxFileSize>
                    </timeBasedFileNamingAndTriggeringPolicy>
                </rollingPolicy>
                <encoder>
                    <pattern>%date{"yyyy-MM-dd'T'HH:mm:ss,SSSZ", UTC} lvl='%level', log='%logger{0}', th='%thread', xff='%X{req.xForwardedFor}', rId='%X{req.requestId}', tok='%X{kb.userToken}', aRId='%X{kb.accountRecordId}', tRId='%X{kb.tenantRecordId}', %maskedMsg%n</pattern>
                </encoder>
            </appender>
        </sift>
    </appender>

    <logger name="com.killbill.billing.myplugin.dao" level="INFO" additivity="false">
        <appender-ref ref="SIFT-myplugin-sqltiming"/>
    </logger>
```
@sbrossie sbrossie force-pushed the log-enhancement-for-plugins branch from b81c561 to b6cc8ae Compare January 20, 2024 00:09
Copy link
Member

@pierre pierre left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Left some food for thoughts, but :shipit:!

}
return markerName;
} else { /* Support for plugins as well */
int next = lookupNextToken(classNameChars, 0, "com.killbill.billing.plugin.");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  • How about a system property, for a list of nextToken? Custom plugins might use another classname?
  • Not sure how Java stores String internally these days: what's the overhead of toCharArray (first thing that lookupNextToken does)? Should we do it once since the String is constant (this is called a lot, just trying to ensure we don't add too much overhead)?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How about a system property, for a list of nextToken? Custom plugins might use another classname?

There are 2 main difficulties:

  1. We would need a rather complex property (a map that says pluginA -> 'com.xxx', ...)
  2. While processing this log, the code does not really know which plugin it is coming from - all we do right now is create a stack trace to detect some pattern

Not sure how Java stores String internally these days: what's the overhead of toCharArray (first thing that lookupNextToken does)? Should we do it once since the String is constant (this is called a lot, just trying to ensure we don't add too much overhead)?

Based on this comment there was a desire speed up things using this scheme - versus doing string comparison. I assumed this was true, and kept the same idea, but I really don't know, whether this extra complexity and code makes sense.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, one thing I don't really like is that name of the file is relatively random as we pick the package name is a rather large stack trace that fits the patterns we have hardcoded. There is definitely some space for improvements...

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

/cc @pierre I am merging - but if you want to discuss any of this in more details, please let me know.

@sbrossie sbrossie merged commit cf829df into master Jan 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants