[PATCHv3 0/3] Implements the GIT_TRACE_CURL environment variable

[PATCHv3 0/3] Implements the GIT_TRACE_CURL environment variable

[Elia Pinto]

This is the third version but in reality is the complete rewriting of the patches discussed here
(here called V1)

$gmane/290520
$gmane/290521

*Changes from V2
($gmane/291868)

- fix garbage comment in http.c (i am very sorry for that)
- add final '.' to the commit message for imap-send.c and to other commit messages
- typofix double ; in http.c
- merge the nice cleanup and code refactoring of Ramsay Jones (Thank you very much !!)
- squash the previous commit 2/4

*Changes from V1

- introduced GIT_TRACE_CURL variable with its documentation
- changed the name of the temporary variable "i" in "w" in the helper routine
- used the c escape sequences instead of the hex equivalent
- dropped the previous GIT_DEBUG_CURL env var
- curl_dump and curl_trace factored out to a shared implementation
in http.c

Elia Pinto (3):
  git.txt: document the new GIT_TRACE_CURL environment variable
  imap-send.c: introduce the GIT_TRACE_CURL enviroment variable
  http.c: implements the GIT_TRACE_CURL environment variable

 Documentation/git.txt |   8 ++++
 http.c                | 101 +++++++++++++++++++++++++++++++++++++++++++++++++-
 http.h                |   6 +++
 imap-send.c           |   6 +++
 4 files changed, 120 insertions(+), 1 deletion(-)

-- 
2.8.1.383.g31b84cc

[PATCHv3 1/3] git.txt: document the new GIT_TRACE_CURL environment variable

[Elia Pinto]

Describe the purpose of the GIT_TRACE_CURL environment variable.

Helped-by: Torsten Bögershausen <tboegi@web.de>
Helped-by: Ramsay Jones <ramsay@ramsayjones.plus.com>
Helped-by: Junio C Hamano <gitster@pobox.com>
Helped-by: Eric Sunshine <sunshine@sunshineco.com>
Helped-by: Jeff King <peff@peff.net>
Signed-off-by: Elia Pinto <gitter.spiros@gmail.com>
---
 Documentation/git.txt | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/Documentation/git.txt b/Documentation/git.txt
index 8afe349..958db0f 100644
--- a/Documentation/git.txt
+++ b/Documentation/git.txt
@@ -1075,6 +1075,14 @@ of clones and fetches.
 	cloning of shallow repositories.
 	See 'GIT_TRACE' for available trace output options.
 
+'GIT_TRACE_CURL'::
+	Enables a curl full trace dump of all incoming and outgoing data,
+	including descriptive information, of the git transport protocol.
+	This is similar to doing curl --trace-ascii on the command line.
+	This option overrides setting the GIT_CURL_VERBOSE environment
+	variable.
+	See 'GIT_TRACE' for available trace output options.
+
 'GIT_LITERAL_PATHSPECS'::
 	Setting this variable to `1` will cause Git to treat all
 	pathspecs literally, rather than as glob patterns. For example,
-- 
2.8.1.383.g31b84cc

[PATCHv3 2/3] imap-send.c: introduce the GIT_TRACE_CURL enviroment variable

[Elia Pinto]

Permit the use of the GIT_TRACE_CURL environment variable calling
the curl_trace and curl_dump http.c helper routine.

Helped-by: Torsten Bögershausen <tboegi@web.de>
Helped-by: Ramsay Jones <ramsay@ramsayjones.plus.com>
Helped-by: Junio C Hamano <gitster@pobox.com>
Helped-by: Eric Sunshine <sunshine@sunshineco.com>
Helped-by: Jeff King <peff@peff.net>
Signed-off-by: Elia Pinto <gitter.spiros@gmail.com>
---
 imap-send.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/imap-send.c b/imap-send.c
index 938c691..61c6787 100644
--- a/imap-send.c
+++ b/imap-send.c
@@ -1444,6 +1444,12 @@ static CURL *setup_curl(struct imap_server_conf *srvc)
 	if (0 < verbosity || getenv("GIT_CURL_VERBOSE"))
 		curl_easy_setopt(curl, CURLOPT_VERBOSE, 1L);
 
