Skip to content

Commit 5ceed3c

Browse files
authored
Merge pull request #187 from SingingBush/feature/logging
#113 use std.experimental.logger
2 parents 74f82af + 111770e commit 5ceed3c

File tree

4 files changed

+148
-0
lines changed

4 files changed

+148
-0
lines changed

.gitignore

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,10 @@ dub.selections.json
2020

2121
# Executable file name when 'dub' is run on linux
2222
mysql-native
23+
integration-tests-phobos/mysql-native_integration-tests-phobos
24+
integration-tests-vibe/mysql-native_integration-tests-vibe
25+
mysql-native-test-unittest
26+
2327
examples/homePage/example
2428

2529
ddoc/packageVersion.ddoc

source/mysql/connection.d

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@ import std.typecons;
1111

1212
import mysql.commands;
1313
import mysql.exceptions;
14+
import mysql.logger;
1415
import mysql.prepared;
1516
import mysql.protocol.comms;
1617
import mysql.protocol.constants;
@@ -387,6 +388,7 @@ package:
387388

388389
static PlainPhobosSocket defaultOpenSocketPhobos(string host, ushort port)
389390
{
391+
logDebug("opening phobos socket %s:%d", host, port);
390392
auto s = new PlainPhobosSocket();
391393
s.connect(new InternetAddress(host, port));
392394
s.setOption(SocketOptionLevel.TCP, SocketOption.TCP_NODELAY, true);
@@ -398,6 +400,7 @@ package:
398400
{
399401
version(Have_vibe_core)
400402
{
403+
logDebug("opening vibe-d socket %s:%d", host, port);
401404
auto s = vibe.core.net.connectTCP(host, port);
402405
s.tcpNoDelay = true;
403406
s.keepAlive = true;

source/mysql/logger.d

Lines changed: 123 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,123 @@
1+
module mysql.logger;
2+
3+
/*
4+
The aliased log functions in this module map to equivelant functions in either vibe.core.log or std.experimental.logger.
5+
For this reason, only log levels common to both are used. The exception to this is logDebug which is uses trace when
6+
using std.experimental.logger, only because it's commonly used and trace/debug/verbose are all similar in use.
7+
Also, I've chosen not to support fatal errors as std.experimental.logger will create an exception if you choose to
8+
log at this level, which is an unhelpful side effect.
9+
10+
See the following table for how they are mapped:
11+
12+
| Our logger | vibe.core.log | LogLevel (std.experimental.logger) |
13+
| --------------- | ------------- | ---------------------------------- |
14+
| logTrace | logTrace | LogLevel.trace |
15+
| N/A | logDebugV | N/A |
16+
| logDebug | logDebug | LogLevel.trace |
17+
| N/A | logDiagnostic | N/A |
18+
| logInfo | logInfo | LogLevel.info |
19+
| logWarn | logWarn | LogLevel.warning |
20+
| logError | logError | LogLevel.error |
21+
| logCritical | logCritical | LogLevel.critical |
22+
| N/A | logFatal | LogLevel.fatal |
23+
24+
*/
25+
version(Have_vibe_core) {
26+
import vibe.core.log;
27+
28+
alias logTrace = vibe.core.log.logTrace;
29+
alias logDebug = vibe.core.log.logDebug;
30+
alias logInfo = vibe.core.log.logInfo;
31+
alias logWarn = vibe.core.log.logWarn;
32+
alias logError = vibe.core.log.logError;
33+
alias logCritical = vibe.core.log.logCritical;
34+
//alias logFatal = vibe.core.log.logFatal;
35+
} else static if(__traits(compiles, (){ import std.experimental.logger; } )) {
36+
import std.experimental.logger;
37+
38+
alias logTrace = std.experimental.logger.tracef;
39+
alias logDebug = std.experimental.logger.tracef; // no debug level in std.experimental.logger but arguably trace/debug/verbose all mean the same
40+
alias logInfo = std.experimental.logger.infof;
41+
alias logWarn = std.experimental.logger.warningf;
42+
alias logError = std.experimental.logger.errorf;
43+
alias logCritical = std.experimental.logger.criticalf;
44+
//alias logFatal = std.experimental.logger.fatalf;
45+
} else static assert(false);
46+
47+
unittest {
48+
version(Have_vibe_core) {
49+
import std.stdio : writeln;
50+
writeln("Running the logger tests using (vibe.core.log)");
51+
// Althouth there are no asserts here, this confirms that the alias compiles ok also the output
52+
// is shown in the terminal when running 'dub test' and the levels logged using different colours.
53+
logTrace("Test that a call to mysql.logger.logTrace maps to vibe.core.log.logTrace");
54+
logDebug("Test that a call to mysql.logger.logDebug maps to vibe.core.log.logDebug");
55+
logInfo("Test that a call to mysql.logger.logInfo maps to vibe.core.log.logInfo");
56+
logWarn("Test that a call to mysql.logger.logWarn maps to vibe.core.log.logWarn");
57+
logError("Test that a call to mysql.logger.logError maps to vibe.core.log.logError");
58+
logCritical("Test that a call to mysql.logger.logCritical maps to vibe.core.log.logCritical");
59+
//logFatal("Test that a call to mysql.logger.logFatal maps to vibe.core.log.logFatal");
60+
} else static if(__traits(compiles, (){ import std.experimental.logger; } )) {
61+
// Checks that when using std.experimental.logger the log entry is correct.
62+
// This test kicks in when commenting out the 'vibe-core' dependency and running 'dub test', although
63+
// not ideal if vibe-core is availble the logging goes through vibe anyway.
64+
// Output can be seen in terminal when running 'dub test'.
65+
import std.experimental.logger : Logger, LogLevel, sharedLog;
66+
import std.stdio : writeln, writefln;
67+
import std.conv : to;
68+
69+
writeln("Running the logger tests using (std.experimental.logger)");
70+
71+
class TestLogger : Logger {
72+
LogLevel logLevel;
73+
string file;
74+
string moduleName;
75+
string msg;
76+
77+
this(LogLevel lv) @safe {
78+
super(lv);
79+
}
80+
81+
override void writeLogMsg(ref LogEntry payload) @trusted {
82+
this.logLevel = payload.logLevel;
83+
this.file = payload.file;
84+
this.moduleName = payload.moduleName;
85+
this.msg = payload.msg;
86+
// now output it to stdio so it can be seen in terminal when testing
87+
writefln(" - testing [%s] %s(%s) : %s", payload.logLevel, payload.file, to!string(payload.line), payload.msg);
88+
}
89+
}
90+
91+
auto logger = new TestLogger(LogLevel.all);
92+
sharedLog = logger;
93+
94+
// check that the various log alias functions get the expected results
95+
logDebug("This is a TRACE message");
96+
assert(logger.logLevel == LogLevel.trace, "expected 'LogLevel.trace' got: " ~ logger.logLevel);
97+
assert(logger.msg == "This is a TRACE message", "The logger should have logged 'This is a TRACE message' but instead was: " ~ logger.msg);
98+
assert(logger.file == "source/mysql/logger.d", "expected 'source/mysql/logger.d' got: " ~ logger.file);
99+
assert(logger.moduleName == "mysql.logger", "expected 'mysql.logger' got: " ~ logger.moduleName);
100+
101+
logDebug("This is a DEBUG message (maps to trace)");
102+
assert(logger.logLevel == LogLevel.trace, "expected 'LogLevel.trace' got: " ~ logger.logLevel);
103+
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);
104+
assert(logger.file == "source/mysql/logger.d", "expected 'source/mysql/logger.d' got: " ~ logger.file);
105+
assert(logger.moduleName == "mysql.logger", "expected 'mysql.logger' got: " ~ logger.moduleName);
106+
107+
logInfo("This is an INFO message");
108+
assert(logger.logLevel == LogLevel.info, "expected 'LogLevel.info' got: " ~ logger.logLevel);
109+
assert(logger.msg == "This is an INFO message", "The logger should have logged 'This is an INFO message' but instead was: " ~ logger.msg);
110+
111+
logWarn("This is a WARNING message");
112+
assert(logger.logLevel == LogLevel.warning, "expected 'LogLevel.warning' got: " ~ logger.logLevel);
113+
assert(logger.msg == "This is a WARNING message", "The logger should have logged 'This is a WARNING message' but instead was: " ~ logger.msg);
114+
115+
logError("This is a ERROR message");
116+
assert(logger.logLevel == LogLevel.error, "expected 'LogLevel.error' got: " ~ logger.logLevel);
117+
assert(logger.msg == "This is a ERROR message", "The logger should have logged 'This is a ERROR message' but instead was: " ~ logger.msg);
118+
119+
logCritical("This is a CRITICAL message");
120+
assert(logger.logLevel == LogLevel.critical, "expected 'LogLevel.critical' got: " ~ logger.logLevel);
121+
assert(logger.msg == "This is a CRITICAL message", "The logger should have logged 'This is a CRITICAL message' but instead was: " ~ logger.msg);
122+
}
123+
}

source/mysql/protocol/comms.d

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,7 @@ import std.variant;
3030

3131
import mysql.connection;
3232
import mysql.exceptions;
33+
import mysql.logger;
3334
import mysql.prepared;
3435
import mysql.result;
3536

@@ -512,9 +513,15 @@ package(mysql) bool execQueryImpl(Connection conn, ExecQueryImplInfo info, out u
512513

513514
// Send data
514515
if(info.isPrepared)
516+
{
517+
logTrace("prepared SQL: %s", info.hStmt);
518+
515519
ProtocolPrepared.sendCommand(conn, info.hStmt, info.psh, info.inParams, info.psa);
520+
}
516521
else
517522
{
523+
logTrace("exec query: %s", info.sql);
524+
518525
conn.sendCmd(CommandType.QUERY, info.sql);
519526
conn._fieldCount = 0;
520527
}
@@ -526,6 +533,11 @@ package(mysql) bool execQueryImpl(Connection conn, ExecQueryImplInfo info, out u
526533
{
527534
conn.resetPacket();
528535
auto okp = OKErrorPacket(packet);
536+
537+
if(okp.error) {
538+
logError("packet error: %s", cast(string) okp.message);
539+
}
540+
529541
enforcePacketOK(okp);
530542
ra = okp.affected;
531543
conn._serverStatus = okp.serverStatus;
@@ -990,6 +1002,11 @@ do
9901002

9911003
auto packet = conn.getPacket();
9921004
auto okp = OKErrorPacket(packet);
1005+
1006+
if(okp.error) {
1007+
logError("Authentication failure: %s", cast(string) okp.message);
1008+
}
1009+
9931010
enforce!MYX(!okp.error, "Authentication failure: " ~ cast(string) okp.message);
9941011
conn._open = Connection.OpenState.authenticated;
9951012
}
@@ -1023,6 +1040,7 @@ package(mysql) PreparedServerInfo performRegister(Connection conn, const(char[])
10231040
{
10241041
auto error = OKErrorPacket(packet);
10251042
enforcePacketOK(error);
1043+
logCritical("Unexpected failure: %s", cast(string) error.message);
10261044
assert(0); // FIXME: what now?
10271045
}
10281046
else

0 commit comments

Comments
 (0)