Обсуждение: tab-completion debug print

Hello.

I was reminded that I was often annoyed with identifying the code
that made a word-completion, by hearing the same complaint from a
collegue of mine just now.

Something like the attached that tweaks completion_matches calls
lets psql emit the line number where a word-completion
happens. The output can be split out using redirection so that it
doesn't break into the conversation on console.

(make -s COPT=-DTABCOMPLETION_DEBUG install)

$ psql postgres 2>~debug.out
=# alt[tab]er [tab]t[tab]ab[tab] [tab]

You can see the following output in another bash session.

$ tail -f ~/debug.out
[1414][1435][1435][1435][1431]

Every number enclosed by brackets is the line number in
tab-complete.c, where completion happens.

Is this useful? Any suggestions, thoughts?


regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index 9dbd555166..2deb892de6 100644
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -60,6 +60,23 @@ extern char *filename_completion_function();
 #define completion_matches rl_completion_matches
 #endif
 
+/*
+ * By enabling the following definition the source line number is emitted to
+ * stderr for every completion attempt. You can isolate them from console
+ * interaction by redirecting stderr into a file.
+ */
+#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(text, list) \
+    (fprintf(stderr, "[%d]", __LINE__), org_completion_matches(text, list))
+#endif
+
 /* word break characters */
 #define WORD_BREAKS        "\t\n@$><=;|&{() "

Kyotaro HORIGUCHI <horiguchi.kyotaro@lab.ntt.co.jp> writes:
> I was reminded that I was often annoyed with identifying the code
> that made a word-completion, by hearing the same complaint from a
> collegue of mine just now.
> Something like the attached that tweaks completion_matches calls
> lets psql emit the line number where a word-completion
> happens. The output can be split out using redirection so that it
> doesn't break into the conversation on console.

> (make -s COPT=-DTABCOMPLETION_DEBUG install)
> $ psql postgres 2>~debug.out
> =# alt[tab]er [tab]t[tab]ab[tab] [tab]

> You can see the following output in another bash session.
> $ tail -f ~/debug.out
> [1414][1435][1435][1435][1431]
> Every number enclosed by brackets is the line number in
> tab-complete.c, where completion happens.

> Is this useful? Any suggestions, thoughts?

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.  Can we get it to print the completion text as well?
I'm imagining something more like

1414: "er "
1435: ""
1435: "ab"
1435: ""
1431: ""

Perhaps there's room as well to print the context that the match looked
at:

1414: "alt" -> "er "
1435: "alter " -> ""
1435: "alter t" -> "ab"

etc.

            regards, tom lane

On Fri, Nov 23, 2018 at 04:32:31PM -0500, Tom Lane wrote:
> Kyotaro HORIGUCHI <horiguchi.kyotaro@lab.ntt.co.jp> writes:
> > I was reminded that I was often annoyed with identifying the code
> > that made a word-completion, by hearing the same complaint from a
> > collegue of mine just now.
> > Something like the attached that tweaks completion_matches calls
> > lets psql emit the line number where a word-completion
> > happens. The output can be split out using redirection so that it
> > doesn't break into the conversation on console.
> 
> > (make -s COPT=-DTABCOMPLETION_DEBUG install)
> > $ psql postgres 2>~debug.out
> > =# alt[tab]er [tab]t[tab]ab[tab] [tab]
> 
> > You can see the following output in another bash session.
> > $ tail -f ~/debug.out
> > [1414][1435][1435][1435][1431]
> > Every number enclosed by brackets is the line number in
> > tab-complete.c, where completion happens.
> 
> > Is this useful? Any suggestions, thoughts?
> 
> 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.  Can we get it to print the completion text as well?
> I'm imagining something more like
> 
> 1414: "er "
> 1435: ""
> 1435: "ab"
> 1435: ""
> 1431: ""
> 
> Perhaps there's room as well to print the context that the match looked
> at:
> 
> 1414: "alt" -> "er "
> 1435: "alter " -> ""
> 1435: "alter t" -> "ab"
> 
> etc.
> 
>             regards, tom lane

Is this something along the lines of what you had in mind?

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

Thank you for the comments.

At Sun, 25 Nov 2018 01:17:27 +0100, David Fetter <david@fetter.org> wrote in <20181125001727.GM958@fetter.org>
> 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.  Can we get it to print the completion text as well?
> > I'm imagining something more like
> > 
> > 1414: "er "
> > 1435: ""
> > 1435: "ab"
> > 1435: ""
> > 1431: ""
> > 
> > Perhaps there's room as well to print the context that the match looked
> > at:
> > 
> > 1414: "alt" -> "er "
> > 1435: "alter " -> ""
> > 1435: "alter t" -> "ab"
> > 
> > etc.
> > 
> >             regards, tom lane
> 
> Is this something along the lines of what you had in mind?

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. Since every debug line is followed by a
line-feed, we don't need the brackets. Since the result is a set
so Devid's proposal to enclose the set by parentheses looks nice.
Also, result can contain matches containing word breaks (or even
an empty string) so quoting make every candidate string more
distinctive.

Finally, the attached shows the following debugging output.


INPUT: alter u<tab>(ser)<tab> <tab>
OUTPUT:
1445: "u" -> ("user", "user", "user mapping for")
1445: "user" -> ("user", "user", "user mapping for")
3630: "" -> ("", "horiguti", "MAPPING FOR", "pg_execute_server_program", "pg_monitor", "pg_read_all_settings",
"pg_read_all_stats","pg_read_server_files", "pg_signal_backend", "pg_stat_scan_tables", "pg_write_server_files",
"usr1","usr2")
 

