[flashrom] [PATCH] Add logfile support to flashrom

Idwer Vollering vidwer at gmail.com
Tue May 8 19:48:24 CEST 2012


2012/5/3 Carl-Daniel Hailfinger <c-d.hailfinger.devel.2006 at gmx.net>:
> I have decided to discard most of the logging code and rewrite it to be
> more readable. It even worked in preliminary tests.
> TODO:
> - Should "-o -" be a no-op which just redirects stderr to stdout? Right
> now "-" is treated as regular file name, but most Unix utilities are
> unable to handle a file with that name (try "less -" for amusement).

Is this a part of your long-term plan?

> - Add man page entry
> - Is the log level difference for screen/logfile a good thing, and
> should we default the logfile level to dbg2 instead of dbg?
>
> Add log file support to flashrom.
>
> If you use cli_classic, the log file will always contain messages at
> a level which is one higher than the one specified. That way we get
> all verbose messages in the log even if the user doesn't specify -V.

This handles -VV and -VVV too, correct?

>
> Convert all printf() after start of logging to msg_*().
>
> Allow separate control of log level for screen and logfile in case
> other frontends (e.g. GUI, cli_mfg) want that.
>
> Signed-off-by: Carl-Daniel Hailfinger <c-d.hailfinger.devel.2006 at gmx.net>
>
> Index: flashrom-logfile/flash.h
> ===================================================================
> --- flashrom-logfile/flash.h    (Revision 1528)
> +++ flashrom-logfile/flash.h    (Arbeitskopie)
> @@ -228,7 +228,8 @@
>        write_gran_1byte,
>        write_gran_256bytes,
>  };
> -extern int verbose;
> +extern int verbose_screen;
> +extern int verbose_logfile;
>  extern const char flashrom_version[];
>  extern char *chip_to_probe;
>  void map_flash_registers(struct flashctx *flash);
> @@ -268,13 +269,20 @@
>  #define ERROR_FLASHROM_LIMIT -201
>
>  /* cli_output.c */
> +#ifndef STANDALONE
> +int open_logfile(const char * const filename);
> +int close_logfile(void);
> +void start_logging(void);
> +#endif
>  /* Let gcc and clang check for correct printf-style format strings. */
> -int print(int type, const char *fmt, ...) __attribute__((format(printf, 2, 3)));
> -#define MSG_ERROR      0
> -#define MSG_INFO       1
> -#define MSG_DEBUG      2
> -#define MSG_DEBUG2     3

http://review.coreboot.org/gitweb?p=coreboot.git;a=blob;f=src/include/console/loglevel.h;h=290cd891eb994b34a5060a469bde9589e1419f90;hb=HEAD

#define MSG_NOTICE 2
#define MSG_DEBUG 3

> -#define MSG_BARF       4

#define MSG_SPEW 4