+	if (curl_trace_want()) {
+		curl_easy_setopt(curl, CURLOPT_VERBOSE, 1L);
+		curl_easy_setopt(curl, CURLOPT_DEBUGFUNCTION, curl_trace);
+		curl_easy_setopt(curl, CURLOPT_DEBUGDATA, NULL);
+	}
+
 	return curl;
 }
 
-- 
2.8.1.383.g31b84cc

[PATCHv3 3/3] http.c: implements the GIT_TRACE_CURL environment variable

[Elia Pinto]

Implements the GIT_TRACE_CURL environment variable to allow a
greater degree of detail of GIT_CURL_VERBOSE, in particular
the complete transport header and all the data payload exchanged.
It might be useful if a particular situation could require a more
thorough debugging analysis.

Helped-by: Torsten Bögershausen <tboegi@web.de>
Helped-by: Ramsay Jones <ramsay@ramsayjones.plus.com>
Helped-by: Junio C Hamano <gitster@pobox.com>
Helped-by: Eric Sunshine <sunshine@sunshineco.com>
Helped-by: Jeff King <peff@peff.net>
Signed-off-by: Elia Pinto <gitter.spiros@gmail.com>
---
 http.c | 101 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
 http.h |   6 ++++
 2 files changed, 106 insertions(+), 1 deletion(-)

diff --git a/http.c b/http.c
index 4304b80..507c386 100644
--- a/http.c
+++ b/http.c
@@ -11,6 +11,7 @@
 #include "gettext.h"
 #include "transport.h"
 
+static struct trace_key trace_curl = TRACE_KEY_INIT(CURL);
 #if LIBCURL_VERSION_NUM >= 0x070a08
 long int git_curl_ipresolve = CURL_IPRESOLVE_WHATEVER;
 #else
@@ -464,6 +465,100 @@ static void set_curl_keepalive(CURL *c)
 }
 #endif
 
+
+void curl_dump(const char *text, unsigned char *ptr, size_t size, char nohex)
+{
+	size_t i;
+	size_t w;
+	struct strbuf out = STRBUF_INIT;
+
+	unsigned int width = 0x10;
+
+	if (nohex)
+		/* without the hex output, we can fit more on screen */
+		width = 0x40;
+
+	strbuf_addf(&out, "%s, %10.10ld bytes (0x%8.8lx)\n",
+		text, (long)size, (long)size);
+
+	for (i = 0; i < size; i += width) {
+
+		strbuf_addf(&out, "%4.4lx: ", (long)i);
+
+		if (!nohex) {
+			/* hex not disabled, show it */
+			for (w = 0; w < width; w++)
+				if (i + w < size)
+					strbuf_addf(&out, "%02x ", ptr[i + w]);
+				else
+					strbuf_addf(&out,"   ");
+		}
+
+		for (w = 0; (w < width) && (i + w < size); w++) {
+			/* check for 0D0A; if found, skip past and start a new line of output */
+			if (nohex && (i + w + 1 < size) && ptr[i + w] == '\r'
+			    && ptr[i + w + 1] == '\n') {
+				i += (w + 2 - width);
+				break;
+			}
+			strbuf_addch(&out, (ptr[i + w] >= 0x20)
+				&& (ptr[i + w] < 0x80) ? ptr[i + w] : '.');
+			/* check again for 0D0A, to avoid an extra \n if it's at width */
+			if (nohex && (i + w + 2 < size)
+			    && ptr[i + w + 1] == '\r'
+			    && ptr[i + w + 2] == '\n') {
+				i += (w + 3 - width);
+				break;
+			}
+		}
+		strbuf_addch(&out, '\n');
+		trace_strbuf(&trace_curl, &out);
+		strbuf_release(&out);
+	}
+}
+
+int curl_trace_want(void)
+{
+	return trace_want(&trace_curl);
+}
+
+int curl_trace(CURL *handle, curl_infotype type,
+	     char *data, size_t size, void *userp)
+{
+	const char *text;
+	(void)handle;		/* prevent compiler warning */
+
+	switch (type) {
+	case CURLINFO_TEXT:
+		trace_printf_key(&trace_curl, "== Info: %s", data);
+	default:		/* in case a new one is introduced to shock us */
+		return 0;
+
+	case CURLINFO_HEADER_OUT:
+		text = "=> Send header";
+		break;
+	case CURLINFO_DATA_OUT:
+		text = "=> Send data";
+		break;
+	case CURLINFO_SSL_DATA_OUT:
+		text = "=> Send SSL data";
+		break;
+	case CURLINFO_HEADER_IN:
+		text = "<= Recv header";
+		break;
+	case CURLINFO_DATA_IN:
+		text = "<= Recv data";
+		break;
+	case CURLINFO_SSL_DATA_IN:
+		text = "<= Recv SSL data";
+		break;
+	}
+
+	curl_dump(text, (unsigned char *)data, size, 1);
+	return 0;
+}
+
+
 static CURL *get_curl_handle(void)
 {
 	CURL *result = curl_easy_init();
@@ -563,7 +658,11 @@ static CURL *get_curl_handle(void)
 			"your curl version is too old (>= 7.19.4)");
 #endif
 
