git/pkt-line.c
Jeff King fd89433dd0 pkt-line: show packets in async processes as "sideband"
If you run "GIT_TRACE_PACKET=1 git push", you may get
confusing output like (line prefixes omitted for clarity):

   packet:      push< \1000eunpack ok0019ok refs/heads/master0000
   packet:      push< unpack ok
   packet:      push< ok refs/heads/master
   packet:      push< 0000
   packet:      push< 0000

Why do we see the data twice, once apparently wrapped inside
another pkt-line, and once unwrapped? Why do we get two
flush packets?

The answer is that we start an async process to demux the
sideband data. The first entry comes from the sideband
process reading the data, and the second from push itself.
Likewise, the first flush is inside the demuxed packet, and
the second is an actual sideband flush.

We can make this a bit more clear by marking the sideband
demuxer explicitly as "sideband" rather than "push". The
most elegant way to do this would be to simply call
packet_trace_identity() inside the sideband demuxer. But we
can't do that reliably, because it relies on a global
variable, which might be shared if pthreads are in use.

What we really need is thread-local storage for
packet_trace_identity. But the async code does not provide
an interface for that, and it would be messy to add it here
(we'd have to care about pthreads, initializing our
pthread_key_t ahead of time, etc).

So instead, let us just assume that any async process is
handling sideband data. That's always true now, and is
likely to remain so in the future.

The output looks like:

   packet:  sideband< \1000eunpack ok0019ok refs/heads/master0000
   packet:      push< unpack ok
   packet:      push< ok refs/heads/master
   packet:      push< 0000
   packet:  sideband< 0000

Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
2015-09-01 15:11:57 -07:00

251 lines
5.4 KiB
C