INPUT: create function <tab>
OUTPUT:
3635: "" -> ("", "pg_ndistinct_out", "path_recv", "int4eq", "spg_quad_picksplit", "tsvectorsend", "float8_var_pop",
"opaque_in","interval_le", "macaddr_cmp", "range_gt..(17272 chars)..nge_in")
 

Wouldn't be a problem with the long line since it is for
debugging purpose. Of course we can limit the length easily (by
number of elements).

>+    for (int i = 0; list && list[i]; ++i)

# Are we using C99 for-loop-variable-declarations?

An arguable change in this version is enclosing empty result
lists with brackets, since it is just an intermediate state for
us.

[1431: "sael" -> ()]
3655: "sael" -> ("")

Showing completion context makes things a bit bothersome, since
complete_from_variables needs to take additional two parameters.
It is already shown in console conversasion so I'm not sure it's
worth the trouble.

1872: (...table t1 alter [COn]) -> ("CONSTRAINT")

To be friendly with the CI, the second patch is attached as the
difference from the first patch.


Note: This is not registered in this  CF.

- v3-0001-Psql-completion-debug-print-feature.patch
  W/O context version

- v3-0002-Add-context-information-in-tab-completion-debug-prin.patch
  W context version

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
From 573d8352331d0fd2ee0b5f3147cfcdcf7f1d4afc Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <horiguchi.kyotaro@lab.ntt.co.jp>
Date: Mon, 26 Nov 2018 12:05:35 +0900
Subject: [PATCH 1/2] Psql completion debug print feature

Sometimes we find it bothersome to identify the code that actually
made a tab-completion. Psql will show the line number and completion
result to stderr by defining TABCOMPLETION_DEBUG at comiple time with
this patch.
---
 src/bin/psql/tab-complete.c | 34 ++++++++++++++++++++++++++++++++++
 1 file changed, 34 insertions(+)

diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index 9dbd555166..00aa730050 100644
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -60,6 +60,40 @@ extern char *filename_completion_function();
 #define completion_matches rl_completion_matches
 #endif
 
+/*
+ * By enabling the following definition every completion attempt emits to
+ * stderr the details of every completion prefixed by the source line number
+ * where it is made. You can isolate them from console interaction by
+ * redirecting stderr into a file.
+ */
+#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);
+
+    /*
+     * enclose empty list with brackets since it is an intermediate state
+     * which is immediately followed by a non-empty list.
+     */
+    fprintf(stderr, "%s%d: \"%s\" -> (", list ? "" : "[", line, text);
+    for (int i = 0; list && list[i]; ++i)
+        fprintf(stderr, "%s\"%s\"", i ? ", " : "", list[i]);            
+    fprintf(stderr, ")%s\n", list ? "": "]");
+
+    return list;
+}
+#endif
+
 /* word break characters */
 #define WORD_BREAKS        "\t\n@$><=;|&{() "
 
-- 
2.16.3

From 4bc47d44fa01417d4052634a003293dc4c6f15ce Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <horiguchi.kyotaro@lab.ntt.co.jp>
Date: Mon, 26 Nov 2018 12:06:10 +0900
Subject: [PATCH 2/2] Add context information in tab-completion debug print

Psql shows completion context instead of just the word to complete.
---
 src/bin/psql/tab-complete.c | 48 ++++++++++++++++++++++++++++++++++-----------
 1 file changed, 37 insertions(+), 11 deletions(-)

diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index 00aa730050..3823a181ec 100644
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -74,18 +74,37 @@ extern char *filename_completion_function();
 #endif
 
 #undef completion_matches
-#define completion_matches(t, f) completion_debug(__LINE__, (t), (f))
+#define completion_matches(text, func) \
+    completion_debug(__LINE__, (text), (func), \
+                     previous_words, previous_words_count)
 
-static char **completion_debug(int line,
-                               const char *text, rl_compentry_func_t *func)
+#define DEBUG_NCONTEXT 3
+
+static char **
+completion_debug(int line, const char *text, rl_compentry_func_t *func,
+                 char **previous_words, int previous_words_count)
 {
     char **list = org_completion_matches(text, func);
+    int nwords = DEBUG_NCONTEXT;
 
     /*
      * enclose empty list with brackets since it is an intermediate state
      * which is immediately followed by a non-empty list.
      */
-    fprintf(stderr, "%s%d: \"%s\" -> (", list ? "" : "[", line, text);
+    fprintf(stderr, "%s%d: ", list ? "" : "[", line);
+
+    fputc('(', stderr);
+    if (previous_words_count > 0)
+    {
+        if (previous_words_count > nwords)
+            fprintf(stderr, "...");
+        else
+            nwords = previous_words_count;
+        for (int i = 0 ; i < nwords ; ++i)
+            fprintf(stderr, "%s ", previous_words[nwords - i - 1]);
+    }
+    fprintf(stderr, "[%s]) -> (", text);
+
     for (int i = 0; list && list[i]; ++i)
         fprintf(stderr, "%s\"%s\"", i ? ", " : "", list[i]);            
     fprintf(stderr, ")%s\n", list ? "": "]");
@@ -1046,7 +1065,8 @@ static void append_variable_names(char ***varnames, int *nvars,
                       int *maxvars, const char *varname,
                       const char *prefix, const char *suffix);
 static char **complete_from_variables(const char *text,
-                        const char *prefix, const char *suffix, bool need_value);
+                      const char *prefix, const char *suffix, bool need_value,
+                      char ** previous_words, int previous_words_count);
 static char *complete_from_files(const char *text, int state);
 
 static char *pg_strdup_keyword_case(const char *s, const char *ref);