-	if (getenv("GIT_CURL_VERBOSE"))
+	if (curl_trace_want()) {
+		curl_easy_setopt(result, CURLOPT_VERBOSE, 1L);
+		curl_easy_setopt(result, CURLOPT_DEBUGFUNCTION, curl_trace);
+		curl_easy_setopt(result, CURLOPT_DEBUGDATA, NULL);
+	} else if (getenv("GIT_CURL_VERBOSE"))
 		curl_easy_setopt(result, CURLOPT_VERBOSE, 1);
 
 	curl_easy_setopt(result, CURLOPT_USERAGENT,
diff --git a/http.h b/http.h
index 4ef4bbd..e452f6a 100644
--- a/http.h
+++ b/http.h
@@ -224,4 +224,10 @@ extern int finish_http_object_request(struct http_object_request *freq);
 extern void abort_http_object_request(struct http_object_request *freq);
 extern void release_http_object_request(struct http_object_request *freq);
 
+/* Debug callback and helper routine for curl_easy_setopt CURLOPT_DEBUGFUNCTION */
+int curl_trace_want(void);
+int curl_trace(CURL *handle, curl_infotype type, char *data, size_t size, void *userp);
+void curl_dump(const char *text, unsigned char *ptr, size_t size, char nohex);
+
+
 #endif /* HTTP_H */
-- 
2.8.1.383.g31b84cc

Re: [PATCHv3 0/3] Implements the GIT_TRACE_CURL environment variable

[Junio C Hamano]

Elia Pinto <gitter.spiros@gmail.com> writes:

> Elia Pinto (3):
>   git.txt: document the new GIT_TRACE_CURL environment variable
>   imap-send.c: introduce the GIT_TRACE_CURL enviroment variable
>   http.c: implements the GIT_TRACE_CURL environment variable

I think 2 & 3 need to be swapped; otherwise 2 would refer to
yet-to-be-invented curl_trace() function, and break the build
without 3, no?

Strictly speaking 1 should come at the end for the same reason, as
setting GIT_TRACE_CURL after seeing that commit would not give users
anything new.

Other than that, I didn't find anything blatantly wrong ;-).  Will
nitpick individual patches later but I expect that it would be
sufficient to locally tweak while queuing without rerolling.

Thanks.

Re: [PATCHv3 3/3] http.c: implements the GIT_TRACE_CURL environment variable

[Junio C Hamano]

Elia Pinto <gitter.spiros@gmail.com> writes:

> Implements the GIT_TRACE_CURL environment variable to allow a

s/Implements/Implement/; speak as if you are giving an order to the
codebase to "be like so".

> greater degree of detail of GIT_CURL_VERBOSE, in particular
> the complete transport header and all the data payload exchanged.
> It might be useful if a particular situation could require a more
> thorough debugging analysis.
>
> Helped-by: Torsten Bögershausen <tboegi@web.de>
> Helped-by: Ramsay Jones <ramsay@ramsayjones.plus.com>
> Helped-by: Junio C Hamano <gitster@pobox.com>
> Helped-by: Eric Sunshine <sunshine@sunshineco.com>
> Helped-by: Jeff King <peff@peff.net>
> Signed-off-by: Elia Pinto <gitter.spiros@gmail.com>
> ---
>  http.c | 101 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
>  http.h |   6 ++++
>  2 files changed, 106 insertions(+), 1 deletion(-)
>
> diff --git a/http.c b/http.c
> index 4304b80..507c386 100644
> --- a/http.c
> +++ b/http.c
> @@ -11,6 +11,7 @@
>  #include "gettext.h"
>  #include "transport.h"
>  
> +static struct trace_key trace_curl = TRACE_KEY_INIT(CURL);
>  #if LIBCURL_VERSION_NUM >= 0x070a08
>  long int git_curl_ipresolve = CURL_IPRESOLVE_WHATEVER;
>  #else
> @@ -464,6 +465,100 @@ static void set_curl_keepalive(CURL *c)
>  }
>  #endif
>  
> +

