001: /*
002: * Licensed to the Apache Software Foundation (ASF) under one
003: * or more contributor license agreements. See the NOTICE file
004: * distributed with this work for additional information
005: * regarding copyright ownership. The ASF licenses this file
006: * to you under the Apache License, Version 2.0 (the
007: * "License"); you may not use this file except in compliance
008: * with the License. You may obtain a copy of the License at
009: *
010: * http://www.apache.org/licenses/LICENSE-2.0
011: *
012: * Unless required by applicable law or agreed to in writing,
013: * software distributed under the License is distributed on an
014: * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
015: * KIND, either express or implied. See the License for the
016: * specific language governing permissions and limitations
017: * under the License.
018: *
019: */
020: package org.apache.mina.filter.logging;
021:
022: import java.io.IOException;
023: import java.net.InetSocketAddress;
024: import java.net.SocketAddress;
025: import java.util.ArrayList;
026: import java.util.Collections;
027: import java.util.List;
028: import java.util.concurrent.CountDownLatch;
029:
030: import junit.framework.TestCase;
031:
032: import org.apache.log4j.AppenderSkeleton;
033: import org.apache.log4j.Level;
034: import org.apache.log4j.spi.LoggingEvent;
035: import org.apache.mina.common.ConnectFuture;
036: import org.apache.mina.common.DefaultIoFilterChainBuilder;
037: import org.apache.mina.common.IdleStatus;
038: import org.apache.mina.common.IoBuffer;
039: import org.apache.mina.common.IoFilterAdapter;
040: import org.apache.mina.common.IoHandlerAdapter;
041: import org.apache.mina.common.IoSession;
042: import org.apache.mina.filter.codec.ProtocolCodecFactory;
043: import org.apache.mina.filter.codec.ProtocolCodecFilter;
044: import org.apache.mina.filter.codec.ProtocolDecoder;
045: import org.apache.mina.filter.codec.ProtocolDecoderAdapter;
046: import org.apache.mina.filter.codec.ProtocolDecoderOutput;
047: import org.apache.mina.filter.codec.ProtocolEncoder;
048: import org.apache.mina.filter.codec.ProtocolEncoderAdapter;
049: import org.apache.mina.filter.codec.ProtocolEncoderOutput;
050: import org.apache.mina.filter.executor.ExecutorFilter;
051: import org.apache.mina.filter.statistic.ProfilerTimerFilter;
052: import org.apache.mina.transport.socket.nio.NioSocketAcceptor;
053: import org.apache.mina.transport.socket.nio.NioSocketConnector;
054: import org.slf4j.Logger;
055: import org.slf4j.LoggerFactory;
056:
057: /**
058: * Tests {@link MdcInjectionFilter} in variuos scenarios.
059: *
060: * @author The Apache MINA Project (dev@mina.apache.org)
061: * @version $Rev: 600461 $, $Date: 2007-12-03 02:55:52 -0700 (Mon, 03 Dec 2007) $
062: */
063: public class MdcInjectionFilterTest extends TestCase {
064:
065: private static Logger logger = LoggerFactory
066: .getLogger(MdcInjectionFilterTest.class);
067: private static final int PORT = 7475;
068: private static final int TIMEOUT = 5000;
069:
070: private MyAppender appender = new MyAppender();
071: private NioSocketAcceptor acceptor;
072:
073: @Override
074: protected void setUp() throws Exception {
075: super .setUp();
076: // comment out next line if you want to see normal logging
077: org.apache.log4j.Logger.getRootLogger().removeAllAppenders();
078: org.apache.log4j.Logger.getRootLogger().setLevel(Level.DEBUG);
079: org.apache.log4j.Logger.getRootLogger().addAppender(appender);
080: acceptor = new NioSocketAcceptor();
081: }
082:
083: @Override
084: protected void tearDown() throws Exception {
085: acceptor.dispose();
086: super .tearDown();
087: }
088:
089: public void testSimpleChain() throws IOException,
090: InterruptedException {
091: DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
092: chain.addFirst("mdc-injector", new MdcInjectionFilter());
093: chain.addLast("dummy", new DummyIoFilter());
094: chain.addLast("protocol", new ProtocolCodecFilter(
095: new DummyProtocolCodecFactory()));
096: test(chain);
097: }
098:
099: public void testExecutorFilterAtTheEnd() throws IOException,
100: InterruptedException {
101: DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
102: MdcInjectionFilter mdcInjectionFilter = new MdcInjectionFilter();
103: chain.addFirst("mdc-injector1", mdcInjectionFilter);
104: chain.addLast("dummy", new DummyIoFilter());
105: chain.addLast("protocol", new ProtocolCodecFilter(
106: new DummyProtocolCodecFactory()));
107: chain.addLast("executor", new ExecutorFilter());
108: chain.addLast("mdc-injector2", mdcInjectionFilter);
109: test(chain);
110: }
111:
112: public void testExecutorFilterAtBeginning() throws IOException,
113: InterruptedException {
114: DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
115: MdcInjectionFilter mdcInjectionFilter = new MdcInjectionFilter();
116: chain.addLast("executor", new ExecutorFilter());
117: chain.addLast("mdc-injector", mdcInjectionFilter);
118: chain.addLast("dummy", new DummyIoFilter());
119: chain.addLast("protocol", new ProtocolCodecFilter(
120: new DummyProtocolCodecFactory()));
121: test(chain);
122: }
123:
124: public void testExecutorFilterBeforeProtocol() throws IOException,
125: 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(
132: new DummyProtocolCodecFactory()));
133: test(chain);
134: }
135:
136: public void testMultipleFilters() throws IOException,
137: InterruptedException {
138: DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
139: MdcInjectionFilter mdcInjectionFilter = new MdcInjectionFilter();
140: chain.addLast("executor", new ExecutorFilter());
141: chain.addLast("mdc-injector", mdcInjectionFilter);
142: chain.addLast("profiler", new ProfilerTimerFilter());
143: chain.addLast("dummy", new DummyIoFilter());
144: chain.addLast("logger", new LoggingFilter());
145: chain.addLast("protocol", new ProtocolCodecFilter(
146: new DummyProtocolCodecFactory()));
147: test(chain);
148: }
149:
150: public void testTwoExecutorFilters() throws IOException,
151: InterruptedException {
152: DefaultIoFilterChainBuilder chain = new DefaultIoFilterChainBuilder();
153: MdcInjectionFilter mdcInjectionFilter = new MdcInjectionFilter();
154: chain.addLast("executor1", new ExecutorFilter());
155: chain.addLast("mdc-injector1", mdcInjectionFilter);
156: chain.addLast("protocol", new ProtocolCodecFilter(
157: new DummyProtocolCodecFactory()));
158: chain.addLast("dummy", new DummyIoFilter());
159: chain.addLast("executor2", new ExecutorFilter());
160: chain.addLast("mdc-injector2", mdcInjectionFilter);
161: test(chain);
162: }
163:
164: public void testOnlyRemoteAddress() throws IOException,
165: 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(
171: new DummyProtocolCodecFactory()));
172: SimpleIoHandler simpleIoHandler = new SimpleIoHandler();
173: acceptor.setHandler(simpleIoHandler);
174: acceptor.bind(new InetSocketAddress(PORT));
175: acceptor.setFilterChainBuilder(chain);
176: // create some clients
177: NioSocketConnector connector = new NioSocketConnector();
178: connector.setHandler(new IoHandlerAdapter());
179: SocketAddress remoteAddressClients[] = new SocketAddress[2];
180: remoteAddressClients[0] = connectAndWrite(connector, 0);
181: remoteAddressClients[1] = connectAndWrite(connector, 1);
182: // wait until Iohandler has received all events
183: simpleIoHandler.messageSentLatch.await();
184: simpleIoHandler.sessionIdleLatch.await();
185: simpleIoHandler.sessionClosedLatch.await();
186: // make a copy to prevent ConcurrentModificationException
187: List<LoggingEvent> events = new ArrayList<LoggingEvent>(
188: appender.events);
189: // verify that all logging events have correct MDC
190: for (LoggingEvent event : events) {
191: for (MdcInjectionFilter.MdcKey mdcKey : MdcInjectionFilter.MdcKey
192: .values()) {
193: String key = mdcKey.name();
194: Object value = event.getMDC(key);
195: if (mdcKey == MdcInjectionFilter.MdcKey.remoteAddress) {
196: assertNotNull("MDC[remoteAddress] not set for ["
197: + event.getMessage() + "]", value);
198: } else {
199: assertNull("MDC[" + key + "] set for ["
200: + event.getMessage() + "]", value);
201: }
202: }
203: }
204: }
205:
206: private void test(DefaultIoFilterChainBuilder chain)
207: throws IOException, InterruptedException {
208: // configure the server
209: SimpleIoHandler simpleIoHandler = new SimpleIoHandler();
210: acceptor.setHandler(simpleIoHandler);
211: acceptor.bind(new InetSocketAddress(PORT));
212: acceptor.setFilterChainBuilder(chain);
213: // create some clients
214: NioSocketConnector connector = new NioSocketConnector();
215: connector.setHandler(new IoHandlerAdapter());
216: SocketAddress remoteAddressClients[] = new SocketAddress[2];
217: remoteAddressClients[0] = connectAndWrite(connector, 0);
218: remoteAddressClients[1] = connectAndWrite(connector, 1);
219: // wait until Iohandler has received all events
220: simpleIoHandler.messageSentLatch.await();
221: simpleIoHandler.sessionIdleLatch.await();
222: simpleIoHandler.sessionClosedLatch.await();
223:
224: // make a copy to prevent ConcurrentModificationException
225: List<LoggingEvent> events = new ArrayList<LoggingEvent>(
226: appender.events);
227:
228: // verify that all logging events have correct MDC
229: for (LoggingEvent event : events) {
230: if (!ExecutorFilter.class.getName().equals(
231: event.getLoggerName())) {
232: Object remoteAddress = event.getMDC("remoteAddress");
233: assertNotNull("MDC[remoteAddress] not set for ["
234: + event.getMessage() + "]", remoteAddress);
235: assertNotNull("MDC[remotePort] not set for ["
236: + event.getMessage() + "]", event
237: .getMDC("remotePort"));
238: assertEquals(
239: "every event should have MDC[handlerClass]",
240: SimpleIoHandler.class.getName(), event
241: .getMDC("handlerClass"));
242: }
243: }
244: // asert we have received all expected logging events for each client
245: for (int i = 0; i < remoteAddressClients.length; i++) {
246: SocketAddress remoteAddressClient = remoteAddressClients[i];
247: assertEventExists(events, "sessionCreated",
248: remoteAddressClient, null);
249: assertEventExists(events, "sessionOpened",
250: remoteAddressClient, null);
251: assertEventExists(events, "decode", remoteAddressClient,
252: null);
253: assertEventExists(events, "messageReceived-1",
254: remoteAddressClient, null);
255: assertEventExists(events, "messageReceived-2",
256: remoteAddressClient, "user-" + i);
257: assertEventExists(events, "encode", remoteAddressClient,
258: null);
259: assertEventExists(events, "exceptionCaught",
260: remoteAddressClient, "user-" + i);
261: assertEventExists(events, "messageSent-1",
262: remoteAddressClient, "user-" + i);
263: assertEventExists(events, "messageSent-2",
264: remoteAddressClient, null);
265: assertEventExists(events, "sessionIdle",
266: remoteAddressClient, "user-" + i);
267: assertEventExists(events, "sessionClosed",
268: remoteAddressClient, "user-" + i);
269: assertEventExists(events, "sessionClosed",
270: remoteAddressClient, "user-" + i);
271: assertEventExists(events, "DummyIoFilter.sessionOpened",
272: remoteAddressClient, "user-" + i);
273: }
274: }
275:
276: private SocketAddress connectAndWrite(NioSocketConnector connector,
277: int clientNr) {
278: ConnectFuture connectFuture = connector
279: .connect(new InetSocketAddress("localhost", PORT));
280: connectFuture.awaitUninterruptibly(TIMEOUT);
281: IoBuffer message = IoBuffer.allocate(4).putInt(clientNr).flip();
282: IoSession session = connectFuture.getSession();
283: session.write(message).awaitUninterruptibly(TIMEOUT);
284: return session.getLocalAddress();
285: }
286:
287: private void assertEventExists(List<LoggingEvent> events,
288: String message, SocketAddress address, String user) {
289: InetSocketAddress remoteAddress = (InetSocketAddress) address;
290: for (LoggingEvent event : events) {
291: if (event.getMessage().equals(message)
292: && event.getMDC("remoteAddress").equals(
293: remoteAddress.toString())
294: && event.getMDC("remoteIp")
295: .equals(
296: remoteAddress.getAddress()
297: .getHostAddress())
298: && event.getMDC("remotePort").equals(
299: remoteAddress.getPort() + "")) {
300: if (user == null && event.getMDC("user") == null) {
301: return;
302: }
303: if (user != null && user.equals(event.getMDC("user"))) {
304: return;
305: }
306: return;
307: }
308: }
309: fail("No LoggingEvent found from [" + remoteAddress
310: + "] with message [" + message + "]");
311: }
312:
313: private static class SimpleIoHandler extends IoHandlerAdapter {
314:
315: CountDownLatch sessionIdleLatch = new CountDownLatch(2);
316: CountDownLatch sessionClosedLatch = new CountDownLatch(2);
317: CountDownLatch messageSentLatch = new CountDownLatch(2);
318:
319: @Override
320: public void sessionCreated(IoSession session) throws Exception {
321: logger.info("sessionCreated");
322: session.getConfig().setIdleTime(IdleStatus.BOTH_IDLE, 1);
323: }
324:
325: @Override
326: public void sessionOpened(IoSession session) throws Exception {
327: logger.info("sessionOpened");
328: }
329:
330: @Override
331: public void sessionClosed(IoSession session) throws Exception {
332: logger.info("sessionClosed");
333: sessionClosedLatch.countDown();
334: }
335:
336: @Override
337: public void sessionIdle(IoSession session, IdleStatus status)
338: throws Exception {
339: logger.info("sessionIdle");
340: sessionIdleLatch.countDown();
341: session.close();
342: }
343:
344: @Override
345: public void exceptionCaught(IoSession session, Throwable cause)
346: throws Exception {
347: logger.info("exceptionCaught", cause);
348: }
349:
350: @Override
351: public void messageReceived(IoSession session, Object message)
352: throws Exception {
353: logger.info("messageReceived-1");
354: // adding a custom property to the context
355: String user = "user-" + message;
356: MdcInjectionFilter.setProperty(session, "user", user);
357: logger.info("messageReceived-2");
358: session.write(message);
359: throw new RuntimeException(
360: "just a test, forcing exceptionCaught");
361: }
362:
363: @Override
364: public void messageSent(IoSession session, Object message)
365: throws Exception {
366: logger.info("messageSent-1");
367: MdcInjectionFilter.removeProperty(session, "user");
368: logger.info("messageSent-2");
369: messageSentLatch.countDown();
370: }
371: }
372:
373: private static class DummyProtocolCodecFactory implements
374: ProtocolCodecFactory {
375:
376: public ProtocolEncoder getEncoder(IoSession session)
377: throws Exception {
378: return new ProtocolEncoderAdapter() {
379: public void encode(IoSession session, Object message,
380: ProtocolEncoderOutput out) throws Exception {
381: logger.info("encode");
382: IoBuffer buffer = IoBuffer.allocate(4).putInt(123)
383: .flip();
384: out.write(buffer);
385: }
386: };
387: }
388:
389: public ProtocolDecoder getDecoder(IoSession session)
390: throws Exception {
391: return new ProtocolDecoderAdapter() {
392: public void decode(IoSession session, IoBuffer in,
393: ProtocolDecoderOutput out) throws Exception {
394: if (in.remaining() >= 4) {
395: int value = in.getInt();
396: logger.info("decode");
397: out.write(value);
398: }
399: }
400: };
401: }
402: }
403:
404: private static class MyAppender extends AppenderSkeleton {
405:
406: List<LoggingEvent> events = Collections
407: .synchronizedList(new ArrayList<LoggingEvent>());
408:
409: @Override
410: protected void append(final LoggingEvent loggingEvent) {
411: loggingEvent.getMDCCopy();
412: events.add(loggingEvent);
413: }
414:
415: @Override
416: public boolean requiresLayout() {
417: return false;
418: }
419:
420: @Override
421: public void close() {
422: }
423: }
424:
425: private static class DummyIoFilter extends IoFilterAdapter {
426: @Override
427: public void sessionOpened(NextFilter nextFilter,
428: IoSession session) throws Exception {
429: logger.info("DummyIoFilter.sessionOpened");
430: nextFilter.sessionOpened(session);
431: }
432: }
433:
434: }
|