Skip to content

Commit 455138f

Browse files
nirsnirs
committed
Improve logging
- Log everything to stderr - this has many advantages: much easier to understand what happened before errors, much easier to understand the daemon state, since stderr is line buffered, so events (e.g. start, stop, connect, disconnect) are logged immediately. Easier to get logs from users. - Replace fprintf and printf with logging macros (ERRORF, ERROR, INFO) - Replace perror with ERRORN, showing the same output an error log. - Use prefix for all logs ("DEBUG|", "INFO |", "ERROR|") to make the meaning of the message clear, and make all log message aligned nicely. - Remove unneeded log for vmnet_return_t when we get VMNET_SUCCESS - Replace print_vmnet_status() with vmnet_strerror() returning readable error name. Callers use ERRORF() to log the vmnet function name, return value and error name. - Log socket length when it is too long - Log the signal name and number - Don't use perror() for logging errors from function snot setting errno - Don't log same error twice (once in a function, second in the caller) Signed-off-by: Nir Soffer <[email protected]>
1 parent 273726b commit 455138f

File tree

1 file changed

+61
-65
lines changed

1 file changed

+61
-65
lines changed

‎main.c

Lines changed: 61 additions & 65 deletions
Original file line numberDiff line numberDiff line change
@@ -26,38 +26,33 @@ static bool debug = false;
2626
fprintf(stderr, "DEBUG| " fmt "\n", __VA_ARGS__); \
2727
} while (0)
2828