No need for this extra blank line.

> +void curl_dump(const char *text, unsigned char *ptr, size_t size, char nohex)
> +{
> +	size_t i;
> +	size_t w;

Is it better to narrow the scope of 'w' to the "for (i)" loop?

> +	struct strbuf out = STRBUF_INIT;
> +

No need for this extra blank line.

> +	unsigned int width = 0x10;
> +
> +	if (nohex)
> +		/* without the hex output, we can fit more on screen */
> +		width = 0x40;
> +
> +	strbuf_addf(&out, "%s, %10.10ld bytes (0x%8.8lx)\n",
> +		text, (long)size, (long)size);

Inconsistent indentation that uses only two HT, when existing
lines and other new lines in thsi patch align with HT with SP
to match "(" on the previous line.

> +
> +	for (i = 0; i < size; i += width) {
> +
> +		strbuf_addf(&out, "%4.4lx: ", (long)i);
> +
> +		if (!nohex) {
> +			/* hex not disabled, show it */

Unlike the previous "without the hex, we can fit more", this comment
is probably adds more noise than value.

> +			for (w = 0; w < width; w++)
> +				if (i + w < size)
> +					strbuf_addf(&out, "%02x ", ptr[i + w]);
> +				else
> +					strbuf_addf(&out,"   ");
> +		}
> +
> +		for (w = 0; (w < width) && (i + w < size); w++) {
> +			/* check for 0D0A; if found, skip past and start a new line of output */
> +			if (nohex && (i + w + 1 < size) && ptr[i + w] == '\r'
> +			    && ptr[i + w + 1] == '\n') {
> +				i += (w + 2 - width);
> +				break;
> +			}
> +			strbuf_addch(&out, (ptr[i + w] >= 0x20)
> +				&& (ptr[i + w] < 0x80) ? ptr[i + w] : '.');

Likewise.

> +			/* check again for 0D0A, to avoid an extra \n if it's at width */
> +			if (nohex && (i + w + 2 < size)
> +			    && ptr[i + w + 1] == '\r'
> +			    && ptr[i + w + 2] == '\n') {
> +				i += (w + 3 - width);
> +				break;
> +			}
> +		}

This may only be the matter of taste, but I somehow found this "we
pretend to go width bytes at a time, unless there is a line-break in
which case we may fold before we hit width bytes" and need for
compensating with "w+3-width" here unnecessarily convoluted.  I
wonder if the code becomes clearer if insterad you said "we go one
line at a time, but we may fold the line if it is wider than width
bytes"?

> +		strbuf_addch(&out, '\n');
> +		trace_strbuf(&trace_curl, &out);
> +		strbuf_release(&out);
> +	}
> +}
> +
> +int curl_trace_want(void)
> +{
> +	return trace_want(&trace_curl);
> +}
> +
> +int curl_trace(CURL *handle, curl_infotype type,
> +	     char *data, size_t size, void *userp)

Inconsistent indentation.

