1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
|
#include "catch.hpp"
#include "test_helpers.hpp"
#include "duckdb.hpp"
#include "duckdb/main/database.hpp"
#include "duckdb/logging/logger.hpp"
#include "duckdb/main/extension/extension_loader.hpp"
#include "duckdb/main/extension_manager.hpp"
#include "duckdb/function/table_function.hpp"
#include "duckdb/logging/log_storage.hpp"
#include "duckdb/logging/log_manager.hpp"
using namespace duckdb;
using namespace std;
template <class SOURCE, typename FUN>
void LogSimpleCustomType(SOURCE &src, FUN f) {
f("custom_type", src, "log-a-lot: 'simple with type'");
}
template <class SOURCE, typename FUN>
void LogFormatStringCustomType(SOURCE &src, FUN f) {
f("custom_type", src, "log-a-lot: '%s'", "format with type");
}
#define TEST_ALL_LOG_MACROS(LOG_LEVEL, SOURCE, LOG_TYPE) \
DUCKDB_LOG_INTERNAL(SOURCE, "default", LOG_LEVEL, "log-a-lot: 'simple'") \
DUCKDB_LOG_INTERNAL(SOURCE, "default", LOG_LEVEL, "log-a-lot: '%s'", "format") \
DUCKDB_LOG_INTERNAL(SOURCE, "default", LOG_LEVEL, string("log-a-lot: 'string type'")) \
DUCKDB_LOG_INTERNAL(SOURCE, "custom_type", LOG_LEVEL, "log-a-lot: 'simple with type'") \
DUCKDB_LOG_INTERNAL(SOURCE, "custom_type", LOG_LEVEL, "log-a-lot: '%s'", "format with type") \
DUCKDB_LOG_INTERNAL(SOURCE, "custom_type", LOG_LEVEL, string("log-a-lot: 'string type with type'"))
// Tests all Logger function entrypoints at the specified log level with the specified enabled/disabled loggers
void test_logging(const string &minimum_level, const string &enabled_log_types, const string &disabled_log_types) {
DuckDB db(nullptr);
Connection con(db);
duckdb::vector<Value> default_types = {"default", "default"};
duckdb::vector<string> log_levels = {"TRACE", "DEBUG", "INFO", "WARNING", "ERROR", "FATAL"};
auto minimum_level_index = std::find(log_levels.begin(), log_levels.end(), minimum_level) - log_levels.begin();
REQUIRE_NO_FAIL(con.Query("set enable_logging=true;"));
REQUIRE_NO_FAIL(con.Query("set logging_level='" + minimum_level + "';"));
if (!enabled_log_types.empty()) {
REQUIRE_NO_FAIL(con.Query("set enabled_log_types='" + enabled_log_types + "';"));
REQUIRE_NO_FAIL(con.Query("set logging_mode='enable_selected';"));
}
if (!disabled_log_types.empty()) {
REQUIRE_NO_FAIL(con.Query("set disabled_log_types='" + disabled_log_types + "';"));
REQUIRE_NO_FAIL(con.Query("set logging_mode='disable_selected';"));
}
bool level_only = (enabled_log_types.empty() && disabled_log_types.empty());
bool enabled_mode = !enabled_log_types.empty();
bool disabled_mode = !disabled_log_types.empty();
// Log all to global logger
TEST_ALL_LOG_MACROS(LogLevel::LOG_TRACE, *db.instance, DatabaseInstance);
TEST_ALL_LOG_MACROS(LogLevel::LOG_DEBUG, *db.instance, DatabaseInstance);
TEST_ALL_LOG_MACROS(LogLevel::LOG_INFO, *db.instance, DatabaseInstance);
TEST_ALL_LOG_MACROS(LogLevel::LOG_WARNING, *db.instance, DatabaseInstance);
TEST_ALL_LOG_MACROS(LogLevel::LOG_ERROR, *db.instance, DatabaseInstance);
TEST_ALL_LOG_MACROS(LogLevel::LOG_FATAL, *db.instance, DatabaseInstance);
// Log all to client context logger
TEST_ALL_LOG_MACROS(LogLevel::LOG_TRACE, *con.context, ClientContext);
TEST_ALL_LOG_MACROS(LogLevel::LOG_DEBUG, *con.context, ClientContext);
TEST_ALL_LOG_MACROS(LogLevel::LOG_INFO, *con.context, ClientContext);
TEST_ALL_LOG_MACROS(LogLevel::LOG_WARNING, *con.context, ClientContext);
TEST_ALL_LOG_MACROS(LogLevel::LOG_ERROR, *con.context, ClientContext);
TEST_ALL_LOG_MACROS(LogLevel::LOG_FATAL, *con.context, ClientContext);
// Generate expected log messages
duckdb::vector<Value> expected_types;
duckdb::vector<Value> expected_messages;
duckdb::vector<Value> expected_log_levels;
idx_t num_runs = 2;
idx_t num_log_levels = 6;
for (idx_t i = 0; i < num_runs; i++) {
for (idx_t j = minimum_level_index; j < num_log_levels; j++) {
if (level_only ||
(enabled_mode && enabled_log_types.find(default_types[i].ToString()) != enabled_log_types.npos) ||
(disabled_mode && disabled_log_types.find(default_types[i].ToString()) == enabled_log_types.npos)) {
expected_messages.push_back("log-a-lot: 'simple'");
expected_messages.push_back("log-a-lot: 'format'");
expected_messages.push_back("log-a-lot: 'string type'");
expected_types.push_back(default_types[i]);
expected_types.push_back(default_types[i]);
expected_types.push_back(default_types[i]);
expected_log_levels.push_back(Value(log_levels[j]));
expected_log_levels.push_back(Value(log_levels[j]));
expected_log_levels.push_back(Value(log_levels[j]));
}
if (level_only || (enabled_mode && enabled_log_types.find("custom_type") != enabled_log_types.npos) ||
(disabled_mode && disabled_log_types.find("custom_type") == enabled_log_types.npos)) {
expected_messages.push_back("log-a-lot: 'simple with type'");
expected_messages.push_back("log-a-lot: 'format with type'");
expected_messages.push_back("log-a-lot: 'string type with type'");
expected_types.push_back("custom_type");
expected_types.push_back("custom_type");
expected_types.push_back("custom_type");
expected_log_levels.push_back(Value(log_levels[j]));
expected_log_levels.push_back(Value(log_levels[j]));
expected_log_levels.push_back(Value(log_levels[j]));
}
}
}
auto res = con.Query("SELECT type, log_level, message, from duckdb_logs where starts_with(message, 'log-a-lot:')");
REQUIRE(CHECK_COLUMN(res, 0, expected_types));
REQUIRE(CHECK_COLUMN(res, 1, expected_log_levels));
REQUIRE(CHECK_COLUMN(res, 2, expected_messages));
}
// This tests
// - all log levels
// - all combinations of log levels and having either enabled_log_types or disabled_log_types
TEST_CASE("Test logging", "[logging][.]") {
duckdb::vector<string> log_levels = {"TRACE", "DEBUG", "INFO", "WARNING", "ERROR", "FATAL"};
for (const auto &level : log_levels) {
// Test in regular mode without explicitly enabled or disabled loggers
test_logging(level, "", "");
// Test various combinations of enabled and disabled loggers
test_logging(level, "custom_type,default", "");
test_logging(level, "custom_type", "");
test_logging(level, "", "default");
test_logging(level, "", "custom_type,default");
}
}
struct TestLoggingData : public LocalTableFunctionState {
explicit TestLoggingData(ExecutionContext &context_p) : context(context_p) {};
ExecutionContext &context;
};
static duckdb::unique_ptr<LocalTableFunctionState>
TestLoggingInitLocal(ExecutionContext &context, TableFunctionInitInput &input, GlobalTableFunctionState *global_state) {
return make_uniq<TestLoggingData>(context);
}
static duckdb::unique_ptr<FunctionData> TestLoggingBind(ClientContext &context, TableFunctionBindInput &input,
duckdb::vector<LogicalType> &return_types,
duckdb::vector<string> &names) {
names.emplace_back("value");
return_types.emplace_back(LogicalType::INTEGER);
return make_uniq<TableFunctionData>();
}
static void TestLoggingFunction(ClientContext &context, TableFunctionInput &data_p, DataChunk &output) {
auto &local_state = data_p.local_state->Cast<TestLoggingData>();
DUCKDB_LOG_INTERNAL(local_state.context, "duckdb.", LogLevel::LOG_INFO, "thread_logger");
output.SetCardinality(0);
}
// This test the thread context logger
TEST_CASE("Test thread context logger", "[logging][.]") {
DuckDB db(nullptr);
Connection con(db);
duckdb::TableFunction tf("test_thread_logger", {}, TestLoggingFunction, TestLoggingBind, nullptr,
TestLoggingInitLocal);
ExtensionInfo extension_info {};
ExtensionActiveLoad load_info {*db.instance, extension_info, "log_test_extension"};
ExtensionLoader loader {load_info};
loader.RegisterFunction(tf);
REQUIRE_NO_FAIL(con.Query("set enable_logging=true;"));
// Run our dummy table function to call the thread local logger
REQUIRE_NO_FAIL(con.Query("FROM test_thread_logger()"));
auto res = con.Query("SELECT scope, message, from duckdb_logs where starts_with(message, 'thread_logger')");
REQUIRE(CHECK_COLUMN(res, 0, {"THREAD"}));
REQUIRE(CHECK_COLUMN(res, 1, {"thread_logger"}));
}
// Testing pluggable log storage
class MyLogStorage : public LogStorage {
public:
void WriteLogEntry(timestamp_t timestamp, LogLevel level, const string &log_type, const string &log_message,
const RegisteredLoggingContext &context) override {
log_store.insert(log_message);
};
void WriteLogEntries(DataChunk &chunk, const RegisteredLoggingContext &context) override {};
void Flush(LoggingTargetTable table) override {};
void FlushAll() override {};
bool IsEnabled(LoggingTargetTable table) override {
return table == LoggingTargetTable::ALL_LOGS;
}
const string GetStorageName() override {
return "MyLogStorage";
}
unordered_set<string> log_store;
};
TEST_CASE("Test pluggable log storage", "[logging][.]") {
DuckDB db(nullptr);
Connection con(db);
auto my_log_storage = make_shared_ptr<MyLogStorage>();
duckdb::shared_ptr<LogStorage> base_ptr = my_log_storage;
db.instance->GetLogManager().RegisterLogStorage("my_log_storage", base_ptr);
REQUIRE_NO_FAIL(con.Query("set enable_logging=true;"));
REQUIRE_NO_FAIL(con.Query("set logging_storage='my_log_storage';"));
REQUIRE_NO_FAIL(con.Query("select write_log('HELLO, BRO');"));
REQUIRE(my_log_storage->log_store.find("HELLO, BRO") != my_log_storage->log_store.end());
}
struct CorrectLogType : public LogType {
static constexpr const char *NAME = "CorrectLogType";
static constexpr LogLevel LEVEL = LogLevel::LOG_INFO;
// Correctly using the unstructured type constructor for VARCHAR
CorrectLogType() : LogType(NAME, LEVEL) {
}
template <typename... ARGS>
static string ConstructLogMessage(const string &str, ARGS... params) {
return StringUtil::Format(str, params...);
}
};
constexpr LogLevel CorrectLogType::LEVEL;
TEST_CASE("Add LogType with VARCHAR type", "[logging][.]") {
DuckDB db(nullptr);
Connection con(db);
LogManager &log_manager = db.instance->GetLogManager();
REQUIRE_NOTHROW(log_manager.RegisterLogType(make_uniq<CorrectLogType>()));
}
|
