threads / patch / 44964

patchgpg-interface: Add some output from gpg when it errors out.

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

## tl;dr

7 messages between Jan 25, 2017 and Jan 26, 2017. Diffs are folded; open one to read it.

replies: 6people: 3as markdown or json

Mike Hommey· Jan 25, 2017, 03:04 UTC · lore
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(-)
Show changes to gpg-interface.c +24 −4
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
Junio C Hamano· Jan 25, 2017, 23:04 UTC · re: Mike Hommey · lore

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

Mike Hommey <mh@glandium.org> writes:
Show 9 quoted lines
> 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.
Mike Hommey· Jan 25, 2017, 23:54 UTC · re: Junio C Hamano · lore

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

On Wed, Jan 25, 2017 at 03:04:38PM -0800, Junio C Hamano wrote:
Show 19 quoted lines
> 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
Junio C Hamano· Jan 26, 2017, 02:37 UTC · re: Mike Hommey · lore

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

Mike Hommey <mh@glandium.org> writes:
Show 14 quoted lines
> 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.
Mike Hommey· Jan 26, 2017, 02:55 UTC · re: Junio C Hamano · lore

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

On Wed, Jan 25, 2017 at 06:37:55PM -0800, Junio C Hamano wrote:
Show 31 quoted lines
> 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
Junio C Hamano· Jan 26, 2017, 18:29 UTC · re: Mike Hommey · lore

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

Mike Hommey <mh@glandium.org> writes:
Show 11 quoted lines
>> 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.

Jeff King· Jan 26, 2017, 05:21 UTC · re: Mike Hommey · lore

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

On Thu, Jan 26, 2017 at 08:54:10AM +0900, Mike Hommey wrote:
Show 5 quoted lines
> > 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:

Show changes to gpg-interface.c +9 −8
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

← back to recent threads