Logging/debugging from within Src/Zle/compmatch.c

Logging/debugging from within Src/Zle/compmatch.c

[nicolas.canceill]

Hi everyone,

Following up on a discussion on zsh-users [1], I wish to try and debug the internals of Src/Zle/compmatch.c, but I am not a gdb guru so I prefer to log a bunch of stuff from within the C functions. Can anyone advise on the best way to do so? Do you think a simple syslog(3) will do?

Best regards.

Nicolas Canceill

[1] http://www.zsh.org/mla/users/2014/threads.html#00611

Re: Logging/debugging from within Src/Zle/compmatch.c

[Bart Schaefer]

On Jun 8, 12:25pm, nicolas.canceill wrote:
}
} Following up on a discussion on zsh-users [1], I wish to try and debug
} the internals of Src/Zle/compmatch.c, but I am not a gdb guru so I
} prefer to log a bunch of stuff from within the C functions. Can anyone
} advise on the best way to do so? Do you think a simple syslog(3) will
} do?

Syslog would certainly do the job, but seems a bit of overkill unless
you're trying to collect logs from several zsh at once to see how they
interact.

I probably didn't understand your question properly before.  I think
what you want is to sprinkle some calls to dputs(ERRMSG(...)) around
the functions you're interested in.

If you do use syslog, using ERRMSG(...) will add helpful stuff like
the file name and line number.

For both dputs and ERRMSG you need to compile with DEBUG defined to the
preprocessor.

Weird completion bug in Src/Zle/compmatch.c#bld_line

[nicolas.canceill]

[-- Attachment #1: Type: text/plain, Size: 4101 bytes --]

Hi zsh-workers,

TL;DR Using openlog(...) (from syslog.h) at the beginning and closelog() at the end of Src/Zle/compmatch.c#bld_line(...) solves a weird completion bug.

***

I feel a little bit like Alice — although this message is not sent to Bob.

As you can read from the threads [1,2], I was looking for the White Rabbit, and Bart Schaefer helped me track him down to Src/Zle/compmatch.c. And the rabbit hole runs deep: 2900 lines! So I was gazing through the looking glass of Zsh C routines, and I was wondering how to log stuff from over there.

Unfortunately, no one can believe what the fix is: you have to see it for yourself. Jun kindly suggested I should use a file descriptor to another TTY, and Bart mentioned dputs. But I first tried with syslog(3), and I started tumbling down the rabbit hole.

syslog(3) actually solved the bug. No kidding. You take the red pill, we stay in Wonderland, and I will show you.

***

Since it initially got posted on zsh-users, let me summarize the bug for you. It originates from that case-insensitive substring-matching completion style I heard about from the Cheshire cat:

zstyle ':completion:*' matcher-list 'm:{a-zA-Z}={A-Za-z}' 'l:|=* r:|=*'

The bug occurs when a completion leads to multiple completion choices, under the following conditions:
* completion choices are all the same length;
* completion choices share a common suffix;
* that suffix is at least half of the length but not the full length;
* in each choice, the first and the n-th character of the suffix are both letters, where n is the length of the prefix;
* in each choice, the character just before the common suffix is a digit (or some other non-letter character, like an underscore, or the Queen of Hearts), and that character is different for each choice.

The Hatter told me that the above list of conditions looked like "quantum mechanics". I myself agree with the Duchess: "he only does it to annoy / because he knows it teases".

Under the above conditions, the bug happens when completing after a substring prefixing the common suffix (i.e. completing after "a" or "al" or ... or "alice", when the common suffix is "alice").

Expected behavior: the suffix gets completed. The Duchess and her baby sneeze.

Actual behavior: the suffix gets completed, but a letter is inserted before the suffix. This letter is the n-th character of the suffix, in inverted case. The baby changes into a pig.

Example 1: in a directory containing two files "1abc" and "2abc", completing after ": a" will expand it to "abc" and then add an extra "A", so the command line will look like ": Aabc".

Example 2: on a table with a cake saying "__eat_me_please" and a bottle saying "drink%me_please", completing after ": me_p" will expand it to "me_please" and then add an extra "E", so the command line will look like ": Eme_please".

***

Now that you know the bug, on to what I have tried so far. I have been working on version 5.0.2, where the bld_line function is in Src/Zle/compmatch.c at lines 1669-1920. By the way, debugging a 350-line-long function fells like swimming in a pool made of my own tears.

So first, I started by #include-ing <syslog.h> and logging parameters in the first lines of the bld_line function, like so:

openlog("zsh",LOG_PID|LOG_CONS,LOG_USER);
syslog(LOG_WARNING,"lpat: %s",lpat->u.str);
closelog();

Compiles fine, logs fine. Great. But then I think "hey, in a minute I am gonna want to log stuff all over the place, let me close the log at the end of the function instead".

So I move the "closelog();" call to the end of the function, and I duplicate it because the bld_line function actually has four return statements. And, like that: poof... he's gone! — I mean that the bug disappeared just because I closed the log at the end of the function!!!

Moreover, the "syslog(...);" call is irrelevant! Simply calling "openlog" at the beginning of the routine, and "closelog" before each return statement, fixes the bug. WAT? So I included a patch, you can show it to you friends and have a good laugh.


[-- Attachment #2: zsh-5.0.2-compmatch.patch --]
[-- Type: application/octet-stream, Size: 1255 bytes --]

diff --git a/Src/Zle/compmatch.c b/Src/Zle/compmatch.c
index 4cd3b9f..27c0e6c 100644
--- a/Src/Zle/compmatch.c
+++ b/Src/Zle/compmatch.c
@@ -29,6 +29,7 @@
 
 #include "complete.mdh"
 #include "compmatch.pro"
+#include <syslog.h>
 
 /*
  * This compares two cpattern lists and returns non-zero if they are
@@ -1679,6 +1680,8 @@ bld_line(Cmatcher mp, ZLE_STRING_T line, char *mword, char *word,
     VARARR(convchar_t, wordchars, wlen);
     VARARR(struct cpattern, genpatarr, mp->llen);
 
+    openlog("zsh",LOG_PID|LOG_CONS,LOG_USER);
+
     /*
      * We may need to start the "word" array from the end.  This
      * is much easier if we convert it to an array of (possibly wide)
@@ -1741,6 +1744,7 @@ bld_line(Cmatcher mp, ZLE_STRING_T line, char *mword, char *word,
 		/*
 		 * No equivalent.  No possible match; give up.
 		 */
+                closelog();
 		return 0;
 	    }
 	    /*
@@ -1909,13 +1913,16 @@ bld_line(Cmatcher mp, ZLE_STRING_T line, char *mword, char *word,
 		}
 	    }
 	    if (!ms)
+                closelog();
 		return 0;	/* Didn't match, give up */
 	}
     }
     if (!llen) {
 	/* Unmatched portion in the line built, return matched length. */
+        closelog();
 	return rl;
     }
