[DIRMINA-833] LoggingFilter does not log SENT bytes when used with a ProtocolCodecFilter

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.0.0
• Fix Version/s: 2.0.8
• Component/s: Filter
• Assignee: Unassigned
• Reporter: Esko Luontola
• Created: 10/May/11 21:55
• Updated: 09/Sep/14 05:35
• Resolved: 09/Sep/14 05:35

Description

Here is a code to reproduce the issue:

import org.apache.mina.core.buffer.IoBuffer;
import org.apache.mina.core.service.IoHandlerAdapter;
import org.apache.mina.core.session.IoSession;
import org.apache.mina.filter.codec.*;
import org.apache.mina.filter.logging.LoggingFilter;
import org.apache.mina.transport.socket.nio.*;
import org.junit.Test;

public class LoggingTest {

    @Test
    public void using_LoggingFilter_and_ProtocolCodecFilter() throws Exception {
        NioSocketAcceptor acceptor = new NioSocketAcceptor();
        acceptor.getFilterChain().addLast("logger", new LoggingFilter());
        acceptor.getFilterChain().addLast("codec", new ProtocolCodecFilter(new MyProtocolEncoder(), new MyProtocolDecoder()));
        acceptor.setHandler(new IoHandlerAdapter() {
            public void messageReceived(IoSession session, Object message) throws Exception {
                session.write(message);
            }
        });
        acceptor.bind();

        NioSocketConnector connector = new NioSocketConnector();
        connector.setHandler(new IoHandlerAdapter());
        IoSession session = connector.connect(acceptor.getLocalAddress()).await().getSession();

        session.write(IoBuffer.allocate(2).
                putChar('x').
                flip());

        Thread.sleep(1000);
        acceptor.unbind();
    }

    private static class MyProtocolEncoder extends ProtocolEncoderAdapter {
        public void encode(IoSession session, Object message, ProtocolEncoderOutput out) throws Exception {
            String s = (String) message;
            out.write(IoBuffer.allocate(2).
                    putChar(s.charAt(0)).
                    flip());
        }
    }

    private static class MyProtocolDecoder extends ProtocolDecoderAdapter {
        public void decode(IoSession session, IoBuffer in, ProtocolDecoderOutput out) throws Exception {
            char c = in.getChar();
            out.write("" + c);
        }
    }
}

When using mina-core 2.0.0-RC1 the above code will print properly:

11.5.2011 0:52:36 org.apache.mina.filter.logging.LoggingFilter log
INFO: CREATED
11.5.2011 0:52:36 org.apache.mina.filter.logging.LoggingFilter log
INFO: OPENED
11.5.2011 0:52:36 org.apache.mina.filter.logging.LoggingFilter log
INFO: RECEIVED: HeapBuffer[pos=0 lim=2 cap=2048: 00 78]
11.5.2011 0:52:36 org.apache.mina.filter.logging.LoggingFilter log
INFO: SENT: HeapBuffer[pos=0 lim=2 cap=2: 00 78]
11.5.2011 0:52:36 org.apache.mina.filter.logging.LoggingFilter log
INFO: SENT: HeapBuffer[pos=0 lim=0 cap=0: empty]
11.5.2011 0:52:37 org.apache.mina.filter.logging.LoggingFilter log
INFO: CLOSED

But when using mina-core 2.0.0 or higher (at least up to 2.0.3), it will not log the "INFO: SENT: HeapBuffer[pos=0 lim=2 cap=2: 00 78]" line:

11.5.2011 0:53:10 org.apache.mina.filter.logging.LoggingFilter log
INFO: CREATED
11.5.2011 0:53:10 org.apache.mina.filter.logging.LoggingFilter log
INFO: OPENED
11.5.2011 0:53:10 org.apache.mina.filter.logging.LoggingFilter log
INFO: RECEIVED: HeapBuffer[pos=0 lim=2 cap=2048: 00 78]
11.5.2011 0:53:10 org.apache.mina.filter.logging.LoggingFilter log
INFO: SENT: HeapBuffer[pos=0 lim=0 cap=0: empty]
11.5.2011 0:53:11 org.apache.mina.filter.logging.LoggingFilter log
INFO: CLOSED