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

[Stefan Tauner]

On Tue, 14 Jun 2011 01:39:13 +0200
Carl-Daniel Hailfinger  wrote:
> Am 13.06.2011 00:26 schrieb Bernd Blaauw:
> > Op 11-6-2011 16:21, Uwe Hermann schreef:
> > > There's a small issue with the patch, it double-prints some lines on
> > > stdout
> > > now (in the logfile they appear only once if -o is used):
> > >
> > > $ ./flashrom
> > >    flashrom v0.9.3-r1331 on Linux 2.6.38-2-amd64 (x86_64), built with
> > > libpci 3.1.7, GCC 4.5.2, little endian
> > >    flashrom is free software, get the source code at
> > > http://www.flashrom.org
> >
> > On DOS platform, I see this "little endian" text truncated as
> > ", l"
> > "ittle endian"
> > "flashrom is free".
> >
> > must be the 80x25 default screen mode. Anyway to make this pretty
> > instead of cutting words?
>
> Yes. I decided to kill most of the version message in normal verbosity.
> > > flashrom v0.9.3-r1331 on Linux 2.6.38-2-amd64 (x86_64), built with
> > > libpci 3.1.7, GCC 4.5.2, little endian
> > >    Calibrating delay loop... OK.
> > >    ERROR: Could not get I/O privileges (Operation not permitted).
> > >    You need to be root.
> > >
> > > Also, not all whitespace seems to be the same as in the logfile, e.g.
> > > for
> > >
> > > $ ./flashrom -L -o foo
> >
> > Seems like Uwe's right about the empty spaces, experienced the same
> > with Idwer's "latest" DOS binary.
>
> I "fixed" this by not logging anything if you specify -L (or any other
> action which won't access the chip).

better fix all occurrences of printf in normal code imho
(those in print.c are fixed in my voltage printing patch set as
mentioned on irc).
> > Otherwise you'd simply give the "you need to be root" warning before
> > doing calibration loop, saving a second of waiting time or so?
>
> Dummy wants calibration as well, but I plan to move that into programmer
> init soon.

yay for removing unnecessary delays ;)
> New version.
>
> Add log file support to flashrom.
>
> The log file will always contain all verbose messages even if the user
> doesn't specify -V. If the user specifies -VV, SPEW messages will be
> logged as well.
>
> Please note that the log file will be empty if no programmer is accessed.
> This affects --list-supported --list-supported-wiki --help --version.
>
> Only print flashrom version and OS in default output, downgrade
> compiler/libpci/endianness info to verbose output.
>
> Signed-off-by: Carl-Daniel Hailfinger

the patch needs a rebase due to the shutdown callback patch. i have
attached a rebased version, but did not put much thought into conflict
resolutions, beware.
> Index: flashrom-logfile/flash.h
>
> --- flashrom-logfile/flash.h	(Revision 1337)
> +++ flashrom-logfile/flash.h	(Arbeitskopie)
> @@ -229,6 +229,12 @@
>  #define ERROR_NONFATAL 0x100
>
> /* cli_output.c */
> +#ifndef STANDALONE
> +int open_logfile(const char * const filename);
> +int close_logfile(void);
> +void start_logging(void);
> +#endif
> +int msg_log(const char *fmt, ...);
>  /* 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
> Index: flashrom-logfile/cli_output.c
> ===================================================================
> --- flashrom-logfile/cli_output.c	(Revision 1337)
> +++ 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
>
> @@ -22,30 +23,96 @@
>  #include <stdarg.h>
>  #include "flash.h"
>
> -int print(int type, const char *fmt, ...)
> +static FILE *logfile = NULL;
> +static int want_log = 0;
>
> +#ifndef STANDALONE
> +int close_logfile(void)
>  {
> if (logfile && fclose(logfile))
> return 1;
> 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)
> +{
> int oldverbose = verbose;
> want_log = 1;
> /* Shut up the console. */
> verbose = -2;
> print_version();
> verbose = oldverbose;
>
> +}