> +{
> +	const char *text;
> +	(void)handle;		/* prevent compiler warning */

What compiler warning?  Usually unused parameter (not unused
variable) is not something compilers warn against.

> +	switch (type) {
> +	case CURLINFO_TEXT:
> +		trace_printf_key(&trace_curl, "== Info: %s", data);
> +	default:		/* in case a new one is introduced to shock us */

The comment bothers me.

What is the longer term plan for this function?  Do we expect to
ignore some type of data, or do we expect to show all new type of
data?  If the former, "we ignore unknown types by default" is fine,
and if the latter, it probably makes more sense to show with
text="unknown type"?

> +		return 0;
> +
> +	case CURLINFO_HEADER_OUT:
> +		text = "=> Send header";
> +		break;
> +	case CURLINFO_DATA_OUT:
> +		text = "=> Send data";
> +		break;
> +	case CURLINFO_SSL_DATA_OUT:
> +		text = "=> Send SSL data";
> +		break;
> +	case CURLINFO_HEADER_IN:
> +		text = "<= Recv header";
> +		break;
> +	case CURLINFO_DATA_IN:
> +		text = "<= Recv data";
> +		break;
> +	case CURLINFO_SSL_DATA_IN:
> +		text = "<= Recv SSL data";
> +		break;
> +	}
> +
> +	curl_dump(text, (unsigned char *)data, size, 1);
> +	return 0;
> +}

Re: [PATCHv3 0/3] Implements the GIT_TRACE_CURL environment variable

[Ramsay Jones]

On 20/04/16 19:41, Junio C Hamano wrote:
> Elia Pinto <gitter.spiros@gmail.com> writes:
> 
>> Elia Pinto (3):
>>   git.txt: document the new GIT_TRACE_CURL environment variable
>>   imap-send.c: introduce the GIT_TRACE_CURL enviroment variable
>>   http.c: implements the GIT_TRACE_CURL environment variable
> 
> I think 2 & 3 need to be swapped; otherwise 2 would refer to
> yet-to-be-invented curl_trace() function, and break the build
> without 3, no?
> 
> Strictly speaking 1 should come at the end for the same reason, as
> setting GIT_TRACE_CURL after seeing that commit would not give users
> anything new.

Yep, I was just about to send an email saying that the patches should
be in the exact opposite order! (ie. 1->3 and 3->1) That is *if* you
want to keep them as a series. I would squash them into one patch ...

> Other than that, I didn't find anything blatantly wrong ;-).  Will
> nitpick individual patches later but I expect that it would be
> sufficient to locally tweak while queuing without rerolling.

I have one small issue ... 

ATB,
Ramsay Jones

Re: [PATCHv3 3/3] http.c: implements the GIT_TRACE_CURL environment variable

[Ramsay Jones]