@@ -1419,11 +1439,14 @@ psql_completion(const char *text, int start, int end)
     else if (text[0] == ':' && text[1] != ':')
     {
         if (text[1] == '\'')
-            matches = complete_from_variables(text, ":'", "'", true);
+            matches = complete_from_variables(text, ":'", "'", true,
+                         previous_words, previous_words_count);
         else if (text[1] == '"')
-            matches = complete_from_variables(text, ":\"", "\"", true);
+            matches = complete_from_variables(text, ":\"", "\"", true,
+                         previous_words, previous_words_count);
         else
-            matches = complete_from_variables(text, ":", "", true);
+            matches = complete_from_variables(text, ":", "", true,
+                         previous_words, previous_words_count);
     }
 
     /* If no previous word, suggest one of the basic sql commands */
@@ -3583,9 +3606,11 @@ psql_completion(const char *text, int start, int end)
             COMPLETE_WITH_CS("single", "double");
     }
     else if (TailMatchesCS("\\unset"))
-        matches = complete_from_variables(text, "", "", true);
+        matches = complete_from_variables(text, "", "", true,
+                         previous_words, previous_words_count);
     else if (TailMatchesCS("\\set"))
-        matches = complete_from_variables(text, "", "", false);
+        matches = complete_from_variables(text, "", "", false,
+                         previous_words, previous_words_count);
     else if (TailMatchesCS("\\set", MatchAny))
     {
         if (TailMatchesCS("AUTOCOMMIT|ON_ERROR_STOP|QUIET|"
@@ -4137,7 +4162,8 @@ append_variable_names(char ***varnames, int *nvars,
  */
 static char **
 complete_from_variables(const char *text, const char *prefix, const char *suffix,
-                        bool need_value)
+                        bool need_value,
+                        char ** previous_words, int previous_words_count)
 {
     char      **matches;
     char      **varnames;
-- 
2.16.3

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.
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.

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.

            regards, tom lane

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.

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.
> 
> 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.

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?

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

On Mon, Nov 26, 2018 at 12:23:16PM +0900, Kyotaro HORIGUCHI wrote:
> Thank you for the comments.
> 
> At Sun, 25 Nov 2018 01:17:27 +0100, David Fetter <david@fetter.org> wrote in <20181125001727.GM958@fetter.org>
> > 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.  Can we get it to print the completion text as well?
> > > I'm imagining something more like
> > > 
> > > 1414: "er "
> > > 1435: ""
> > > 1435: "ab"
> > > 1435: ""
> > > 1431: ""
> > > 
> > > Perhaps there's room as well to print the context that the match looked
> > > at:
> > > 
> > > 1414: "alt" -> "er "
> > > 1435: "alter " -> ""
> > > 1435: "alter t" -> "ab"
> > > 
> > > etc.
> > > 
> > >             regards, tom lane
> > 
> > Is this something along the lines of what you had in mind?
> 
> 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. Since every debug line is followed by a
> line-feed, we don't need the brackets. Since the result is a set
> so Devid's proposal to enclose the set by parentheses looks nice.
> Also, result can contain matches containing word breaks (or even
> an empty string) so quoting make every candidate string more
> distinctive.
> 
> Finally, the attached shows the following debugging output.
> 
> 
> INPUT: alter u<tab>(ser)<tab> <tab>
> OUTPUT:
> 1445: "u" -> ("user", "user", "user mapping for")
> 1445: "user" -> ("user", "user", "user mapping for")
> 3630: "" -> ("", "horiguti", "MAPPING FOR", "pg_execute_server_program", "pg_monitor", "pg_read_all_settings",
"pg_read_all_stats","pg_read_server_files", "pg_signal_backend", "pg_stat_scan_tables", "pg_write_server_files",
"usr1","usr2")
 
> 
> INPUT: create function <tab>
> OUTPUT:
> 3635: "" -> ("", "pg_ndistinct_out", "path_recv", "int4eq", "spg_quad_picksplit", "tsvectorsend", "float8_var_pop",
"opaque_in","interval_le", "macaddr_cmp", "range_gt..(17272 chars)..nge_in")
 
> 
> Wouldn't be a problem with the long line since it is for
> debugging purpose. Of course we can limit the length easily (by
> number of elements).

We could wrap just about anywhere if needed. I found it relatively
easy to puzzle what was going on in my brief tests just by looking at
the potentially-long lines.

> >+    for (int i = 0; list && list[i]; ++i)
> 
> # Are we using C99 for-loop-variable-declarations?

I thought we were using all of it, but of course I can move it
outside.

> An arguable change in this version is enclosing empty result
> lists with brackets, since it is just an intermediate state for
> us.
> 
> [1431: "sael" -> ()]
> 3655: "sael" -> ("")

That's certainly fixable.

> Showing completion context makes things a bit bothersome, since
> complete_from_variables needs to take additional two parameters.
> It is already shown in console conversasion so I'm not sure it's
> worth the trouble.
> 
> 1872: (...table t1 alter [COn]) -> ("CONSTRAINT")
> 
> To be friendly with the CI, the second patch is attached as the
> difference from the first patch.
> 
> 
> Note: This is not registered in this  CF.

Should it be?

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

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

On Tue, Nov 27, 2018 at 06:06:06PM +0900, Kyotaro HORIGUCHI wrote:
> 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.

Am I understanding correctly that currently, -L specifies a separate
log that only shows the output of queries?

If we're using that log, we'll need to rethink how best to describe
the new sub-feature, and possibly rethink how -L should function.
Tom's suggestion about recording both the catalog queries and their
result set/error messages seems in scope.

Speaking of scope, do we want something like \L (analogous to \o) for
this, or would a thing like that be fundamentally distinct?

> psql -L ~/psqldebug.log postgres

Excellent!

Do we still want this as a compile-time option, or does it make more
sense as a run-time option? I'm thinking that with \L, it might make
sense as a run-time option.

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

David Fetter <david@fetter.org> writes:
> Do we still want this as a compile-time option, or does it make more
> sense as a run-time option? I'm thinking that with \L, it might make
> sense as a run-time option.

This seems to me to be strictly a developer debugging feature.

            regards, tom lane

On Tue, Nov 27, 2018 at 03:54:55PM -0500, Tom Lane wrote:
> David Fetter <david@fetter.org> writes:
> > Do we still want this as a compile-time option, or does it make more
> > sense as a run-time option? I'm thinking that with \L, it might make
> > sense as a run-time option.
> 
> This seems to me to be strictly a developer debugging feature.

I would have thought so, but as our tab completion gets bigger--and
it's been steadily doing that--we may find ourselves in a situation
where it'd be handy to debug things in a production environment, with
all the restrictions that implies.

Can we conceive of a circumstance where the check for -L/\L would be
significant?  I've seen people type pretty quickly, but not thus far
fast enough to notice a cache miss.

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

Hello.

At Tue, 27 Nov 2018 22:30:57 +0100, David Fetter <david@fetter.org> wrote in <20181127213057.GT958@fetter.org>
> On Tue, Nov 27, 2018 at 03:54:55PM -0500, Tom Lane wrote:
> > David Fetter <david@fetter.org> writes:
> > > Do we still want this as a compile-time option, or does it make more
> > > sense as a run-time option? I'm thinking that with \L, it might make
> > > sense as a run-time option.
> > 
> > This seems to me to be strictly a developer debugging feature.
> 
> I would have thought so, but as our tab completion gets bigger--and
> it's been steadily doing that--we may find ourselves in a situation
> where it'd be handy to debug things in a production environment, with
> all the restrictions that implies.

I'm not sure how much it is wanted but it's easy to do.  Using
psql variable doesn't seem to make sense since the debug print
(currently) requires session log file, which can be turned on
only at the startup time. '-g' option is available by 0003.

$ psql -gL ~/psql.log  postgres 

> Can we conceive of a circumstance where the check for -L/\L would be
> significant?  I've seen people type pretty quickly, but not thus far
> fast enough to notice a cache miss.

We could switch completion_matches body as necessity using
function poniter, but we aren't so eager for speed here. It is at
most called every time entering tab.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
From eb0599c11c97b4ce2d37fa25f8fbb003e5696e71 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 1/3] 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 7993c05283..747587030b 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

From 5553c084c815aa70b8bef139bac0694740f1dc0e Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <horiguchi.kyotaro@lab.ntt.co.jp>
Date: Wed, 28 Nov 2018 09:36:59 +0900
Subject: [PATCH 2/3] With-context version of tab-completion debug print.

This is another version of tab-completion debug print. This shows
input context instead of just the current word.
---
 src/bin/psql/tab-complete.c | 53 +++++++++++++++++++++++++++++++++++----------
 1 file changed, 41 insertions(+), 12 deletions(-)

diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index 747587030b..704a6879a8 100644
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -73,24 +73,46 @@ extern char *filename_completion_function();
 #endif
 
 #undef completion_matches
-#define completion_matches(t, f) completion_debug(__LINE__, (t), (f))
+#define completion_matches(text, func) \
+    completion_debug(__LINE__, (text), (func), \
+                     previous_words, previous_words_count)
 
-static char **completion_debug(int line,
-                               const char *text, rl_compentry_func_t *func)
+#define DEBUG_NCONTEXT 3
+
+static char **
+completion_debug(int line, const char *text, rl_compentry_func_t *func,
+                 char **previous_words, int previous_words_count)
 {
     char **list = org_completion_matches(text, func);
+    int nwords = DEBUG_NCONTEXT;
 
-    if (pset.logfile)
+    if (pset.debug && 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);
+        fprintf(pset.logfile, "%s:%d: %s(", __FILE__, line, list ? "" : "[");
+
+        /* input context */
+        if (previous_words_count > 0)
+        {
+            if (previous_words_count > nwords)
+                fprintf(pset.logfile, "...");
+            else
+                nwords = previous_words_count;
+            for (int i = 0 ; i < nwords ; ++i)
+                fprintf(pset.logfile, "%s ", previous_words[nwords - i - 1]);
+        }
+
+        fprintf(pset.logfile, "[%s]) -> (", text);
+
+        /* completion result */
         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);
     }
 
@@ -1050,7 +1072,8 @@ static void append_variable_names(char ***varnames, int *nvars,
                       int *maxvars, const char *varname,
                       const char *prefix, const char *suffix);
 static char **complete_from_variables(const char *text,
-                        const char *prefix, const char *suffix, bool need_value);
+                      const char *prefix, const char *suffix, bool need_value,
+                      char ** previous_words, int previous_words_count);
 static char *complete_from_files(const char *text, int state);
 
 static char *pg_strdup_keyword_case(const char *s, const char *ref);
@@ -1423,11 +1446,14 @@ psql_completion(const char *text, int start, int end)
     else if (text[0] == ':' && text[1] != ':')
     {
         if (text[1] == '\'')
-            matches = complete_from_variables(text, ":'", "'", true);
+            matches = complete_from_variables(text, ":'", "'", true,
+                         previous_words, previous_words_count);
         else if (text[1] == '"')
-            matches = complete_from_variables(text, ":\"", "\"", true);
+            matches = complete_from_variables(text, ":\"", "\"", true,
+                         previous_words, previous_words_count);
         else
-            matches = complete_from_variables(text, ":", "", true);
+            matches = complete_from_variables(text, ":", "", true,
+                         previous_words, previous_words_count);
     }
 
     /* If no previous word, suggest one of the basic sql commands */
@@ -3588,9 +3614,11 @@ psql_completion(const char *text, int start, int end)
             COMPLETE_WITH_CS("single", "double");
     }
     else if (TailMatchesCS("\\unset"))