+    closelog();
     return 0;
 }
 

[-- Attachment #3: Type: text/plain, Size: 1267 bytes --]



Either my gcc is making fun of me, or... it finally happened, happened, I'm slightly maaaaaaad. What is going on? I thought I did not drink any of his special tea... his specialty... Why is a raven like a writing desk?

***

Sorry about the Carroll-esque tone, I could not help it — maybe I am indeed slightly mad. If you know why syslog(3) fixes the bug, or if you have any insight about what is happening here, I will be happy to hear from you.

Cheers guys.

Nicolas Canceill

[1] http://www.zsh.org/mla/users/2014/threads.html#0061
[2] http://www.zsh.org/mla/workers/2014/threads.html#00534



Le 8 juin 2014 à 17:47, Jun T. <takimoto-j@kba.biglobe.ne.jp> a écrit :

> 2014/06/08 19:25, nicolas.canceill <nicolas.canceill@laposte.net> wrote:
>> 
>>  ... so I prefer to log a bunch of stuff from within the C functions.
> 
> How about writing to the tty of another window?
> 
> Open a terminal window, and use the 'tty' command to show the device name
> of the tty of this window:
> 
> $ tty
> /dev/ttys002
> 
> Then open another terminal window, edit the source code to add lines like
> 
>    FILE *mylog = fopen("/dev/ttys002", "w");
>    ...
>    fprintf(mylog, "log/debug info....\n");
> 
> and build/run the program.

Re: Weird completion bug in Src/Zle/compmatch.c#bld_line

[Jun T.]

What you are getting is not a mystery at all, but may give some hint.

In your patch:

 	    if (!ms)
+                closelog();
 		return 0;	/* Didn't match, give up */

but you need a block { .. } here, as follows:

 	    if (!ms) {
                closelog();
 		return 0;	/* Didn't match, give up */
	    }


If you use your patch, the function returns 0 even if ms is not NULL.
In the original code, the function returns 0 if ms is NULL and llen is 0;
otherwise it returns rl.

I guess your journey continues...

Re: Weird completion bug in Src/Zle/compmatch.c#bld_line

[nicolas.canceill]

Woops... I feel like an Apple engineer in front of the "goto fail;" bug...

Be back with more tea soon!

Nicolas Canceill


Le 9 juin 2014 à 15:25, Jun T. <takimoto-j@kba.biglobe.ne.jp> a écrit :

> What you are getting is not a mystery at all, but may give some hint.
> 
> In your patch:
> 
> 	    if (!ms)
> +                closelog();
> 		return 0;	/* Didn't match, give up */
> 
> but you need a block { .. } here, as follows:
> 
> 	    if (!ms) {
>                closelog();
> 		return 0;	/* Didn't match, give up */
> 	    }
> 
> 
> If you use your patch, the function returns 0 even if ms is not NULL.
> In the original code, the function returns 0 if ms is NULL and llen is 0;
> otherwise it returns rl.
> 
> I guess your journey continues...

Re: Weird completion bug in Src/Zle/compmatch.c#bld_line

[Bart Schaefer]

On Jun 9, 11:18am, nicolas.canceill wrote:
}
} Since it initially got posted on zsh-users, let me summarize the bug
} for you.

This is OK because it's good to have the bug description in the archive,
but it's not strictly necessary because all zsh-users mail is forwarded
to zsh-workers.

} Actual behavior: the suffix gets completed, but a letter is inserted
} before the suffix. This letter is the n-th character of the suffix, in
} inverted case. The baby changes into a pig.

The "nth character in inverted case" may be a red herring.  If you do

    % touch '?ghi' '!ghi'
    % : g<TAB>
    % : \Hghi

so I think we've got a simple case of a pointer running off the end of a
buffer and using whatever random stuff is there, and it just happens that
most of the time that's part of the suffix.

-- 
Barton E. Schaefer