misleading name imho.
maybe it could be integrated into print_version itself, but you
probably wanted them to be split up.
the want_log = 1 may be better in open_logfile (which could/should then
be renamed to "start_logging?). on the whole i dont think it is worth it
to make a distinction between log and output (besides having different
verbose levels). why not just output the compile info in debug mode in
addition to the version + link stuff in normal mode?

i would like the logging to have the following properties:
 - the log should contain at least as much info as the output on screen
   (i.e. verbosity for logging should be >= of the verbosity of the
   printing).
 - the log should be as equal as possible to the printing when the same
   verbosity is used.
 - the log file is created automatically when not turned off by a
   command line option (switchable behavior with a macro maybe. it
   should be enabled by packagers so that we are always able to get
   logs from end users in case of emergencies. this could/should also
   be incorporated into the "DONT POWER OFF" message. but it may be nice
   to turn it off while developing/testing a lot.)
 - the log file name should contain a timestamp (YYYY-MM-DD
   hh-mm-ss, maybe even a timezone indicator where available) by
   default (i.e. if its name is not overridden by the user).
> +#endif /* STANDALONE */
>
> +int msg_log(const char *fmt, ...)
> +{
>    va_list ap;
>    int ret;
> FILE *output_type;
> if (!logfile)
> return -1;
> va_start(ap, fmt);
> ret = vfprintf(logfile, fmt, ap);
> va_end(ap);
> return ret;
>
> +}
>
> +int print(int type, const char *fmt, ...)
> +{
> va_list ap;
> int ret = 0;
> int want_screen = 1;
> int want_file = 1;
> FILE *output_type = stdout;
> switch (type) {
> case MSG_ERROR:
> output_type = stderr;
> case MSG_BARF:
> if (verbose < 2) {
> 	want_screen = 0;
> 	want_file = 0;
> }
> break;
> case MSG_BARF:
> if (verbose < 2)
> 	return 0;
> case MSG_DEBUG:
> if (verbose < 1)
> 	return 0;
> 	want_screen = 0;
> break;
> case MSG_INFO:
> if (verbose < 0)
> 	want_screen = 0;
> break;
> case MSG_ERROR:
> if (verbose < -1)
> 	want_screen = 0;
> output_type = stderr;
> break;
> default:
> output_type = stdout;
>
> break;
> }
>
> va_start(ap, fmt);
>
> ret = vfprintf(output_type, fmt, ap);
>
> va_end(ap);
> if (want_screen) {
> va_start(ap, fmt);
> ret = vfprintf(output_type, fmt, ap);
> va_end(ap);
> }
> if (want_file && logfile && want_log) {
> va_start(ap, fmt);
> ret = vfprintf(logfile, fmt, ap);
> va_end(ap);
> }
> return ret;
>
> }
> Index: flashrom-logfile/cli_classic.c
> ===================================================================
> --- flashrom-logfile/cli_classic.c	(Revision 1337)
> +++ flashrom-logfile/cli_classic.c	(Arbeitskopie)
> @@ -38,7 +38,8 @@
>             "-z|"
>  #endif
>             "-E|-r <file>|-w <file>|-v <file>]\n"
>       "       [-c <chipname>] [-m [<vendor>:]<part>] [-l <file>]\n"
>       "       [-c <chipname>] [-m [<vendor>:]<part>] [-l <file>] "
>         "[-o <file>]\n"
>     "       [-i <image>] [-p <programmername>[:<parameters>]]\n\n");
>
> printf("Please note that the command line interface for flashrom has "
>
> @@ -72,6 +73,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 "
> @@ -118,7 +120,7 @@
>    int operation_specified = 0;
>    int i;
> static const char optstring[] = "r:Rw:v:nVEfc:m:l:i:p:Lzh";
> static const char optstring[] = "r:Rw:v:nVEfc:m:l:i:p:Lzho:";
> static const struct option long_options[] = {
> {"read", 1, NULL, 'r'},
> {"write", 1, NULL, 'w'},
>
> @@ -136,6 +138,7 @@
>    	{"programmer", 1, NULL, 'p'},
>    	{"help", 0, NULL, 'h'},
>    	{"version", 0, NULL, 'R'},
> {"output", 1, NULL, 'o'},
> {NULL, 0, NULL, 0}
> };
>
> @@ -307,14 +310,22 @@
>    		cli_classic_usage(argv[0]);
>    		exit(0);
>    		break;
> case 'o':
> 	tempstr = strdup(optarg);
>
> +#ifdef STANDALONE
> 	fprintf(stderr, "Log file not supported in standalone "
> 		"mode. Aborting.\n");
>
> +#else /* STANDALONE */
> 	if (open_logfile(tempstr))
>
> +#endif /* STANDALONE */
> 		cli_classic_abort_usage();
> 	break;
> default:
> 	cli_classic_abort_usage();
> 	break;
> }
> }
> /* FIXME: Print the actions flashrom will take. */
> if (list_supported) {
>   print_supported();
>   exit(0);
>
> @@ -355,11 +366,21 @@
>    	flash = NULL;
>    }
>
> +#ifndef STANDALONE
> start_logging();
>
> +#endif /* STANDALONE */
> msg_gdbg("Command line:");
> for (i = 0; i < argc; i++) {
> msg_gdbg(" %s", argv[i]);
> }
> msg_gdbg("\n");

