From 1b6fa7eade4b1f57577d5a4dc005927dd67c9b33 Mon Sep 17 00:00:00 2001 From: Francesco Lavra Date: Fri, 15 Nov 2024 12:10:51 +0100 Subject: [PATCH 1/5] tracelog: remove reference to fs_status Commit 721d2b972da63e4dbc86c8ac5c6382e561cf71cc removed the fs_status enum and the string_from_fs_status() function. Adapt the tracelog code to use standard error numbers. --- src/kernel/tracelog.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/kernel/tracelog.c b/src/kernel/tracelog.c index 7e8219f18..99270969c 100644 --- a/src/kernel/tracelog.c +++ b/src/kernel/tracelog.c @@ -632,11 +632,11 @@ static void init_tracelog_file_writer(value v) } filesystem fs = get_root_fs(); tuple root = filesystem_getroot(fs); - fs_status s = filesystem_get_node(&fs, fs->get_inode(fs, root), + int s = filesystem_get_node(&fs, fs->get_inode(fs, root), buffer_to_sstring((buffer)v), true, true, false, false, &file, &fsf); - if (s != FS_STATUS_OK) { - msg_err("failed to open tracelog file: %s\n", string_from_fs_status(s)); + if (s < 0) { + msg_err("failed to open tracelog file: %s\n", string_from_errno(-s)); return; } filesystem_put_node(fs, file); From 273d9fbf526a0fedf69d22599fda5080c8bb8fe5 Mon Sep 17 00:00:00 2001 From: Francesco Lavra Date: Fri, 15 Nov 2024 13:08:40 +0100 Subject: [PATCH 2/5] Network socket: avoid unneeded checks on socket type When a network socket is created via the socket() syscall, the supplied type is checked against supported types, so that it is not possible to create a socket with a non-supported type; therefore, there is no need to check for non-supported types in the socket callbacks. --- src/net/netsyscall.c | 23 ++++------------------- 1 file changed, 4 insertions(+), 19 deletions(-) diff --git a/src/net/netsyscall.c b/src/net/netsyscall.c index c934ffe21..a66f2ccc8 100755 --- a/src/net/netsyscall.c +++ b/src/net/netsyscall.c @@ -868,11 +868,8 @@ static sysreturn socket_write_internal(struct sock *sock, void *source, struct i blockq_action ba = closure_from_context(ctx, socket_write_tcp_bh, s, source, iov, length, flags, completion); return blockq_check(sock->txbq, ba, bh); - } else if (sock->type == SOCK_DGRAM) { - rv = socket_write_udp(s, source, iov, length, dest_addr, addrlen); } else { - msg_err("socket type %d unsupported\n", sock->type); - rv = -EINVAL; + rv = socket_write_udp(s, source, iov, length, dest_addr, addrlen); } net_debug("completed\n"); out: @@ -1512,17 +1509,13 @@ static sysreturn netsock_bind(struct sock *sock, struct sockaddr *addr, } net_debug("calling tcp_bind, pcb %p, port %d\n", s->info.tcp.lw, port); err = tcp_bind(s->info.tcp.lw, &ipaddr, port); - } else if (sock->type == SOCK_DGRAM) { + } else { if (s->info.udp.lw->local_port != 0) { ret = -EINVAL; /* already bound */ goto unlock_out; } net_debug("calling udp_bind, pcb %p, port %d\n", s->info.udp.lw, port); err = udp_bind(s->info.udp.lw, &ipaddr, port); - } else { - msg_warn("unsupported socket type %d\n", s->sock.type); - ret = -EINVAL; - goto unlock_out; } ret = lwip_to_errno(err); unlock_out: @@ -1715,12 +1708,9 @@ static sysreturn netsock_connect(struct sock *sock, struct sockaddr *addr, } else { ret = connect_tcp(s, &ipaddr, port); } - } else if (s->sock.type == SOCK_DGRAM) { + } else { /* Set remote endpoint */ ret = lwip_to_errno(udp_connect(s->info.udp.lw, &ipaddr, port)); - } else { - msg_err("can't connect on socket type %d\n", s->sock.type); - ret = -EINVAL; } netsock_unlock(s); out: @@ -2322,18 +2312,13 @@ static sysreturn netsock_getsockname(struct sock *sock, struct sockaddr *addr, s port = 0; ip_addr = (ip_addr_t *)IP_ADDR_ANY; } - } else if (s->sock.type == SOCK_DGRAM) { + } else { netsock_lock(s); port = s->info.udp.lw->local_port; ip_addr = &s->info.udp.lw->local_ip; - } else { - msg_warn("not supported for socket type %d\n", s->sock.type); - rv = -EINVAL; - goto unlock_out; } addrport_to_sockaddr(s->sock.domain, ip_addr, port, addr, addrlen); rv = 0; - unlock_out: if (s->sock.type == SOCK_STREAM) { if (tcp_lw) netsock_tcp_put(tcp_lw); From c5865e2be19e2807749136afedfbb1a8a82eb356 Mon Sep 17 00:00:00 2001 From: Francesco Lavra Date: Fri, 15 Nov 2024 13:34:34 +0100 Subject: [PATCH 3/5] Unix standard files: fix check for allocation errors The unix file cache is an objcache, thus it returns INVALID_ADDRESS on allocation failure. --- src/unix/unix.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/unix/unix.c b/src/unix/unix.c index 7875c3b83..ee90d5876 100644 --- a/src/unix/unix.c +++ b/src/unix/unix.c @@ -442,7 +442,7 @@ static boolean create_stdfiles(unix_heaps uh, process p) file in = unix_cache_alloc(uh, file); file out = unix_cache_alloc(uh, file); file err = unix_cache_alloc(uh, file); - if (!in || !out || !err) { + if ((in == INVALID_ADDRESS) || (out == INVALID_ADDRESS) || (err == INVALID_ADDRESS)) { msg_err("failed to allocate files\n"); return false; } From 9caf262316c31c37e638a806f95f5c7c187bc70a Mon Sep 17 00:00:00 2001 From: Francesco Lavra Date: Fri, 15 Nov 2024 19:44:08 +0100 Subject: [PATCH 4/5] mkfs translate(): remove unused status_handler parameter --- tools/mkfs.c | 21 +++++++-------------- 1 file changed, 7 insertions(+), 14 deletions(-) diff --git a/tools/mkfs.c b/tools/mkfs.c index 2eec18733..b6200e9b0 100644 --- a/tools/mkfs.c +++ b/tools/mkfs.c @@ -291,12 +291,6 @@ closure_function(2, 1, void, bwrite, apply(req->completion, STATUS_OK); } -closure_func_basic(status_handler, void, err, - status s) -{ - rprintf("reported error\n"); -} - static buffer get_file_contents(heap h, const char *target_root, value v) { value path = table_find((table)v, sym(host)); @@ -311,10 +305,10 @@ static buffer get_file_contents(heap h, const char *target_root, value v) } static value translate(heap h, vector worklist, - const char *target_root, filesystem fs, value v, status_handler sh); + const char *target_root, filesystem fs, value v); -closure_function(6, 2, boolean, translate_each, - heap, h, vector, worklist, const char *, target_root, filesystem, fs, status_handler, sh, tuple, out, +closure_function(5, 2, boolean, translate_each, + heap, h, vector, worklist, const char *, target_root, filesystem, fs, tuple, out, value k, value child) { assert(is_symbol(k)); @@ -322,7 +316,7 @@ closure_function(6, 2, boolean, translate_each, vector_push(bound(worklist), build_vector(bound(h), bound(out), child)); } else { set(bound(out), k, translate(bound(h), bound(worklist), bound(target_root), - bound(fs), child, bound(sh))); + bound(fs), child)); } return true; } @@ -330,11 +324,11 @@ closure_function(6, 2, boolean, translate_each, // dont really like the file/tuple duality, but we need to get something running today, // so push all the bodies onto a worklist static value translate(heap h, vector worklist, - const char *target_root, filesystem fs, value v, status_handler sh) + const char *target_root, filesystem fs, value v) { if (is_tuple(v)) { tuple out = allocate_tuple(); - iterate((tuple)v, stack_closure(translate_each, h, worklist, target_root, fs, sh, out)); + iterate((tuple)v, stack_closure(translate_each, h, worklist, target_root, fs, out)); return out; } return v; @@ -362,8 +356,7 @@ closure_function(4, 2, void, fsc, heap h = bound(h); vector worklist = allocate_vector(h, 10); - tuple md = translate(h, worklist, bound(target_root), fs, root, - closure_func(h, status_handler, err)); + tuple md = translate(h, worklist, bound(target_root), fs, root); buffer b = allocate_buffer(transient, 64); u8 uuid[UUID_LEN]; From f695ae1d4d02c901b2ffee8d7124b0d1bd1bf28f Mon Sep 17 00:00:00 2001 From: Francesco Lavra Date: Fri, 15 Nov 2024 19:52:17 +0100 Subject: [PATCH 5/5] Logging: add user-adjustable log levels ("err", "warn", "info") The log_printf() function now takes an enum log_level parameter, and prints the message to the console if the supplied level is lower than or equal than the configured kernel log level (which can be set via the "log_level" manifest option). The default log level is "err". The msg_{err,warn,info} macros have been repurposed so that in kernel code they expand to log_printf() function calls; calls to these macros have been modified so that the format string starts with a sensible prefix; the trailing newline is added by log_printf(), thus it has been removed from the macro invocations. Some rprintf() and thread_log() calls have been converted to use the msg_{print,err,warn,info} macros. --- klib/aws.c | 26 +++++----- klib/azure.c | 10 ++-- klib/azure_diagnostics.c | 28 +++++------ klib/cloud_azure.c | 24 ++++----- klib/cloud_init.c | 24 ++++----- klib/cloudwatch.c | 50 +++++++++---------- klib/digitalocean.c | 12 ++--- klib/firewall.c | 26 +++++----- klib/gcp.c | 20 ++++---- klib/mbedtls.c | 6 +-- klib/ntp.c | 48 +++++++++--------- klib/radar.c | 16 +++--- klib/shmem.c | 2 +- klib/strace.c | 2 +- klib/syslog.c | 30 +++++------ klib/test/lock.c | 12 ++--- klib/tmpfs.c | 2 +- klib/tun.c | 8 +-- platform/pc/pci.c | 6 +-- platform/pc/service.c | 2 +- platform/virt/service.c | 2 +- src/aarch64/interrupt.c | 2 +- src/aarch64/rtc.c | 2 +- src/boot/elf.c | 2 +- src/boot/uefi.c | 8 +-- src/drivers/acpi.c | 22 ++++----- src/drivers/ata.c | 4 +- src/drivers/console.c | 6 +-- src/drivers/gve.c | 14 +++--- src/drivers/netconsole.c | 10 ++-- src/drivers/nvme.c | 52 ++++++++++---------- src/fs/9p.c | 2 +- src/fs/fs.c | 4 +- src/fs/tfs.c | 8 +-- src/fs/tlog.c | 6 +-- src/gdb/gdbstub.c | 6 +-- src/gdb/gdbutil.c | 4 +- src/http/http.c | 2 +- src/hyperv/netvsc/netvsc.c | 4 +- src/hyperv/storvsc/storvsc.c | 4 +- src/hyperv/utilities/vmbus_shutdown.c | 2 +- src/hyperv/vmbus/hyperv.c | 2 +- src/hyperv/vmbus/vmbus_xact.c | 6 +-- src/kernel/elf.c | 12 ++--- src/kernel/init.c | 17 ++++--- src/kernel/klib.c | 2 +- src/kernel/kvm_platform.c | 4 +- src/kernel/lockstats.c | 10 ++-- src/kernel/log.c | 32 ++++++++++++ src/kernel/log.h | 7 +++ src/kernel/ltrace.c | 2 +- src/kernel/management_telnet.c | 2 +- src/kernel/page.c | 4 +- src/kernel/page_backed_heap.c | 4 +- src/kernel/pagecache.c | 6 +-- src/kernel/pci.c | 4 +- src/kernel/stage3.c | 5 +- src/kernel/storage.c | 10 ++-- src/kernel/symtab.c | 6 +-- src/kernel/tracelog.c | 27 +++++----- src/net/direct.c | 10 ++-- src/net/lwipopts.h | 4 +- src/net/net.c | 43 +++++++--------- src/net/netsyscall.c | 43 ++++++++-------- src/riscv64/interrupt.c | 6 +-- src/riscv64/kernel_machine.c | 2 +- src/runtime/bitmap.c | 4 +- src/runtime/clock.h | 3 +- src/runtime/format.c | 19 +------ src/runtime/format.h | 3 -- src/runtime/heap/freelist.c | 1 - src/runtime/heap/id.c | 14 +++--- src/runtime/heap/mcache.c | 6 +-- src/runtime/heap/objcache.c | 70 +++++++++++++------------- src/runtime/range.c | 2 +- src/runtime/runtime.h | 27 +++++++--- src/runtime/tuple.c | 4 +- src/unix/eventfd.c | 8 +-- src/unix/exec.c | 6 +-- src/unix/ftrace.c | 36 +++++++------- src/unix/futex.c | 15 ++---- src/unix/mmap.c | 26 +++++----- src/unix/netlink.c | 12 ++--- src/unix/pipe.c | 14 +++--- src/unix/poll.c | 2 +- src/unix/signal.c | 11 ++--- src/unix/socket.c | 10 ++-- src/unix/socket.h | 4 +- src/unix/special.c | 2 +- src/unix/syscall.c | 17 ++++--- src/unix/thread.c | 4 +- src/unix/timer.c | 6 +-- src/unix/unix.c | 12 ++--- src/unix/unix_clock.c | 2 +- src/unix_process/socket_user.c | 4 +- src/virtio/virtio_9p.c | 6 +-- src/virtio/virtio_balloon.c | 4 +- src/virtio/virtio_mmio.c | 4 +- src/virtio/virtio_net.c | 14 +++--- src/virtio/virtio_rng.c | 2 +- src/virtio/virtio_scsi.c | 10 ++-- src/virtio/virtio_socket.c | 6 +-- src/virtio/virtio_storage.c | 2 +- src/vmware/pvscsi.c | 4 +- src/vmware/vmxnet3_net.c | 2 +- src/x86_64/hpet.c | 4 +- src/x86_64/interrupt.c | 2 +- src/xen/xen.c | 50 +++++++++---------- src/xen/xenblk.c | 24 ++++----- src/xen/xennet.c | 9 ++-- test/runtime/mmap.c | 4 +- test/unit/bitmap_test.c | 42 ++++++++-------- test/unit/buffer_test.c | 4 +- test/unit/id_heap_test.c | 69 +++++++++++++------------- test/unit/network_test.c | 2 +- test/unit/objcache_test.c | 24 ++++----- test/unit/parser_test.c | 7 +-- test/unit/pqueue_test.c | 2 +- test/unit/random_test.c | 16 +++--- test/unit/range_test.c | 15 +++--- test/unit/rbtree_test.c | 38 +++++++------- test/unit/table_test.c | 71 ++++++++++++++------------- test/unit/tuple_test.c | 4 +- tools/dump.c | 2 +- tools/mkfs.c | 8 +-- tools/tfs-fuse.c | 2 +- 126 files changed, 809 insertions(+), 778 deletions(-) diff --git a/klib/aws.c b/klib/aws.c index 66ac4024b..5a0f169a2 100644 --- a/klib/aws.c +++ b/klib/aws.c @@ -42,12 +42,12 @@ closure_function(5, 1, boolean, aws_metadata_in, heap h = bound(h); value_handler vh = closure(h, aws_metadata_recv, handler, &bound(done)); if (vh == INVALID_ADDRESS) { - msg_err("failed to allocate value handler\n"); + msg_err("%s: failed to allocate value handler", func_ss); goto error; } bound(parser) = allocate_http_parser(h, vh); if (bound(parser) == INVALID_ADDRESS) { - msg_err("failed to allocate HTTP parser\n"); + msg_err("%s: failed to allocate HTTP parser", func_ss); deallocate_closure(vh); goto error; } @@ -61,7 +61,7 @@ closure_function(5, 1, boolean, aws_metadata_in, return false; } } else { - msg_err("failed to parse HTTP response: %v\n", s); + msg_err("%s: failed to parse HTTP response: %v", func_ss, s); timm_dealloc(s); } } else { /* connection closed */ @@ -84,19 +84,19 @@ closure_function(3, 1, input_buffer_handler, aws_metadata_ch, heap h = bound(h); buffer_handler handler = bound(handler); if (!out) { - msg_err("failed to connect to server\n"); + msg_err("%s: failed to connect to server", func_ss); goto error; } tuple req = allocate_tuple(); if (req == INVALID_ADDRESS) { - msg_err("failed to allocate request\n"); + msg_err("%s: failed to allocate request", func_ss); goto error; } set(req, sym(url), alloca_wrap_sstring(bound(uri))); status s = http_request(h, out, HTTP_REQUEST_METHOD_GET, req, 0); deallocate_value(req); if (!is_ok(s)) { - msg_err("failed to send HTTP request: %v\n", s); + msg_err("%s: failed to send HTTP request: %v", func_ss, s); timm_dealloc(s); goto error; } @@ -127,10 +127,10 @@ void aws_metadata_get(heap h, sstring uri, buffer_handler handler) status s = direct_connect(h, &md_server, 80, ch); if (is_ok(s)) return; - msg_err("failed to connect to server: %v\n", s); + msg_err("%s: failed to connect to server: %v", func_ss, s); timm_dealloc(s); } else { - msg_err("failed to allocate closure\n"); + msg_err("%s: failed to allocate closure", func_ss); } apply(handler, 0); } @@ -157,7 +157,7 @@ static boolean aws_cred_parse_item(buffer data, sstring name, buffer value) data->start = 0; /* rewind buffer start, so that it can be re-used to parse other items */ return true; error: - msg_err("parsing of %s failed (%b)\n", name, data); + msg_err("%s: parsing of %s failed (%b)", func_ss, name, data); return false; } @@ -190,13 +190,13 @@ closure_function(2, 1, status, aws_iam_role_get, aws_cred_handler handler = bound(handler); closure_finish(); if (!data || (buffer_length(data) == 0)) { - msg_err("no IAM role associated to instance\n"); + msg_err("%s: no role associated to instance", func_ss); goto error; } buffer uri = wrap_string_cstring(AWS_CRED_URI); push_u8(uri, '/'); if (!push_buffer(uri, data)) { - msg_err("failed to build URI\n"); + msg_err("%s: failed to build URI", func_ss); deallocate_buffer(uri); goto error; } @@ -205,7 +205,7 @@ closure_function(2, 1, status, aws_iam_role_get, aws_metadata_get(h, buffer_to_sstring(uri), cred_parser); return STATUS_OK; } else { - msg_err("failed to allocate closure\n"); + msg_err("%s: failed to allocate closure", func_ss); deallocate_buffer(uri); } error: @@ -219,7 +219,7 @@ void aws_cred_get(heap h, aws_cred_handler handler) if (role_handler != INVALID_ADDRESS) { aws_metadata_get(h, ss(AWS_CRED_URI), role_handler); } else { - msg_err("failed to allocate closure\n"); + msg_err("%s: failed to allocate closure", func_ss); apply(handler, 0); } } diff --git a/klib/azure.c b/klib/azure.c index 70918e3a4..35056042f 100644 --- a/klib/azure.c +++ b/klib/azure.c @@ -53,7 +53,7 @@ closure_function(1, 1, void, azure_instance_md_parsed, closure_func_basic(parse_error, void, azure_instance_md_err, string data) { - msg_err("failed to parse JSON: %b\n", data); + msg_err("%s: failed to parse JSON: %b", func_ss, data); } closure_func_basic(value_handler, void, azure_instance_md_vh, @@ -62,7 +62,7 @@ closure_func_basic(value_handler, void, azure_instance_md_vh, az_instance_md_req req_data = struct_from_closure(az_instance_md_req, vh); deallocate_value(req_data->req); if (!v) { - msg_err("failed to retrieve instance metadata\n"); + msg_err("%s: failed to retrieve metadata", func_ss); goto done; } value start_line = get(v, sym(start_line)); @@ -74,7 +74,7 @@ closure_func_basic(value_handler, void, azure_instance_md_vh, else content = 0; if (!content) { - msg_err("unexpected metadata server response %v\n", v); + msg_err("%s: unexpected server response %v", func_ss, v); goto done; } tuple md = 0; @@ -106,12 +106,12 @@ void azure_instance_md_get(az_instance_md_handler complete) req_params.method = HTTP_REQUEST_METHOD_GET; az_instance_md_req req_data = allocate(azure.h, sizeof(*req_data)); if (req_data == INVALID_ADDRESS) { - msg_err("out of memory\n"); + msg_err("%s: out of memory", func_ss); goto error; } tuple req = allocate_tuple(); if (req == INVALID_ADDRESS) { - msg_err("out of memory\n"); + msg_err("%s: out of memory", func_ss); deallocate(azure.h, req_data, sizeof(*req_data)); goto error; } diff --git a/klib/azure_diagnostics.c b/klib/azure_diagnostics.c index 3af530eee..28a25fb31 100644 --- a/klib/azure_diagnostics.c +++ b/klib/azure_diagnostics.c @@ -75,7 +75,7 @@ static boolean azure_metric_get_interval(tuple metrics, sstring name, const u64 u64 interval; if (get_u64(metrics, sym_sstring(name), &interval)) { if (interval < min_value) { - rprintf("Azure diagnostics: invalid metrics %s (minimum allowed value %ld seconds)\n", + msg_err("Azure diagnostics: invalid metrics %s (minimum allowed value %ld seconds)", name, min_value); return false; } @@ -158,11 +158,11 @@ static void azdiag_resolve_cb(sstring name, const ip_addr_t *addr, void *cb_arg) if (addr) { azdiag_debug("connecting to server (%F)", ch); if (tls_connect((ip_addr_t *)addr, 443, ch) < 0) { - msg_err("failed to connect to server %s\n", name); + msg_err("%s: failed to connect to server %s", func_ss, name); apply(ch, 0); } } else { - msg_err("failed to resolve server name %s\n", name); + msg_err("%s: failed to resolve server name %s", func_ss, name); apply(ch, 0); } } @@ -193,7 +193,7 @@ static boolean azure_metrics_table_post(az_diag diag, sstring resource, buffer c status s = http_request(diag->h, diag->metrics.out, HTTP_REQUEST_METHOD_POST, req, body); boolean success = is_ok(s); if (!success) { - msg_err("%v\n", s); + msg_err("%s error %v", func_ss, s); timm_dealloc(s); } deallocate_value(req); @@ -253,7 +253,7 @@ closure_func_basic(status_handler, void, azdiag_setup_complete, * instance startup (a few seconds might elapse before the network interface acquires a DHCP * address). */ if (setup->retry_backoff > seconds(2)) - msg_err("%v\n", s); + msg_err("%s error %v", func_ss, s); else azdiag_debug("setup error %v, retrying", s); @@ -268,7 +268,7 @@ closure_func_basic(status_handler, void, azdiag_setup_complete, false, 0, setup_retry); return; } else { - msg_err("out of memory\n"); + msg_err("%s: out of memory", func_ss); } } deallocate(h, setup, sizeof(*setup)); @@ -357,12 +357,12 @@ static boolean azure_metrics_post(az_diag diag) { timestamp ts = diag->metrics.ts; if ((ts >= diag->metrics.table_switch) && !azure_metrics_table_switch(diag)) { - msg_err("failed to create table\n"); + msg_err("%s: failed to create table", func_ss); return false; } buffer b = allocate_buffer(diag->h, 1024); if (b == INVALID_ADDRESS) { - msg_err("out of memory\n"); + msg_err("%s: out of memory", func_ss); return false; } u64 secs = sec_from_timestamp(ts); @@ -419,7 +419,7 @@ closure_func_basic(input_buffer_handler, boolean, azure_metrics_in_handler, if (!diag->metrics.out) return true; } else { - msg_err("failed to parse response: %v\n", s); + msg_err("%s: failed to parse response: %v", func_ss, s); timm_dealloc(s); apply(diag->metrics.out, 0); return true; @@ -449,13 +449,13 @@ closure_func_basic(value_handler, void, azure_metrics_value_handler, } if (i == _countof(expected_codes)) { if (status_code == 403) - rprintf("Azure: invalid storage account SAS token\n"); + msg_err("Azure: invalid storage account SAS token"); else status_code = 0; } } if (!status_code) - msg_err("unexpected response %v\n", v); + msg_err("%s: unexpected response %v", func_ss, v); apply(diag->metrics.out, 0); diag->metrics.out = 0; /* signal to input buffer handler that connection is closed */ } @@ -474,8 +474,8 @@ int azure_diag_init(tuple cfg) tuple metrics = get_tuple(cfg, sym_this("metrics")); if (metrics) { if (!diag->storage_account || !diag->storage_account_sas) { - rprintf("Azure diagnostics: missing storage account or SAS token, " - "required for metrics\n"); + msg_err("Azure diagnostics: missing storage account or SAS token, " + "required for metrics"); return KLIB_INIT_FAILED; } if (!azure_metric_get_interval(metrics, ss("sample_interval"), 15, 15, @@ -524,7 +524,7 @@ int azure_diag_init(tuple cfg) extension->name = ss("Microsoft.Azure.Diagnostics.LinuxDiagnostic"); extension->version = ss("3.0.142"); if (!azure_register_ext(extension)) { - rprintf("Azure diagnostics: failed to register extension\n"); + msg_err("Azure diagnostics: failed to register extension"); return KLIB_INIT_FAILED; } azdiag_setup_s setup = allocate(h, sizeof(*setup)); diff --git a/klib/cloud_azure.c b/klib/cloud_azure.c index 66b9f3839..fedaaa491 100644 --- a/klib/cloud_azure.c +++ b/klib/cloud_azure.c @@ -75,7 +75,7 @@ closure_func_basic(timer_handler, void, az_report_th, if (is_ok(s)) { az->goalstate_pending = true; } else { - msg_err("%v\n", s); + msg_err("%s error %v", func_ss, s); timm_dealloc(s); } } @@ -85,7 +85,7 @@ static void az_report_status(azure az) heap h = az->h; buffer blob = allocate_buffer(h, KB); if (blob == INVALID_ADDRESS) { - msg_err("out of memory\n"); + msg_err("%s: out of memory", func_ss); return; } status s; @@ -169,7 +169,7 @@ static void az_report_status(azure az) s = net_http_req(req_params); done: if (!is_ok(s)) { - msg_err("%v\n", s); + msg_err("%s error %v", func_ss, s); timm_dealloc(s); deallocate_buffer(blob); } @@ -184,7 +184,7 @@ closure_func_basic(value_handler, void, az_get_ext_vh, deallocate_value(req_data->req); deallocate(az->h, req_data, sizeof(*req_data)); if (!v) { - msg_err("failed to get response\n"); + msg_err("%s: failed to get response", func_ss); return; } buffer content = get(v, sym(content)); @@ -277,10 +277,10 @@ closure_func_basic(value_handler, void, az_get_ext_vh, return; } parse_error: - msg_err("failed to parse response\n"); + msg_err("%s: failed to parse response", func_ss); return; alloc_error: - msg_err("out of memory\n"); + msg_err("%s: out of memory", func_ss); } static void az_get_ext_config(azure az) @@ -330,7 +330,7 @@ static void az_get_ext_config(azure az) if (req_data != INVALID_ADDRESS) deallocate(h, req_data, sizeof(*req_data)); if (!is_ok(s)) { - msg_err("%v\n", s); + msg_err("%s error %v", func_ss, s); timm_dealloc(s); } } @@ -340,7 +340,7 @@ closure_func_basic(value_handler, void, az_status_upload_vh, { azure az = struct_from_closure(azure, status_upload.vh); if (!v) { - msg_err("failed to get response\n"); + msg_err("%s: failed to get response", func_ss); return; } value start_line = get(v, sym(start_line)); @@ -355,12 +355,12 @@ closure_func_basic(value_handler, void, az_status_upload_vh, if (is_ok(s)) { az->status_upload.last_update = kern_now(CLOCK_ID_REALTIME); } else { - msg_err("failed to upload blob page: %v\n", s); + msg_err("%s: failed to upload blob page: %v", func_ss, s); timm_dealloc(s); deallocate_buffer(req_params->body); } } else { - msg_err("unexpected response %v\n", v); + msg_err("%s: unexpected response %v", func_ss, v); } } @@ -370,7 +370,7 @@ closure_func_basic(value_handler, void, az_goalstate_vh, azure az = struct_from_closure(azure, goalstate_vh); az->goalstate_pending = false; if (!v) { - msg_err("failed to get response\n"); + msg_err("%s: failed to get response", func_ss); return; } buffer content = get(v, sym(content)); @@ -415,7 +415,7 @@ closure_func_basic(value_handler, void, az_goalstate_vh, return; } exit: - msg_err("failed to parse response %v\n", v); + msg_err("%s: failed to parse response %v", func_ss, v); } closure_func_basic(value_handler, void, az_ready_vh, diff --git a/klib/cloud_init.c b/klib/cloud_init.c index abd5fbc4f..4dd1c781f 100644 --- a/klib/cloud_init.c +++ b/klib/cloud_init.c @@ -98,11 +98,11 @@ static int cloud_download_parse(tuple config, cloud_download_cfg parsed_cfg) { buffer src = get(config, sym(src)); if (!src) { - rprintf("cloud_init: missing download source in %v\n", config); + msg_err("cloud_init: missing download source in %v", config); return KLIB_INIT_FAILED; } if (!is_string(src) || (buffer_length(src) < 8)) { - rprintf("cloud_init: invalid download source %v\n", src); + msg_err("cloud_init: invalid download source %v", src); return KLIB_INIT_FAILED; } if (!runtime_memcmp(buffer_ref(src, 0), "http://", 7)) { @@ -114,7 +114,7 @@ static int cloud_download_parse(tuple config, cloud_download_cfg parsed_cfg) parsed_cfg->server_port = 443; parsed_cfg->tls = true; } else { - rprintf("cloud_init: invalid download source %b\n", src); + msg_err("cloud_init: invalid download source %b", src); return KLIB_INIT_FAILED; } parsed_cfg->server_host.contents = buffer_ref(src, 0); @@ -134,14 +134,14 @@ static int cloud_download_parse(tuple config, cloud_download_cfg parsed_cfg) host_end = buffer_strchr(&parsed_cfg->server_host, ':'); if (host_end >= 0) { if (host_end == buffer_length(&parsed_cfg->server_host) - 1) { - rprintf("cloud_init: invalid download source %b\n", src); + msg_err("cloud_init: invalid download source %b", src); return KLIB_INIT_FAILED; } buffer b = alloca_wrap_buffer(buffer_ref(&parsed_cfg->server_host, host_end + 1), buffer_length(&parsed_cfg->server_host) - host_end - 1); u64 port; if (!u64_from_value(b, &port) || (port > U16_MAX)) { - rprintf("invalid server port in download source %b\n", src); + msg_err("cloud_init: invalid server port in download source %b", src); return KLIB_INIT_FAILED; } parsed_cfg->server_port = port; @@ -501,16 +501,16 @@ static int cloud_download_file_parse(tuple config, vector tasks) return ret; parsed_cfg->file_path = get(config, sym(dest)); if (!parsed_cfg->file_path) { - rprintf("cloud_init: missing download destination in %v\n", config); + msg_err("cloud_init: missing download destination in %v", config); return KLIB_INIT_FAILED; } if (!is_string(parsed_cfg->file_path)) { - rprintf("cloud_init: invalid download destination %v\n", parsed_cfg->file_path); + msg_err("cloud_init: invalid download destination %v", parsed_cfg->file_path); return KLIB_INIT_FAILED; } fsfile f = fsfile_open_or_create(buffer_to_sstring(parsed_cfg->file_path), false); if (!f) { - rprintf("cloud_init: download destination file '%b' cannot be created\n", + msg_err("cloud_init: download destination file '%b' cannot be created", parsed_cfg->file_path); return KLIB_INIT_FAILED; } @@ -646,7 +646,7 @@ static int cloud_download_env_parse(tuple config, vector tasks) value path = get(config, sym(path)); if (path) { if (!is_string(path)) { - rprintf("download_env: invalid path %v\n", path); + msg_err("cloud_init download_env: invalid path %v", path); return KLIB_INIT_FAILED; } cfg->attribute_path = split(cloud_heap, path, '/'); @@ -674,7 +674,7 @@ int init(status_handler complete) if (!config) return KLIB_INIT_OK; if (!is_tuple(config)) { - rprintf("invalid cloud_init configuration\n"); + msg_err("cloud_init: invalid configuration"); return KLIB_INIT_FAILED; } vector tasks = allocate_vector(cloud_heap, 8); @@ -684,7 +684,7 @@ int init(status_handler complete) if (download) { ret = cloud_init_parse_vector(download, cloud_download_file_parse, tasks); if (ret != KLIB_INIT_OK) { - rprintf("invalid cloud_init download configuration\n"); + msg_err("cloud_init: invalid download configuration"); goto error; } } @@ -692,7 +692,7 @@ int init(status_handler complete) if (download_env) { ret = cloud_init_parse_vector(download_env, cloud_download_env_parse, tasks); if (ret != KLIB_INIT_OK) { - rprintf("invalid cloud_init download_env configuration\n"); + msg_err("cloud_init: invalid download_env configuration"); goto error; } } diff --git a/klib/cloudwatch.c b/klib/cloudwatch.c index 73b706956..2b4a4141d 100644 --- a/klib/cloudwatch.c +++ b/klib/cloudwatch.c @@ -160,7 +160,7 @@ static void cw_dns_cb(sstring name, const ip_addr_t *ipaddr, void *callback_arg) if (t != INVALID_ADDRESS) async_apply(t); else - msg_err("failed to allocate closure\n"); + msg_err("%s: failed to allocate closure", func_ss); } static void cw_connect(sstring server, void (*handler)(const ip_addr_t *server)) @@ -201,7 +201,7 @@ closure_function(1, 1, void, cw_logstream_vh, buffer content = get_string(v, sym(content)); if (content && (buffer_strstr(content, ss("ResourceAlreadyExistsException")) >= 0)) goto success; - msg_err("unexpected response %v\n", v); + msg_err("%s: unexpected response %v", func_ss, v); return; success: spin_lock(&cw.lock); @@ -216,7 +216,7 @@ closure_function(3, 1, boolean, cw_log_meta_ibh, { status s = apply(bound(parser), data); if (!is_ok(s)) { - msg_err("failed to parse response: %v\n", s); + msg_err("%s: failed to parse response: %v", func_ss, s); timm_dealloc(s); if (data) { apply(bound(out), 0); @@ -239,12 +239,12 @@ closure_function(2, 1, input_buffer_handler, cw_logstream_ch, buffer_handler parser = bound(parser); boolean success = false; if (!out) { - msg_err("connection failed\n"); + msg_err("%s: connection failed", func_ss); goto exit; } tuple req = allocate_tuple(); if (req == INVALID_ADDRESS) { - msg_err("failed to allocate request\n"); + msg_err("%s: failed to allocate request", func_ss); goto exit; } set(req, sym(url), alloca_wrap_cstring("/")); @@ -259,7 +259,7 @@ closure_function(2, 1, input_buffer_handler, cw_logstream_ch, cw.log_group, cw.log_stream); input_buffer_handler ibh = closure(cw.h, cw_log_meta_ibh, parser, bound(parsed), out); if (ibh == INVALID_ADDRESS) { - msg_err("failed to allocate input buffer handler\n"); + msg_err("%s: failed to allocate input buffer handler", func_ss); goto req_done; } success = cw_aws_req_send(ss(CLOUDWATCH_LOG_SERVICE_NAME), ss("Logs_20140328.CreateLogStream"), @@ -284,29 +284,29 @@ closure_function(2, 1, input_buffer_handler, cw_logstream_ch, static void cw_logstream_create(const ip_addr_t *server) { if (!server) { - msg_err("failed to get server address\n"); + msg_err("%s: failed to get server address", func_ss); return; } value_handler vh = closure(cw.h, cw_logstream_vh, false); if (vh == INVALID_ADDRESS) { - msg_err("failed to allocate value handler\n"); + msg_err("%s: failed to allocate value handler", func_ss); return; } buffer_handler parser = allocate_http_parser(cw.h, vh); if (parser == INVALID_ADDRESS) { - msg_err("failed to allocate HTTP parser\n"); + msg_err("%s: failed to allocate HTTP parser", func_ss); deallocate_closure(vh); return; } connection_handler ch = closure(cw.h, cw_logstream_ch, parser, &closure_member(cw_logstream_vh, vh, parsed)); if (ch == INVALID_ADDRESS) { - msg_err("failed to allocate connection handler\n"); + msg_err("%s: failed to allocate connection handler", func_ss); goto dealloc_parser; } if (tls_connect((ip_addr_t *)server, 443, ch) == 0) return; - msg_err("failed to connect to server\n"); + msg_err("%s: failed to connect to server", func_ss); deallocate_closure(ch); dealloc_parser: apply(parser, 0); @@ -327,7 +327,7 @@ closure_function(1, 1, void, cw_loggroup_vh, buffer content = get_string(v, sym(content)); if (content && (buffer_strstr(content, ss("ResourceAlreadyExistsException")) >= 0)) goto success; - msg_err("unexpected response %v\n", v); + msg_err("%s: unexpected response %v", func_ss, v); return; success: cw_connect(isstring(cw.log_servername, cw.log_servername_len), cw_logstream_create); @@ -340,12 +340,12 @@ closure_function(2, 1, input_buffer_handler, cw_loggroup_ch, buffer_handler parser = bound(parser); boolean success = false; if (!out) { - msg_err("connection failed\n"); + msg_err("%s: connection failed", func_ss); goto exit; } tuple req = allocate_tuple(); if (req == INVALID_ADDRESS) { - msg_err("failed to allocate request\n"); + msg_err("%s: failed to allocate request", func_ss); goto exit; } set(req, sym(url), alloca_wrap_cstring("/")); @@ -359,7 +359,7 @@ closure_function(2, 1, input_buffer_handler, cw_loggroup_ch, bprintf(body, "{\"logGroupName\":\"%b\"}", cw.log_group); input_buffer_handler ibh = closure(cw.h, cw_log_meta_ibh, parser, bound(parsed), out); if (ibh == INVALID_ADDRESS) { - msg_err("failed to allocate input buffer handler\n"); + msg_err("%s: failed to allocate input buffer handler", func_ss); goto req_done; } success = cw_aws_req_send(ss(CLOUDWATCH_LOG_SERVICE_NAME), ss("Logs_20140328.CreateLogGroup"), @@ -384,29 +384,29 @@ closure_function(2, 1, input_buffer_handler, cw_loggroup_ch, static void cw_loggroup_create(const ip_addr_t *server) { if (!server) { - msg_err("failed to get server address\n"); + msg_err("%s: failed to get server address", func_ss); return; } value_handler vh = closure(cw.h, cw_loggroup_vh, false); if (vh == INVALID_ADDRESS) { - msg_err("failed to allocate value handler\n"); + msg_err("%s: failed to allocate value handler", func_ss); return; } buffer_handler parser = allocate_http_parser(cw.h, vh); if (parser == INVALID_ADDRESS) { - msg_err("failed to allocate HTTP parser\n"); + msg_err("%s: failed to allocate HTTP parser", func_ss); deallocate_closure(vh); return; } connection_handler ch = closure(cw.h, cw_loggroup_ch, parser, &closure_member(cw_loggroup_vh, vh, parsed)); if (ch == INVALID_ADDRESS) { - msg_err("failed to allocate connection handler\n"); + msg_err("%s: failed to allocate connection handler", func_ss); goto dealloc_parser; } if (tls_connect((ip_addr_t *)server, 443, ch) == 0) return; - msg_err("failed to connect to server\n"); + msg_err("%s: failed to connect to server", func_ss); deallocate_closure(ch); dealloc_parser: apply(parser, 0); @@ -456,7 +456,7 @@ define_closure_function(1, 1, void, cw_aws_setup_complete, if (cw.log_entries) cw_log_setup(); } else { - msg_err("setup failed: %v\n", s); + msg_err("CloudWatch setup failed: %v", s); timm_dealloc(s); timestamp retry_backoff = bound(retry_backoff); if (retry_backoff < seconds(3600)) @@ -531,7 +531,7 @@ define_closure_function(1, 1, boolean, cw_metrics_in_handler, aws_cred_get(cw.h, init_closure(&cw.aws_cred_handler, cw_aws_cred_handler, (status_handler)&cw.aws_setup_complete)); } else { - msg_err("server response: '%b'\n", data); + msg_err("%s error: server response: '%b'", func_ss, data); } } apply(bound(out), 0); @@ -668,7 +668,7 @@ closure_func_basic(value_handler, void, cw_log_vh, aws_cred_get(cw.h, init_closure(&cw.aws_cred_handler, cw_aws_cred_handler, (status_handler)&cw.aws_setup_complete)); } else { - msg_err("unexpected response %v\n", v); + msg_err("%s: unexpected response %v", func_ss, v); cw_log_pending_delete(); } } @@ -686,7 +686,7 @@ closure_func_basic(input_buffer_handler, boolean, cw_log_in_handler, return true; } } else { - msg_err("failed to parse response: %v\n", s); + msg_err("%s: failed to parse response: %v", func_ss, s); timm_dealloc(s); apply(cw.log_out, 0); return true; @@ -836,7 +836,7 @@ int init(status_handler complete) if (metrics_interval) { u64 interval; if (!u64_from_value(metrics_interval, &interval)) { - rprintf("CloudWatch: invalid memory metrics interval\n"); + msg_err("CloudWatch: invalid memory metrics interval"); return KLIB_INIT_FAILED; } cw.metrics_interval = seconds(interval); diff --git a/klib/digitalocean.c b/klib/digitalocean.c index 0f1bdada5..2300d3269 100644 --- a/klib/digitalocean.c +++ b/klib/digitalocean.c @@ -302,7 +302,7 @@ closure_func_basic(status_handler, void, do_setup_complete, * instance startup (a few seconds might elapse before the network interface acquires a DHCP * address). */ if (digitalocean.retry_backoff > seconds(2)) - msg_err("setup failed: %v\n", s); + msg_err("DigitalOcean setup failed: %v", s); timm_dealloc(s); if (digitalocean.retry_backoff < seconds(3600)) @@ -398,7 +398,7 @@ static boolean do_metrics_post(void) req, body); success = is_ok(s); if (!success) { - msg_err("%v\n", s); + msg_err("%s error %v", func_ss, s); timm_dealloc(s); } } @@ -437,7 +437,7 @@ closure_func_basic(input_buffer_handler, boolean, do_metrics_in_handler, if (!digitalocean.metrics.out) return true; } else { - msg_err("failed to parse response: %v\n", s); + msg_err("%s: failed to parse response: %v", func_ss, s); timm_dealloc(s); apply(digitalocean.metrics.out, 0); return true; @@ -454,7 +454,7 @@ closure_func_basic(value_handler, void, do_metrics_value_handler, value resp = get(v, sym(start_line)); buffer status_code = get(resp, integer_key(1)); if (!status_code || peek_char(status_code) != '2') - msg_err("unexpected response %v\n", v); + msg_err("%s: unexpected response %v", func_ss, v); apply(digitalocean.metrics.out, 0); digitalocean.metrics.out = 0; /* signal to input buffer handler that connection is closed */ } @@ -475,8 +475,8 @@ int init(status_handler complete) u64 interval; if (get_u64(metrics, sym_this("interval"), &interval)) { if (interval < min_interval) { - rprintf("DigitalOcean: invalid metrics interval (minimum allowed value %ld " - "seconds)\n", min_interval); + msg_err("DigitalOcean: invalid metrics interval (minimum allowed value %ld " + "seconds)", min_interval); return KLIB_INIT_FAILED; } } else { diff --git a/klib/firewall.c b/klib/firewall.c index 1395a2234..22aede993 100644 --- a/klib/firewall.c +++ b/klib/firewall.c @@ -286,7 +286,7 @@ static void firewall_dealloc_l3_constraint(heap h, firewall_constraint c) static boolean firewall_rule_parse_l3(heap h, firewall_rule rule, value spec, boolean ipv6) { if (!is_tuple(spec)) { - rprintf("firewall: invalid value '%v'\n", spec); + msg_err("firewall: invalid value '%v'", spec); return false; } rule->l3_match = allocate_vector(h, 2); @@ -294,7 +294,7 @@ static boolean firewall_rule_parse_l3(heap h, firewall_rule rule, value spec, bo string src = get(spec, sym(src)); if (src) { if (!is_string(src) || !buffer_length(src)) { - rprintf("firewall: invalid ip src value '%v'\n", src); + msg_err("firewall: invalid ip src value '%v'", src); return false; } sstring src_str = buffer_to_sstring(src); @@ -316,7 +316,7 @@ static boolean firewall_rule_parse_l3(heap h, firewall_rule rule, value spec, bo else parsed = ip4addr_aton(src_str, &addr.u_addr.ip4); if (!parsed) { - rprintf("firewall: invalid IPv%c address '%s'\n", ipv6 ? '6' : '4', src_str); + msg_err("firewall: invalid IPv%c address '%s'", ipv6 ? '6' : '4', src_str); return false; } u64 netmask; @@ -326,7 +326,7 @@ static boolean firewall_rule_parse_l3(heap h, firewall_rule rule, value spec, bo buffer netmask_str = alloca_wrap_sstring(src_str); if (!parse_int(netmask_str, 10, &netmask) || buffer_length(netmask_str) || (netmask == 0) || (netmask > (ipv6 ? 128 : 32))) { - rprintf("firewall: invalid network mask '%s'\n", src_str); + msg_err("firewall: invalid network mask '%s'", src_str); return false; } } else { @@ -397,7 +397,7 @@ static void firewall_rule_add_l4_proto(heap h, firewall_rule rule, u8 proto) static boolean firewall_rule_parse_l4(heap h, firewall_rule rule, value spec, u8 proto) { if (!is_tuple(spec)) { - rprintf("firewall: invalid transport protocol value '%v'\n", spec); + msg_err("firewall: invalid transport protocol value '%v'", spec); return false; } rule->l4_match = allocate_vector(h, 2); @@ -406,7 +406,7 @@ static boolean firewall_rule_parse_l4(heap h, firewall_rule rule, value spec, u8 if (dest) { firewall_constraint_val c = firewall_create_constraint_val(h, dest, 2); if (!c) { - rprintf("firewall: invalid transport protocol dest value '%v'\n", dest); + msg_err("firewall: invalid transport protocol dest value '%v'", dest); return false; } c->c.type = FW_L4_DEST; @@ -452,7 +452,7 @@ static void firewall_dealloc_udp_constraint(heap h, firewall_constraint c) static boolean firewall_create_rule(heap h, value spec) { if (!is_tuple(spec)) { - rprintf("invalid firewall rule '%v'\n", spec); + msg_err("firewall: invalid rule '%v'", spec); return false; } firewall_rule rule = allocate(h, sizeof(*rule)); @@ -469,7 +469,7 @@ static boolean firewall_create_rule(heap h, value spec) value ip6 = get(spec, sym(ip6)); if (ip6) { if (ip4) { - rprintf("firewall: found both IPv4 and IPv6 in the same rule %v\n", spec); + msg_err("firewall: found both IPv4 and IPv6 in the same rule %v", spec); return false; } if (!firewall_rule_parse_ip6(h, rule, ip6)) @@ -483,7 +483,7 @@ static boolean firewall_create_rule(heap h, value spec) l4 = get(spec, sym(udp)); if (l4) { if (rule->l4_proto) { - rprintf("firewall: found different transport protocols in the same rule %v\n", spec); + msg_err("firewall: found different transport protocols in the same rule %v", spec); return false; } if (!firewall_rule_parse_udp(h, rule, l4)) @@ -492,7 +492,7 @@ static boolean firewall_create_rule(heap h, value spec) value action = get(spec, sym(action)); if (action) { if (!is_string(action)) { - rprintf("firewall: invalid action value %v\n", action); + msg_err("firewall: invalid action value %v", action); return false; } if (!buffer_strcmp(action, "accept")) { @@ -500,7 +500,7 @@ static boolean firewall_create_rule(heap h, value spec) } else if (!buffer_strcmp(action, "drop")) { rule->drop = true; } else { - rprintf("firewall: invalid action '%b'\n", action); + msg_err("firewall: invalid action '%b'", action); return false; } } else { /* default action */ @@ -552,14 +552,14 @@ int init(status_handler complete) if (!config) return KLIB_INIT_OK; if (!is_tuple(config)) { - rprintf("invalid firewall configuration\n"); + msg_err("firewall: invalid configuration"); return KLIB_INIT_FAILED; } value rules = get(config, sym(rules)); if (!rules) return KLIB_INIT_OK; if (!is_composite(rules)) { - rprintf("invalid firewall rules\n"); + msg_err("firewall: invalid rules"); return KLIB_INIT_FAILED; } list_init(&firewall.rules); diff --git a/klib/gcp.c b/klib/gcp.c index f0f89d224..d9a4737dc 100644 --- a/klib/gcp.c +++ b/klib/gcp.c @@ -429,7 +429,7 @@ define_closure_function(1, 1, void, gcp_setup_complete, * right after instance startup (e.g. HTTP 500 response with "Failed to authenticate request * (Type 0)". */ if (retry_backoff > seconds(1)) - msg_err("setup failed: %v\n", s); + msg_err("GCP setup failed: %v", s); timm_dealloc(s); if (retry_backoff < seconds(3600)) @@ -448,11 +448,11 @@ static void gcp_dns_cb(sstring name, const ip_addr_t *addr, void *cb_arg) connection_handler ch = cb_arg; if (addr) { if (tls_connect((ip_addr_t *)addr, 443, ch) < 0) { - msg_err("failed to connect to server %s\n", name); + msg_err("%s: failed to connect to server %s", func_ss, name); apply(ch, 0); } } else { - msg_err("failed to resolve server name %s\n", name); + msg_err("%s: failed to resolve server name %s", func_ss, name); apply(ch, 0); } } @@ -512,7 +512,7 @@ closure_func_basic(value_handler, void, gcp_log_vh, /* The access token must have expired: renew it. */ gcp_setup(); } else { - msg_err("unexpected response %v\n", v); + msg_err("%s: unexpected response %v", func_ss, v); gcp_log_pending_delete(); } gcp.log_resp_recved = true; @@ -530,7 +530,7 @@ closure_func_basic(input_buffer_handler, boolean, gcp_log_in_handler, return true; } } else { - msg_err("failed to parse response: %v\n", s); + msg_err("%s: failed to parse response: %v", func_ss, s); timm_dealloc(s); apply(gcp.log_out, 0); return true; @@ -621,7 +621,7 @@ static boolean gcp_log_post(void) status s = http_request(gcp.h, gcp.log_out, HTTP_REQUEST_METHOD_POST, req, body); success = is_ok(s); if (!success) { - msg_err("%v\n", s); + msg_err("%s error %v", func_ss, s); timm_dealloc(s); } req_done: @@ -790,7 +790,7 @@ static boolean gcp_metrics_post(void) status s = http_request(gcp.h, gcp.metrics_out, HTTP_REQUEST_METHOD_POST, req, body); success = is_ok(s); if (!success) { - msg_err("%v\n", s); + msg_err("%s error %v", func_ss, s); timm_dealloc(s); } req_done: @@ -824,7 +824,7 @@ closure_func_basic(input_buffer_handler, boolean, gcp_metrics_in_handler, if (!gcp.metrics_out) return true; } else { - msg_err("failed to parse response: %v\n", s); + msg_err("%s: failed to parse response: %v", func_ss, s); timm_dealloc(s); apply(gcp.metrics_out, 0); return true; @@ -845,7 +845,7 @@ closure_func_basic(value_handler, void, gcp_metrics_value_handler, /* The access token must have expired: renew it. */ gcp_setup(); } else if (buffer_strcmp(status_code, "200")) { - msg_err("unexpected response %v\n", v); + msg_err("%s: unexpected response %v", func_ss, v); } } apply(gcp.metrics_out, 0); @@ -887,7 +887,7 @@ int init(status_handler complete) u64 interval; if (get_u64(metrics, sym(interval), &interval)) { if (interval < min_interval) { - rprintf("GCP: invalid metrics interval (minimum allowed value %ld seconds)\n", + msg_err("GCP: invalid metrics interval (minimum allowed value %ld seconds)", min_interval); return KLIB_INIT_FAILED; } diff --git a/klib/mbedtls.c b/klib/mbedtls.c index 36bff226c..a470dd0b5 100644 --- a/klib/mbedtls.c +++ b/klib/mbedtls.c @@ -220,7 +220,7 @@ int tls_set_cacert(void *cert, u64 len) mbedtls_x509_crt_init(&tls.cacert); int ret = mbedtls_x509_crt_parse(&tls.cacert, cert, len); if (ret < 0) { - msg_err("cannot parse certificate (%d)\n", ret); + msg_err("%s: cannot parse certificate (%d)", func_ss, ret); return ret; } mbedtls_ssl_conf_ca_chain(&tls.conf, &tls.cacert, NULL); @@ -236,7 +236,7 @@ int tls_connect(ip_addr_t *addr, u16 port, connection_handler ch) mbedtls_ssl_init(&conn->ssl); int ret = mbedtls_ssl_setup(&conn->ssl, &tls.conf); if (ret) { - msg_err("cannot set up SSL context\n"); + msg_err("%s: cannot set up SSL context", func_ss); goto err_ssl_setup; } conn->app_ch = ch; @@ -265,7 +265,7 @@ int init(status_handler complete) mbedtls_ctr_drbg_init(&tls.ctr_drbg); mbedtls_entropy_init(&tls.entropy); if (mbedtls_ctr_drbg_seed(&tls.ctr_drbg, mbedtls_entropy_func, &tls.entropy, 0, 0)) { - rprintf("TLS init: cannot seed entropy source\n"); + msg_err("TLS init: cannot seed entropy source"); return KLIB_INIT_FAILED; } mbedtls_ssl_config_defaults(&tls.conf, MBEDTLS_SSL_IS_CLIENT, diff --git a/klib/ntp.c b/klib/ntp.c index 0902b208a..1c38634ca 100644 --- a/klib/ntp.c +++ b/klib/ntp.c @@ -251,7 +251,8 @@ static inline s64 fpdiv(s64 dividend, s64 divisor) u128 d = ((u128)dividend) << CLOCK_FP_BITS; s64 q = div128_64(d, divisor); if (q == -1) { - msg_err("%f / %f quotient out of range at %p!\n", dividend, divisor, __builtin_return_address(0)); + msg_err("%s: %f / %f quotient out of range at %p", func_ss, dividend, divisor, + __builtin_return_address(0)); q = fpmax; } if (neg) @@ -308,7 +309,7 @@ static void ntp_query(ntp_server server) runtime_memcpy(&server->last_originate_time, &t, sizeof(t)); err_t err = udp_sendto(ntp.pcb, p, &server->ip_addr, server->port); if (err != ERR_OK) { - msg_err("failed to send request: %d\n", err); + msg_err("%s: failed to send request: %d", func_ss, err); ntp_query_complete(false); } pbuf_free(p); @@ -511,18 +512,19 @@ static boolean chrony_new_sample(timestamp t, s64 off, s64 pdelay, s64 pdisp, s6 return true; s64 est_off, est_freq, sd, skew; if (!regression(&est_off, &est_freq, &sd, &skew)) { - msg_err("regression computation failed\n"); + msg_err("%s: regression computation failed", func_ss); if (++ntp.bad_regressions == MAX_BAD_REGRESSIONS) goto badlimit; return false; } /* if the frequency is out of range then assume bad data or misbehaving clock and clamp */ if (ABS(ntp.base_freq + est_freq) > ntp.max_base_freq) { - msg_err("freq out of range: %f limit=%f\n", ABS(ntp.base_freq + est_freq), ntp.max_base_freq); + msg_err("%s: freq out of range: %f limit=%f", func_ss, ABS(ntp.base_freq + est_freq), + ntp.max_base_freq); /* if too many bad regressions in a row, then toss everything and start over */ if (++ntp.bad_regressions == MAX_BAD_REGRESSIONS) { badlimit: - msg_err("too many bad regressions; starting over\n"); + msg_err("%s: too many bad regressions; starting over", func_ss); stop_slew(); ntp_reset_state(); clock_set_freq(0); @@ -635,7 +637,7 @@ static void ntp_input(void *z, struct udp_pcb *pcb, struct pbuf *p, struct ntp_packet *pkt = p->payload; boolean success; if (p->len != sizeof(*pkt)) { - msg_err("invalid response length %d\n", p->len); + msg_err("%s: invalid response length %d", func_ss, p->len); success = false; goto done; } @@ -649,7 +651,7 @@ static void ntp_input(void *z, struct udp_pcb *pcb, struct pbuf *p, goto exit; } if (!sanity_checks(server, pkt)) { - msg_err("packet sanity checks failed; discarded\n"); + msg_err("%s: packet sanity checks failed; discarded", func_ss); success = false; goto done; } @@ -706,7 +708,7 @@ static void ntp_dns_cb(sstring name, const ip_addr_t *ipaddr, void *callback_arg server->ip_addr = *ipaddr; ntp_query(server); } else { - msg_err("failed to resolve hostname %s\n", name); + msg_err("NTP: failed to resolve hostname %s", name); ntp_query_complete(false); } } @@ -717,7 +719,7 @@ static boolean ntp_resolve_and_query(ntp_server server) if (err == ERR_OK) { ntp_query(server); } else if (err != ERR_INPROGRESS) { - msg_err("failed to resolve hostname %s: %d\n", server->addr, err); + msg_err("NTP: failed to resolve hostname %s: %d", server->addr, err); return false; } return true; @@ -732,7 +734,7 @@ closure_func_basic(timer_handler, void, ntp_query_func, if ((ntp.current_server < 0) || (ntp.query_errors >= NTP_QUERY_ATTEMPTS)) { timestamp t = kern_now(CLOCK_ID_MONOTONIC_RAW) - ntp.resp_time; if (t >= seconds(ntp.no_resp_warn_time * 60)) { - rprintf("NTP: failed to receive any valid server response in the past %d minutes\n", + msg_err("NTP: failed to receive any valid server response in the past %d minutes", ntp.no_resp_warn_time); if (ntp.no_resp_warn_time <= 30) ntp.no_resp_warn_time <<= 1; @@ -827,7 +829,7 @@ int init(status_handler complete) { tuple root = get_root_tuple(); if (!root) { - rprintf("NTP: failed to get root tuple\n"); + msg_err("NTP: failed to get root tuple"); return KLIB_INIT_FAILED; } heap h = heap_locked(get_kernel_heaps()); @@ -842,18 +844,18 @@ int init(status_handler complete) if (ptp_clock_now) ntp.ptp_clock = true; else - rprintf("chrony: PTP clock not available, using NTP\n"); + msg_err("chrony: PTP clock not available, using NTP"); } else { refclock_ok = false; } } if (!refclock_ok) { - rprintf("chrony: invalid refclock %v\n", refclock); + msg_err("chrony: invalid refclock %v", refclock); return KLIB_INIT_FAILED; } } } else { - rprintf("chrony: invalid configuration %v\n", chrony); + msg_err("chrony: invalid configuration %v", chrony); return KLIB_INIT_FAILED; } } @@ -876,12 +878,12 @@ int init(status_handler complete) string server; for (int i = 0; (server = get_string(servers, integer_key(i))); i++) { if (!ntp_server_parse(h, server)) { - rprintf("NTP: invalid server '%b'\n", server); + msg_err("NTP: invalid server '%b'", server); return KLIB_INIT_FAILED; } } if (vector_length(ntp.servers) == 0) { - rprintf("NTP: invalid servers %v\n", servers); + msg_err("NTP: invalid servers %v", servers); return KLIB_INIT_FAILED; } } else { @@ -895,7 +897,7 @@ int init(status_handler complete) u64 interval; if (!u64_from_value(pollmin, &interval) || (interval < NTP_QUERY_INTERVAL_MIN) || (interval > NTP_QUERY_INTERVAL_MAX)) { - rprintf("NTP: invalid minimum poll interval\n"); + msg_err("NTP: invalid minimum poll interval"); return KLIB_INIT_FAILED; } ntp.pollmin = interval; @@ -907,13 +909,13 @@ int init(status_handler complete) u64 interval; if (!u64_from_value(pollmax, &interval) || (interval < NTP_QUERY_INTERVAL_MIN) || (interval > NTP_QUERY_INTERVAL_MAX)) { - rprintf("NTP: invalid maximum poll interval\n"); + msg_err("NTP: invalid maximum poll interval"); return KLIB_INIT_FAILED; } ntp.pollmax = interval; if (interval < ntp.pollmin) { if (pollmin) { - rprintf("NTP: maximum poll interval smaller than minimum poll interval\n"); + msg_err("NTP: maximum poll interval smaller than minimum poll interval"); return KLIB_INIT_FAILED; } ntp.pollmin = interval; @@ -924,7 +926,7 @@ int init(status_handler complete) if (reset_thresh) { u64 thresh; if (!u64_from_value(reset_thresh, &thresh) || (thresh > 0 && thresh < NTP_RESET_THRESHOLD_MIN)) { - rprintf("NTP: invalid reset threshold\n"); + msg_err("NTP: invalid reset threshold"); return KLIB_INIT_FAILED; } ntp.reset_threshold = seconds(thresh); @@ -934,7 +936,7 @@ int init(status_handler complete) if (corr_freq) { u64 ppm; if (!u64_from_value(corr_freq, &ppm) || (ppm > 0 && ppm < NTP_MAX_SLEW_LIMIT)) { - rprintf("NTP: invalid max slew frequency\n"); + msg_err("NTP: invalid max slew frequency"); return KLIB_INIT_FAILED; } ntp.max_corr_freq = PPM_SCALE(ppm); @@ -944,7 +946,7 @@ int init(status_handler complete) if (base_freq) { u64 ppm; if (!u64_from_value(base_freq, &ppm) || (ppm > 0 && ppm < NTP_MAX_FREQ_LIMIT)) { - rprintf("NTP: invalid max base frequency\n"); + msg_err("NTP: invalid max base frequency"); return KLIB_INIT_FAILED; } ntp.max_base_freq = PPM_SCALE(ppm); @@ -954,7 +956,7 @@ int init(status_handler complete) } else { ntp.pcb = udp_new_ip_type(IPADDR_TYPE_ANY); if (!ntp.pcb) { - rprintf("NTP: failed to create PCB\n"); + msg_err("NTP: failed to create PCB"); return KLIB_INIT_FAILED; } udp_recv(ntp.pcb, ntp_input, 0); diff --git a/klib/radar.c b/klib/radar.c index ae8189c55..83d6efdb0 100644 --- a/klib/radar.c +++ b/klib/radar.c @@ -76,7 +76,7 @@ static void telemetry_dns_cb(sstring name, const ip_addr_t *ipaddr, void *callba { connection_handler ch = callback_arg; if (!ipaddr) { - rprintf("Radar: failed to look up server hostname\n"); + msg_err("Radar: failed to look up server hostname"); goto error; } thunk t = closure(telemetry.h, telemetry_connect, *ipaddr, ch); @@ -137,11 +137,11 @@ closure_function(2, 1, boolean, telemetry_recv, if (parser != INVALID_ADDRESS) { status s = apply(parser, data); if (!is_ok(s)) { - rprintf("Radar: failed to parse HTTP response: %v\n", s); + msg_err("Radar: failed to parse HTTP response: %v", s); timm_dealloc(s); } } else { - rprintf("Radar: failed to allocate HTTP parser\n"); + msg_err("Radar: failed to allocate HTTP parser"); apply(vh, 0); } } @@ -383,7 +383,7 @@ static void telemetry_stats_send(void) { buffer b = allocate_buffer(telemetry.h, 128); if (b == INVALID_ADDRESS) { - msg_err("failed to allocate buffer\n"); + msg_err("%s: failed to allocate buffer", func_ss); return; } bprintf(b, "{\"bootID\":%ld,\"memUsed\":[", telemetry.boot_id); @@ -394,7 +394,7 @@ static void telemetry_stats_send(void) storage_iterate(stack_closure(telemetry_vh, b, 0)); buffer_write_cstring(b, "]}\r\n"); if (!telemetry_send(ss("/api/v1/machine-stats"), b, 0)) { - msg_err("failed to send stats\n"); + msg_err("Radar: failed to send stats"); deallocate_buffer(b); } } @@ -433,7 +433,7 @@ int init(status_handler complete) telemetry.h = heap_locked(kh); telemetry.phys = (heap)heap_physical(kh); if (tls_set_cacert(RADAR_CA_CERT, sizeof(RADAR_CA_CERT)) != 0) { - rprintf("Radar: failed to set CA certificate\n"); + msg_err("Radar: failed to set CA certificate"); return KLIB_INIT_FAILED; } telemetry.env = get_environment(); @@ -445,12 +445,12 @@ int init(status_handler complete) init_closure_func(&telemetry.stats_func, timer_handler, telemetry_stats); telemetry.dump = allocate(telemetry.h, sizeof(*telemetry.dump)); if (telemetry.dump == INVALID_ADDRESS) { - rprintf("Radar: failed to allocate log dump\n"); + msg_err("Radar: failed to allocate log dump"); return KLIB_INIT_FAILED; } status_handler sh = closure_func(telemetry.h, status_handler, klog_dump_loaded); if (sh == INVALID_ADDRESS) { - rprintf("Radar: failed to allocate log dump load handler\n"); + msg_err("Radar: failed to allocate log dump load handler"); deallocate(telemetry.h, telemetry.dump, sizeof(*telemetry.dump)); return KLIB_INIT_FAILED; } diff --git a/klib/shmem.c b/klib/shmem.c index 020099a94..e4594f85a 100644 --- a/klib/shmem.c +++ b/klib/shmem.c @@ -38,7 +38,7 @@ int init(status_handler complete) { shmem.fs = tmpfs_new(); if (shmem.fs == INVALID_ADDRESS) { - rprintf("shmem: failed to create tmpfs\n"); + msg_err("shmem: failed to create tmpfs"); return KLIB_INIT_FAILED; } swap_syscall_handler(linux_syscalls, SYS_memfd_create, memfd_create); diff --git a/klib/strace.c b/klib/strace.c index fca9c6884..9d555704d 100644 --- a/klib/strace.c +++ b/klib/strace.c @@ -915,6 +915,6 @@ int init(status_handler complete) strace_misc_init(); return KLIB_INIT_OK; oom: - msg_err("out of memory\n"); + msg_err("strace: out of memory"); return KLIB_INIT_FAILED; } diff --git a/klib/syslog.c b/klib/syslog.c index 733c80e36..c0a7a0560 100644 --- a/klib/syslog.c +++ b/klib/syslog.c @@ -361,18 +361,18 @@ closure_func_basic(binding_handler, boolean, syslog_cfg, { if (s == sym(file)) { if (!is_string(v)) { - rprintf("invalid syslog file\n"); + msg_err("syslog: invalid file"); return false; } syslog.file_path = v; } else if (s == sym(file_max_size)) { if (!is_string(v)) { - rprintf("invalid syslog file max size\n"); + msg_err("syslog: invalid file max size"); return false; } buffer b = alloca_wrap(v); if (!parse_int(b, 10, &syslog.file_max_size)) { - rprintf("invalid syslog file max size\n"); + msg_err("syslog: invalid file max size"); return false; } if (buffer_length(b) == 1) { @@ -392,32 +392,32 @@ closure_func_basic(binding_handler, boolean, syslog_cfg, size = syslog.file_max_size * GB; break; default: - rprintf("invalid syslog file max size suffix '%c'\n", suffix); + msg_err("syslog: invalid file max size suffix '%c'", suffix); return false; } if (size < syslog.file_max_size) { /* Size value cannot be represented in 64 bits. */ - rprintf("invalid syslog file max size\n"); + msg_err("syslog: invalid file max size"); return false; } syslog.file_max_size = size; } else if (buffer_length(b) > 1) { - rprintf("invalid syslog file max size\n"); + msg_err("syslog: invalid file max size"); return false; } } else if (s == sym(file_rotate)) { if (!(is_string(v) || is_integer(v)) || !u64_from_value(v, &syslog.file_rotate)) { - rprintf("invalid syslog file rotate count\n"); + msg_err("syslog: invalid file rotate count"); return false; } else if (syslog.file_rotate > SYSLOG_FILE_ROTATE_MAX) { - rprintf("syslog file rotate count greater than %d not supported\n", + msg_err("syslog: file rotate count greater than %d not supported", SYSLOG_FILE_ROTATE_MAX); return false; } } else if (s == sym(server)) { if (!is_string(v)) { - rprintf("invalid syslog server\n"); + msg_err("syslog: invalid server"); return false; } syslog.server = buffer_to_sstring(v); @@ -425,12 +425,12 @@ closure_func_basic(binding_handler, boolean, syslog_cfg, u64 port; if (!(is_string(v) || is_integer(v)) || !u64_from_value(v, &port) || (port > U16_MAX)) { - rprintf("invalid syslog port\n"); + msg_err("syslog: invalid server port"); return false; } syslog.server_port = port; } else { - rprintf("invalid syslog option '%v'\n", s); + msg_err("syslog: invalid option '%v'", s); return false; } return true; @@ -442,7 +442,7 @@ int init(status_handler complete) tuple root = get_root_tuple(); tuple cfg = get(root, sym(syslog)); if (!cfg) { - rprintf("syslog configuration not specified\n"); + msg_err("syslog configuration not specified"); return KLIB_INIT_FAILED; } @@ -452,13 +452,13 @@ int init(status_handler complete) syslog.server_port = SYSLOG_UDP_PORT_DEFAULT; if (!is_tuple(cfg) || !iterate(cfg, stack_closure_func(binding_handler, syslog_cfg))) { - rprintf("invalid syslog configuration\n"); + msg_err("syslog: invalid configuration"); return KLIB_INIT_FAILED; } if (syslog.file_path) { syslog.fsf = fsfile_open_or_create(buffer_to_sstring(syslog.file_path), false); if (!syslog.fsf) { - rprintf("cannot create syslog output file\n"); + msg_err("syslog: cannot create output file"); return KLIB_INIT_FAILED; } syslog.fs_write = pagecache_node_get_writer(fsfile_get_cachenode(syslog.fsf)); @@ -474,7 +474,7 @@ int init(status_handler complete) buffer_length(syslog.program) + 7; syslog.udp_pcb = udp_new_ip_type(IPADDR_TYPE_ANY); if (!syslog.udp_pcb) { - rprintf("syslog: unable to create UDP PCB\n"); + msg_err("syslog: unable to create UDP PCB"); return KLIB_INIT_FAILED; } list_init(&syslog.udp_msgs); diff --git a/klib/test/lock.c b/klib/test/lock.c index a68f815b2..51c04d6cf 100644 --- a/klib/test/lock.c +++ b/klib/test/lock.c @@ -5,31 +5,31 @@ static boolean klib_test_rw_spinlock(void) struct rw_spinlock l; spin_rw_lock_init(&l); if (!spin_tryrlock(&l)) { - msg_err("couldn't rlock unlocked spinlock\n"); + msg_err("%s: couldn't rlock unlocked spinlock", func_ss); return false; } if (spin_trywlock(&l)) { - msg_err("could wlock rlocked spinlock\n"); + msg_err("%s: could wlock rlocked spinlock", func_ss); return false; } #if defined(SMP_ENABLE) if (!spin_tryrlock(&l)) { - msg_err("couldn't rlock rlocked spinlock\n"); + msg_err("%s: couldn't rlock rlocked spinlock", func_ss); return false; } spin_runlock(&l); #endif spin_runlock(&l); if (!spin_trywlock(&l)) { - msg_err("couldn't wlock unlocked spinlock\n"); + msg_err("%s: couldn't wlock unlocked spinlock", func_ss); return false; } if (spin_tryrlock(&l)) { - msg_err("could rlock wlocked spinlock\n"); + msg_err("%s: could rlock wlocked spinlock", func_ss); return false; } if (spin_trywlock(&l)) { - msg_err("could wlock wlocked spinlock\n"); + msg_err("%s: could wlock wlocked spinlock", func_ss); return false; } spin_wunlock(&l); diff --git a/klib/tmpfs.c b/klib/tmpfs.c index 9715f956f..6d0b7cf08 100644 --- a/klib/tmpfs.c +++ b/klib/tmpfs.c @@ -212,7 +212,7 @@ filesystem tmpfs_new(void) return INVALID_ADDRESS; status s = filesystem_init(&fs->fs, h, 0, 1, false); if (!is_ok(s)) { - msg_err("%v\n", s); + msg_err("%s error %v", func_ss, s); timm_dealloc(s); goto err_fsinit; } diff --git a/klib/tun.c b/klib/tun.c index a224e80f6..0e8db115e 100644 --- a/klib/tun.c +++ b/klib/tun.c @@ -251,19 +251,19 @@ static void get_tun_config(sstring name, ip4_addr_t *ipaddr, ip4_addr_t *netmask if (ipb) { sstring ip = buffer_to_sstring(ipb); if (!ip4addr_aton(ip, ipaddr)) { - rprintf("tun: invalid ipaddress %s\n", ip); + msg_err("tun: invalid ipaddress %s", ip); } } buffer nmb = get(cfg, sym(netmask)); if (nmb) { sstring nm = buffer_to_sstring(nmb); if (!ip4addr_aton(nm, netmask) || !ip4_addr_netmask_valid(netmask->addr)) { - rprintf("tun: invalid netmask %s\n", nm); + msg_err("tun: invalid netmask %s", nm); } } if (get_u64(cfg, sym(mtu), mtu)) { if (*mtu >= U64_FROM_BIT(16)) { - rprintf("tun: invalid mtu %ld; ignored\n", *mtu); + msg_err("tun: invalid mtu %ld; ignored", *mtu); *mtu = 0; } } @@ -432,7 +432,7 @@ int init(status_handler complete) return KLIB_INIT_FAILED; tun_cfg = get(root, sym(tun)); if (tun_cfg && !is_tuple(tun_cfg)) { - rprintf("invalid tun cfg\n"); + msg_err("tun: invalid configuration"); return KLIB_INIT_FAILED; } spec_file_open open = closure_func(tun_heap, spec_file_open, tun_open); diff --git a/platform/pc/pci.c b/platform/pc/pci.c index d48f12e33..c0b0cad4c 100644 --- a/platform/pc/pci.c +++ b/platform/pc/pci.c @@ -171,13 +171,13 @@ void pci_platform_init_bar(pci_dev dev, int bar) if (base & (is_io ? ~PCI_BAR_B_IOPORT_MASK : ~PCI_BAR_B_MEMORY_MASK)) return; /* BAR configured by BIOS */ if (is_io) { - msg_err("I/O port resource allocation not supported (%d:%d:%d, bar %d)\n", + msg_err("%s: I/O port resource allocation not supported (%d:%d:%d, bar %d)", func_ss, dev->bus, dev->slot, dev->function, bar); return; } id_heap iomem = pci_bus_get_iomem(dev->bus); if (!iomem) { - msg_err("I/O memory heap not available for bus %d\n", dev->bus); + msg_err("%s: I/O memory heap not available for bus %d", func_ss, dev->bus); return; } base = id_heap_alloc_subrange(iomem, @@ -188,7 +188,7 @@ void pci_platform_init_bar(pci_dev dev, int bar) if (flags & PCI_BAR_F_64BIT) pci_cfgwrite(dev, PCIR_BAR(bar + 1), 4, base >> 32); } else { - msg_err("failed to allocate I/O memory (%d:%d:%d, bar %d)\n", + msg_err("%s: failed to allocate I/O memory (%d:%d:%d, bar %d)", func_ss, dev->bus, dev->slot, dev->function, bar); } } diff --git a/platform/pc/service.c b/platform/pc/service.c index 7423cecae..15c253af6 100644 --- a/platform/pc/service.c +++ b/platform/pc/service.c @@ -212,7 +212,7 @@ void count_cpus_present(void) init_debug("ACPI reports %d processors", present_processors); return; } - rprintf("warning: ACPI MADT not found, default to 1 processor\n"); + msg_warn("ACPI MADT not found, default to 1 processor"); #endif present_processors = 1; diff --git a/platform/virt/service.c b/platform/virt/service.c index c11a939db..e726a76d2 100644 --- a/platform/virt/service.c +++ b/platform/virt/service.c @@ -528,7 +528,7 @@ void detect_devices(kernel_heaps kh, storage_attach sa) if (!is_ok(s)) halt("Hyper-V probe failed: %v\n", s); if (!hv_storvsc_attached) - msg_err("cannot detect Hyper-V storage device\n"); + msg_err("Hyper-V: cannot detect storage device"); } else { init_virtio_network(kh); init_aws_ena(kh); diff --git a/src/aarch64/interrupt.c b/src/aarch64/interrupt.c index abed048a0..905617849 100644 --- a/src/aarch64/interrupt.c +++ b/src/aarch64/interrupt.c @@ -480,7 +480,7 @@ void __attribute__((noreturn)) __stack_chk_fail(void) { cpuinfo ci = current_cpu(); context ctx = get_current_context(ci); - rprintf("stack check failed on cpu %d\n", ci->id); + msg_err("stack check failed on cpu %d", ci->id); dump_context(ctx); vm_exit(VM_EXIT_FAULT); } diff --git a/src/aarch64/rtc.c b/src/aarch64/rtc.c index 7efc8bb2b..a4a9125d4 100644 --- a/src/aarch64/rtc.c +++ b/src/aarch64/rtc.c @@ -115,7 +115,7 @@ static boolean rtc_detect(void) rtc.set_seconds = pl031_set_seconds; return true; } - rprintf("No RTC detected!\n"); + msg_err("RTC not detected"); } return !!rtc.get_seconds; } diff --git a/src/boot/elf.c b/src/boot/elf.c index c1b127ad3..998cabb8d 100644 --- a/src/boot/elf.c +++ b/src/boot/elf.c @@ -51,7 +51,7 @@ closure_function(2, 5, boolean, kernel_elf_map, } return true; alloc_fail: - msg_err("failed to allocate kernel bss mapping\n"); + msg_err("%s: failed to allocate bss mapping", func_ss); return false; } diff --git a/src/boot/uefi.c b/src/boot/uefi.c index 16ef1509c..26141a1f5 100644 --- a/src/boot/uefi.c +++ b/src/boot/uefi.c @@ -64,14 +64,14 @@ u64 random_u64() efi_status status = UBS->locate_handle_buffer(by_protocol, &uefi_rng_proto, 0, &handle_count, &handle_buffer); if (EFI_ERROR(status)) { - msg_err("failed to locate RNG handles: %d\n", status); + msg_err("%s: failed to locate RNG handles: %d", func_ss, status); return 0; } for (u64 index = 0; index < handle_count; index++) { status = UBS->open_protocol(handle_buffer[index], &uefi_rng_proto, (void **)&rng, uefi_image_handle, 0, EFI_OPEN_PROTOCOL_GET_PROTOCOL); if (EFI_ERROR(status)) - msg_err("failed to open RNG protocol: %d\n", status); + msg_err("%s: failed to open RNG protocol: %d", func_ss, status); else break; } @@ -250,7 +250,7 @@ efi_status efi_main(void *image_handle, efi_system_table system_table) efi_status status = UBS->locate_handle_buffer(by_protocol, &uefi_block_io_proto, 0, &handle_count, &handle_buffer); if (EFI_ERROR(status)) { - msg_err("failed to locate block I/O handles: %d\n", status); + msg_err("%s: failed to locate block I/O handles: %d", func_ss, status); return status; } for (u64 index = 0; index < handle_count; index++) { @@ -262,7 +262,7 @@ efi_status efi_main(void *image_handle, efi_system_table system_table) u8 mbr[SECTOR_SIZE]; status = block_io->read_blocks(block_io, block_io->media->media_id, 0, SECTOR_SIZE, &mbr); if (EFI_ERROR(status)) { - msg_err("failed to read first sector: %d\n", status); + msg_warn("%s: failed to read first sector: %d", func_ss, status); continue; } struct partition_entry *bootfs_part = partition_get(mbr, PARTITION_BOOTFS); diff --git a/src/drivers/acpi.c b/src/drivers/acpi.c index c6f2a8820..204668de3 100644 --- a/src/drivers/acpi.c +++ b/src/drivers/acpi.c @@ -102,7 +102,7 @@ closure_function(1, 0, void, acpi_eject, arg_list.Pointer = &arg; ACPI_STATUS rv = AcpiEvaluateObject(device, "_EJ0", &arg_list, NULL); if (ACPI_FAILURE(rv)) - msg_err("failed to eject device (%d)\n", rv); + msg_err("ACPI: failed to eject device (%d)", rv); closure_finish(); } @@ -119,7 +119,7 @@ static void acpi_pci_notify(ACPI_HANDLE device, UINT32 value, void *context) ACPI_STATUS rv = AcpiEvaluateObjectTyped(device, METHOD_NAME__ADR, NULL, &retb, ACPI_TYPE_INTEGER); if (ACPI_FAILURE(rv)) { - msg_err("failed to get device address (%d)\n", rv); + msg_err("%s: failed to get device address (%d)", func_ss, rv); return; } u32 adr = obj.Integer.Value; @@ -135,7 +135,7 @@ static void acpi_pci_notify(ACPI_HANDLE device, UINT32 value, void *context) if (complete != INVALID_ADDRESS) pci_remove_device(&dev, complete); else - msg_err("failed to allocate device ejection closure\n"); + msg_err("%s: failed to allocate device ejection closure", func_ss); break; } } @@ -183,7 +183,7 @@ static ACPI_STATUS acpi_device_handler(ACPI_HANDLE object, u32 nesting_level, vo if (ACPI_SUCCESS(rv)) pci_bridge_set_iomem(ctx.bridge_window, iomem); else - msg_err("cannot retrieve PCI root bridge resources: %d\n", rv); + msg_err("ACPI: cannot retrieve PCI root bridge resources: %d", rv); } ACPI_FREE(dev_info); } @@ -202,7 +202,7 @@ static ACPI_STATUS acpi_device_handler(ACPI_HANDLE object, u32 nesting_level, vo rv = AcpiInstallNotifyHandler(object, ACPI_SYSTEM_NOTIFY, acpi_pci_notify, pointer_from_u64(parent_info->Address)); if (ACPI_FAILURE(rv)) - msg_err("cannot install PCI notify handler: %d\n", rv); + msg_err("ACPI: cannot install PCI notify handler: %d", rv); } ACPI_FREE(parent_info); } @@ -229,22 +229,22 @@ static UINT32 acpi_sleep(void *context) const u64 sleep_state = 3; /* S3 state */ ACPI_STATUS rv = AcpiEnterSleepStatePrep(sleep_state); if (ACPI_FAILURE(rv)) { - msg_err("failed to prepare to sleep (%d)\n", rv); + msg_err("ACPI: failed to prepare to sleep (%d)", rv); goto exit; } rv = AcpiEnterSleepState(sleep_state); if (ACPI_FAILURE(rv)) { - msg_err("failed to enter sleep state (%d)\n", rv); + msg_err("ACPI: failed to enter sleep state (%d)", rv); goto exit; } rv = AcpiLeaveSleepStatePrep(sleep_state); if (ACPI_FAILURE(rv)) { - msg_err("failed to prepare to leave sleep state (%d)\n", rv); + msg_err("ACPI: failed to prepare to leave sleep state (%d)", rv); goto exit; } rv = AcpiLeaveSleepState(sleep_state); if (ACPI_FAILURE(rv)) - msg_err("failed to leave sleep state (%d)\n", rv); + msg_err("ACPI: failed to leave sleep state (%d)", rv); exit: return ACPI_INTERRUPT_HANDLED; } @@ -292,7 +292,7 @@ static ACPI_STATUS acpi_pwrbtn_probe(ACPI_HANDLE object, u32 nesting_level, void ACPI_STATUS rv = AcpiInstallNotifyHandler(object, ACPI_DEVICE_NOTIFY, acpi_pwrbtn_handler, NULL); if (ACPI_FAILURE(rv)) - msg_err("failed to install power button handler: %d\n", rv); + msg_err("ACPI: failed to install power button handler: %d", rv); return rv; } @@ -332,7 +332,7 @@ static ACPI_STATUS acpi_ged_res_probe(ACPI_RESOURCE *resource, void *context) default: rv = AcpiGetHandle(context, "_EVT", &event); if (ACPI_FAILURE(rv)) { - msg_err("failed to locate _EVT method: %d\n", rv); + msg_err("ACPI GED: failed to locate _EVT method: %d", rv); return rv; } } diff --git a/src/drivers/ata.c b/src/drivers/ata.c index b979de535..dd7f7e0bf 100644 --- a/src/drivers/ata.c +++ b/src/drivers/ata.c @@ -257,7 +257,7 @@ void ata_io_cmd(void * _dev, int cmd, void * buf, range blocks, status_handler s timeout: err = ss("ata_io_cmd: device timeout"); - msg_err("%s\n", err); + msg_err("%s", err); apply(s, timm_sstring(ss("result"), err)); } @@ -345,7 +345,7 @@ boolean ata_probe(struct ata *dev) // identify if (ata_wait(dev, 0) < 0) { - msg_err("drive busy\n"); + msg_err("%s: drive busy", func_ss); return false; } ata_out8(dev, ATA_COMMAND, ATA_ATA_IDENTIFY); diff --git a/src/drivers/console.c b/src/drivers/console.c index 9f8a18ac1..1c8304bc0 100644 --- a/src/drivers/console.c +++ b/src/drivers/console.c @@ -66,7 +66,7 @@ closure_function(1, 2, boolean, config_console_each, value a, value v) { if (!is_string(v)) { - msg_err("value (attr %v) not a string\n", a); + msg_err("consoles: value (attr %v) not a string", a); return false; } if (buffer_length(v) < 2) @@ -105,9 +105,9 @@ void config_console(tuple root) if (v == 0) return; if (!is_composite(v)) { - msg_err("consoles config is neither vector nor tuple\n"); + msg_err("consoles config is neither vector nor tuple"); return; } if (!iterate(v, stack_closure(config_console_each, root))) - msg_err("error parsing consoles from manifest\n"); + msg_err("consoles parsing error"); } diff --git a/src/drivers/gve.c b/src/drivers/gve.c index 6a4b69c45..1ab101e05 100644 --- a/src/drivers/gve.c +++ b/src/drivers/gve.c @@ -319,7 +319,7 @@ static boolean gve_adminq_execute_cmd(gve adapter, struct gve_adminq_command *cm { u32 index = gve_adminq_issue_cmd(adapter); if (!gve_adminq_wait(adapter, index)) { - msg_err("command %d timed out\n", be32toh(cmd->opcode)); + msg_err("%s: command %d timed out", func_ss, be32toh(cmd->opcode)); return false; } read_barrier(); @@ -544,7 +544,7 @@ closure_func_basic(thunk, void, gve_rx_service) if (length <= GVE_RX_PADDING) continue; if (desc->flags_seq & (GVE_RXF_ERR | GVE_RXF_PKT_CONT)) { - msg_err("unexpected flags 0x%x\n", desc->flags_seq); + msg_err("%s: unexpected flags 0x%x", func_ss, desc->flags_seq); continue; } u32 qpl_index = rx->qpl_head + rx->qpl_available; @@ -565,7 +565,7 @@ closure_func_basic(thunk, void, gve_rx_service) if (p) { pbuf_take(p, payload, length); } else { - msg_err("failed to allocate pbuf\n"); + msg_err("%s: failed to allocate pbuf", func_ss); continue; } } @@ -796,19 +796,19 @@ static boolean gve_init(gve adapter) pci_bar_write_4(&adapter->reg_bar, GVE_REG_ADMINQ_PFN, htobe32(physical_from_virtual(adapter->adminq) >> PAGELOG)); if (!gve_describe_device(adapter)) { - msg_err("failed to describe device\n"); + msg_err("GVE: failed to describe device"); goto err1; } if (!gve_cfg_device_resources(adapter)) { - msg_err("failed to configure device resources\n"); + msg_err("GVE: failed to configure device resources"); goto err1; } if (!gve_init_interrupts(adapter)) { - msg_err("failed to initialize interrupts\n"); + msg_err("GVE: failed to initialize interrupts"); goto err2; } if (!gve_setup_queues(adapter)) { - msg_err("failed to set up TX/RX queues\n"); + msg_err("GVE: failed to set up TX/RX queues"); goto err3; } return true; diff --git a/src/drivers/netconsole.c b/src/drivers/netconsole.c index 0c58470d2..796e7bccb 100644 --- a/src/drivers/netconsole.c +++ b/src/drivers/netconsole.c @@ -54,7 +54,7 @@ static void netconsole_config(void *_d, tuple r) netconsole_driver nd = _d; nd->pcb = udp_new_ip_type(IPADDR_TYPE_ANY); if (!nd->pcb) { - msg_err("failed to allocate pcb\n"); + msg_err("netconsole: failed to allocate pcb"); return; } @@ -62,23 +62,23 @@ static void netconsole_config(void *_d, tuple r) sstring b = dst_ip ? buffer_to_sstring(dst_ip) : ss(DEFAULT_IP); if (b.len > IPADDR_STRLEN_MAX) { - msg_err("ip address too long\n"); + msg_err("netconsole: ip address too long"); return; } if (!ipaddr_aton(b, &nd->dst_ip)) { - msg_err("failed to translate ip address\n"); + msg_err("netconsole: failed to translate ip address"); return; } buffer dst_port = get(r, sym(netconsole_port)); u64 port = DEFAULT_PORT; if (dst_port && !parse_int(dst_port, 10, &port)) { - msg_err("failed to parse port\n"); + msg_err("netconsole: failed to parse port"); return; } if (port >= U64_FROM_BIT(16)) { - msg_err("port out of range\n"); + msg_err("netconsole: port out of range"); return; } nd->port = (u16)port; diff --git a/src/drivers/nvme.c b/src/drivers/nvme.c index a77225dd0..5036016be 100644 --- a/src/drivers/nvme.c +++ b/src/drivers/nvme.c @@ -468,16 +468,16 @@ static void nvme_ns_resp_parse(nvme n, u32 ns_id, void *ns_resp, nvme_debug("identify namespace response (cmd ID %d)", NVME_CMD_ID(cqe->dw3)); int sc = NVME_STATUS_CODE(cqe->dw3); if (sc != NVME_SC_OK) { - msg_err("failed to identify namespace: status code 0x%x\n", sc); + msg_err("NVMe: failed to identify namespace: status code 0x%x", sc); for (int i = 0; i < U64_FROM_BIT(n->asq.order); i++) { struct nvme_sqe *sqe = &n->asq.ring[i]; - rprintf("sqe %x %x %x %x %x %x %x %x %x %x %x %x\n", + msg_err("\tsqe %x %x %x %x %x %x %x %x %x %x %x %x", sqe->cdw0, sqe->nsid, sqe->reserved, sqe->mptr, sqe->dptr.prp1, sqe->dptr.prp2, sqe->cdw10, sqe->cdw11, sqe->cdw12, sqe->cdw13, sqe->cdw14, sqe->cdw15); } for (int i = 0; i < U64_FROM_BIT(n->acq.order); i++) { struct nvme_cqe *cqe = &n->acq.ring[i]; - rprintf("cqe %x %x %x %x\n", cqe->dw0, cqe->dw1, cqe->dw2, cqe->dw3); + msg_err("\tcqe %x %x %x %x", cqe->dw0, cqe->dw1, cqe->dw2, cqe->dw3); } return; } @@ -488,13 +488,13 @@ static void nvme_ns_resp_parse(nvme n, u32 ns_id, void *ns_resp, u32 lbaf = *(u32 *)(ns_resp + 128 + flbas); /* LBA format */ int lbads = 1 << ((lbaf >> 16) & 0xFF); /* LBA data size */ if (lbads != SECTOR_SIZE) { - msg_err("unsupported sector size %ld", lbads); + msg_err("%s: unsupported sector size %ld", func_ss, lbads); return; } u64 disk_size = nsze * lbads; thunk ns_attach = closure(n->general, nvme_ns_attach, n, ns_id, disk_size, a); if (ns_attach == INVALID_ADDRESS) - msg_err("failed to allocate NS attach closure\n"); + msg_err("%s: failed to allocate NS attach closure", func_ss); else async_apply_bh(ns_attach); } @@ -565,7 +565,7 @@ closure_function(3, 1, void, nvme_identify_controller_resp, void *resp = bound(resp); int sc = NVME_STATUS_CODE(cqe->dw3); if (sc != NVME_SC_OK) { - msg_err("failed to identify controller: status code 0x%x\n", sc); + msg_err("NVMe: failed to identify controller: status code 0x%x", sc); goto error; } u16 vid = *(u16 *)resp; /* PCI Vendor ID */ @@ -594,7 +594,7 @@ closure_function(3, 1, void, nvme_identify_controller_resp, nvme_ns_query_next(n, 1, nn, resp); goto done; } else { - msg_err("failed to allocate completion handler\n"); + msg_err("%s: failed to allocate completion handler", func_ss); } error: deallocate(n->contiguous, resp, NVME_IDENTIFY_RESP_SIZE); @@ -606,12 +606,12 @@ static boolean nvme_identify_controller(nvme n, storage_attach a) { void *resp = allocate(n->contiguous, NVME_IDENTIFY_RESP_SIZE); if (resp == INVALID_ADDRESS) { - msg_err("failed to allocate response\n"); + msg_err("%s: failed to allocate response", func_ss); return false; } n->ac_handler = closure(n->general, nvme_identify_controller_resp, n, resp, a); if (n->ac_handler == INVALID_ADDRESS) { - msg_err("failed to allocate completion handler\n"); + msg_err("%s: failed to allocate completion handler", func_ss); deallocate(n->contiguous, resp, NVME_IDENTIFY_RESP_SIZE); return false; } @@ -633,12 +633,12 @@ closure_function(3, 1, void, nvme_get_active_namespaces_resp, void *resp = bound(resp); int sc = NVME_STATUS_CODE(cqe->dw3); if (sc != NVME_SC_OK) { - msg_err("failed to get active namespaces: status code 0x%x\n", sc); + msg_err("NVMe: failed to get active namespaces: status code 0x%x", sc); goto error; } void *ns_resp = allocate(n->contiguous, NVME_IDENTIFY_RESP_SIZE); if (ns_resp == INVALID_ADDRESS) { - msg_err("failed to allocate namespace data response\n"); + msg_err("%s: failed to allocate namespace data response", func_ss); goto error; } n->ac_handler = closure(n->general, nvme_ns_query_resp_active, n, resp, 0, ns_resp, bound(a)); @@ -646,7 +646,7 @@ closure_function(3, 1, void, nvme_get_active_namespaces_resp, nvme_ns_query_next_active(n, resp, 0, ns_resp); goto done; } else { - msg_err("failed to allocate completion handler\n"); + msg_err("%s: failed to allocate completion handler", func_ss); deallocate(n->contiguous, ns_resp, NVME_IDENTIFY_RESP_SIZE); } error: @@ -659,12 +659,12 @@ static boolean nvme_get_active_namespaces(nvme n, u32 start_id, storage_attach a { void *resp = allocate(n->contiguous, NVME_IDENTIFY_RESP_SIZE); if (resp == INVALID_ADDRESS) { - msg_err("failed to allocate response\n"); + msg_err("%s: failed to allocate response", func_ss); return false; } n->ac_handler = closure(n->general, nvme_get_active_namespaces_resp, n, resp, a); if (n->ac_handler == INVALID_ADDRESS) { - msg_err("failed to allocate completion handler\n"); + msg_err("%s: failed to allocate completion handler", func_ss); deallocate(n->contiguous, resp, NVME_IDENTIFY_RESP_SIZE); return false; } @@ -693,7 +693,7 @@ closure_function(2, 1, void, nvme_create_iosq_resp, else nvme_identify_controller(n, a); } else { - msg_err("failed to create I/O SQ: status code 0x%x\n", sc); + msg_err("NVMe: failed to create I/O SQ: status code 0x%x", sc); } closure_finish(); } @@ -701,12 +701,12 @@ closure_function(2, 1, void, nvme_create_iosq_resp, static boolean nvme_create_iosq(nvme n, storage_attach a) { if (!nvme_init_sq(n, &n->iosq, n->ioq_order)) { - msg_err("failed to initialize queue\n"); + msg_err("NVMe: failed to initialize I/O SQ"); return false; } n->ac_handler = closure(n->general, nvme_create_iosq_resp, n, a); if (n->ac_handler == INVALID_ADDRESS) { - msg_err("failed to allocate completion handler\n"); + msg_err("%s: failed to allocate completion handler", func_ss); nvme_deinit_sq(n, &n->iosq); return false; } @@ -737,7 +737,7 @@ closure_function(2, 1, void, nvme_create_iocq_resp, nvme_debug("I/O CQ created"); nvme_create_iosq(n, bound(a)); } else { - msg_err("failed to create I/O CQ: status code 0x%x\n", sc); + msg_err("NVMe: failed to create I/O CQ: status code 0x%x", sc); } closure_finish(); } @@ -745,18 +745,18 @@ closure_function(2, 1, void, nvme_create_iocq_resp, static boolean nvme_create_iocq(nvme n, storage_attach a) { if (!nvme_init_cq(n, &n->iocq, n->ioq_order)) { - msg_err("failed to initialize queue\n"); + msg_err("NVMe: failed to initialize I/O CQ"); return false; } n->ac_handler = closure(n->general, nvme_create_iocq_resp, n, a); if (n->ac_handler == INVALID_ADDRESS) { - msg_err("failed to allocate completion handler\n"); + msg_err("%s: failed to allocate completion handler", func_ss); nvme_deinit_cq(n, &n->iocq); return false; } if (pci_setup_msix(n->d, NVME_IOQ_MSIX, init_closure_func(&n->io_irq, thunk, nvme_io_irq), ss("nvme I/O")) == INVALID_PHYSICAL) { - msg_err("failed to allocate MSI-X vector\n"); + msg_err("%s: failed to allocate MSI-X vector", func_ss); return false; } struct nvme_sqe *cmd = nvme_get_sqe(&n->asq); @@ -812,7 +812,7 @@ closure_function(3, 1, boolean, nvme_probe, if (retries++ <= 8) { kernel_delay(milliseconds(1 << retries)); } else { - msg_err("failed to reset controller\n"); + msg_err("%s: failed to reset controller", func_ss); goto deinit_acq; } } @@ -828,7 +828,7 @@ closure_function(3, 1, boolean, nvme_probe, NVME_VS_MJR(n->vs), NVME_VS_MNR(n->vs), NVME_VS_TER(n->vs), mqes, n->ioq_order); n->cmds = allocate_vector(general, NVME_CID_MAX + 1); if (n->cmds == INVALID_ADDRESS) { - msg_err("failed to allocate request vector\n"); + msg_err("%s: failed to allocate request vector", func_ss); goto deinit_acq; } pci_bar_write_4(&n->bar, NVME_AQA, NVME_AQA_ACQS(U64_FROM_BIT(NVME_ACQ_ORDER)) | @@ -844,7 +844,7 @@ closure_function(3, 1, boolean, nvme_probe, if (retries++ <= 8) { kernel_delay(milliseconds(1 << retries)); } else { - msg_err("failed to enable controller\n"); + msg_err("%s: failed to enable controller", func_ss); goto free_cmds; } } @@ -852,7 +852,7 @@ closure_function(3, 1, boolean, nvme_probe, pci_enable_msix(d); if (pci_setup_msix(d, NVME_AQ_MSIX, init_closure_func(&n->admin_irq, thunk, nvme_admin_irq), ss("nvme admin")) == INVALID_PHYSICAL) { - msg_err("failed to allocate MSI-X vector\n"); + msg_err("%s: failed to allocate MSI-X vector", func_ss); goto free_cmds; } n->attach_id = -1; @@ -904,7 +904,7 @@ closure_func_basic(pci_remove, void, nvme_remove, if (nvme_complete != INVALID_ADDRESS) storage_detach((storage_req_handler)&n->req_handler, nvme_complete); else - msg_err("failed to allocate completion closure\n"); + msg_err("%s: failed to allocate completion closure", func_ss); } void init_nvme(kernel_heaps kh, storage_attach a) diff --git a/src/fs/9p.c b/src/fs/9p.c index 37a792128..3603424e4 100644 --- a/src/fs/9p.c +++ b/src/fs/9p.c @@ -205,7 +205,7 @@ closure_func_basic(status_handler, void, p9fsf_sync_complete, status s) { if (!is_ok(s)) { - msg_err("failed to sync page cache node: %v\n", s); + msg_err("9p: failed to sync page cache node: %v", s); timm_dealloc(s); } fsfile f = struct_from_closure(fsfile, sync_complete); diff --git a/src/fs/fs.c b/src/fs/fs.c index ebada543f..04c9c27ed 100644 --- a/src/fs/fs.c +++ b/src/fs/fs.c @@ -435,7 +435,7 @@ closure_func_basic(status_handler, void, fs_free, status s) { if (!is_ok(s)) { - msg_warn("failed to flush filesystem: %v\n", s); + msg_warn("filesystem failed to flush: %v", s); timm_dealloc(s); } filesystem fs = struct_from_closure(filesystem, free); @@ -1095,7 +1095,7 @@ int filesystem_resolve_sstring(filesystem *fs, tuple cwd, sstring f, tuple *entr while (!sstring_is_empty(f)) { c = utf8_decode(f, &nbytes); if (!nbytes) { - msg_err("Invalid UTF-8 sequence.\n"); + msg_warn("%s: invalid UTF-8 sequence", func_ss); err = -ENOENT; p = false; goto done; diff --git a/src/fs/tfs.c b/src/fs/tfs.c index 6ee56f5ef..62aea4ef5 100644 --- a/src/fs/tfs.c +++ b/src/fs/tfs.c @@ -154,7 +154,7 @@ void ingest_extent(tfsfile f, symbol off, tuple value) tfs fs = tfs_from_file(f); if (!filesystem_reserve_storage(fs, storage_blocks)) { /* soft error... */ - msg_err("unable to reserve storage blocks %R\n", storage_blocks); + msg_err("TFS %s: unable to reserve storage blocks %R", func_ss, storage_blocks); } range r = irangel(file_offset, length); extent ex = allocate_extent(fs->fs.h, r, storage_blocks); @@ -427,7 +427,7 @@ static void destroy_extent(tfs fs, extent ex) { range q = irangel(ex->start_block, ex->allocated); if (!filesystem_free_storage(fs, q)) - msg_err("failed to mark extent at %R as free", q); + msg_err("TFS: failed to mark extent at %R as free", q); if (ex->uninited && ex->uninited != INVALID_ADDRESS) refcount_release(&ex->uninited->refcount); deallocate(fs->fs.h, ex, sizeof(*ex)); @@ -1069,7 +1069,7 @@ int filesystem_mkentry(filesystem fs, tuple cwd, sstring fp, tuple entry, boolea continue; } - msg_err("a path component (\"%s\") is missing\n", token); + msg_err("%s: a path component (\"%s\") is missing", func_ss, token); status = -ENOENT; break; } @@ -1237,7 +1237,7 @@ closure_func_basic(status_handler, void, tfsfile_sync_complete, status s) { if (!is_ok(s)) { - msg_err("failed to purge page cache node: %v\n", s); + msg_err("TFS: failed to purge page cache node: %v", s); timm_dealloc(s); } tfsfile f = (tfsfile)struct_from_closure(fsfile, sync_complete); diff --git a/src/fs/tlog.c b/src/fs/tlog.c index 14338561d..2dfdd7a3c 100644 --- a/src/fs/tlog.c +++ b/src/fs/tlog.c @@ -502,7 +502,7 @@ closure_function(2, 1, void, log_switch_complete, rangemap_foreach(to_be_destroyed->extensions, ext) { tlog_debug(" deallocating extension at %R\n", __func__, ext->r); if (!filesystem_free_storage(fs, ext->r)) - msg_err("failed to mark to_be_destroyed log at %R as free", ext->r); + msg_err("tlog: failed to mark to_be_destroyed log at %R as free", ext->r); } run_flush_completions(old_tl, s); @@ -578,7 +578,7 @@ void log_flush(log tl, status_handler completion) fail_log_ext_close: close_log_extension(new_ext); if (!filesystem_free_storage(fs, new_ext->sectors)) - msg_err("failed to mark new_ext at %R as free", new_ext->sectors); + msg_err("tlog: failed to mark new_ext at %R as free", new_ext->sectors); fail_log_destroy: log_destroy(new_tl); } @@ -886,7 +886,7 @@ log log_create(heap h, tfs fs, boolean initialize, status_handler sh) #ifndef TLOG_READ_ONLY range sectors = irange(0, TFS_LOG_INITIAL_SIZE >> fs->fs.blocksize_order); if (!filesystem_reserve_storage(fs, sectors)) { - msg_err("failed to reserve sectors in allocation map"); + msg_err("tlog: failed to reserve sectors in allocation map"); return INVALID_ADDRESS; } #endif diff --git a/src/gdb/gdbstub.c b/src/gdb/gdbstub.c index 8e4e33e04..1095f9a8a 100644 --- a/src/gdb/gdbstub.c +++ b/src/gdb/gdbstub.c @@ -447,7 +447,7 @@ static boolean handle_request(gdb g, buffer b, buffer output) if (breakpoint_remove(g->h, addr, closure(g->h, send_ok, g))) return false; else { - rprintf("hardware breakpoint could not be found\n"); + msg_err("gdbserver: hardware breakpoint could not be found"); bprintf(output, "E08"); } } @@ -462,7 +462,7 @@ static boolean handle_request(gdb g, buffer b, buffer output) check(b, ','); parse_hex_pair(b, &addr, &length); if (addr >= USER_LIMIT) { - rprintf("kernel breakpoints not currently allowed\n"); + msg_err("gdbserver: kernel breakpoints not currently allowed"); bprintf(output, "E08"); break; } @@ -472,7 +472,7 @@ static boolean handle_request(gdb g, buffer b, buffer output) if (breakpoint_insert(g->h, addr, 0, 8, closure(g->h, send_ok, g))) return false; else { - rprintf("maximum number of hardware breakpoints reached\n"); + msg_err("gdbserver: maximum number of hardware breakpoints reached"); bprintf(output, "E08"); } } diff --git a/src/gdb/gdbutil.c b/src/gdb/gdbutil.c index a4107075f..94bc8aeec 100644 --- a/src/gdb/gdbutil.c +++ b/src/gdb/gdbutil.c @@ -76,7 +76,7 @@ void putpacket_deferred(gdb g, string b) u64 flags = spin_lock_irq(&g->send_lock); if (g->sending) { spin_unlock_irq(&g->send_lock, flags); - rprintf("putpacket_deferred dropped, already sending\n"); + msg_err("gdbserver: %s dropped, already sending", func_ss); return; } g->sending = true; @@ -90,7 +90,7 @@ void putpacket(gdb g, string b) u64 flags = spin_lock_irq(&g->send_lock); if (g->sending) { spin_unlock_irq(&g->send_lock, flags); - rprintf("putpacket dropped, already sending\n"); + msg_err("gdbserver: %s dropped, already sending", func_ss); return; } put_sendstring(g, b); diff --git a/src/http/http.c b/src/http/http.c index da91a7146..af05dc533 100644 --- a/src/http/http.c +++ b/src/http/http.c @@ -254,7 +254,7 @@ closure_function(1, 1, status, http_recv, if (x == '\r') { if (p->s == sym(Content-Length)) { if (!parse_int(p->word, 10, &p->content_length)) - msg_err("failed to parse content length\n"); + msg_err("%s: failed to parse content length", func_ss); /* unconsume the bytes consumed by parse_int() */ p->word->start = 0; diff --git a/src/hyperv/netvsc/netvsc.c b/src/hyperv/netvsc/netvsc.c index 3c5b9492d..9d2f06e4c 100644 --- a/src/hyperv/netvsc/netvsc.c +++ b/src/hyperv/netvsc/netvsc.c @@ -289,7 +289,7 @@ closure_function(1, 3, boolean, netvsc_probe, { status s = netvsc_attach(bound(kh), device); if (!is_ok(s)) { - msg_err("attach failed with status %v\n", s); + msg_err("netvsc attach failed with status %v", s); return false; } return true; @@ -404,7 +404,7 @@ netvsc_recv(struct hv_device *device_ctx, netvsc_packet *packet) err_enum_t err = n->input((struct pbuf *)x, n); if (err != ERR_OK) { - msg_err("netvsc: rx drop by stack, err %d\n", err); + msg_err("netvsc: rx drop by stack, err %d", err); receive_buffer_release((struct pbuf *)x); } return 0; diff --git a/src/hyperv/storvsc/storvsc.c b/src/hyperv/storvsc/storvsc.c index dc7208fac..18396e4cf 100644 --- a/src/hyperv/storvsc/storvsc.c +++ b/src/hyperv/storvsc/storvsc.c @@ -521,7 +521,7 @@ static int hv_storvsc_io_request(struct storvsc_softc *sc, struct hv_storvsc_req } if (ret != 0) { - rprintf("Unable to send packet %p ret %d", vstor_packet, ret); + msg_err("storvsc: unable to send packet %p, ret %d", vstor_packet, ret); } else { fetch_and_add_32(&sc->hs_num_out_reqs, 1); } @@ -1308,7 +1308,7 @@ closure_function(1, 3, boolean, storvsc_probe, { status s = storvsc_attach(bound(kh), device, a); if (!is_ok(s)) { - msg_err("attach failed with status %v\n", s); + msg_err("storvsc attach failed with status %v", s); return false; } *storvsc_attached = true; diff --git a/src/hyperv/utilities/vmbus_shutdown.c b/src/hyperv/utilities/vmbus_shutdown.c index cfdd084b0..d12cb6dc4 100644 --- a/src/hyperv/utilities/vmbus_shutdown.c +++ b/src/hyperv/utilities/vmbus_shutdown.c @@ -135,7 +135,7 @@ closure_function(1, 3, boolean, vmbus_shutdown_probe, { status s = vmbus_shutdown_attach(bound(kh), device); if (!is_ok(s)) { - msg_err("attach failed with status %v\n", s); + msg_err("vmbus_shutdown attach failed with status %v", s); return false; } return true; diff --git a/src/hyperv/vmbus/hyperv.c b/src/hyperv/vmbus/hyperv.c index 6fcabcc7f..28864ccf2 100644 --- a/src/hyperv/vmbus/hyperv.c +++ b/src/hyperv/vmbus/hyperv.c @@ -106,7 +106,7 @@ init_vmbus(kernel_heaps kh) status s = vmbus_attach(kh, &hyperv_info.vmbus); if (!is_ok(s)) { - msg_err("attach failed with status %v\n", s); + msg_err("vmbus attach failed with status %v", s); return; } diff --git a/src/hyperv/vmbus/vmbus_xact.c b/src/hyperv/vmbus/vmbus_xact.c index 4126e8207..2bd92fcb8 100644 --- a/src/hyperv/vmbus/vmbus_xact.c +++ b/src/hyperv/vmbus/vmbus_xact.c @@ -223,7 +223,7 @@ vmbus_xact_return(struct vmbus_xact *xact, size_t *resp_len) * Orphaned and no response was received yet; fake up * an one byte response. */ - rprintf("vmbus: xact ctx was orphaned w/ pending xact\n"); + msg_err("vmbus: xact ctx was orphaned w/ pending xact"); vmbus_xact_save_resp(ctx->xc_active, &b, sizeof(b)); } assert(xact->x_resp != NULL); //no response @@ -324,7 +324,7 @@ vmbus_xact_save_resp(struct vmbus_xact *xact, const void *data, size_t dlen) size_t cplen = dlen; if (cplen > ctx->xc_resp_size) { - rprintf("vmbus: xact response truncated %zu -> %zu\n", + msg_warn("vmbus: xact response truncated %zu -> %zu", cplen, ctx->xc_resp_size); cplen = ctx->xc_resp_size; } @@ -349,7 +349,7 @@ vmbus_xact_wakeup(struct vmbus_xact *xact, const void *data, size_t dlen) vmbus_xact_save_resp(xact, data, dlen); } else { assert(ctx->xc_flags & VMBUS_XACT_CTXF_DESTROY); //no active xact pending - rprintf("vmbus: drop xact response\n"); + msg_warn("vmbus: drop xact response"); } spin_unlock_irq(&ctx->xc_lock, flags); } diff --git a/src/kernel/elf.c b/src/kernel/elf.c index dc9bff33f..2ab4e7689 100644 --- a/src/kernel/elf.c +++ b/src/kernel/elf.c @@ -55,7 +55,7 @@ void elf_symbols(buffer elf, elf_sym_handler each) } if (!symbols || !symbol_strings) { - msg_warn("failed: symtab not found\n"); + msg_warn("%s failed: symtab not found", func_ss); return; } @@ -70,7 +70,7 @@ void elf_symbols(buffer elf, elf_sym_handler each) } return; out_elf_fail: - msg_err("failed to parse elf file, len %d; check file image consistency\n", buffer_length(elf)); + msg_err("%s: failed to parse file, len %d", func_ss, buffer_length(elf)); } closure_function(6, 1, boolean, elf_sym_relocate, @@ -170,7 +170,7 @@ boolean elf_dyn_parse(buffer elf, Elf64_Shdr **symtab, Elf64_Shdr **strtab, Elf6 ELF_CHECK_PTR(*strtab, Elf64_Shdr); return true; out_elf_fail: - msg_err("failed to parse elf, len %d\n", buffer_length(elf)); + msg_err("%s failed, len %d", func_ss, buffer_length(elf)); return false; } @@ -313,8 +313,8 @@ void *load_elf(buffer elf, u64 load_offset, elf_map_handler mapper) p->p_memsz - p->p_filesz, flags); if (!apply(mapper, p->p_vaddr + load_offset, p->p_offset, p->p_filesz, p->p_memsz - p->p_filesz, flags)) { - msg_err("call to mapper %F failed (vaddr 0x%lx, offset 0x%lx, " - "data size 0x%lx, bss size 0x%lx, flags 0x%lx)\n", + msg_err("elf load: call to mapper %F failed (vaddr 0x%lx, offset 0x%lx, " + "data size 0x%lx, bss size 0x%lx, flags 0x%lx)", mapper, p->p_vaddr + load_offset, p->p_offset, p->p_filesz, p->p_memsz - p->p_filesz, flags); goto out_elf_fail; @@ -324,7 +324,7 @@ void *load_elf(buffer elf, u64 load_offset, elf_map_handler mapper) elf_debug(" done; entry 0x%lx\n", entry); return pointer_from_u64(entry); out_elf_fail: - msg_err("failed to parse elf file, len %d; check file image consistency\n", buffer_length(elf)); + msg_err("elf load: failed to parse file, len %d", buffer_length(elf)); return INVALID_ADDRESS; } diff --git a/src/kernel/init.c b/src/kernel/init.c index 9237e221f..6ba3cd9d3 100644 --- a/src/kernel/init.c +++ b/src/kernel/init.c @@ -231,7 +231,7 @@ closure_function(1, 1, void, kern_start, thunk stage3 = bound(stage3); apply(stage3); } else { - msg_err("%v\n", s); + msg_err("%s error %v", func_ss, s); timm_dealloc(s); } closure_finish(); @@ -266,6 +266,9 @@ closure_function(4, 2, void, fsstarted, tuple root = (tuple)wrapped_root; boot_params_apply(root); reclaim_regions(); /* for pc: no accessing regions after this point */ + string klog_level = get_string(root, sym_this("log_level")); + if (klog_level) + klog_set_level(klog_level); tuple mounts = get_tuple(root, sym(mounts)); if (mounts) storage_set_mountpoints(mounts); @@ -551,7 +554,7 @@ closure_function(6, 1, void, mbr_read, { init_debug("%s", func_ss); if (!is_ok(s)) { - msg_err("unable to read partitions: %v\n", s); + msg_err("storage: unable to read partitions: %v", s); goto out; } u8 *mbr = bound(mbr); @@ -567,9 +570,9 @@ closure_function(6, 1, void, mbr_read, if (fs_init != INVALID_ADDRESS) volume_add(uuid, label, req_handler, fs_init, bound(attach_id)); else - msg_err("failed to allocate closure, skipping volume\n"); + msg_err("storage: failed to allocate closure, skipping volume"); } else { - msg_err("failed to probe filesystem: %v\n", get(s, sym_this("result"))); + msg_err("storage: failed to probe filesystem: %v", get(s, sym_this("result"))); timm_dealloc(s); } deallocate((heap)heap_linear_backed(init_heaps), mbr, PAGESIZE); @@ -594,13 +597,13 @@ closure_function(2, 3, void, attach_storage, /* Read partition table from disk, use backed heap for guaranteed alignment */ u8 *mbr = allocate(bh, PAGESIZE); if (mbr == INVALID_ADDRESS) { - msg_err("cannot allocate memory for MBR sector\n"); + msg_err("storage: cannot allocate memory for MBR sector"); return; } status_handler sh = closure(h, mbr_read, mbr, req_handler, length, attach_id, bound(start), bound(complete)); if (sh == INVALID_ADDRESS) { - msg_err("cannot allocate MBR read closure\n"); + msg_err("storage: cannot allocate MBR read closure"); deallocate(bh, mbr, PAGESIZE); return; } @@ -735,7 +738,7 @@ closure_function(3, 1, void, storage_shutdown, status s) { if (!is_ok(s)) { - rprintf("%b\n", get_string(s, sym(result))); + msg_err("%s error: %b", func_ss, get_string(s, sym(result))); timm_dealloc(s); } int status = bound(status); diff --git a/src/kernel/klib.c b/src/kernel/klib.c index 893aae43c..94c59150f 100644 --- a/src/kernel/klib.c +++ b/src/kernel/klib.c @@ -99,7 +99,7 @@ closure_function(2, 5, boolean, klib_elf_map, } return true; alloc_fail: - msg_err("failed to allocate klib mapping\n"); + msg_err("%s: failed to allocate mapping", func_ss); return false; } diff --git a/src/kernel/kvm_platform.c b/src/kernel/kvm_platform.c index 78eeb9796..c085b102d 100644 --- a/src/kernel/kvm_platform.c +++ b/src/kernel/kvm_platform.c @@ -43,7 +43,7 @@ static boolean probe_kvm_pvclock(kernel_heaps kh, u32 cpuid_fn) kvm_debug("after write msr"); if (vc->system_time == 0) { /* noise, but we should know if this happens */ - msg_err("kvm pvclock probe failed: detected kvm pvclock, but system_time == 0\n"); + msg_err("kvm pvclock probe failed: detected kvm pvclock, but system_time == 0"); return false; } init_pvclock(heap_general(kh), vc, (struct pvclock_wall_clock *)(vc + 1)); @@ -65,7 +65,7 @@ boolean kvm_detect(kernel_heaps kh) if (fn == KVM_CPUID_END) return false; if (!probe_kvm_pvclock(kh, fn)) { - msg_err("unable to probe pvclock\n"); + msg_err("kvm: unable to probe pvclock"); return false; } diff --git a/src/kernel/lockstats.c b/src/kernel/lockstats.c index 491b00fbf..5170f580e 100644 --- a/src/kernel/lockstats.c +++ b/src/kernel/lockstats.c @@ -185,7 +185,7 @@ static boolean log_output(pqueue pq, buffer b) return true; } -#define catch_err(s) do {if (!is_ok(s)) msg_err("lockstat: failed to send HTTP response: %v\n", (s));} while(0) +#define catch_err(s) do {if (!is_ok(s)) msg_err("lockstats: failed to send HTTP response: %v", (s));} while(0) static void lockstats_send_http_response(http_responder handler, buffer b) @@ -281,7 +281,7 @@ init_http_listener(void) lockstats_hl = allocate_http_listener(lockstats_heap, LOCKSTATS_PORT); if (lockstats_hl == INVALID_ADDRESS) { - msg_err("could not allocate lock stat HTTP listener\n"); + msg_err("lockstats: could not allocate HTTP listener"); return -1; } @@ -295,14 +295,14 @@ init_http_listener(void) connection_handler_from_http_listener(lockstats_hl) ); if (!is_ok(s)) { - msg_err("listen_port(port=%d) failed for lockstat HTTP listener\n", + msg_err("lockstats: listen_port(port=%d) failed", LOCKSTATS_PORT ); deallocate_http_listener(lockstats_heap, lockstats_hl); return -1; } - rprintf("started lockstat http listener on port %d\n", LOCKSTATS_PORT); + msg_info("lockstats: started HTTP listener on port %d", LOCKSTATS_PORT); return 0; } @@ -320,5 +320,5 @@ void lockstats_init(kernel_heaps kh) } int ret = init_http_listener(); if (ret != 0) - msg_err("failed to start http listener\n"); + msg_err("lockstats: failed to start HTTP listener"); } diff --git a/src/kernel/log.c b/src/kernel/log.c index d79ae0263..810540492 100644 --- a/src/kernel/log.c +++ b/src/kernel/log.c @@ -48,6 +48,7 @@ static struct { u64 disk_offset; storage_req_handler disk_handler; closure_struct(klog_load_sh, load_sh); + enum log_level level; } klog __attribute__ ((aligned(SECTOR_SIZE))); #define klog_lock() u64 _irqflags = spin_lock_irq(&klog.lock) @@ -144,3 +145,34 @@ void klog_dump_clear(void) }; apply(klog.disk_handler, &req); } + +void klog_set_level(string level) +{ + if (!buffer_strcmp(level, "info")) + klog.level = LOG_INFO; + else if (!buffer_strcmp(level, "warn")) + klog.level = LOG_WARN; + else if (!buffer_strcmp(level, "err")) + klog.level = LOG_ERR; + else + msg_err("log_level: invalid value '%b'", level); +} + +boolean klog_level_enabled(enum log_level level) +{ + return (level <= klog.level); +} + +void log_printf(enum log_level level, sstring fmt, ...) +{ + if (level <= klog.level) { + vlist a; + vstart(a, fmt); + buffer b = little_stack_buffer(1024); + bprintf(b, "[%T] ", now(CLOCK_ID_BOOTTIME)); + vbprintf(b, fmt, &a); + vend(a); + push_u8(b, '\n'); + buffer_print(b); + } +} diff --git a/src/kernel/log.h b/src/kernel/log.h index 853dfc3b5..9cc857549 100644 --- a/src/kernel/log.h +++ b/src/kernel/log.h @@ -11,6 +11,8 @@ typedef struct klog_dump { char msgs[KLOG_DUMP_SIZE - 16]; /* total size of the struct must match KLOG_DUMP_SIZE */ } __attribute__((packed)) *klog_dump; +#ifdef KERNEL + void klog_write(const char *s, bytes count); void klog_disk_setup(u64 disk_offset, storage_req_handler req_handler); @@ -18,3 +20,8 @@ void klog_set_boot_id(u64 id); void klog_load(klog_dump dest, status_handler sh); void klog_save(int exit_code, status_handler sh); void klog_dump_clear(void); + +void klog_set_level(string level); +boolean klog_level_enabled(enum log_level level); + +#endif diff --git a/src/kernel/ltrace.c b/src/kernel/ltrace.c index 1bd5caf7f..1359eccb7 100644 --- a/src/kernel/ltrace.c +++ b/src/kernel/ltrace.c @@ -117,7 +117,7 @@ void ltrace_init(value cfg, buffer exe, u64 load_offset) if (!elf_dyn_parse(exe, &symtab, &strtab, &reltab, &relcount)) halt("ltrace: failed to parse dynamic section\n"); if (!symtab || !strtab || !reltab) { - rprintf("ltrace: not a dynamically linked executable\n"); + msg_err("ltrace: not a dynamically linked executable"); return; } u64 plt_addr, plt_offset, plt_size; diff --git a/src/kernel/management_telnet.c b/src/kernel/management_telnet.c index 32b88a0fb..e8fb389c8 100644 --- a/src/kernel/management_telnet.c +++ b/src/kernel/management_telnet.c @@ -45,5 +45,5 @@ void init_management_telnet(heap h, value meta) { // XXX config port listen_port(h, 9090, closure(h, each_telnet_connection, h)); - rprintf("Debug telnet server started on port 9090\n"); + msg_info("Debug telnet server started on port 9090"); } diff --git a/src/kernel/page.c b/src/kernel/page.c index 7f4de7dc9..af1245616 100644 --- a/src/kernel/page.c +++ b/src/kernel/page.c @@ -75,7 +75,7 @@ void *allocate_table_page(u64 *phys) page_init_debug(" [new alloc, pa: "); u64 pa = allocate_u64(pagemem.pageheap, PAGEMEM_ALLOC_SIZE); if (pa == INVALID_PHYSICAL) { - msg_err("failed to allocate page table memory\n"); + msg_err("page table: failed to allocate memory"); return INVALID_ADDRESS; } page_init_debug_u64(pa); @@ -485,7 +485,6 @@ static boolean map_level(u64 *table_ptr, int level, range v, u64 *p, u64 flags, void *tp; u64 tp_phys; if ((tp = allocate_table_page(&tp_phys)) == INVALID_ADDRESS) { - msg_err("failed to allocate page table memory\n"); return false; } /* user and writable are AND of flags from all levels */ @@ -559,7 +558,6 @@ void map(u64 v, physical p, u64 length, pageflags flags) u64 *table_ptr = pointer_from_pteaddr(get_pagetable_base(v)); if (!map_level(table_ptr, PT_FIRST_LEVEL, r, &p, flags.w, fe)) { pagetable_unlock(); - rprintf("ra %p\n", __builtin_return_address(0)); print_frame_trace_from_here(); halt("map failed for v 0x%lx, p 0x%lx, len 0x%lx, flags 0x%lx\n", v, p, length, flags.w); diff --git a/src/kernel/page_backed_heap.c b/src/kernel/page_backed_heap.c index 3708990e8..8e408dbdc 100644 --- a/src/kernel/page_backed_heap.c +++ b/src/kernel/page_backed_heap.c @@ -15,7 +15,7 @@ void page_backed_dealloc_virtual(backed_heap bh, u64 x, bytes length) page_backed_heap pbh = (page_backed_heap)bh; u64 padlen = pad(length, pbh->bh.h.pagesize); if (x & (pbh->bh.h.pagesize - 1)) { - msg_err("attempt to free unaligned area at %lx, length %x; leaking\n", x, length); + msg_err("%s error: unaligned area at %lx, length %x; leaking", func_ss, x, length); return; } @@ -48,7 +48,7 @@ static inline void page_backed_dealloc_unmap(backed_heap bh, void *virt, u64 phy { page_backed_heap pbh = (page_backed_heap)bh; if (u64_from_pointer(virt) & (pbh->bh.h.pagesize - 1)) { - msg_err("attempt to free unaligned area at %lx, length %x; leaking\n", virt, len); + msg_err("%s error: unaligned area at %lx, length %x; leaking", func_ss, virt, len); return; } if (phys == 0) { diff --git a/src/kernel/pagecache.c b/src/kernel/pagecache.c index 0596ab04c..0186852a2 100644 --- a/src/kernel/pagecache.c +++ b/src/kernel/pagecache.c @@ -280,7 +280,7 @@ closure_function(3, 1, void, pagecache_read_page_complete, if (!is_ok(s)) { /* TODO need policy for capturing/reporting I/O errors... */ - msg_err("error reading page 0x%lx: %v\n", page_offset(pp) << pc->page_order, s); + msg_err("pagecache: error reading page 0x%lx: %v", page_offset(pp) << pc->page_order, s); } pagecache_lock_state(pc); change_page_state_locked(bound(pc), pp, PAGECACHE_PAGESTATE_NEW); @@ -951,7 +951,7 @@ define_closure_function(3, 1, void, pagecache_commit_dirty_ranges, rp->end = MIN(rp->end, limit); sg_list sg = allocate_sg_list(); if (sg == INVALID_ADDRESS) { - msg_err("unable to allocate sg list\n"); + msg_err("%s: unable to allocate sg list", func_ss); if (committing == 0) s = timm("result", "unable to allocate sg list"); break; @@ -973,7 +973,7 @@ define_closure_function(3, 1, void, pagecache_commit_dirty_ranges, } else { sgb = sg_list_tail_add(sg, len); if (sgb == INVALID_ADDRESS) { - msg_warn("sgbuf alloc fail\n"); + msg_warn("%s: sgbuf alloc fail", func_ss); if (committing == 0) s = timm("result", "unable to allocate sg buffer"); r.end = start; diff --git a/src/kernel/pci.c b/src/kernel/pci.c index 5a7521150..2ff5e7d4c 100644 --- a/src/kernel/pci.c +++ b/src/kernel/pci.c @@ -273,7 +273,7 @@ void pci_probe_device(pci_dev dev) if (dev_index < 0) { pci_dev new_dev = allocate(devices->h, sizeof(*new_dev)); if (new_dev == INVALID_ADDRESS) { - msg_err("cannot allocate memory for PCI device\n"); + msg_err("PCI: cannot allocate memory for device"); spin_unlock(&pci_lock); return; } @@ -356,7 +356,7 @@ void pci_remove_device(pci_dev dev, thunk completion) if (pci_completion != INVALID_ADDRESS) completion = pci_completion; else - msg_err("cannot allocate completion closure\n"); + msg_err("%s: cannot allocate completion closure", func_ss); driver = d->driver; driver_data = d->driver_data; d->driver_data = 0; diff --git a/src/kernel/stage3.c b/src/kernel/stage3.c index e46dbb523..fa88e7aa7 100644 --- a/src/kernel/stage3.c +++ b/src/kernel/stage3.c @@ -78,10 +78,7 @@ closure_function(6, 0, void, startup, program_set_perms(root, pro); init_network_iface(root, bound(m)); closure_member(program_start, start, path) = (string)p; - if (trace_get_flags(get(root, sym(trace))) & TRACE_OTHER) { - rprintf("read program complete: %p ", root); - rprintf("gitversion: %s\n", gitversion); - } + msg_info("gitversion: %s", gitversion); storage_when_ready(apply_merge(bound(m))); apply(bound(completion), s); closure_finish(); diff --git a/src/kernel/storage.c b/src/kernel/storage.c index d0a341f2c..6568ca8cc 100644 --- a/src/kernel/storage.c +++ b/src/kernel/storage.c @@ -111,7 +111,7 @@ closure_function(2, 2, void, volume_link, inode mount_dir = bound(mount_dir); int fss = filesystem_mount(storage.root_fs, mount_dir, fs); if (fss != 0) { - msg_err("cannot mount filesystem: %s\n", string_from_errno(-fss)); + msg_err("%s: cannot mount filesystem: %s", func_ss, string_from_errno(-fss)); } else { v->fs = fs; v->mount_dir = mount_dir; @@ -119,7 +119,7 @@ closure_function(2, 2, void, volume_link, notify_mount_change_locked(); } } else { - msg_err("cannot mount filesystem: %v\n", s); + msg_err("%s: cannot mount filesystem: %v", func_ss, s); } v->mounting = false; if (!v->fs && (fs != INVALID_ADDRESS)) @@ -145,20 +145,20 @@ static void volume_mount(volume v, buffer mount_point) int fss = filesystem_get_node(&fs, fs->get_inode(fs, root), cmount_point, false, false, false, false, &mount_dir_t, 0); if (fss != 0) { - msg_err("mount point %s not found\n", cmount_point); + msg_err("storage: mount point %s not found", cmount_point); return; } inode mount_dir = fs->get_inode(fs, mount_dir_t); boolean ok = (fs == storage.root_fs) && (mount_dir_t != root) && children(mount_dir_t); filesystem_put_node(fs, mount_dir_t); if (!ok) { - msg_err("invalid mount point %s\n", cmount_point); + msg_err("storage: invalid mount point %s", cmount_point); return; } filesystem_complete complete = closure(storage.h, volume_link, v, mount_dir); if (complete == INVALID_ADDRESS) { - msg_err("cannot allocate closure\n"); + msg_err("%s: cannot allocate closure", func_ss); return; } storage_debug("mounting volume%s at %s", readonly ? ss(" readonly") : sstring_empty(), diff --git a/src/kernel/symtab.c b/src/kernel/symtab.c index 576cd2065..6fd926439 100644 --- a/src/kernel/symtab.c +++ b/src/kernel/symtab.c @@ -45,16 +45,14 @@ closure_function(1, 4, void, elf_symtable_add, range r = irangel(a + bound(load_offset), len); boolean match = rangemap_range_intersects(elf_symtable, r); if (match) { -#ifdef ELF_SYMTAB_DEBUG - msg_err("\"%s\" %R would overlap in rangemap; skipping\n", name, r); -#endif + msg_warn("%s: \"%s\" %R would overlap in rangemap; skipping", func_ss, name, r); return; } elfsym es = allocate_elfsym(r, name); if (!rangemap_insert(elf_symtable, &es->node)) { /* shouldn't ever happen, so bark if it does */ - msg_err("unable to add symbol \"%s\" of range %R to map; skipping\n", + msg_err("%s: unable to add symbol \"%s\" of range %R to map; skipping", func_ss, name, r); } } diff --git a/src/kernel/tracelog.c b/src/kernel/tracelog.c index 99270969c..57ea3fb0c 100644 --- a/src/kernel/tracelog.c +++ b/src/kernel/tracelog.c @@ -187,8 +187,8 @@ static void close_trace_entry(cpuinfo ci, tracelog_buffer tb) isstring(te->str, te->str_len)); buffer_produce(b, TRACELOG_ENTRY_SIZE - entry_len); if (!buffer_extend(b, TRACELOG_ENTRY_SIZE)) { /* for next */ - msg_err("failed to extend tracelog buffer; reduce collate threshold, reduce " - "volume of traces or increase memory; disabling tracing\n"); + msg_err("tracelog: failed to extend buffer; reduce collate threshold, reduce " + "volume of traces or increase memory; disabling tracing"); /* TODO consider eating up oldest entries to keep system alive through shutdown */ tracelog.disabled = true; } @@ -332,7 +332,8 @@ closure_function(4, 1, void, tracelog_file_write_complete, status s) { if (!is_ok(s)) - msg_err("failed to %s tracelog: %v\n", bound(flushing) ? ss("flush") : ss("write to"), s); + msg_err("tracelog: failed to %s log: %v", bound(flushing) ? ss("flush") : ss("write to"), + s); if (bound(flushing)) { async_apply_status_handler(bound(complete), s); closure_finish(); @@ -396,7 +397,7 @@ static void tracelog_file_write(status_handler complete) fail_dealloc_sg: deallocate_sg_list(sg); fail: - msg_err("out of memory\n"); + msg_err("%s: out of memory", func_ss); if (complete) async_apply_status_handler(complete, timm_oom); } @@ -423,7 +424,7 @@ static void tracelog_collate(status_handler complete) cpuinfo ci = cpuinfo_from_id(i); tracelog_buffer nb = tracelog.disabled ? 0 : allocate_tracelog_buffer_locked(); if (nb == INVALID_ADDRESS) { - msg_err("failed to allocate tracelog buffer for cpu %d; disabling tracing\n", i); + msg_err("%s: failed to allocate buffer for cpu %d; disabling tracing", func_ss, i); tracelog.disabled = true; nb = 0; } @@ -449,7 +450,7 @@ static void tracelog_collate(status_handler complete) } continue; timeout: - msg_err("timeout while waiting for busy tracelog buffer on cpu %d\n", i); + msg_err("%s: timeout while waiting for busy buffer on cpu %d", func_ss, i); } tracelog_buffer tb; @@ -479,7 +480,7 @@ closure_func_basic(thunk, void, tracelog_collator) tracelog_collate(0); } -#define catch_err(s) do {if (!is_ok(s)) msg_err("tracelog: failed to send HTTP response: %v\n", (s));} while(0) +#define catch_err(s) do {if (!is_ok(s)) msg_err("tracelog: failed to send HTTP response: %v", (s));} while(0) static inline void tracelog_send_http_response(http_responder handler, buffer b) { @@ -605,9 +606,9 @@ static void init_tracelog_http_listener(void) connection_handler ch = connection_handler_from_http_listener(tracelog.http_listener); status s = listen_port(tracelog.h, TRACELOG_HTTP_PORT, ch); if (is_ok(s)) { - rprintf("started tracelog http listener on port %d\n", TRACELOG_HTTP_PORT); + msg_info("tracelog: started HTTP listener on port %d", TRACELOG_HTTP_PORT); } else { - msg_err("listen_port() (port %d) failed for tracelog HTTP listener\n", + msg_err("tracelog HTTP: listen_port() (port %d) failed", TRACELOG_HTTP_PORT); deallocate_http_listener(tracelog.h, tracelog.http_listener); } @@ -627,7 +628,7 @@ static void init_tracelog_file_writer(value v) fsfile fsf; if (!is_string(v)) { - msg_err("invalid tracelog filename: %v\n", v); + msg_err("tracelog: invalid filename: %v", v); return; } filesystem fs = get_root_fs(); @@ -636,7 +637,7 @@ static void init_tracelog_file_writer(value v) buffer_to_sstring((buffer)v), true, true, false, false, &file, &fsf); if (s < 0) { - msg_err("failed to open tracelog file: %s\n", string_from_errno(-s)); + msg_err("tracelog: failed to open file: %s", string_from_errno(-s)); return; } filesystem_put_node(fs, file); @@ -645,7 +646,7 @@ static void init_tracelog_file_writer(value v) tracelog.file_offset = fsfile_get_length(tracelog.logfile); /* append */ add_shutdown_completion(closure_func(tracelog.h, shutdown_handler, tracelog_shutdown_handler)); schedule_collator_timer(); - rprintf("tracelog file opened, offset %ld\n", tracelog.file_offset); + msg_info("tracelog file opened, offset %ld", tracelog.file_offset); } void init_tracelog_config(tuple root) @@ -659,7 +660,7 @@ void init_tracelog_config(tuple root) if (get(tl, sym(disable))) { /* don't trace on startup */ tracelog.disabled = true; - rprintf("tracelog disabled on start\n"); + msg_info("tracelog disabled on start"); } bytes alloc_size; diff --git a/src/net/direct.c b/src/net/direct.c index 4f0196dec..2fb3bb2e6 100644 --- a/src/net/direct.c +++ b/src/net/direct.c @@ -113,7 +113,7 @@ static direct direct_alloc(heap h, connection_handler ch) return d; d->p = tcp_new_ip_type(IPADDR_TYPE_ANY); if (!d->p) { - msg_err("PCB creation failed\n"); + msg_err("DNET: PCB creation failed"); deallocate(h, d, sizeof(struct direct)); return INVALID_ADDRESS; } @@ -215,7 +215,7 @@ static void direct_conn_send_internal(direct_conn dc, qbuf q, boolean lwip_locke err = tcp_output(dc->p); if (err != ERR_OK) { - msg_err("tcp_output failed with %d\n", err); + msg_err("DNET: tcp_output failed with %d", err); break; } @@ -290,7 +290,7 @@ static void direct_conn_err(void *z, err_t err) direct_conn_enqueue(dc, 0); return; } - msg_err("dc %p, err %d\n", dc, err); + msg_err("%s: dc %p, err %d", func_ss, dc, err); dc->pending_err = err; } @@ -326,14 +326,14 @@ static direct_conn direct_conn_alloc(direct d, struct tcp_pcb *pcb) fail_dealloc: deallocate(d->h, dc, sizeof(struct direct_conn)); fail: - msg_err("failed to establish direct connection\n"); + msg_err("%s failed", func_ss); return INVALID_ADDRESS; } static void direct_listen_err(void *z, err_t err) { direct d = z; - msg_err("d %p, err %d\n", d, err); + msg_err("%s: d %p, err %d", func_ss, d, err); /* XXX TODO */ } diff --git a/src/net/lwipopts.h b/src/net/lwipopts.h index f7fa05874..a58ff75a1 100644 --- a/src/net/lwipopts.h +++ b/src/net/lwipopts.h @@ -9,8 +9,7 @@ #define ARP_QUEUEING 1 //#define LWIP_DEBUG #ifdef LWIP_DEBUG -#define lwip_debug(fmt, ...) lwip_debug_sstring(ss(fmt), ##__VA_ARGS__) -#define LWIP_PLATFORM_DIAG(x) do {lwip_debug x;} while(0) +#define LWIP_PLATFORM_DIAG(x) do {rprintf x;} while(0) #define LWIP_DBG_MIN_LEVEL LWIP_DBG_LEVEL_ALL #define ETHARP_DEBUG LWIP_DBG_ON #define NETIF_DEBUG LWIP_DBG_ON @@ -142,7 +141,6 @@ struct tcpip_api_call_data #define SYS_LIGHTWEIGHT_PROT 0 typedef unsigned long long time; -extern void lwip_debug_sstring(sstring format, ...); #define MEM_LIBC_MALLOC 1 diff --git a/src/net/net.c b/src/net/net.c index a2777b945..48527070a 100644 --- a/src/net/net.c +++ b/src/net/net.c @@ -58,7 +58,7 @@ closure_func_basic(timer_handler, void, dispatch_lwip_timer, u64 expiry, u64 overruns) { #ifdef LWIP_DEBUG - lwip_debug("dispatching timer\n"); + rprintf("lwIP: dispatching timer\n"); #endif sys_check_timeouts(); timestamp next_expiry = milliseconds(sys_timeouts_sleeptime()); @@ -72,13 +72,6 @@ u32 sys_now(void) return msec_from_timestamp(t); } -void lwip_debug_sstring(sstring format, ...) -{ - vlist a; - vstart(a, format); - log_vprintf(ss("LWIP"), format, &a); -} - void *lwip_allocate(u64 size) { void *p = allocate(lwip_heap, size); @@ -131,13 +124,13 @@ static void lwip_ext_callback(struct netif* netif, netif_nsc_reason_t reason, ifname.len = netif_name_cpy(ifname.ptr, netif); if (reason & LWIP_NSC_IPV4_ADDRESS_CHANGED) { u8 *n = (u8 *)&netif->ip_addr; - rprintf("%s: assigned %d.%d.%d.%d\n", ifname, n[0], n[1], n[2], n[3]); + msg_print("%s: assigned %d.%d.%d.%d", ifname, n[0], n[1], n[2], n[3]); check_netif_ready(netif, false); } if ((reason & LWIP_NSC_IPV6_ADDR_STATE_CHANGED) && (netif_ip6_addr_state(netif, args->ipv6_addr_state_changed.addr_index) & IP6_ADDR_VALID)) { char addr[IP6ADDR_STRLEN_MAX]; - rprintf("%s: assigned %s\n", ifname, + msg_print("%s: assigned %s", ifname, isstring(addr, ipaddr_ntoa_r(args->ipv6_addr_state_changed.address, addr, sizeof(addr)))); check_netif_ready(netif, true); @@ -257,10 +250,11 @@ static boolean get_static_config(tuple t, struct netif *n, sstring ifname, boole if (trace) { char addr[IP4ADDR_STRLEN_MAX]; - rprintf("NET: static IP config for interface %s:\n", ifname); - rprintf(" address\t%s\n", isstring(addr, ip4addr_ntoa_r(&ip, addr, sizeof(addr)))); - rprintf(" netmask\t%s\n", isstring(addr, ip4addr_ntoa_r(&netmask, addr, sizeof(addr)))); - rprintf(" gateway\t%s\n", isstring(addr, ip4addr_ntoa_r(&gw, addr, sizeof(addr)))); + msg_print("NET: static IP config for interface %s:\n" + "\taddress\t%s\n\tnetmask\t%s\n\tgateway\t%s", ifname, + isstring(addr, ip4addr_ntoa_r(&ip, addr, sizeof(addr))), + isstring(addr, ip4addr_ntoa_r(&netmask, addr, sizeof(addr))), + isstring(addr, ip4addr_ntoa_r(&gw, addr, sizeof(addr)))); } netif_set_addr(n, &ip, &netmask, &gw); @@ -276,7 +270,7 @@ static boolean get_static_ip6_config(tuple t, struct netif *n, sstring ifname, b ip6_addr_t ip6; if (ip6addr_aton(str, &ip6)) { if (trace) - rprintf("NET: static IPv6 address for interface %s: %s\n", ifname, str); + msg_print("NET: static IPv6 address for interface %s: %s", ifname, str); netif_add_ip6_address(n, &ip6, 0); return true; } @@ -306,7 +300,7 @@ static void net_complete_cfg(tuple t, symbol opt, struct netif *n, boolean ipv6, return; u64 timeout; if (!u64_from_value(v, &timeout)) { - rprintf("option '%b' has invalid time, ignoring\n", symbol_string(opt)); + msg_err("%b: invalid time, ignoring", symbol_string(opt)); return; } if (timeout == 0 || timeout > 180) @@ -328,7 +322,7 @@ static void net_complete_cfg(tuple t, symbol opt, struct netif *n, boolean ipv6, void init_network_iface(tuple root, merge m) { struct netif *n; struct netif *default_iface = 0; - boolean trace = !!(trace_get_flags(get(root, sym(trace))) & TRACE_OTHER); + boolean trace = klog_level_enabled(LOG_INFO); /* NETIF_FOREACH traverses interfaces in reverse order...so go by index */ for (int i = 1; (n = netif_get_by_index(i)); i++) { @@ -360,21 +354,22 @@ void init_network_iface(tuple root, merge m) { netif_dev dev = n->state; netif_dev_setup setup = (netif_dev_setup)&dev->setup; if (*setup && !apply(setup, t)) - msg_err("failed to set up %s\n", ifname); + msg_err("NET: failed to set up interface %s", ifname); u64 mtu; if (t) { if (get_u64(t, sym(mtu), &mtu)) { if (mtu < U64_FROM_BIT(16)) { if (trace) - rprintf("NET: setting MTU for interface %s to %ld\n", ifname, mtu); + msg_print("NET: setting MTU for interface %s to %ld", ifname, mtu); n->mtu = mtu; } else { - rprintf("NET: invalid MTU %ld for interface %s; ignored\n", mtu, ifname); + msg_err("NET: invalid MTU %ld for interface %s; ignored", mtu, ifname); } } if (get(t, sym(default))) { - rprintf("NET: setting interface %s as default\n", ifname); + if (trace) + msg_print("NET: setting interface %s as default", ifname); default_iface = n; } } @@ -386,12 +381,12 @@ void init_network_iface(tuple root, merge m) { if (!t || !get_static_config(t, n, ifname, trace)) { if (trace) - rprintf("NET: starting DHCP for interface %s\n", ifname); + msg_print("NET: starting DHCP for interface %s", ifname); dhcp_start(n); } if (!t || !get_static_ip6_config(t, n, ifname, trace)) { if (trace) - rprintf("NET: starting DHCPv6 for interface %s\n", ifname); + msg_print("NET: starting DHCPv6 for interface %s", ifname); dhcp6_enable_stateful(n); } if (t) { @@ -409,7 +404,7 @@ void init_network_iface(tuple root, merge m) { ip_addr_t dns_server = IPADDR4_INIT_BYTES(1, 1, 1, 1); dns_setserver(0, &dns_server); } else { - rprintf("NET: no network interface found\n"); + msg_err("NET: no network interface found"); } } diff --git a/src/net/netsyscall.c b/src/net/netsyscall.c index a66f2ccc8..11f646e42 100755 --- a/src/net/netsyscall.c +++ b/src/net/netsyscall.c @@ -820,7 +820,7 @@ static sysreturn socket_write_udp(netsock s, void *source, struct iovec *iov, u6 struct pbuf *pbuf = pbuf_alloc(PBUF_TRANSPORT, xfer_len, PBUF_RAM); if (!pbuf) { netsock_unlock(s); - msg_err("failed to allocate pbuf for udp_send()\n"); + msg_err("%s: failed to allocate pbuf for udp_send()", func_ss); return -ENOBUFS; } if (context_set_err(ctx)) { @@ -1209,7 +1209,7 @@ static sysreturn netsock_shutdown(struct sock *sock, int how) shut_tx = 1; break; default: - msg_warn("Wrong value passed for direction sock %d, type %d\n", sock->fd, s->sock.type); + msg_warn("%s: invalid 'how' value %d", func_ss, how); rv = -EINVAL; goto out; } @@ -1298,7 +1298,7 @@ static void udp_input_lower(void *z, struct udp_pcb *pcb, struct pbuf *p, s->sock.rx_len += p->tot_len; wakeup_sock(s, WAKEUP_SOCK_RX); } else { - msg_err("null pbuf\n"); + msg_err("%s error: null pbuf", func_ss); } } @@ -1309,7 +1309,7 @@ static int allocate_sock(process p, int af, int type, u32 flags, boolean alloc_f s = unix_cache_alloc(p->uh, socket); if (s == INVALID_ADDRESS) { - msg_err("failed to allocate struct sock\n"); + msg_err("netsock: failed to allocate structure"); goto err_sock; } @@ -1326,7 +1326,7 @@ static int allocate_sock(process p, int af, int type, u32 flags, boolean alloc_f s->incoming = allocate_queue(h, SOCK_QUEUE_LEN); if (s->incoming == INVALID_ADDRESS) { - msg_err("failed to allocate queue\n"); + msg_err("netsock: failed to allocate queue"); goto err_queue; } @@ -1408,7 +1408,7 @@ sysreturn socket(int domain, int type, int protocol) case AF_VSOCK: return vsock_open(type, protocol); default: - msg_warn("domain %d not supported\n", domain); + msg_warn("socket domain %d not supported", domain); return -EAFNOSUPPORT; } @@ -1418,11 +1418,10 @@ sysreturn socket(int domain, int type, int protocol) if (check_flags_and_clear(flags, SOCK_NONBLOCK)) nonblock = true; - if (check_flags_and_clear(flags, SOCK_CLOEXEC)) - msg_warn("close-on-exec not applicable; ignored\n"); + flags &= ~SOCK_CLOEXEC; if ((flags & ~SOCK_TYPE_MASK) != 0) - msg_warn("unhandled type flags 0x%x\n", flags); + msg_warn("%s: unhandled flags 0x%x", func_ss, flags); type &= SOCK_TYPE_MASK; if (type == SOCK_STREAM) { @@ -1448,7 +1447,7 @@ sysreturn socket(int domain, int type, int protocol) net_debug("new udp fd %d, pcb %p\n", fd, p); return fd; } - msg_warn("unsupported socket type %d\n", type); + msg_warn("%s: unsupported type %d", func_ss, type); return -EINVAL; } @@ -1462,7 +1461,7 @@ static err_t tcp_input_lower(void *z, struct tcp_pcb *pcb, struct pbuf *p, err_t if (err != ERR_OK) { /* shouldn't happen according to lwIP sources; just report */ - msg_err("Unexpected error from lwIP: %d\n", err); + msg_err("%s error from lwIP: %d", func_ss, err); } /* A null pbuf indicates connection closed. */ @@ -1470,7 +1469,7 @@ static err_t tcp_input_lower(void *z, struct tcp_pcb *pcb, struct pbuf *p, err_t if (p) { if ((s->sock.rx_len + p->tot_len > so_rcvbuf) || !enqueue(s->incoming, p)) { netsock_unlock(s); - msg_err("incoming queue full\n"); + msg_err("%s error: incoming queue full", func_ss); return ERR_BUF; /* XXX verify */ } s->sock.rx_len += p->tot_len; @@ -1703,7 +1702,7 @@ static sysreturn netsock_connect(struct sock *sock, struct sockaddr *addr, } else if (s->info.tcp.state == TCP_SOCK_OPEN) { ret = -EISCONN; } else if (s->info.tcp.state == TCP_SOCK_LISTENING) { - msg_warn("attempt to connect on listening socket fd = %d; ignored\n", sock->fd); + msg_warn("%s: attempt to connect on listening socket fd = %d", func_ss, sock->fd); ret = -EINVAL; } else { ret = connect_tcp(s, &ipaddr, port); @@ -1734,24 +1733,24 @@ static sysreturn sendto_prepare(struct sock *sock, int flags) { /* Process flags */ if (flags & MSG_CONFIRM) - msg_warn("MSG_CONFIRM unimplemented; ignored\n"); + msg_warn("send flag MSG_CONFIRM ignored"); if (flags & MSG_DONTROUTE) - msg_warn("MSG_DONTROUTE unimplemented; ignored\n"); + msg_warn("send flag MSG_DONTROUTE ignored"); if (flags & MSG_EOR) { - msg_warn("MSG_EOR unimplemented\n"); + msg_err("send flag MSG_EOR unimplemented"); return -EOPNOTSUPP; } if (flags & MSG_MORE) - msg_warn("MSG_MORE unimplemented; ignored\n"); + msg_warn("send flag MSG_MORE ignored"); if (flags & MSG_NOSIGNAL) - msg_warn("MSG_NOSIGNAL unimplemented; ignored\n"); + msg_warn("send flag MSG_NOSIGNAL ignored"); if (flags & MSG_OOB) - msg_warn("MSG_OOB unimplemented; ignored\n"); + msg_warn("send flag MSG_OOB ignored"); return 0; } @@ -2076,7 +2075,7 @@ static err_t accept_tcp_from_lwip(void * z, struct tcp_pcb * lw, err_t err) tcp_err(lw, lwip_tcp_conn_err); tcp_sent(lw, lwip_tcp_sent); if (!enqueue(s->incoming, sn)) { - msg_err("queue overrun; shouldn't happen with lwIP listen backlog\n"); + msg_err("%s queue overrun", func_ss); err = ERR_BUF; /* lwIP will do tcp_abort */ goto unlock_out; } @@ -2479,7 +2478,7 @@ static sysreturn netsock_setsockopt(struct sock *sock, int level, rv = 0; goto out; unimplemented: - msg_warn("setsockopt unimplemented: fd %d, level %d, optname %d\n", + msg_warn("setsockopt unimplemented: fd %d, level %d, optname %d", sock->fd, level, optname); rv = 0; out: @@ -2731,7 +2730,7 @@ static sysreturn netsock_getsockopt(struct sock *sock, int level, rv = sockopt_copy_to_user(optval, optlen, &ret_optval, ret_optlen); goto out; unimplemented: - msg_err("getsockopt unimplemented optname: fd %d, level %d, optname %d\n", + msg_err("getsockopt unimplemented: fd %d, level %d, optname %d", sock->fd, level, optname); rv = -ENOPROTOOPT; out: diff --git a/src/riscv64/interrupt.c b/src/riscv64/interrupt.c index 7834eaf3e..a94348c59 100644 --- a/src/riscv64/interrupt.c +++ b/src/riscv64/interrupt.c @@ -198,7 +198,7 @@ void riscv_timer(void) static boolean invoke_handlers_for_vector(cpuinfo ci, int v) { if (list_empty(&handlers[v])) { - rprintf("\nno handler for %s %d\n", v <= PLIC_MAX_INT ? ss("interrupt") : ss("IPI"), v); + msg_err("irq: no handler for %s %d", v <= PLIC_MAX_INT ? ss("interrupt") : ss("IPI"), v); return false; } @@ -253,7 +253,7 @@ void trap_interrupt(void) (f[FRAME_STATUS] & STATUS_SPP) ? ss("false") : ss("true")); if (i > PLIC_MAX_INT) { - rprintf("\ndispatched interrupt %d exceeds PLIC_MAX_INT\n", i); + msg_err("%s: dispatched interrupt %d exceeds PLIC_MAX_INT", func_ss, i); goto exit_fault; } @@ -454,7 +454,7 @@ void __attribute__((noreturn)) __stack_chk_fail(void) { cpuinfo ci = current_cpu(); context ctx = get_current_context(ci); - rprintf("stack check failed on cpu %d\n", ci->id); + msg_err("stack check failed on cpu %d", ci->id); dump_context(ctx); vm_exit(VM_EXIT_FAULT); } diff --git a/src/riscv64/kernel_machine.c b/src/riscv64/kernel_machine.c index 3b81175af..46e3249d3 100644 --- a/src/riscv64/kernel_machine.c +++ b/src/riscv64/kernel_machine.c @@ -168,7 +168,7 @@ void count_cpus_present(void) vector_set(hartids_by_cpuid, 0, (void*)boot_hartid); dt_node n = dtb_find_node_by_path(DEVICETREE, ss("/cpus")); if (n == INVALID_ADDRESS) { - msg_err("unable to find \"/cpus/cpu-map/cluster0\" in device tree; resorting to single cpu\n"); + msg_err("device tree: unable to find \"/cpus/cpu-map/cluster0\"; resorting to single cpu"); return; } diff --git a/src/runtime/bitmap.c b/src/runtime/bitmap.c index d4eb0f616..e20711492 100644 --- a/src/runtime/bitmap.c +++ b/src/runtime/bitmap.c @@ -191,13 +191,13 @@ boolean bitmap_dealloc(bitmap b, u64 bit, u64 size) assert(mapbase); if (bit + size > b->maxbits) { - msg_err("bitmap %p, bit %ld, order %ld: exceeds bit length %ld\n", + msg_err("bitmap %p, bit %ld, order %ld: exceeds bit length %ld", b, bit, order, b->maxbits); return false; } if (!for_range_in_map(mapbase, bit, size, false, true)) { - msg_err("bitmap %p, bit %ld, order %ld: not allocated in map; leaking\n", + msg_err("bitmap %p, bit %ld, order %ld: not allocated in map; leaking", b, bit, order); return false; } diff --git a/src/runtime/clock.h b/src/runtime/clock.h index 90702c887..733f9b4fe 100644 --- a/src/runtime/clock.h +++ b/src/runtime/clock.h @@ -83,7 +83,8 @@ static inline timestamp now(clock_id id) s64 interval = t - last_raw; t += clock_freq_adjust(interval); if (t < last_raw) { - msg_err("t(%T) < last_raw(%T) after freq adjust (%f)\n", t, last_raw, __vdso_dat->base_freq); + msg_err("%s error: t(%T) < last_raw(%T) after freq adjust (%f)", + func_ss, t, last_raw, __vdso_dat->base_freq); t = last_raw; } switch (id) { diff --git a/src/runtime/format.c b/src/runtime/format.c index 8d595ebe0..a71ad1166 100644 --- a/src/runtime/format.c +++ b/src/runtime/format.c @@ -97,23 +97,6 @@ void vbprintf(buffer d, sstring fmt, vlist *ap) } } -// XXX fixme -/* XXX the various debug stuff needs to be folded into one log facility...somewhere */ -void log_vprintf(sstring prefix, sstring log_format, vlist *a) -{ - buffer b = little_stack_buffer(1024); - bprintf(b, "[%T] %s: ", now(CLOCK_ID_BOOTTIME), prefix); - vbprintf(b, log_format, a); - buffer_print(b); -} - -void log_printf(sstring prefix, sstring log_format, ...) -{ - vlist a; - vstart(a, log_format); - log_vprintf(prefix, log_format, &a); -} - buffer aprintf_sstring(heap h, sstring fmt, ...) { buffer b = allocate_buffer(h, 80); @@ -136,7 +119,7 @@ int rsnprintf_sstring(char *str, u64 size, sstring fmt, ...) { buffer b = allocate_buffer(transient, size); if (b == INVALID_ADDRESS) { - msg_err("buffer allocation failed\n"); + msg_err("%s: buffer allocation failed", func_ss); if (size > 0) str[0] = '\0'; return 0; diff --git a/src/runtime/format.h b/src/runtime/format.h index 37b41f58f..5d7f39ed0 100644 --- a/src/runtime/format.h +++ b/src/runtime/format.h @@ -1,8 +1,5 @@ extern void vbprintf(buffer s, sstring fmt, vlist *ap); -extern void log_vprintf(sstring prefix, sstring log_format, vlist *a); -extern void log_printf(sstring prefix, sstring log_format, ...); - struct formatter_state { int state; int format; // format character ('s', 'd', ...) diff --git a/src/runtime/heap/freelist.c b/src/runtime/heap/freelist.c index 4ad856834..bc3ae900b 100644 --- a/src/runtime/heap/freelist.c +++ b/src/runtime/heap/freelist.c @@ -24,7 +24,6 @@ static void freelist_deallocate(heap h, u64 x, bytes size) freelist f = (freelist)h; *(void **)pointer_from_u64(x) = f->free; f->free = pointer_from_u64(x); - // rprintf("freelist deallocate %p\n", x); size = MAX(size, sizeof(void *)); assert(f->count >= size); f->count -= size; diff --git a/src/runtime/heap/id.c b/src/runtime/heap/id.c index dba298f2b..d6755e1c4 100644 --- a/src/runtime/heap/id.c +++ b/src/runtime/heap/id.c @@ -65,7 +65,7 @@ static id_range id_add_range(id_heap i, u64 base, u64 length) if (ir == INVALID_ADDRESS) return ir; if (!rangemap_insert(i->ranges, &ir->n)) { - msg_err("range insertion failure; conflict with range %R\n", ir->n.r); + msg_err("%s failed: conflict with range %R", func_ss, ir->n.r); goto fail; } @@ -77,7 +77,7 @@ static id_range id_add_range(id_heap i, u64 base, u64 length) ir->b = allocate_bitmap(i->meta, i->map, pages + page_start_mask); if (ir->b == INVALID_ADDRESS) { - msg_err("failed to allocate bitmap for range %R\n", ir->n.r); + msg_err("%s: failed to allocate bitmap for range %R", func_ss, ir->n.r); goto fail; } if (page_start_mask) @@ -195,7 +195,7 @@ closure_function(2, 1, boolean, dealloc_from_range, u64 pages = range_span(ri); int order = find_order(pages); if (!bitmap_dealloc(r->b, bit, pages)) { - msg_err("heap %p: bitmap dealloc for range %R failed; leaking\n", i, q); + msg_err("id heap %p: bitmap dealloc for range %R failed; leaking", i, q); return false; } u64 pages_rounded = U64_FROM_BIT(order); @@ -216,7 +216,7 @@ closure_function(2, 1, boolean, dealloc_gap, id_heap, h, range, q, range r) { - msg_err("heap %p: gap %R found while deallocating %R\n", bound(h), r, bound(q)); + msg_err("id heap %p: gap %R found while deallocating %R", bound(h), r, bound(q)); return false; } @@ -228,7 +228,7 @@ static inline void id_dealloc(heap h, u64 a, bytes count) return; if ((a & page_mask(i)) != 0 || (count & page_mask(i)) != 0) { - msg_err("heap %p: a 0x%lx, count 0x%lx not page-aligned; leaking\n", h, a, count); + msg_err("id heap %p: a 0x%lx, count 0x%lx not page-aligned; leaking", h, a, count); return; } @@ -236,7 +236,7 @@ static inline void id_dealloc(heap h, u64 a, bytes count) rmnode_handler nh = stack_closure(dealloc_from_range, i, q); range_handler rh = stack_closure(dealloc_gap, i, q); if (rangemap_range_lookup_with_gaps(i->ranges, q, nh, rh) == RM_ABORT) - msg_err("failed, ra %p\n", __builtin_return_address(0)); + msg_err("%s failed, ra %p", func_ss, __builtin_return_address(0)); } closure_function(1, 1, boolean, destruct_id_range, @@ -298,7 +298,7 @@ closure_function(2, 1, boolean, set_gap, range r) { /* really no reason to ever set across ranges, so we should know if it happens... */ - msg_err("heap: %p, gap %R found while setting %R\n", bound(i), r, bound(q)); + msg_err("id heap %p: gap %R found while setting %R", bound(i), r, bound(q)); return false; } diff --git a/src/runtime/heap/mcache.c b/src/runtime/heap/mcache.c index 500e7b92f..7722220c8 100644 --- a/src/runtime/heap/mcache.c +++ b/src/runtime/heap/mcache.c @@ -304,18 +304,18 @@ heap allocate_mcache(heap meta, heap parent, int min_order, int max_order, bytes { if (pagesize < parent->pagesize || ((pagesize - 1) & pagesize)) { - msg_err("pagesize (%d) must be a power-of-2 >= parent pagesize (%d)\n", + msg_err("mcache pagesize (%d) must be a power-of-2 >= parent pagesize (%d)", pagesize, parent->pagesize); return INVALID_ADDRESS; } if (U64_FROM_BIT(max_order) >= pagesize) { - msg_err("max obj size (%d) must be less than pagesize %d\n", U64_FROM_BIT(max_order), pagesize); + msg_err("mcache max obj size (%d) must be less than pagesize %d", U64_FROM_BIT(max_order), pagesize); return INVALID_ADDRESS; } if (min_order > max_order) { - msg_err("min_order (%d) cannot exceed max_order (%d)\n", min_order, max_order); + msg_err("mcache min_order (%d) cannot exceed max_order (%d)", min_order, max_order); return INVALID_ADDRESS; } diff --git a/src/runtime/heap/objcache.c b/src/runtime/heap/objcache.c index d654e7070..33117ca0a 100644 --- a/src/runtime/heap/objcache.c +++ b/src/runtime/heap/objcache.c @@ -100,7 +100,7 @@ static footer objcache_addpage(objcache o) { page p = allocate_u64(o->parent, page_size(o)); if (p == INVALID_PHYSICAL) { - msg_warn("unable to allocate page\n"); + msg_warn("objcache: unable to allocate page"); return 0; } @@ -129,12 +129,12 @@ static void objcache_removepage(objcache o, footer f) static inline boolean validate_page(objcache o, footer f) { if (f->magic != FOOTER_MAGIC) { - msg_err("objcache %p, footer %p, bad magic! (%x)\n", o, f, f->magic); + msg_err("objcache %p, footer %p, bad magic! (%x)", o, f, f->magic); return false; } if (f->cache != (heap)o && (o->wrapper_heap && f->cache != o->wrapper_heap)) { - msg_err("objcache %p, footer %p, f->cache mismatch (%p)\n", o, f, f->cache); + msg_err("objcache %p, footer %p, f->cache mismatch (%p)", o, f, f->cache); return false; } @@ -148,7 +148,7 @@ static inline void objcache_deallocate(heap h, u64 x, bytes size) footer f = footer_from_page(o, p); if (size != object_size(o)) { - msg_err("on heap %p: dealloc size (%d) doesn't match object size (%d); leaking\n",\ + msg_err("objcache %p: dealloc size (%d) doesn't match object size (%d); leaking", h, size, object_size(o)); return; } @@ -159,7 +159,7 @@ static inline void objcache_deallocate(heap h, u64 x, bytes size) x, p, f->free, f->head, f->avail); if (!validate_page(o, f)) { - msg_err("leaking object\n"); + msg_err("%s: leaking object", func_ss); return; } @@ -183,7 +183,7 @@ static inline u64 objcache_allocate(heap h, bytes size) { objcache o = (objcache)h; if (size != object_size(o)) { - msg_err("on heap %p: alloc size (%d) doesn't match object size (%d)\n", + msg_err("objcache %p: alloc size (%d) doesn't match object size (%d)", h, size, object_size(o)); return INVALID_PHYSICAL; } @@ -202,7 +202,7 @@ static inline u64 objcache_allocate(heap h, bytes size) } if (!validate_page(o, f)) { - msg_err("alloc failed\n"); + msg_err("%s failed", func_ss); return INVALID_PHYSICAL; } @@ -299,18 +299,18 @@ boolean objcache_validate(heap h) page p = page_from_footer(o, f); if (!validate_page(o, f)) { - msg_err("page %lx on free list failed validate\n", p); + msg_err("%s failed on page %lx on free list", func_ss, p); return false; } if (f->avail == 0) { - msg_err("page %lx on free list but has 0 avail\n", p); + msg_err("%s error: page %lx on free list but has 0 avail", func_ss, p); return false; } if (!is_valid_index(f->free) && f->head == o->objs_per_page) { - msg_err("page %lx on free list but object freelist empty " - "and no uninitialized objects\n", p); + msg_err("%s error: page %lx on free list but object freelist empty " + "and no uninitialized objects", func_ss, p); return false; } @@ -323,8 +323,8 @@ boolean objcache_validate(heap h) do { /* validate index */ if (next >= o->objs_per_page) { - msg_err("page %lx on free list has invalid object index %d, objs_per_page %ld\n", - p, next, o->objs_per_page); + msg_err("%s error: page %lx on free list has invalid object index %d, " + "objs_per_page %ld", func_ss, p, next, o->objs_per_page); return false; } u64 obj = obj_from_index(o, p, next); @@ -333,22 +333,22 @@ boolean objcache_validate(heap h) } while(is_valid_index(next) && free_tally <= invalid_index); if (free_tally > invalid_index) { - msg_err("page %lx on free list overflow while walking free list; " - "corrupt from possible loop, free_tally %d\n", p, free_tally); + msg_err("%s error: page %lx on free list overflow while walking free list; " + "corrupt from possible loop, free_tally %d", func_ss, p, free_tally); return false; } } if (f->head > o->objs_per_page) { - msg_err("page %lx on free list has f->head = %d > objs_per_page = %ld\n", - p, f->head, o->objs_per_page); + msg_err("%s error: page %lx on free list has f->head = %d > objs_per_page = %ld", + func_ss, p, f->head, o->objs_per_page); return false; } int uninit_count = o->objs_per_page - f->head; if (free_tally + uninit_count != f->avail) { - msg_err("page %lx free (%d) and uninit (%d) counts do not equal f->avail (%d)\n", - p, free_tally, uninit_count, f->avail); + msg_err("%s error: page %lx free (%d) and uninit (%d) counts do not equal f->avail " + "(%d)", func_ss, p, free_tally, uninit_count, f->avail); return false; } @@ -364,25 +364,25 @@ boolean objcache_validate(heap h) page p = page_from_footer(o, f); if (!validate_page(o, f)) { - msg_err("page %lx on full list failed validate\n", p); + msg_err("%s failed on page %lx on full list", func_ss, p); return false; } if (f->avail != 0) { - msg_err("page %lx on full list but has non-zero avail (%d)\n", - p, f->avail); + msg_err("%s error: page %lx on full list but has non-zero avail (%d)", + func_ss, p, f->avail); return false; } if (is_valid_index(f->free)) { - msg_err("page %lx on full list but object freelist non-empty (%d)\n", - p, f->free); + msg_err("%s error: page %lx on full list but object freelist non-empty (%d)", + func_ss, p, f->free); return false; } if (f->head < o->objs_per_page) { - msg_err("page %lx on full list but uninitialized objects remain (%ld)\n", - p, o->objs_per_page - f->head); + msg_err("%s error: page %lx on full list but uninitialized objects remain (%ld)", + func_ss, p, o->objs_per_page - f->head); return false; } @@ -391,14 +391,14 @@ boolean objcache_validate(heap h) /* validate counts */ if (total_pages * o->objs_per_page != o->total_objs) { - msg_err("total_objs (%ld) doesn't match tallied pages (%ld) * objs_per_page (%ld)\n", - o->total_objs, total_pages, o->objs_per_page); + msg_err("%s error: total_objs (%ld) doesn't match tallied pages (%ld) * objs_per_page " + "(%ld)", func_ss, o->total_objs, total_pages, o->objs_per_page); return false; } if (o->total_objs - total_avail != o->alloced_objs) { - msg_err("total_objs (%ld) - tallied available objs (%ld) doesn't match o->alloced_objs (%ld)\n", - o->total_objs, total_avail, o->alloced_objs); + msg_err("%s error: total_objs (%ld) - tallied available objs (%ld) doesn't match " + "o->alloced_objs (%ld)", func_ss, o->total_objs, total_avail, o->alloced_objs); return false; } @@ -519,13 +519,13 @@ caching_heap allocate_objcache(heap meta, heap parent, bytes objsize, bytes page u64 objs_per_page; if (objsize < sizeof(u16)) { - msg_err("object size must be > %d\n", sizeof(u16)); + msg_err("objcache object size must be > %d", sizeof(u16)); return INVALID_ADDRESS; } if (pagesize < parent->pagesize || ((pagesize - 1) & pagesize)) { - msg_err("pagesize (%d) must be a power-of-2 >= parent pagesize (%d)\n", + msg_err("objcache pagesize (%d) must be a power-of-2 >= parent pagesize (%d)", pagesize, parent->pagesize); return INVALID_ADDRESS; } @@ -537,15 +537,15 @@ caching_heap allocate_objcache(heap meta, heap parent, bytes objsize, bytes page meta, parent, objsize, pagesize, objs_per_page); if (objs_per_page == 0) { - msg_err("page size %d cannot accomodate object size %d\n", + msg_err("objcache page size %d cannot accommodate object size %d", pagesize, objsize); return INVALID_ADDRESS; } if (objs_per_page >= U64_FROM_BIT(16)) { objs_per_page = U64_FROM_BIT(16) - 1; - msg_err("too many objects per page (pagesize %d, objsize %d); " - "limiting to %ld\n", pagesize, objsize, objs_per_page); + msg_warn("objcache: too many objects per page (pagesize %d, objsize %d); " + "limiting to %ld", pagesize, objsize, objs_per_page); } objcache o = allocate(meta, sizeof(struct objcache)); diff --git a/src/runtime/range.c b/src/runtime/range.c index 4884254ea..3d03e0db7 100644 --- a/src/runtime/range.c +++ b/src/runtime/range.c @@ -25,7 +25,7 @@ boolean rangemap_insert(rangemap rm, rmnode n) break; range i = range_intersection(curr->r, n->r); if (range_span(i)) { - msg_warn("attempt to insert %p (%R) but overlap with %p (%R)\n", + msg_warn("rangemap: attempt to insert %p (%R) but overlap with %p (%R)", n, n->r, curr, curr->r); return false; } diff --git a/src/runtime/runtime.h b/src/runtime/runtime.h index 2352a75b7..806999461 100644 --- a/src/runtime/runtime.h +++ b/src/runtime/runtime.h @@ -181,19 +181,34 @@ typedef struct flush_entry *flush_entry; #include #include -/* XXX: Note that printing function names will reveal our internals to - some degree. All the logging stuff needs more time in the oven. */ +#ifdef KERNEL + +enum log_level { + LOG_ALWAYS = -1, + LOG_ERR, + LOG_WARN, + LOG_INFO, +}; + +#define msg_print(fmt, ...) log_printf(LOG_ALWAYS, ss(fmt), ##__VA_ARGS__) +#define msg_err(fmt, ...) log_printf(LOG_ERR, ss(fmt), ##__VA_ARGS__) +#define msg_warn(fmt, ...) log_printf(LOG_WARN, ss(fmt), ##__VA_ARGS__) +#define msg_info(fmt, ...) log_printf(LOG_INFO, ss(fmt), ##__VA_ARGS__) + +void log_printf(enum log_level level, sstring fmt, ...); -#define msg_err(fmt, ...) rprintf("%s error: " fmt, func_ss, \ - ##__VA_ARGS__) +#else + +#define msg_err(fmt, ...) rprintf(fmt "\n", ##__VA_ARGS__) #ifdef ENABLE_MSG_WARN -#define msg_warn(fmt, ...) rprintf("%s warning: " fmt, func_ss, \ - ##__VA_ARGS__) +#define msg_warn(fmt, ...) rprintf(fmt "\n", ##__VA_ARGS__) #else #define msg_warn(fmt, ...) #endif +#endif + #ifdef ENABLE_MSG_DEBUG #define msg_debug(fmt, ...) rprintf("%s debug: " fmt, func_ss, \ ##__VA_ARGS__) diff --git a/src/runtime/tuple.c b/src/runtime/tuple.c index 05dc117b2..46fce553d 100644 --- a/src/runtime/tuple.c +++ b/src/runtime/tuple.c @@ -451,7 +451,7 @@ value decode_value(heap h, table dictionary, buffer source, u64 *total, return null_value; } if (!old_encoding) - rprintf("%s: warning: untyped buffer, len %ld, offset %d: %B\n", func_ss, + msg_warn("%s: untyped buffer, len %ld, offset %d: %B", func_ss, len, source->start, alloca_wrap_buffer(buffer_ref(source, 0), len)); /* address a long-standing bug in bootloaders; untyped buffers must be tagged */ @@ -510,7 +510,7 @@ static void encode_value_internal(buffer dest, table dictionary, value v, u64 *t encode_string(dest, (string)v); } else { if (v != null_value) { - rprintf("%s: untyped value %v, len %d, from %p\n", func_ss, v, + msg_err("%s: untyped value %v, len %d, from %p", func_ss, v, buffer_length((buffer)v), __builtin_return_address(0)); print_frame_trace_from_here(); } diff --git a/src/unix/eventfd.c b/src/unix/eventfd.c index 635f798c3..25e18e077 100644 --- a/src/unix/eventfd.c +++ b/src/unix/eventfd.c @@ -183,7 +183,7 @@ int do_eventfd2(unsigned int count, int flags) } efd = allocate(h, sizeof(*efd)); if (efd == INVALID_ADDRESS) { - msg_err("failed to allocate eventfd structure\n"); + msg_err("eventfd: failed to allocate structure"); goto err_efd; } @@ -199,13 +199,13 @@ int do_eventfd2(unsigned int count, int flags) efd->read_bq = allocate_blockq(h, ss("eventfd read")); if (efd->read_bq == INVALID_ADDRESS) { - msg_err("failed to allocated blockq\n"); + msg_err("eventfd: failed to allocate read blockq"); goto err_read_bq; } efd->write_bq = allocate_blockq(h, ss("eventfd write")); if (efd->write_bq == INVALID_ADDRESS) { - msg_err("failed to allocate blockq\n"); + msg_err("eventfd: failed to allocate write blockq"); goto err_write_bq; } @@ -213,7 +213,7 @@ int do_eventfd2(unsigned int count, int flags) efd->io_event = false; efd->fd = allocate_fd(current->p, efd); if (efd->fd == INVALID_PHYSICAL) { - msg_err("failed to allocate fd\n"); + msg_err("eventfd: failed to allocate fd"); apply(efd->f.close, 0, io_completion_ignore); return -EMFILE; } diff --git a/src/unix/exec.c b/src/unix/exec.c index d934b7290..2fbd77e37 100644 --- a/src/unix/exec.c +++ b/src/unix/exec.c @@ -52,7 +52,7 @@ closure_function(1, 2, boolean, fill_arguments_each, { u64 i; if (!u64_from_attribute(a, &i)) { - msg_err("arguments attribute %v is not an index\n", a); + msg_err("arguments attribute %v is not an index", a); return false; } vector_set(bound(r), i, v); @@ -260,7 +260,7 @@ closure_function(4, 5, boolean, static_map, } return true; alloc_fail: - msg_err("failed to allocate interp vmap\n"); + msg_err("exec: failed to allocate vmap"); return false; } @@ -306,7 +306,7 @@ closure_function(4, 5, boolean, faulting_map, } return true; alloc_fail: - msg_err("failed to allocate vmap\n"); + msg_err("exec: failed to allocate vmap"); return false; } diff --git a/src/unix/ftrace.c b/src/unix/ftrace.c index 764c4a095..6d917def9 100644 --- a/src/unix/ftrace.c +++ b/src/unix/ftrace.c @@ -236,7 +236,7 @@ printer_init(struct ftrace_printer * p, unsigned long flags) { p->b = allocate_buffer(ftrace_heap, TRACE_PRINTER_INIT_SIZE); if (p->b == INVALID_ADDRESS) { - msg_err("failed to allocate ftrace buffer\n"); + msg_err("ftrace: failed to allocate buffer"); return -1; } init_timer(&p->t); @@ -442,7 +442,7 @@ rbuf_init(struct rbuf * rbuf, unsigned long buffer_size_kb) rbuf->trace_array = allocate(rbuf_heap, sizeof(struct rbuf_entry) * rbuf->size); if (rbuf->trace_array == INVALID_ADDRESS) { - msg_err("failed to allocate ftrace trace array\n"); + msg_err("ftrace: failed to allocate trace array"); return -ENOMEM; } spin_lock_init(&rbuf->rb_lock); @@ -1420,7 +1420,7 @@ FTRACE_FN(trace_pipe, events)(file f) static sysreturn FTRACE_FN(tracing_enable_on, get)(struct ftrace_printer * p) { - rprintf("ftrace recording on\n"); + msg_info("ftrace recording on"); tracing_on = 1; return 0; } @@ -1429,7 +1429,7 @@ static sysreturn FTRACE_FN(tracing_enable_off, get)(struct ftrace_printer * p) { tracing_on = 0; - rprintf("ftrace recording off\n"); + msg_info("ftrace recording off"); return 0; } @@ -1596,7 +1596,7 @@ ftrace_send_http_chunked_response(http_responder handler) s = send_http_chunked_response(handler, timm("ContentType", "text/html")); if (!is_ok(s)) - msg_err("ftrace: failed to send HTTP response\n"); + msg_err("ftrace: failed to send HTTP response"); } static void @@ -1606,7 +1606,7 @@ ftrace_send_http_response(http_responder handler, buffer b) s = send_http_response(handler, timm("ContentType", "text/html"), b); if (!is_ok(s)) - msg_err("ftrace: failed to send HTTP response\n"); + msg_err("ftrace: failed to send HTTP response"); } static void @@ -1619,7 +1619,7 @@ ftrace_send_http_uri_not_found(http_responder handler) "

Not Found

\r\n") ); if (!is_ok(s)) - msg_err("ftrace: failed to send HTTP response\n"); + msg_err("ftrace: failed to send HTTP response"); } static void @@ -1632,7 +1632,7 @@ ftrace_send_http_no_method(http_responder handler, http_method method) "

Not Implemented

\r\n") ); if (!is_ok(s)) - msg_err("ftrace: failed to send HTTP response\n"); + msg_err("ftrace: failed to send HTTP response"); } static void @@ -1645,7 +1645,7 @@ ftrace_send_http_server_error(http_responder handler) "

Internal Server Error

\r\n") ); if (!is_ok(s)) - msg_err("ftrace: failed to send HTTP response\n"); + msg_err("ftrace: failed to send HTTP response"); } @@ -1658,7 +1658,7 @@ __ftrace_send_http_chunk_internal(struct ftrace_routine * routine, struct ftrace /* no real error handling for http get here */ if (ret < 0) { - msg_err("get failed with %d\n", ret); + msg_err("ftrace HTTP: get failed with %d", ret); return false; } @@ -1670,7 +1670,7 @@ __ftrace_send_http_chunk_internal(struct ftrace_routine * routine, struct ftrace /* reset printer for next chunk */ p->flags &= ~TRACE_FLAG_HEADER; if (printer_init(p, p->flags) < 0) { - msg_err("printer_init failed (alloc)\n"); + msg_err("ftrace HTTP: printer_init failed (alloc)"); return false; } @@ -1699,7 +1699,7 @@ __ftrace_send_http_chunk_internal(struct ftrace_routine * routine, struct ftrace return false; send_http_chunk_failed: - msg_err("send_http_chunk failed with %v\n", s); + msg_err("ftrace: send_http_chunk failed with %v", s); return false; } @@ -1853,7 +1853,7 @@ init_http_listener(void) ftrace_hl = allocate_http_listener(ftrace_heap, FTRACE_TRACE_PORT); if (ftrace_hl == INVALID_ADDRESS) { - msg_err("could not allocate ftrace HTTP listener\n"); + msg_err("ftrace: could not allocate HTTP listener"); return -1; } @@ -1867,14 +1867,14 @@ init_http_listener(void) connection_handler_from_http_listener(ftrace_hl) ); if (!is_ok(s)) { - msg_err("listen_port(port=%d) failed for ftrace HTTP listener\n", + msg_err("ftrace HTTP: listen_port(port=%d) failed", FTRACE_TRACE_PORT ); deallocate_http_listener(ftrace_heap, ftrace_hl); return -1; } - rprintf("started DEBUG http listener on port %d\n", FTRACE_TRACE_PORT); + msg_info("ftrace: started HTTP listener on port %d", FTRACE_TRACE_PORT); return 0; } @@ -1890,7 +1890,7 @@ ftrace_init(unix_heaps uh, filesystem fs) cpu_rbufs = allocate_vector(ftrace_heap, total_processors); if (cpu_rbufs == INVALID_ADDRESS) { - msg_err("unable to allocate rbufs vector\n"); + msg_err("ftrace: unable to allocate rbufs vector"); return -1; } u64 per_cpu_kb = DEFAULT_TRACE_ARRAY_SIZE_KB / total_processors; @@ -1898,7 +1898,7 @@ ftrace_init(unix_heaps uh, filesystem fs) vector_foreach(cpuinfos, ci) { struct rbuf *rb = allocate_rbuf(ftrace_heap, per_cpu_kb); if (rb == INVALID_ADDRESS) { - msg_err("unable to allocate cpu rbuf\n"); + msg_err("ftrace: unable to allocate cpu rbuf"); return -1; } vector_set(cpu_rbufs, ci->id, rb); @@ -1936,7 +1936,7 @@ ftrace_cpu_init(cpuinfo ci) sizeof(struct ftrace_graph_entry) * FTRACE_RETFUNC_DEPTH ); if (ci->graph_stack == INVALID_ADDRESS) { - msg_err("failed to allocare ftrace return stack array\n"); + msg_err("ftrace: failed to allocate return stack array"); return -ENOMEM; } diff --git a/src/unix/futex.c b/src/unix/futex.c index 98cfb1153..7fac3e205 100644 --- a/src/unix/futex.c +++ b/src/unix/futex.c @@ -32,14 +32,14 @@ static struct futex * soft_create_futex(process p, u64 key) f = allocate(h, sizeof(struct futex)); if (f == INVALID_ADDRESS) { - msg_err("failed to allocate futex\n"); + msg_err("futex: failed to allocate structure"); goto out; } f->h = h; f->bq = allocate_blockq(f->h, ss("futex")); if (f->bq == INVALID_ADDRESS) { - msg_err("failed to allocate futex blockq\n"); + msg_err("futex: failed to allocate blockq"); deallocate(f->h, f, sizeof(struct futex)); f = INVALID_ADDRESS; goto out; @@ -302,14 +302,9 @@ sysreturn futex(int *uaddr, int futex_op, int val, return rv; } - case FUTEX_REQUEUE: rprintf("futex_requeue not implemented\n"); break; - case FUTEX_WAKE_BITSET: rprintf("futex_wake_bitset not implemented\n"); break; - case FUTEX_LOCK_PI: rprintf("futex_lock_pi not implemented\n"); break; - case FUTEX_TRYLOCK_PI: rprintf("futex_trylock_pi not implemented\n"); break; - case FUTEX_UNLOCK_PI: rprintf("futex_unlock_pi not implemented\n"); break; - case FUTEX_CMP_REQUEUE_PI: rprintf("futex_cmp_requeue_pi not implemented\n"); break; - case FUTEX_WAIT_REQUEUE_PI: rprintf("futex_wait_requeue_pi not implemented\n"); break; - default: rprintf("futex op %d not implemented\n", op); break; + default: + msg_err("futex op %d not implemented", op); + break; } return set_syscall_error(current, ENOSYS); diff --git a/src/unix/mmap.c b/src/unix/mmap.c index a484e9110..0912e6af6 100644 --- a/src/unix/mmap.c +++ b/src/unix/mmap.c @@ -78,7 +78,7 @@ closure_func_basic(thunk, void, pending_fault_complete) vmap_unlock(p); pf_debug("%s: vaddr 0x%lx, status %v\n", func_ss, vaddr, s); if (!is_ok(s)) { - msg_err("page fill failed with %v\n", s); + msg_err("page fill failed with %v", s); } demand_page_done(ctx, vaddr, s); context_schedule_return(ctx); @@ -339,7 +339,7 @@ static status demand_page_internal(process p, context ctx, u64 vaddr, vmap vm, p { if ((vm->flags & (VMAP_FLAG_MMAP | VMAP_FLAG_STACK | VMAP_FLAG_HEAP | VMAP_FLAG_BSS | VMAP_FLAG_PROG)) == 0) { - msg_err("vaddr 0x%lx matched vmap with invalid flags (0x%x)\n", + msg_err("page fault: vaddr 0x%lx matched vmap with invalid flags (0x%x)", vaddr, vm->flags); return timm("result", "vaddr 0x%lx matched vmap with invalid flags (0x%x)\n", vaddr, vm->flags); @@ -516,7 +516,7 @@ closure_function(1, 1, boolean, vmap_paranoia_node, vmap v = (vmap)n; vmap last = *bound(last); if (last && vmap_compare_attributes(last, v) && last->node.r.end == v->node.r.start) { - rprintf("%s: check failed; adjacent nodes %p (%R) and %p (%R) share same attributes\n", + msg_err("%s: check failed; adjacent nodes %p (%R) and %p (%R) share same attributes", func_ss, last, last->node.r, v, v->node.r); return false; } @@ -800,7 +800,7 @@ sysreturn mremap(void *old_address, u64 old_size, u64 new_size, int flags, void } u64 vnew = process_get_virt_range_locked(p, new_size, PROCESS_VIRTUAL_MMAP_RANGE); if (vnew == (u64)INVALID_ADDRESS) { - msg_err("failed to allocate virtual memory, size %ld\n", new_size); + msg_err("%s: failed to allocate virtual memory, size %ld", func_ss, new_size); rv = -ENOMEM; goto unlock_out; } @@ -830,7 +830,7 @@ sysreturn mremap(void *old_address, u64 old_size, u64 new_size, int flags, void /* create new vmap with old attributes */ k.node.r = new; if (allocate_vmap_locked(p->vmaps, &k) == INVALID_ADDRESS) { - msg_err("failed to allocate vmap\n"); + msg_err("%s: failed to allocate vmap", func_ss); rv = -ENOMEM; goto unlock_out; } @@ -876,7 +876,7 @@ closure_function(3, 3, boolean, mincore_fill_vec, closure_func_basic(range_handler, boolean, mincore_vmap_gap, range r) { - thread_log(current, " found gap [0x%lx, 0x%lx)", r.start, r.end); + msg_info("mincore: found gap [0x%lx, 0x%lx)", r.start, r.end); return false; } @@ -1018,7 +1018,7 @@ closure_func_basic(range_handler, boolean, vmap_update_protections_gap, range r) { vmap_debug("%s: gap %R\n", func_ss, r); - thread_log(current, " found gap [0x%lx, 0x%lx)", r.start, r.end); + msg_info("mprotect: found gap [0x%lx, 0x%lx)", r.start, r.end); return false; } @@ -1291,7 +1291,7 @@ static sysreturn mmap(void *addr, u64 length, int prot, int flags, int fd, u64 o } if ((flags & MAP_FIXED_NOREPLACE) && rangemap_range_intersects(p->vmaps, q)) { - thread_log(current, " MAP_FIXED_NOREPLACE and collision in range %R", q); + msg_info("%s: MAP_FIXED_NOREPLACE and collision in range %R", func_ss, q); ret = -EEXIST; goto out_unlock; } @@ -1348,7 +1348,7 @@ static sysreturn mmap(void *addr, u64 length, int prot, int flags, int fd, u64 o default: thread_log(current, " fd %d: custom", fd); if (!desc->mmap) { - thread_log(current, " fail: attempt to mmap file of invalid type %d", desc->type); + msg_info("%s: invalid file type %d", func_ss, desc->type); ret = -EINVAL; goto out_unlock; } @@ -1358,7 +1358,7 @@ static sysreturn mmap(void *addr, u64 length, int prot, int flags, int fd, u64 o } } if ((vmflags & VMAP_FLAG_PROT_MASK) & ~allowed_flags) { - thread_log(current, " fail: forbidden access type 0x%x (allowed 0x%x)", + msg_info("%s: forbidden access type 0x%x (allowed 0x%x)", func_ss, vmflags & VMAP_FLAG_PROT_MASK, allowed_flags); ret = -EACCES; goto out_unlock; @@ -1376,7 +1376,7 @@ static sysreturn mmap(void *addr, u64 length, int prot, int flags, int fd, u64 o u64 vaddr = process_get_virt_range_locked(p, len, alloc_region); if (vaddr == INVALID_PHYSICAL) { ret = -ENOMEM; - thread_log(current, " failed to get virtual address range"); + msg_warn("%s failed to get virtual address range", func_ss); goto out_unlock; } q = irangel(vaddr, len); @@ -1385,7 +1385,7 @@ static sysreturn mmap(void *addr, u64 length, int prot, int flags, int fd, u64 o k.node.r = q; ret = apply(desc->mmap, &k, offset); if (ret < 0) { - thread_log(current, " custom_mmap() failed with %ld", ret); + msg_info("%s: custom handler failed with %ld", func_ss, ret); goto out_unlock; } } @@ -1575,7 +1575,7 @@ void mmap_process_init(process p, tuple root) mmap_info.thp_max_size = PAGESIZE; } if (!mmap_info.thp_max_size) - msg_err("invalid 'transparent_hugepage' value '%v'\n", transparent_hugepage); + msg_err("transparent_hugepage: invalid value '%v'", transparent_hugepage); } if (!mmap_info.thp_max_size) mmap_info.thp_max_size = low_memory ? PAGEHEAP_LOWMEM_PAGESIZE : PAGESIZE_2M; diff --git a/src/unix/netlink.c b/src/unix/netlink.c index 2ecef62a5..6609f77aa 100644 --- a/src/unix/netlink.c +++ b/src/unix/netlink.c @@ -318,7 +318,7 @@ static void nl_enqueue(nlsock s, void *msg, u64 msg_len) blockq_wake_one(s->sock.rxbq); fdesc_notify_events(&s->sock.f); } else { - msg_err("failed to enqueue message\n"); + msg_err("netlink: failed to enqueue message"); deallocate(s->sock.h, msg, msg_len); } } @@ -331,7 +331,7 @@ static void nl_enqueue_ifinfo(nlsock s, u16 type, u16 flags, u32 seq, u32 pid, s resp_len += RTA_SPACE(netif->hwaddr_len); struct nlmsghdr *hdr = allocate(s->sock.h, resp_len); if (hdr == INVALID_ADDRESS) { - msg_err("failed to allocate message\n"); + msg_err("%s: failed to allocate message", func_ss); return; } hdr->nlmsg_len = resp_len; @@ -369,7 +369,7 @@ static void nl_enqueue_ifaddr(nlsock s, u16 type, u16 flags, u32 seq, u32 pid, s RTA_SPACE(addr_len) + RTA_SPACE(sizeof(netif->name) + 2)); struct nlmsghdr *hdr = allocate(s->sock.h, resp_len); if (hdr == INVALID_ADDRESS) { - msg_err("failed to allocate message\n"); + msg_err("%s: failed to allocate message", func_ss); return; } hdr->nlmsg_len = resp_len; @@ -441,7 +441,7 @@ static void nl_enqueue_rtmsg(nlsock s, u16 type, u16 flags, u32 seq, u32 pid, st } struct nlmsghdr *hdr = allocate(s->sock.h, resp_len); if (hdr == INVALID_ADDRESS) { - msg_err("failed to allocate message\n"); + msg_err("%s: failed to allocate message", func_ss); return; } hdr->nlmsg_len = resp_len; @@ -505,7 +505,7 @@ static void nl_enqueue_done(nlsock s, struct nlmsghdr *req) { struct nlmsghdr *hdr = allocate(s->sock.h, NLMSG_HDRLEN); if (hdr == INVALID_ADDRESS) { - msg_err("failed to allocate message\n"); + msg_err("%s: failed to allocate message", func_ss); return; } hdr->nlmsg_len = NLMSG_HDRLEN; @@ -521,7 +521,7 @@ static void nl_enqueue_error(nlsock s, struct nlmsghdr *msg, int errno) int errmsg_len = NLMSG_ALIGN(sizeof(struct nlmsghdr) + sizeof(struct nlmsgerr)); struct nlmsghdr *hdr = allocate(s->sock.h, errmsg_len); if (hdr == INVALID_ADDRESS) { - msg_err("failed to allocate message\n"); + msg_err("%s: failed to allocate message", func_ss); return; } hdr->nlmsg_len = errmsg_len; diff --git a/src/unix/pipe.c b/src/unix/pipe.c index 38768a7d2..4225e1f6d 100644 --- a/src/unix/pipe.c +++ b/src/unix/pipe.c @@ -276,7 +276,7 @@ int do_pipe2(int fds[2], int flags) { pipe pipe = unix_cache_alloc(get_unix_heaps(), pipe); if (pipe == INVALID_ADDRESS) { - msg_err("failed to allocate struct pipe\n"); + msg_err("pipe: failed to allocate structure"); return -ENOMEM; } @@ -284,7 +284,7 @@ int do_pipe2(int fds[2], int flags) return -EINVAL; if (flags & O_DIRECT) { - msg_err("O_DIRECT unsupported\n"); + msg_err("pipe: O_DIRECT unsupported"); return -EOPNOTSUPP; } @@ -305,7 +305,7 @@ int do_pipe2(int fds[2], int flags) pipe->data = allocate_buffer(pipe->h, INITIAL_PIPE_DATA_SIZE); if (pipe->data == INVALID_ADDRESS) { - msg_err("failed to allocate pipe's data buffer\n"); + msg_err("pipe: failed to allocate data buffer"); goto err; } spin_lock_init(&pipe->lock); @@ -323,13 +323,13 @@ int do_pipe2(int fds[2], int flags) reader->bq = allocate_blockq(pipe->h, ss("pipe read")); if (reader->bq == INVALID_ADDRESS) { - msg_err("failed to allocate blockq\n"); + msg_err("pipe: failed to allocate blockq"); apply(reader->f.close, 0, io_completion_ignore); return -ENOMEM; } reader->fd = fds[PIPE_READ] = allocate_fd(pipe->proc, reader); if (reader->fd == INVALID_PHYSICAL) { - msg_err("failed to allocate fd\n"); + msg_err("pipe: failed to allocate fd"); apply(reader->f.close, 0, io_completion_ignore); return -EMFILE; } @@ -348,7 +348,7 @@ int do_pipe2(int fds[2], int flags) writer->bq = allocate_blockq(pipe->h, ss("pipe write")); if (writer->bq == INVALID_ADDRESS) { - msg_err("failed to allocate blockq\n"); + msg_err("pipe: failed to allocate blockq"); apply(writer->f.close, 0, io_completion_ignore); deallocate_fd(pipe->proc, fds[PIPE_READ]); fdesc_put(&pipe->files[PIPE_READ].f); @@ -356,7 +356,7 @@ int do_pipe2(int fds[2], int flags) } writer->fd = fds[PIPE_WRITE] = allocate_fd(pipe->proc, writer); if (writer->fd == INVALID_PHYSICAL) { - msg_err("failed to allocate fd\n"); + msg_err("pipe: failed to allocate fd"); apply(writer->f.close, 0, io_completion_ignore); deallocate_fd(pipe->proc, fds[PIPE_READ]); fdesc_put(&pipe->files[PIPE_READ].f); diff --git a/src/unix/poll.c b/src/unix/poll.c index f1777946f..01927fc44 100644 --- a/src/unix/poll.c +++ b/src/unix/poll.c @@ -687,7 +687,7 @@ sysreturn epoll_ctl(int epfd, int op, int fd, struct epoll_event *event) rv = epoll_add_fd(e, fd, event->events, event->data); break; default: - msg_err("unknown op %d\n", op); + msg_warn("%s: unknown op %d", func_ss, op); rv = -EINVAL; } spin_wunlock(&e->fds_lock); diff --git a/src/unix/signal.c b/src/unix/signal.c index 2798a28cd..f892b6681 100644 --- a/src/unix/signal.c +++ b/src/unix/signal.c @@ -430,18 +430,18 @@ sysreturn rt_sigaction(int signum, /* XXX we should sanitize values ... */ if (act->sa_flags & SA_NOCLDSTOP) - msg_warn("Warning: SA_NOCLDSTOP unsupported.\n"); + msg_warn("sigaction flag SA_NOCLDSTOP unsupported"); if (act->sa_flags & SA_NOCLDWAIT) - msg_warn("Warning: SA_NOCLDWAIT unsupported.\n"); + msg_warn("sigaction flag SA_NOCLDWAIT unsupported"); if (act->sa_flags & SA_RESETHAND) - msg_warn("Warning: SA_RESETHAND unsupported.\n"); + msg_warn("sigaction flag SA_RESETHAND unsupported"); #ifdef __x86_64__ /* libc should always set this on x64 ... */ if (!(act->sa_flags & SA_RESTORER)) { - msg_err("sigaction without SA_RESTORER not supported.\n"); + msg_err("sigaction without SA_RESTORER not supported"); return -EINVAL; } #endif @@ -968,7 +968,7 @@ static sysreturn allocate_signalfd(const u64 *mask, int flags) err_mem_bq: deallocate(h, sfd, sizeof(*sfd)); err_mem: - msg_err("failed to allocate\n"); + msg_err("signalfd: failed to allocate structure"); return set_syscall_error(current, ENOMEM); } @@ -1087,7 +1087,6 @@ static void default_signal_action(thread t, queued_signal qs) dump_context(&t->syscall->uc.kc.context); } } - thread_log(t, "%s", fate); halt_with_code(VM_EXIT_SIGNAL(signum), ss("%s\n"), fate); } diff --git a/src/unix/socket.c b/src/unix/socket.c index a5315b691..d9d5e92dd 100644 --- a/src/unix/socket.c +++ b/src/unix/socket.c @@ -591,7 +591,7 @@ static sysreturn unixsock_listen(struct sock *sock, int backlog) if (!s->conn_q) { s->conn_q = allocate_queue(sock->h, backlog); if (s->conn_q == INVALID_ADDRESS) { - msg_err("failed to allocate connection queue\n"); + msg_err("%s: failed to allocate connection queue", func_ss); s->conn_q = 0; ret = -ENOMEM; } @@ -832,7 +832,7 @@ static sysreturn unixsock_getsockopt(struct sock *sock, int level, rv = sockopt_copy_to_user(optval, optlen, &ret_optval, ret_optlen); goto out; unimplemented: - msg_err("getsockopt unimplemented optname: fd %d, level %d, optname %d\n", + msg_err("getsockopt unimplemented: fd %d, level %d, optname %d", sock->fd, level, optname); rv = -ENOPROTOOPT; out: @@ -911,16 +911,16 @@ static unixsock unixsock_alloc(heap h, int type, u32 flags, boolean alloc_fd) { unixsock s = allocate(h, sizeof(*s)); if (s == INVALID_ADDRESS) { - msg_err("failed to allocate socket structure\n"); + msg_err("unixsock: failed to allocate socket structure"); return 0; } s->data = allocate_queue(h, UNIXSOCK_QUEUE_MAX_LEN); if (s->data == INVALID_ADDRESS) { - msg_err("failed to allocate data buffer\n"); + msg_err("unixsock: failed to allocate data buffer"); goto err_queue; } if (socket_init(h, AF_UNIX, type, flags, &s->sock) < 0) { - msg_err("failed to initialize socket\n"); + msg_err("unixsock: failed to initialize socket"); goto err_socket; } s->sock.f.read = init_closure_func(&s->read, file_io, unixsock_read); diff --git a/src/unix/socket.h b/src/unix/socket.h index 5b1f01f65..80f1e52d1 100644 --- a/src/unix/socket.h +++ b/src/unix/socket.h @@ -115,12 +115,12 @@ static inline int socket_init(heap h, int domain, int type, u32 flags, struct so runtime_memset((u8 *) s, 0, sizeof(*s)); s->rxbq = allocate_blockq(h, ss("sock receive")); if (s->rxbq == INVALID_ADDRESS) { - msg_err("failed to allocate blockq\n"); + msg_err("%s: failed to allocate blockq", func_ss); goto err_rx; } s->txbq = allocate_blockq(h, ss("sock transmit")); if (s->txbq == INVALID_ADDRESS) { - msg_err("failed to allocate blockq\n"); + msg_err("%s: failed to allocate blockq", func_ss); goto err_tx; } s->rx_len = 0; diff --git a/src/unix/special.c b/src/unix/special.c index 8ac6ea9c6..fb74db7a5 100644 --- a/src/unix/special.c +++ b/src/unix/special.c @@ -123,7 +123,7 @@ closure_function(1, 4, void, mounts_handler, } } /* something has gone wrong looking up mount point */ - msg_err("error looking up mount point for volume '%s'\n", label); + msg_err("%s: error looking up mount point for volume '%s'", func_ss, label); b->end = saved_end; return; } else { /* root filesystem */ diff --git a/src/unix/syscall.c b/src/unix/syscall.c index e7d43c6e1..0f9d28f9f 100755 --- a/src/unix/syscall.c +++ b/src/unix/syscall.c @@ -500,8 +500,10 @@ closure_function(5, 1, void, file_read_complete, sg_list, sg, range, r, file, f, boolean, is_file_offset, io_completion, completion, status s) { - thread t = current; - thread_log(t, "%s: status %v", func_ss, s); + if (!is_ok(s)) { + sstring err_string = string_from_errno(-sysreturn_from_fs_status_value(s)); + msg_info("file read error: %s, status %v", err_string, s); + } file_io_complete(bound(f), bound(r), bound(is_file_offset), bound(sg), bound(completion), s); closure_finish(); @@ -611,8 +613,10 @@ closure_function(6, 1, void, file_write_complete, } sg_list sg = bound(sg); io_completion completion = bound(completion); - thread_log(current, "%s: f %p, sg, %p, completion %F, status %v", - func_ss, f, sg, completion, s); + if (!is_ok(s)) { + sstring err_string = string_from_errno(-sysreturn_from_fs_status_value(s)); + msg_info("file write error: %s, status %v", err_string, s); + } file_io_complete(f, bound(r), bound(is_file_offset), sg, completion, s); closure_finish(); } @@ -981,9 +985,6 @@ sysreturn dup3(int oldfd, int newfd, int flags) } /* Setting file descriptor flags on newfd is not supported. */ - if (flags & O_CLOEXEC) { - msg_warn("close-on-exec flag not supported, ignored\n"); - } return dup2(oldfd, newfd); } @@ -1959,7 +1960,7 @@ sysreturn close(int fd) if (fetch_and_add(&f->refcnt, -2) == 2) { if (f->close) return apply(f->close, get_current_context(current_cpu()), syscall_io_complete); - msg_err("no close handler for fd %d\n", fd); + msg_err("close: no handler for fd %d", fd); } return 0; diff --git a/src/unix/thread.c b/src/unix/thread.c index 5d6cbc19d..3866dcba1 100644 --- a/src/unix/thread.c +++ b/src/unix/thread.c @@ -55,7 +55,7 @@ static sysreturn clone_internal(struct clone_args_internal *args) return -EINVAL; if (!(flags & CLONE_THREAD)) { - thread_log(current, "attempted to create new process, aborting."); + msg_warn("clone: attempted to create new process"); return -ENOSYS; } @@ -478,7 +478,7 @@ thread create_thread(process p, u64 tid) destruct_context(&t->context); deallocate(h, t, sizeof(struct thread)); fail: - msg_err("failed to allocate\n"); + msg_err("thread: failed to allocate structure"); return INVALID_ADDRESS; } diff --git a/src/unix/timer.c b/src/unix/timer.c index d3b8809db..5b93b1a07 100644 --- a/src/unix/timer.c +++ b/src/unix/timer.c @@ -557,7 +557,7 @@ sysreturn timer_create(int clockid, struct sigevent *sevp, u32 *timerid) break; case SIGEV_THREAD: /* should never see this, but bark if we do */ - msg_err("SIGEV_THREAD should be handled by libc / nptl\n"); + msg_err("%s: SIGEV_THREAD should be handled by libc / nptl", func_ss); /* no break */ default: rv = -EINVAL; @@ -634,7 +634,7 @@ sysreturn timer_create(int clockid, struct sigevent *sevp, u32 *timerid) sysreturn getitimer(int which, struct itimerval *curr_value) { if (which == ITIMER_VIRTUAL) { - msg_err("timer type %d not yet supported\n", which); + msg_err("%s: timer type %d not supported", func_ss, which); return -EOPNOTSUPP; } else if ((which != ITIMER_REAL) && (which != ITIMER_PROF)) { return -EINVAL; @@ -755,7 +755,7 @@ sysreturn setitimer(int which, const struct itimerval *new_value, struct itimerval *old_value) { if (which == ITIMER_VIRTUAL) { - msg_err("timer type %d not yet supported\n", which); + msg_err("%s: timer type %d not supported", func_ss, which); return -EOPNOTSUPP; } else if ((which != ITIMER_REAL) && (which != ITIMER_PROF)) { return -EINVAL; diff --git a/src/unix/unix.c b/src/unix/unix.c index ee90d5876..0bba4056b 100644 --- a/src/unix/unix.c +++ b/src/unix/unix.c @@ -32,7 +32,7 @@ u64 allocate_fd(process p, void *f) process_lock(p); u64 fd = allocate_u64((heap)p->fdallocator, 1); if (fd == INVALID_PHYSICAL) { - msg_err("fail; maxed out\n"); + msg_err("fd allocation failed"); goto out; } if (!vector_set(p->files, fd, f)) { @@ -49,7 +49,7 @@ u64 allocate_fd_gte(process p, u64 min, void *f) process_lock(p); u64 fd = id_heap_alloc_gte(p->fdallocator, 1, min); if (fd == INVALID_PHYSICAL) { - msg_err("failed\n"); + msg_err("fd allocation failed"); } else { if (!vector_set(p->files, fd, f)) { @@ -142,7 +142,7 @@ void demand_page_done(context ctx, u64 vaddr, status s) oom_last_time = here; spin_unlock(&oom_lock); if (here - last < seconds(1) && oom_count >= 10) { - msg_err("out of memory in multiple page faults; program killed\n"); + msg_err("page fault: out of memory, program killed"); deliver_fault_signal(SIGKILL, t, vaddr, 0); } else { deliver_fault_signal(SIGBUS, t, vaddr, BUS_ADRERR); @@ -323,7 +323,7 @@ closure_func_basic(fault_handler, context, unix_fault_handler, if (is_instruction_fault(ctx->frame) && !user) { vmap_unlock(p); - msg_err("kernel instruction fault\n"); + msg_err("%s: kernel instruction fault", func_ss); goto bug; } @@ -443,7 +443,7 @@ static boolean create_stdfiles(unix_heaps uh, process p) file out = unix_cache_alloc(uh, file); file err = unix_cache_alloc(uh, file); if ((in == INVALID_ADDRESS) || (out == INVALID_ADDRESS) || (err == INVALID_ADDRESS)) { - msg_err("failed to allocate files\n"); + msg_err("Unix: failed to allocate standard files"); return false; } assert(allocate_fd(p, in) == 0); @@ -706,7 +706,7 @@ process init_unix(kernel_heaps kh, tuple root, filesystem fs) out: return kernel_process; alloc_fail: - msg_err("failed to allocate kernel objects\n"); + msg_err("%s: failed to allocate kernel objects", func_ss); return INVALID_ADDRESS; } diff --git a/src/unix/unix_clock.c b/src/unix/unix_clock.c index b29678cde..3b309be22 100644 --- a/src/unix/unix_clock.c +++ b/src/unix/unix_clock.c @@ -130,7 +130,7 @@ sysreturn clock_nanosleep(clockid_t _clock_id, int flags, const struct timespec /* Report any attempted use of CLOCK_PROCESS_CPUTIME_ID */ if (_clock_id == CLOCK_PROCESS_CPUTIME_ID) { - rprintf("%s: CLOCK_PROCESS_CPUTIME_ID not yet supported\n", func_ss); + msg_err("%s: CLOCK_PROCESS_CPUTIME_ID not supported", func_ss); return -EINVAL; } diff --git a/src/unix_process/socket_user.c b/src/unix_process/socket_user.c index a4e2c336e..6a4f42a74 100644 --- a/src/unix_process/socket_user.c +++ b/src/unix_process/socket_user.c @@ -394,7 +394,7 @@ notifier create_epoll_notifier(heap h) { descriptor f; if ((f = epoll_create(1)) < 0) { - msg_err("epoll_create failed, %s (%d)\n", errno_sstring(), errno); + msg_err("epoll_create failed, %s (%d)", errno_sstring(), errno); return 0; } epoll_notifier e = allocate(h, sizeof(struct epoll_notifier)); @@ -526,7 +526,7 @@ void connection(heap h, // this is still blocking! int res = connect(s, (struct sockaddr *)&where, sizeof(struct sockaddr_in)); if (res) { - rprintf("zikkay %d %p\n", res, failure); + msg_err("zikkay %d %p", res, failure); apply(failure, timm("errno", "%d", errno)); } else { register_descriptor_write(h, n, s, closure(h, connection_start, h, s, n, c)); diff --git a/src/virtio/virtio_9p.c b/src/virtio/virtio_9p.c index 513390a42..e2e914666 100644 --- a/src/virtio/virtio_9p.c +++ b/src/virtio/virtio_9p.c @@ -99,7 +99,7 @@ static boolean v9p_dev_attach(heap general, backed_heap backed, vtdev dev) v9p_debug(" attachment ID %ld\n", attach_id); status s = virtio_alloc_virtqueue(dev, ss("virtio 9p"), 0, &v9p->vq); if (!is_ok(s)) { - msg_err("failed to allocate virtqueue: %v\n", s); + msg_err("v9p: failed to allocate virtqueue: %v", s); goto err; } spin_lock_init(&v9p->lock); @@ -112,7 +112,7 @@ static boolean v9p_dev_attach(heap general, backed_heap backed, vtdev dev) if (!volume_add(uuid, label, v9p, init_closure_func(&v9p->fs_init, fs_init_handler, v9p_fs_init), (int)attach_id)) { - msg_err("failed to add volume\n"); + msg_err("v9p: failed to add volume"); goto err; } return true; @@ -578,7 +578,7 @@ int v9p_version(void *priv, u32 msize, sstring version, u32 *ret_msize) *ret_msize = resp->msize; s = 0; } else { - msg_err("version %s not supported\n", version); + msg_err("v9p version %s not supported", version); s = -EINVAL; } } else { diff --git a/src/virtio/virtio_balloon.c b/src/virtio/virtio_balloon.c index d6bba8206..419e729d7 100644 --- a/src/virtio/virtio_balloon.c +++ b/src/virtio/virtio_balloon.c @@ -152,7 +152,7 @@ static u64 virtio_balloon_inflate(u64 n_balloon_pages) or assertion failure, however we can't completely account for effects of fragmentation in the physical id heap. Emit a warning and quit inflating for now. */ - msg_err("failed to allocate balloon page from physical heap\n"); + msg_err("%s: failed to allocate balloon page from physical heap", func_ss); break; } @@ -392,7 +392,7 @@ static boolean virtio_balloon_attach(heap general, backed_heap backed, id_heap p virtio_balloon_init_statsq(); return true; fail: - msg_err("failed to attach: %v\n", s); + msg_err("vtbln failed to attach: %v", s); return false; } diff --git a/src/virtio/virtio_mmio.c b/src/virtio/virtio_mmio.c index d0990545b..dae543f2c 100644 --- a/src/virtio/virtio_mmio.c +++ b/src/virtio/virtio_mmio.c @@ -137,7 +137,7 @@ static boolean vtmmio_negotatiate_features(vtmmio dev, u64 mask) virtio_mmio_debug("device features 0x%lx, mask 0x%lx", virtio_dev->dev_features, mask); if (!(virtio_dev->dev_features & VIRTIO_F_VERSION_1)) { - msg_err("unsupported device features 0x%lx for device at 0x%x\n", + msg_err("vtmmio: unsupported device features 0x%lx for device at 0x%x", virtio_dev->dev_features, dev->membase); return false; } @@ -162,7 +162,7 @@ boolean attach_vtmmio(heap h, backed_heap page_allocator, vtmmio d, u64 feature_ virtio_mmio_debug("attaching device at 0x%lx, irq %d", d->membase, d->irq); vtmmio_set_status(d, VIRTIO_CONFIG_STATUS_DRIVER); if (!vtmmio_negotatiate_features(d, feature_mask)) { - msg_err("could not negotiate features for device at 0x%x\n", + msg_err("vtmmio: could not negotiate features for device at 0x%x", d->membase); return false; } diff --git a/src/virtio/virtio_net.c b/src/virtio/virtio_net.c index 2dcec0377..b75e374aa 100644 --- a/src/virtio/virtio_net.c +++ b/src/virtio/virtio_net.c @@ -369,7 +369,7 @@ closure_function(2, 1, void, vnet_cmd_mq_complete, if (s == STATUS_OK) { netif_set_link_up(&bound(vn)->ndev.n); } else { - msg_err("status %v\n", s); + msg_err("%s error %v", func_ss, s); timm_dealloc(s); } closure_finish(); @@ -421,7 +421,7 @@ closure_func_basic(netif_dev_setup, boolean, virtio_net_setup, if (dev->features & VIRTIO_NET_F_MQ) { max_vq_pairs = vtdev_cfg_read_2(dev, VIRTIO_NET_R_MAX_VQ); if (max_vq_pairs == 0) { - msg_err("device reports 0 virtqueue pairs\n"); + msg_err("%s error: device reports 0 virtqueue pairs", func_ss); return false; } if (config && get_u64(config, sym_this("io-queues"), &vq_pairs) && (vq_pairs > 0)) @@ -453,7 +453,7 @@ closure_func_basic(netif_dev_setup, boolean, virtio_net_setup, int vq_index = 2 * i; status s = virtio_alloc_vq_aff(dev, ss("virtio net rx"), vq_index, cpu_affinity, &vq); if (!is_ok(s)) { - msg_err("failed to allocate vq: %v\n", s); + msg_err("%s: failed to allocate vq: %v", func_ss, s); timm_dealloc(s); goto err2; } @@ -464,7 +464,7 @@ closure_func_basic(netif_dev_setup, boolean, virtio_net_setup, vq_index++; s = virtio_alloc_vq_aff(dev, ss("virtio net tx"), vq_index, cpu_affinity, &vq); if (!is_ok(s)) { - msg_err("failed to allocate vq: %v\n", s); + msg_err("%s: failed to allocate vq: %v", func_ss, s); timm_dealloc(s); goto err2; } @@ -476,7 +476,7 @@ closure_func_basic(netif_dev_setup, boolean, virtio_net_setup, if (vq_pairs > 1) { status s = virtio_alloc_virtqueue(dev, ss("virtio net ctrl"), 2 * max_vq_pairs, &vn->ctl); if (!is_ok(s)) { - msg_err("failed to allocate vq: %v\n", s); + msg_err("%s: failed to allocate vq: %v", func_ss, s); timm_dealloc(s); goto err2; } @@ -498,7 +498,7 @@ closure_func_basic(netif_dev_setup, boolean, virtio_net_setup, goto err3; for (u16 i = 0; i < vq_pairs; i++) if (post_receive(vn, vn->rx + i) == 0) { - msg_err("failed to fill rx queues (%d)\n", rxq_entries); + msg_err("%s: failed to fill rx queues (%d)", func_ss, rxq_entries); goto err4; } if (vq_pairs > 1) { @@ -529,7 +529,7 @@ closure_func_basic(netif_dev_setup, boolean, virtio_net_setup, err1: deallocate(h, rx, vq_pairs * sizeof(*rx)); err: - msg_err("vq pairs %d (max %d)\n", vq_pairs, max_vq_pairs); + msg_err("%s error: vq pairs %d (max %d)", func_ss, vq_pairs, max_vq_pairs); return false; } diff --git a/src/virtio/virtio_rng.c b/src/virtio/virtio_rng.c index f7fe63403..0368d5086 100644 --- a/src/virtio/virtio_rng.c +++ b/src/virtio/virtio_rng.c @@ -118,7 +118,7 @@ static boolean virtio_rng_attach(heap general, backed_heap backed, vtdev v) preferred_get_seed = virtio_rng_get_seed; return true; fail: - msg_err("failed to attach: %v\n", s); + msg_err("vtrng failed to attach: %v", s); return false; } diff --git a/src/virtio/virtio_scsi.c b/src/virtio/virtio_scsi.c index a128eee99..680bc884f 100644 --- a/src/virtio/virtio_scsi.c +++ b/src/virtio/virtio_scsi.c @@ -163,7 +163,7 @@ static void virtio_scsi_detach_disk(virtio_scsi s, u16 target, u16 lun) return; } spin_unlock(&s->lock); - msg_err("target %d lun %d not found\n", target, lun); + msg_err("%s: target %d lun %d not found", func_ss, target, lun); } closure_function(2, 1, void, virtio_scsi_event_complete, @@ -174,7 +174,7 @@ closure_function(2, 1, void, virtio_scsi_event_complete, virtio_scsi s = bound(s); virtio_scsi_debug("event 0x%x\n", e->event); if (e->event & VIRTIO_SCSI_EVENT_LOST) - msg_err("scsi event reported lost due to missing buffers\n"); + msg_err("vitio_scsi event lost due to missing buffers"); switch (e->event & ~VIRTIO_SCSI_EVENT_LOST) { case VIRTIO_SCSI_T_TRANSPORT_RESET: { u16 target = e->lun[1]; @@ -472,7 +472,7 @@ closure_function(5, 2, void, virtio_scsi_read_capacity_done, spin_unlock(&s->lock); d = allocate(s->v->virtio_dev.general, sizeof(*d)); if (d == INVALID_ADDRESS) { - msg_err("cannot allocate SCSI disk\n"); + msg_err("virtio_scsi: cannot allocate disk"); goto out; } @@ -619,7 +619,7 @@ static void send_lun_inquiry(virtio_scsi s, u16 target, u16 lun) vsr_complete completion = closure(s->v->virtio_dev.general, virtio_scsi_inquiry_done, s->sa, target, lun, -1, 0, 0); if (completion == INVALID_ADDRESS) { - msg_err("failed to allocate completion\n"); + msg_err("virtio_scsi LUN inquiry: failed to allocate completion"); return; } virtio_scsi_inquiry_vpd(s, target, lun, SCSI_VPD_DEVID, completion); @@ -723,7 +723,7 @@ static void virtio_scsi_attach(heap general, storage_attach a, backed_heap page_ for (int i = 0; i < VIRTIO_SCSI_NUM_EVENTS; i++) virtio_scsi_enqueue_event(s, s->events + i, 0); else - msg_err("failed to allocate events\n"); + msg_err("%s: failed to allocate events", func_ss); // scan bus for (u16 target = 0; target <= s->max_target; target++) diff --git a/src/virtio/virtio_socket.c b/src/virtio/virtio_socket.c index 512817163..a2b7a0ec5 100644 --- a/src/virtio/virtio_socket.c +++ b/src/virtio/virtio_socket.c @@ -102,13 +102,13 @@ static boolean virtio_sock_dev_attach(heap general, backed_heap backed, vtdev de virtio_sock_debug(" guest CID %d", vs->guest_cid); status s = virtio_alloc_virtqueue(dev, ss("virtio socket rx"), 0, &vs->rxq); if (!is_ok(s)) { - msg_err("failed to allocate rx virtqueue: %v\n", s); + msg_err("%s: failed to allocate rx virtqueue: %v", func_ss, s); timm_dealloc(s); goto err; } s = virtio_alloc_virtqueue(dev, ss("virtio socket tx"), 1, &vs->txq); if (!is_ok(s)) { - msg_err("failed to allocate tx virtqueue: %v\n", s); + msg_err("%s: failed to allocate tx virtqueue: %v", func_ss, s); timm_dealloc(s); goto err; } @@ -117,7 +117,7 @@ static boolean virtio_sock_dev_attach(heap general, backed_heap backed, vtdev de * about an "attempt to use virtio queue that is not marked ready". */ s = virtio_alloc_virtqueue(dev, ss("virtio socket events"), 2, &vs->eventq); if (!is_ok(s)) { - msg_err("failed to allocate event virtqueue: %v\n", s); + msg_err("%s: failed to allocate event virtqueue: %v", func_ss, s); timm_dealloc(s); goto err; } diff --git a/src/virtio/virtio_storage.c b/src/virtio/virtio_storage.c index 30ecddc05..2baf0cca0 100644 --- a/src/virtio/virtio_storage.c +++ b/src/virtio/virtio_storage.c @@ -166,7 +166,7 @@ static inline void storage_rw_internal(storage st, boolean write, void * buf, vqmsg_commit(vq, m, c); return; out_inval: - msg_err("%s", err); /* yes, bark */ + msg_err("vtblk R/W error: %s", err); apply(sh, timm("result", "%s", err)); } diff --git a/src/vmware/pvscsi.c b/src/vmware/pvscsi.c index fa3c3176c..f82bdfb74 100644 --- a/src/vmware/pvscsi.c +++ b/src/vmware/pvscsi.c @@ -180,7 +180,7 @@ closure_function(6, 0, void, pvscsi_io_done, bound(len)); return; } - rprintf("scsi_status not ok: %d\n", hcb->scsi_status); + msg_err("pvscsi: scsi_status not ok: %d", hcb->scsi_status); scsi_dump_sense(hcb->sense, sizeof(hcb->sense)); st = timm("result", "status %d", hcb->scsi_status); } @@ -237,7 +237,7 @@ closure_function(5, 0, void, pvscsi_read_capacity_done, pvscsi_disk d = allocate(s->general, sizeof(*d)); if (d == INVALID_ADDRESS) { - msg_err("cannot allocate PVSCSI disk\n"); + msg_err("pvscsi: cannot allocate disk"); goto out; } diff --git a/src/vmware/vmxnet3_net.c b/src/vmware/vmxnet3_net.c index 102928572..3caec78f6 100644 --- a/src/vmware/vmxnet3_net.c +++ b/src/vmware/vmxnet3_net.c @@ -253,7 +253,7 @@ closure_function(1, 0, void, vmxnet3_rx_service_bh, struct netif *n = &vn->ndev.n; err_enum_t err = n->input((struct pbuf *)rxb, n); if (err != ERR_OK) { - msg_err("vmxnet3: rx drop by stack, err %d\n", err); + msg_err("vmxnet3: rx drop by stack, err %d", err); receive_buffer_release((struct pbuf *)rxb); } } diff --git a/src/x86_64/hpet.c b/src/x86_64/hpet.c index 9a6325d3d..a4e9eb1ad 100644 --- a/src/x86_64/hpet.c +++ b/src/x86_64/hpet.c @@ -188,7 +188,7 @@ closure_function(0, 0, timestamp, hpet_now) boolean init_hpet(kernel_heaps kh) { void *hpet_page = allocate((heap)heap_virtual_page(kh), PAGESIZE); if (hpet_page == INVALID_ADDRESS) { - msg_err("failed to allocate page for HPET\n"); + msg_err("HPET: failed to allocate page"); return false; } @@ -214,6 +214,6 @@ boolean init_hpet(kernel_heaps kh) { 0 /* no per-cpu init */); return true; } - msg_err("failed to initialize HPET; main counter not incrementing\n"); + msg_err("HPET init failed; main counter not incrementing"); return false; } diff --git a/src/x86_64/interrupt.c b/src/x86_64/interrupt.c index 00d65f1d3..5121a23de 100644 --- a/src/x86_64/interrupt.c +++ b/src/x86_64/interrupt.c @@ -403,7 +403,7 @@ void __attribute__((noreturn)) __stack_chk_fail(void) { cpuinfo ci = current_cpu(); context ctx = get_current_context(ci); - rprintf("stack check failed on cpu %d\n", ci->id); + msg_err("stack check failed on cpu %d", ci->id); dump_context(ctx); vm_exit(VM_EXIT_FAULT); } diff --git a/src/xen/xen.c b/src/xen/xen.c index d929ba3ea..7ce83348e 100644 --- a/src/xen/xen.c +++ b/src/xen/xen.c @@ -168,11 +168,11 @@ static boolean xen_grant_init(kernel_heaps kh) qs.dom = DOMID_SELF; int rv = HYPERVISOR_grant_table_op(GNTTABOP_query_size, &qs, 1); if (rv < 0) { - msg_err("failed to query grant table size (rv %d)\n", rv); + msg_err("xen: failed to query grant table size (rv %d)", rv); return false; } if (qs.status != GNTST_okay) { - msg_err("grant table query returned error status %d\n", qs.status); + msg_err("xen: grant table query returned error status %d", qs.status); return false; } gt->n_entries = qs.max_nr_frames * (PAGESIZE / sizeof(grant_entry_v2_t)); @@ -181,7 +181,7 @@ static boolean xen_grant_init(kernel_heaps kh) heap table_heap = (heap)heap_linear_backed(kh); gt->table = allocate_zero(table_heap, qs.max_nr_frames * PAGESIZE); if (gt->table == INVALID_ADDRESS) { - msg_err("failed to allocate grant table\n"); + msg_err("xen: failed to allocate grant table"); return false; } xen_debug("%s: table v 0x%lx, p 0x%lx", func_ss, gt->table, physical_from_virtual(gt->table)); @@ -191,14 +191,14 @@ static boolean xen_grant_init(kernel_heaps kh) gt->entry_heap = (heap)create_id_heap(h, h, GTAB_RESERVED_ENTRIES + 1, gt->n_entries - GTAB_RESERVED_ENTRIES, 1, true); if (gt->entry_heap == INVALID_ADDRESS) { - msg_err("failed to allocate grant table occupancy heap\n"); + msg_err("xen: failed to allocate grant table occupancy heap"); goto fail_dealloc_table; } /* We have this feature on the platforms we care about now, but we can add support for the other case if need be. */ if (!xen_feature_supported(XENFEAT_auto_translated_physmap)) { - msg_err("auto translated physmap feature required\n"); + msg_err("%s error: auto translated physmap feature required", func_ss); goto fail_dealloc_heap; } @@ -216,7 +216,7 @@ static boolean xen_grant_init(kernel_heaps kh) xen_debug("grant page %d, gpfn %x", xatp.idx, xatp.gpfn); rv = HYPERVISOR_memory_op(XENMEM_add_to_physmap, &xatp); if (rv < 0) { - msg_err("failed to add grant table page (rv %d)\n", rv); + msg_err("xen: failed to add grant table page (rv %d)", rv); goto fail_dealloc_heap; } } @@ -266,7 +266,7 @@ closure_func_basic(clock_timer, void, xen_runloop_timer, sst.flags = 0; int rv = HYPERVISOR_vcpu_op(VCPUOP_set_singleshot_timer, vcpu, &sst); if (rv != 0) { - msg_err("failed on cpu %d; rv %d\n", vcpu, rv); + msg_err("%s failed on cpu %d; rv %d", func_ss, vcpu, rv); } } @@ -286,7 +286,7 @@ static void xenstore_watch_event(struct xsd_sockmsg *msg) do { s64 r = xenstore_read_internal(b, length); if (r < 0) { - msg_err("failed to read\n"); + msg_err("%s: failed to read", func_ss); return; } length -= r; @@ -295,13 +295,13 @@ static void xenstore_watch_event(struct xsd_sockmsg *msg) sstring path = sstring_from_cstring(buffer_ref(b, 0), msg->len); bytes path_len = path.len; if (path_len == msg->len) { - msg_err("no string terminator for xenstore path\n"); + msg_err("%s: no string terminator for xenstore path", func_ss); return; } buffer_consume(b, path_len + 1); u64 token; if (!parse_int(b, 16, &token)) { - msg_err("failed to parse token\n"); + msg_err("%s: failed to parse token", func_ss); return; } @@ -345,7 +345,7 @@ static int xen_setup_vcpu(int vcpu, u64 shared_info_phys) vrvi.offset = vci_pa & (PAGESIZE - 1); int rv = HYPERVISOR_vcpu_op(VCPUOP_register_vcpu_info, vcpu, &vrvi); if (rv < 0) { - msg_err("failed to register vcpu info for cpu %d (rv %d)\n", vcpu, rv); + msg_err("xen: failed to register vcpu info for cpu %d (rv %d)", vcpu, rv); return rv; } @@ -354,7 +354,7 @@ static int xen_setup_vcpu(int vcpu, u64 shared_info_phys) xen_debug("stopping periodic tick timer on cpu %d...", vcpu); rv = HYPERVISOR_vcpu_op(VCPUOP_stop_periodic_timer, vcpu, 0); if (rv < 0) { - msg_err("unable to stop periodic timer on cpu %d (rv %d)\n", vcpu, rv); + msg_err("xen: unable to stop periodic timer on cpu %d (rv %d)", vcpu, rv); return rv; } @@ -364,7 +364,7 @@ static int xen_setup_vcpu(int vcpu, u64 shared_info_phys) eop.u.bind_virq.vcpu = vcpu; rv = HYPERVISOR_event_channel_op(&eop); if (rv < 0) { - msg_err("failed to bind virtual timer IRQ for cpu %d (rv %d)\n", vcpu, rv); + msg_err("xen: failed to bind virtual timer IRQ for cpu %d (rv %d)", vcpu, rv); return rv; } evtchn_port_t timer_evtchn = eop.u.bind_virq.port; @@ -430,7 +430,7 @@ boolean xen_detect(kernel_heaps kh) cpuid(XEN_CPUID_LEAF(2), 0, v); if (v[0] != 1) { - msg_err("xen reporting %d hypercall pages; not supported\n", v[0]); + msg_err("xen reporting %d hypercall pages; not supported", v[0]); return false; } xen_info.msr_base = v[1]; @@ -460,14 +460,14 @@ boolean xen_detect(kernel_heaps kh) xfi.submap_idx = 0; int rv = HYPERVISOR_xen_version(XENVER_get_features, &xfi); if (rv < 0) { - msg_err("failed to get xen features map (rv %d)\n", rv); + msg_err("xen: failed to get features map (rv %d)", rv); return false; } xen_info.features = xfi.submap; xen_debug("reported features map 0x%x", xen_info.features); if (!xen_feature_supported(XENFEAT_hvm_safe_pvclock)) { - msg_err("failed to init; XENFEAT_hvm_safe_pvclock required\n"); + msg_err("xen failed to init; XENFEAT_hvm_safe_pvclock required"); return false; } @@ -478,7 +478,7 @@ boolean xen_detect(kernel_heaps kh) xen_hvm_param.index = HVM_PARAM_STORE_PFN; rv = HYPERVISOR_hvm_op(HVMOP_get_param, &xen_hvm_param); if (rv < 0) { - msg_err("failed to get xenstore page address (rv %d)\n", rv); + msg_err("xen: failed to get xenstore page address (rv %d)", rv); return false; } xen_info.xenstore_paddr = xen_hvm_param.value << PAGELOG; @@ -495,7 +495,7 @@ boolean xen_detect(kernel_heaps kh) xen_hvm_param.index = HVM_PARAM_STORE_EVTCHN; rv = HYPERVISOR_hvm_op(HVMOP_get_param, &xen_hvm_param); if (rv < 0) { - msg_err("failed to get xenstore event channel (rv %d)\n", rv); + msg_err("xen: failed to get xenstore event channel (rv %d)", rv); return false; } @@ -515,13 +515,13 @@ boolean xen_detect(kernel_heaps kh) xatp.gpfn = shared_info_phys >> PAGELOG; rv = HYPERVISOR_memory_op(XENMEM_add_to_physmap, &xatp); if (rv < 0) { - msg_err("failed to add shared info map (rv %d)\n", rv); + msg_err("xen: failed to add shared info map (rv %d)", rv); goto out_dealloc_shared_page; } xen_debug("shared info page: %p, phys 0x%lx", shared_info, shared_info_phys); if (!xen_feature_supported(XENFEAT_hvm_callback_vector)) { - msg_err("HVM callback vector must be supported; xen setup failed (features mask 0x%x)\n", + msg_err("xen setup failed: HVM callback vector must be supported (features mask 0x%x)", xen_info.features); goto out_dealloc_shared_page; } @@ -536,7 +536,7 @@ boolean xen_detect(kernel_heaps kh) xen_hvm_param.value = (2ull << 56) | irq; rv = HYPERVISOR_hvm_op(HVMOP_set_param, &xen_hvm_param); if (rv < 0) { - msg_err("failed to register event channel interrupt vector (rv %d)\n", rv); + msg_err("xen: failed to register event channel interrupt vector (rv %d)", rv); goto out_unregister_irq; } @@ -560,7 +560,7 @@ boolean xen_detect(kernel_heaps kh) assert(xen_unmask_evtchn(xen_info.xenstore_evtchn) == 0); if (!xen_grant_init(kh)) { - msg_err("failed to set up grant tables\n"); + msg_err("xen: failed to set up grant tables"); goto out_unregister_irq; } @@ -569,7 +569,7 @@ boolean xen_detect(kernel_heaps kh) init_closure_func(&xen_info.shutdown_watcher, xenstore_watch_handler, xen_shutdown_watcher), true))) - msg_err("failed to register shutdown handler\n"); + msg_err("xen: failed to register shutdown handler"); xen_debug("xen initialization complete"); list_init(&xen_info.driver_list); @@ -1095,7 +1095,7 @@ closure_func_basic(thunk, void, xen_scan_service) status s = xen_scan(); atomic_clear_bit(&xen_info.scanning, 0); if (!is_ok(s)) { - msg_warn("cannot scan devices: %v\n", s); + msg_warn("xen: cannot scan devices: %v", s); timm_dealloc(s); } } @@ -1112,7 +1112,7 @@ status xen_probe_devices(void) xen_watch_handler), true); if (!is_ok(s)) { - msg_warn("cannot watch devices: %v\n", s); + msg_warn("xen: cannot watch devices: %v", s); timm_dealloc(s); s = STATUS_OK; } diff --git a/src/xen/xenblk.c b/src/xen/xenblk.c index f3dfcc4bf..750c209bb 100644 --- a/src/xen/xenblk.c +++ b/src/xen/xenblk.c @@ -269,7 +269,7 @@ static void xenblk_remove(xenblk_dev xbd) status s = xenbus_watch_state(xbd->dev.backend, (xenstore_watch_handler)&xbd->watch_handler, false); if (!is_ok(s)) { - msg_err("failed to unwatch backend state: %v\n", s); + msg_err("%s: failed to unwatch backend state: %v", func_ss, s); timm_dealloc(s); return; } @@ -294,7 +294,7 @@ closure_func_basic(thunk, void, xenblk_watch_service) XenbusState backend_state; status s = xenbus_get_state(xbd->dev.backend, &backend_state); if (!is_ok(s)) { - msg_err("failed to get backend state: %v\n", s); + msg_err("%s: failed to get backend state: %v", func_ss, s); timm_dealloc(s); return; } @@ -306,11 +306,11 @@ closure_func_basic(thunk, void, xenblk_watch_service) u64 sector_size; s = xenstore_read_u64(0, xd->backend, ss("sector-size"), §or_size); if (!is_ok(s)) { - msg_err("cannot read sector size: %v\n", s); + msg_err("%s: cannot read sector size: %v", func_ss, s); timm_dealloc(s); goto remove; } else if (sector_size != SECTOR_SIZE) { - msg_err("unsupported sector size %ld\n", sector_size); + msg_err("%s: unsupported sector size %ld", func_ss, sector_size); goto remove; } s = xenstore_read_u64(0, xd->backend, ss("physical-sector-size"), @@ -319,26 +319,26 @@ closure_func_basic(thunk, void, xenblk_watch_service) /* physical sector size is the same as logical sector size */ timm_dealloc(s); } else if (sector_size != SECTOR_SIZE) { - msg_err("unsupported physical sector size %ld\n", sector_size); + msg_err("%s: unsupported physical sector size %ld", func_ss, sector_size); goto remove; } u64 sectors; s = xenstore_read_u64(0, xd->backend, ss("sectors"), §ors); if (!is_ok(s)) { - msg_err("cannot read number of sectors: %v\n", s); + msg_err("%s: cannot read number of sectors: %v", func_ss, s); timm_dealloc(s); goto remove; } xbd->capacity = sector_size * sectors; s = xenbus_set_state(0, xd->frontend, XenbusStateConnected); if (!is_ok(s)) { - msg_err("cannot set frontend state to connected: %v\n", s); + msg_err("%s: cannot set frontend state to connected: %v", func_ss, s); timm_dealloc(s); goto remove; } int rv = xen_unmask_evtchn(xbd->evtchn); if (rv < 0) { - msg_err("failed to unmask event channel %d: rv %d\n", xbd->evtchn, rv); + msg_err("%s: failed to unmask event channel %d: rv %d", func_ss, xbd->evtchn, rv); goto remove; } int attach_id; @@ -489,7 +489,7 @@ closure_function(2, 3, boolean, xenblk_probe, heap h = heap_locked(kh); xenblk_dev xbd = allocate(h, sizeof(*xbd)); if (xbd == INVALID_ADDRESS) { - msg_err("cannot allocate device structure\n"); + msg_err("%s: cannot allocate device structure", func_ss); return false; } xen_dev xd = &xbd->dev; @@ -497,13 +497,13 @@ closure_function(2, 3, boolean, xenblk_probe, xbd->contiguous = (heap)heap_linear_backed(kh); status s = xendev_attach(xd, id, frontend, meta); if (!is_ok(s)) { - msg_err("cannot attach Xen device: %v\n", s); + msg_err("%s: cannot attach Xen device: %v", func_ss, s); timm_dealloc(s); goto dealloc_xbd; } xbd->rreqs = allocate_vector(h, XENBLK_RING_SIZE); if (xbd->rreqs == INVALID_ADDRESS) { - msg_err("cannot allocate request vector\n"); + msg_err("%s: cannot allocate request vector", func_ss); goto dealloc_xbd; } list_init(&xbd->pending); @@ -515,7 +515,7 @@ closure_function(2, 3, boolean, xenblk_probe, xbd->meta = meta; s = xenblk_enable(xbd); if (!is_ok(s)) { - msg_err("cannot enable device: %v\n", s); + msg_err("%s: cannot enable device: %v", func_ss, s); timm_dealloc(s); goto dealloc_reqs; } diff --git a/src/xen/xennet.c b/src/xen/xennet.c index 6f2539a5d..24299de21 100644 --- a/src/xen/xennet.c +++ b/src/xen/xennet.c @@ -272,7 +272,8 @@ static void xennet_service_tx_ring(xennet_dev xd) if (tx->status != NETIF_RSP_OKAY) { /* XXX counters */ - msg_err("cons %d, tx resp id %d, status %d\n", cons, tx->id, tx->status); + msg_err("%s error: cons %d, tx resp id %d, status %d", + func_ss, cons, tx->id, tx->status); } xennet_tx_page txp = xennet_get_tx_page(txb, xennet_tx_page_idx_from_id(tx->id)); @@ -543,7 +544,7 @@ static void xennet_populate_rx_ring(xennet_dev xd) xennet_rx_buf rxb = xennet_get_rxbuf(xd); if (!rxb) { /* not a ring underrun, but we still want to know if we're close */ - msg_err("xennet_get_rxbuf underrun\n"); + msg_err("xennet_get_rxbuf underrun"); break; } @@ -635,7 +636,7 @@ closure_function(1, 0, void, xennet_rx_service_bh, struct netif *n = &xd->ndev.n; err_enum_t err = n->input((struct pbuf *)&rxb->p, n); if (err != ERR_OK) { - msg_err("xennet: rx drop by stack, err %d\n", err); + msg_err("xennet: rx drop by stack, err %d", err); xennet_return_rxbuf((struct pbuf *)&rxb->p); } } @@ -840,7 +841,7 @@ closure_function(1, 3, boolean, xennet_probe, xennet_debug("probe for id %d, meta: %v", id, meta); status s = xennet_attach(bound(kh), id, frontend, meta); if (!is_ok(s)) { - msg_err("attach failed with status %v\n", s); + msg_err("xennet attach failed with status %v", s); return false; } return true; diff --git a/test/runtime/mmap.c b/test/runtime/mmap.c index 9f75823de..8b679bd74 100644 --- a/test/runtime/mmap.c +++ b/test/runtime/mmap.c @@ -1081,7 +1081,7 @@ static void filebacked_test(heap h) sha256(sha, b); munmap(p, PAGESIZE); if (!buffer_compare(sha, test)) { - rprintf(" sha mismatch for faulted page: %X\n", sha); + msg_err("%s: sha mismatch for faulted page: %X", func_ss, sha); close(fd); exit(EXIT_FAILURE); } @@ -1126,7 +1126,7 @@ static void filebacked_test(heap h) munmap(p, PAGESIZE); close(fd); if (!buffer_compare(sha, test)) { - rprintf(" sha mismatch for faulted page 2: %X\n", sha); + msg_err("%s: sha mismatch for faulted page 2: %X", func_ss, sha); close(fd); exit(EXIT_FAILURE); } diff --git a/test/unit/bitmap_test.c b/test/unit/bitmap_test.c index eca9cb42d..b81228233 100644 --- a/test/unit/bitmap_test.c +++ b/test/unit/bitmap_test.c @@ -12,7 +12,7 @@ bitmap test_alloc(heap h) { bitmap b = allocate_bitmap(h, h, 4096); bitmap_foreach_set(b, i) { if (i) { - msg_err("!!! allocation failed for bitmap\n"); + msg_err("%s failed for bitmap", func_ss); return NULL; } } @@ -32,12 +32,12 @@ boolean test_clone(bitmap b) { bitmap_foreach_set(b, j) { // implicit test for bitmap_foreach_set if (!bitmap_get(b, j)) { - msg_err("!!! foreach_set failed for bitmap\n"); + msg_err("%s: foreach_set failed for bitmap", func_ss); deallocate_bitmap(b_cpy); return false; } if (!bitmap_get(b_cpy, j)) { - msg_err("!!! cloning failed for bitmap\n"); + msg_err("%s: cloning failed for bitmap", func_ss); deallocate_bitmap(b_cpy); return false; } @@ -46,12 +46,12 @@ boolean test_clone(bitmap b) { bitmap_foreach_set(b_cpy, j) { // implicit test for bitmap_foreach_set if (!bitmap_get(b_cpy, j)) { - msg_err("!!! foreach_set failed for bitmap\n"); + msg_err("%s: foreach_set failed for bitmap", func_ss); deallocate_bitmap(b_cpy); return false; } if (!bitmap_get(b, j)) { - msg_err("!!! cloning failed for bitmap\n"); + msg_err("%s: cloning failed for bitmap", func_ss); deallocate_bitmap(b_cpy); return false; } @@ -76,12 +76,12 @@ boolean test_copy(heap h, bitmap b) { bitmap_foreach_set(b, j) { // implicit test for bitmap_foreach_set if (!bitmap_get(b, j)) { - msg_err("!!! foreach_set failed for bitmap\n"); + msg_err("%s: foreach_set failed for bitmap", func_ss); deallocate_bitmap(b_cpy); return false; } if (!bitmap_get(b_cpy, j)) { - msg_err("!!! cloning failed for bitmap\n"); + msg_err("%s: copy failed for bitmap", func_ss); deallocate_bitmap(b_cpy); return false; } @@ -90,12 +90,12 @@ boolean test_copy(heap h, bitmap b) { bitmap_foreach_set(b_cpy, j) { // implicit test for bitmap_foreach_set if (!bitmap_get(b_cpy, j)) { - msg_err("!!! foreach_set failed for bitmap\n"); + msg_err("%s: foreach_set failed for bitmap", func_ss); deallocate_bitmap(b_cpy); return false; } if (!bitmap_get(b, j)) { - msg_err("!!! cloning failed for bitmap\n"); + msg_err("%s: copy failed for bitmap", func_ss); deallocate_bitmap(b_cpy); return false; } @@ -112,7 +112,7 @@ boolean test_set_and_get(bitmap b) { u64 i = rand(); bitmap_set(b, i, 1); if (!bitmap_get(b, i)) { - msg_err("!!! set and get failed for bitmap\n"); + msg_err("%s failed for bitmap", func_ss); return false; } return true; @@ -129,7 +129,7 @@ boolean test_wrap(heap h) { for (int i = 0; i < 64; i++) { if (((map & (1ULL << i)) && !bitmap_get(b, i)) || (!(map & (1ULL << i)) && bitmap_get(b, i))) { - msg_err("!!! wrap failed for bitmap at bit %d | map: %ld bitmap: %ld\n", + msg_err("%s: wrap failed for bitmap at bit %d | map: %ld bitmap: %ld", func_ss, i, (map & (1ULL << i)), bitmap_get(b, i)); bitmap_unwrap(b); return false; @@ -150,7 +150,7 @@ boolean test_bitmap_alloc(bitmap b, u64 start, u64 end) { first = bitmap_alloc_within_range(b, nbits, start, end); if (first != INVALID_PHYSICAL) { if (nbits > (end-start)) { - msg_err("!!! invalid value for nbits: %ld end-start: %ld\n", nbits, (end-start)); + msg_err("%s: nbits (%ld) > end-start (%ld)", func_ss, nbits, (end-start)); return false; } break; @@ -161,16 +161,16 @@ boolean test_bitmap_alloc(bitmap b, u64 start, u64 end) { // check that specified range is set properly for (int i = first; i < first + nbits; i++) { if (bitmap_get(b, i) != 1) { - msg_err("!!! bitmap_alloc failed for bitmap at bit %d | expected: %d actual: %d\n", + msg_err("%s failed at bit %d | expected: %d actual: %d", func_ss, i, 1, bitmap_get(b, i)); if (!bitmap_dealloc(b, first, nbits)) - msg_err("!!! bitmap_dealloc failed for bitmap\n"); + msg_err("%s: bitmap_dealloc failed", func_ss); return false; } } // check that dealloc is successful if (!bitmap_dealloc(b, first, nbits)) { - msg_err("!!! bitmap_dealloc failed for bitmap\n"); + msg_err("%s: bitmap_dealloc failed", func_ss); return false; } return true; @@ -188,7 +188,7 @@ boolean test_range_check_set(bitmap b) { // check that specified range is set properly for (int i = start; i < start + nbits; i++) { if (bitmap_get(b, i) != set) { - msg_err("!!! range check and set failed for bitmap at bit %d | expected: %d actual: %d\n", + msg_err("%s failed for bitmap at bit %d | expected: %d actual: %d", func_ss, i, set, bitmap_get(b, i)); return false; } @@ -201,12 +201,12 @@ boolean test_range_get_first(bitmap b) { u64 first = bitmap_range_get_first(b, start, nbits); if (first != INVALID_PHYSICAL) { if (!point_in_range(irangel(start, nbits), first)) { - msg_err("range_get_first() returned %ld, expected range %R\n", first, + msg_err("%s error: returned %ld, expected range %R", func_ss, first, irangel(start, nbits)); return false; } if (!bitmap_get(b, first)) { - msg_err("range_get_first() failed at bit %ld, expected 1 (start %ld, nbits %ld)\n", + msg_err("%s failed at bit %ld, expected 1 (start %ld, nbits %ld)", func_ss, first, start, nbits); return false; } @@ -215,8 +215,8 @@ boolean test_range_get_first(bitmap b) { } for (u64 i = start; i < first; i++) { if (bitmap_get(b, i)) { - msg_err("range_get_first() failed at bit %ld, expected 0 " - "(start %ld, nbits %ld, first %ld)\n", i, start, nbits, first); + msg_err("%s failed at bit %ld, expected 0 (start %ld, nbits %ld, first %ld)", + func_ss, i, start, nbits, first); return false; } } @@ -272,7 +272,7 @@ int main(int argc, char **argv) msg_debug("test passed\n"); exit(EXIT_SUCCESS); fail: - msg_err("test failed\n"); + msg_err("Bitmap test failed"); exit(EXIT_FAILURE); } diff --git a/test/unit/buffer_test.c b/test/unit/buffer_test.c index e18d4438d..d7522e0c7 100644 --- a/test/unit/buffer_test.c +++ b/test/unit/buffer_test.c @@ -10,7 +10,7 @@ #define test_assert(expr) do { \ if (expr) ; else { \ - msg_err("%s -- failed at %s:%d\n", ss(#expr), file_ss, __LINE__); \ + msg_err("%s: %s -- failed at %s:%d", func_ss, ss(#expr), file_ss, __LINE__); \ goto fail; \ } \ } while (0) @@ -369,7 +369,7 @@ int main(int argc, char **argv) failure |= ringbuf_tests(h); if (failure) { - msg_err("Test failed\n"); + msg_err("Buffer test failed"); exit(EXIT_FAILURE); } exit(EXIT_SUCCESS); diff --git a/test/unit/id_heap_test.c b/test/unit/id_heap_test.c index 3016f5b9a..8823bc95e 100644 --- a/test/unit/id_heap_test.c +++ b/test/unit/id_heap_test.c @@ -28,12 +28,12 @@ static boolean basic_test(heap h) for (int i=0; i < pages; i += n) { u64 a = allocate_u64(id, pagesize * n); if (a == INVALID_PHYSICAL) { - msg_err("!!! allocation failed for page %ld\n", i); + msg_err("%s: allocation failed for page %ld", func_ss, i); return false; } u64 expect = base + i * pagesize; if (a != expect) { - msg_err("!!! allocation for page %ld returned %lx, expecting %lx\n", + msg_err("%s: allocation for page %ld returned 0x%lx, expecting 0x%lx", func_ss, i, a, expect); return false; } @@ -51,7 +51,7 @@ static boolean basic_test(heap h) id_heap_set_next((id_heap)id, pagesize * n, 0); } if (heap_allocated(id) > 0) { - msg_err("heap allocated should be zero; fail\n"); + msg_err("%s: heap allocated should be zero; fail", func_ss); return false; } destroy_heap(id); @@ -93,7 +93,7 @@ static boolean random_test(heap h, heap rh, u64 page_order, int churn) alloc_result_vec[o] = allocate_u64(id, alloc_size_vec[o]); msg_debug("alloc %d, size %ld, result %lx\n", o, alloc_size_vec[o], alloc_result_vec[o]); if (alloc_result_vec[o] == INVALID_PHYSICAL) { - msg_err("alloc of size %ld failed\n", alloc_size_vec[o]); + msg_err("%s: alloc of size %ld failed", func_ss, alloc_size_vec[o]); goto fail; } } @@ -111,7 +111,7 @@ static boolean random_test(heap h, heap rh, u64 page_order, int churn) if ((i_first >= j_first && i_first <= j_last) || (i_last >= j_first && i_last <= j_last)) { - msg_err("results %d and %d intersect\n", i, j); + msg_err("%s error: results %d and %d intersect", func_ss, i, j); goto fail; } } @@ -133,15 +133,15 @@ static boolean random_test(heap h, heap rh, u64 page_order, int churn) } while(churn-- > 0); if (heap_allocated(id) > 0) { - msg_err("heap allocated (%d) should be zero; fail\n", heap_allocated(id)); + msg_err("%s: heap allocated (%d) should be zero; fail", func_ss, heap_allocated(id)); return false; } destroy_heap(id); return true; fail: - msg_err("test vector:\ni\t(alloc,\tresult)\n"); + msg_err("%s error: test vector:\ni\t(alloc,\tresult)", func_ss); for (int i=0; i < VEC_LEN; i++) { - rprintf("%d\t(%ld,\t%lx)\n", i, alloc_size_vec[i], alloc_result_vec[i]); + msg_err("%d\t(%ld,\t%lx)", i, alloc_size_vec[i], alloc_result_vec[i]); } return false; } @@ -176,22 +176,22 @@ static boolean alloc_gte_test(heap h) { id_heap idh = create_id_heap(h, h, 0, GTE_TEST_MAX, 1, false); if (idh == INVALID_ADDRESS) { - msg_err("cannot create heap\n"); + msg_err("%s error: cannot create heap", func_ss); return false; } if (id_heap_alloc_gte(idh, 1, GTE_TEST_MAX) != INVALID_PHYSICAL) { - msg_err("allocation should have failed for id %ld\n", GTE_TEST_MAX); + msg_err("%s error: allocation should have failed for id %ld", func_ss, GTE_TEST_MAX); return false; } for (u64 id = 0; id < GTE_TEST_MAX; id++) { u64 allocated = id_heap_alloc_gte(idh, 1, id); if (allocated != id) { if (allocated == INVALID_PHYSICAL) { - msg_err("allocation failed for id %ld\n", id); + msg_err("%s: allocation failed for id %ld", func_ss, id); return false; } else { - msg_err("allocation returned %ld, expecting %ld\n", allocated, + msg_err("%s error: allocation returned %ld, expecting %ld", func_ss, allocated, id); return false; } @@ -204,11 +204,11 @@ static boolean alloc_gte_test(heap h) u64 allocated = id_heap_alloc_gte(idh, 1, id); if (allocated != id) { if (allocated == INVALID_PHYSICAL) { - msg_err("allocation failed for id %ld\n", id); + msg_err("%s: allocation failed for id %ld", func_ss, id); return false; } else { - msg_err("allocation returned %ld, expecting %ld\n", allocated, + msg_err("%s error: allocation returned %ld, expecting %ld", func_ss, allocated, id); return false; } @@ -221,13 +221,13 @@ static boolean alloc_gte_test(heap h) u64 allocated = id_heap_alloc_gte(idh, 1, 0); if (allocated == INVALID_PHYSICAL) { if (id != GTE_TEST_MAX) { - msg_err("allocation failed for id %ld\n", id); + msg_err("%s: allocation failed for id %ld", func_ss, id); return false; } break; } else if (id == GTE_TEST_MAX) { - msg_err("allocation should have failed for id %ld\n", GTE_TEST_MAX); + msg_err("%s error: allocation should have failed for id %ld", func_ss, GTE_TEST_MAX); return false; } } @@ -235,19 +235,19 @@ static boolean alloc_gte_test(heap h) deallocate_u64((heap)idh, id, 1); } if (heap_allocated((heap)idh) > 0) { - msg_err("heap allocated is %d, should be zero\n", heap_allocated((heap)idh)); + msg_err("%s error: non-zero heap allocated (%d)", func_ss, heap_allocated((heap)idh)); return false; } destroy_heap((heap)idh); idh = create_id_heap(h, h, 1, 2, 1, false); if (idh == INVALID_ADDRESS) { - msg_err("cannot create heap\n"); + msg_err("%s error: cannot create heap", func_ss); return false; } u64 id = id_heap_alloc_gte(idh, 1, 1); if (id != 1) { - msg_err("allocation returned %ld, expecting 1\n", id); + msg_err("%s error: allocation returned %ld, expecting 1", func_ss, id); return false; } deallocate_u64((heap)idh, id, 1); @@ -267,25 +267,25 @@ static boolean alloc_subrange_test(heap h) id_heap id = create_id_heap(h, h, SUBRANGE_TEST_MIN, SUBRANGE_TEST_LENGTH, PAGESIZE, false); if (id == INVALID_ADDRESS) { - msg_err("cannot create heap\n"); + msg_err("%s error: cannot create heap", func_ss); return false; } /* these should fail */ if (id_heap_alloc_subrange(id, PAGESIZE, 0, SUBRANGE_TEST_MIN) != INVALID_PHYSICAL) { - msg_err("should have failed for lower non-intersecting subrange\n"); + msg_err("%s error: should have failed for lower non-intersecting subrange", func_ss); return false; } if (id_heap_alloc_subrange(id, 1, SUBRANGE_TEST_END - PAGESIZE + 1, SUBRANGE_TEST_END + PAGESIZE) != INVALID_PHYSICAL) { - msg_err("should have failed for upper non-intersecting subrange\n"); + msg_err("%s error: should have failed for upper non-intersecting subrange", func_ss); return false; } if (id_heap_alloc_subrange(id, PAGESIZE, SUBRANGE_TEST_MIN + PAGESIZE + 1, SUBRANGE_TEST_MIN + 2 * PAGESIZE + 1) != INVALID_PHYSICAL) { - msg_err("should have failed for unaligned subrange\n"); + msg_err("%s error: should have failed for unaligned subrange", func_ss); return false; } @@ -299,14 +299,14 @@ static boolean alloc_subrange_test(heap h) u64 res; for (int i = 0; i < allocs; i++) { if ((res = id_heap_alloc_subrange(id, alloc_size, start, end)) != expect) { - msg_err("subrange alloc expected 0x%lx, got 0x%lx\n", expect, res); + msg_err("%s error: subrange alloc expected 0x%lx, got 0x%lx", func_ss, expect, res); return false; } pages_remaining--; expect += PAGESIZE; } if ((res = id_heap_alloc_subrange(id, alloc_size, start, end)) != INVALID_PHYSICAL) { - msg_err("superfluous subrange alloc should have failed, got 0x%lx\n", res); + msg_err("%s error: superfluous subrange alloc did not fail, got 0x%lx", func_ss, res); return false; } @@ -319,20 +319,22 @@ static boolean alloc_subrange_test(heap h) for (int i = 0; i < allocs; i++) { if ((res = id_heap_alloc_subrange(id, alloc_size, start, end)) != expect) { - msg_err("multi-page subrange alloc expected 0x%lx, got 0x%lx\n", expect, res); + msg_err("%s error: multi-page subrange alloc expected 0x%lx, got 0x%lx", + func_ss, expect, res); return false; } pages_remaining -= 3; expect += 4 * PAGESIZE; } if ((res = id_heap_alloc_subrange(id, alloc_size, start, end)) != INVALID_PHYSICAL) { - msg_err("multi-page superfluous subrange alloc should have failed, got 0x%lx\n", res); + msg_err("%s error: multi-page superfluous subrange alloc should have failed, got 0x%lx", + func_ss, res); return false; } /* we should have a remainder page for each 3-page alloc plus the skipped page above */ if (pages_remaining != allocs + 1) { - msg_err("test bug, pages_remaining %d, should be %d\n", pages_remaining, allocs + 1); + msg_err("%s error: pages_remaining %d, should be %d", func_ss, pages_remaining, allocs + 1); return false; } @@ -345,14 +347,15 @@ static boolean alloc_subrange_test(heap h) expect = SUBRANGE_TEST_MIN; /* should wrap around and pick up skipped page from above */ if ((res = allocate_u64((heap)id, PAGESIZE)) != expect) { - msg_err("remainder alloc returned 0x%lx, should be 0x%lx (iter %d)\n", res, expect, i); + msg_err("%s error: remainder alloc returned 0x%lx, should be 0x%lx (iter %d)", + func_ss, res, expect, i); return false; } } /* we should have exhausted the number space */ if ((res = allocate_u64((heap)id, PAGESIZE)) != INVALID_PHYSICAL) { - msg_err("should have exhausted number space, got 0x%lx\n", res); + msg_err("%s error: should have exhausted number space, got 0x%lx", func_ss, res); return false; } @@ -366,13 +369,13 @@ static boolean alloc_align_test(heap h) const u64 heap_size = 0x20000; id_heap id = create_id_heap(h, h, unaligned_base, heap_size, 1, false); if (id == INVALID_ADDRESS) { - msg_err("cannot create heap\n"); + msg_err("%s failed to create heap", func_ss); return false; } for (int size = 1; pad(unaligned_base, size) + size <= unaligned_base + heap_size; size <<= 1) { u64 i = allocate_u64((heap)id, size); if (i != pad(unaligned_base, size)) { - msg_err("unexpected allocation 0x%lx for size 0x%x\n", i, size); + msg_err("%s error: unexpected allocation 0x%lx for size 0x%x", func_ss, i, size); return false; } deallocate_u64((heap)id, i, size); @@ -409,6 +412,6 @@ int main(int argc, char **argv) msg_debug("test passed\n"); exit(EXIT_SUCCESS); fail: - msg_err("test failed\n"); + msg_err("Id heap test failed"); exit(EXIT_FAILURE); } diff --git a/test/unit/network_test.c b/test/unit/network_test.c index d7ac15cb1..bdd0f2f63 100644 --- a/test/unit/network_test.c +++ b/test/unit/network_test.c @@ -102,7 +102,7 @@ closure_function(8, 0, void, startconn, closure_func_basic(status_handler, void, connection_error, status s) { - rprintf("connection error! %v\n", s); + msg_err("connection error %v", s); exit(1); } diff --git a/test/unit/objcache_test.c b/test/unit/objcache_test.c index de35fc658..cc754284f 100644 --- a/test/unit/objcache_test.c +++ b/test/unit/objcache_test.c @@ -15,7 +15,7 @@ static inline boolean validate(heap h) { if (!objcache_validate(h)) { - msg_err("objcache_validate failed\n"); + msg_err("objcache_validate failed"); return false; } @@ -26,7 +26,7 @@ static inline boolean validate_obj(heap h, void * obj) { heap o = objcache_from_object(u64_from_pointer(obj), TEST_PAGESIZE); if (o != h) { - msg_err("objcache_from_object returned %p, doesn't match heap %p\n", o, h); + msg_err("objcache_from_object returned %p, doesn't match heap %p", o, h); return false; } return true; @@ -35,7 +35,7 @@ static inline boolean validate_obj(heap h, void * obj) static boolean alloc_vec(heap h, int n, int s, vector v) { if (!validate(h)) { - msg_err("tb: failed first heap validation\n"); + msg_err("%s: failed first heap validation", func_ss); return false; } for (int i=0; i < n; i++) { @@ -43,14 +43,14 @@ static boolean alloc_vec(heap h, int n, int s, vector v) if (p == INVALID_ADDRESS) return false; if (!validate_obj(h, p)) { - msg_err("tb: failed object validation\n"); + msg_err("%s: failed object validation", func_ss); return false; } vector_set(v, i, p); } if (!validate(h)) { - msg_err("tb: failed second heap validation\n"); + msg_err("%s: failed second heap validation", func_ss); return false; } @@ -87,14 +87,14 @@ boolean objcache_test(heap meta, heap parent, int objsize) msg_debug("objs %p, heap %p\n", objs, h); if (h == INVALID_ADDRESS) { - msg_err("tb: failed to allocate objcache heap\n"); + msg_err("%s: failed to allocate objcache heap", func_ss); deallocate_vector(objs); return false; } /* allocate a page's worth */ if (!alloc_vec(h, opp, objsize, objs)) { - msg_err("tb: failed to allocate object\n"); + msg_err("%s: failed to allocate object", func_ss); return false; } @@ -104,7 +104,7 @@ boolean objcache_test(heap meta, heap parent, int objsize) /* re-allocate a page's worth + 1 to trigger parent allocation */ if (!alloc_vec(h, opp + 1, objsize, objs)) { - msg_err("tb: failed to allocate object\n"); + msg_err("%s: failed to allocate object", func_ss); return false; } @@ -113,7 +113,7 @@ boolean objcache_test(heap meta, heap parent, int objsize) return false; if (heap_allocated(h) > 0) { - msg_err("allocated (%d) should be 0; fail\n", heap_allocated(h)); + msg_err("%s: allocated (%d) should be 0; fail", func_ss, heap_allocated(h)); return false; } destroy_heap(h); @@ -135,7 +135,7 @@ boolean preallocated_objcache_test(heap meta, heap parent, int objsize, boolean msg_debug("objs %p, heap %p\n", objs, h); if (h == INVALID_ADDRESS) { - msg_err("tb: failed to allocate objcache heap\n"); + msg_err("%s: failed to allocate objcache heap", func_ss); deallocate_vector(objs); return false; } @@ -155,7 +155,7 @@ boolean preallocated_objcache_test(heap meta, heap parent, int objsize, boolean /* re-allocate a page + 1 worth to trigger parent allocation */ if (!(alloc_vec(h, opp + 1, objsize, objs) != prealloc_only)) { - msg_err("tb: unexpectedly %s to allocate object\n", + msg_err("%s: unexpectedly %s to allocate object", func_ss, prealloc_only ? ss("able") : ss("failed")); return false; } @@ -166,7 +166,7 @@ boolean preallocated_objcache_test(heap meta, heap parent, int objsize, boolean return false; if (heap_allocated(h) > 0) { - msg_err("allocated (%d) should be 0; fail\n", heap_allocated(h)); + msg_err("%s: allocated (%d) should be 0; fail", func_ss, heap_allocated(h)); return false; } } diff --git a/test/unit/parser_test.c b/test/unit/parser_test.c index 9138c9437..c614643b0 100644 --- a/test/unit/parser_test.c +++ b/test/unit/parser_test.c @@ -8,14 +8,14 @@ /* s must be a string literal */ #define test_strings_equal(b, s) do { \ if (buffer_strcmp(b, s) != 0) { \ - msg_err("\"%b\" != \"%s\" -- failed at %s:%d\n", b, ss(s), file_ss, __LINE__); \ + msg_err("%s: \"%b\" != \"%s\" -- failed at %s:%d", func_ss, b, ss(s), file_ss, __LINE__); \ return false; \ } \ } while (0) #define test_no_errors() do { \ if (errors_count) { \ - msg_err("%d parse error(s), last: %b\n", errors_count, last_error); \ + msg_err("%s: %d parse error(s), last: %b", func_ss, errors_count, last_error); \ } \ test_assert(errors_count == 0); \ } while (0) @@ -864,7 +864,8 @@ int main(int argc, char **argv) } if (failure) { - msg_err("Test failed\n"); exit(EXIT_FAILURE); + msg_err("Parser test failed"); + exit(EXIT_FAILURE); } exit(EXIT_SUCCESS); } diff --git a/test/unit/pqueue_test.c b/test/unit/pqueue_test.c index 5ba49304e..cf7f545da 100644 --- a/test/unit/pqueue_test.c +++ b/test/unit/pqueue_test.c @@ -387,6 +387,6 @@ int main(int argc, char **argv) msg_debug("pqueue test passed\n"); exit(EXIT_SUCCESS); fail: - msg_err("pqueue test failed\n"); + msg_err("Pqueue test failed"); exit(EXIT_FAILURE); } diff --git a/test/unit/random_test.c b/test/unit/random_test.c index 137b67ded..89c033d7d 100644 --- a/test/unit/random_test.c +++ b/test/unit/random_test.c @@ -120,14 +120,14 @@ static int ent_get_stats(char *path, struct ent_stat_entry *stats) f = popen(&ent_cmd[0], "r"); if (!f) { - msg_err("Can't start ent, perhaps it is not installed?\n"); + msg_err("%s failed to start ent", func_ss); return -1; } matched = fread(&ent_buf[0], 1024, 1, f); if (ferror(f)) { pclose(f); - msg_err("Can't read ent statistics, matched=%d.\n", matched); + msg_err("%s failed to read ent statistics, matched=%d", func_ss, matched); return -1; } @@ -153,7 +153,7 @@ static int ent_get_stats(char *path, struct ent_stat_entry *stats) else if (linenum == 1) sscanf(s, "%lf", &stats[nfield - (ENT_NSTATS + 1)].val); else if (linenum < 0) { - msg_err("unable to parse\n"); + msg_err("%s error: unable to parse", func_ss); pclose(f); return -1; } @@ -187,7 +187,7 @@ static int ent_test(struct ent_stat_entry *stats) double val; if (!ent_stat_get(stats, "Entropy", &val)) { - msg_err("Cannot get bytestream entropy.\n"); + msg_err("%s failed to get bytestream entropy", func_ss); goto out_fail; } @@ -199,12 +199,12 @@ static int ent_test(struct ent_stat_entry *stats) } if (comp > COMPRESS_PASS_THRESH) { - msg_err("Insufficient entropy.\n"); + msg_err("%s error: insufficient entropy", func_ss); goto out_fail; } if (!ent_stat_get(stats, "Mean", &val)) { - msg_err("Cannot get sequence mean\n"); + msg_err("%s failed to get sequence mean", func_ss); goto out_fail; } @@ -216,7 +216,7 @@ static int ent_test(struct ent_stat_entry *stats) } if (fabs(mean_dev) > MEAN_DEV_THRESH) { - msg_err("Mean deviation too large.\n"); + msg_err("%s error: mean deviation too large", func_ss); goto out_fail; } @@ -262,7 +262,7 @@ int main(int argc, char **argv) rm_bytestream("/tmp/test"); if (result != EXIT_SUCCESS) - msg_err("Test failed.\n"); + msg_err("Random test failed"); exit(result); } diff --git a/test/unit/range_test.c b/test/unit/range_test.c index 659a1bd78..e0a9bdc50 100644 --- a/test/unit/range_test.c +++ b/test/unit/range_test.c @@ -29,12 +29,12 @@ closure_func_basic(rmnode_handler, boolean, basic_test_validate, range r = range_from_rmnode(node); int val = ((test_node)node)->val; if (count >= nresults) { - msg_err("range lookup extraneous result: %R, %p\n", r, val); + msg_err("%s error: range lookup extraneous result: %R, %p", func_ss, r, val); exit(EXIT_FAILURE); } if (!range_equal(r, rm_results[count].r) || val != rm_results[count].val) { - msg_err("count %d, range lookup result mismatch, expected %R, %d but got %R, %d\n", - count, rm_results[count].r, rm_results[count].val, r, val); + msg_err("%s error: count %d, range lookup result mismatch, expected %R, %d, got %R, %d", + func_ss, count, rm_results[count].r, rm_results[count].val, r, val); exit(EXIT_FAILURE); } count++; @@ -65,7 +65,7 @@ boolean basic_test(heap h) char * msg = ""; rangemap rm = allocate_rangemap(h); if (rm == INVALID_ADDRESS) { - msg_err("failed to allocate rangemap\n"); + msg_err("%s failed to allocate rangemap", func_ss); return false; } @@ -182,7 +182,8 @@ static void rangemap_verify_ranges(rangemap rm, int expected_count, u64 expected u64 previous_end = 0; rangemap_foreach(rm, n) { if ((count++ > 0) && (n->r.start <= previous_end)) { - msg_err("unexpected range %R, previous end %ld)\n", n->r, previous_end); + msg_err("%s error: unexpected range %R, previous end %ld)", + func_ss, n->r, previous_end); exit(EXIT_FAILURE); } length += range_span(n->r); @@ -205,7 +206,7 @@ static boolean rangemap_merge_test(heap h) { rangemap rm = allocate_rangemap(h); if (rm == INVALID_ADDRESS) { - msg_err("failed to allocate rangemap\n"); + msg_err("%s failed to allocate rangemap", func_ss); return false; } rangemap_verify_ranges(rm, 0, 0); @@ -257,6 +258,6 @@ int main(int argc, char **argv) msg_debug("range test passed\n"); exit(EXIT_SUCCESS); fail: - msg_err("range test failed\n"); + msg_err("Range test failed"); exit(EXIT_FAILURE); } diff --git a/test/unit/rbtree_test.c b/test/unit/rbtree_test.c index 4b6182810..ebb4a66f8 100644 --- a/test/unit/rbtree_test.c +++ b/test/unit/rbtree_test.c @@ -48,7 +48,7 @@ closure_function(3, 1, boolean, test_max_lte_node, rbnode ml = rbtree_lookup_max_lte(bound(t), &k.node); rbnode x = *bound(last) ? *bound(last) : INVALID_ADDRESS; if (ml != x) { - rprintf("%s: lookup max lte returned %p, should be last (%p)\n", + msg_err("%s error: lookup max lte returned %p, should be last (%p)", func_ss, ml, x); *bound(result) = false; return false; @@ -68,8 +68,8 @@ static boolean test_max_lte(rbtree t) k.key = ((testnode)last)->key + 1; rbnode ml = rbtree_lookup_max_lte(t, &k.node); if (ml != last) { - rprintf("%s: lookup max lte for key %d after last node " - "returned %p instead of last (%p)\n", func_ss, + msg_err("%s error: lookup max lte for key %d after last node " + "returned %p instead of last (%p)", func_ss, k.key, ml, last); return false; } @@ -115,7 +115,7 @@ static boolean test_remove(heap h, rbtree t, int key, boolean expect) rbtest_debug("deleting by key %d\n", key); boolean result = rbtree_remove_by_key(t, &tk.node); if (result != expect) { - msg_err("delete failed (result %d)\n", result); + msg_err("%s: delete failed (result %d)", func_ss, result); return false; } #ifdef RBTEST_DEBUG @@ -123,13 +123,13 @@ static boolean test_remove(heap h, rbtree t, int key, boolean expect) #endif status s = rbtree_validate(t); if (!is_ok(s)) { - msg_err("validate failed: %v\n", s); + msg_err("%s: validate failed: %v", func_ss, s); return false; } rbtest_debug("lookup:\n"); rbnode r = rbtree_lookup(t, &tk.node); if (r != INVALID_ADDRESS) { - msg_err("lookup for key %d should have failed (returned %p, key %d)\n", + msg_err("%s error: lookup for key %d should have failed (returned %p, key %d)", func_ss, key, r, ((testnode)r)->key); return false; } @@ -222,12 +222,12 @@ closure_function(3, 1, boolean, validate_preorder_vec, int *p = bound(vec) + i; rbtest_debug("index %d, expect %d, tn->key %d\n", i, *p, tn->key); if (*p == -1) { - rprintf("%s: result vec exceeded at index %d\n", func_ss, i); + msg_err("%s: result vec exceeded at index %d", func_ss, i); *bound(match) = false; return false; } if (*p != tn->key) { - rprintf("%s: key %d at index %d, expected %d\n", func_ss, tn->key, i, *p); + msg_err("%s: key %d at index %d, expected %d", func_ss, tn->key, i, *p); *bound(match) = false; return false; } @@ -250,7 +250,7 @@ static boolean do_transformation_test(rbtree t, heap h, int i, boolean insert) rbtest_debug(" %d: %d\n", j, k); boolean result = insert ? test_insert(h, t, k, true) : test_remove(h, t, k, true); if (!result) { - rprintf("%s: %s failed for test %d, idx %d, key %d\n", func_ss, op, i, j, k); + msg_err("%s: %s failed for test %d, idx %d, key %d", func_ss, op, i, j, k); return false; /* XXX leak */ } } @@ -265,13 +265,13 @@ static boolean do_transformation_test(rbtree t, heap h, int i, boolean insert) stack_closure(validate_preorder_vec, rvec, &index, &match)); if (match) { if (rvec[index] != -1) { - rprintf("%s: in-order traversal for %s test %d gave incomplete results, end index %d\n", + msg_err("%s: in-order traversal for %s test %d gave incomplete results, end index %d", func_ss, op, i, index); return false; } } if (!match) { - rprintf("%s: validate for %s test %d failed\n", func_ss, op, i); + msg_err("%s: validate for %s test %d failed", func_ss, op, i); return false; } rbtest_debug("passed\n\n"); @@ -303,7 +303,7 @@ static boolean basic_test(heap h) rbtree t = allocate_rbtree(h, closure_func(h, rb_key_compare, test_compare), closure_func(h, rbnode_handler, dump_node)); if (t == INVALID_ADDRESS) { - msg_err("allocate_rbtree() failed\n"); + msg_err("%s: allocate_rbtree() failed", func_ss); return false; } @@ -322,7 +322,7 @@ static boolean basic_test(heap h) rbtest_debug("attempt to insert duplicates\n"); for (int i = 0; i < 200; i++) { if (test_insert(h, t, i, false)) { - msg_err("insert should have failed\n"); + msg_err("%s error: insert should have failed", func_ss); return false; } } @@ -336,7 +336,7 @@ static boolean basic_test(heap h) destruct_rbtree(t, stack_closure(dealloc_testnode, h)); status s = rbtree_validate(t); if (!is_ok(s)) { - rprintf("validate failed after tree destruct: %v\n", s); + msg_err("%s: validate failed after tree destruct: %v", func_ss, s); return false; } boolean result = true; @@ -354,7 +354,7 @@ static boolean random_test(heap h) closure_func(h, rbnode_handler, dump_node)); assert(rbtree_get_count(t) == 0); if (t == INVALID_ADDRESS) { - msg_err("allocate_rbtree() failed\n"); + msg_err("%s: allocate_rbtree() failed", func_ss); return false; } @@ -369,11 +369,11 @@ static boolean random_test(heap h) tn.key = vec[i]; rbnode rn = rbtree_lookup(t, &tn.node); if (rn == INVALID_ADDRESS) { - msg_err("both insert and lookup failed\n"); + msg_err("%s: both insert and lookup failed", func_ss); return false; } if (((testnode)rn)->key != vec[i]) { - msg_err("found node key mismatch\n"); + msg_err("%s error: node key mismatch", func_ss); return false; } goto redo; @@ -389,7 +389,7 @@ static boolean random_test(heap h) destruct_rbtree(t, stack_closure(dealloc_testnode, h)); status s = rbtree_validate(t); if (!is_ok(s)) { - rprintf("validate failed after tree destruct: %v\n", s); + msg_err("%s: validate failed after tree destruct: %v", func_ss, s); return false; } boolean result = true; @@ -413,6 +413,6 @@ int main(int argc, char **argv) msg_debug("test passed\n"); exit(EXIT_SUCCESS); fail: - msg_err("test failed\n"); + msg_err("Rbtree test failed"); exit(EXIT_FAILURE); } diff --git a/test/unit/table_test.c b/test/unit/table_test.c index aeae21331..234749232 100644 --- a/test/unit/table_test.c +++ b/test/unit/table_test.c @@ -27,14 +27,14 @@ static boolean basic_table_tests(heap h, u64 (*key_function)(void *x), u64 n_ele table_validate(t, ss("basic_table_tests: alloc")); if (table_elements(t) != 0) { - msg_err("table_elements() not zero on empty table\n"); + msg_err("%s error: table_elements() not zero on empty table", func_ss); return false; } table_foreach(t, n, v) { (void) n; (void) v; - msg_err("table_foreach() on empty table\n"); + msg_err("%s error: table_foreach() on empty table", func_ss); return false; } @@ -52,15 +52,15 @@ static boolean basic_table_tests(heap h, u64 (*key_function)(void *x), u64 n_ele count = 0; table_foreach(t, n, v) { if ((u64)v != (u64)n + 1) { - msg_err("table_foreach() invalid value %d for name %d, " - "should be %d\n", (u64)v, (u64)n, (u64)n + 1); + msg_err("%s error: table_foreach() invalid value %ld for name %ld, should be %ld", + func_ss, (u64)v, (u64)n, (u64)n + 1); return false; } count++; } if (count != n_elem) { - msg_err("table_foreach() invalid iteration count %d\n", count); + msg_err("%s error: table_foreach() invalid iteration count %ld", func_ss, count); return false; } @@ -68,30 +68,30 @@ static boolean basic_table_tests(heap h, u64 (*key_function)(void *x), u64 n_ele u64 v = (u64)table_find(t, (void *)count); if (!v) { - msg_err("element %d not found\n", count); + msg_err("%s error: element %ld not found", func_ss, count); return false; } if (v != count + 1) { - msg_err("element %d invalid value %d, should be %d\n", count, v, + msg_err("%s error: element %ld invalid value %ld, should be %ld", func_ss, count, v, count + 1); return false; } } if (table_find(t, (void *)count)) { - msg_err("found unexpected element %d\n", count); + msg_err("%s error: unexpected element %ld", func_ss, count); return false; } if (table_set_noreplace(t, pointer_from_u64(n_elem / 2), pointer_from_u64(1))) { - msg_err("could replace element %ld\n", n_elem / 2); + msg_err("%s error: could replace element %ld", func_ss, n_elem / 2); return false; } /* Remove one element from the table. */ table_set(t, 0, 0); if (table_find(t, 0)) { - msg_err("found unexpected element 0\n"); + msg_err("%s error: unexpected element 0", func_ss); return false; } @@ -99,21 +99,21 @@ static boolean basic_table_tests(heap h, u64 (*key_function)(void *x), u64 n_ele count = table_elements(t); if (count != n_elem - 1) { - msg_err("invalid table_elements() %d, should be %d\n", count, + msg_err("%s error: invalid table_elements() %ld, should be %ld", func_ss, count, n_elem - 1); return false; } val = u64_from_pointer(table_remove(t, (pointer_from_u64(1)))); if (val != 2) { - msg_err("invalid element %ld removed, should be 2\n", val); + msg_err("%s error: invalid element %ld removed, should be 2", func_ss, val); return false; } table_validate(t, ss("basic_table_tests: after table_remove()")); count = table_elements(t); if (count != n_elem - 2) { - msg_err("invalid table_elements() %ld after table_remove(), should be %ld\n", - count, n_elem - 2); + msg_err("%s error: invalid table_elements() %ld after table_remove(), should be %ld", + func_ss, count, n_elem - 2); return false; } @@ -131,23 +131,25 @@ static boolean basic_table_tests(heap h, u64 (*key_function)(void *x), u64 n_ele count = table_elements(t); if (count != 0) { - msg_err("invalid table_elements() %d, should be 0\n"); + msg_err("%s error: invalid table_elements() %ld, should be 0", func_ss, count); return false; } if (!table_set_noreplace(t, pointer_from_u64(0), pointer_from_u64(n_elem))) { - msg_err("could not set element at 0\n"); + msg_err("%s failed to set element at 0", func_ss); return false; } val = u64_from_pointer(table_find(t, pointer_from_u64(0))); if (val != n_elem) { - msg_err("unexpected element %ld at 0 after table_set_noreplace()\n", val); + msg_err("%s error: unexpected element %ld at 0 after table_set_noreplace()", + func_ss, val); return false; } deallocate_table(t); if (heap_allocated(h) != heap_occupancy) { - msg_err("leak: heap_allocated(h) %ld, originally %ld\n", heap_allocated(h), heap_occupancy); + msg_err("%s leak: heap_allocated(h) %ld, originally %ld", + func_ss, heap_allocated(h), heap_occupancy); return false; } return true; @@ -170,25 +172,25 @@ static boolean one_elem_table_tests(heap h, u64 n_elem) count = 0; table_foreach(t, n, v) { if (n != 0) { - msg_err("table_foreach() invalid name %d\n", (u64)n); + msg_err("%s error: table_foreach() invalid name %ld", func_ss, (u64)n); return false; } if ((u64)v != n_elem) { - msg_err("table_foreach() invalid value %d for name %d, " - "should be %d\n", (u64)v, (u64)n, n_elem); + msg_err("%s error: table_foreach() invalid value %ld for name %ld, should be %ld", + func_ss, (u64)v, (u64)n, n_elem); return false; } count++; } if (count != 1) { - msg_err("table_foreach() invalid iteration count %d\n", count); + msg_err("%s error: table_foreach() invalid iteration count %ld", func_ss, count); return false; } count = table_elements(t); if (count != 1) { - msg_err("invalid table_elements() %d, should be 1\n", count); + msg_err("%s error: invalid table_elements() %ld, should be 1", func_ss, count); return false; } @@ -196,35 +198,36 @@ static boolean one_elem_table_tests(heap h, u64 n_elem) u64 v = (u64)table_find(t, (void *)count); if (!v) { - msg_err("element %d not found\n", count); + msg_err("%s error: element %ld not found", func_ss, count); return false; } if (v != n_elem) { - msg_err("element %d invalid value %d, should be %d\n", count, v, + msg_err("%s error: element %ld invalid value %ld, should be %ld", func_ss, count, v, n_elem); return false; } } if (!table_find(t, (void *)count)) { - msg_err("element %d not found\n", count); + msg_err("%s error: element %ld not found", func_ss, count); return false; } table_clear(t); if (table_find(t, (void *)count)) { - msg_err("element found after table_clear()\n"); + msg_err("%s error: element found after table_clear()", func_ss); return false; } count = table_elements(t); if (count != 0) { - msg_err("invalid table_elements() %d after table_clear()\n", count); + msg_err("%s error: invalid table_elements() %ld after table_clear()", func_ss, count); return false; } deallocate_table(t); if (heap_allocated(h) != heap_occupancy) { - msg_err("leak: heap_allocated(h) %ld, originally %ld\n", heap_allocated(h), heap_occupancy); + msg_err("%s leak: heap_allocated(h) %ld, originally %ld", + func_ss, heap_allocated(h), heap_occupancy); return false; } return true; @@ -248,7 +251,7 @@ static boolean preallocated_table_tests(heap h, u64 (*key_function)(void *x), u6 table_validate(t, ss("preallocated_table_tests: alloc")); if (table_elements(t) != 0) { - msg_err("table_elements() not zero on empty table\n"); + msg_err("%s error: table_elements() not zero on empty table", func_ss); return false; } for (count = 0; count < n_elem; count++) { @@ -258,13 +261,14 @@ static boolean preallocated_table_tests(heap h, u64 (*key_function)(void *x), u6 table_validate(t, ss("preallocated_table_tests: after fill")); if (heap_allocated(h) != heap_occupancy) { - msg_err("unexpected allocation: heap_allocated(h) %llu, originally %llu\n", heap_allocated(h), heap_occupancy); + msg_err("%s error: unexpected allocation: heap_allocated(h) %lu, originally %lu", + func_ss, heap_allocated(h), heap_occupancy); return false; } table_set(t, 0, 0); if (table_find(t, 0)) { - msg_err("found unexpected element 0\n"); + msg_err("%s error: unexpected element 0", func_ss); return false; } table_validate(t, ss("preallocated_table_tests: after remove one")); @@ -277,7 +281,8 @@ static boolean preallocated_table_tests(heap h, u64 (*key_function)(void *x), u6 destroy_heap(pageheap); if (heap_allocated(h) != heap_occupancy_before) { - msg_err("leak: heap_allocated(h) %ld, originally %ld\n", heap_allocated(h), heap_occupancy_before); + msg_err("%s leak: heap_allocated(h) %lu, originally %lu", + func_ss, heap_allocated(h), heap_occupancy_before); return false; } return true; diff --git a/test/unit/tuple_test.c b/test/unit/tuple_test.c index 20abdb475..b34baa6c9 100644 --- a/test/unit/tuple_test.c +++ b/test/unit/tuple_test.c @@ -9,7 +9,7 @@ #define test_assert(expr) do { \ if (expr) ; else { \ - msg_err("%s -- failed at %s:%d\n", ss(#expr), file_ss, __LINE__); \ + msg_err("%s: %s -- failed at %s:%d", func_ss, ss(#expr), file_ss, __LINE__); \ goto fail; \ } \ } while (0) @@ -371,7 +371,7 @@ int main(int argc, char **argv) failure |= encode_decode_lengthy_test(h); if (failure) { - msg_err("Test failed\n"); + msg_err("Tuple test failed"); exit(EXIT_FAILURE); } exit(EXIT_SUCCESS); diff --git a/tools/dump.c b/tools/dump.c index 83c42eabe..e09facf2f 100644 --- a/tools/dump.c +++ b/tools/dump.c @@ -157,7 +157,7 @@ closure_function(3, 2, void, fsc, heap h = bound(h); if (!is_ok(s)) { - rprintf("failed to initialize filesystem: %v\n", s); + msg_err("dump: failed to initialize filesystem: %v", s); exit(EXIT_FAILURE); } diff --git a/tools/mkfs.c b/tools/mkfs.c index b6200e9b0..3e16491e7 100644 --- a/tools/mkfs.c +++ b/tools/mkfs.c @@ -243,7 +243,7 @@ closure_func_basic(parse_finish, void, finish, closure_func_basic(parse_error, void, perr, string s) { - rprintf("manifest parse error %b\n", s); + msg_err("manifest parse error: %b", s); exit(EXIT_FAILURE); } @@ -341,7 +341,7 @@ closure_func_basic(io_status_handler, void, mkfs_write_handler, status s, bytes length) { if (!is_ok(s)) { - rprintf("write failed with %v\n", s); + msg_err("write failed with %v", s); exit(EXIT_FAILURE); } } @@ -584,7 +584,7 @@ closure_func_basic(parse_finish, void, cmdline_tuple_finish, void *v) { if (!is_tuple(v)) { - rprintf("parsed cmdline value is not a tuple: %v\n", v); + msg_err("cmdline value is not a tuple: %v", v); exit(EXIT_FAILURE); } vector_push(cmdline_tuples, v); @@ -593,7 +593,7 @@ closure_func_basic(parse_finish, void, cmdline_tuple_finish, closure_func_basic(parse_error, void, cmdline_tuple_err, string s) { - rprintf("cmdline tuple parse error %b\n", s); + msg_err("cmdline tuple parse error: %b", s); exit(EXIT_FAILURE); } diff --git a/tools/tfs-fuse.c b/tools/tfs-fuse.c index 0893bcc23..188353fd1 100644 --- a/tools/tfs-fuse.c +++ b/tools/tfs-fuse.c @@ -825,7 +825,7 @@ closure_func_basic(filesystem_complete, void, fsc, filesystem fs, status s) { if (!is_ok(s)) { - rprintf("failed to initialize filesystem: %v\n", s); + msg_err("tfs-fuse: failed to initialize filesystem: %v", s); exit(EXIT_FAILURE); }