29-
static void print_vmnet_status(const char *func, vmnet_return_t v) {
29+
#define INFOF(fmt, ...) fprintf(stderr, "INFO | " fmt "\n", __VA_ARGS__)
30+
#define ERROR(msg) fprintf(stderr, "ERROR| " msg "\n")
31+
#define ERRORF(fmt, ...) fprintf(stderr, "ERROR| " fmt "\n", __VA_ARGS__)
32+
#define ERRORN(name) ERRORF(name ": %s", strerror(errno))
33+
34+
static const char *vmnet_strerror(vmnet_return_t v) {
3035
switch (v) {
3136
case VMNET_SUCCESS:
32-
DEBUGF("%s(): vmnet_return_t VMNET_SUCCESS", func);
33-
break;
37+
return "VMNET_SUCCESS";
3438
case VMNET_FAILURE:
35-
fprintf(stderr, "%s(): vmnet_return_t VMNET_FAILURE\n", func);
36-
break;
39+
return "VMNET_FAILURE";
3740
case VMNET_MEM_FAILURE:
38-
fprintf(stderr, "%s(): vmnet_return_t VMNET_MEM_FAILURE\n", func);
39-
break;
41+
return "VMNET_MEM_FAILURE";
4042
case VMNET_INVALID_ARGUMENT:
41-
fprintf(stderr, "%s(): vmnet_return_t VMNET_INVALID_ARGUMENT\n", func);
42-
break;
43+
return "VMNET_INVALID_ARGUMENT";
4344
case VMNET_SETUP_INCOMPLETE:
44-
fprintf(stderr, "%s(): vmnet_return_t VMNET_SETUP_INCOMPLETE\n", func);
45-
break;
45+
return "VMNET_SETUP_INCOMPLETE";
4646
case VMNET_INVALID_ACCESS:
47-
fprintf(stderr, "%s(): vmnet_return_t VMNET_INVALID_ACCESS\n", func);
48-
break;
47+
return "VMNET_INVALID_ACCESS";
4948
case VMNET_PACKET_TOO_BIG:
50-
fprintf(stderr, "%s(): vmnet_return_t VMNET_PACKET_TOO_BIG\n", func);
51-
break;
49+
return "VMNET_PACKET_TOO_BIG";
5250
case VMNET_BUFFER_EXHAUSTED:
53-
fprintf(stderr, "%s(): vmnet_return_t VMNET_BUFFER_EXHAUSTED\n", func);
54-
break;
51+
return "VMNET_BUFFER_EXHAUSTED";
5552
case VMNET_TOO_MANY_PACKETS:
56-
fprintf(stderr, "%s(): vmnet_return_t VMNET_TOO_MANY_PACKETS\n", func);
57-
break;
53+
return "VMNET_TOO_MANY_PACKETS";
5854
default:
59-
fprintf(stderr, "%s(): vmnet_return_t %d\n", func, v);
60-
break;
55+
return "(unknown status)";
6156
}
6257
}
6358

@@ -67,17 +62,17 @@ static void print_vmnet_start_param(xpc_object_t param) {
6762
xpc_dictionary_apply(param, ^bool(const char *key, xpc_object_t value) {
6863
xpc_type_t t = xpc_get_type(value);
6964
if (t == XPC_TYPE_UINT64)
70-
printf("* %s: %lld\n", key, xpc_uint64_get_value(value));
65+
INFOF("* %s: %lld", key, xpc_uint64_get_value(value));
7166
else if (t == XPC_TYPE_INT64)
72-
printf("* %s: %lld\n", key, xpc_int64_get_value(value));
67+
INFOF("* %s: %lld", key, xpc_int64_get_value(value));
7368
else if (t == XPC_TYPE_STRING)
74-
printf("* %s: %s\n", key, xpc_string_get_string_ptr(value));
69+
INFOF("* %s: %s", key, xpc_string_get_string_ptr(value));
7570
else if (t == XPC_TYPE_UUID) {
7671
char uuid_str[36 + 1];
7772
uuid_unparse(xpc_uuid_get_bytes(value), uuid_str);
78-
printf("* %s: %s\n", key, uuid_str);
73+
INFOF("* %s: %s", key, uuid_str);
7974
} else
80-
printf("* %s: (unknown type)\n", key);
75+
INFOF("* %s: (unknown type)", key);
8176
return true;
8277
});
8378
}
@@ -136,29 +131,28 @@ static void _on_vmnet_packets_available(interface_ref iface, int64_t buf_count,
136131
// TODO: use prealloced pool
137132
struct vmpktdesc *pdv = calloc(buf_count, sizeof(struct vmpktdesc));
138133
if (pdv == NULL) {
139-
perror("calloc(estim_count, sizeof(struct vmpktdesc)");
134+
ERRORN("calloc(estim_count, sizeof(struct vmpktdesc)");
140135
goto done;
141136
}
142137
for (int i = 0; i < buf_count; i++) {
143138
pdv[i].vm_flags = 0;
144139
pdv[i].vm_pkt_size = max_bytes;
145140
pdv[i].vm_pkt_iovcnt = 1, pdv[i].vm_pkt_iov = malloc(sizeof(struct iovec));
146141
if (pdv[i].vm_pkt_iov == NULL) {
147-
perror("malloc(sizeof(struct iovec))");
142+
ERRORN("malloc(sizeof(struct iovec))");
148143
goto done;
149144
}
150145
pdv[i].vm_pkt_iov->iov_base = malloc(max_bytes);
151146
if (pdv[i].vm_pkt_iov->iov_base == NULL) {
152-
perror("malloc(max_bytes)");
147+
ERRORN("malloc(max_bytes)");
153148
goto done;
154149
}
155150
pdv[i].vm_pkt_iov->iov_len = max_bytes;
156151
}
157152
int received_count = buf_count;
158153
vmnet_return_t read_status = vmnet_read(iface, pdv, &received_count);
159-
print_vmnet_status(__FUNCTION__, read_status);
160154
if (read_status != VMNET_SUCCESS) {
161-
perror("vmnet_read");
155+
ERRORF("vmnet_read: [%d] %s", read_status, vmnet_strerror(read_status));
162156
goto done;
163157
}
164158

@@ -200,7 +194,7 @@ static void _on_vmnet_packets_available(interface_ref iface, int64_t buf_count,
200194
"header)",
201195
i, written);
202196
if (written < 0) {
203-
perror("writev");
197+
ERRORN("writev");
204198
goto done;
205199
}
206200
}
@@ -235,11 +229,11 @@ static void on_vmnet_packets_available(interface_ref iface, int64_t estim_count,
235229
}
236230

237231
static interface_ref start(struct state *state, struct cli_options *cliopt) {
238-
printf("Initializing vmnet.framework (mode %d)\n", cliopt->vmnet_mode);
232+
INFOF("Initializing vmnet.framework (mode %d)", cliopt->vmnet_mode);
239233
xpc_object_t dict = xpc_dictionary_create(NULL, NULL, 0);
240234
xpc_dictionary_set_uint64(dict, vmnet_operation_mode_key, cliopt->vmnet_mode);
241235
if (cliopt->vmnet_interface != NULL) {
242-
printf("Using network interface \"%s\"\n", cliopt->vmnet_interface);
236+
INFOF("Using network interface \"%s\"", cliopt->vmnet_interface);
243237
xpc_dictionary_set_string(dict, vmnet_shared_interface_name_key,
244238
cliopt->vmnet_interface);
245239
}
@@ -278,10 +272,10 @@ static interface_ref start(struct state *state, struct cli_options *cliopt) {
278272
dispatch_semaphore_signal(sem);
279273
});
280274
dispatch_semaphore_wait(sem, DISPATCH_TIME_FOREVER);
281-
print_vmnet_status(__FUNCTION__, status);
282275
dispatch_release(q);
283276
xpc_release(dict);
284277
if (status != VMNET_SUCCESS) {
278+
ERRORF("vmnet_start_interface: [%d] %s", status, vmnet_strerror(status));
285279
return NULL;
286280
}
287281

@@ -301,7 +295,7 @@ static interface_ref start(struct state *state, struct cli_options *cliopt) {
301295

302296
static sigjmp_buf jmpbuf;
303297
static void signalhandler(int signal) {
304-
printf("\nReceived signal %d\n", signal);
298+
INFOF("Received signal: %s", strsignal(signal));
305299
siglongjmp(jmpbuf, 1);
306300
}
307301

@@ -318,9 +312,11 @@ static void stop(interface_ref iface) {
318312
dispatch_semaphore_signal(sem);
319313
});
320314
dispatch_semaphore_wait(sem, DISPATCH_TIME_FOREVER);
321-
print_vmnet_status(__FUNCTION__, status);
322315
dispatch_release(q);
323316
// TODO: release event_q ?
317+
if (status != VMNET_SUCCESS) {
318+
ERRORF("vmnet_stop_interface: [%d] %s", status, vmnet_strerror(status));
319+
}
324320
}
325321