yay!
in very stupid cases distinguishing between arguments may help
debugging. something like
msg_gspew(" "%s"", argv[i]);
> /* FIXME: Delay calibration should happen in programmer code. */
>    myusec_calibrate_delay();
>
> if (programmer_init(pparam)) {
> fprintf(stderr, "Error: Programmer initialization failed.\n");
> msg_perr("Error: Programmer initialization failed.\n");
> exit(1);
> }
>
> @@ -372,26 +393,31 @@
>    }
>
> if (chipcount > 1) {
> printf("Multiple flash chips were detected:");
> msg_cinfo("Multiple flash chips were detected:");
> for (i = 0; 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");
> programmer_shutdown();
> exit(1);
> } 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) {
> 	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");
> startchip = probe_flash(0, &flashes[0], 1);
> 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);
> 	programmer_shutdown();
> 	exit(1);
> }
> 	printf("Please note that forced reads most likely contain garbage.\n");
> 	msg_cinfo("Please note that forced reads most likely "
> 		  "contain garbage.\n");
> return read_flash_to_file(&flashes[0], filename);
> }
> // FIXME: flash writes stay enabled!
>
> @@ -406,21 +432,21 @@
>    size = fill_flash->total_size * 1024;
>    if (check_max_decode((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");
>
> programmer_shutdown();
> return 1;
> }
>
> if (!(read_it | write_it | verify_it | erase_it)) {
> printf("No operations were specified.\n");
> msg_ginfo("No operations were specified.\n");
>
> // FIXME: flash writes stay enabled!
> programmer_shutdown();
> exit(0);
> }
>
> if (!filename && !erase_it) {
> printf("Error: No filename specified.\n");
> msg_gerr("Error: No filename specified.\n");
> // FIXME: flash writes stay enabled!
> programmer_shutdown();
> exit(1);
> Index: flashrom-logfile/flashrom.c
>
> --- flashrom-logfile/flashrom.c	(Revision 1337)
> +++ flashrom-logfile/flashrom.c	(Arbeitskopie)
> @@ -543,13 +543,18 @@
>
> int programmer_shutdown(void)
>  {
> int ret = 0;
> /* Registering shutdown functions is no longer allowed. */
> may_register_shutdown = 0;
> while (shutdown_fn_count > 0) {
> int i = --shutdown_fn_count;
> shutdown_fn[i].func(shutdown_fn[i].data);
> }
> return programmer_table[programmer].shutdown();
> ret = programmer_table[programmer].shutdown();
>
> +#ifndef STANDALONE
> ret |= close_logfile();
>
> +#endif
> return ret;
>
> }
>
> void *programmer_map_flash_region(const char *descr, unsigned long phys_addr,
> @@ -1649,37 +1654,37 @@
>    msg_ginfo(" on %s %s (%s)", osinfo.sysname, osinfo.release,
>    	  osinfo.machine);
>  #else
> msg_ginfo(" on unknown machine");
> msg_gdbg(" 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");
>  }

i did not rigorously review everything, so no ack (yet). if you wanna
commit as is i could look at it more carefully...