mg(1) log internals to file

classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

mg(1) log internals to file

Mark Lumsden-3
This diff allows mg to log its internal status to a file. At the moment it
only logs line information like front and back pointers in the linked
list, how many characters are used and where the cursor is placed in the
file, but I am finding it incredibly useful debugging mg at the moment.

Below is an example log file after opening a file with this contents:

abc
def
ghk

After I open the file in mg, I move forward a line (C-n), then move
forward a character (C-f):

$ cat log/mg.log
next-line
>3 3 0xc3a3557ae00 b^0xc3a592eac20 f.0xc3a592ea4a0 abc
  3 3 0xc3a592ea4a0 b^0xc3a3557ae00 f.0xc3a592ea660 def
  3 3 0xc3a592ea660 b^0xc3a592ea4a0 f.0xc3a307830e0 ghk
  0 0 0xc3a307830e0 b^0xc3a592ea660 f.0xc3a592eac20 (null)
  head 0xc3a592eac20 b^0xc3a307830e0 f.0xc3a3557ae00
(EOB)

forward-char
  3 3 0xc3a3557ae00 b^0xc3a592eac20 f.0xc3a592ea4a0 abc
>3 3 0xc3a592ea4a0 b^0xc3a3557ae00 f.0xc3a592ea660 def
  3 3 0xc3a592ea660 b^0xc3a592ea4a0 f.0xc3a307830e0 ghk
  0 0 0xc3a307830e0 b^0xc3a592ea660 f.0xc3a592eac20 (null)
  head 0xc3a592eac20 b^0xc3a307830e0 f.0xc3a3557ae00
(EOB)

The three columns of pointer addresses are (from the 'def' line):

0xc3a592ea4a0 the lines own pointer.
0xc3a3557ae00 the pointer to back(b^) line
0xc3a592ea660 the pointer to forward(f.) line

The numbers at the start of the first four lines are l_size and l_used.

With this diff logging is not switched on by default and has to compiled
into mg.  -DMGDEBUG has to be added to the Makefile:

CFLAGS+=-Wall -DREGEX  -DMGDEBUG

And the comment removed from:

#SRCS+=  log.c

The information logged at the moment is viewable by gdb, however, if a bug
that I have introduced doesn't present itself for XX number of key
presses, I can struggle to work out what has caused it in gdb, logging
like this makes problems I have introduced much more obvious and easier
to fix.

I have tried to make the ifdefs as minimal as possible. Any objections to
this diff?

Mark

Index: Makefile
===================================================================
RCS file: /cvs/src/usr.bin/mg/Makefile,v
retrieving revision 1.33
diff -u -p -u -p -r1.33 Makefile
--- Makefile 16 Sep 2016 17:17:40 -0000 1.33
+++ Makefile 7 Jun 2019 14:42:39 -0000
@@ -9,6 +9,7 @@ DPADD+= ${LIBCURSES} ${LIBUTIL}
  #
  # REGEX -- create regular expression functions.
  # STARTUPFILE -- look for and handle initialization file.
+# MGDEBUG -- debug mg internals to a log file.
  #
  CFLAGS+=-Wall -DREGEX

@@ -22,6 +23,11 @@ SRCS= autoexec.c basic.c bell.c buffer.c
  # More or less standalone extensions.
  #
  SRCS+= cmode.c cscope.c dired.c grep.c tags.c
+
+#
+# -DMGDEBUG source file.
+#
+#SRCS+= log.c

  afterinstall:
  ${INSTALL} -d -o root -g wheel ${DESTDIR}${DOCDIR}/mg
Index: kbd.c
===================================================================
RCS file: /cvs/src/usr.bin/mg/kbd.c,v
retrieving revision 1.30
diff -u -p -u -p -r1.30 kbd.c
--- kbd.c 26 Sep 2015 21:51:58 -0000 1.30
+++ kbd.c 7 Jun 2019 14:42:39 -0000
@@ -15,6 +15,10 @@
  #include "key.h"
  #include "macro.h"

+#ifdef  MGDEBUG
+#include "log.h"
+#endif
+
  #define METABIT 0x80

  #define PROMPTL 80
@@ -151,6 +155,11 @@ doin(void)
  while ((funct = doscan(curmap, (key.k_chars[key.k_count++] =
     getkey(TRUE)), &curmap)) == NULL)
  /* nothing */;