On 20/04/16 19:53, Junio C Hamano wrote:
> Elia Pinto <gitter.spiros@gmail.com> writes:
> 
>> Implements the GIT_TRACE_CURL environment variable to allow a
> 
> s/Implements/Implement/; speak as if you are giving an order to the
> codebase to "be like so".
> 
>> greater degree of detail of GIT_CURL_VERBOSE, in particular
>> the complete transport header and all the data payload exchanged.
>> It might be useful if a particular situation could require a more
>> thorough debugging analysis.
>>
>> Helped-by: Torsten Bögershausen <tboegi@web.de>
>> Helped-by: Ramsay Jones <ramsay@ramsayjones.plus.com>
>> Helped-by: Junio C Hamano <gitster@pobox.com>
>> Helped-by: Eric Sunshine <sunshine@sunshineco.com>
>> Helped-by: Jeff King <peff@peff.net>
>> Signed-off-by: Elia Pinto <gitter.spiros@gmail.com>
>> ---
>>  http.c | 101 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
>>  http.h |   6 ++++
>>  2 files changed, 106 insertions(+), 1 deletion(-)
>>
>> diff --git a/http.c b/http.c
>> index 4304b80..507c386 100644
>> --- a/http.c
>> +++ b/http.c
>> @@ -11,6 +11,7 @@
>>  #include "gettext.h"
>>  #include "transport.h"
>>  
>> +static struct trace_key trace_curl = TRACE_KEY_INIT(CURL);
>>  #if LIBCURL_VERSION_NUM >= 0x070a08
>>  long int git_curl_ipresolve = CURL_IPRESOLVE_WHATEVER;
>>  #else
>> @@ -464,6 +465,100 @@ static void set_curl_keepalive(CURL *c)
>>  }
>>  #endif
>>  
>> +
> 
> No need for this extra blank line.
> 
>> +void curl_dump(const char *text, unsigned char *ptr, size_t size, char nohex)
>> +{
>> +	size_t i;
>> +	size_t w;

As I said in a previous email, curl_dump() should be marked
static here (and remove the declaration from http.h). Unless,
of course, there are plans for future use/calls being added?

ATB,
Ramsay Jones

Re: [PATCHv3 3/3] http.c: implements the GIT_TRACE_CURL environment variable

[Junio C Hamano]

On Wed, Apr 20, 2016 at 12:56 PM, Ramsay Jones
<ramsay@ramsayjones.plus.com> wrote:
>>> +void curl_dump(const char *text, unsigned char *ptr, size_t size, char nohex)
>>> +{
>>> +    size_t i;
>>> +    size_t w;
>
> As I said in a previous email, curl_dump() should be marked
> static here (and remove the declaration from http.h). Unless,
> of course, there are plans for future use/calls being added?

Good point. Thanks.

Re: [PATCHv3 0/3] Implements the GIT_TRACE_CURL environment variable

[Jeff King]

On Wed, Apr 20, 2016 at 08:49:55PM +0100, Ramsay Jones wrote:

> > Strictly speaking 1 should come at the end for the same reason, as
> > setting GIT_TRACE_CURL after seeing that commit would not give users
> > anything new.
> 
> Yep, I was just about to send an email saying that the patches should
> be in the exact opposite order! (ie. 1->3 and 3->1) That is *if* you
> want to keep them as a series. I would squash them into one patch ...

I also wondered about simply squashing them. IMHO it does not help to
split documentation from the addition of a feature. It is not as if we
will take one over the other, and by putting them in the same patch you
do not have to justify one without the other.

> > Other than that, I didn't find anything blatantly wrong ;-).  Will
> > nitpick individual patches later but I expect that it would be
> > sufficient to locally tweak while queuing without rerolling.
> 
> I have one small issue ... 

Overall I'm pleased at the concept, though I find the output a little
funny in places.

Most of the "Send/Recv SSL data" chunks are just line noise. Do people
actually care about seeing them? I can conceive of a case where you are
debugging SSL-level stuff, but I feel like you might do better using
openssl s_client to do so, and not git. Should we stick to more
HTTP-level debugging?

For the actual data packets, the first line gets treated differently
than the rest, and you get:

16:33:38.164068 http.c:515              => Send header, 0000000167 bytes (0x000000a7)
0000: GET /git/git/info/refs?service=git-upload-pack HTTP/1.1
16:33:38.164070 http.c:515              0039: Host: github.com
16:33:38.164072 http.c:515              004b: User-Agent: git/2.8.1.220.g9816fc6
...

for instance. Would it be saner to break the "Send header..." bit and
the first data line into separate trace outputs, and end up with
something more like:

16:33:38.164068 http.c:515              => Send header, 0000000167 bytes (0x000000a7)
16:33:38.164069 http.c:515              0000: GET /git/git/info/refs?service=git-upload-pack HTTP/1.1
16:33:38.164070 http.c:515              0039: Host: github.com
16:33:38.164072 http.c:515              004b: User-Agent: git/2.8.1.220.g9816fc6

Or it might even be nice to prefix each line to indicate it is about
sending a header. That would make it much easier to grep for just
particular 

It might even be nice to prefix _all_ of the lines with some state
information, like "send header". That's more verbose, but makes it much
easier to pick out snippets with line-oriented tools like grep. I often
find myself doing that kind of thing, either to inspect a subset of the
output, or because I want to be able to pull out things like request
content verbatim so I can replay it.

One of my complaints with GIT_CURL_VERBOSE is that it puts your
credentials into the debugging output. Since it looks like we're
parsing through the data anyway, I wonder if we could auto-censor
Authorization headers by default (and then possibly output them if an
extra variable is given). That would make it safe to ask people to show
the output of GIT_CURL_TRACE on the list without having to explain
further.

-Peff