#include "cache.h"
#include "pkt-line.h"
#include "run-command.h"
char packet_buffer[LARGE_PACKET_MAX];
static const char *packet_trace_prefix = "git";
static struct trace_key trace_packet = TRACE_KEY_INIT(PACKET);
static struct trace_key trace_pack = TRACE_KEY_INIT(PACKFILE);
void packet_trace_identity(const char *prog)
{
packet_trace_prefix = xstrdup(prog);
}
static const char *get_trace_prefix(void)
{
return in_async() ? "sideband" : packet_trace_prefix;
}
static int packet_trace_pack(const char *buf, unsigned int len, int sideband)
{
if (!sideband) {
trace_verbatim(&trace_pack, buf, len);
return 1;
} else if (len && *buf == '\1') {
trace_verbatim(&trace_pack, buf + 1, len - 1);
return 1;
} else {
/* it's another non-pack sideband */
return 0;
}
}
static void packet_trace(const char *buf, unsigned int len, int write)
{
int i;
struct strbuf out;
static int in_pack, sideband;
if (!trace_want(&trace_packet) && !trace_want(&trace_pack))
return;
if (in_pack) {
if (packet_trace_pack(buf, len, sideband))
return;
} else if (starts_with(buf, "PACK") || starts_with(buf, "\1PACK")) {
in_pack = 1;
sideband = *buf == '\1';
packet_trace_pack(buf, len, sideband);
/*
* Make a note in the human-readable trace that the pack data
* started.
*/
buf = "PACK ...";
len = strlen(buf);
}
if (!trace_want(&trace_packet))
return;
/* +32 is just a guess for header + quoting */
strbuf_init(&out, len+32);
strbuf_addf(&out, "packet: %12s%c ",
get_trace_prefix(), write ? '>' : '<');
/* XXX we should really handle printable utf8 */
for (i = 0; i < len; i++) {
/* suppress newlines */
if (buf[i] == '\n')
continue;
if (buf[i] >= 0x20 && buf[i] <= 0x7e)
strbuf_addch(&out, buf[i]);
else
strbuf_addf(&out, "\\%o", buf[i]);
}
strbuf_addch(&out, '\n');
trace_strbuf(&trace_packet, &out);
strbuf_release(&out);
}
/*
* If we buffered things up above (we don't, but we should),
* we'd flush it here
*/
void packet_flush(int fd)
{
packet_trace("0000", 4, 1);
write_or_die(fd, "0000", 4);
}
void packet_buf_flush(struct strbuf *buf)
{
packet_trace("0000", 4, 1);
strbuf_add(buf, "0000", 4);
}
#define hex(a) (hexchar[(a) & 15])
static void format_packet(struct strbuf *out, const char *fmt, va_list args)
{
static char hexchar[] = "0123456789abcdef";
size_t orig_len, n;
orig_len = out->len;
strbuf_addstr(out, "0000");
strbuf_vaddf(out, fmt, args);
n = out->len - orig_len;
if (n > LARGE_PACKET_MAX)
die("protocol error: impossibly long line");
out->buf[orig_len + 0] = hex(n >> 12);
out->buf[orig_len + 1] = hex(n >> 8);
out->buf[orig_len + 2] = hex(n >> 4);
out->buf[orig_len + 3] = hex(n);
packet_trace(out->buf + orig_len + 4, n - 4, 1);
}
void packet_write(int fd, const char *fmt, ...)
{
static struct strbuf buf = STRBUF_INIT;
va_list args;
strbuf_reset(&buf);
va_start(args, fmt);
format_packet(&buf, fmt, args);
va_end(args);
write_or_die(fd, buf.buf, buf.len);
}
void packet_buf_write(struct strbuf *buf, const char *fmt, ...)
{
va_list args;
va_start(args, fmt);
format_packet(buf, fmt, args);
va_end(args);
}
static int get_packet_data(int fd, char **src_buf, size_t *src_size,
void *dst, unsigned size, int options)
{
ssize_t ret;
if (fd >= 0 && src_buf && *src_buf)
die("BUG: multiple sources given to packet_read");
/* Read up to "size" bytes from our source, whatever it is. */
if (src_buf && *src_buf) {
ret = size < *src_size ? size : *src_size;
memcpy(dst, *src_buf, ret);
*src_buf += ret;
*src_size -= ret;
} else {
ret = read_in_full(fd, dst, size);
if (ret < 0)
die_errno("read error");
}
/* And complain if we didn't get enough bytes to satisfy the read. */
if (ret < size) {
if (options & PACKET_READ_GENTLE_ON_EOF)
return -1;
die("The remote end hung up unexpectedly");
}
return ret;
}
static int packet_length(const char *linelen)
{
int n;
int len = 0;
for (n = 0; n < 4; n++) {
unsigned char c = linelen[n];
len <<= 4;
if (c >= '0' && c <= '9') {
len += c - '0';
continue;
}
if (c >= 'a' && c <= 'f') {
len += c - 'a' + 10;
continue;
}
if (c >= 'A' && c <= 'F') {
len += c - 'A' + 10;
continue;
}
return -1;
}
return len;
}
int packet_read(int fd, char **src_buf, size_t *src_len,
char *buffer, unsigned size, int options)
{
int len, ret;
char linelen[4];
ret = get_packet_data(fd, src_buf, src_len, linelen, 4, options);
if (ret < 0)
return ret;
len = packet_length(linelen);
if (len < 0)
die("protocol error: bad line length character: %.4s", linelen);
if (!len) {
packet_trace("0000", 4, 0);
return 0;
}
len -= 4;
if (len >= size)
die("protocol error: bad line length %d", len);
ret = get_packet_data(fd, src_buf, src_len, buffer, len, options);
if (ret < 0)
return ret;
if ((options & PACKET_READ_CHOMP_NEWLINE) &&
len && buffer[len-1] == '\n')
len--;
buffer[len] = 0;
packet_trace(buffer, len, 0);
return len;
}
static char *packet_read_line_generic(int fd,
char **src, size_t *src_len,
int *dst_len)
{
int len = packet_read(fd, src, src_len,
packet_buffer, sizeof(packet_buffer),
PACKET_READ_CHOMP_NEWLINE);
if (dst_len)
*dst_len = len;
return len ? packet_buffer : NULL;
}
char *packet_read_line(int fd, int *len_p)
{
return packet_read_line_generic(fd, NULL, NULL, len_p);
}
char *packet_read_line_buf(char **src, size_t *src_len, int *dst_len)
{
return packet_read_line_generic(-1, src, src_len, dst_len);
}