+
+#ifdef  MGDEBUG
+ if (!mglog(funct))
+ ewprintf("Problem with logging");
+#endif

  if (macrodef && macrocount < MAXMACRO)
  macro[macrocount++].m_funct = funct;
Index: log.c
===================================================================
RCS file: log.c
diff -N log.c
--- /dev/null 1 Jan 1970 00:00:00 -0000
+++ log.c 7 Jun 2019 14:42:39 -0000
@@ -0,0 +1,121 @@
+/* $OpenBSD$ */
+
+/*
+ * This file is in the public domain.
+ *
+ * Author: Mark Lumsden <[hidden email]>
+ *
+ */
+
+/*
+ * Record a history of an mg session for temporal debugging.
+ * Sometimes pressing a key will set the scene for a bug only visible
+ * dozens of keystrokes later. gdb has its limitations in this scenario.
+ */
+
+#include <sys/queue.h>
+#include <sys/stat.h>
+#include <ctype.h>
+#include <fcntl.h>
+#include <signal.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <unistd.h>
+
+#include "def.h"
+#include "log.h"
+#include "funmap.h"
+
+static char mglogpath[20];
+
+int
+mglog(PF funct)
+{
+ struct line     *lp;
+ struct stat      sb;
+ char *curline;
+ FILE            *fd;
+ int i;
+
+ i = 0;
+
+ if(stat(mglogpath, &sb))
+ return (FALSE);
+
+ fd = fopen(mglogpath, "a");
+ if (fprintf(fd, "%s\n", function_name(funct)) == -1) {
+ fclose(fd);
+ return (FALSE);
+ }
+ lp = bfirstlp(curbp);
+
+ for(;;) {
+ i++;
+ curline = " ";
+ if (i == curwp->w_dotline)
+ curline = ">";
+ if (fprintf(fd, "%s%d %d %p b^%p f.%p %s\n", curline,
+    lp->l_size, lp->l_used, lp, lp->l_bp, lp->l_fp,
+    lp->l_text) == -1) {
+ fclose(fd);
+ return (FALSE);
+ }
+ lp = lforw(lp);
+ if (lp == curbp->b_headp) {
+ if (fprintf(fd, " head %p b^%p f.%p\n(EOB)\n\n",
+    lp, lp->l_bp, lp->l_fp) == -1) {
+ fclose(fd);
+                        return (FALSE);
+ }
+ break;
+ }
+ }
+ fclose(fd);
+
+ return (TRUE);
+}
+
+
+/*
+ * Make sure logging to log file can happen.
+ */
+int
+mgloginit(void)
+{
+ struct stat sb;
+ mode_t           dir_mode, f_mode, oumask;
+ char *mglogdir;
+ int     fd;
+
+ mglogdir = "./log/";
+
+ oumask = umask(0);
+ f_mode = 0777& ~oumask;
+ dir_mode = f_mode | S_IWUSR | S_IXUSR;
+
+ if(stat(mglogdir, &sb)) {
+ if (mkdir(mglogdir, dir_mode) != 0)
+ return (FALSE);
+ if (chmod(mglogdir, f_mode) < 0)
+ return (FALSE);
+ }
+ if (strlcpy(mglogpath, mglogdir, sizeof(mglogpath)) >
+    sizeof(mglogpath))
+ return (FALSE);
+ if (strlcat(mglogpath, mglogfile, sizeof(mglogpath)) >
+    sizeof(mglogpath))
+ return (FALSE);
+
+ if(stat(mglogpath, &sb))
+ fd = open(mglogpath, O_RDWR | O_CREAT | O_TRUNC, 0644);
+ else
+ fd = open(mglogpath, O_RDWR | O_TRUNC, 0644);
+
+ if (fd == -1)
+ return (FALSE);
+
+ close(fd);
+
+ return (TRUE);
+}
Index: log.h
===================================================================
RCS file: log.h
diff -N log.h
--- /dev/null 1 Jan 1970 00:00:00 -0000
+++ log.h 7 Jun 2019 14:42:39 -0000
@@ -0,0 +1,14 @@
+/*      $OpenBSD$   */
+
+/* This file is in the public domain. */
+
+/*
+ * Specifically for mg logging functionality.
+ *
+ */
+
+int mglog(PF);
+int                      mgloginit(void);
+
+extern char             *mglogfile;
+
Index: main.c
===================================================================
RCS file: /cvs/src/usr.bin/mg/main.c,v
retrieving revision 1.85
diff -u -p -u -p -r1.85 main.c
--- main.c 13 Dec 2018 14:59:16 -0000 1.85
+++ main.c 7 Jun 2019 14:42:39 -0000
@@ -21,6 +21,11 @@
  #include "funmap.h"
  #include "macro.h"

