diff --git a/.gitignore b/.gitignore index a2c732fb..15281e79 100644 --- a/.gitignore +++ b/.gitignore @@ -20,6 +20,10 @@ dub.selections.json # Executable file name when 'dub' is run on linux mysql-native +integration-tests-phobos/mysql-native_integration-tests-phobos +integration-tests-vibe/mysql-native_integration-tests-vibe +mysql-native-test-unittest + examples/homePage/example ddoc/packageVersion.ddoc diff --git a/source/mysql/connection.d b/source/mysql/connection.d index 0086ca0e..46cd5200 100644 --- a/source/mysql/connection.d +++ b/source/mysql/connection.d @@ -11,6 +11,7 @@ import std.typecons; import mysql.commands; import mysql.exceptions; +import mysql.logger; import mysql.prepared; import mysql.protocol.comms; import mysql.protocol.constants; @@ -387,6 +388,7 @@ package: static PlainPhobosSocket defaultOpenSocketPhobos(string host, ushort port) { + logDebug("opening phobos socket %s:%d", host, port); auto s = new PlainPhobosSocket(); s.connect(new InternetAddress(host, port)); s.setOption(SocketOptionLevel.TCP, SocketOption.TCP_NODELAY, true); @@ -398,6 +400,7 @@ package: { version(Have_vibe_core) { + logDebug("opening vibe-d socket %s:%d", host, port); auto s = vibe.core.net.connectTCP(host, port); s.tcpNoDelay = true; s.keepAlive = true; diff --git a/source/mysql/logger.d b/source/mysql/logger.d new file mode 100644 index 00000000..f06a2dbd --- /dev/null +++ b/source/mysql/logger.d @@ -0,0 +1,123 @@ +module mysql.logger; + +/* + The aliased log functions in this module map to equivelant functions in either vibe.core.log or std.experimental.logger. + For this reason, only log levels common to both are used. The exception to this is logDebug which is uses trace when + using std.experimental.logger, only because it's commonly used and trace/debug/verbose are all similar in use. + Also, I've chosen not to support fatal errors as std.experimental.logger will create an exception if you choose to + log at this level, which is an unhelpful side effect. + + See the following table for how they are mapped: + + | Our logger | vibe.core.log | LogLevel (std.experimental.logger) | + | --------------- | ------------- | ---------------------------------- | + | logTrace | logTrace | LogLevel.trace | + | N/A | logDebugV | N/A | + | logDebug | logDebug | LogLevel.trace | + | N/A | logDiagnostic | N/A | + | logInfo | logInfo | LogLevel.info | + | logWarn | logWarn | LogLevel.warning | + | logError | logError | LogLevel.error | + | logCritical | logCritical | LogLevel.critical | + | N/A | logFatal | LogLevel.fatal | + +*/ +version(Have_vibe_core) { + import vibe.core.log; + + alias logTrace = vibe.core.log.logTrace; + alias logDebug = vibe.core.log.logDebug; + alias logInfo = vibe.core.log.logInfo; + alias logWarn = vibe.core.log.logWarn; + alias logError = vibe.core.log.logError; + alias logCritical = vibe.core.log.logCritical; + //alias logFatal = vibe.core.log.logFatal; +} else static if(__traits(compiles, (){ import std.experimental.logger; } )) { + import std.experimental.logger; + + alias logTrace = std.experimental.logger.tracef; + alias logDebug = std.experimental.logger.tracef; // no debug level in std.experimental.logger but arguably trace/debug/verbose all mean the same + alias logInfo = std.experimental.logger.infof; + alias logWarn = std.experimental.logger.warningf; + alias logError = std.experimental.logger.errorf; + alias logCritical = std.experimental.logger.criticalf; + //alias logFatal = std.experimental.logger.fatalf; +} else static assert(false); + +unittest { + version(Have_vibe_core) { + import std.stdio : writeln; + writeln("Running the logger tests using (vibe.core.log)"); + // Althouth there are no asserts here, this confirms that the alias compiles ok also the output + // is shown in the terminal when running 'dub test' and the levels logged using different colours. + logTrace("Test that a call to mysql.logger.logTrace maps to vibe.core.log.logTrace"); + logDebug("Test that a call to mysql.logger.logDebug maps to vibe.core.log.logDebug"); + logInfo("Test that a call to mysql.logger.logInfo maps to vibe.core.log.logInfo"); + logWarn("Test that a call to mysql.logger.logWarn maps to vibe.core.log.logWarn"); + logError("Test that a call to mysql.logger.logError maps to vibe.core.log.logError"); + logCritical("Test that a call to mysql.logger.logCritical maps to vibe.core.log.logCritical"); + //logFatal("Test that a call to mysql.logger.logFatal maps to vibe.core.log.logFatal"); + } else static if(__traits(compiles, (){ import std.experimental.logger; } )) { + // Checks that when using std.experimental.logger the log entry is correct. + // This test kicks in when commenting out the 'vibe-core' dependency and running 'dub test', although + // not ideal if vibe-core is availble the logging goes through vibe anyway. + // Output can be seen in terminal when running 'dub test'. + import std.experimental.logger : Logger, LogLevel, sharedLog; + import std.stdio : writeln, writefln; + import std.conv : to; + + writeln("Running the logger tests using (std.experimental.logger)"); + + class TestLogger : Logger { + LogLevel logLevel; + string file; + string moduleName; + string msg; + + this(LogLevel lv) @safe { + super(lv); + } + + override void writeLogMsg(ref LogEntry payload) @trusted { + this.logLevel = payload.logLevel; + this.file = payload.file; + this.moduleName = payload.moduleName; + this.msg = payload.msg; + // now output it to stdio so it can be seen in terminal when testing + writefln(" - testing [%s] %s(%s) : %s", payload.logLevel, payload.file, to!string(payload.line), payload.msg); + } + } + + auto logger = new TestLogger(LogLevel.all); + sharedLog = logger; + + // check that the various log alias functions get the expected results + logDebug("This is a TRACE message"); + assert(logger.logLevel == LogLevel.trace, "expected 'LogLevel.trace' got: " ~ logger.logLevel); + assert(logger.msg == "This is a TRACE message", "The logger should have logged 'This is a TRACE message' but instead was: " ~ logger.msg); + assert(logger.file == "source/mysql/logger.d", "expected 'source/mysql/logger.d' got: " ~ logger.file); + assert(logger.moduleName == "mysql.logger", "expected 'mysql.logger' got: " ~ logger.moduleName); + + logDebug("This is a DEBUG message (maps to trace)"); + assert(logger.logLevel == LogLevel.trace, "expected 'LogLevel.trace' got: " ~ logger.logLevel); + assert(logger.msg == "This is a DEBUG message (maps to trace)", "The logger should have logged 'This is a DEBUG message (maps to trace)' but instead was: " ~ logger.msg); + assert(logger.file == "source/mysql/logger.d", "expected 'source/mysql/logger.d' got: " ~ logger.file); + assert(logger.moduleName == "mysql.logger", "expected 'mysql.logger' got: " ~ logger.moduleName); + + logInfo("This is an INFO message"); + assert(logger.logLevel == LogLevel.info, "expected 'LogLevel.info' got: " ~ logger.logLevel); + assert(logger.msg == "This is an INFO message", "The logger should have logged 'This is an INFO message' but instead was: " ~ logger.msg); + + logWarn("This is a WARNING message"); + assert(logger.logLevel == LogLevel.warning, "expected 'LogLevel.warning' got: " ~ logger.logLevel); + assert(logger.msg == "This is a WARNING message", "The logger should have logged 'This is a WARNING message' but instead was: " ~ logger.msg); + + logError("This is a ERROR message"); + assert(logger.logLevel == LogLevel.error, "expected 'LogLevel.error' got: " ~ logger.logLevel); + assert(logger.msg == "This is a ERROR message", "The logger should have logged 'This is a ERROR message' but instead was: " ~ logger.msg); + + logCritical("This is a CRITICAL message"); + assert(logger.logLevel == LogLevel.critical, "expected 'LogLevel.critical' got: " ~ logger.logLevel); + assert(logger.msg == "This is a CRITICAL message", "The logger should have logged 'This is a CRITICAL message' but instead was: " ~ logger.msg); + } +} diff --git a/source/mysql/protocol/comms.d b/source/mysql/protocol/comms.d index c4f21d45..bf95c334 100644 --- a/source/mysql/protocol/comms.d +++ b/source/mysql/protocol/comms.d @@ -30,6 +30,7 @@ import std.variant; import mysql.connection; import mysql.exceptions; +import mysql.logger; import mysql.prepared; import mysql.result; @@ -512,9 +513,15 @@ package(mysql) bool execQueryImpl(Connection conn, ExecQueryImplInfo info, out u // Send data if(info.isPrepared) + { + logTrace("prepared SQL: %s", info.hStmt); + ProtocolPrepared.sendCommand(conn, info.hStmt, info.psh, info.inParams, info.psa); + } else { + logTrace("exec query: %s", info.sql); + conn.sendCmd(CommandType.QUERY, info.sql); conn._fieldCount = 0; } @@ -526,6 +533,11 @@ package(mysql) bool execQueryImpl(Connection conn, ExecQueryImplInfo info, out u { conn.resetPacket(); auto okp = OKErrorPacket(packet); + + if(okp.error) { + logError("packet error: %s", cast(string) okp.message); + } + enforcePacketOK(okp); ra = okp.affected; conn._serverStatus = okp.serverStatus; @@ -990,6 +1002,11 @@ do auto packet = conn.getPacket(); auto okp = OKErrorPacket(packet); + + if(okp.error) { + logError("Authentication failure: %s", cast(string) okp.message); + } + enforce!MYX(!okp.error, "Authentication failure: " ~ cast(string) okp.message); conn._open = Connection.OpenState.authenticated; } @@ -1023,6 +1040,7 @@ package(mysql) PreparedServerInfo performRegister(Connection conn, const(char[]) { auto error = OKErrorPacket(packet); enforcePacketOK(error); + logCritical("Unexpected failure: %s", cast(string) error.message); assert(0); // FIXME: what now? } else