1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20 package org.apache.mina.filter.logging;
21
22 import java.io.IOException;
23 import java.net.InetSocketAddress;
24 import java.net.SocketAddress;
25 import java.util.ArrayList;
26 import java.util.Collections;
27 import java.util.List;
28 import java.util.concurrent.CountDownLatch;
29
30 import org.apache.log4j.AppenderSkeleton;
31 import org.apache.log4j.Level;
32 import org.apache.log4j.spi.LoggingEvent;
33 import org.apache.mina.core.buffer.IoBuffer;
34 import org.apache.mina.core.filterchain.DefaultIoFilterChainBuilder;
35 import org.apache.mina.core.filterchain.IoFilterAdapter;
36 import org.apache.mina.core.future.ConnectFuture;
37 import org.apache.mina.core.service.IoHandlerAdapter;
38 import org.apache.mina.core.session.IdleStatus;
39 import org.apache.mina.core.session.IoSession;
40 import org.apache.mina.filter.codec.ProtocolCodecFactory;
41 import org.apache.mina.filter.codec.ProtocolCodecFilter;
42 import org.apache.mina.filter.codec.ProtocolDecoder;
43 import org.apache.mina.filter.codec.ProtocolDecoderAdapter;
44 import org.apache.mina.filter.codec.ProtocolDecoderOutput;
45 import org.apache.mina.filter.codec.ProtocolEncoder;
46 import org.apache.mina.filter.codec.ProtocolEncoderAdapter;
47 import org.apache.mina.filter.codec.ProtocolEncoderOutput;
48 import org.apache.mina.filter.executor.ExecutorFilter;
49 import org.apache.mina.filter.statistic.ProfilerTimerFilter;
50 import org.apache.mina.transport.socket.nio.NioSocketAcceptor;
51 import org.apache.mina.transport.socket.nio.NioSocketConnector;
52 import org.junit.After;
53 import org.junit.Before;
54 import org.junit.Test;
55 import static org.junit.Assert.assertNotNull;
56 import static org.junit.Assert.assertNull;
57 import static org.junit.Assert.assertEquals;
58 import static org.junit.Assert.fail;
59 import org.slf4j.Logger;
60 import org.slf4j.LoggerFactory;
61
62
63
64
65
66
67
68 public class MdcInjectionFilterTest {
69
70 private static Logger logger = LoggerFactory.getLogger(MdcInjectionFilterTest.class);
71 private static final int TIMEOUT = 5000;
72
73 private final MyAppender appender = new MyAppender();
74 private int port;
75 private NioSocketAcceptor acceptor;
76
77 @Before
78 public void setUp() throws Exception {
79
80 org.apache.log4j.Logger.getRootLogger().removeAllAppenders();
81 org.apache.log4j.Logger.getRootLogger().setLevel(Level.DEBUG);
82 org.apache.log4j.Logger.getRootLogger().addAppender(appender);
83 acceptor = new NioSocketAcceptor();
84 }
85
86
87 @After
88 public void tearDown() throws Exception {
89 acceptor.dispose();
90 }
91
92 @Test
93 public void testSimpleChain() throws IOException, InterruptedException {
94 DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
95 chain.addFirst("mdc-injector", new MdcInjectionFilter());
96 chain.addLast("dummy", new DummyIoFilter());
97 chain.addLast("protocol", new ProtocolCodecFilter(new DummyProtocolCodecFactory()));
98 test(chain);
99 }
100
101 @Test
102 public void testExecutorFilterAtTheEnd() throws IOException, InterruptedException {
103 DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
104 MdcInjectionFilter mdcInjectionFilter = new MdcInjectionFilter();
105 chain.addFirst("mdc-injector1", mdcInjectionFilter);
106 chain.addLast("dummy", new DummyIoFilter());
107 chain.addLast("protocol", new ProtocolCodecFilter(new DummyProtocolCodecFactory()));
108 chain.addLast("executor" , new ExecutorFilter());
109 chain.addLast("mdc-injector2", mdcInjectionFilter);
110 test(chain);
111 }
112
113 @Test
114 public void testExecutorFilterAtBeginning() throws IOException, InterruptedException {
115 DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
116 MdcInjectionFilter mdcInjectionFilter = new MdcInjectionFilter();
117 chain.addLast("executor" , new ExecutorFilter());
118 chain.addLast("mdc-injector", mdcInjectionFilter);
119 chain.addLast("dummy", new DummyIoFilter());
120 chain.addLast("protocol", new ProtocolCodecFilter(new DummyProtocolCodecFactory()));
121 test(chain);
122 }
123
124 @Test
125 public void testExecutorFilterBeforeProtocol() throws IOException, InterruptedException {
126 DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
127 MdcInjectionFilter mdcInjectionFilter = new MdcInjectionFilter();
128 chain.addLast("executor" , new ExecutorFilter());
129 chain.addLast("mdc-injector", mdcInjectionFilter);
130 chain.addLast("dummy", new DummyIoFilter());
131 chain.addLast("protocol", new ProtocolCodecFilter(new DummyProtocolCodecFactory()));
132 test(chain);
133 }
134
135 @Test
136 public void testMultipleFilters() throws IOException, InterruptedException {
137 DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
138 MdcInjectionFilter mdcInjectionFilter = new MdcInjectionFilter();
139 chain.addLast("executor" , new ExecutorFilter());
140 chain.addLast("mdc-injector", mdcInjectionFilter);
141 chain.addLast("profiler", new ProfilerTimerFilter());
142 chain.addLast("dummy", new DummyIoFilter());
143 chain.addLast("logger", new LoggingFilter());
144 chain.addLast("protocol", new ProtocolCodecFilter(new DummyProtocolCodecFactory()));
145 test(chain);
146 }
147
148
149 @Test
150 public void testTwoExecutorFilters() throws IOException, InterruptedException {
151 DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
152 MdcInjectionFilter mdcInjectionFilter = new MdcInjectionFilter();
153 chain.addLast("executor1" , new ExecutorFilter());
154 chain.addLast("mdc-injector1", mdcInjectionFilter);
155 chain.addLast("protocol", new ProtocolCodecFilter(new DummyProtocolCodecFactory()));
156 chain.addLast("dummy", new DummyIoFilter());
157 chain.addLast("executor2" , new ExecutorFilter());
158
159
160 chain.addLast("mdc-injector2", mdcInjectionFilter);
161 test(chain);
162 }
163
164 @Test
165 public void testOnlyRemoteAddress() throws IOException, InterruptedException {
166 DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
167 chain.addFirst("mdc-injector", new MdcInjectionFilter(
168 MdcInjectionFilter.MdcKey.remoteAddress));
169 chain.addLast("dummy", new DummyIoFilter());
170 chain.addLast("protocol", new ProtocolCodecFilter(new DummyProtocolCodecFactory()));
171 SimpleIoHandler simpleIoHandler = new SimpleIoHandler();
172 acceptor.setHandler(simpleIoHandler);
173 acceptor.bind(new InetSocketAddress(0));
174 port = acceptor.getLocalAddress().getPort();
175 acceptor.setFilterChainBuilder(chain);
176
177 NioSocketConnector connector = new NioSocketConnector();
178 connector.setHandler(new IoHandlerAdapter());
179 connectAndWrite(connector,0);
180 connectAndWrite(connector,1);
181
182 simpleIoHandler.messageSentLatch.await();
183 simpleIoHandler.sessionIdleLatch.await();
184 simpleIoHandler.sessionClosedLatch.await();
185 connector.dispose();
186
187
188 List<LoggingEvent> events = new ArrayList<LoggingEvent>(appender.events);
189
190 for (LoggingEvent event : events) {
191 for (MdcInjectionFilter.MdcKey mdcKey : MdcInjectionFilter.MdcKey.values()) {
192 String key = mdcKey.name();
193 Object value = event.getMDC(key);
194 if (mdcKey == MdcInjectionFilter.MdcKey.remoteAddress) {
195 assertNotNull(
196 "MDC[remoteAddress] not set for [" + event.getMessage() + "]", value);
197 } else {
198 assertNull("MDC[" + key + "] set for [" + event.getMessage() + "]", value);
199 }
200 }
201 }
202 }
203
204 private void test(DefaultIoFilterChainBuilder chain) throws IOException, InterruptedException {
205
206 SimpleIoHandler simpleIoHandler = new SimpleIoHandler();
207 acceptor.setHandler(simpleIoHandler);
208 acceptor.bind(new InetSocketAddress(0));
209 port = acceptor.getLocalAddress().getPort();
210 acceptor.setFilterChainBuilder(chain);
211
212 NioSocketConnector connector = new NioSocketConnector();
213 connector.setHandler(new IoHandlerAdapter());
214 SocketAddress remoteAddressClients[] = new SocketAddress[2];
215 remoteAddressClients[0] = connectAndWrite(connector,0);
216 remoteAddressClients[1] = connectAndWrite(connector,1);
217
218 simpleIoHandler.messageSentLatch.await();
219 simpleIoHandler.sessionIdleLatch.await();
220 simpleIoHandler.sessionClosedLatch.await();
221 connector.dispose();
222
223
224 List<LoggingEvent> events = new ArrayList<LoggingEvent>(appender.events);
225
226
227 for (LoggingEvent event : events) {
228 if (!ExecutorFilter.class.getName().equals(event.getLoggerName())) {
229 Object remoteAddress = event.getMDC("remoteAddress");
230 assertNotNull(
231 "MDC[remoteAddress] not set for [" + event.getMessage() + "]",
232 remoteAddress);
233 assertNotNull(
234 "MDC[remotePort] not set for [" + event.getMessage() + "]",
235 event.getMDC("remotePort"));
236 assertEquals(
237 "every event should have MDC[handlerClass]",
238 SimpleIoHandler.class.getName(),
239 event.getMDC("handlerClass") );
240 }
241 }
242
243 for (int i = 0; i < remoteAddressClients.length; i++) {
244 SocketAddress remoteAddressClient = remoteAddressClients[i];
245 assertEventExists(events, "sessionCreated", remoteAddressClient, null);
246 assertEventExists(events, "sessionOpened", remoteAddressClient, null);
247 assertEventExists(events, "decode", remoteAddressClient, null);
248 assertEventExists(events, "messageReceived-1", remoteAddressClient, null);
249 assertEventExists(events, "messageReceived-2", remoteAddressClient, "user-" + i);
250 assertEventExists(events, "encode", remoteAddressClient, null);
251 assertEventExists(events, "exceptionCaught", remoteAddressClient, "user-" + i);
252 assertEventExists(events, "messageSent-1", remoteAddressClient, "user-" + i);
253 assertEventExists(events, "messageSent-2", remoteAddressClient, null);
254 assertEventExists(events, "sessionIdle", remoteAddressClient, "user-" + i);
255 assertEventExists(events, "sessionClosed", remoteAddressClient, "user-" + i);
256 assertEventExists(events, "sessionClosed", remoteAddressClient, "user-" + i);
257 assertEventExists(events, "DummyIoFilter.sessionOpened", remoteAddressClient, "user-" + i);
258 }
259 }
260
261 private SocketAddress connectAndWrite(NioSocketConnector connector, int clientNr) {
262 ConnectFuture connectFuture = connector.connect(new InetSocketAddress("localhost", port));
263 connectFuture.awaitUninterruptibly(TIMEOUT);
264 IoBuffer message = IoBuffer.allocate(4).putInt(clientNr).flip();
265 IoSession session = connectFuture.getSession();
266 session.write(message).awaitUninterruptibly(TIMEOUT);
267 return session.getLocalAddress();
268 }
269
270 private void assertEventExists(List<LoggingEvent> events,
271 String message,
272 SocketAddress address,
273 String user) {
274 InetSocketAddress remoteAddress = (InetSocketAddress) address;
275 for (LoggingEvent event : events) {
276 if (event.getMessage().equals(message) &&
277 event.getMDC("remoteAddress").equals(remoteAddress.toString()) &&
278 event.getMDC("remoteIp").equals(remoteAddress.getAddress().getHostAddress()) &&
279 event.getMDC("remotePort").equals(remoteAddress.getPort()+"") ) {
280 if (user == null && event.getMDC("user") == null) {
281 return;
282 }
283 if (user != null && user.equals(event.getMDC("user"))) {
284 return;
285 }
286 return;
287 }
288 }
289 fail("No LoggingEvent found from [" + remoteAddress +"] with message [" + message + "]");
290 }
291
292 private static class SimpleIoHandler extends IoHandlerAdapter {
293
294 CountDownLatch sessionIdleLatch = new CountDownLatch(2);
295 CountDownLatch sessionClosedLatch = new CountDownLatch(2);
296 CountDownLatch messageSentLatch = new CountDownLatch(2);
297
298 @Override
299 public void sessionCreated(IoSession session) throws Exception {
300 logger.info("sessionCreated");
301 session.getConfig().setIdleTime(IdleStatus.BOTH_IDLE, 1);
302 }
303
304 @Override
305 public void sessionOpened(IoSession session) throws Exception {
306 logger.info("sessionOpened");
307 }
308
309 @Override
310 public void sessionClosed(IoSession session) throws Exception {
311 logger.info("sessionClosed");
312 sessionClosedLatch.countDown();
313 }
314
315 @Override
316 public void sessionIdle(IoSession session, IdleStatus status) throws Exception {
317 logger.info("sessionIdle");
318 sessionIdleLatch.countDown();
319 session.close(true);
320 }
321
322 @Override
323 public void exceptionCaught(IoSession session, Throwable cause) throws Exception {
324 logger.info("exceptionCaught", cause);
325 }
326
327 @Override
328 public void messageReceived(IoSession session, Object message) throws Exception {
329 logger.info("messageReceived-1");
330
331 String user = "user-" + message;
332 MdcInjectionFilter.setProperty(session, "user", user);
333 logger.info("messageReceived-2");
334 session.getService().broadcast(message);
335 throw new RuntimeException("just a test, forcing exceptionCaught");
336 }
337
338 @Override
339 public void messageSent(IoSession session, Object message) throws Exception {
340 logger.info("messageSent-1");
341 MdcInjectionFilter.removeProperty(session, "user");
342 logger.info("messageSent-2");
343 messageSentLatch.countDown();
344 }
345 }
346
347 private static class DummyProtocolCodecFactory implements ProtocolCodecFactory {
348
349 public ProtocolEncoder getEncoder(IoSession session) throws Exception {
350 return new ProtocolEncoderAdapter() {
351 public void encode(IoSession session, Object message, ProtocolEncoderOutput out) throws Exception {
352 logger.info("encode");
353 IoBuffer buffer = IoBuffer.allocate(4).putInt(123).flip();
354 out.write(buffer);
355 }
356 };
357 }
358
359 public ProtocolDecoder getDecoder(IoSession session) throws Exception {
360 return new ProtocolDecoderAdapter() {
361 public void decode(IoSession session, IoBuffer in, ProtocolDecoderOutput out) throws Exception {
362 if (in.remaining() >= 4) {
363 int value = in.getInt();
364 logger.info("decode");
365 out.write(value);
366 }
367 }
368 };
369 }
370 }
371
372 private static class MyAppender extends AppenderSkeleton {
373
374 List<LoggingEvent> events = Collections.synchronizedList(new ArrayList<LoggingEvent>());
375
376 @Override
377 protected void append(final LoggingEvent loggingEvent) {
378 loggingEvent.getMDCCopy();
379 events.add(loggingEvent);
380 }
381
382 @Override
383 public boolean requiresLayout() {
384 return false;
385 }
386
387 @Override
388 public void close() {
389 }
390 }
391
392 private static class DummyIoFilter extends IoFilterAdapter {
393 @Override
394 public void sessionOpened(NextFilter nextFilter, IoSession session) throws Exception {
395 logger.info("DummyIoFilter.sessionOpened");
396 nextFilter.sessionOpened(session);
397 }
398 }
399
400 }