+#ifdef  MGDEBUG
+#include "log.h"
+char            *mglogfile = "mg.log";
+#endif
+
  int thisflag; /* flags, this command */
  int lastflag; /* flags, last command */
  int curgoal; /* goal column */
@@ -86,6 +91,11 @@ main(int argc, char **argv)

  maps_init(); /* Keymaps and modes. */
  funmap_init(); /* Functions. */
+
+#ifdef  MGDEBUG
+ if (!mgloginit())
+ errx(1, "Unable to create logging environment.");
+#endif

  /*
  * This is where we initialize standalone extensions that should

Reply | Threaded
Open this post in threaded view
|

Re: mg(1) log internals to file

Florian Obser-2
On Fri, Jun 07, 2019 at 03:18:27PM +0000, Mark Lumsden wrote:

> This diff allows mg to log its internal status to a file. At the moment it
> only logs line information like front and back pointers in the linked list,
> how many characters are used and where the cursor is placed in the file, but
> I am finding it incredibly useful debugging mg at the moment.
>
> Below is an example log file after opening a file with this contents:
>
> abc
> def
> ghk
>
> After I open the file in mg, I move forward a line (C-n), then move forward
> a character (C-f):
>
> $ cat log/mg.log
> next-line
> > 3 3 0xc3a3557ae00 b^0xc3a592eac20 f.0xc3a592ea4a0 abc
>  3 3 0xc3a592ea4a0 b^0xc3a3557ae00 f.0xc3a592ea660 def
>  3 3 0xc3a592ea660 b^0xc3a592ea4a0 f.0xc3a307830e0 ghk
>  0 0 0xc3a307830e0 b^0xc3a592ea660 f.0xc3a592eac20 (null)
>  head 0xc3a592eac20 b^0xc3a307830e0 f.0xc3a3557ae00
> (EOB)
>
> forward-char
>  3 3 0xc3a3557ae00 b^0xc3a592eac20 f.0xc3a592ea4a0 abc
> > 3 3 0xc3a592ea4a0 b^0xc3a3557ae00 f.0xc3a592ea660 def
>  3 3 0xc3a592ea660 b^0xc3a592ea4a0 f.0xc3a307830e0 ghk
>  0 0 0xc3a307830e0 b^0xc3a592ea660 f.0xc3a592eac20 (null)
>  head 0xc3a592eac20 b^0xc3a307830e0 f.0xc3a3557ae00
> (EOB)
>
> The three columns of pointer addresses are (from the 'def' line):
>
> 0xc3a592ea4a0 the lines own pointer.
> 0xc3a3557ae00 the pointer to back(b^) line
> 0xc3a592ea660 the pointer to forward(f.) line
>
> The numbers at the start of the first four lines are l_size and l_used.
>
> With this diff logging is not switched on by default and has to compiled
> into mg.  -DMGDEBUG has to be added to the Makefile:
>
> CFLAGS+=-Wall -DREGEX  -DMGDEBUG
>
> And the comment removed from:
>
> #SRCS+=  log.c
>
> The information logged at the moment is viewable by gdb, however, if a bug
> that I have introduced doesn't present itself for XX number of key presses,
> I can struggle to work out what has caused it in gdb, logging like this
> makes problems I have introduced much more obvious and easier to fix.
>
> I have tried to make the ifdefs as minimal as possible. Any objections to
> this diff?
>

I'm not fundamentally opposed to such a functionality since I have
written an ad-hoc version of this on multiple occasions.

That being said, I would prefer a version that is so non-invasive that
we can compile it in always so that it does not fall to bitrot. I'd
also like an api that allows me to log arbitrary strings in addition
to what you have written here.

It does not quite live up to OpenBSD coding standards, see inline
(ignoring that your mail client seemed to have mangled the diff).

> Mark
>
> Index: Makefile
> ===================================================================
> RCS file: /cvs/src/usr.bin/mg/Makefile,v
> retrieving revision 1.33
> diff -u -p -u -p -r1.33 Makefile
> --- Makefile 16 Sep 2016 17:17:40 -0000 1.33
> +++ Makefile 7 Jun 2019 14:42:39 -0000
> @@ -9,6 +9,7 @@ DPADD+= ${LIBCURSES} ${LIBUTIL}
>  #
>  # REGEX -- create regular expression functions.
>  # STARTUPFILE -- look for and handle initialization file.
> +# MGDEBUG -- debug mg internals to a log file.
>  #
>  CFLAGS+=-Wall -DREGEX
>
> @@ -22,6 +23,11 @@ SRCS= autoexec.c basic.c bell.c buffer.c
>  # More or less standalone extensions.
>  #
>  SRCS+= cmode.c cscope.c dired.c grep.c tags.c
> +
> +#
> +# -DMGDEBUG source file.
> +#
> +#SRCS+= log.c
>
>  afterinstall:
>   ${INSTALL} -d -o root -g wheel ${DESTDIR}${DOCDIR}/mg
> Index: kbd.c
> ===================================================================
> RCS file: /cvs/src/usr.bin/mg/kbd.c,v
> retrieving revision 1.30
> diff -u -p -u -p -r1.30 kbd.c
> --- kbd.c 26 Sep 2015 21:51:58 -0000 1.30
> +++ kbd.c 7 Jun 2019 14:42:39 -0000
> @@ -15,6 +15,10 @@
>  #include "key.h"
>  #include "macro.h"
>
> +#ifdef  MGDEBUG
> +#include "log.h"
> +#endif
> +
>  #define METABIT 0x80
>
>  #define PROMPTL 80
> @@ -151,6 +155,11 @@ doin(void)
>   while ((funct = doscan(curmap, (key.k_chars[key.k_count++] =
>      getkey(TRUE)), &curmap)) == NULL)
>   /* nothing */;
> +
> +#ifdef  MGDEBUG
> + if (!mglog(funct))
> + ewprintf("Problem with logging");
> +#endif
>
>   if (macrodef && macrocount < MAXMACRO)
>   macro[macrocount++].m_funct = funct;
> Index: log.c
> ===================================================================
> RCS file: log.c
> diff -N log.c
> --- /dev/null 1 Jan 1970 00:00:00 -0000
> +++ log.c 7 Jun 2019 14:42:39 -0000
> @@ -0,0 +1,121 @@
> +/* $OpenBSD$ */
> +
> +/* + * This file is in the public domain.
> + *
> + * Author: Mark Lumsden <[hidden email]>
> + *
> + */
> +
> +/*
> + * Record a history of an mg session for temporal debugging.
> + * Sometimes pressing a key will set the scene for a bug only visible + *
> dozens of keystrokes later. gdb has its limitations in this scenario.
> + */
> +
> +#include <sys/queue.h>
> +#include <sys/stat.h>
> +#include <ctype.h>
> +#include <fcntl.h>
> +#include <signal.h>
> +#include <stdio.h>
> +#include <stdlib.h>
> +#include <string.h>
> +#include <unistd.h>
> +
> +#include "def.h"
> +#include "log.h"
> +#include "funmap.h"
> +
> +static char mglogpath[20];
                          ^^ this is a weird spelling of PATH_MAX

