Skip to main content

log4j TCP SyslogAppender

The current SyslogAppender in log4j uses UDP to transmit the logs to syslog server. It potentially has risks of losing data and our ops guy was looking for a TCP based appender and ran into this http://www.rsyslog.com/tcp-syslog-rfc5424-log4j-appender/ and plugged it in. Then something weird happen as an appnode would keep running out of file handles and other app node ran into issue where all threads were stuck. The implementation at this link is buggy so I rewrote this and publishing here in case anyone is interested.

/**
 * TCP appender to syslog. This class uses a blocking queue with 10K message capacity and any requests beyond that would be rejected.
 * The append method from all caller threads inserts the message into blocking queue and there is a single background thread that logs to the syslog.
 * This complex queueing is introduced to relieve the user thread as soon as possible.
 *
 *
 */
public class Syslog4jTCPAppender extends Syslog4jAppender {
    private static final long serialVersionUID = 1L;

    private static ThreadLocal dateFormat = new ThreadLocal() {

        @Override
        protected SimpleDateFormat initialValue() {
            SimpleDateFormat df = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss.S'Z'");
            df.setTimeZone(TimeZone.getTimeZone("UTC"));
            return df;
        }

    };

    private Map facilitiesMap = new HashMap();

    private String localHost;

    private BlockingQueue blockingQueue = new ArrayBlockingQueue(10000);

    @Override
    public void activateOptions() {
        super.activateOptions();
        String[] facilities = { "KERN", "USER", "MAIL", "DAEMON", "AUTH", "SYSLOG", "LPR", "NEWS", "UUCP", "CRON", "AUTHPRIV",
                "FTP", "LOCAL0", "LOCAL1", "LOCAL2", "LOCAL3", "LOCAL4", "LOCAL5", "LOCAL6", "LOCAL7" };
        int[] facIntArray = { 0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 16, 17, 18, 19, 20, 21, 22, 23 };
        for (int i = 0; i < facilities.length; i++) {
            facilitiesMap.put(facilities[i], facIntArray[i]);
        }
        try {
            localHost = InetAddress.getLocalHost().getHostName();
        } catch (UnknownHostException e) {
            System.out.println("UnknownHostException" + e.getMessage());
            localHost = "Unknown";
        }
        SocketLoggerThread socketLoggerThread = new SocketLoggerThread();
        socketLoggerThread.setDaemon(true);
        socketLoggerThread.start();
    }

    @Override
    protected void append(LoggingEvent event) {
        int priority = calcPriority(event);
        String trace = super.layout.format(event);
        String newLineChar = "\n";
        String msg = trace.replaceAll(newLineChar, " ");
        Date dt = new Date();
        String dateString = dateFormat.get().format(dt);
        String message = "<" + priority + ">" + dateString + " " + localHost + " " + super.getIdent() + ": " + msg + "\n";
        blockingQueue.offer(message);
    }

    private int calcPriority(LoggingEvent event) {
        String facility = super.getFacility().toUpperCase();
        Integer facPriority = facilitiesMap.get(facility);
        if (facPriority == null) {
            facPriority = 1;
        }
        int level = event.getLevel().getSyslogEquivalent();
        int priority = facPriority * 8 + level;
        return priority;
    }

    private class SocketLoggerThread extends Thread {
        private Socket socket;

        private DataOutputStream os;
        private int counter;

        @Override
        public void run() {
            reinit();
            while (true) {
                try {
                    consume(blockingQueue.take());
                } catch (InterruptedException e) {
                    System.out.println("Syslog socket logger interrupted while waiting" + e.getMessage());
                } catch (Exception e) {
                    System.out.println("Unknown exception " + e.getMessage());
                }
            }
        }

        private void close() {
            try {
                if (os != null) {
                    os.close();
                }
            } catch (IOException e) {
                System.out.println("IOException closing os" + e.getMessage());
            }
            try {
                if (socket != null) {
                    socket.close();
                }
            } catch (IOException e) {
                System.out.println("IOException closing socket " + e.getMessage());
            }
        }

