diff --git a/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLogEntryContent.java b/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLogEntryContent.java new file mode 100644 index 0000000000000..027dac2b8e00e --- /dev/null +++ b/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLogEntryContent.java @@ -0,0 +1,43 @@ +/* + * Copyright (c) 2002-2017 "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 Affero 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 Affero General Public License for more details. + * + * You should have received a copy of the GNU Affero General Public License + * along with this program. If not, see . + */ +package org.neo4j.kernel.impl.query; + +import org.neo4j.graphdb.config.Setting; +import org.neo4j.graphdb.factory.GraphDatabaseSettings; +import org.neo4j.kernel.configuration.Config; + +enum QueryLogEntryContent +{ + LOG_PARAMETERS( GraphDatabaseSettings.log_queries_parameter_logging_enabled ), + LOG_DETAILED_TIME( GraphDatabaseSettings.log_queries_detailed_time_logging_enabled ), + LOG_ALLOCATED_BYTES( GraphDatabaseSettings.log_queries_allocation_logging_enabled ), + LOG_PAGE_DETAILS( GraphDatabaseSettings.log_queries_page_detail_logging_enabled ); + private final Setting setting; + + QueryLogEntryContent( Setting setting ) + { + this.setting = setting; + } + + boolean enabledIn( Config config ) + { + return config.get( setting ); + } +} diff --git a/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLogFormatter.java b/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLogFormatter.java new file mode 100644 index 0000000000000..781aa13cf07ba --- /dev/null +++ b/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLogFormatter.java @@ -0,0 +1,105 @@ +/* + * Copyright (c) 2002-2017 "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 Affero 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 Affero General Public License for more details. + * + * You should have received a copy of the GNU Affero General Public License + * along with this program. If not, see . + */ +package org.neo4j.kernel.impl.query; + +import java.util.Collection; +import java.util.Collections; +import java.util.Map; + +import org.neo4j.helpers.Strings; +import org.neo4j.kernel.api.query.QuerySnapshot; + +class QueryLogFormatter +{ + static void formatPageDetails( StringBuilder result, QuerySnapshot query ) + { + result.append( query.pageHits() ).append( " page hits, " ); + result.append( query.pageFaults() ).append( " page faults - " ); + } + + static void formatAllocatedBytes( StringBuilder result, QuerySnapshot query ) + { + Long bytes = query.allocatedBytes(); + if ( bytes != null ) + { + result.append( bytes ).append( " B - " ); + } + } + + static void formatDetailedTime( StringBuilder result, QuerySnapshot query ) + { + result.append( "(planning: " ).append( query.planningTimeMillis() ); + Long cpuTime = query.cpuTimeMillis(); + if ( cpuTime != null ) + { + result.append( ", cpu: " ).append( cpuTime ); + } + result.append( ", waiting: " ).append( query.waitTimeMillis() ); + result.append( ") - " ); + } + + static void formatMap( StringBuilder result, Map params ) + { + formatMap( result, params, Collections.emptySet() ); + } + + static void formatMap( StringBuilder result, Map params, Collection obfuscate ) + { + result.append( '{' ); + if ( params != null ) + { + String sep = ""; + for ( Map.Entry entry : params.entrySet() ) + { + result + .append( sep ) + .append( entry.getKey() ) + .append( ": " ); + + if ( obfuscate.contains( entry.getKey() ) ) + { + result.append( "******" ); + } + else + { + formatValue( result, entry.getValue() ); + } + sep = ", "; + } + } + result.append( "}" ); + } + + private static void formatValue( StringBuilder result, Object value ) + { + if ( value instanceof Map ) + { + formatMap( result, (Map) value ); + } + else if ( value instanceof String ) + { + result.append( '\'' ).append( value ).append( '\'' ); + } + else + { + result.append( Strings.prettyPrint( value ) ); + } + } +} diff --git a/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLogger.java b/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLogger.java new file mode 100644 index 0000000000000..ca58ef76576ca --- /dev/null +++ b/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLogger.java @@ -0,0 +1,125 @@ +/* + * Copyright (c) 2002-2017 "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 Affero 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 Affero General Public License for more details. + * + * You should have received a copy of the GNU Affero General Public License + * along with this program. If not, see . + */ +package org.neo4j.kernel.impl.query; + +import java.util.EnumSet; +import java.util.HashSet; +import java.util.Set; +import java.util.regex.Matcher; +import java.util.regex.Pattern; + +import org.neo4j.kernel.api.query.ExecutingQuery; +import org.neo4j.kernel.api.query.QuerySnapshot; +import org.neo4j.logging.Log; + +class QueryLogger implements QueryExecutionMonitor +{ + private final Log log; + private final long thresholdMillis; + private final boolean logQueryParameters, logDetailedTime, logAllocatedBytes, logPageDetails; + + private static final Pattern PASSWORD_PATTERN = Pattern.compile( + // call signature + "(?:(?i)call)\\s+dbms(?:\\.security)?\\.change(?:User)?Password\\(" + + // optional username parameter, in single, double quotes, or parametrized + "(?:\\s*(?:'(?:(?<=\\\\)'|[^'])*'|\"(?:(?<=\\\\)\"|[^\"])*\"|[^,]*)\\s*,)?" + + // password parameter, in single, double quotes, or parametrized + "\\s*('(?:(?<=\\\\)'|[^'])*'|\"(?:(?<=\\\\)\"|[^\"])*\"|\\$\\w*|\\{\\w*\\})\\s*\\)" ); + + QueryLogger( Log log, long thresholdMillis, EnumSet flags ) + { + this.log = log; + this.thresholdMillis = thresholdMillis; + this.logQueryParameters = flags.contains( QueryLogEntryContent.LOG_PARAMETERS ); + this.logDetailedTime = flags.contains( QueryLogEntryContent.LOG_DETAILED_TIME ); + this.logAllocatedBytes = flags.contains( QueryLogEntryContent.LOG_ALLOCATED_BYTES ); + this.logPageDetails = flags.contains( QueryLogEntryContent.LOG_PAGE_DETAILS ); + } + + @Override + public void startQueryExecution( ExecutingQuery query ) + { + } + + @Override + public void endFailure( ExecutingQuery query, Throwable failure ) + { + log.error( logEntry( query.snapshot() ), failure ); + } + + @Override + public void endSuccess( ExecutingQuery query ) + { + QuerySnapshot snapshot = query.snapshot(); + if ( snapshot.elapsedTimeMillis() >= thresholdMillis ) + { + log.info( logEntry( snapshot ) ); + } + } + + private String logEntry( QuerySnapshot query ) + { + String sourceString = query.clientConnection().asConnectionDetails(); + String queryText = query.queryText(); + + Set passwordParams = new HashSet<>(); + Matcher matcher = PASSWORD_PATTERN.matcher( queryText ); + + while ( matcher.find() ) + { + String password = matcher.group( 1 ).trim(); + if ( password.charAt( 0 ) == '$' ) + { + passwordParams.add( password.substring( 1 ) ); + } + else if ( password.charAt( 0 ) == '{' ) + { + passwordParams.add( password.substring( 1, password.length() - 1 ) ); + } + else + { + queryText = queryText.replace( password, "******" ); + password = ""; + } + } + + StringBuilder result = new StringBuilder(); + result.append( query.elapsedTimeMillis() ).append( " ms: " ); + if ( logDetailedTime ) + { + QueryLogFormatter.formatDetailedTime( result, query ); + } + if ( logAllocatedBytes ) + { + QueryLogFormatter.formatAllocatedBytes( result, query ); + } + if ( logPageDetails ) + { + QueryLogFormatter.formatPageDetails( result, query ); + } + result.append( sourceString ).append( " - " ).append( queryText ); + if ( logQueryParameters ) + { + QueryLogFormatter.formatMap( result.append(" - "), query.queryParameters(), passwordParams ); + } + QueryLogFormatter.formatMap( result.append(" - "), query.transactionAnnotationData() ); + return result.toString(); + } +} diff --git a/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLoggerKernelExtension.java b/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLoggerKernelExtension.java index a21f812301dd0..182b08bc6e729 100644 --- a/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLoggerKernelExtension.java +++ b/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLoggerKernelExtension.java @@ -22,22 +22,11 @@ import java.io.Closeable; import java.io.File; import java.io.OutputStream; -import java.util.Collection; -import java.util.Collections; import java.util.EnumSet; -import java.util.HashSet; -import java.util.Map; -import java.util.Set; -import java.util.regex.Matcher; -import java.util.regex.Pattern; -import org.neo4j.graphdb.config.Setting; import org.neo4j.graphdb.factory.GraphDatabaseSettings; import org.neo4j.helpers.Service; -import org.neo4j.helpers.Strings; import org.neo4j.io.fs.FileSystemAbstraction; -import org.neo4j.kernel.api.query.ExecutingQuery; -import org.neo4j.kernel.api.query.QuerySnapshot; import org.neo4j.kernel.configuration.Config; import org.neo4j.kernel.extension.KernelExtensionFactory; import org.neo4j.kernel.impl.logging.LogService; @@ -69,25 +58,6 @@ public interface Dependencies JobScheduler jobScheduler(); } - enum Flag - { - LOG_PARAMETERS( GraphDatabaseSettings.log_queries_parameter_logging_enabled ), - LOG_DETAILED_TIME( GraphDatabaseSettings.log_queries_detailed_time_logging_enabled ), - LOG_ALLOCATED_BYTES( GraphDatabaseSettings.log_queries_allocation_logging_enabled ), - LOG_PAGE_DETAILS( GraphDatabaseSettings.log_queries_page_detail_logging_enabled ); - private final Setting setting; - - Flag( Setting setting ) - { - this.setting = setting; - } - - boolean enabledIn( Config config ) - { - return config.get( setting ); - } - } - public QueryLoggerKernelExtension() { super( "query-logging" ); @@ -119,8 +89,8 @@ public void init() throws Throwable Long thresholdMillis = config.get( GraphDatabaseSettings.log_queries_threshold ); Long rotationThreshold = config.get( GraphDatabaseSettings.log_queries_rotation_threshold ); int maxArchives = config.get( GraphDatabaseSettings.log_queries_max_archives ); - EnumSet flags = EnumSet.noneOf( Flag.class ); - for ( Flag flag : Flag.values() ) + EnumSet flags = EnumSet.noneOf( QueryLogEntryContent.class ); + for ( QueryLogEntryContent flag : QueryLogEntryContent.values() ) { if (flag.enabledIn(config)) { @@ -162,161 +132,4 @@ private Lifecycle createEmptyAdapter() { return new LifecycleAdapter(); } - - static class QueryLogger implements QueryExecutionMonitor - { - private final Log log; - private final long thresholdMillis; - private final boolean logQueryParameters, logDetailedTime, logAllocatedBytes, logPageDetails; - - private static final Pattern PASSWORD_PATTERN = Pattern.compile( - // call signature - "(?:(?i)call)\\s+dbms(?:\\.security)?\\.change(?:User)?Password\\(" + - // optional username parameter, in single, double quotes, or parametrized - "(?:\\s*(?:'(?:(?<=\\\\)'|[^'])*'|\"(?:(?<=\\\\)\"|[^\"])*\"|[^,]*)\\s*,)?" + - // password parameter, in single, double quotes, or parametrized - "\\s*('(?:(?<=\\\\)'|[^'])*'|\"(?:(?<=\\\\)\"|[^\"])*\"|\\$\\w*|\\{\\w*\\})\\s*\\)" ); - - QueryLogger( Log log, long thresholdMillis, EnumSet flags ) - { - this.log = log; - this.thresholdMillis = thresholdMillis; - this.logQueryParameters = flags.contains( Flag.LOG_PARAMETERS ); - this.logDetailedTime = flags.contains( Flag.LOG_DETAILED_TIME ); - this.logAllocatedBytes = flags.contains( Flag.LOG_ALLOCATED_BYTES ); - this.logPageDetails = flags.contains( Flag.LOG_PAGE_DETAILS ); - } - - @Override - public void startQueryExecution( ExecutingQuery query ) - { - } - - @Override - public void endFailure( ExecutingQuery query, Throwable failure ) - { - log.error( logEntry( query.snapshot() ), failure ); - } - - @Override - public void endSuccess( ExecutingQuery query ) - { - QuerySnapshot snapshot = query.snapshot(); - if ( snapshot.elapsedTimeMillis() >= thresholdMillis ) - { - log.info( logEntry( snapshot ) ); - } - } - - private String logEntry( QuerySnapshot query ) - { - String sourceString = query.clientConnection().asConnectionDetails(); - String queryText = query.queryText(); - String metaData = mapAsString( query.transactionAnnotationData() ); - - Set passwordParams = new HashSet<>(); - Matcher matcher = PASSWORD_PATTERN.matcher( queryText ); - - while ( matcher.find() ) - { - String password = matcher.group( 1 ).trim(); - if ( password.charAt( 0 ) == '$' ) - { - passwordParams.add( password.substring( 1 ) ); - } - else if ( password.charAt( 0 ) == '{' ) - { - passwordParams.add( password.substring( 1, password.length() - 1 ) ); - } - else - { - queryText = queryText.replace( password, "******" ); - password = ""; - } - } - - StringBuilder result = new StringBuilder(); - result.append( query.elapsedTimeMillis() ).append( " ms: " ); - if ( logDetailedTime ) - { - result.append( "(planning: " ).append( query.planningTimeMillis() ); - Long cpuTime = query.cpuTimeMillis(); - if ( cpuTime != null ) - { - result.append( ", cpu: " ).append( cpuTime ); - } - result.append( ", waiting: " ).append( query.waitTimeMillis() ); - result.append( ") - " ); - } - if ( logAllocatedBytes ) - { - Long bytes = query.allocatedBytes(); - if ( bytes != null ) - { - result.append( bytes ).append( " B - " ); - } - } - if ( logPageDetails ) - { - result.append( query.pageHits() ).append( " page hits, " ); - result.append( query.pageFaults() ).append( " page faults - " ); - } - result.append( sourceString ).append( " - " ).append( queryText ); - if ( logQueryParameters ) - { - result.append( " - " ).append( mapAsString( query.queryParameters(), passwordParams ) ); - } - result.append( " - " ).append( metaData ); - return result.toString(); - } - - private static String mapAsString( Map params ) - { - return mapAsString( params, Collections.emptySet() ); - } - - private static String mapAsString( Map params, Collection obfuscate ) - { - if ( params == null ) - { - return "{}"; - } - - StringBuilder builder = new StringBuilder( "{" ); - String sep = ""; - for ( Map.Entry entry : params.entrySet() ) - { - builder - .append( sep ) - .append( entry.getKey() ) - .append( ": " ); - - if ( obfuscate.contains( entry.getKey() ) ) - { - builder.append( "******" ); - } - else - { - builder.append( valueToString( entry.getValue() ) ); - } - sep = ", "; - } - builder.append( "}" ); - - return builder.toString(); - } - - private static String valueToString( Object value ) - { - if ( value instanceof Map ) - { - return mapAsString( (Map) value ); - } - if ( value instanceof String ) - { - return format( "'%s'", String.valueOf( value ) ); - } - return Strings.prettyPrint( value ); - } - } } diff --git a/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerTest.java b/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerTest.java index eb7ee7d71ba94..694c78e3a1709 100644 --- a/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerTest.java +++ b/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerTest.java @@ -31,7 +31,6 @@ import org.neo4j.io.pagecache.tracing.cursor.PageCursorCounters; import org.neo4j.kernel.api.query.ExecutingQuery; -import org.neo4j.kernel.impl.query.QueryLoggerKernelExtension.QueryLogger; import org.neo4j.kernel.impl.query.clientconnection.ClientConnectionInfo; import org.neo4j.kernel.impl.query.clientconnection.ShellConnectionInfo; import org.neo4j.logging.AssertableLogProvider; @@ -48,10 +47,10 @@ import static org.hamcrest.Matchers.sameInstance; import static org.hamcrest.core.Is.is; import static org.neo4j.helpers.collection.MapUtil.map; -import static org.neo4j.kernel.impl.query.QueryLoggerKernelExtension.Flag.LOG_ALLOCATED_BYTES; -import static org.neo4j.kernel.impl.query.QueryLoggerKernelExtension.Flag.LOG_DETAILED_TIME; -import static org.neo4j.kernel.impl.query.QueryLoggerKernelExtension.Flag.LOG_PAGE_DETAILS; -import static org.neo4j.kernel.impl.query.QueryLoggerKernelExtension.Flag.LOG_PARAMETERS; +import static org.neo4j.kernel.impl.query.QueryLogEntryContent.LOG_ALLOCATED_BYTES; +import static org.neo4j.kernel.impl.query.QueryLogEntryContent.LOG_DETAILED_TIME; +import static org.neo4j.kernel.impl.query.QueryLogEntryContent.LOG_PAGE_DETAILS; +import static org.neo4j.kernel.impl.query.QueryLogEntryContent.LOG_PARAMETERS; import static org.neo4j.logging.AssertableLogProvider.inLog; public class QueryLoggerTest @@ -468,9 +467,9 @@ public void shouldBeAbleToLogPageHitsAndPageFaults() throws Exception containsString( " 17 page hits, 12 page faults - " ) ) ); } - private QueryLogger queryLogger( LogProvider logProvider, QueryLoggerKernelExtension.Flag... flags ) + private QueryLogger queryLogger( LogProvider logProvider, QueryLogEntryContent... flags ) { - EnumSet flagSet = EnumSet.noneOf( QueryLoggerKernelExtension.Flag.class ); + EnumSet flagSet = EnumSet.noneOf( QueryLogEntryContent.class ); Collections.addAll( flagSet, flags ); return new QueryLogger( logProvider.getLog( getClass() ), 10/*ms*/, flagSet ); }