Line data Source code
1 : /*
2 : Copyright 2018-2024, Barcelona Supercomputing Center (BSC), Spain
3 : Copyright 2015-2024, Johannes Gutenberg Universitaet Mainz, Germany
4 :
5 : This software was partially supported by the
6 : EC H2020 funded project NEXTGenIO (Project ID: 671951, www.nextgenio.eu).
7 :
8 : This software was partially supported by the
9 : ADA-FS project under the SPPEXA project funded by the DFG.
10 :
11 : This file is part of GekkoFS' POSIX interface.
12 :
13 : GekkoFS' POSIX interface is free software: you can redistribute it and/or
14 : modify it under the terms of the GNU Lesser General Public License as
15 : published by the Free Software Foundation, either version 3 of the License,
16 : or (at your option) any later version.
17 :
18 : GekkoFS' POSIX interface is distributed in the hope that it will be useful,
19 : but WITHOUT ANY WARRANTY; without even the implied warranty of
20 : MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
21 : GNU Lesser General Public License for more details.
22 :
23 : You should have received a copy of the GNU Lesser General Public License
24 : along with GekkoFS' POSIX interface. If not, see
25 : <https://www.gnu.org/licenses/>.
26 :
27 : SPDX-License-Identifier: LGPL-3.0-or-later
28 : */
29 :
30 : #include <client/logging.hpp>
31 : #include <client/env.hpp>
32 : #include <client/make_array.hpp>
33 : #include <regex>
34 : #include <filesystem>
35 : #include <ctime>
36 :
37 : #ifdef GKFS_ENABLE_LOGGING
38 :
39 : #include <hermes/logging.hpp>
40 :
41 : #endif
42 :
43 : namespace fs = std::filesystem;
44 :
45 : namespace {
46 : enum class split_str_mode {
47 : is_any_of,
48 : is_exactly_of // not used at the moment
49 : }; ///> Mode for string splitter
50 :
51 : /**
52 : * @brief Splits a string by a given delimiter for a given split_mode
53 : * @param input String to be splitted
54 : * @param delimiter split token
55 : * @param split_mode <split_str_node> how the string is split
56 : * @return vector<string> entries for splitted string
57 : */
58 : std::vector<std::string>
59 538 : split_str(const std::string& input, const std::string_view delimiter,
60 : const split_str_mode split_mode) {
61 538 : std::vector<std::string> out{};
62 538 : std::string regex_builder{};
63 538 : if(split_mode == split_str_mode::is_any_of) {
64 538 : regex_builder = fmt::format("[{}]+", delimiter);
65 : } else {
66 0 : regex_builder = delimiter;
67 : }
68 538 : const std::regex line_re(regex_builder,
69 538 : std::regex::ECMAScript | std::regex::optimize);
70 538 : std::copy(
71 1076 : std::sregex_token_iterator(input.begin(), input.end(), line_re, -1),
72 538 : std::sregex_token_iterator(), std::back_inserter(out));
73 1076 : return out;
74 : }
75 : } // namespace
76 :
77 : namespace gkfs::log {
78 :
79 : struct opt_info {
80 : const char name_[32];
81 : const std::size_t length_;
82 : const char help_text_[8][64];
83 : const log_level mask_;
84 : };
85 :
86 : #define STR_AND_LEN(strbuf) strbuf, sizeof(strbuf) - 1
87 :
88 : static const auto constexpr debug_opts = utils::make_array(
89 :
90 : opt_info{STR_AND_LEN("none"), {"don't print any messages"}, log::none},
91 :
92 : #ifdef GKFS_DEBUG_BUILD
93 :
94 : opt_info{STR_AND_LEN("syscalls"),
95 : {"Trace system calls: print the name of each system call,",
96 : "its arguments, and its return value. All system calls are",
97 : "printed after being executed save for those that may not",
98 : "return, such as execve() and execve_at()",
99 : "[ default: off ]"},
100 : log::syscall},
101 :
102 : opt_info{STR_AND_LEN("syscalls_at_entry"),
103 : {"Trace system calls: print the name of each system call",
104 : "and its arguments. All system calls are printed before ",
105 : "being executed and therefore their return values are not",
106 : "available in the log", "[ default: off ]"},
107 : log::syscall_at_entry},
108 :
109 : #endif // !GKFS_DEBUG_BUILD
110 :
111 : opt_info{STR_AND_LEN("info"),
112 : {"Print information messages", "[ default: on ]"},
113 : log::info},
114 :
115 : opt_info{STR_AND_LEN("critical"),
116 : {"Print critical errors", "[ default: on ]"},
117 : log::critical},
118 :
119 : opt_info{STR_AND_LEN("errors"),
120 : {"Print errors", "[ default: on ]"},
121 : log::error},
122 :
123 : opt_info{STR_AND_LEN("warnings"),
124 : {"Print warnings", "[ default: on ]"},
125 : log::warning},
126 :
127 : opt_info{STR_AND_LEN("hermes"),
128 : {"Print messages from Hermes (GekkoFS high-level RPC library)",
129 : "[ default: on ]"},
130 : log::hermes},
131 :
132 : opt_info{STR_AND_LEN("mercury"),
133 : {"Print messages from Mercury (GekkoFS low-level RPC library)",
134 : "[ default: on ]"},
135 : log::mercury},
136 :
137 : opt_info{STR_AND_LEN("trace_reads"),
138 : {"Print extended read information", "[ default: off ]"},
139 : log::trace_reads},
140 :
141 : #ifdef GKFS_DEBUG_BUILD
142 :
143 : opt_info{STR_AND_LEN("debug"),
144 : {"Print debug messages", "[ default: off ]"},
145 : log::debug},
146 :
147 : opt_info{STR_AND_LEN("most"),
148 : {"All previous options except 'syscalls_at_entry' combined."},
149 : log::most},
150 :
151 : #endif // !GKFS_DEBUG_BUILD
152 :
153 : opt_info{STR_AND_LEN("all"),
154 : {"All previous options combined."},
155 : log::all},
156 :
157 : opt_info{STR_AND_LEN("help"),
158 : {"Print this help message and exit."},
159 : log::help});
160 :
161 : static const auto constexpr max_debug_opt_length =
162 : sizeof("syscalls_at_entry") - 1;
163 :
164 : static const auto constexpr max_help_text_rows =
165 : sizeof(debug_opts[0].help_text_) / sizeof(debug_opts[0].help_text_[0]);
166 :
167 : /**
168 : * process_log_options -- process the string given as parameter to determine
169 : * which debugging options are enabled and return a
170 : * log_level describing them
171 : */
172 : log_level
173 269 : process_log_options(const std::string gkfs_debug) {
174 :
175 : #ifndef GKFS_ENABLE_LOGGING
176 :
177 : (void) gkfs_debug;
178 : logger::log_message(stdout, "warning: logging options ignored: "
179 : "logging support was disabled in this build");
180 : return log::none;
181 :
182 : #endif // ! GKFS_ENABLE_LOGGING
183 269 : log_level dm = log::none;
184 :
185 : // skip separating white spaces and commas
186 538 : auto tokens = ::split_str(gkfs_debug, " ,", ::split_str_mode::is_any_of);
187 :
188 538 : for(const auto& t : tokens) {
189 :
190 3497 : bool is_known = false;
191 :
192 3497 : for(const auto& opt : debug_opts) {
193 : // none disables any future and previous flags observed
194 3497 : if(t == "none") {
195 0 : return log::none;
196 : }
197 :
198 3497 : if(t == opt.name_) {
199 269 : dm |= opt.mask_;
200 269 : is_known = true;
201 269 : break;
202 : }
203 : }
204 :
205 269 : if(!is_known) {
206 0 : logger::log_message(stdout,
207 : "warning: logging option '{}' unknown; "
208 : "try {}=help",
209 : t, gkfs::env::LOG);
210 : }
211 : }
212 :
213 269 : if(!!(dm & log::help)) {
214 0 : logger::log_message(stdout,
215 : "Valid options for the {} "
216 : "environment variable are:\n",
217 : gkfs::env::LOG);
218 :
219 :
220 0 : for(const auto& opt : debug_opts) {
221 0 : const auto padding = max_debug_opt_length - opt.length_ + 2;
222 :
223 0 : logger::log_message(stdout, " {}{:>{}}{}", opt.name_, "", padding,
224 0 : opt.help_text_[0]);
225 :
226 0 : for(auto i = 1lu; i < max_help_text_rows; ++i) {
227 0 : if(opt.help_text_[i][0] != 0) {
228 0 : logger::log_message(stdout, " {:>{}}{}", "",
229 0 : max_debug_opt_length + 2,
230 0 : opt.help_text_[i]);
231 : }
232 : }
233 :
234 0 : logger::log_message(stdout, "");
235 : }
236 :
237 0 : logger::log_message(stdout,
238 : "\n"
239 : "To direct the logging output into a file "
240 : "instead of standard output\n"
241 : "a filename can be specified using the "
242 : "{} environment variable.",
243 : gkfs::env::LOG_OUTPUT);
244 0 : ::_exit(0);
245 : }
246 :
247 : return dm;
248 : }
249 :
250 : #ifdef GKFS_DEBUG_BUILD
251 :
252 : std::bitset<512>
253 269 : process_log_filter(const std::string& log_filter) {
254 269 : std::bitset<512> filtered_syscalls;
255 :
256 269 : if(log_filter.empty()) {
257 : return filtered_syscalls;
258 : }
259 :
260 : // skip separating white spaces and commas
261 269 : auto tokens = ::split_str(log_filter, " ,", ::split_str_mode::is_any_of);
262 :
263 807 : for(const auto& t : tokens) {
264 538 : const auto sc = syscall::lookup_by_name(t);
265 :
266 538 : if(std::strcmp(sc.name(), "unknown_syscall") == 0) {
267 0 : logger::log_message(stdout,
268 : "warning: system call '{}' unknown; "
269 : "will not filter",
270 : t);
271 0 : continue;
272 : }
273 :
274 538 : filtered_syscalls.set(sc.number());
275 : }
276 :
277 269 : return filtered_syscalls;
278 : }
279 :
280 : #endif // GKFS_DEBUG_BUILD
281 :
282 269 : logger::logger(const std::string& opts, const std::string& path,
283 : bool log_per_process, bool trunc
284 : #ifdef GKFS_DEBUG_BUILD
285 : ,
286 : const std::string& filter, int verbosity
287 : #endif
288 269 : ) {
289 :
290 : /* use stderr by default */
291 269 : log_fd_ = 2;
292 269 : log_process_id_ = ::syscall_no_intercept(SYS_gettid);
293 269 : log_mask_ = process_log_options(opts);
294 :
295 : #ifdef GKFS_DEBUG_BUILD
296 269 : filtered_syscalls_ = process_log_filter(filter);
297 269 : debug_verbosity_ = verbosity;
298 : #endif
299 :
300 269 : if(!path.empty()) {
301 269 : int flags = O_CREAT | O_RDWR | O_APPEND | O_TRUNC;
302 :
303 269 : if(!trunc) {
304 269 : flags &= ~O_TRUNC;
305 : }
306 :
307 538 : std::string file_path = path;
308 269 : if(log_per_process) {
309 0 : if(fs::is_regular_file(file_path) && fs::exists(file_path)) {
310 0 : fs::remove(file_path);
311 : }
312 0 : fs::create_directories(path);
313 0 : file_path = fmt::format("{}/{}", path, log_process_id_);
314 : }
315 :
316 : // we use ::open() here rather than ::syscall_no_intercept(SYS_open)
317 : // because we want the call to be intercepted by our hooks, which
318 : // allows us to categorize the resulting fd as 'internal' and
319 : // relocate it to our private range
320 269 : int fd = ::open(file_path.c_str(), flags, 0600);
321 :
322 269 : if(fd == -1) {
323 0 : log(gkfs::log::error, __func__, __LINE__,
324 : "Failed to open log "
325 : "file '{}'. Logging will fall back to stderr",
326 : path);
327 0 : return;
328 : }
329 :
330 269 : log_fd_ = fd;
331 : }
332 :
333 : #ifdef GKFS_ENABLE_LOGGING
334 269 : const auto log_hermes_message =
335 85 : [](const std::string& msg, hermes::log::level l, int severity,
336 : const std::string& file, const std::string& func, int lineno) {
337 170 : const auto name = [](hermes::log::level l, int severity) {
338 85 : using namespace std::string_literals;
339 :
340 85 : switch(l) {
341 0 : case hermes::log::info:
342 0 : return "info"s;
343 0 : case hermes::log::warning:
344 0 : return "warning"s;
345 85 : case hermes::log::error:
346 85 : return "error"s;
347 0 : case hermes::log::fatal:
348 0 : return "fatal"s;
349 0 : case hermes::log::mercury:
350 0 : return "mercury"s;
351 0 : default:
352 0 : return "unknown"s;
353 : }
354 : };
355 :
356 170 : LOG(HERMES, "[{}] {}", name(l, severity), msg);
357 85 : };
358 :
359 : #ifdef GKFS_DEBUG_BUILD
360 269 : const auto log_hermes_debug_message =
361 72676 : [this](const std::string& msg, hermes::log::level l, int severity,
362 : const std::string& file, const std::string& func,
363 72676 : int lineno) {
364 72676 : if(severity > debug_verbosity_) {
365 : return;
366 : }
367 :
368 38718 : LOG(HERMES, "[debug{}] <{}():{}> {}",
369 : (severity == 0 ? "" : std::to_string(severity + 1)), func,
370 72676 : lineno, msg);
371 269 : };
372 : #endif // GKFS_DEBUG_BUILD
373 :
374 269 : const auto log_hg_message = [](const std::string& msg, hermes::log::level l,
375 : int severity, const std::string& file,
376 : const std::string& func, int lineno) {
377 0 : (void) l;
378 :
379 : // mercury message might contain one or more sub-messages
380 : // separated by '\n'
381 0 : auto sub_msgs = ::split_str(msg, "\n", ::split_str_mode::is_any_of);
382 :
383 0 : for(const auto& m : sub_msgs) {
384 0 : if(!m.empty()) {
385 0 : LOG(MERCURY, "{}", m);
386 : }
387 : }
388 0 : };
389 :
390 : // register log callbacks into hermes so that we can manage
391 : // both its and mercury's log messages
392 269 : hermes::log::logger::register_callback(hermes::log::info,
393 : log_hermes_message);
394 269 : hermes::log::logger::register_callback(hermes::log::warning,
395 : log_hermes_message);
396 269 : hermes::log::logger::register_callback(hermes::log::error,
397 : log_hermes_message);
398 269 : hermes::log::logger::register_callback(hermes::log::fatal,
399 : log_hermes_message);
400 : #ifdef GKFS_DEBUG_BUILD
401 269 : hermes::log::logger::register_callback(hermes::log::debug,
402 : log_hermes_debug_message);
403 : #endif
404 538 : hermes::log::logger::register_callback(hermes::log::mercury,
405 : log_hg_message);
406 :
407 : #endif // GKFS_ENABLE_LOGGING
408 : }
409 :
410 538 : logger::~logger() {
411 269 : log_fd_ = ::syscall_no_intercept(SYS_close, log_fd_);
412 269 : }
413 :
414 : void
415 29083781 : logger::log_syscall(syscall::info info, const long syscall_number,
416 : const long args[6], std::optional<long> result) {
417 :
418 :
419 29083781 : const bool log_syscall_entry = !!(log::syscall_at_entry & log_mask_);
420 29083781 : const bool log_syscall_result = !!(log::syscall & log_mask_);
421 :
422 : // log the syscall if and only if logging for syscalls is enabled
423 29083781 : if(!log_syscall_entry && !log_syscall_result) {
424 27812633 : return;
425 : }
426 :
427 : #ifdef GKFS_DEBUG_BUILD
428 29083778 : if(filtered_syscalls_[syscall_number]) {
429 : return;
430 : }
431 : #endif
432 :
433 : // log the syscall even if we don't have information on it, since it may
434 : // be important to the user (we assume that the syscall has completed
435 : // though)
436 1271148 : if(info == syscall::no_info) {
437 0 : goto print_syscall;
438 : }
439 :
440 : // log the syscall entry if the syscall may not return (e.g. execve) or
441 : // if we are sure that it won't ever return (e.g. exit), even if
442 : // log::syscall_at_entry is disabled
443 2542289 : if(syscall::may_not_return(syscall_number) ||
444 1271148 : syscall::never_returns(syscall_number)) {
445 842 : goto print_syscall;
446 : }
447 :
448 1270299 : if(log_syscall_entry && syscall::execution_is_pending(info)) {
449 634560 : goto print_syscall;
450 : }
451 :
452 635739 : if(log_syscall_result && !syscall::execution_is_pending(info)) {
453 635739 : goto print_syscall;
454 : }
455 :
456 : return;
457 :
458 1271141 : print_syscall:
459 :
460 2542380 : fmt::basic_memory_buffer<char, max_buffer_size> buffer;
461 :
462 1271141 : detail::format_timestamp_to(buffer);
463 1271136 : detail::format_syscall_info_to(buffer, info);
464 :
465 1271164 : if(result) {
466 635730 : syscall::decode(buffer, syscall_number, args, *result);
467 : } else {
468 635434 : syscall::decode(buffer, syscall_number, args);
469 : }
470 :
471 1271175 : fmt::format_to(std::back_inserter(buffer), "\n");
472 :
473 1270386 : ::syscall_no_intercept(SYS_write, log_fd_, buffer.data(), buffer.size());
474 : }
475 :
476 : } // namespace gkfs::log
|