Re: tab-completion debug print

Hello.

At Mon, 26 Nov 2018 07:08:53 +0100, David Fetter <david@fetter.org> wrote in <20181126060853.GP958@fetter.org>
> On Sun, Nov 25, 2018 at 11:21:51PM -0500, Tom Lane wrote:
> > Kyotaro HORIGUCHI <horiguchi.kyotaro@lab.ntt.co.jp> writes:
> > >> On Fri, Nov 23, 2018 at 04:32:31PM -0500, Tom Lane wrote:
> > >>> Hm.  I can see the value of instrumenting tab-complete when you're trying
> > >>> to debug why it did something, but this output format seems pretty terse
> > >>> and unreadable.
> > 
> > > The reason for the minimal output was it won't disturb console so
> > > much when stderr is not redirected. It could be richer if we
> > > premise redirection.
> > 
> > It seems to me this behavior would be completely unusable if it's not
> > redirected; I don't understand why you're even considering that as an
> > interesting option.  libreadline is necessarily active when we're doing
> > this, and it will get very confused (or at least produce a very confused
> > display) if anything else is emitting text onto the active console line.

The mess here started because I forgot about -L option of psql. I
wouldn't do that if I knew of it.

> Integrating with libreadline would be a *much* bigger project for
> reasons starting with the ones you state.
> 
> > Maybe somebody who never makes any typing errors at all and doesn't
> > really need to see what they typed could use it like that, but I for
> > one would find it quite useless.
> > In fact, I was thinking of proposing that the output shouldn't go to
> > stderr in the first place.  If you do it like that, then you're also
> > confusing this info with query error output, which does little for
> > usability either.

So, we can use the exiting log file feature of psql.

> > Speaking of query error output, it wouldn't be a bad thing if this
> > mode could show any errors from the tab-completion queries.  I
> > suppose people look into the postmaster log for that right now; but
> > if this were all going to some separate log file, I'd vote for
> > showing the constructed queries and their results or errors.
> 
> I briefly thought about logging this to the postmaster log, but psql
> is not the server, and doesn't, as a rule, have access to the same
> kinds of things the server does, so it's not really the right thing.
> On a busy server, because we don't yet have ways to carve off streams
> of logs, these ones could get lost in the noise.

Agreed.

> This brings up an interesting idea, though. It seems like we're
> backing into a logging facility for psql with this feature. How about
> just sending stderr to some file(s) in /var/log/psql/ , or if we're
> getting super fancy, to the syslog family?

syslog seems to be a kind of overdone for psql.. As mentioned
above, this version emits logs into the file specifed by -L
option. Some other information is also emitted into the file but
it doesn't seem to be a problem.

psql -L ~/psqldebug.log postgres

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
From 32a4dd7adecab70e464222af41552b22332679b4 Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <horiguchi.kyotaro@lab.ntt.co.jp>
Date: Tue, 27 Nov 2018 14:57:46 +0900
Subject: [PATCH] Tab-copletion debug log

With this patch, psql built with TABCOMPLETION_DEBUG defined emits
tab-completion debug log into the file specified -L option.
---
 src/bin/psql/tab-complete.c | 38 ++++++++++++++++++++++++++++++++++++++
 1 file changed, 38 insertions(+)

diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index 9dbd555166..a8758b22ee 100644
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -60,6 +60,44 @@ extern char *filename_completion_function();
 #define completion_matches rl_completion_matches
 #endif
 
+/*
+ * By enabling the following definition every completion attempt emits a log
+ * line into the log file if any. Every log line consists of the source line
+ * number where it is made, completion context and the completion result.
+ */
+#ifdef TABCOMPLETION_DEBUG
+#ifdef HAVE_RL_COMPLETION_MATCHES
+#define org_completion_matches rl_completion_matches
+#else
+#define org_completion_matches completion_matches
+#endif
+
+#undef completion_matches
+#define completion_matches(t, f) completion_debug(__LINE__, (t), (f))
+
+static char **completion_debug(int line,
+                               const char *text, rl_compentry_func_t *func)
+{
+    char **list = org_completion_matches(text, func);
+
+    if (pset.logfile)
+    {
+        /* Emit completion log */
+
+        /* Enclose empty list with brackets since it is an intermediate state
+         * which is immediately followed by a non-empty list.
+         */
+        fprintf(pset.logfile, "%s:%d:%s\"%s\" -> (", __FILE__, line, list ? "" : "[", text);
+        for (int i = 0; list && list[i]; ++i)
+            fprintf(pset.logfile, "%s\"%s\"", i ? ", " : "", list[i]);            
+        fprintf(pset.logfile, ")%s\n", list ? "": "]");
+        fflush(pset.logfile);
+    }
+
+    return list;
+}
+#endif
+
 /* word break characters */
 #define WORD_BREAKS        "\t\n@$><=;|&{() "
 
-- 
2.16.3