diff --git a/community/bolt/src/main/java/org/neo4j/bolt/BoltKernelExtension.java b/community/bolt/src/main/java/org/neo4j/bolt/BoltKernelExtension.java index 617ee50f58ecd..847cf3d2a9aaf 100644 --- a/community/bolt/src/main/java/org/neo4j/bolt/BoltKernelExtension.java +++ b/community/bolt/src/main/java/org/neo4j/bolt/BoltKernelExtension.java @@ -37,6 +37,7 @@ import org.neo4j.bolt.security.ssl.KeyStoreFactory; import org.neo4j.bolt.security.ssl.KeyStoreInformation; import org.neo4j.bolt.transport.BoltProtocol; +import org.neo4j.bolt.transport.Netty4LogBridge; import org.neo4j.bolt.transport.NettyServer; import org.neo4j.bolt.transport.SocketTransport; import org.neo4j.bolt.v1.runtime.MonitoredSessions; @@ -56,13 +57,16 @@ import org.neo4j.kernel.configuration.Config; import org.neo4j.kernel.configuration.ConfigValues; import org.neo4j.kernel.extension.KernelExtensionFactory; +import org.neo4j.kernel.impl.core.ThreadToStatementContextBridge; import org.neo4j.kernel.impl.logging.LogService; +import org.neo4j.kernel.impl.query.QueryExecutionEngine; import org.neo4j.kernel.impl.spi.KernelContext; import org.neo4j.kernel.impl.util.JobScheduler; import org.neo4j.kernel.lifecycle.LifeSupport; import org.neo4j.kernel.lifecycle.Lifecycle; import org.neo4j.kernel.monitoring.Monitors; import org.neo4j.logging.Log; +import org.neo4j.server.security.auth.AuthManager; import org.neo4j.udc.UsageData; import static org.neo4j.bolt.BoltKernelExtension.EncryptionLevel.OPTIONAL; @@ -170,6 +174,12 @@ public interface Dependencies UsageData usageData(); Monitors monitors(); + + AuthManager authManager(); + + ThreadToStatementContextBridge txBridge(); + + QueryExecutionEngine queryEngine(); } public BoltKernelExtension() @@ -190,11 +200,15 @@ public Lifecycle newInstance( KernelContext context, Dependencies dependencies ) final JobScheduler scheduler = dependencies.scheduler(); + Netty4LogBridge.setLogProvider( logging.getInternalLogProvider() ); + Sessions sessions = new MonitoredSessions( dependencies.monitors(), - new ThreadedSessions( - life.add( new StandardSessions( api, dependencies.usageData(), logging ) ), - scheduler, logging ), Clock.systemUTC() ); + new ThreadedSessions( + life.add( new StandardSessions( api, dependencies.usageData(), logging, + dependencies.txBridge(), + dependencies.queryEngine() ) ), + scheduler, logging ), Clock.systemUTC() ); List connectors = new ArrayList<>(); diff --git a/community/server/src/main/java/org/neo4j/server/logging/Netty4LogBridge.java b/community/bolt/src/main/java/org/neo4j/bolt/transport/Netty4LogBridge.java similarity index 98% rename from community/server/src/main/java/org/neo4j/server/logging/Netty4LogBridge.java rename to community/bolt/src/main/java/org/neo4j/bolt/transport/Netty4LogBridge.java index 0fe954d9fa9a6..977dfd7f7c6cf 100644 --- a/community/server/src/main/java/org/neo4j/server/logging/Netty4LogBridge.java +++ b/community/bolt/src/main/java/org/neo4j/bolt/transport/Netty4LogBridge.java @@ -17,7 +17,7 @@ * You should have received a copy of the GNU General Public License * along with this program. If not, see . */ -package org.neo4j.server.logging; +package org.neo4j.bolt.transport; import io.netty.util.internal.logging.InternalLoggerFactory; diff --git a/community/server/src/main/java/org/neo4j/server/logging/Netty4LoggerFactory.java b/community/bolt/src/main/java/org/neo4j/bolt/transport/Netty4LoggerFactory.java similarity index 79% rename from community/server/src/main/java/org/neo4j/server/logging/Netty4LoggerFactory.java rename to community/bolt/src/main/java/org/neo4j/bolt/transport/Netty4LoggerFactory.java index 64e6f19b4c3cb..d5da0feab8b30 100644 --- a/community/server/src/main/java/org/neo4j/server/logging/Netty4LoggerFactory.java +++ b/community/bolt/src/main/java/org/neo4j/bolt/transport/Netty4LoggerFactory.java @@ -17,7 +17,7 @@ * You should have received a copy of the GNU General Public License * along with this program. If not, see . */ -package org.neo4j.server.logging; +package org.neo4j.bolt.transport; import io.netty.util.internal.logging.AbstractInternalLogger; import io.netty.util.internal.logging.InternalLogger; @@ -53,13 +53,15 @@ public boolean isTraceEnabled() @Override public boolean isDebugEnabled() { - return false; + return log.isDebugEnabled(); } @Override public boolean isInfoEnabled() { - return false; + // No way to tell log level with better granularity yet, and INFO + // logging for Netty component is most likely DEBUG anyway + return log.isDebugEnabled(); } @Override @@ -83,19 +85,19 @@ public void debug( String s ) @Override public void debug( String s, Object o ) { - log.debug( s, o ); + log.debug( asNeoTemplate(s), o ); } @Override public void debug( String s, Object o, Object o1 ) { - log.debug( s, o, o1 ); + log.debug( asNeoTemplate(s), o, o1 ); } @Override public void debug( String s, Object... objects ) { - log.debug( s, objects ); + log.debug( asNeoTemplate(s), objects ); } @Override @@ -113,19 +115,19 @@ public void info( String s ) @Override public void info( String s, Object o ) { - log.info( s, o ); + log.info( asNeoTemplate(s), o ); } @Override public void info( String s, Object o, Object o1 ) { - log.info( s, o, o1 ); + log.info( asNeoTemplate(s), o, o1 ); } @Override public void info( String s, Object... objects ) { - log.info( s, objects ); + log.info( asNeoTemplate(s), objects ); } @Override @@ -143,19 +145,19 @@ public void warn( String s ) @Override public void warn( String s, Object o ) { - log.warn( s, o ); + log.warn( asNeoTemplate(s), o ); } @Override public void warn( String s, Object... objects ) { - log.warn( s, objects ); + log.warn( asNeoTemplate(s), objects ); } @Override public void warn( String s, Object o, Object o1 ) { - log.warn( s, o, o1 ); + log.warn( asNeoTemplate(s), o, o1 ); } @Override @@ -173,19 +175,19 @@ public void error( String s ) @Override public void error( String s, Object o ) { - log.error( s, o ); + log.error( asNeoTemplate(s), o ); } @Override public void error( String s, Object o, Object o1 ) { - log.error( s, o, o1 ); + log.error( asNeoTemplate(s), o, o1 ); } @Override public void error( String s, Object... objects ) { - log.error( s, objects ); + log.error( asNeoTemplate(s), objects ); } @Override @@ -224,6 +226,14 @@ public void trace( String s, Throwable throwable ) } + private String asNeoTemplate( String nettyLogTemplate ) + { + // Netty uses MessageFormat as placeholders, we use String.format() + // Sidenote: MessageFormat is the right tool for this job, it handles + // pluralization, i18n etc., we should change at some point. + return nettyLogTemplate.replaceAll( "\\{\\}", "%s" ); + } + }; } } diff --git a/community/bolt/src/main/java/org/neo4j/bolt/v1/runtime/internal/StandardSessions.java b/community/bolt/src/main/java/org/neo4j/bolt/v1/runtime/internal/StandardSessions.java index 3f05ccfdf9975..8fa85148b1105 100644 --- a/community/bolt/src/main/java/org/neo4j/bolt/v1/runtime/internal/StandardSessions.java +++ b/community/bolt/src/main/java/org/neo4j/bolt/v1/runtime/internal/StandardSessions.java @@ -42,14 +42,18 @@ public class StandardSessions extends LifecycleAdapter implements Sessions private CypherStatementRunner statementRunner; private ThreadToStatementContextBridge txBridge; + private final QueryExecutionEngine engine; - public StandardSessions( GraphDatabaseAPI gds, UsageData usageData, LogService logging ) + public StandardSessions( GraphDatabaseAPI gds, + UsageData usageData, LogService logging, + ThreadToStatementContextBridge txBridge, + QueryExecutionEngine engine ) { this.gds = gds; this.usageData = usageData; this.logging = logging; - // TODO: Introduce a clean SPI rather than use GDS - this.txBridge = gds.getDependencyResolver().resolveDependency( ThreadToStatementContextBridge.class ); + this.txBridge = txBridge; + this.engine = engine; } @Override @@ -61,8 +65,7 @@ public void init() throws Throwable @Override public void start() throws Throwable { - QueryExecutionEngine queryExecutionEngine = gds.getDependencyResolver().resolveDependency( QueryExecutionEngine.class ); - statementRunner = new CypherStatementRunner( gds, queryExecutionEngine ); + statementRunner = new CypherStatementRunner( gds, engine ); life.start(); } diff --git a/community/bolt/src/test/java/org/neo4j/bolt/v1/runtime/integration/TestSessions.java b/community/bolt/src/test/java/org/neo4j/bolt/v1/runtime/integration/TestSessions.java index 1d790808caee5..1ae0b8ab14352 100644 --- a/community/bolt/src/test/java/org/neo4j/bolt/v1/runtime/integration/TestSessions.java +++ b/community/bolt/src/test/java/org/neo4j/bolt/v1/runtime/integration/TestSessions.java @@ -30,20 +30,22 @@ import java.util.LinkedList; import org.neo4j.bolt.v1.runtime.Session; +import org.neo4j.bolt.v1.runtime.Sessions; import org.neo4j.bolt.v1.runtime.internal.StandardSessions; -import org.neo4j.graphdb.GraphDatabaseService; +import org.neo4j.bolt.v1.runtime.internal.concurrent.ThreadedSessions; +import org.neo4j.graphdb.DependencyResolver; import org.neo4j.kernel.GraphDatabaseAPI; +import org.neo4j.kernel.impl.core.ThreadToStatementContextBridge; import org.neo4j.kernel.impl.logging.NullLogService; +import org.neo4j.kernel.impl.query.QueryExecutionEngine; import org.neo4j.kernel.impl.util.Neo4jJobScheduler; import org.neo4j.kernel.lifecycle.LifeSupport; -import org.neo4j.bolt.v1.runtime.Sessions; -import org.neo4j.bolt.v1.runtime.internal.concurrent.ThreadedSessions; import org.neo4j.test.TestGraphDatabaseFactory; import org.neo4j.udc.UsageData; public class TestSessions implements TestRule, Sessions { - private GraphDatabaseService gdb; + private GraphDatabaseAPI gdb; private Sessions actual; private LinkedList startedSessions = new LinkedList<>(); private final LifeSupport life = new LifeSupport(); @@ -56,10 +58,14 @@ public Statement apply( final Statement base, Description description ) @Override public void evaluate() throws Throwable { - gdb = new TestGraphDatabaseFactory().newImpermanentDatabase(); + gdb = (GraphDatabaseAPI) new TestGraphDatabaseFactory().newImpermanentDatabase(); Neo4jJobScheduler scheduler = life.add( new Neo4jJobScheduler() ); + DependencyResolver resolver = gdb.getDependencyResolver(); StandardSessions sessions = life.add( - new StandardSessions( (GraphDatabaseAPI) gdb, new UsageData(), NullLogService.getInstance() ) ); + new StandardSessions( gdb, new UsageData(), NullLogService.getInstance(), + resolver.resolveDependency( ThreadToStatementContextBridge.class ), + resolver.resolveDependency( QueryExecutionEngine.class )) + ); actual = new ThreadedSessions( sessions, scheduler, NullLogService.getInstance() ); diff --git a/community/bolt/src/test/java/org/neo4j/bolt/v1/transport/integration/NettyLoggingIT.java b/community/bolt/src/test/java/org/neo4j/bolt/v1/transport/integration/NettyLoggingIT.java new file mode 100644 index 0000000000000..a99829aa4bb9f --- /dev/null +++ b/community/bolt/src/test/java/org/neo4j/bolt/v1/transport/integration/NettyLoggingIT.java @@ -0,0 +1,148 @@ +/* + * Copyright (c) 2002-2016 "Neo Technology," + * Network Engine for Objects in Lund AB [http://neotechnology.com] + * + * This file is part of Neo4j. + * + * Neo4j is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see . + */ +package org.neo4j.bolt.v1.transport.integration; + +import org.junit.After; +import org.junit.Test; + +import org.neo4j.bolt.BoltKernelExtension; +import org.neo4j.graphdb.GraphDatabaseService; +import org.neo4j.kernel.GraphDatabaseAPI; +import org.neo4j.kernel.configuration.Config; +import org.neo4j.kernel.impl.core.ThreadToStatementContextBridge; +import org.neo4j.kernel.impl.logging.LogService; +import org.neo4j.kernel.impl.logging.SimpleLogService; +import org.neo4j.kernel.impl.query.QueryExecutionEngine; +import org.neo4j.kernel.impl.spi.KernelContext; +import org.neo4j.kernel.impl.util.JobScheduler; +import org.neo4j.kernel.lifecycle.LifeSupport; +import org.neo4j.kernel.monitoring.Monitors; +import org.neo4j.logging.AssertableLogProvider; +import org.neo4j.server.security.auth.AuthManager; +import org.neo4j.udc.UsageData; + +import static org.hamcrest.Matchers.equalTo; +import static org.hamcrest.Matchers.greaterThan; +import static org.mockito.Mockito.mock; +import static org.neo4j.bolt.BoltKernelExtension.Settings.connector; +import static org.neo4j.bolt.BoltKernelExtension.Settings.enabled; +import static org.neo4j.helpers.collection.MapUtil.stringMap; +import static org.neo4j.logging.AssertableLogProvider.inLog; + +public class NettyLoggingIT +{ + private LifeSupport life; + + @Test + public void shouldEnableNettyDebugLoggingIfAsked() throws Throwable + { + // Given + AssertableLogProvider log = new AssertableLogProvider( true ); + + Config config = new Config(stringMap( + connector( 0, enabled ).name(), "true" + )); + + life = new LifeSupport(); + life.add( new BoltKernelExtension().newInstance( + mock( KernelContext.class ), + stubDependencies( config, log ) ) ); + + // When + life.start(); + + // Then + log.assertAtLeastOnce( + // Depending on netty internals here - point is to assert on something + // that shows we're getting netty debug logging coming through. If + // we upgrade netty and this changes, just assert some other debug statement + // from netty shows up. + inLog("io.netty.buffer.PooledByteBufAllocator") + .debug( + equalTo( "-Dio.netty.allocator.cacheTrimInterval: %s"), + greaterThan( 0 ) ) ); + } + + @After + public void cleanup() + { + life.shutdown(); + } + + private BoltKernelExtension.Dependencies stubDependencies( final Config config, final AssertableLogProvider log ) + { + return new BoltKernelExtension.Dependencies() + { + @Override + public LogService logService() + { + return new SimpleLogService( log, log ); + } + + @Override + public Config config() + { + return config; + } + + @Override + public GraphDatabaseService db() + { + return mock( GraphDatabaseAPI.class ); + } + + @Override + public JobScheduler scheduler() + { + return mock( JobScheduler.class ); + } + + @Override + public UsageData usageData() + { + return new UsageData(); + } + + @Override + public Monitors monitors() + { + return new Monitors(); + } + + @Override + public AuthManager authManager() + { + return mock(AuthManager.class); + } + + @Override + public ThreadToStatementContextBridge txBridge() + { + return mock(ThreadToStatementContextBridge.class); + } + + @Override + public QueryExecutionEngine queryEngine() + { + return mock( QueryExecutionEngine.class ); + } + }; + } +} diff --git a/community/server/src/main/java/org/neo4j/server/Bootstrapper.java b/community/server/src/main/java/org/neo4j/server/Bootstrapper.java index 31719f433c41e..56a46111d6663 100644 --- a/community/server/src/main/java/org/neo4j/server/Bootstrapper.java +++ b/community/server/src/main/java/org/neo4j/server/Bootstrapper.java @@ -38,7 +38,7 @@ import org.neo4j.server.configuration.ServerSettings; import org.neo4j.server.logging.JULBridge; import org.neo4j.server.logging.JettyLogBridge; -import org.neo4j.server.logging.Netty4LogBridge; + import static java.lang.String.format; import static org.neo4j.server.configuration.ServerSettings.SERVER_CONFIG_FILE; import static org.neo4j.server.configuration.ServerSettings.SERVER_CONFIG_FILE_KEY; @@ -78,7 +78,6 @@ public int start( File configFile, Pair ... configOverrides ) Logger.getLogger( "" ).setLevel( Level.WARNING ); JULBridge.forwardTo( userLogProvider ); JettyLogBridge.setLogProvider( userLogProvider ); - Netty4LogBridge.setLogProvider( userLogProvider ); log = userLogProvider.getLog( getClass() );