[PATCH] gpg-interface: Add some output from gpg when it errors out.

[PATCH] gpg-interface: Add some output from gpg when it errors out.

[Mike Hommey]

When e.g. signing a tag fails, the user is left with the following
output on their console:
  error: gpg failed to sign the data
  error: unable to sign the tag

There is no indication of what specifically failed, and no indication
how they might solve the problem.

It turns out, gpg still does output some messages without a [GNUPG:]
prefix. The same messages it outputs when run standalone, in fact.

Those messages can be helpful to find what made the gpg command fail.

For instance, after changing my laptop for a new one, I copied my
configs, but had some environment differences that broke gpg.
With this change applied, the output becomes, on this new machine:
  gpg: keyblock resource '/usr/share/keyrings/debian-keyring.gpg': No
such file or directory
  error: gpg failed to sign the data
  error: unable to sign the tag

which makes it clearer what's wrong.

Signed-off-by: Mike Hommey <mh@glandium.org>
---
 gpg-interface.c | 28 ++++++++++++++++++++++++----
 1 file changed, 24 insertions(+), 4 deletions(-)

diff --git a/gpg-interface.c b/gpg-interface.c
index e44cc27da..2768bb307 100644
--- a/gpg-interface.c
+++ b/gpg-interface.c
@@ -149,6 +149,26 @@ const char *get_signing_key(void)
 	return git_committer_info(IDENT_STRICT|IDENT_NO_DATE);
 }
 
+static int pipe_gpg_command(struct child_process *cmd,
+			    const char *in, size_t in_len,
+			    struct strbuf *out, size_t out_hint,
+			    struct strbuf *err, size_t err_hint)
+{
+	int ret = pipe_command(cmd, in, in_len, out, out_hint, err, err_hint);
+	/* Print out any line that doesn't start with [GNUPG:] if the gpg
+	 * command failed. */
+	if (ret) {
+		struct strbuf **err_lines = strbuf_split(err, '\n');
+		for (struct strbuf **line = err_lines; *line; line++) {
+			if (memcmp((*line)->buf, "[GNUPG:]", 8)) {
+				strbuf_rtrim(*line);
+				fprintf(stderr, "%s\n", (*line)->buf);
+			}
+		}
+		strbuf_list_free(err_lines);
+	}
+	return ret;
+}
 /*
  * Create a detached signature for the contents of "buffer" and append
  * it after "signature"; "buffer" and "signature" can be the same
@@ -175,8 +195,8 @@ int sign_buffer(struct strbuf *buffer, struct strbuf *signature, const char *sig
 	 * because gpg exits without reading and then write gets SIGPIPE.
 	 */
 	sigchain_push(SIGPIPE, SIG_IGN);
-	ret = pipe_command(&gpg, buffer->buf, buffer->len,
-			   signature, 1024, &gpg_status, 0);
+	ret = pipe_gpg_command(&gpg, buffer->buf, buffer->len,
+			       signature, 1024, &gpg_status, 0);
 	sigchain_pop(SIGPIPE);
 
 	ret |= !strstr(gpg_status.buf, "\n[GNUPG:] SIG_CREATED ");