-        matches = complete_from_variables(text, "", "", true);
+        matches = complete_from_variables(text, "", "", true,
+                         previous_words, previous_words_count);
     else if (TailMatchesCS("\\set"))
-        matches = complete_from_variables(text, "", "", false);
+        matches = complete_from_variables(text, "", "", false,
+                         previous_words, previous_words_count);
     else if (TailMatchesCS("\\set", MatchAny))
     {
         if (TailMatchesCS("AUTOCOMMIT|ON_ERROR_STOP|QUIET|"
@@ -4142,7 +4170,8 @@ append_variable_names(char ***varnames, int *nvars,
  */
 static char **
 complete_from_variables(const char *text, const char *prefix, const char *suffix,
-                        bool need_value)
+                        bool need_value,
+                        char ** previous_words, int previous_words_count)
 {
     char      **matches;
     char      **varnames;
-- 
2.16.3

From 951378ff8a3c88162fb2df908b78b11f6b87fbe9 Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <horiguchi.kyotaro@lab.ntt.co.jp>
Date: Wed, 28 Nov 2018 11:24:53 +0900
Subject: [PATCH 3/3] Add psql -g option to control debug print

Adds -g option and related help messages. The code acutually uses the
option is still defaultly inactivated.
---
 src/bin/psql/help.c     |  1 +
 src/bin/psql/settings.h |  1 +
 src/bin/psql/startup.c  | 12 +++++++++++-
 3 files changed, 13 insertions(+), 1 deletion(-)

diff --git a/src/bin/psql/help.c b/src/bin/psql/help.c
index 2e9fe760eb..d5d4c85a9c 100644
--- a/src/bin/psql/help.c
+++ b/src/bin/psql/help.c
@@ -123,6 +123,7 @@ usage(unsigned short int pager)
                       "                           set field separator for unaligned output to zero byte\n"));
     fprintf(output, _("  -0, --record-separator-zero\n"
                       "                           set record separator for unaligned output to zero byte\n"));
+    fprintf(output, _("  -g, --debug              turn on debug print to session log file\n"));
 
     fprintf(output, _("\nConnection options:\n"));
     /* Display default host */
diff --git a/src/bin/psql/settings.h b/src/bin/psql/settings.h
index 176c85afd0..c0bc96bf20 100644
--- a/src/bin/psql/settings.h
+++ b/src/bin/psql/settings.h
@@ -140,6 +140,7 @@ typedef struct _psqlSettings
     const char *prompt3;
     PGVerbosity verbosity;        /* current error verbosity level */
     PGContextVisibility show_context;    /* current context display level */
+    bool        debug;
 } PsqlSettings;
 
 extern PsqlSettings pset;
diff --git a/src/bin/psql/startup.c b/src/bin/psql/startup.c
index e7536a8a06..25f78bcc2c 100644
--- a/src/bin/psql/startup.c
+++ b/src/bin/psql/startup.c
@@ -310,6 +310,12 @@ main(int argc, char *argv[])
             exit(EXIT_FAILURE);
         }
     }
