WIP: Improve logging #46
Conversation
| #define INFOF(fmt, ...) fprintf(stderr, "INFO | " fmt "\n", __VA_ARGS__) | ||
| #define ERROR(msg) fprintf(stderr, "ERROR| " msg "\n") | ||
| #define ERRORF(fmt, ...) fprintf(stderr, "ERROR| " fmt "\n", __VA_ARGS__) | ||
| #define ERRORN(name) ERRORF(name ": %s", strerror(errno)) |
There was a problem hiding this comment.
This should move to log.h so we can split the to code to multiple files and use consistent logging.
There was a problem hiding this comment.
I guess we should use https://developer.apple.com/documentation/os/os_log ?
There was a problem hiding this comment.
See man 3 os_log for the usage
There was a problem hiding this comment.
Sure, I'll try this.
But I think we should keep the logging macros so it is easy to change the logging backend later.
| default: | ||
| fprintf(stderr, "%s(): vmnet_return_t %d\n", func, v); | ||
| break; | ||
| return "(unknown status)"; |
There was a problem hiding this comment.
I did not check the enums values, maybe we can replace this with a simpler table lookup.
- 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
Signed-off-by: Nir Soffer <nsoffer@redhat.com>
| @@ -330,39 +326,40 @@ static int socket_bindlisten(const char *socket_path, | |||
| memset(&addr, 0, sizeof(addr)); | |||
| unlink(socket_path); /* avoid EADDRINUSE */ | |||
| if ((fd = socket(PF_LOCAL, SOCK_STREAM, 0)) < 0) { | |||
| perror("socket"); | |||
| ERRORN("socket"); | |||
There was a problem hiding this comment.
ERRORN was a quick way to convert perror calls to standard logs, but I think in most case it will be better to use ERRORF and add more context about the error. For example here adding the socket path will help to debug issues.
| goto err; | ||
| } | ||
| /* fchown can't be used (EINVAL) */ | ||
| if (chown(socket_path, -1, grp->gr_gid) < 0) { | ||
| perror("chown"); | ||
| ERRORN("chown"); |
There was a problem hiding this comment.
Here including the argument so the call in the error can help debugging later.
| goto err; | ||
| } | ||
| if (chmod(socket_path, 0770) < 0) { | ||
| perror("chmod"); | ||
| ERRORN("chmod"); |
There was a problem hiding this comment.
Including the permissions in the error message can help debugging.
| @@ -406,15 +403,15 @@ int main(int argc, char *argv[]) { | |||
| pid_fd = open(cliopt->pidfile, | |||
| O_WRONLY | O_CREAT | O_EXLOCK | O_TRUNC | O_NONBLOCK, 0644); | |||
| if (pid_fd == -1) { | |||
| perror("pidfile_open"); | |||
| ERRORN("pidfile_open"); | |||
There was a problem hiding this comment.
Including the path that failed will help debugging.
| @@ -423,23 +420,23 @@ int main(int argc, char *argv[]) { | |||
| state.sem = dispatch_semaphore_create(1); | |||
| iface = start(&state, cliopt); | |||
| if (iface == NULL) { | |||
| perror("start"); | |||
| ERRORN("start"); | |||
There was a problem hiding this comment.
This looks wrong - start does not set errno and already logged failures.
| goto done; | ||
| } | ||
|
|
||
| if (pid_fd != -1) { | ||
| char pid[20]; | ||
| snprintf(pid, sizeof(pid), "%u", getpid()); | ||
| if (write(pid_fd, pid, strlen(pid)) != (ssize_t)strlen(pid)) { | ||
| perror("pidfile_write"); | ||
| ERRORN("pidfile_write"); |
There was a problem hiding this comment.
Should be ERRNO("write"), but using ERRORF with more context will be more helpful.
| goto done; | ||
| } | ||
| uint32_t header = ntohl(header_be); | ||
| assert(header <= buf_len); | ||
| ssize_t received = read(accept_fd, buf, header); | ||
| if (received < 0) { | ||
| perror("read"); | ||
| ERRORN("read"); |
There was a problem hiding this comment.
Should be ERRORN("read[body]") for consistency with ERRORN("read[header]").
This is a quick draft to experiment with better logging. Posting to get an early review on this changes.
This does not fix all the issues mentioned in #43 but prepare the infrastructure. With these changes adding timestamps for all logs is a trivial change.
Example log with this change