Re: [flashrom] [PATCH] Add logfile support to flashrom

[Idwer Vollering]

2012/5/3 Carl-Daniel Hailfinger :
> 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
> 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/consol...

#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
> 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%5Cn");
>        msg_ginfo("\n");
>  }
> @@ -1840,6 +1841,5 @@
>        free(oldcontents);
>        free(newcontents);
>  out_nofree:
> programmer_shutdown();
>
> return ret;
>  }
>
> flashrom mailing list
> [e-mail]
> http://www.flashrom.org/mailman/listinfo/flashrom