From 1d26c897ee68a11c14ccb8cf2242b46fd96ca153 Mon Sep 17 00:00:00 2001 From: Andrea Luzzardi Date: Sun, 8 Oct 2006 20:25:30 +0000 Subject: [PATCH] Improved logging --- pam_usb/src/conf.c | 24 ++++++++++++++++++++---- pam_usb/src/device.c | 16 ++++++++++++---- pam_usb/src/hal.c | 3 +-- pam_usb/src/log.c | 8 ++++++-- pam_usb/src/log.h | 5 +++-- pam_usb/src/otp.c | 26 +++++++++++++++----------- pam_usb/src/test.c | 26 +++++++++----------------- 7 files changed, 66 insertions(+), 42 deletions(-) diff --git a/pam_usb/src/conf.c b/pam_usb/src/conf.c index 32ce147..c0e7528 100644 --- a/pam_usb/src/conf.c +++ b/pam_usb/src/conf.c @@ -103,7 +103,6 @@ static int pusb_conf_device_get_property(t_pusb_options *opts, static int pusb_conf_parse_device(t_pusb_options *opts, xmlDoc *doc) { - log_debug("Parsing settings...\n"); if (!pusb_conf_device_get_property(opts, doc, "vendor", opts->device.vendor, sizeof(opts->device.vendor))) return (0); @@ -134,6 +133,20 @@ int pusb_conf_init(t_pusb_options *opts) return (1); } +static void pusb_conf_dump(t_pusb_options *opts) +{ + log_debug("Configuration dump:\n"); + log_debug("enable:\t\t\t%d\n", opts->enable); + log_debug("probe_timeout:\t\t%d\n", opts->probe_timeout); + log_debug("try_otp:\t\t\t%d\n", opts->try_otp); + log_debug("enforce_otp:\t\t%d\n", opts->enforce_otp); + log_debug("debug:\t\t\t%d\n", opts->debug); + log_debug("hostname:\t\t%s\n", opts->hostname); + log_debug("system_otp_directory:\t%s\n", opts->system_otp_directory); + log_debug("device_otp_directory:\t%s\n", opts->device_otp_directory); +} + + int pusb_conf_parse(const char *file, t_pusb_options *opts, const char *user, const char *service) { @@ -142,15 +155,17 @@ int pusb_conf_parse(const char *file, t_pusb_options *opts, char device_xpath[sizeof(CONF_USER_XPATH) + CONF_USER_MAXLEN + \ sizeof("device")]; + log_debug("Parsing settings...\n", + user, service); if (strlen(user) > CONF_USER_MAXLEN) { - log_error("Username \"%s\" is too long (max: %d)\n", user, + log_error("Username \"%s\" is too long (max: %d).\n", user, CONF_USER_MAXLEN); return (0); } if (!(doc = xmlReadFile(file, NULL, 0))) { - log_error("Unable to parse \"%s\"\n", file); + log_error("Unable to parse \"%s\".\n", file); return (0); } snprintf(device_xpath, sizeof(device_xpath), CONF_USER_XPATH, user, @@ -161,7 +176,7 @@ int pusb_conf_parse(const char *file, t_pusb_options *opts, sizeof(opts->device.name)); if (!retval || !pusb_conf_parse_device(opts, doc)) { - log_error("No device found for user \"%s\"\n", user); + log_error("No device configured for user \"%s\".\n", user); xmlFreeDoc(doc); xmlCleanupParser(); return (0); @@ -174,5 +189,6 @@ int pusb_conf_parse(const char *file, t_pusb_options *opts, } xmlFreeDoc(doc); xmlCleanupParser(); + pusb_conf_dump(opts); return (1); } diff --git a/pam_usb/src/device.c b/pam_usb/src/device.c index 85f67ee..1dd03bd 100644 --- a/pam_usb/src/device.c +++ b/pam_usb/src/device.c @@ -32,7 +32,7 @@ static LibHalDrive *pusb_device_get_storage(t_pusb_options *opts, LibHalContext int maxloop = 0; LibHalDrive *drive = NULL; - log_debug("Waiting for device to come up...\n"); + log_info("Waiting for storage device probing...\n"); while (!(phy_udi = pusb_hal_find_item(ctx, "info.parent", udi, "info.bus", "usb", @@ -67,6 +67,7 @@ int pusb_device_check(t_pusb_options *opts) char *udi = NULL; int retval = 0; + log_debug("Connecting to HAL...\n"); if (!(dbus = pusb_hal_dbus_connect())) return (0); if (!(ctx = pusb_hal_init(dbus))) @@ -74,7 +75,8 @@ int pusb_device_check(t_pusb_options *opts) pusb_hal_dbus_disconnect(dbus); return (0); } - + log_debug("Searching for \"%s\" in the hardware database...\n", + opts->device.name); udi = pusb_hal_find_item(ctx, "usb_device.serial", opts->device.serial, "usb_device.vendor", opts->device.vendor, @@ -82,15 +84,21 @@ int pusb_device_check(t_pusb_options *opts) NULL); if (!udi) { + log_error("Device \"%s\" is not connected.\n", + opts->device.name); pusb_hal_dbus_disconnect(dbus); libhal_ctx_free(ctx); return (0); } - log_debug("Valid device %s\n", udi); + log_info("Device \"%s\" is connected (good).\n", opts->device.name); if (!opts->try_otp && !opts->enforce_otp) - retval = 1; + { + log_debug("One time pad is disabled, no more verifications to do.\n"); + retval = 1; + } else { + log_info("Performing one time pad verification...\n"); if (!(drive = pusb_device_get_storage(opts, ctx, udi))) retval = !opts->enforce_otp; else diff --git a/pam_usb/src/hal.c b/pam_usb/src/hal.c index aa50a96..7c18252 100644 --- a/pam_usb/src/hal.c +++ b/pam_usb/src/hal.c @@ -87,8 +87,7 @@ char *pusb_hal_get_property(LibHalContext *ctx, name, &error); if (!data) { - log_error("Cannot retrieve device property %s for udi %s: %s\n", - name, udi, error.message); + log_debug("%s\n", error.message); dbus_error_free(&error); return (NULL); } diff --git a/pam_usb/src/log.c b/pam_usb/src/log.c index a95a969..561045b 100644 --- a/pam_usb/src/log.c +++ b/pam_usb/src/log.c @@ -19,10 +19,12 @@ #include #include "log.h" -void log_debug(const char *fmt, ...) +void __log_debug(const char *file, int line, const char *fmt, ...) { va_list ap; + return ; + fprintf(stderr, "\033[01;34m*\033[00m [%s:%03d] ", file, line); va_start(ap, fmt); vfprintf(stderr, fmt, ap); va_end(ap); @@ -32,15 +34,17 @@ void log_error(const char *fmt, ...) { va_list ap; + fprintf(stderr, "\033[01;31m*\033[00m "); va_start(ap, fmt); vfprintf(stderr, fmt, ap); va_end(ap); } -void log_verbose(const char *fmt, ...) +void log_info(const char *fmt, ...) { va_list ap; + fprintf(stderr, "\033[01;32m*\033[00m "); va_start(ap, fmt); vfprintf(stderr, fmt, ap); va_end(ap); diff --git a/pam_usb/src/log.h b/pam_usb/src/log.h index 2718209..ad6b6b9 100644 --- a/pam_usb/src/log.h +++ b/pam_usb/src/log.h @@ -18,8 +18,9 @@ #ifndef PUSB_LOG_H_ # define PUSB_LOG_H_ -void log_debug(const char *fmt, ...); +void __log_debug(const char *file, int line, const char *fmt, ...); +#define log_debug(s, ...) __log_debug(__FILE__, __LINE__, s, ##__VA_ARGS__) void log_error(const char *fmt, ...); -void log_verbose(const char *fmt, ...); +void log_info(const char *fmt, ...); #endif /* !PUSB_LOG_H_ */ diff --git a/pam_usb/src/otp.c b/pam_usb/src/otp.c index 14d9b5c..3b3f073 100644 --- a/pam_usb/src/otp.c +++ b/pam_usb/src/otp.c @@ -38,7 +38,7 @@ static LibHalVolume *pusb_otp_find_volume(t_pusb_options *opts, LibHalContext *c if (!n_volumes) { libhal_free_string_array(volumes); - log_error("No volumes found\n"); + log_debug("No volumes found\n"); return (NULL); } for (i = 0; i < n_volumes; ++i) @@ -90,7 +90,7 @@ static FILE *pusb_otp_open_device(t_pusb_options *opts, LibHalVolume *volume, free(path); if (!f) { - log_error("Cannot open device file: %s\n", strerror(errno)); + log_debug("Cannot open device file: %s\n", strerror(errno)); return (NULL); } return (f); @@ -116,7 +116,7 @@ static FILE *pusb_otp_open_system(t_pusb_options *opts, const char *mode) free(path); if (!f) { - log_error("Cannot open system file: %s\n", strerror(errno)); + log_debug("Cannot open system file: %s\n", strerror(errno)); return (NULL); } return (f); @@ -129,27 +129,30 @@ static void pusb_otp_update(t_pusb_options *opts, LibHalVolume *volume) int magic[1024]; int i; - log_debug("Updating one time pad... "); if (!(f_device = pusb_otp_open_device(opts, volume, "w+"))) { - log_error("Unable to update pads\n"); + log_error("Unable to update pads.\n"); return ; } if (!(f_system = pusb_otp_open_system(opts, "w+"))) { - log_error("Unable to update pads\n"); + log_error("Unable to update pads.\n"); fclose(f_device); return ; } + log_debug("Generating %d bytes unique pad...\n", sizeof(magic)); srand(getpid() * time(NULL)); for (i = 0; i < (sizeof(magic) / sizeof(int)); ++i) magic[i] = rand(); + log_debug("Writing pad to the device...\n"); fwrite(magic, sizeof(int), sizeof(magic) / sizeof(int), f_system); + log_debug("Writing pad to the system...\n"); fwrite(magic, sizeof(int), sizeof(magic) / sizeof(int), f_device); + log_debug("Synchronizing filesystems...\n"); fclose(f_system); fclose(f_device); sync(); - log_debug("done.\n"); + log_debug("One time pads updated.\n"); } static int pusb_otp_compare(t_pusb_options *opts, LibHalVolume *volume) @@ -167,7 +170,9 @@ static int pusb_otp_compare(t_pusb_options *opts, LibHalVolume *volume) fclose(f_system); return (0); } + log_debug("Loading device pad...\n"); fread(magic_device, sizeof(int), sizeof(magic_device) / sizeof(int), f_device); + log_debug("Loading system pad...\n"); fread(magic_system, sizeof(int), sizeof(magic_system) / sizeof(int), f_system); retval = memcmp(magic_system, magic_device, sizeof(magic_system)); fclose(f_system); @@ -186,7 +191,7 @@ int pusb_otp_check(t_pusb_options *opts, LibHalContext *ctx, maxtries = ((opts->probe_timeout * 1000000) / 250000); for (i = 0; i < maxtries; ++i) { - log_debug("Waiting volumes...\n"); + log_debug("Waiting for volumes to come up...\n"); volume = pusb_otp_find_volume(opts, ctx, drive); if (volume) break; @@ -194,15 +199,14 @@ int pusb_otp_check(t_pusb_options *opts, LibHalContext *ctx, } if (!volume) return (!opts->enforce_otp); - log_debug("Checking one time pads... "); retval = pusb_otp_compare(opts, volume); if (retval) { - log_debug("okay.\n"); + log_info("Verification match, updating one time pads...\n"); pusb_otp_update(opts, volume); } else - log_debug("mismatch !\n"); + log_error("Pad checking failed !\n"); libhal_volume_free(volume); return (retval); } diff --git a/pam_usb/src/test.c b/pam_usb/src/test.c index eb6094b..56a1018 100644 --- a/pam_usb/src/test.c +++ b/pam_usb/src/test.c @@ -20,38 +20,30 @@ #include "log.h" #include "device.h" -static void pusb_dump_conf(t_pusb_options *opts) -{ - printf("\nConfiguration dump:\n"); - printf("enable:\t\t\t%d\n", opts->enable); - printf("probe_timeout:\t\t%d\n", opts->probe_timeout); - printf("try_otp:\t\t%d\n", opts->try_otp); - printf("enforce_otp:\t\t%d\n", opts->enforce_otp); - printf("debug:\t\t\t%d\n", opts->debug); - printf("hostname:\t\t%s\n", opts->hostname); - printf("system_otp_directory:\t%s\n", opts->system_otp_directory); - printf("device_otp_directory:\t%s\n", opts->device_otp_directory); -} - int main(int argc, char **argv) { t_pusb_options opts; + int retval; if (argc < 3) { printf("Usage: %s \n", argv[0]); return (1); } + log_info("Authentication request for user \"%s\" (%s)\n", + argv[1], argv[2]); pusb_conf_init(&opts); if (!pusb_conf_parse("conf.xml", &opts, argv[1], argv[2])) return (0); - pusb_dump_conf(&opts); if (!opts.enable) { - printf("not enabled, exiting\n"); + log_debug("Not enabled, exiting...\n"); return (0); } - printf("\n"); - printf ("Access %s.\n", pusb_device_check(&opts) ? "granted" : "denied"); + retval = pusb_device_check(&opts); + if (retval) + log_info("Access granted.\n"); + else + log_error("Access denied.\n"); return (0); }