@@ -232,8 +252,8 @@ int verify_signed_buffer(const char *payload, size_t payload_size,
 		gpg_status = &buf;
 
 	sigchain_push(SIGPIPE, SIG_IGN);
-	ret = pipe_command(&gpg, payload, payload_size,
-			   gpg_status, 0, gpg_output, 0);
+	ret = pipe_gpg_command(&gpg, payload, payload_size,
+			       gpg_status, 0, gpg_output, 0);
 	sigchain_pop(SIGPIPE);
 
 	delete_tempfile(&temp);
-- 
2.11.0.dirty

Re: [PATCH] gpg-interface: Add some output from gpg when it errors out.

[Junio C Hamano]

Mike Hommey <mh@glandium.org> writes:

> For instance, after changing my laptop for a new one, I copied my
> configs, but had some environment differences that broke gpg.
> With this change applied, the output becomes, on this new machine:
>   gpg: keyblock resource '/usr/share/keyrings/debian-keyring.gpg': No
> such file or directory
>   error: gpg failed to sign the data
>   error: unable to sign the tag
>
> which makes it clearer what's wrong.

Overall I think this is a good thing to do.  Instead of eating the
status output, showing what we got, especially when we know the
command failed, would make the bug-hunting of user's environment
easier, like you showed above.

The only thing in the design that makes me wonder is the filtering
out based on "[GNUPG:]" prefix.  Why do we need to filter them out?

Implementation-wise, I'd be happier if we do not add any new
callsites of strbuf_split(), which is a horrible interface.  But
that is a minor detail.

Thanks.

Re: [PATCH] gpg-interface: Add some output from gpg when it errors out.

[Mike Hommey]

On Wed, Jan 25, 2017 at 03:04:38PM -0800, Junio C Hamano wrote:
> Mike Hommey <mh@glandium.org> writes:
> 
> > For instance, after changing my laptop for a new one, I copied my
> > configs, but had some environment differences that broke gpg.
> > With this change applied, the output becomes, on this new machine:
> >   gpg: keyblock resource '/usr/share/keyrings/debian-keyring.gpg': No
> > such file or directory
> >   error: gpg failed to sign the data
> >   error: unable to sign the tag
> >
> > which makes it clearer what's wrong.
> 
> Overall I think this is a good thing to do.  Instead of eating the
> status output, showing what we got, especially when we know the
> command failed, would make the bug-hunting of user's environment
> easier, like you showed above.
> 
> The only thing in the design that makes me wonder is the filtering
> out based on "[GNUPG:]" prefix.  Why do we need to filter them out?

The [GNUPG:] lines are part of the status-fd protocol. They show details
that don't really seem interesting to the user. In fact, they even
contain the signed message (yes, in my case, it turns out gpg was
actually still signing, but returned an error code...).

For instance, in that failed run above, the entire output looks like:

gpg: keyblock resource '/usr/share/keyrings/debian-keyring.gpg': No
such file or directory
[GNUPG:] ERROR add_keyblock_resource ...
[GNUPG:] KEY_CONSIDERED ...
[GNUPG:] BEGIN_SIGNING H2
[GNUPG:] SIG_CREATED ...

All the [GNUPG:] lines are implementation details that don't seem
particularly useful. A case could be made for the ERROR one, though,
although it's also implementation detail-y.

> Implementation-wise, I'd be happier if we do not add any new
> callsites of strbuf_split(), which is a horrible interface.  But
> that is a minor detail.

What would you suggest otherwise?

Mike

Re: [PATCH] gpg-interface: Add some output from gpg when it errors out.

[Junio C Hamano]

Mike Hommey <mh@glandium.org> writes:

> On Wed, Jan 25, 2017 at 03:04:38PM -0800, Junio C Hamano wrote:
> ...
>> Overall I think this is a good thing to do.  Instead of eating the
>> status output, showing what we got, especially when we know the
>> command failed, would make the bug-hunting of user's environment
>> easier, like you showed above.
>> 
>> The only thing in the design that makes me wonder is the filtering
>> out based on "[GNUPG:]" prefix.  Why do we need to filter them out?
>
> The [GNUPG:] lines are part of the status-fd protocol. They show details
> that don't really seem interesting to the user. In fact, they even
> contain the signed message (yes, in my case, it turns out gpg was
> actually still signing, but returned an error code...).

OK, that detail was what was missing in the proposed log message.
Without that "why do we filter?", readers cannot correctly assess
why it is a good idea.  I wasn't arguing against filtering it; I
just wanted to make sure "git log" readers (and "git show" user
after "git blame" identifies this change in the history) will know
how we decided to filter lines with the prefix.  

With that information recorded in the log (or in-code comment, or
both), if it turns out that some lines with the prefix are useful
(or some other lines without the prefix are not very useful), they
can tweak the filtering criteria as appropriate, with confidence
that they _know_ for what purpose the initial "filter lines with the
prefix" was trying to serve, and their update is still in the same
spirit as the original, only executed better.

Thanks.

Re: [PATCH] gpg-interface: Add some output from gpg when it errors out.

[Mike Hommey]

On Wed, Jan 25, 2017 at 06:37:55PM -0800, Junio C Hamano wrote:
> Mike Hommey <mh@glandium.org> writes:
> 
> > On Wed, Jan 25, 2017 at 03:04:38PM -0800, Junio C Hamano wrote:
> > ...
> >> Overall I think this is a good thing to do.  Instead of eating the
> >> status output, showing what we got, especially when we know the
> >> command failed, would make the bug-hunting of user's environment
> >> easier, like you showed above.
> >> 
> >> The only thing in the design that makes me wonder is the filtering
> >> out based on "[GNUPG:]" prefix.  Why do we need to filter them out?
> >
> > The [GNUPG:] lines are part of the status-fd protocol. They show details
> > that don't really seem interesting to the user. In fact, they even
> > contain the signed message (yes, in my case, it turns out gpg was
> > actually still signing, but returned an error code...).
> 
> OK, that detail was what was missing in the proposed log message.
> Without that "why do we filter?", readers cannot correctly assess
> why it is a good idea.  I wasn't arguing against filtering it; I
> just wanted to make sure "git log" readers (and "git show" user
> after "git blame" identifies this change in the history) will know
> how we decided to filter lines with the prefix.  
> 
> With that information recorded in the log (or in-code comment, or
> both), if it turns out that some lines with the prefix are useful
> (or some other lines without the prefix are not very useful), they
> can tweak the filtering criteria as appropriate, with confidence
> that they _know_ for what purpose the initial "filter lines with the
> prefix" was trying to serve, and their update is still in the same
> spirit as the original, only executed better.

Come to think of it, and considering that mutt happily signs emails in
the same conditions, maybe it would make sense to just ignore gpg return
code as long as there is a SIG_CREATED message...

Mike

Re: [PATCH] gpg-interface: Add some output from gpg when it errors out.

[Jeff King]

On Thu, Jan 26, 2017 at 08:54:10AM +0900, Mike Hommey wrote:

> > Implementation-wise, I'd be happier if we do not add any new
> > callsites of strbuf_split(), which is a horrible interface.  But
> > that is a minor detail.
> 
> What would you suggest otherwise?

Try string_list_split() (or its in_place() variant, since it is probably
OK to hack up the string for your use case). Like this:

diff --git a/gpg-interface.c b/gpg-interface.c
index 2768bb307..051bb7d3e 100644
--- a/gpg-interface.c
+++ b/gpg-interface.c
@@ -158,14 +158,16 @@ static int pipe_gpg_command(struct child_process *cmd,
 	/* Print out any line that doesn't start with [GNUPG:] if the gpg
 	 * command failed. */
 	if (ret) {
-		struct strbuf **err_lines = strbuf_split(err, '\n');
-		for (struct strbuf **line = err_lines; *line; line++) {
-			if (memcmp((*line)->buf, "[GNUPG:]", 8)) {
-				strbuf_rtrim(*line);
-				fprintf(stderr, "%s\n", (*line)->buf);
-			}
+		struct string_list lines = STRING_LIST_INIT_NODUP;
+		int i;
+
+		string_list_split_in_place(&lines, err->buf, '\n', 0);
+		for (i = 0; i < lines.nr; i++) {
+			const char *line = lines.items[i].string;
+			if (!starts_with(line, "[GNUPG:]"))
+				fprintf(stderr, "%s\n", line);
 		}
-		strbuf_list_free(err_lines);
+		string_list_clear(&lines, 0);
 	}
 	return ret;
 }

Note that I also replaced the memcmp with starts_with(). That avoids the
magic number "8". I also suspect your original can read off the end of
the buffer when the line is shorter than 8 characters (e.g., if memcmp
does 64-bit loads).

-Peff

Re: [PATCH] gpg-interface: Add some output from gpg when it errors out.

[Junio C Hamano]

Mike Hommey <mh@glandium.org> writes:

>> With that information recorded in the log (or in-code comment, or
>> both), if it turns out that some lines with the prefix are useful
>> (or some other lines without the prefix are not very useful), they
>> can tweak the filtering criteria as appropriate, with confidence
>> that they _know_ for what purpose the initial "filter lines with the
>> prefix" was trying to serve, and their update is still in the same
>> spirit as the original, only executed better.
>
> Come to think of it, and considering that mutt happily signs emails in
> the same conditions, maybe it would make sense to just ignore gpg return
> code as long as there is a SIG_CREATED message...

I do not think we want to go there.  If GPG reports failure, there
is something funny going on.