        private void reinit() {
            close();
            try {
                socket = new Socket(Syslog4jTCPAppender.super.getSyslogHost(), Integer.parseInt(Syslog4jTCPAppender.super.getPort()));
                os = new DataOutputStream(socket.getOutputStream());
            } catch (IOException e) {
                System.out.println("IOException opening socket" + e.getMessage());
            }
        }

        private void consume(String message) {
            try {
                counter++;
                os.writeUTF(message);
                if (counter % 5000 == 0) {
                    System.out.println("Reiniting syslog socket");
                    reinit();
                    counter = 0;
                }
            } catch (IOException e) {
                System.out.println("IOException writing message" + e.getMessage());
                reinit();
            }
        }
    }
}

Comments

  1. Thanks for the rewrite! Would you mind if we include this on the rsyslog side (and/or the tarball?)

    ReplyDelete
  2. Rainer please go ahead. I will github it soon when I get time but for now please go ahead and include it on the rsyslog side.

    fyi the code is live on 100+ nodes and so far I am not seeing any issues.

    ReplyDelete
  3. Kalpesh, did this code get onto github?

    ReplyDelete

Post a Comment

Popular posts from this blog

RabbitMQ java clients for beginners

Here is a sample of a consumer and producer example for RabbitMQ. The steps are
Download ErlangDownload Rabbit MQ ServerDownload Rabbit MQ Java client jarsCompile and run the below two class and you are done.
This sample create a Durable Exchange, Queue and a Message. You will have to start the consumer first before you start the for the first time.

For more information on AMQP, Exchanges, Queues, read this excellent tutorial
http://blogs.digitar.com/jjww/2009/01/rabbits-and-warrens/

+++++++++++++++++RabbitMQProducer.java+++++++++++++++++++++++++++
import com.rabbitmq.client.Connection; import com.rabbitmq.client.Channel; import com.rabbitmq.client.*; public class RabbitMQProducer { public static void main(String []args) throws Exception { ConnectionFactory factory = new ConnectionFactory(); factory.setUsername("guest"); factory.setPassword("guest"); factory.setVirtualHost("/"); factory.setHost("127.0.0.1"); factory.setPort(5672); Conne…

What a rocky start to labor day weekend

Woke up by earthquake at 7:00 AM in morning and then couldn't get to sleep. I took a bath, made my tea and started checking emails and saw that after last night deployment three storage node out of 100s of nodes were running into Full GC. What was special about the 3 nodes was that each one was in a different Data centre but it was named same app02.  This got me curious I asked the node to be taken out of rotation and take a heap dump.  Yesterday night a new release has happened and I had upgraded spymemcached library version as new relic now natively supports instrumentation on it so it was a suspect. And the hunch was a bullseye, the heap dump clearly showed it taking 1.3G and full GCs were taking 6 sec but not claiming anything.



I have a quartz job in each jvm that takes a thread dump every 5 minutes and saves last 300 of them, checking few of them quickly showed a common thread among all 3 data centres. It seems there was a long running job that was trying to replicate pending…

Spring query timeout or transaction timeout

If you are using spring to manage transactions then you can specify default transaction timeout using

    <bean id="transactionManager"
        class="org.springframework.jdbc.datasource.DataSourceTransactionManager">
        <property name="dataSource" ref="dataSource" />
        <property name="defaultTimeout" value="30" /> <!--30 sec--->             
    </bean>

or you can override the timeout in the annotation

    @Transactional(readOnly = false, timeout=30)


or if you are doing it programatic transactions then you can do


DataSourceTransactionManager transactionManager = new DataSourceTransactionManager(dataSource);
transactionManager.setDefaultTimeout(30);

 or you can override the timeout for one particular transaction

TransactionTemplate transactionTemplate = new TransactionTemplate();
transactionTemplate.setTimeout(30);