> +
> +int
> +mglog(PF funct)
> +{
> + struct line     *lp;
> + struct stat      sb;
> + char *curline;
> + FILE            *fd;
> + int i;
> +
> + i = 0;
> +
> + if(stat(mglogpath, &sb))
> + return (FALSE);
> +
> + fd = fopen(mglogpath, "a");
> + if (fprintf(fd, "%s\n", function_name(funct)) == -1) {
> + fclose(fd);
> + return (FALSE);
> + }

what's the point of constant stat'ing and opening the file?
Can't you just keep it open in mloginit?

Also stat + fopen is a dangerous pattern.

> + lp = bfirstlp(curbp);
> +
> + for(;;) {
> + i++;
> + curline = " ";
> + if (i == curwp->w_dotline)
> + curline = ">";
> + if (fprintf(fd, "%s%d %d %p b^%p f.%p %s\n", curline,
> +    lp->l_size, lp->l_used, lp, lp->l_bp, lp->l_fp,
> +    lp->l_text) == -1) {
> + fclose(fd);
> + return (FALSE);
> + }
> + lp = lforw(lp);
> + if (lp == curbp->b_headp) {
> + if (fprintf(fd, " head %p b^%p f.%p\n(EOB)\n\n",
> +    lp, lp->l_bp, lp->l_fp) == -1) {
> + fclose(fd);
> +                        return (FALSE);
> + }
> + break;
> + }
> + }
> + fclose(fd);
> +
> + return (TRUE);
> +}
> +
> +
> +/*
> + * Make sure logging to log file can happen.
> + */
> +int
> +mgloginit(void)
> +{
> + struct stat sb;
> + mode_t           dir_mode, f_mode, oumask;
> + char *mglogdir;
> + int     fd;
> +
> + mglogdir = "./log/";

why don't you statically init mlogpath?

> +
> + oumask = umask(0);
> + f_mode = 0777& ~oumask;
                     ^ missing space

> + dir_mode = f_mode | S_IWUSR | S_IXUSR;
> +
> + if(stat(mglogdir, &sb)) {
> + if (mkdir(mglogdir, dir_mode) != 0)
> + return (FALSE);
> + if (chmod(mglogdir, f_mode) < 0)
> + return (FALSE);
> + }

mg(1) is not a config managment system, I think we should just require
the directory to be there. Also this looks like a neat TOCTOU problem.

It would probably be best to store logfiles somewhere in $HOME and
not squat on ./

Maybe the filename should contain a timestamp so that you can keep
multiple sessions?

> + if (strlcpy(mglogpath, mglogdir, sizeof(mglogpath)) >
> +    sizeof(mglogpath))
> + return (FALSE);
> + if (strlcat(mglogpath, mglogfile, sizeof(mglogpath)) >
> +    sizeof(mglogpath))
> + return (FALSE);

if it's always the same filename you can skip this whole song and dance
and just statically assign it.

> +
> + if(stat(mglogpath, &sb))
> + fd = open(mglogpath, O_RDWR | O_CREAT | O_TRUNC, 0644);
> + else
> + fd = open(mglogpath, O_RDWR | O_TRUNC, 0644);
> +

what's the point? just get rid of the stat() and do
        fd = open(mglogpath, O_RDWR | O_CREAT | O_TRUNC, 0644);

> + if (fd == -1)
> + return (FALSE);
> +
> + close(fd); +

just keep the fd or FILE* open through the lifetime of mg

> + return (TRUE);
> +}
> Index: log.h
> ===================================================================
> RCS file: log.h
> diff -N log.h
> --- /dev/null 1 Jan 1970 00:00:00 -0000
> +++ log.h 7 Jun 2019 14:42:39 -0000
> @@ -0,0 +1,14 @@
> +/*      $OpenBSD$   */
> +
> +/* This file is in the public domain. */
> +
> +/*
> + * Specifically for mg logging functionality.
> + *
> + */
> +
> +int mglog(PF);
> +int                      mgloginit(void);

tab vs. space

> +
> +extern char             *mglogfile;
> +
> Index: main.c
> ===================================================================
> RCS file: /cvs/src/usr.bin/mg/main.c,v
> retrieving revision 1.85
> diff -u -p -u -p -r1.85 main.c
> --- main.c 13 Dec 2018 14:59:16 -0000 1.85
> +++ main.c 7 Jun 2019 14:42:39 -0000
> @@ -21,6 +21,11 @@
>  #include "funmap.h"
>  #include "macro.h"
>
> +#ifdef  MGDEBUG
> +#include "log.h"
> +char            *mglogfile = "mg.log";
> +#endif
> +
>  int thisflag; /* flags, this command */
>  int lastflag; /* flags, last command */
>  int curgoal; /* goal column */
> @@ -86,6 +91,11 @@ main(int argc, char **argv)
>
>   maps_init(); /* Keymaps and modes. */
>   funmap_init(); /* Functions. */
> +
> +#ifdef  MGDEBUG
> + if (!mgloginit())
> + errx(1, "Unable to create logging environment.");
> +#endif
>
>   /*
>   * This is where we initialize standalone extensions that should
>

--
I'm not entirely sure you are real.