Hi Marcel,
On 25.10.2011 13:52, Marcel Holtmann wrote:
>> When using syslog() directly we are in danger to deadlock
>> when syslog() is already been called by normal code
>> and the signal kicks in. With using a socket to "/dev/log"
>> we are safe even in the signal handler to log messages.
>> ---
>> src/log.c | 153
>> +++++++++++++++++++++++++++++++++++++++++++++++++++++++++----
>> 1 files changed, 143 insertions(+), 10 deletions(-)
>
> so we wanna just use /dev/log from all of our logging calls. Is this to
> unify things a bit further or is this fixing a real bug as well.
As it turns out, it is both. I started with the attempt fix the deadlock
I see sometimes.
> I was
> thinking of keep using syslog() and only open /dev/log from the signal
> handler.
I would like to use the same code path for the normal logging and for
the signal handler logging. This increases the likelihood if there are
problems with the socket approach we will see it earlier with using it
for the all day logging. Having two separate code paths sounds sub
optimal to me. Also it is not clear if the ordering of the logs would
stay consistent.
BTW, systemd does it exactly like this. So it is not that unusual to do
so :)
>
>> diff --git a/src/log.c b/src/log.c
>> index 04e61f3..63f1df3 100644
>> --- a/src/log.c
>> +++ b/src/log.c
>> @@ -32,12 +32,92 @@
>> #include <syslog.h>
>> #include <execinfo.h>
>> #include <dlfcn.h>
>> +#include <sys/socket.h>
>> +#include <sys/un.h>
>> +#include <errno.h>
>>
>> #include "connman.h"
>>
>> static const char *program_exec;
>> static const char *program_path;
>>
>> +static int log_option;
>
> Maybe we can a bit smarter in just always have to check the log_option.
Okay.
>> +static int syslog_fd;
>> +
>> +static char *program_str;
>> +static char *pid_str;
>> +static const char * const level_str[] = { "<0>", "<1>", "<2>", "<3>",
>> + "<4>", "<5>", "<6>", "<7>" };
>
> There is a double const here ;)
On purpose, checkpatch complained, that I miss a const. Since you don't
like it I drop it :)
>> +
>> +#define IOVEC_SET_STRING(i, s) \
>> + do { \
>> + struct iovec *_i = &(i); \
>> + char *_s = (char *)(s); \
>> + _i->iov_base = _s; \
>> + _i->iov_len = strlen(_s); \
>> + } while (0);
>> +
>> +static int write_to_syslog(unsigned int level, const char *buffer)
>> +{
>> + struct iovec iovec[4];
>> + struct msghdr msghdr;
>> +
>> + if (level > LOG_DEBUG)
>> + level = LOG_DEBUG;
>> +
>> + memset(iovec, 0, sizeof(iovec));
>> + IOVEC_SET_STRING(iovec[0], level_str[level]);
>> + IOVEC_SET_STRING(iovec[1], program_str);
>> + IOVEC_SET_STRING(iovec[2], pid_str);
>> + IOVEC_SET_STRING(iovec[3], buffer);
>> +
>> + memset(&msghdr, 0, sizeof(msghdr));
>> + msghdr.msg_iov = iovec;
>> + msghdr.msg_iovlen = 4;
>> +
>> + if (writev(syslog_fd, iovec, 4) < 0)
>> + return -errno;
>> +
>> + return 0;
>> +}
>> +
>> +static int write_to_console(const char *buffer)
>> +{
>> + struct iovec iovec[4];
>> + struct msghdr msghdr;
>> +
>> + memset(iovec, 0, sizeof(iovec));
>> + IOVEC_SET_STRING(iovec[0], program_str);
>> + IOVEC_SET_STRING(iovec[1], pid_str);
>> + IOVEC_SET_STRING(iovec[2], buffer);
>> + IOVEC_SET_STRING(iovec[3], "\n");
>> +
>> + memset(&msghdr, 0, sizeof(msghdr));
>> + msghdr.msg_iov = iovec;
>> + msghdr.msg_iovlen = 4;
>> +
>> + if (writev(STDERR_FILENO, iovec, 4) < 0)
>> + return -errno;
>> +
>> + return 0;
>> +}
>
> To optimize this, we might be able to create only one iovec and just
> call writev with an offset to it. I don't see a need to allocate an
> iovec twice.
Good point. Will improve that part.
>
>> +
>> +static void log_dispatch(unsigned int level, const char *format, va_list ap)
>> +{
>> + char name[16], pid[16];
>> + char *buffer;
>> + int len;
>
> So who is using name, pid and len (and more important why the compiler
> did not complain loudly).
As it turns out I have compiled with --disable-optimization. Enable the
optimization the compiler warns loud and clear.
>> +
>> + len = vasprintf(&buffer, format, ap);
>> +
>> + write_to_syslog(level, buffer);
>> +
>> + if ((log_option & LOG_PERROR) == LOG_PERROR)
>> + write_to_console(buffer);
>> +
>> + free(buffer);
>> +}
>> +
>> /**
>> * connman_info:
>> * @format: format string
>> @@ -51,7 +131,7 @@ void connman_info(const char *format, ...)
>>
>> va_start(ap, format);
>>
>> - vsyslog(LOG_INFO, format, ap);
>> + log_dispatch(LOG_INFO, format, ap);
>>
>> va_end(ap);
>> }
>> @@ -69,7 +149,7 @@ void connman_warn(const char *format, ...)
>>
>> va_start(ap, format);
>>
>> - vsyslog(LOG_WARNING, format, ap);
>> + log_dispatch(LOG_WARNING, format, ap);
>>
>> va_end(ap);
>> }
>> @@ -87,7 +167,7 @@ void connman_error(const char *format, ...)
>>
>> va_start(ap, format);
>>
>> - vsyslog(LOG_ERR, format, ap);
>> + log_dispatch(LOG_ERR, format, ap);
>>
>> va_end(ap);
>> }
>> @@ -105,7 +185,7 @@ void connman_debug(const char *format, ...)
>>
>> va_start(ap, format);
>>
>> - vsyslog(LOG_DEBUG, format, ap);
>> + log_dispatch(LOG_DEBUG, format, ap);
>>
>> va_end(ap);
>> }
>> @@ -238,6 +318,37 @@ static void signal_setup(sighandler_t handler)
>> sigaction(SIGPIPE, &sa, NULL);
>> }
>>
>> +static int open_syslog(void)
>> +{
>> + union {
>> + struct sockaddr sa;
>> + struct sockaddr_un un;
>> + } sa;
>
> Please don't do that. Just cast it in connect() call.
Okay. Seems I had used a bad example for this :)
>
>> + memset(&sa, 0, sizeof(sa));
>> + sa.un.sun_family = AF_UNIX;
>> + strncpy(sa.un.sun_path, "/dev/log", sizeof(sa.un.sun_path));
>
> You could just use strcpy since we know how long the string is.
Okay.
>> +
>> + syslog_fd = socket(AF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC, 0);
>> + if (syslog_fd < 0)
>> + return -errno;
>> +
>> + if (connect(syslog_fd, &sa.sa, sizeof(sa)) < 0) {
>> + close(syslog_fd);
>> + return -errno;
>> + }
>> +
>> + return 0;
>> +}
>> +
>> +static void close_syslog(void)
>> +{
>> + if (syslog_fd <= 0)
>> + return;
>> +
>> + close(syslog_fd);
>> +}
>> +
>
> For open_syslog and close_syslog we might be better do it directly in
> init and exit functions of src/log.c here. No need trying to emulate
> syslog.
Right. I'll update the patch accordingly.
>
>> extern struct connman_debug_desc __start___debug[];
>> extern struct connman_debug_desc __stop___debug[];
>>
>> @@ -320,6 +431,7 @@ int __connman_log_init(const char *program, const char
>> *debug,
>> {
>> static char path[PATH_MAX];
>> int option = LOG_NDELAY | LOG_PID;
>> + int err;
>>
>> program_exec = program;
>> program_path = getcwd(path, sizeof(path));
>> @@ -329,25 +441,46 @@ int __connman_log_init(const char *program, const char
>> *debug,
>>
>> __connman_log_enable(__start___debug, __stop___debug);
>>
>> + if (asprintf(&program_str, "%s", basename(program_exec)) < 0) {
>> + err = -errno;
>> + goto err;
>> + }
>> +
>> + if (asprintf(&pid_str, "[%lu]: ", (unsigned long)getpid()) < 0) {
>> + err = -errno;
>> + goto err;
>> + }
>> +
>> + err = open_syslog();
>> + if (err < 0)
>> + goto err;
>> +
>> if (detach == FALSE)
>> - option |= LOG_PERROR;
>> + log_option |= LOG_PERROR;
>>
>> signal_setup(signal_handler);
>>
>> - openlog(basename(program), option, LOG_DAEMON);
>> -
>> - syslog(LOG_INFO, "Connection Manager version %s", VERSION);
>> + connman_info("Connection Manager version %s", VERSION);
>>
>> return 0;
>> +
>> +err:
>> + g_free(program_str);
>> + g_free(pid_str);
>> +
>> + return err;
>> }
>>
>> void __connman_log_cleanup(void)
>> {
>> - syslog(LOG_INFO, "Exit");
>> + connman_info("Exit");
>>
>> - closelog();
>> + close_syslog();
>>
>> signal_setup(SIG_DFL);
>>
>> + g_free(program_str);
>> + g_free(pid_str);
>> +
>
> We could just have static strings here. We know what the max will be.
Sure thing.
>> g_strfreev(enabled);
>> }
thanks for the review.
daniel
_______________________________________________
connman mailing list
[email protected]
http://lists.connman.net/listinfo/connman
