We use SLF4J in Candlepin. SLF4J is a logging facade that can bridge to multiple logging implementations (including Log4j, java.util.logging, and others). We are using Logback as our implementation.
When possible, only have your class rely on classes from SLF4J. Using facade gives us flexibility. Under most circumstances, this is all you will need to do.
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class Foo {
private static Logger log = LoggerFactory.getLogger(Foo.class);
public static void main(String[] args) {
log.info("Hello world")
}
}
Note that the log object is declared as static. There is some debate about this practice, but on Candlepin we stick to statics because our code isn’t meant to be deployed on a shared classpath.
Now let’s say you want to print out an object. That’s where SLF4J shines: parameterized messages. Here’s the old way:
//DO NOT DO THIS ANYMORE
Object x = new Something();
log.debug("Hello " + x);
The old way incurs the cost of the toString() operation as soon as the debug()
method is called even if logging is not set at debug level (whereupon the
message wouldn’t be logged at all). You can get around this with a
if(log.isDebugEnabled())
but that gets really ugly fast. With parameterized
messages the cost of the toString() operation is deferred until we know that we
are actually going to log the message. Here is the new way:
Object x = new Something();
log.debug("Hello {}", x);
What if you don’t want to log any message, but just the object itself? Easy: log.debug("{}", x)
If you are going to perform some expensive method call in the logging statement and you want to avoid the cost when possible, then you are going to have to use an if statement because the nested method call is going to get resolved before debug() is called.
Object x = new Something();
if (log.isDebugEnabled()) {
log.debug("Hello {}", x.doSomethingExpensive());
}
That’s about all you need to know about SLF4J but I recommend reading the FAQ
First, read the manual. Specifically the chapters on architecture (which is very similar to Log4J’s), configuration, filters, and Mapped Diagnostic Contexts. The rest you can just refer to when you need it.
If you want to do something fancy with logging, then you are going to need to access the underlying implementation. SLF4J doesn’t really allow you to configure loggers. To interact with Logback, you need to get the logging context first.
LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
With the context, you can access Loggers, attach new Appenders, etc.
start()
it. If the Logback class you’re using implements LifeCycle (and the Filters,
Appenders, Evaluators, TurboFilters, and Encoders all do), you need to set it
up and then call start()
otherwise it’s not going to do anything.
Loggers are the exception to this rule.debug="true"
attribute to the configuration
element in
logback.xml. See http://logback.qos.ch/manual/configuration.html#automaticStatusPrintingWe have a few customizations to logging.
Logger levels are set primarily in /etc/candlepin/candlepin.conf.
log4j.logger.org.candlepin.servlet.filter=DEBUG
The “log4j.logger” part is just a prefix; the rest is the Logger name and then the level you want. The LoggingConfig class handles setting the Loggers. This means that you should hardly ever actually need to touch logback.xml which is where the basic configuration is.
Superadmins can enable different logging levels for different orgs. To set to debug:
$ curl -k -u admin:admin -X PUT "https://localhost:8443/candlepin/owners/{owner_key}/log"
You can specify other levels with a level query param. For example
$ curl -k -u admin:admin -X PUT "https://localhost:8443/candlepin/owners/{owner_key}/log?level=TRACE"
To turn org level logging off
$ curl -k -u admin:admin -X DELETE "https://localhost:8443/candlepin/owners/{owner_key}/log"
@Verify
annotated parameters put the parameters in order of likelihood that
the user will pass them. That way we will have the org if a subsequent
parameter fails its @Verify
check. Most methods don’t have multiple
@Verify
annotations so this shouldn’t be a common occurrence.Hibernate has a great feature that will show the SQL statements which is some what useful for debugging. To turn this on simply add set ‘hibernate.show_sql = true’. This will show the SQL logging in Tomcat’s catalina log. To show these in the candlepin.log, you can set the following properties (in /etc/candlepin/candlepin.conf):
log4j.logger.org.hibernate=INFO
log4j.logger.org.hibernate.SQL=DEBUG # shows the queries
log4j.logger.org.hibernate.type.descriptor.sql=TRACE # shows query parameter values
2021-12-16 10:15:46,507 [thread=localhost-startStop-1] [=, org=, csid=] DEBUG org.hibernate.SQL - select asyncjobst0_.id as id1_18_, asyncjobst0_.created as created2_18_, asyncjobst0_.updated as updated3_18_, asyncjobst0_.attempts as attempts4_18_, asyncjobst0_.correlation_id as correlat5_18_, asyncjobst0_.end_time as end_time6_18_, asyncjobst0_.executor as executor7_18_, asyncjobst0_.job_group as job_grou8_18_, asyncjobst0_.job_key as job_key9_18_, asyncjobst0_.log_execution_details as log_exe10_18_, asyncjobst0_.log_level as log_lev11_18_, asyncjobst0_.max_attempts as max_att12_18_, asyncjobst0_.name as name13_18_, asyncjobst0_.origin as origin14_18_, asyncjobst0_.owner_id as owner_i15_18_, asyncjobst0_.previous_state as previou16_18_, asyncjobst0_.principal as princip17_18_, asyncjobst0_.job_result as job_res18_18_, asyncjobst0_.start_time as start_t19_18_, asyncjobst0_.state as state20_18_, asyncjobst0_.version as version21_18_ from cp_async_jobs asyncjobst0_ where (asyncjobst0_.state in (?)) and (asyncjobst0_.executor in (?))
2021-12-16 10:15:46,508 [thread=localhost-startStop-1] [=, org=, csid=] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [INTEGER] - [4]
2021-12-16 10:15:46,508 [thread=localhost-startStop-1] [=, org=, csid=] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - [candlepin.example.com]
Logging to syslog is possible but it requires customization of the logback.xml
file packaged with Candlepin.
Add a section like
<appender name="SyslogAppender" class="ch.qos.logback.classic.net.SyslogAppender">
<syslogHost>localhost</syslogHost>
<facility>DAEMON</facility>
<suffixPattern>[%thread] %logger %msg</suffixPattern>
</appender>
and add an appender-ref
element with ref="SyslogAppender"
under the root
element.
E.g.
<root level="WARN">
<appender-ref ref="CandlepinAppender" />
<appender-ref ref="SyslogAppender" />
<appender-ref ref="ErrorAppender" />
</root>
Allow syslog to listen on port 541. The exact steps here will depend on whether you are using rsyslog or syslog-ng. For rsyslog, you’ll want to add the lines below and restart the daemon.
# Provides UDP syslog reception
# for parameters see http://www.rsyslog.com/doc/imudp.html
module(load="imudp") # needs to be done just once
input(type="imudp" port="514")
Note that if you are using a SystemD based distribution, the messages sent to
port 514 are not going to appear in the journal. If you want the messages
to go to the journal as well, you’ll need to use something like rsyslog’s
omjournal
. Logback itself does
not have an appender implementation for the journal, although third-party
libraries exist.