logback Notes — Rolling by Time and Size, and Collecting Flume Logs

Two logback notes posted on the same day, merged. One is about how to split application logs; the other is about collecting those logs in one place.

Rolling by time and size together

This splits the file when the date changes or the size passes 100MB. Most setups pick one; both can be applied together.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
<appender name="debug" class="ch.qos.logback.core.rolling.RollingFileAppender">   
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>DEBUG</level>
    </filter>
    <prudent>false</prudent>
    <file>/logs/debug.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>/logs/old/debug.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
        <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
          <maxFileSize>100mb</maxFileSize>
        </timeBasedFileNamingAndTriggeringPolicy>
        <maxHistory>30</maxHistory> 
    </rollingPolicy>
    <encoder>
        <pattern>[%-5level] %d{HH:mm:ss.SSS} %logger{36} - %msg%n</pattern>
    </encoder>
</appender>

<maxFileSize /> is the split size (kb and gb work too)
<maxHistory /> deletes logs older than 30 days, oldest first

SizeAndTimeBasedFNATP is the key part. Nesting it inside TimeBasedRollingPolicy is what makes date and size apply together. That is also why the filename pattern needs %i — within one day the file can roll several more times on size, so it needs an index.

Leaving out <maxHistory /> fills the disk. That is the most common server incident there is.

Switching Flume’s default logger from log4j to logback

Installing

Download logback from http://logback.qos.ch/download.html (v1.1.3 at the time)
Unpack and copy logback-classic-1.1.3.jar and logback-core-1.1.3.jar into $FLUME_HOME/lib
Rename the existing ./lib/slf4j-log4j12-1.6.1.jar to ./lib/slf4j-log4j12-1.6.1.jar.back. Removing log4j is optional — leaving it in means both will write
Put your logback.xml at $FLUME_HOME/conf/logback.xml

logback.xml

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
<?xml version="1.0" encoding="UTF-8"?>
<configuration>

	<!-- Appenders -->
	<appender name="console" class="ch.qos.logback.core.ConsoleAppender">    
      	<encoder>
        	<pattern>[%-5level] %d{HH:mm:ss.SSS} [%thread] %logger{36} - %msg%n</pattern>
       	</encoder>
    </appender>
    <appender name="daily" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <prudent>false</prudent>
        <file>./logs/flume1.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>./logs/old/flume1.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>100mb</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>[%-5level] %d{HH:mm:ss.SSS} %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="event" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <prudent>false</prudent>
        <file>./logs/collect.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>./logs/old/collect.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>100mb</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
    </appender>

	<logger name="kimpaper" level="debug">
        <appender-ref ref="event" />
	</logger>

    <!-- 3rdparty Loggers -->
	<logger name="org.apache.flume.lifecycle" level="info">
	</logger>
	<logger name="org.jboss" level="warn">
	</logger>
	<logger name="org.mortbay" level="info">
	</logger>
	<logger name="org.apache.avro.ipc.NettyTransceiver" level="warn">
	</logger>
	
	<logger name="org.apache.hadoop" level="info">
	</logger>
	<logger name="org.apache.hadoop.hive" level="error">
	</logger>
	
	
	<!-- Root Logger -->
	<root level="info">
		<appender-ref ref="console" />
		<appender-ref ref="daily" />
	</root>
	
</configuration>

Two appenders is the point. daily holds Flume’s own logs, event holds the collected events. Only the kimpaper logger writes to event, which keeps the collected data from mixing with Flume’s operational logging.

Writing a custom collection sink

The plan was to use file_roll as the sink that gathers logs on the master server, but it has drawbacks:

You cannot set the filename
Log files just keep accumulating

Those turned out to matter more than expected, so I wrote a small sink project. https://github.com/kimpaper/flume-slj4j-sink

See that repository for installation. Applying it looks like this:

1
2
3
4
5
...
agent1.sinks.k1.type = kimpaper.flume.sink.Slj4jSink
agent1.sinks.k1.logLevel = info
agent1.sinks.k1.channel = c1
...

Routing the sink through slf4j means it picks up the rolling policy from the logback.xml above. The filename is determined and maxHistory handles deletion — both drawbacks go away at once.

From there, logs arriving from each server accumulate merged into collect.log.

Summary

To apply date and size together, nest SizeAndTimeBasedFNATP inside TimeBasedRollingPolicy
%i in the filename pattern is required — it can roll several times in one day
Always set maxHistory, or the disk fills
Switching Flume’s default logger to logback lets collected logs share the same rolling policy
Routing through an slf4j sink fixes file_roll’s filename and retention problems