Improved logging

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);
 }

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

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);
     }

pam_usb/src/log.c

@@ -19,10 +19,12 @@
 #include <stdarg.h>
 #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);

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_ */

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);
 }

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 <username> <service>\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);
 }