/src/rt/rust_log.cpp

  1/*
  2 * Logging infrastructure that aims to support multi-threading
  3 */
  4
  5
  6#include "rust_log.h"
  7#include "util/array_list.h"
  8#include "rust_util.h"
  9#include "rust_task.h"
 10
 11/**
 12 * Synchronizes access to the underlying logging mechanism.
 13 */
 14static lock_and_signal _log_lock;
 15/**
 16 * Indicates whether we are outputing to the console.
 17 * Protected by _log_lock;
 18 */
 19static bool _log_to_console = true;
 20
 21/*
 22 * Request that console logging be turned on.
 23 */
 24void
 25log_console_on() {
 26    scoped_lock with(_log_lock);
 27    _log_to_console = true;
 28}
 29
 30/*
 31 * Request that console logging be turned off. Can be
 32 * overridden by the environment.
 33 */
 34void
 35log_console_off(rust_env *env) {
 36    scoped_lock with(_log_lock);
 37    if (env->logspec == NULL) {
 38        _log_to_console = false;
 39    }
 40}
 41
 42rust_log::rust_log(rust_sched_loop *sched_loop) :
 43    _sched_loop(sched_loop) {
 44}
 45
 46rust_log::~rust_log() {
 47
 48}
 49
 50const uint16_t
 51hash(uintptr_t ptr) {
 52#   if(ULONG_MAX == 0xFFFFFFFF)
 53    // Robert Jenkins' 32 bit integer hash function
 54    ptr = (ptr + 0x7ed55d16) + (ptr << 12);
 55    ptr = (ptr ^ 0xc761c23c) ^ (ptr >> 19);
 56    ptr = (ptr + 0x165667b1) + (ptr << 5);
 57    ptr = (ptr + 0xd3a2646c) ^ (ptr << 9);
 58    ptr = (ptr + 0xfd7046c5) + (ptr << 3);
 59    ptr = (ptr ^ 0xb55a4f09) ^ (ptr >> 16);
 60#   elif(ULONG_MAX == 0xFFFFFFFFFFFFFFFF)
 61    // "hash64shift()" from http://www.concentric.net/~Ttwang/tech/inthash.htm
 62    ptr = (~ptr) + (ptr << 21); // ptr = (ptr << 21) - ptr - 1;
 63    ptr = ptr ^ (ptr >> 24);
 64    ptr = (ptr + (ptr << 3)) + (ptr << 8); // ptr * 265
 65    ptr = ptr ^ (ptr >> 14);
 66    ptr = (ptr + (ptr << 2)) + (ptr << 4); // ptr * 21
 67    ptr = ptr ^ (ptr >> 28);
 68    ptr = ptr + (ptr << 31);
 69#   else
 70#   error "hash() not defined for this pointer size"
 71#   endif
 72    return (uint16_t) ptr;
 73}
 74
 75char *
 76copy_string(char *dst, const char *src, size_t length) {
 77    return strncpy(dst, src, length) + length;
 78}
 79
 80char *
 81append_string(char *buffer, const char *format, ...) {
 82    if (buffer != NULL && format) {
 83        va_list args;
 84        va_start(args, format);
 85        size_t off = strlen(buffer);
 86        vsnprintf(buffer + off, BUF_BYTES - off, format, args);
 87        va_end(args);
 88    }
 89    return buffer;
 90}
 91
 92void
 93rust_log::log(rust_task* task, uint32_t level, char const *fmt, ...) {
 94    char buf[BUF_BYTES];
 95    va_list args;
 96    va_start(args, fmt);
 97    int formattedbytes = vsnprintf(buf, sizeof(buf), fmt, args);
 98    if( formattedbytes and (unsigned)formattedbytes > BUF_BYTES ){
 99        const char truncatedstr[] = "[...]";
100        memcpy( &buf[BUF_BYTES-sizeof(truncatedstr)],
101                truncatedstr,
102                sizeof(truncatedstr));
103    }
104    trace_ln(task, level, buf);
105    va_end(args);
106}
107
108void
109rust_log::trace_ln(char *prefix, char *message) {
110    char buffer[BUF_BYTES] = "";
111    _log_lock.lock();
112    append_string(buffer, "%s", prefix);
113    append_string(buffer, "%s", message);
114    if (_log_to_console) {
115        fprintf(stderr, "rust: %s\n", buffer);
116        fflush(stderr);
117    }
118    _log_lock.unlock();
119}
120
121void
122rust_log::trace_ln(rust_task *task, uint32_t level, char *message) {
123
124    if (task) {
125        // There is not enough room to be logging on the rust stack
126        assert(!task->on_rust_stack() && "logging on rust stack");
127    }
128
129    // FIXME (#2672): The scheduler and task names used to have meaning,
130    // but they are always equal to 'main' currently
131#if 0
132
133#if defined(__WIN32__)
134    uint32_t thread_id = 0;
135#else
136    uint32_t thread_id = hash((uintptr_t) pthread_self());
137#endif
138
139    char prefix[BUF_BYTES] = "";
140    if (_sched_loop && _sched_loop-.name) {
141        append_string(prefix, "%04" PRIxPTR ":%.10s:",
142                      thread_id, _sched_loop->name);
143    } else {
144        append_string(prefix, "%04" PRIxPTR ":0x%08" PRIxPTR ":",
145                      thread_id, (uintptr_t) _sched_loop);
146    }
147    if (task) {
148        if (task->name) {
149            append_string(prefix, "%.10s:", task->name);
150        } else {
151            append_string(prefix, "0x%08" PRIxPTR ":", (uintptr_t) task);
152        }
153    }
154#else
155    char prefix[BUF_BYTES] = "";
156#endif
157
158    trace_ln(prefix, message);
159}
160
161// Reading log directives and setting log level vars
162
163struct mod_entry {
164    const char* name;
165    uint32_t* state;
166};
167
168struct cratemap {
169    const mod_entry* entries;
170    const cratemap* children[1];
171};
172
173struct log_directive {
174    char* name;
175    size_t level;
176};
177
178const size_t max_log_directives = 255;
179const size_t max_log_level = 255;
180const size_t default_log_level = 0;
181
182// This is a rather ugly parser for strings in the form
183// "crate1,crate2.mod3,crate3.x=1". Log levels are 0-255,
184// with the most likely ones being 0-3 (defined in core::).
185size_t parse_logging_spec(char* spec, log_directive* dirs) {
186    size_t dir = 0;
187    while (dir < max_log_directives && *spec) {
188        char* start = spec;
189        char cur;
190        while (true) {
191            cur = *spec;
192            if (cur == ',' || cur == '=' || cur == '\0') {
193                if (start == spec) {spec++; break;}
194                if (*spec != '\0') {
195                    *spec = '\0';
196                    spec++;
197                }
198                size_t level = max_log_level;
199                if (cur == '=' && *spec != '\0') {
200                    level = *spec - '0';
201                    if (level > max_log_level) level = max_log_level;
202                    if (*spec) ++spec;
203                }
204                dirs[dir].name = start;
205                dirs[dir++].level = level;
206                break;
207            } else {
208                spec++;
209            }
210        }
211    }
212    return dir;
213}
214
215void update_module_map(const mod_entry* map, log_directive* dirs,
216                       size_t n_dirs, size_t *n_matches) {
217    for (const mod_entry* cur = map; cur->name; cur++) {
218        size_t level = default_log_level, longest_match = 0;
219        for (size_t d = 0; d < n_dirs; d++) {
220            if (strstr(cur->name, dirs[d].name) == cur->name &&
221                strlen(dirs[d].name) > longest_match) {
222                longest_match = strlen(dirs[d].name);
223                level = dirs[d].level;
224            }
225        }
226        *cur->state = level;
227        (*n_matches)++;
228    }
229}
230
231void update_crate_map(const cratemap* map, log_directive* dirs,
232                      size_t n_dirs, size_t *n_matches) {
233    // First update log levels for this crate
234    update_module_map(map->entries, dirs, n_dirs, n_matches);
235    // Then recurse on linked crates
236    // FIXME (#2673) this does double work in diamond-shaped deps. could
237    //   keep a set of visited addresses, if it turns out to be actually
238    //   slow
239    for (size_t i = 0; map->children[i]; i++) {
240        update_crate_map(map->children[i], dirs, n_dirs, n_matches);
241    }
242}
243
244void print_crate_log_map(const cratemap* map) {
245    for (const mod_entry* cur = map->entries; cur->name; cur++) {
246        printf("  %s\n", cur->name);
247    }
248    for (size_t i = 0; map->children[i]; i++) {
249        print_crate_log_map(map->children[i]);
250    }
251}
252
253// These are pseudo-modules used to control logging in the runtime.
254
255uint32_t log_rt_mem;
256uint32_t log_rt_box;
257uint32_t log_rt_comm;
258uint32_t log_rt_task;
259uint32_t log_rt_dom;
260uint32_t log_rt_trace;
261uint32_t log_rt_cache;
262uint32_t log_rt_upcall;
263uint32_t log_rt_timer;
264uint32_t log_rt_gc;
265uint32_t log_rt_stdlib;
266uint32_t log_rt_kern;
267uint32_t log_rt_backtrace;
268uint32_t log_rt_callback;
269
270static const mod_entry _rt_module_map[] =
271    {{"::rt::mem", &log_rt_mem},
272     {"::rt::box", &log_rt_box},
273     {"::rt::comm", &log_rt_comm},
274     {"::rt::task", &log_rt_task},
275     {"::rt::dom", &log_rt_dom},
276     {"::rt::trace", &log_rt_trace},
277     {"::rt::cache", &log_rt_cache},
278     {"::rt::upcall", &log_rt_upcall},
279     {"::rt::timer", &log_rt_timer},
280     {"::rt::gc", &log_rt_gc},
281     {"::rt::stdlib", &log_rt_stdlib},
282     {"::rt::kern", &log_rt_kern},
283     {"::rt::backtrace", &log_rt_backtrace},
284     {"::rt::callback", &log_rt_callback},
285     {NULL, NULL}};
286
287void update_log_settings(void* crate_map, char* settings) {
288    char* buffer = NULL;
289    log_directive dirs[256];
290    size_t n_dirs = 0;
291
292    if (settings) {
293
294        if (strcmp(settings, "::help") == 0 ||
295            strcmp(settings, "?") == 0) {
296            printf("\nCrate log map:\n\n");
297            print_crate_log_map((const cratemap*)crate_map);
298            printf("\n");
299            exit(1);
300        }
301
302        size_t buflen = strlen(settings) + 1;
303        buffer = (char*)malloc(buflen);
304        strncpy(buffer, settings, buflen);
305        n_dirs = parse_logging_spec(buffer, &dirs[0]);
306    }
307
308    size_t n_matches = 0;
309    update_module_map(_rt_module_map, &dirs[0], n_dirs, &n_matches);
310    update_crate_map((const cratemap*)crate_map, &dirs[0],
311                     n_dirs, &n_matches);
312
313    if (n_matches < n_dirs) {
314        printf("warning: got %" PRIdPTR " RUST_LOG specs, "
315               "enabled %" PRIdPTR " flags.",
316               (uintptr_t)n_dirs, (uintptr_t)n_matches);
317    }
318
319    free(buffer);
320}
321
322
323//
324// Local Variables:
325// mode: C++
326// fill-column: 78;
327// indent-tabs-mode: nil
328// c-basic-offset: 4
329// buffer-file-coding-system: utf-8-unix
330// compile-command: "make -k -C $RBUILD 2>&1 | sed -e 's/\\/x\\//x:\\//g'";
331// End:
332//