+    else if (pset.debug)
+    {
+        fprintf(stderr, _("%s: no session log file, turn off debug print\n"),
+                pset.progname);
+        pset.debug = false;
+    }
 
     if (!options.no_psqlrc)
         process_psqlrc(argv[0]);
@@ -440,6 +446,7 @@ parse_psql_options(int argc, char *argv[], struct adhoc_opts *options)
         {"no-align", no_argument, NULL, 'A'},
         {"command", required_argument, NULL, 'c'},
         {"dbname", required_argument, NULL, 'd'},
+        {"debug", no_argument, NULL, 'g'},
         {"echo-queries", no_argument, NULL, 'e'},
         {"echo-errors", no_argument, NULL, 'b'},
         {"echo-hidden", no_argument, NULL, 'E'},
@@ -480,7 +487,7 @@ parse_psql_options(int argc, char *argv[], struct adhoc_opts *options)
 
     memset(options, 0, sizeof *options);
 
-    while ((c = getopt_long(argc, argv, "aAbc:d:eEf:F:h:HlL:no:p:P:qR:sStT:U:v:VwWxXz?01",
+    while ((c = getopt_long(argc, argv, "aAbc:d:eEf:F:gh:HlL:no:p:P:qR:sStT:U:v:VwWxXz?01",
                             long_options, &optindex)) != -1)
     {
         switch (c)
@@ -518,6 +525,9 @@ parse_psql_options(int argc, char *argv[], struct adhoc_opts *options)
                                           ACT_FILE,
                                           optarg);
                 break;
+            case 'g':
+                pset.debug = true;
+                break;
             case 'F':
                 pset.popt.topt.fieldSep.separator = pg_strdup(optarg);
                 pset.popt.topt.fieldSep.separator_zero = false;
-- 
2.16.3

Hello.

At Wed, 28 Nov 2018 17:28:39 +0900 (Tokyo Standard Time), Kyotaro HORIGUCHI <horiguchi.kyotaro@lab.ntt.co.jp> wrote in
<20181128.172839.242071562.horiguchi.kyotaro@lab.ntt.co.jp>
> I'm not sure how much it is wanted but it's easy to do.  Using
> psql variable doesn't seem to make sense since the debug print
> (currently) requires session log file, which can be turned on
> only at the startup time. '-g' option is available by 0003.
> 
> $ psql -gL ~/psql.log  postgres 
> 
> > Can we conceive of a circumstance where the check for -L/\L would be
> > significant?  I've seen people type pretty quickly, but not thus far
> > fast enough to notice a cache miss.
> 
> We could switch completion_matches body as necessity using
> function poniter, but we aren't so eager for speed here. It is at
> most called every time entering tab.

So, the new version v6 patch consists of the following two files:

- v6-0001-Tab-copletion-debug-log.patch

  Full-context version. Activated by -DTABCOMPLETION_DEBUG at
  compile time and always emit logs into session log file
  specified -L. The format of a line looks like below.

> tab-complete.c:1870: (...table t1 alter [CO]) -> ("CO", "COLUMN", "CONSTRAINT")


- v6-0002-Add-psql-g-option-to-control-debug-print.patch

  Applies on top of 0001. Code is always active, -g addition to
  -L activates debug print into the log file. If only -g is
  specified it is forcibly turned off.

  > $ psql postgres -g
  > psql: no session log file, turn off debug print
  > psql (12devel)
  > Type "help" for help.

  -g option shows in help message. (perhaps arguable.)

I'll register this to the next CF.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
From ab5f2b27a13ee6fd19e0c496748d1b0d299e86d6 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 1/2] 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 | 82 +++++++++++++++++++++++++++++++++++++++++----
 1 file changed, 75 insertions(+), 7 deletions(-)

diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index fa44b2820b..8addca60a6 100644
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -60,6 +60,67 @@ extern char *filename_completion_function();
 #define completion_matches rl_completion_matches
 #endif
 
+/*
+ * By enabling TABCOMPLETION_DEBUG, every completion attempt is logged in
+ * session log file if any.
+ */
+#ifdef TABCOMPLETION_DEBUG
+
+#undef completion_matches
+#define completion_matches(text, func) \
+    completion_debug(__LINE__, (text), (func), \
+                     previous_words, previous_words_count)
+
+#define DEBUG_NCONTEXT 3
+
+static char **
+completion_debug(int line, const char *text, rl_compentry_func_t *func,
+                 char **previous_words, int previous_words_count)
+{
+#ifdef HAVE_RL_COMPLETION_MATCHES
+    char **list = rl_completion_matches(text, func);
+#else
+    char **list = completion_matches(text, func);
+#endif
+
+    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(", __FILE__, line, list ? "" : "[");
+
+        /* input context */
+        if (previous_words_count > 0)
+        {
+            int nwords = DEBUG_NCONTEXT;
+
+            /* ellipse more than DEBUG_NCONTEXT words back */
+            if (previous_words_count > nwords)
+                fprintf(pset.logfile, "...");
+            else
+                nwords = previous_words_count;
+
+            for (int i = 0 ; i < nwords ; ++i)
+                fprintf(pset.logfile, "%s ", previous_words[nwords - i - 1]);
+        }
+
+        fprintf(pset.logfile, "[%s]) -> (", text);
+
+        /* completion result */
+        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    /* TABCOMPLETION_DEBUG */
+
 /* word break characters */
 #define WORD_BREAKS        "\t\n@$><=;|&{() "
 
@@ -1012,7 +1073,8 @@ static void append_variable_names(char ***varnames, int *nvars,
                       int *maxvars, const char *varname,
                       const char *prefix, const char *suffix);
 static char **complete_from_variables(const char *text,
-                        const char *prefix, const char *suffix, bool need_value);
+                      const char *prefix, const char *suffix, bool need_value,
+                      char ** previous_words, int previous_words_count);
 static char *complete_from_files(const char *text, int state);
 
 static char *pg_strdup_keyword_case(const char *s, const char *ref);
@@ -1385,11 +1447,14 @@ psql_completion(const char *text, int start, int end)
     else if (text[0] == ':' && text[1] != ':')
     {
         if (text[1] == '\'')
-            matches = complete_from_variables(text, ":'", "'", true);
+            matches = complete_from_variables(text, ":'", "'", true,
+                         previous_words, previous_words_count);
         else if (text[1] == '"')
-            matches = complete_from_variables(text, ":\"", "\"", true);
+            matches = complete_from_variables(text, ":\"", "\"", true,
+                         previous_words, previous_words_count);
         else
-            matches = complete_from_variables(text, ":", "", true);
+            matches = complete_from_variables(text, ":", "", true,
+                         previous_words, previous_words_count);
     }
 
     /* If no previous word, suggest one of the basic sql commands */
@@ -3548,9 +3613,11 @@ psql_completion(const char *text, int start, int end)
             COMPLETE_WITH_CS("single", "double");
     }
     else if (TailMatchesCS("\\unset"))
-        matches = complete_from_variables(text, "", "", true);
+        matches = complete_from_variables(text, "", "", true,
+                         previous_words, previous_words_count);
     else if (TailMatchesCS("\\set"))
-        matches = complete_from_variables(text, "", "", false);
+        matches = complete_from_variables(text, "", "", false,
+                         previous_words, previous_words_count);
     else if (TailMatchesCS("\\set", MatchAny))
     {
         if (TailMatchesCS("AUTOCOMMIT|ON_ERROR_STOP|QUIET|"
@@ -4102,7 +4169,8 @@ append_variable_names(char ***varnames, int *nvars,
  */
 static char **
 complete_from_variables(const char *text, const char *prefix, const char *suffix,
-                        bool need_value)
+                        bool need_value,
+                        char ** previous_words, int previous_words_count)
 {
     char      **matches;
     char      **varnames;
-- 
2.16.3

From 5a7dbb38167c226dcc093e5190b0ab4437c138df Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <horiguchi.kyotaro@lab.ntt.co.jp>
Date: Wed, 28 Nov 2018 11:24:53 +0900
Subject: [PATCH 2/2] Add psql -g option to control debug print

Added -g option and related help messages. TABCOMPLETION_DEBUG was
removed and the previously ifdef'ed code became always active.
---
 src/bin/psql/help.c         |  2 +-
 src/bin/psql/settings.h     |  1 +
 src/bin/psql/startup.c      | 12 +++++++++++-
 src/bin/psql/tab-complete.c | 14 +-------------
 4 files changed, 14 insertions(+), 15 deletions(-)

diff --git a/src/bin/psql/help.c b/src/bin/psql/help.c
index 2e9fe760eb..43f224f3e8 100644
--- a/src/bin/psql/help.c
+++ b/src/bin/psql/help.c
@@ -123,7 +123,7 @@ usage(unsigned short int pager)
                       "                           set field separator for unaligned output to zero byte\n"));
     fprintf(output, _("  -0, --record-separator-zero\n"
                       "                           set record separator for unaligned output to zero byte\n"));
-
+    fprintf(output, _("  -g, --debug              turn on debug print to session log file\n"));
     fprintf(output, _("\nConnection options:\n"));
     /* Display default host */
     env = getenv("PGHOST");
diff --git a/src/bin/psql/settings.h b/src/bin/psql/settings.h
index 176c85afd0..c0bc96bf20 100644
--- a/src/bin/psql/settings.h
+++ b/src/bin/psql/settings.h
@@ -140,6 +140,7 @@ typedef struct _psqlSettings
     const char *prompt3;
     PGVerbosity verbosity;        /* current error verbosity level */
     PGContextVisibility show_context;    /* current context display level */
+    bool        debug;
 } PsqlSettings;
 
 extern PsqlSettings pset;
diff --git a/src/bin/psql/startup.c b/src/bin/psql/startup.c
index e7536a8a06..25f78bcc2c 100644
--- a/src/bin/psql/startup.c
+++ b/src/bin/psql/startup.c
@@ -310,6 +310,12 @@ main(int argc, char *argv[])
             exit(EXIT_FAILURE);
         }
     }
+    else if (pset.debug)
+    {
+        fprintf(stderr, _("%s: no session log file, turn off debug print\n"),
+                pset.progname);
+        pset.debug = false;
+    }
 
     if (!options.no_psqlrc)
         process_psqlrc(argv[0]);
@@ -440,6 +446,7 @@ parse_psql_options(int argc, char *argv[], struct adhoc_opts *options)
         {"no-align", no_argument, NULL, 'A'},
         {"command", required_argument, NULL, 'c'},
         {"dbname", required_argument, NULL, 'd'},
+        {"debug", no_argument, NULL, 'g'},
         {"echo-queries", no_argument, NULL, 'e'},
         {"echo-errors", no_argument, NULL, 'b'},
         {"echo-hidden", no_argument, NULL, 'E'},
@@ -480,7 +487,7 @@ parse_psql_options(int argc, char *argv[], struct adhoc_opts *options)
 
     memset(options, 0, sizeof *options);
 
-    while ((c = getopt_long(argc, argv, "aAbc:d:eEf:F:h:HlL:no:p:P:qR:sStT:U:v:VwWxXz?01",
+    while ((c = getopt_long(argc, argv, "aAbc:d:eEf:F:gh:HlL:no:p:P:qR:sStT:U:v:VwWxXz?01",
                             long_options, &optindex)) != -1)
     {
         switch (c)
@@ -518,6 +525,9 @@ parse_psql_options(int argc, char *argv[], struct adhoc_opts *options)
                                           ACT_FILE,
                                           optarg);
                 break;
+            case 'g':
+                pset.debug = true;
+                break;
             case 'F':
                 pset.popt.topt.fieldSep.separator = pg_strdup(optarg);
                 pset.popt.topt.fieldSep.separator_zero = false;
diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index 8addca60a6..e034ff6da2 100644
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -56,17 +56,6 @@
 extern char *filename_completion_function();
 #endif
 
-#ifdef HAVE_RL_COMPLETION_MATCHES
-#define completion_matches rl_completion_matches
-#endif
-
-/*
- * By enabling TABCOMPLETION_DEBUG, every completion attempt is logged in
- * session log file if any.
- */
-#ifdef TABCOMPLETION_DEBUG
-
-#undef completion_matches
 #define completion_matches(text, func) \
     completion_debug(__LINE__, (text), (func), \
                      previous_words, previous_words_count)
@@ -83,7 +72,7 @@ completion_debug(int line, const char *text, rl_compentry_func_t *func,
     char **list = completion_matches(text, func);
 #endif
 
-    if (pset.logfile)
+    if (pset.debug && pset.logfile)
     {
         /* Emit completion log */
 
@@ -119,7 +108,6 @@ completion_debug(int line, const char *text, rl_compentry_func_t *func,
 
     return list;
 }
-#endif    /* TABCOMPLETION_DEBUG */
 
 /* word break characters */
 #define WORD_BREAKS        "\t\n@$><=;|&{() "
-- 
2.16.3

On 13/12/2018 12:07, Kyotaro HORIGUCHI wrote:
> - v6-0002-Add-psql-g-option-to-control-debug-print.patch
> 
>   Applies on top of 0001. Code is always active, -g addition to
>   -L activates debug print into the log file. If only -g is
>   specified it is forcibly turned off.
> 
>   > $ psql postgres -g
>   > psql: no session log file, turn off debug print
>   > psql (12devel)
>   > Type "help" for help.
> 
>   -g option shows in help message. (perhaps arguable.)

I'm not sure that this should be a run-time option.  But we surely don't
want to use up a good short option letter for this.

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Thu, Dec 13, 2018 at 07:43:52PM +0100, Peter Eisentraut wrote:
> On 13/12/2018 12:07, Kyotaro HORIGUCHI wrote:
> > - v6-0002-Add-psql-g-option-to-control-debug-print.patch
> > 
> >   Applies on top of 0001. Code is always active, -g addition to
> >   -L activates debug print into the log file. If only -g is
> >   specified it is forcibly turned off.
> > 
> >   > $ psql postgres -g
> >   > psql: no session log file, turn off debug print
> >   > psql (12devel)
> >   > Type "help" for help.
> > 
> >   -g option shows in help message. (perhaps arguable.)
> 
> I'm not sure that this should be a run-time option.

Given the often onerous givens of installing new software on
production machines, I'm thinking it actually should be.

> But we surely don't want to use up a good short option letter for
> this.

Would it make sense to roll this into the -L option?

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

David Fetter <david@fetter.org> writes:
> On Thu, Dec 13, 2018 at 07:43:52PM +0100, Peter Eisentraut wrote:
>> I'm not sure that this should be a run-time option.

> Given the often onerous givens of installing new software on
> production machines, I'm thinking it actually should be.

What's that have to do with it?  This is a development option,
not a production option.  I don't think it should be in production
builds at all, let alone be invokable via a simple command-line switch.
The notion that ordinary users will want to use it is hogwash ---
we'd be much more likely to get complaints about psql spewing unexpected
output.

            regards, tom lane

On Fri, Dec 14, 2018 at 12:23:17AM -0500, Tom Lane wrote:
> David Fetter <david@fetter.org> writes:
> > On Thu, Dec 13, 2018 at 07:43:52PM +0100, Peter Eisentraut wrote:
> >> I'm not sure that this should be a run-time option.
> 
> > Given the often onerous givens of installing new software on
> > production machines, I'm thinking it actually should be.
> 
> What's that have to do with it?  This is a development option,
> not a production option.

There are problems tab completion, e.g. its catalog queries, could
cause in production that would be difficult to simulate elsewhere.

> I don't think it should be in production builds at all, let alone be
> invokable via a simple command-line switch.  The notion that
> ordinary users will want to use it is hogwash --- we'd be much more
> likely to get complaints about psql spewing unexpected output.

With utmost respect, by the time someone is turning on logging for
psql, they're trying to diagnose a problem. If they're lucky, it's a
problem that's happening during development of psql itself and gets
caught during that process. I don't see "if they're lucky" is a
helpful approach to observability.

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

On 14/12/2018 06:41, David Fetter wrote:
> There are problems tab completion, e.g. its catalog queries, could
> cause in production that would be difficult to simulate elsewhere.

Where are all these reports of tab completion query problems that we are
building elaborate infrastructure to diagnose?

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hi,

On 2018-12-14 08:45:49 +0100, Peter Eisentraut wrote:
> On 14/12/2018 06:41, David Fetter wrote:
> > There are problems tab completion, e.g. its catalog queries, could
> > cause in production that would be difficult to simulate elsewhere.
> 
> Where are all these reports of tab completion query problems that we are
> building elaborate infrastructure to diagnose?

My impression is that this patch ought to marked as rejected?

Greetings,

Andres Freund

On Thu, Jan 31, 2019 at 04:53:49AM -0800, Andres Freund wrote:
> My impression is that this patch ought to marked as rejected?

I may be missing something, but I have the same impression.
--
Michael

On Fri, Feb 01, 2019 at 11:07:02AM +0900, Michael Paquier wrote:
> On Thu, Jan 31, 2019 at 04:53:49AM -0800, Andres Freund wrote:
> > My impression is that this patch ought to marked as rejected?
>
> I may be missing something, but I have the same impression.

Re-reading the thread I think that's too severe.  Tom has mentioned
something interesting here:
https://www.postgresql.org/message-id/f6698.1543206111@sss.pgh.pa.us

So I am marking that stuff as returned with feedback.
--
Michael