> +enum msglevel {
> +       MSG_ERROR       = 0,
> +       MSG_INFO        = 1,
> +       MSG_DEBUG       = 2,
> +       MSG_DEBUG2      = 3,
> +       MSG_BARF        = 4,
> +};
> +int print(enum msglevel level, const char *fmt, ...) __attribute__((format(printf, 2, 3)));
>  #define msg_gerr(...)  print(MSG_ERROR, __VA_ARGS__)   /* general errors */
>  #define msg_perr(...)  print(MSG_ERROR, __VA_ARGS__)   /* programmer errors */
>  #define msg_cerr(...)  print(MSG_ERROR, __VA_ARGS__)   /* chip errors */
> Index: flashrom-logfile/cli_output.c
> ===================================================================
> --- flashrom-logfile/cli_output.c       (Revision 1528)
> +++ flashrom-logfile/cli_output.c       (Arbeitskopie)
> @@ -2,6 +2,7 @@
>  * This file is part of the flashrom project.
>  *
>  * Copyright (C) 2009 Sean Nelson <audiohacked at gmail.com>
> + * Copyright (C) 2011 Carl-Daniel Hailfinger
>  *
>  * This program is free software; you can redistribute it and/or modify
>  * it under the terms of the GNU General Public License as published by
> @@ -20,36 +21,80 @@
>
>  #include <stdio.h>
>  #include <stdarg.h>
> +#include <string.h>
> +#include <errno.h>
>  #include "flash.h"
>
> -int print(int type, const char *fmt, ...)
> +static FILE *logfile = NULL;
> +
> +#ifndef STANDALONE
> +int close_logfile(void)
>  {
> +       if (logfile && fclose(logfile)) {

No sync() / fsync() ?
From http://linux.die.net/man/3/fclose "Note that fclose() only
flushes the user space buffers provided by the C library. To ensure
that the data is physically stored on disk the kernel buffers must be
flushed too, for example, with sync(2) or fsync(2)."

> +               /* fclose returned an error. Stop writing to be safe. */
> +               logfile = NULL;
> +               msg_perr("Closing the log file returned error %s\n",
> +                        strerror(errno));
> +               return 1;
> +       }
> +       logfile = NULL;
> +       return 0;
> +}
> +
> +int open_logfile(const char * const filename)
> +{
> +       if (!filename) {
> +               msg_gerr("No filename specified.\n");
> +               return 1;
> +       }
> +       if ((logfile = fopen(filename, "w")) == NULL) {
> +               perror(filename);
> +               return 1;
> +       }
> +       return 0;
> +}
> +
> +void start_logging(void)
> +{
> +       enum msglevel oldverbose_screen = verbose_screen;
> +       enum msglevel oldverbose_logfile = verbose_logfile;
> +
> +       /* Shut up the console. */
> +       verbose_screen = MSG_ERROR;
> +       verbose_logfile = MSG_DEBUG;
> +       print_version();
> +       verbose_screen = oldverbose_screen;
> +       verbose_logfile = oldverbose_logfile;
> +}
> +#endif /* STANDALONE */
> +
> +/* Please note that level is the verbosity, not the importance of the message.
> + */
> +int print(enum msglevel level, const char *fmt, ...)
> +{
>        va_list ap;
> -       int ret;
> -       FILE *output_type;
> +       int ret = 0;
> +       FILE *output_level = stdout;
>
> -       switch (type) {
> -       case MSG_ERROR:
> -               output_type = stderr;
> -               break;
> -       case MSG_BARF:
> -               if (verbose < 3)
> -                       return 0;
> -       case MSG_DEBUG2:
> -               if (verbose < 2)
> -                       return 0;
> -       case MSG_DEBUG:
> -               if (verbose < 1)
> -                       return 0;
> -       case MSG_INFO:
> -       default:
> -               output_type = stdout;
> -               break;
> +       if (level == MSG_ERROR)
> +               output_level = stderr;
> +
> +       if (level <= verbose_screen) {
> +               va_start(ap, fmt);
> +               ret = vfprintf(output_level, fmt, ap);
> +               va_end(ap);
> +               /* msg_*spew usually happens inside chip accessors in possibly
> +                * time-critical operations. Don't slow them down by flushing.
> +                */
> +               if (level != MSG_BARF)
> +                       fflush(output_level);
>        }
> -
> -       va_start(ap, fmt);
> -       ret = vfprintf(output_type, fmt, ap);
> -       va_end(ap);
> -       fflush(output_type);
> +       if ((level <= verbose_logfile) && logfile) {
> +               va_start(ap, fmt);
> +               ret = vfprintf(logfile, fmt, ap);
> +               va_end(ap);
> +               if (level != MSG_BARF)
> +                       fflush(logfile);
> +       }
>        return ret;
>  }
> Index: flashrom-logfile/cli_classic.c
> ===================================================================
> --- flashrom-logfile/cli_classic.c      (Revision 1528)
> +++ flashrom-logfile/cli_classic.c      (Arbeitskopie)
> @@ -106,7 +106,7 @@
>                 "-z|"
>  #endif
>                 "-E|-r <file>|-w <file>|-v <file>]\n"
> -              "       [-c <chipname>] [-l <file>]\n"
> +              "       [-c <chipname>] [-l <file>] [-o <file>]\n"
>               "       [-i <image>] [-p <programmername>[:<parameters>]]\n\n");
>
>        printf("Please note that the command line interface for flashrom has "
> @@ -135,6 +135,7 @@
>                 "<file>\n"
>               "   -i | --image <name>               only flash image <name> "
>                 "from flash layout\n"
> +              "   -o | --output <name>              log to file <name>\n"
>               "   -L | --list-supported             print supported devices\n"
>  #if CONFIG_PRINT_WIKI == 1
>               "   -z | --list-supported-wiki        print supported devices "
> @@ -177,7 +178,7 @@
>        enum programmer prog = PROGRAMMER_INVALID;
>        int ret = 0;
>
> -       static const char optstring[] = "r:Rw:v:nVEfc:l:i:p:Lzh";
> +       static const char optstring[] = "r:Rw:v:nVEfc:l:i:p:Lzho:";
>        static const struct option long_options[] = {
>                {"read",                1, NULL, 'r'},
>                {"write",               1, NULL, 'w'},
> @@ -194,11 +195,13 @@
>                {"programmer",          1, NULL, 'p'},
>                {"help",                0, NULL, 'h'},
>                {"version",             0, NULL, 'R'},
> +               {"output",              1, NULL, 'o'},
>                {NULL,                  0, NULL, 0},
>        };
>
>        char *filename = NULL;
>        char *layoutfile = NULL;
> +       char *log_name = NULL;
>        char *tempstr = NULL;
>        char *pparam = NULL;
>
> @@ -260,7 +263,8 @@
>                        chip_to_probe = strdup(optarg);
>                        break;
>                case 'V':
> -                       verbose++;
> +                       verbose_screen++;
> +                       verbose_logfile++;
>                        break;
>                case 'E':
>                        if (++operation_specified > 1) {
> @@ -366,6 +370,19 @@
>                        cli_classic_usage(argv[0]);
>                        exit(0);
>                        break;
> +               case 'o':
> +#ifdef STANDALONE
> +                       fprintf(stderr, "Log file not supported in standalone "
> +                               "mode. Aborting.\n");
> +                       cli_classic_abort_usage();
> +#else /* STANDALONE */
> +                       log_name = strdup(optarg);
> +                       if (log_name[0] == '\0') {
> +                               fprintf(stderr, "No log filename specified.\n");
> +                               cli_classic_abort_usage();
> +                       }
> +#endif /* STANDALONE */
> +                       break;
>                default:
>                        cli_classic_abort_usage();
>                        break;
> @@ -377,20 +394,40 @@
>                cli_classic_abort_usage();
>        }
>
> -       /* FIXME: Print the actions flashrom will take. */
> -
> -       if (list_supported) {
> -               print_supported();
> -               exit(0);
> +       if ((read_it | write_it | verify_it) && !filename) {
> +               fprintf(stderr, "Error: No filename specified.\n");

"No log filename specified.\n" ?

> +               cli_classic_abort_usage();
>        }
> +       if (filename && (filename[0] == '\0')) {
> +               fprintf(stderr, "Error: No filename specified.\n");

dito

> +               cli_classic_abort_usage();
> +       }
> +       if (filename && (filename[0] == '-'))
> +               fprintf(stderr, "Warning: Supplied file name starts with -\n");
>
> +#ifndef STANDALONE
> +       if (log_name && (log_name[0] == '-'))
> +               fprintf(stderr, "Warning: Supplied file name starts with -\n");
> +       if (log_name && open_logfile(log_name))

WARNING or Warning? Maybe add a line that says that this will change
in the future?

> +               return 1;
> +#endif /* !STANDALONE */
> +
>  #if CONFIG_PRINT_WIKI == 1
>        if (list_supported_wiki) {
>                print_supported_wiki();
> -               exit(0);
> +               ret = 0;
> +               goto out;
>        }
>  #endif
>
> +       if (list_supported) {
> +               print_supported();
> +               ret = 0;
> +               goto out;
> +       }
> +
> +       // FIXME: cli_classic_abort_usage() does exit(1) and we rely on the OS
> +       // to flush log file buffers. Is that behaviour guaranteed?
>        if (layoutfile && read_romlayout(layoutfile))
>                cli_classic_abort_usage();
>        if (process_include_args())
> @@ -415,11 +452,22 @@
>        if (prog == PROGRAMMER_INVALID)
>                prog = default_programmer;
>
> +#ifndef STANDALONE
> +       start_logging();
> +#endif /* STANDALONE */
> +
> +       msg_gdbg("Command line:");
> +       for (i = 0; i < argc; i++) {
> +               msg_gdbg(" %s", argv[i]);
> +       }
> +       msg_gdbg("\n");
> +
> +
>        /* FIXME: Delay calibration should happen in programmer code. */
>        myusec_calibrate_delay();
>
>        if (programmer_init(prog, pparam)) {
> -               fprintf(stderr, "Error: Programmer initialization failed.\n");
> +               msg_perr("Error: Programmer initialization failed.\n");
>                ret = 1;
>                goto out_shutdown;
>        }
> @@ -442,25 +490,25 @@
>        }
>
>        if (chipcount > 1) {
> -               printf("Multiple flash chips were detected: \"%s\"",
> -                       flashes[0].name);
> +               msg_cinfo("Multiple flash chips were detected: \"%s\"",
> +                         flashes[0].name);
>                for (i = 1; i < chipcount; i++)
> -                       printf(", \"%s\"", flashes[i].name);
> -               printf("\nPlease specify which chip to use with the "
> -                      "-c <chipname> option.\n");
> +                       msg_cinfo(", \"%s\"", flashes[i].name);
> +               msg_cinfo("\nPlease specify which chip to use with the -c "
> +                         "<chipname> option.\n");
>                ret = 1;
>                goto out_shutdown;
>        } else if (!chipcount) {
> -               printf("No EEPROM/flash device found.\n");
> +               msg_cinfo("No EEPROM/flash device found.\n");
>                if (!force || !chip_to_probe) {
> -                       printf("Note: flashrom can never write if the flash "
> -                              "chip isn't found automatically.\n");
> +                       msg_cinfo("Note: flashrom can never write if the flash "
> +                                 "chip isn't found automatically.\n");
>                }
>                if (force && read_it && chip_to_probe) {
>                        struct registered_programmer *pgm;
>                        int compatible_programmers = 0;
> -                       printf("Force read (-f -r -c) requested, pretending "
> -                              "the chip is there:\n");
> +                       msg_cinfo("Force read (-f -r -c) requested, pretending "
> +                                 "the chip is there:\n");
>                        /* This loop just counts compatible controllers. */
>                        for (j = 0; j < registered_programmer_count; j++) {
>                                pgm = &registered_programmers[j];
> @@ -468,9 +516,9 @@
>                                        compatible_programmers++;
>                        }
>                        if (compatible_programmers > 1)
> -                               printf("More than one compatible controller "
> -                                      "found for the requested flash chip, "
> -                                      "using the first one.\n");
> +                               msg_cinfo("More than one compatible controller "
> +                                         "found for the requested flash chip, "
> +                                         "using the first one.\n");
>                        for (j = 0; j < registered_programmer_count; j++) {
>                                pgm = &registered_programmers[j];
>                                startchip = probe_flash(pgm, 0, &flashes[0], 1);
> @@ -478,14 +526,15 @@
>                                        break;
>                        }
>                        if (startchip == -1) {
> -                               printf("Probing for flash chip '%s' failed.\n",
> -                                      chip_to_probe);
> +                               msg_cinfo("Probing for flash chip '%s' failed."
> +                                         "\n", chip_to_probe);
>                                ret = 1;
>                                goto out_shutdown;
>                        }
> -                       printf("Please note that forced reads most likely "
> -                              "contain garbage.\n");
> -                       return read_flash_to_file(&flashes[0], filename);
> +                       msg_cinfo("Please note that forced reads most likely "
> +                                 "contain garbage.\n");
> +                       ret = read_flash_to_file(&flashes[0], filename);
> +                       goto out_shutdown;
>                }
>                ret = 1;
>                goto out_shutdown;
> @@ -505,23 +554,17 @@
>        size = fill_flash->total_size * 1024;
>        if (check_max_decode(fill_flash->pgm->buses_supported & fill_flash->bustype, size) &&
>            (!force)) {
> -               fprintf(stderr, "Chip is too big for this programmer "
> -                       "(-V gives details). Use --force to override.\n");
> +               msg_cerr("Chip is too big for this programmer "
> +                        "(-V gives details). Use --force to override.\n");
>                ret = 1;
>                goto out_shutdown;
>        }
>
>        if (!(read_it | write_it | verify_it | erase_it)) {
> -               printf("No operations were specified.\n");
> +               msg_ginfo("No operations were specified.\n");
>                goto out_shutdown;
>        }
>
> -       if (!filename && !erase_it) {
> -               printf("Error: No filename specified.\n");
> -               ret = 1;
> -               goto out_shutdown;
> -       }
> -
>        /* Always verify write operations unless -n is used. */
>        if (write_it && !dont_verify_it)
>                verify_it = 1;
> @@ -531,9 +574,13 @@
>         * Give the chip time to settle.
>         */
>        programmer_delay(100000);
> -       return doit(fill_flash, force, filename, read_it, write_it, erase_it, verify_it);
> +       ret |= doit(fill_flash, force, filename, read_it, write_it, erase_it, verify_it);
>
>  out_shutdown:
>        programmer_shutdown();
> +out:
> +#ifndef STANDALONE
> +       ret |= close_logfile();
> +#endif
>        return ret;
>  }
> Index: flashrom-logfile/flashrom.c
> ===================================================================
> --- flashrom-logfile/flashrom.c (Revision 1528)
> +++ flashrom-logfile/flashrom.c (Arbeitskopie)
> @@ -40,7 +40,8 @@
>
>  const char flashrom_version[] = FLASHROM_VERSION;
>  char *chip_to_probe = NULL;
> -int verbose = 0;
> +int verbose_screen = MSG_INFO;
> +int verbose_logfile = MSG_DEBUG;
>
>  static enum programmer programmer = PROGRAMMER_INVALID;
>
> @@ -1457,27 +1458,27 @@
>                        if (firstline)
>                                firstline = 0;
>                        else
> -                               printf("\n");
> +                               msg_ginfo("\n");
>                        for (i = 0; i < startcol; i++)
> -                               printf(" ");
> +                               msg_ginfo(" ");
>                        remaining = cols - startcol;
>                } else {
> -                       printf(" ");
> +                       msg_ginfo(" ");
>                        remaining--;
>                }
>                if (paren && (p == 0)) {
> -                       printf("(");
> +                       msg_ginfo("(");
>                        remaining--;
>                }
> -               printf("%s", pname);
> +               msg_ginfo("%s", pname);
>                remaining -= pnamelen;
>                if (p < PROGRAMMER_INVALID - 1) {
> -                       printf(",");
> +                       msg_ginfo(",");
>                        remaining--;
>                } else {
>                        if (paren)
> -                               printf(")");
> -                       printf("\n");
> +                               msg_ginfo(")");
> +                       msg_ginfo("\n");
>                }
>        }
>  }
> @@ -1493,35 +1494,35 @@
>  #else
>        msg_ginfo(" on unknown machine");
>  #endif
> -       msg_ginfo(", built with");
> +       msg_gdbg(", built with");
>  #if NEED_PCI == 1
>  #ifdef PCILIB_VERSION
> -       msg_ginfo(" libpci %s,", PCILIB_VERSION);
> +       msg_gdbg(" libpci %s,", PCILIB_VERSION);
>  #else
> -       msg_ginfo(" unknown PCI library,");
> +       msg_gdbg(" unknown PCI library,");
>  #endif
>  #endif
>  #ifdef __clang__
> -       msg_ginfo(" LLVM Clang");
> +       msg_gdbg(" LLVM Clang");
>  #ifdef __clang_version__
> -       msg_ginfo(" %s,", __clang_version__);
> +       msg_gdbg(" %s,", __clang_version__);
>  #else
> -       msg_ginfo(" unknown version (before r102686),");
> +       msg_gdbg(" unknown version (before r102686),");
>  #endif
>  #elif defined(__GNUC__)
> -       msg_ginfo(" GCC");
> +       msg_gdbg(" GCC");
>  #ifdef __VERSION__
> -       msg_ginfo(" %s,", __VERSION__);
> +       msg_gdbg(" %s,", __VERSION__);
>  #else
> -       msg_ginfo(" unknown version,");
> +       msg_gdbg(" unknown version,");
>  #endif
>  #else
> -       msg_ginfo(" unknown compiler,");
> +       msg_gdbg(" unknown compiler,");
>  #endif
>  #if defined (__FLASHROM_LITTLE_ENDIAN__)
> -       msg_ginfo(" little endian");
> +       msg_gdbg(" little endian");
>  #else
> -       msg_ginfo(" big endian");
> +       msg_gdbg(" big endian");
>  #endif
>        msg_ginfo("\n");
>  }
> @@ -1534,7 +1535,7 @@
>
>  void print_banner(void)
>  {
> -       msg_ginfo("flashrom is free software, get the source code at "
> +       msg_ginfo("flashrom is free software. Get the source code at "
>                  "http://www.flashrom.org\n");
>        msg_ginfo("\n");
>  }
> @@ -1840,6 +1841,5 @@
>        free(oldcontents);
>        free(newcontents);
>  out_nofree:
> -       programmer_shutdown();
>        return ret;
>  }
>
>
> --
> http://www.hailfinger.org/
>
>
> _______________________________________________
> flashrom mailing list
> flashrom at flashrom.org
> http://www.flashrom.org/mailman/listinfo/flashrom


More information about the flashrom mailing list