Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

profiles: Extend the existing ThreadNameBasedDiscriminator to make it usable from killbill plugins #1953

Merged
merged 1 commit into from
Jan 22, 2024

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>
```
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:!

@@ -173,9 +200,22 @@ private String getKillbillCaller() {
markerName += kar;
}
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
21 checks passed
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.

None yet

2 participants