326322
static int socket_bindlisten(const char *socket_path,
@@ -330,40 +326,41 @@ static int socket_bindlisten(const char *socket_path,
330326
memset(&addr, 0, sizeof(addr));
331327
unlink(socket_path); /* avoid EADDRINUSE */
332328
if ((fd = socket(PF_LOCAL, SOCK_STREAM, 0)) < 0) {
333-
perror("socket");
329+
ERRORN("socket");
334330
goto err;
335331
}
336332
addr.sun_family = PF_LOCAL;
337-
if (strlen(socket_path) + 1 > sizeof(addr.sun_path)) {
338-
fprintf(stderr, "the socket path is too long\n");
333+
size_t socket_len = strlen(socket_path);
334+
if (socket_len + 1 > sizeof(addr.sun_path)) {
335+
ERRORF("the socket path is too long: %zu", socket_len);
339336
goto err;
340337
}
341338
strncpy(addr.sun_path, socket_path, sizeof(addr.sun_path) - 1);
342339
if (bind(fd, (struct sockaddr *)&addr, sizeof(addr)) < 0) {
343-
perror("bind");
340+
ERRORN("bind");
344341
goto err;
345342
}
346343
if (listen(fd, 0) < 0) {
347-
perror("listen");
344+
ERRORN("listen");
348345
goto err;
349346
}
350347
if (socket_group != NULL) {
351348
errno = 0;
352349
struct group *grp = getgrnam(socket_group); /* Do not free */
353350
if (grp == NULL) {
354351
if (errno != 0)
355-
perror("getgrnam");
352+
ERRORN("getgrnam");
356353
else
357-
fprintf(stderr, "unknown group name \"%s\"\n", socket_group);
354+
ERRORF("unknown group name \"%s\"", socket_group);
358355
goto err;
359356
}
360357
/* fchown can't be used (EINVAL) */
361358
if (chown(socket_path, -1, grp->gr_gid) < 0) {
362-
perror("chown");
359+
ERRORN("chown");
363360
goto err;
364361
}
365362
if (chmod(socket_path, 0770) < 0) {
366-
perror("chmod");
363+
ERRORN("chmod");
367364
goto err;
368365
}
369366
}
@@ -386,12 +383,12 @@ int main(int argc, char *argv[]) {
386383
struct cli_options *cliopt = cli_options_parse(argc, argv);
387384
assert(cliopt != NULL);
388385
if (geteuid() != 0) {
389-
fprintf(stderr, "WARNING: Running without root. This is very unlikely to "
390-
"work. See README.md .\n");
386+
ERROR("WARNING: Running without root. This is very unlikely to "
387+
"work: See README.md");
391388
}
392389
if (geteuid() != getuid()) {
393-
fprintf(stderr, "WARNING: Seems running with SETUID. This is insecure and "
394-
"highly discouraged. See README.md .\n");
390+
ERROR("WARNING: Seems running with SETUID. This is insecure and "
391+
"highly discouraged: See README.md");
395392
}
396393

397394
if (sigsetjmp(jmpbuf, 1) != 0) {
@@ -409,15 +406,15 @@ int main(int argc, char *argv[]) {
409406
pid_fd = open(cliopt->pidfile,
410407
O_WRONLY | O_CREAT | O_EXLOCK | O_TRUNC | O_NONBLOCK, 0644);
411408
if (pid_fd == -1) {
412-
perror("pidfile_open");
409+
ERRORN("pidfile_open");
413410
goto done;
414411
}
415412
}
416413
DEBUGF("Opening socket \"%s\" (for UNIX group \"%s\")", cliopt->socket_path,
417414
cliopt->socket_group);
418415
listen_fd = socket_bindlisten(cliopt->socket_path, cliopt->socket_group);
419416
if (listen_fd < 0) {
420-
perror("socket_bindlisten");
417+
ERRORN("socket_bindlisten");
421418
goto done;
422419
}
423420

@@ -426,23 +423,23 @@ int main(int argc, char *argv[]) {
426423
state.sem = dispatch_semaphore_create(1);
427424
iface = start(&state, cliopt);
428425
if (iface == NULL) {
429-
perror("start");
426+
// Error already logged.
430427
goto done;
431428
}
432429

433430
if (pid_fd != -1) {
434431
char pid[20];
435432
snprintf(pid, sizeof(pid), "%u", getpid());
436433
if (write(pid_fd, pid, strlen(pid)) != (ssize_t)strlen(pid)) {
437-
perror("pidfile_write");
434+
ERRORN("write");
438435
goto done;
439436
}
440437
}
441438

442439
while (1) {
443440
int accept_fd = accept(listen_fd, NULL, NULL);
444441
if (accept_fd < 0) {
445-
perror("accept");
442+
ERRORN("accept");
446443
goto done;
447444
}
448445
struct state *state_p = &state;
@@ -469,12 +466,12 @@ int main(int argc, char *argv[]) {
469466
}
470467

471468
static void on_accept(struct state *state, int accept_fd, interface_ref iface) {
472-
printf("Accepted a connection (fd %d)\n", accept_fd);
469+
INFOF("Accepted a connection (fd %d)", accept_fd);
473470
state_add_socket_fd(state, accept_fd);
474471
size_t buf_len = 64 * 1024;
475472
void *buf = malloc(buf_len);
476473
if (buf == NULL) {
477-
perror("malloc");
474+
ERRORN("malloc");
478475
goto done;
479476
}
480477
for (uint64_t i = 0;; i++) {
@@ -483,24 +480,24 @@ static void on_accept(struct state *state, int accept_fd, interface_ref iface) {
483480
uint32_t header_be = 0;
484481
ssize_t header_received = read(accept_fd, &header_be, 4);
485482
if (header_received < 0) {
486-
perror("read[header]");
483+
ERRORN("read[header]");
487484
goto done;
488485
}
489486
if (header_received == 0) {
490487
// EOF according to man page of read.
491-
fprintf(stderr, "Connection closed by peer (fd %d)\n", accept_fd);
488+
INFOF("Connection closed by peer (fd %d)", accept_fd);
492489
goto done;
493490
}
494491
uint32_t header = ntohl(header_be);
495492
assert(header <= buf_len);
496493
ssize_t received = read(accept_fd, buf, header);
497494
if (received < 0) {
498-
perror("read");
495+
ERRORN("read[body]");
499496
goto done;
500497
}
501498
if (received == 0) {
502499
// EOF according to man page of read.
503-
fprintf(stderr, "Connection closed by peer (fd %d)\n", accept_fd);
500+
INFOF("Connection closed by peer (fd %d)", accept_fd);
504501
goto done;
505502
}
506503
assert(received == header);
@@ -520,9 +517,8 @@ static void on_accept(struct state *state, int accept_fd, interface_ref iface) {
520517
DEBUGF("[Socket-to-VMNET i=%lld] Sending to VMNET: %ld bytes", i,
521518
pd.vm_pkt_size);
522519
vmnet_return_t write_status = vmnet_write(iface, &pd, &written_count);
523-
print_vmnet_status(__FUNCTION__, write_status);
524520
if (write_status != VMNET_SUCCESS) {
525-
perror("vmnet_write");
521+
ERRORF("vmnet_write: [%d] %s", write_status, vmnet_strerror(write_status));
526522
goto done;
527523
}
528524
DEBUGF("[Socket-to-VMNET i=%lld] Sent to VMNET: %ld bytes", i,
@@ -555,13 +551,13 @@ static void on_accept(struct state *state, int accept_fd, interface_ref iface) {
555551
"bytes (including uint32be header)",
556552
i, accept_fd, conn->socket_fd, written);
557553
if (written < 0) {
558-
perror("writev");
554+
ERRORN("writev");
559555
continue;
560556
}
561557
}
562558
}
563559
done:
564-
printf("Closing a connection (fd %d)\n", accept_fd);
560+
INFOF("Closing a connection (fd %d)", accept_fd);
565561
state_remove_socket_fd(state, accept_fd);
566562
close(accept_fd);
567563
if (buf != NULL) {

0 commit comments

Comments
 (0)