From commits-return-2912-apmail-knox-commits-archive=knox.apache.org@knox.apache.org Wed Mar 21 17:12:34 2018 Return-Path: X-Original-To: apmail-knox-commits-archive@minotaur.apache.org Delivered-To: apmail-knox-commits-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 6066D18909 for ; Wed, 21 Mar 2018 17:12:34 +0000 (UTC) Received: (qmail 23979 invoked by uid 500); 21 Mar 2018 17:12:34 -0000 Delivered-To: apmail-knox-commits-archive@knox.apache.org Received: (qmail 23946 invoked by uid 500); 21 Mar 2018 17:12:34 -0000 Mailing-List: contact commits-help@knox.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@knox.apache.org Delivered-To: mailing list commits@knox.apache.org Received: (qmail 23937 invoked by uid 99); 21 Mar 2018 17:12:34 -0000 Received: from git1-us-west.apache.org (HELO git1-us-west.apache.org) (140.211.11.23) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 21 Mar 2018 17:12:34 +0000 Received: by git1-us-west.apache.org (ASF Mail Server at git1-us-west.apache.org, from userid 33) id 22A5BF4E15; Wed, 21 Mar 2018 17:12:34 +0000 (UTC) Content-Type: text/plain; charset="us-ascii" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit From: more@apache.org To: commits@knox.apache.org Message-Id: X-Mailer: ASF-Git Admin Mailer Subject: knox git commit: KNOX-1091 - Knox Audit Logging - duplicate correlation ids (Kevin Risden via Sandeep More) Date: Wed, 21 Mar 2018 17:12:34 +0000 (UTC) Repository: knox Updated Branches: refs/heads/master ee55e06fc -> 02f1b8b5a KNOX-1091 - Knox Audit Logging - duplicate correlation ids (Kevin Risden via Sandeep More) Project: http://git-wip-us.apache.org/repos/asf/knox/repo Commit: http://git-wip-us.apache.org/repos/asf/knox/commit/02f1b8b5 Tree: http://git-wip-us.apache.org/repos/asf/knox/tree/02f1b8b5 Diff: http://git-wip-us.apache.org/repos/asf/knox/diff/02f1b8b5 Branch: refs/heads/master Commit: 02f1b8b5ad4ccf9936bb650c7228e401acee09cd Parents: ee55e06 Author: Sandeep More Authored: Wed Mar 21 13:12:24 2018 -0400 Committer: Sandeep More Committed: Wed Mar 21 13:12:24 2018 -0400 ---------------------------------------------------------------------- .../org/apache/knox/gateway/GatewayFilter.java | 21 +- .../knox/gateway/filter/CorrelationHandler.java | 7 +- .../apache/knox/gateway/AuditLoggingTest.java | 63 ++++-- .../apache/knox/test/log/CollectAppender.java | 5 +- .../knox/gateway/GatewayCorrelationIdTest.java | 205 +++++++++++++++++++ .../src/test/resources/log4j.properties | 3 + 6 files changed, 274 insertions(+), 30 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/knox/blob/02f1b8b5/gateway-server/src/main/java/org/apache/knox/gateway/GatewayFilter.java ---------------------------------------------------------------------- diff --git a/gateway-server/src/main/java/org/apache/knox/gateway/GatewayFilter.java b/gateway-server/src/main/java/org/apache/knox/gateway/GatewayFilter.java index 25d4f75..b88691e 100644 --- a/gateway-server/src/main/java/org/apache/knox/gateway/GatewayFilter.java +++ b/gateway-server/src/main/java/org/apache/knox/gateway/GatewayFilter.java @@ -169,19 +169,7 @@ public class GatewayFilter implements Filter { servletRequest.setAttribute( AbstractGatewayFilter.TARGET_SERVICE_ROLE, chain.getResourceRole() ); try { chain.doFilter( servletRequest, servletResponse ); - } catch( IOException e ) { - LOG.failedToExecuteFilter( e ); - auditor.audit( Action.ACCESS, contextWithPathAndQuery, ResourceType.URI, ActionOutcome.FAILURE ); - throw e; - } catch( ServletException e ) { - LOG.failedToExecuteFilter( e ); - auditor.audit( Action.ACCESS, contextWithPathAndQuery, ResourceType.URI, ActionOutcome.FAILURE ); - throw e; - } catch( RuntimeException e ) { - LOG.failedToExecuteFilter( e ); - auditor.audit( Action.ACCESS, contextWithPathAndQuery, ResourceType.URI, ActionOutcome.FAILURE ); - throw e; - } catch( ThreadDeath e ) { + } catch( IOException | RuntimeException | ThreadDeath | ServletException e ) { LOG.failedToExecuteFilter( e ); auditor.audit( Action.ACCESS, contextWithPathAndQuery, ResourceType.URI, ActionOutcome.FAILURE ); throw e; @@ -189,11 +177,18 @@ public class GatewayFilter implements Filter { LOG.failedToExecuteFilter( e ); auditor.audit( Action.ACCESS, contextWithPathAndQuery, ResourceType.URI, ActionOutcome.FAILURE ); throw new ServletException( e ); + } finally { + // Make sure to destroy the correlationContext to prevent threading issues + CorrelationServiceFactory.getCorrelationService().detachContext(); } } else { LOG.failedToMatchPath( requestPath ); httpResponse.setStatus( HttpServletResponse.SC_NOT_FOUND ); + + // Make sure to destroy the correlationContext to prevent threading issues + CorrelationServiceFactory.getCorrelationService().detachContext(); } + //KAM[ Don't do this or the Jetty default servlet will overwrite any response setup by the filter. // filterChain.doFilter( servletRequest, servletResponse ); //] http://git-wip-us.apache.org/repos/asf/knox/blob/02f1b8b5/gateway-server/src/main/java/org/apache/knox/gateway/filter/CorrelationHandler.java ---------------------------------------------------------------------- diff --git a/gateway-server/src/main/java/org/apache/knox/gateway/filter/CorrelationHandler.java b/gateway-server/src/main/java/org/apache/knox/gateway/filter/CorrelationHandler.java index 90933c3..c6aadc9 100644 --- a/gateway-server/src/main/java/org/apache/knox/gateway/filter/CorrelationHandler.java +++ b/gateway-server/src/main/java/org/apache/knox/gateway/filter/CorrelationHandler.java @@ -18,6 +18,7 @@ package org.apache.knox.gateway.filter; import org.apache.knox.gateway.audit.api.CorrelationContext; +import org.apache.knox.gateway.audit.api.CorrelationService; import org.apache.knox.gateway.audit.api.CorrelationServiceFactory; import org.eclipse.jetty.server.Request; import org.eclipse.jetty.server.handler.HandlerWrapper; @@ -33,13 +34,15 @@ public class CorrelationHandler extends HandlerWrapper { @Override public void handle( String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response ) throws IOException, ServletException { - CorrelationContext correlationContext = CorrelationServiceFactory.getCorrelationService().createContext(); + CorrelationService correlationService = CorrelationServiceFactory.getCorrelationService(); + CorrelationContext correlationContext = correlationService.createContext(); correlationContext.setRequestId( UUID.randomUUID().toString() ); try { super.handle( target, baseRequest, request, response ); } finally { + // Ensure that the correlationContext is destroyed between requests correlationContext.destroy(); + correlationService.detachContext(); } } - } http://git-wip-us.apache.org/repos/asf/knox/blob/02f1b8b5/gateway-server/src/test/java/org/apache/knox/gateway/AuditLoggingTest.java ---------------------------------------------------------------------- diff --git a/gateway-server/src/test/java/org/apache/knox/gateway/AuditLoggingTest.java b/gateway-server/src/test/java/org/apache/knox/gateway/AuditLoggingTest.java index 03ee0d7..22bc308 100644 --- a/gateway-server/src/test/java/org/apache/knox/gateway/AuditLoggingTest.java +++ b/gateway-server/src/test/java/org/apache/knox/gateway/AuditLoggingTest.java @@ -26,9 +26,11 @@ import static org.junit.Assert.fail; import java.io.IOException; import java.net.URI; import java.net.URISyntaxException; -import java.util.ArrayList; -import java.util.Collections; -import java.util.Iterator; +import java.util.*; +import java.util.concurrent.Callable; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; import javax.servlet.Filter; import javax.servlet.FilterChain; @@ -58,8 +60,12 @@ import org.easymock.EasyMock; import org.junit.After; import org.junit.Before; import org.junit.Test; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; public class AuditLoggingTest { + private static Logger LOG = LoggerFactory.getLogger( AuditLoggingTest.class ); + private static final String METHOD = "GET"; private static final String PATH = "path"; private static final String CONTEXT_PATH = "contextPath/"; @@ -86,7 +92,7 @@ public class AuditLoggingTest { * action=access request_type=uri outcome=unavailable * action=access request_type=uri outcome=success message=Response status: 404 */ - public void testNoFiltersAudit() throws ServletException, IOException { + public void testNoFiltersAudit() throws Exception { FilterConfig config = EasyMock.createNiceMock( FilterConfig.class ); EasyMock.replay( config ); @@ -113,15 +119,48 @@ public class AuditLoggingTest { FilterChain chain = EasyMock.createNiceMock( FilterChain.class ); EasyMock.replay( chain ); - GatewayFilter gateway = new GatewayFilter(); - gateway.init( config ); - gateway.doFilter( request, response, chain ); - gateway.destroy(); + Random rnd = new Random(); + + // Make number of total requests between 1-100 + int numberTotalRequests = rnd.nextInt(99) + 1; + Set> callables = new HashSet<>(numberTotalRequests); + for (int i = 0; i < numberTotalRequests; i++) { + callables.add(() -> { + GatewayFilter gateway = new GatewayFilter(); + gateway.init( config ); + gateway.doFilter( request, response, chain ); + gateway.destroy(); + return null; + }); + } - assertThat( CollectAppender.queue.size(), is( 1 ) ); - Iterator iterator = CollectAppender.queue.iterator(); - LoggingEvent accessEvent = iterator.next(); - verifyAuditEvent( accessEvent, CONTEXT_PATH + PATH, ResourceType.URI, Action.ACCESS, ActionOutcome.UNAVAILABLE, null, "Request method: GET" ); + // Make number of concurrent requests between 1-10 + int numberConcurrentRequests = rnd.nextInt( 9) + 1; + + LOG.info("Executing %d total requests with %d concurrently", numberTotalRequests, numberConcurrentRequests); + + ExecutorService executor = Executors.newFixedThreadPool(numberConcurrentRequests); + executor.invokeAll(callables); + executor.shutdown(); + executor.awaitTermination(5, TimeUnit.SECONDS); + assertThat(executor.isTerminated(), is(true)); + + assertThat( CollectAppender.queue.size(), is( numberTotalRequests ) ); + + // Use a set to make sure to dedupe any requestIds to get only unique ones + Set requestIds = new HashSet<>(); + for (LoggingEvent accessEvent : CollectAppender.queue) { + verifyAuditEvent( accessEvent, CONTEXT_PATH + PATH, ResourceType.URI, Action.ACCESS, ActionOutcome.UNAVAILABLE, null, "Request method: GET" ); + + CorrelationContext cc = (CorrelationContext)accessEvent.getMDC( Log4jCorrelationService.MDC_CORRELATION_CONTEXT_KEY ); + // There are some events that do not have a CorrelationContext associated (ie: deploy) + if(cc != null) { + requestIds.add(cc.getRequestId()); + } + } + + // There should be a unique correlation id for each request + assertThat(requestIds.size(), is(numberTotalRequests)); } @Test http://git-wip-us.apache.org/repos/asf/knox/blob/02f1b8b5/gateway-test-utils/src/main/java/org/apache/knox/test/log/CollectAppender.java ---------------------------------------------------------------------- diff --git a/gateway-test-utils/src/main/java/org/apache/knox/test/log/CollectAppender.java b/gateway-test-utils/src/main/java/org/apache/knox/test/log/CollectAppender.java index 3ab0c93..ff46e3e 100644 --- a/gateway-test-utils/src/main/java/org/apache/knox/test/log/CollectAppender.java +++ b/gateway-test-utils/src/main/java/org/apache/knox/test/log/CollectAppender.java @@ -29,9 +29,8 @@ public class CollectAppender extends AppenderSkeleton { super(); } - public static BlockingQueue queue = new LinkedBlockingQueue(); - public static boolean closed = false; - + public static final BlockingQueue queue = new LinkedBlockingQueue<>(); + @Override protected void append( LoggingEvent event ) { event.getProperties(); http://git-wip-us.apache.org/repos/asf/knox/blob/02f1b8b5/gateway-test/src/test/java/org/apache/knox/gateway/GatewayCorrelationIdTest.java ---------------------------------------------------------------------- diff --git a/gateway-test/src/test/java/org/apache/knox/gateway/GatewayCorrelationIdTest.java b/gateway-test/src/test/java/org/apache/knox/gateway/GatewayCorrelationIdTest.java new file mode 100644 index 0000000..b1b86fd --- /dev/null +++ b/gateway-test/src/test/java/org/apache/knox/gateway/GatewayCorrelationIdTest.java @@ -0,0 +1,205 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.knox.gateway; + +import com.mycila.xmltool.XMLDoc; +import com.mycila.xmltool.XMLTag; +import org.apache.http.HttpStatus; +import org.apache.knox.gateway.audit.api.CorrelationContext; +import org.apache.knox.gateway.audit.log4j.correlation.Log4jCorrelationService; +import org.apache.knox.gateway.config.GatewayConfig; +import org.apache.knox.gateway.services.DefaultGatewayServices; +import org.apache.knox.gateway.services.ServiceLifecycleException; +import org.apache.knox.test.TestUtils; +import org.apache.knox.test.log.CollectAppender; +import org.apache.log4j.spi.LoggingEvent; +import org.hamcrest.MatcherAssert; +import org.junit.AfterClass; +import org.junit.BeforeClass; +import org.junit.Test; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import java.io.File; +import java.io.FileOutputStream; +import java.net.URL; +import java.util.*; +import java.util.concurrent.*; + +import static io.restassured.RestAssured.given; +import static org.apache.knox.test.TestUtils.LOG_ENTER; +import static org.apache.knox.test.TestUtils.LOG_EXIT; +import static org.hamcrest.CoreMatchers.is; +import static org.hamcrest.CoreMatchers.notNullValue; +import static org.hamcrest.MatcherAssert.assertThat; + +public class GatewayCorrelationIdTest { + + private static Logger LOG = LoggerFactory.getLogger( GatewayCorrelationIdTest.class ); + + public static GatewayConfig config; + public static GatewayServer gateway; + public static String gatewayUrl; + public static String clusterUrl; + private static GatewayTestDriver driver = new GatewayTestDriver(); + + @BeforeClass + public static void setupSuite() throws Exception { + LOG_ENTER(); + URL resource = GatewayCorrelationIdTest.class.getClassLoader().getResource("users-dynamic.ldif"); + assert resource != null; + driver.setupLdap( 0, new File(resource.toURI()) ); + setupGateway(); + CollectAppender.queue.clear(); + LOG_EXIT(); + } + + @AfterClass + public static void cleanupSuite() throws Exception { + LOG_ENTER(); + gateway.stop(); + driver.cleanup(); + CollectAppender.queue.clear(); + LOG_EXIT(); + } + + public static void setupGateway() throws Exception { + File targetDir = new File( System.getProperty( "user.dir" ), "target" ); + File gatewayDir = new File( targetDir, "gateway-home-" + UUID.randomUUID() ); + gatewayDir.mkdirs(); + + GatewayTestConfig testConfig = new GatewayTestConfig(); + config = testConfig; + testConfig.setGatewayHomeDir( gatewayDir.getAbsolutePath() ); + + File topoDir = new File( testConfig.getGatewayTopologyDir() ); + topoDir.mkdirs(); + + File deployDir = new File( testConfig.getGatewayDeploymentDir() ); + deployDir.mkdirs(); + + File descriptor = new File( topoDir, "test-cluster.xml" ); + FileOutputStream stream = new FileOutputStream( descriptor ); + createTopology().toStream( stream ); + stream.close(); + + DefaultGatewayServices srvcs = new DefaultGatewayServices(); + Map options = new HashMap<>(); + options.put( "persist-master", "false" ); + options.put( "master", "password" ); + try { + srvcs.init( testConfig, options ); + } catch ( ServiceLifecycleException e ) { + e.printStackTrace(); // I18N not required. + } + + gateway = GatewayServer.startGateway( testConfig, srvcs ); + MatcherAssert.assertThat( "Failed to start gateway.", gateway, notNullValue() ); + + LOG.info( "Gateway port = " + gateway.getAddresses()[ 0 ].getPort() ); + + gatewayUrl = "http://localhost:" + gateway.getAddresses()[0].getPort() + "/" + config.getGatewayPath(); + clusterUrl = gatewayUrl + "/test-cluster"; + } + + private static XMLTag createTopology() { + return XMLDoc.newDocument( true ) + .addRoot( "topology" ) + .addTag( "gateway" ) + .addTag( "provider" ) + .addTag( "role" ).addText( "authentication" ) + .addTag( "name" ).addText( "ShiroProvider" ) + .addTag( "enabled" ).addText( "true" ) + .addTag( "param" ) + .addTag( "name" ).addText( "main.ldapRealm" ) + .addTag( "value" ).addText( "org.apache.knox.gateway.shirorealm.KnoxLdapRealm" ).gotoParent() + .addTag( "param" ) + .addTag( "name" ).addText( "main.ldapRealm.userDnTemplate" ) + .addTag( "value" ).addText( "uid={0},ou=people,dc=hadoop,dc=apache,dc=org" ).gotoParent() + .addTag( "param" ) + .addTag( "name" ).addText( "main.ldapRealm.contextFactory.url" ) + .addTag( "value" ).addText( driver.getLdapUrl() ).gotoParent() + .addTag( "param" ) + .addTag( "name" ).addText( "main.ldapRealm.contextFactory.authenticationMechanism" ) + .addTag( "value" ).addText( "simple" ).gotoParent() + .addTag( "param" ) + .addTag( "name" ).addText( "urls./**" ) + .addTag( "value" ).addText( "authcBasic" ).gotoParent().gotoParent() + .addTag( "provider" ) + .addTag( "role" ).addText( "identity-assertion" ) + .addTag( "enabled" ).addText( "true" ) + .addTag( "name" ).addText( "Default" ).gotoParent() + .addTag( "provider" ) + .gotoRoot() + .addTag( "service" ) + .addTag( "role" ).addText( "test-service-role" ) + .gotoRoot(); + } + + @Test( timeout = TestUtils.MEDIUM_TIMEOUT ) + public void testTestService() throws Exception { + LOG_ENTER(); + String username = "guest"; + String password = "guest-password"; + String serviceUrl = clusterUrl + "/test-service-path/test-service-resource"; + + Random rnd = new Random(); + + // Make number of total requests between 1-100 + int numberTotalRequests = rnd.nextInt(99) + 1; + Set> callables = new HashSet<>(numberTotalRequests); + for (int i = 0; i < numberTotalRequests; i++) { + callables.add(() -> { + given() + .auth().preemptive().basic( username, password ) + .then() + .statusCode( HttpStatus.SC_OK ) + .contentType( "text/plain" ) + .body( is( "test-service-response" ) ) + .when().get( serviceUrl ); + return null; + }); + } + + // Make number of concurrent requests between 1-10 + int numberConcurrentRequests = rnd.nextInt( 9) + 1; + + LOG.info("Executing %d total requests with %d concurrently", numberTotalRequests, numberConcurrentRequests); + + ExecutorService executor = Executors.newFixedThreadPool(numberConcurrentRequests); + executor.invokeAll(callables); + executor.shutdown(); + executor.awaitTermination(5, TimeUnit.SECONDS); + assertThat(executor.isTerminated(), is(true)); + + // Use a set to make sure to dedupe any requestIds to get only unique ones + Set requestIds = new HashSet<>(); + for (LoggingEvent accessEvent : CollectAppender.queue) { + CorrelationContext cc = (CorrelationContext)accessEvent.getMDC( Log4jCorrelationService.MDC_CORRELATION_CONTEXT_KEY ); + // There are some events that do not have a CorrelationContext associated (ie: deploy) + if(cc != null) { + requestIds.add(cc.getRequestId()); + } + } + + // There should be a unique correlation id for each request + assertThat(requestIds.size(), is(numberTotalRequests)); + + LOG_EXIT(); + } +} http://git-wip-us.apache.org/repos/asf/knox/blob/02f1b8b5/gateway-test/src/test/resources/log4j.properties ---------------------------------------------------------------------- diff --git a/gateway-test/src/test/resources/log4j.properties b/gateway-test/src/test/resources/log4j.properties index f3ee344..201b537 100644 --- a/gateway-test/src/test/resources/log4j.properties +++ b/gateway-test/src/test/resources/log4j.properties @@ -23,6 +23,9 @@ log4j.appender.stdout=org.apache.log4j.ConsoleAppender log4j.appender.stdout.layout=org.apache.log4j.PatternLayout log4j.appender.stdout.layout.ConversionPattern=%5p [%c] %m%n +log4j.logger.audit = INFO, collectappender +log4j.appender.collectappender = org.apache.knox.test.log.CollectAppender + #log4j.logger.org.apache.knox.gateway=DEBUG #log4j.logger.org.apache.knox.test=DEBUG #log4j.logger.org.apache.knox.gateway.http=TRACE