{"thread":{"id":"39602","subject":"[PATCH v2] fetch-pack: optionally save packs to disk","startedAt":"2015-06-11T18:59:28Z","lastAt":"2015-06-26T18:47:03Z","messageCount":33,"participants":["Augie Fackler","Johannes Sixt","Junio C Hamano","Jeff King","Stefan Beller","Duy Nguyen"],"isPatch":true,"patchVersion":2,"patchTotal":null},"messages":[{"id":"263628","messageId":"1434049168-10613-1-git-send-email-augie@google.com","threadId":"39602","inReplyTo":"CAGZ79kaS4utvDbXOo7emmSUH6M-8LY-oA65Ss3PLDkFModkbSg@mail.gmail.com","subject":"[PATCH v2] fetch-pack: optionally save packs to disk","fromName":"Augie Fackler","fromEmail":"augie@google.com","sentAt":"2015-06-11T18:59:28Z","receivedAt":"2015-06-11T18:59:28Z","isPatch":true,"sender":{"key":"augie@google.com","avatar":null},"body":"When developing server software, it's often helpful to save a\npotentially-bogus pack for later analysis. This makes that trivial,\ninstead of painful. This is made a little complicated by the fact that\nin some cases (like cloning from smart-http, but not from a local repo)\nthe fetch code reads the pack header before sending the pack to\nindex-pack (which then gets a --pack_header flag). The included tests\ncover both of these cases.\n\nTo use the new feature, set GIT_SAVE_FETCHED_PACK_TO to a file path and\ngit-fetch will do the rest. The resulting pack can be examined with\ngit-index-pack or similar tools (although if it's corrupt, custom tools\ncan be especially helpful.)\n\nSigned-off-by: Augie Fackler \n---\n Documentation/git.txt | 6 ++++++\n fetch-pack.c | 44 ++++++++++++++++++++++++++++++++++++++++----\n t/t5551-http-fetch-smart.sh | 12 ++++++++++++\n t/t5601-clone.sh | 9 +++++++++\n 4 files changed, 67 insertions(+), 4 deletions(-)\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex 45b64a7..31bc3b5 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -1060,6 +1060,12 @@ GIT_ICASE_PATHSPECS::\n \tan operation has touched every ref (e.g., because you are\n \tcloning a repository to make a backup).\n \n+`GIT_SAVE_FETCHED_PACK_TO`::\n+\tIf set, save any fetched pack to the path in the\n+\tvariable. This is mostly useful if you're writing a custom\n+\tserver and are producing broken packs, as the saved pack won't\n+\tbe cleaned up even if it's corrupt.\n+\n \n Discussion[[Discussion]]\n ------------------------\ndiff --git a/fetch-pack.c b/fetch-pack.c\nindex a912935..fe6ba58 100644\n--- a/fetch-pack.c\n+++ b/fetch-pack.c\n@@ -684,7 +684,7 @@ static int get_pack(struct fetch_pack_args *args,\n \tconst char *argv[22];\n \tchar keep_arg[256];\n \tchar hdr_arg[256];\n-\tconst char **av, *cmd_name;\n+\tconst char **av, *cmd_name, *savepath;\n \tint do_keep = args->keep_pack;\n \tstruct child_process cmd = CHILD_PROCESS_INIT;\n \tint ret;\n@@ -708,9 +708,8 @@ static int get_pack(struct fetch_pack_args *args,\n \tcmd.argv = argv;\n \tav = argv;\n \t*hdr_arg = 0;\n+\tstruct pack_header header;\n \tif (!args->keep_pack && unpack_limit) {\n-\t\tstruct pack_header header;\n-\n \t\tif (read_pack_header(demux.out, &header))\n \t\t\tdie(\"protocol error: bad pack header\");\n \t\tsnprintf(hdr_arg, sizeof(hdr_arg),\n@@ -762,7 +761,44 @@ static int get_pack(struct fetch_pack_args *args,\n \t\t*av++ = \"--strict\";\n \t*av++ = NULL;\n \n-\tcmd.in = demux.out;\n+\tsavepath = getenv(\"GIT_SAVE_FETCHED_PACK_TO\");\n+\tif (savepath) {\n+\t\tstruct child_process cmd2 = CHILD_PROCESS_INIT;\n+\t\tconst char *argv2[22];\n+\t\tint pipefds[2];\n+\t\tint e;\n+\t\tconst char **av2;\n+\t\tcmd2.argv = argv2;\n+\t\tav2 = argv2;\n+\t\t*av2++ = \"tee\";\n+\t\tif (*hdr_arg) {\n+\t\t\t/* hdr_arg being nonempty means we already read the\n+\t\t\t * pack header from demux, so we need to drop a pack\n+\t\t\t * header in place for tee to append to, otherwise\n+\t\t\t * we'll end up with a broken pack on disk.\n+\t\t\t */\n+\t\t\tint fp;\n+\t\t\tstruct sha1file *s;\n+\t\t\tfp = open(savepath, O_CREAT | O_TRUNC | O_WRONLY, 0666);\n+\t\t\ts = sha1fd_throughput(fp, savepath, NULL);\n+\t\t\tsha1write(s, &header, sizeof(header));\n+\t\t\tsha1flush(s);\n+\t\t\tclose(fp);\n+\t\t\t/* -a is supported by both GNU and BSD tee */\n+\t\t\t*av2++ = \"-a\";\n+\t\t}\n+\t\t*av2++ = savepath;\n+\t\t*av2++ = NULL;\n+\t\tcmd2.in = demux.out;\n+\t\te = pipe(pipefds);\n+\t\tif (e != 0)\n+\t\t\tdie(\"couldn't make pipe to save pack\");\n+\t\tcmd2.out = pipefds[1];\n+\t\tcmd.in = pipefds[0];\n+\t\tif (start_command(&cmd2))\n+\t\t\tdie(\"couldn't start tee to save a pack\");\n+\t} else\n+\t\tcmd.in = demux.out;\n \tcmd.git_cmd = 1;\n \tif (start_command(&cmd))\n \t\tdie(\"fetch-pack: unable to fork off %s\", cmd_name);\ndiff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh\nindex 58207d8..bf4640d 100755\n--- a/t/t5551-http-fetch-smart.sh\n+++ b/t/t5551-http-fetch-smart.sh\n@@ -82,11 +82,23 @@ test_expect_success 'fetch changes via http' '\n \ttest_cmp file clone/file\n '\n \n+test_expect_success 'fetch changes via http and save pack' '\n+\techo content >>file &&\n+\tgit commit -a -m two &&\n+\tgit push public &&\n+\tGIT_SAVE_FETCHED_PACK_TO=saved.pack &&\n+\texport GIT_SAVE_FETCHED_PACK_TO &&\n+\t(cd clone && git pull) &&\n+\tgit index-pack clone/saved.pack\n+'\n+\n cat >exp <output 2>&1 &&\n+\ttest -e saved.pack &&\n+\tgit index-pack saved.pack\n+'\n+\n test_expect_success 'clone does not keep pack' '\n \n \trm -fr dst &&\n-- \n2.4.3.369.gda395ba.dirty\n"},{"id":"263649","messageId":"557A7ABA.2000404@kdbg.org","threadId":"39602","inReplyTo":"1434049168-10613-1-git-send-email-augie@google.com","subject":"Re: [PATCH v2] fetch-pack: optionally save packs to disk","fromName":"Johannes Sixt","fromEmail":"j6t@kdbg.org","sentAt":"2015-06-12T06:22:50Z","receivedAt":"2015-06-12T06:22:50Z","isPatch":true,"sender":{"key":"j6t@kdbg.org","avatar":"https://avatars.githubusercontent.com/u/14810926?v=4"},"body":"Am 11.06.2015 um 20:59 schrieb Augie Fackler:\n> When developing server software, it's often helpful to save a\n> potentially-bogus pack for later analysis. This makes that trivial,\n> instead of painful.\n\nWhen you develop server software, shouldn't you test drive the server \nvia the bare metal protocol anyway? That *is* painful, but unavoidable \nbecause you must harden the server against any garbage that a \npotentially malicous client could throw at it. Restricting yourself to a \nwell-behaved client such as fetch-pack is only half the deal.\n\nThat said, I do think that fetch-pack could learn a mode that makes it \neasier to debug the normal behavior of a server (if such a mode is \nmissing currently).\n\nWhat is the problem with the current fetch-pack implementation? Does it \nremove a bogus packfile after download? Does it abort during download \nwhen it detects a broken packfile? Does --keep not do what you need?\n\nInstead of your approach (which forks off tee to dump a copy of the \npackfile), would it not be simpler to add an option --debug-pack \n(probably not the best name) that skips the cleanup step when a broken \npackfile is detected and prints the name of the downloaded packfile?\n\n> diff --git a/fetch-pack.c b/fetch-pack.c\n> index a912935..fe6ba58 100644\n> --- a/fetch-pack.c\n> +++ b/fetch-pack.c\n> @@ -684,7 +684,7 @@ static int get_pack(struct fetch_pack_args *args,\n> \tconst char *argv[22];\n> \tchar keep_arg[256];\n> \tchar hdr_arg[256];\n> -\tconst char **av, *cmd_name;\n> +\tconst char **av, *cmd_name, *savepath;\n> \tint do_keep = args->keep_pack;\n> \tstruct child_process cmd = CHILD_PROCESS_INIT;\n> \tint ret;\n> @@ -708,9 +708,8 @@ static int get_pack(struct fetch_pack_args *args,\n> \tcmd.argv = argv;\n> \tav = argv;\n> \t*hdr_arg = 0;\n> +\tstruct pack_header header;\n> \tif (!args->keep_pack && unpack_limit) {\n> -\t\tstruct pack_header header;\n> -\n> \t\tif (read_pack_header(demux.out, &header))\n> \t\t\tdie(\"protocol error: bad pack header\");\n> \t\tsnprintf(hdr_arg, sizeof(hdr_arg),\n> @@ -762,7 +761,44 @@ static int get_pack(struct fetch_pack_args *args,\n> \t\t*av++ = \"--strict\";\n> \t*av++ = NULL;\n>\n> -\tcmd.in = demux.out;\n> +\tsavepath = getenv(\"GIT_SAVE_FETCHED_PACK_TO\");\n> +\tif (savepath) {\n> +\t\tstruct child_process cmd2 = CHILD_PROCESS_INIT;\n> +\t\tconst char *argv2[22];\n> +\t\tint pipefds[2];\n> +\t\tint e;\n> +\t\tconst char **av2;\n> +\t\tcmd2.argv = argv2;\n> +\t\tav2 = argv2;\n> +\t\t*av2++ = \"tee\";\n> +\t\tif (*hdr_arg) {\n> +\t\t\t/* hdr_arg being nonempty means we already read the\n> +\t\t\t * pack header from demux, so we need to drop a pack\n> +\t\t\t * header in place for tee to append to, otherwise\n> +\t\t\t * we'll end up with a broken pack on disk.\n> +\t\t\t */\n\n\t\t\t/*\n\t\t\t * Write multi-line comments\n\t\t\t * like this (/* on its own line)\n\t\t\t */\n\n> +\t\t\tint fp;\n> +\t\t\tstruct sha1file *s;\n> +\t\t\tfp = open(savepath, O_CREAT | O_TRUNC | O_WRONLY, 0666);\n> +\t\t\ts = sha1fd_throughput(fp, savepath, NULL);\n> +\t\t\tsha1write(s, &header, sizeof(header));\n> +\t\t\tsha1flush(s);\n\nAre you abusing sha1write() and sha1flush() to write a byte sequence to \na file? Is write_in_full() not sufficient?\n\n> +\t\t\tclose(fp);\n> +\t\t\t/* -a is supported by both GNU and BSD tee */\n> +\t\t\t*av2++ = \"-a\";\n> +\t\t}\n> +\t\t*av2++ = savepath;\n> +\t\t*av2++ = NULL;\n> +\t\tcmd2.in = demux.out;\n> +\t\te = pipe(pipefds);\n> +\t\tif (e != 0)\n> +\t\t\tdie(\"couldn't make pipe to save pack\");\n\nstart_command() can create the pipe for you. Just say cmd2.out = -1.\n\n> +\t\tcmd2.out = pipefds[1];\n> +\t\tcmd.in = pipefds[0];\n> +\t\tif (start_command(&cmd2))\n> +\t\t\tdie(\"couldn't start tee to save a pack\");\n\nWhen you call start_command(), you must also call finish_command(). \nstart_command() prints an error message for you; you don't have to do \nthat (the start_command() in the context below is a bad example).\n\n> +\t} else\n> +\t\tcmd.in = demux.out;\n> \tcmd.git_cmd = 1;\n> \tif (start_command(&cmd))\n> \t\tdie(\"fetch-pack: unable to fork off %s\", cmd_name);\n> diff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh\n> index 58207d8..bf4640d 100755\n> --- a/t/t5551-http-fetch-smart.sh\n> +++ b/t/t5551-http-fetch-smart.sh\n> @@ -82,11 +82,23 @@ test_expect_success 'fetch changes via http' '\n> \ttest_cmp file clone/file\n> '\n>\n> +test_expect_success 'fetch changes via http and save pack' '\n> +\techo content >>file &&\n> +\tgit commit -a -m two &&\n> +\tgit push public &&\n> +\tGIT_SAVE_FETCHED_PACK_TO=saved.pack &&\n> +\texport GIT_SAVE_FETCHED_PACK_TO &&\n> +\t(cd clone && git pull) &&\n\nThis can be written as\n\n\t(\n\t\tcd clone &&\n\t\tGIT_SAVE_FETCHED_PACK_TO=../saved.pack git pull\n\t) &&\n\nwithout 'export'.\n\n> +\tgit index-pack clone/saved.pack\n> +'\n> +\n> cat >exp < GET /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n> POST /smart/repo.git/git-upload-pack HTTP/1.1 200\n> GET /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n> POST /smart/repo.git/git-upload-pack HTTP/1.1 200\n> +GET /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n> +POST /smart/repo.git/git-upload-pack HTTP/1.1 200\n> EOF\n> test_expect_success 'used upload-pack service' '\n> \tsed -e \"\n> diff --git a/t/t5601-clone.sh b/t/t5601-clone.sh\n> index bfdaf75..73f9e1c 100755\n> --- a/t/t5601-clone.sh\n> +++ b/t/t5601-clone.sh\n> @@ -40,6 +40,15 @@ test_expect_success C_LOCALE_OUTPUT 'output from clone' '\n> \ttest $(grep Clon output | wc -l) = 1\n> '\n>\n> +test_expect_success 'clone allows saving a pack' '\n> +\trm -fr dst saved.pack &&\n> +\tGIT_SAVE_FETCHED_PACK_TO=saved.pack &&\n> +\texport GIT_SAVE_FETCHED_PACK_TO &&\n> +\tgit clone -n \"file://$(pwd)/src\" dst >output 2>&1 &&\n\nSame here.\n\n> +\ttest -e saved.pack &&\n> +\tgit index-pack saved.pack\n> +'\n> +\n> test_expect_success 'clone does not keep pack' '\n>\n> \trm -fr dst &&\n>\n\n-- Hannes\n"},{"id":"263667","messageId":"xmqqmw05dkxz.fsf@gitster.dls.corp.google.com","threadId":"39602","inReplyTo":"557A7ABA.2000404@kdbg.org","subject":"Re: [PATCH v2] fetch-pack: optionally save packs to disk","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2015-06-12T15:07:36Z","receivedAt":"2015-06-12T15:07:36Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Johannes Sixt writes:\n\n> What is the problem with the current fetch-pack implementation? Does\n> it remove a bogus packfile after download? Does it abort during\n> download when it detects a broken packfile? Does --keep not do what\n> you need?\n\nDoesn't the incoming data still go through the fattening process,\nthough? You will not be able to inspect the byte-for-byte identical\nstream that came out of the server end whose packfile generation\nlogic is suspect.\n\nFor the purpose of debugging your own new server implementation, it\nmight be a better approach to capture the pack as it comes out at\nthe server end, instead of doing it at the fetch-pack end as it\ncomes in. But the approach to add this \"dump\" at the fetch-pack side\nis that it gives us a tool to diagnose problems that come from\nbroken server (re)implementations by other people we cannot debug,\ni.e. \"you are spewing this corrupt pack against this request; here\nis a dump we took to help you go fix your server\".\n\n> Instead of your approach (which forks off tee to dump a copy of the\n> packfile), would it not be simpler to add an option --debug-pack\n> (probably not the best name) that skips the cleanup step when a broken\n> packfile is detected and prints the name of the downloaded packfile?\n\nAs long as we need to debug a thin pack that comes from the other\nend, that approach is not sufficient, I am afraid.\n\nI anticipated that you'd have problem with its use of \"tee\". It\nprobably can do this internally with async interface, perhaps,\ninstead?\n"},{"id":"263674","messageId":"CAHcr6HZsevG+RyRb3+hghgeRhMY7kmcRZBwt1D8JWn0RfSuHSQ@mail.gmail.com","threadId":"39602","inReplyTo":"557A7ABA.2000404@kdbg.org","subject":"Re: [PATCH v2] fetch-pack: optionally save packs to disk","fromName":"Augie Fackler","fromEmail":"augie@google.com","sentAt":"2015-06-12T16:54:24Z","receivedAt":"2015-06-12T16:54:24Z","isPatch":true,"sender":{"key":"augie@google.com","avatar":null},"body":"On Fri, Jun 12, 2015 at 2:22 AM, Johannes Sixt wrote:\n>\n> Am 11.06.2015 um 20:59 schrieb Augie Fackler:\n>>\n>> When developing server software, it's often helpful to save a\n>> potentially-bogus pack for later analysis. This makes that trivial,\n>> instead of painful.\n>\n>\n> When you develop server software, shouldn't you test drive the server via\nthe bare metal protocol anyway? That *is* painful, but unavoidable because\nyou must harden the server against any garbage that a potentially malicous\nclient could throw at it. Restricting yourself to a well-behaved client\nsuch as fetch-pack is only half the deal.\n\n\nWe do that too, but sometimes I've encountered an edge case that's\ntrivially reproduced from an existing repo, and going through the work to\nmanually drive the server is a monumental pain in the butt, and all I\n*really* need is to see the bytes sent from the server to the client. If it\nweren't for SSL-everywhere, I'd probably just do this with wireshark, but\nthat's not the world I live in.\n\n>\n>\n> That said, I do think that fetch-pack could learn a mode that makes it\neasier to debug the normal behavior of a server (if such a mode is missing\ncurrently).\n>\n> What is the problem with the current fetch-pack implementation? Does it\nremove a bogus packfile after download? Does it abort during download when\nit detects a broken packfile? Does --keep not do what you need?\n\n\nfetch-pack doesn't store the pack anywhere - it's sending it to index-pack\n(or unpack-objects) using --stdin, which means that the raw bytes from the\nserver currently are never materialized anywhere on disk. Having index-pack\ndo this is too late, because it's doing things like rewriting the pack\nheader in a potentially new format.\n\n(Junio also covered this well, thanks!)\n\n>\n>\n> Instead of your approach (which forks off tee to dump a copy of the\npackfile), would it not be simpler to add an option --debug-pack (probably\nnot the best name) that skips the cleanup step when a broken packfile is\ndetected and prints the name of the downloaded packfile?\n>\n>\n>> diff --git a/fetch-pack.c b/fetch-pack.c\n>> index a912935..fe6ba58 100644\n>> --- a/fetch-pack.c\n>> +++ b/fetch-pack.c\n>> @@ -684,7 +684,7 @@ static int get_pack(struct fetch_pack_args *args,\n>> const char *argv[22];\n>> char keep_arg[256];\n>> char hdr_arg[256];\n>> - const char **av, *cmd_name;\n>> + const char **av, *cmd_name, *savepath;\n>> int do_keep = args->keep_pack;\n>> struct child_process cmd = CHILD_PROCESS_INIT;\n>> int ret;\n>> @@ -708,9 +708,8 @@ static int get_pack(struct fetch_pack_args *args,\n>> cmd.argv = argv;\n>> av = argv;\n>> *hdr_arg = 0;\n>> + struct pack_header header;\n>> if (!args->keep_pack && unpack_limit) {\n>> - struct pack_header header;\n>> -\n>> if (read_pack_header(demux.out, &header))\n>> die(\"protocol error: bad pack header\");\n>> snprintf(hdr_arg, sizeof(hdr_arg),\n>> @@ -762,7 +761,44 @@ static int get_pack(struct fetch_pack_args *args,\n>> *av++ = \"--strict\";\n>> *av++ = NULL;\n>>\n>> - cmd.in = demux.out;\n>> + savepath = getenv(\"GIT_SAVE_FETCHED_PACK_TO\");\n>> + if (savepath) {\n>> + struct child_process cmd2 = CHILD_PROCESS_INIT;\n>> + const char *argv2[22];\n>> + int pipefds[2];\n>> + int e;\n>> + const char **av2;\n>> + cmd2.argv = argv2;\n>> + av2 = argv2;\n>> + *av2++ = \"tee\";\n>> + if (*hdr_arg) {\n>> + /* hdr_arg being nonempty means we already read\nthe\n>> + * pack header from demux, so we need to drop a\npack\n>> + * header in place for tee to append to,\notherwise\n>> + * we'll end up with a broken pack on disk.\n>> + */\n>\n>\n> /*\n> * Write multi-line comments\n> * like this (/* on its own line)\n> */\n>\n>> + int fp;\n>> + struct sha1file *s;\n>> + fp = open(savepath, O_CREAT | O_TRUNC |\nO_WRONLY, 0666);\n>> + s = sha1fd_throughput(fp, savepath, NULL);\n>> + sha1write(s, &header, sizeof(header));\n>> + sha1flush(s);\n>\n>\n> Are you abusing sha1write() and sha1flush() to write a byte sequence to a\nfile? Is write_in_full() not sufficient?\n\n\nI didn't know about write_in_full. I'm very much *not* familiar with git's\ncodebase - I know the protocols and formats reasonably well, but have\nneeded only occasionally to look at the code. That works, thanks.\n\n>\n>\n>\n>> + close(fp);\n>> + /* -a is supported by both GNU and BSD tee */\n>> + *av2++ = \"-a\";\n>> + }\n>> + *av2++ = savepath;\n>> + *av2++ = NULL;\n>> + cmd2.in = demux.out;\n>> + e = pipe(pipefds);\n>> + if (e != 0)\n>> + die(\"couldn't make pipe to save pack\");\n>\n>\n> start_command() can create the pipe for you. Just say cmd2.out = -1.\n>\n>> + cmd2.out = pipefds[1];\n>> + cmd.in = pipefds[0];\n>> + if (start_command(&cmd2))\n>> + die(\"couldn't start tee to save a pack\");\n>\n>\n> When you call start_command(), you must also call finish_command().\nstart_command() prints an error message for you; you don't have to do that\n(the start_command() in the context below is a bad example).\n\nI looked around, and there are nonzero exit paths from start_command()\nwhich do not print an error and die, so this seems safer. It's also in line\nwith the vast majority of uses of start_command in the codebase, so I left\nthis as-is. If you've got something specific you'd like to see here\ninstead, do let me know (presumably I still need to check the error code\nfrom start_command()...)\n\n>\n>\n>\n>> + } else\n>> + cmd.in = demux.out;\n>> cmd.git_cmd = 1;\n>> if (start_command(&cmd))\n>> die(\"fetch-pack: unable to fork off %s\", cmd_name);\n\n[snip some good comments about test cleanups, all addressed]\n\n>\n> -- Hannes\n>\n\nI'll wait to mail a v3 until at least I know what's going on with\nstart_command() and error checking - perhaps until I get consensus on the\nuse of tee vs something else to save the bytes from the server.\n\nhttps://github.com/durin42/git/commit/save-pack has the current version of\nthe patch if you want to see where it stands now.\n\nThanks for the review!\n\nAugie\n"},{"id":"263675","messageId":"CAHcr6HYv+3z+QLFqwKxVFNOu0Nk4pfWeVhGe_bxu6Fn=wruD8Q@mail.gmail.com","threadId":"39602","inReplyTo":"xmqqmw05dkxz.fsf@gitster.dls.corp.google.com","subject":"Re: [PATCH v2] fetch-pack: optionally save packs to disk","fromName":"Augie Fackler","fromEmail":"augie@google.com","sentAt":"2015-06-12T17:02:43Z","receivedAt":"2015-06-12T17:02:43Z","isPatch":true,"sender":{"key":"augie@google.com","avatar":null},"body":"On Fri, Jun 12, 2015 at 11:07 AM, Junio C Hamano wrote:\n>> What is the problem with the current fetch-pack implementation? Does\n>> it remove a bogus packfile after download? Does it abort during\n>> download when it detects a broken packfile? Does --keep not do what\n>> you need?\n>\n> Doesn't the incoming data still go through the fattening process,\n> though? You will not be able to inspect the byte-for-byte identical\n> stream that came out of the server end whose packfile generation\n> logic is suspect.\n>\n> For the purpose of debugging your own new server implementation, it\n> might be a better approach to capture the pack as it comes out at\n> the server end, instead of doing it at the fetch-pack end as it\n> comes in. But the approach to add this \"dump\" at the fetch-pack side\n> is that it gives us a tool to diagnose problems that come from\n> broken server (re)implementations by other people we cannot debug,\n> i.e. \"you are spewing this corrupt pack against this request; here\n> is a dump we took to help you go fix your server\".\n\n*nod* that's an important part of it. Also, in the small-pull case,\nthe pack data gets sent to unpack-objects anyway, so git is never\nsaving the packfile anywhere in that case (I think it's for a pull of\nless than 100 objects, which characterizes most of my reduced test\ncases for weirdness.)\n\n>\n>> Instead of your approach (which forks off tee to dump a copy of the\n>> packfile), would it not be simpler to add an option --debug-pack\n>> (probably not the best name) that skips the cleanup step when a broken\n>> packfile is detected and prints the name of the downloaded packfile?\n>\n> As long as we need to debug a thin pack that comes from the other\n> end, that approach is not sufficient, I am afraid.\n>\n> I anticipated that you'd have problem with its use of \"tee\". It\n> probably can do this internally with async interface, perhaps,\n> instead?\n\nI'd be happy to make such changes if that's the consensus and someone\ncan give me pointers. My C is admittedly pretty rusty from non-use,\nand I'm not at all familiar with git's codebase, but I'll at least\ntry.\n\nThanks!\n"},{"id":"263682","messageId":"20150612180005.GA9242@peff.net","threadId":"39602","inReplyTo":"xmqqmw05dkxz.fsf@gitster.dls.corp.google.com","subject":"Re: [PATCH v2] fetch-pack: optionally save packs to disk","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-12T18:00:05Z","receivedAt":"2015-06-12T18:00:05Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Jun 12, 2015 at 08:07:36AM -0700, Junio C Hamano wrote:\n\n> Johannes Sixt writes:\n> \n> > What is the problem with the current fetch-pack implementation? Does\n> > it remove a bogus packfile after download? Does it abort during\n> > download when it detects a broken packfile? Does --keep not do what\n> > you need?\n> \n> Doesn't the incoming data still go through the fattening process,\n> though? You will not be able to inspect the byte-for-byte identical\n> stream that came out of the server end whose packfile generation\n> logic is suspect.\n> \n> For the purpose of debugging your own new server implementation, it\n> might be a better approach to capture the pack as it comes out at\n> the server end, instead of doing it at the fetch-pack end as it\n> comes in. But the approach to add this \"dump\" at the fetch-pack side\n> is that it gives us a tool to diagnose problems that come from\n> broken server (re)implementations by other people we cannot debug,\n> i.e. \"you are spewing this corrupt pack against this request; here\n> is a dump we took to help you go fix your server\".\n\nWhen I added GIT_TRACE_PACKET long ago, I had always intended to\nfollow-up with a GIT_TRACE_PACKFILE. The former stops tracing when we\nget to the binary data, but I had intended the latter to store the pure\non-the-wire packfile transmission for later debugging to. I never got\naround to it, but I think it is something like the patch below.\n\nWith:\n\n GIT_TRACE_PACKET=1 GIT_TRACE_PACK=/tmp/foo.pack git clone ...\n\nthis yields a usable pack in /tmp/foo.pack (note that it only kicks in\nwhen packet-tracing is on at all; if we restructure the code a bit, we\ncan remove that limitation).\n\nIn theory it would also work when receiving a pack via push, but I\nthink we actually skip the pkt-line protocol there. We'd have to\nmanually check GIT_TRACE_PACK.\n\nAlso, as a bonus, it means we do not stop tracing completely when we\nstart to receive a sideband pack. The current GIT_TRACE_PACKET code\nmisses any sideband-2 messages that come after we start receiving the\npack.\n\ndiff --git a/pkt-line.c b/pkt-line.c\nindex 187a229..f82871a 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -4,20 +4,39 @@\n char packet_buffer[LARGE_PACKET_MAX];\n static const char *packet_trace_prefix = \"git\";\n static struct trace_key trace_packet = TRACE_KEY_INIT(PACKET);\n+static struct trace_key trace_pack = TRACE_KEY_INIT(PACK);\n \n void packet_trace_identity(const char *prog)\n {\n \tpacket_trace_prefix = xstrdup(prog);\n }\n \n+static int packet_trace_pack(const char *buf, unsigned int len, int sideband)\n+{\n+\tif (!sideband) {\n+\t\ttrace_verbatim(&trace_pack, buf, len);\n+\t\treturn 1;\n+\t} else if (len && *buf == '\\1') {\n+\t\ttrace_verbatim(&trace_pack, buf + 1, len - 1);\n+\t\treturn 1;\n+\t} else {\n+\t\t/* it's another non-pack sideband */\n+\t\treturn 0;\n+\t}\n+}\n+\n static void packet_trace(const char *buf, unsigned int len, int write)\n {\n \tint i;\n \tstruct strbuf out;\n+\tstatic int in_pack, sideband;\n \n \tif (!trace_want(&trace_packet))\n \t\treturn;\n \n+\tif (in_pack && packet_trace_pack(buf, len, sideband))\n+\t\treturn;\n+\n \t/* +32 is just a guess for header + quoting */\n \tstrbuf_init(&out, len+32);\n \n@@ -27,7 +46,9 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n \tif ((len >= 4 && starts_with(buf, \"PACK\")) ||\n \t (len >= 5 && starts_with(buf+1, \"PACK\"))) {\n \t\tstrbuf_addstr(&out, \"PACK ...\");\n-\t\ttrace_disable(&trace_packet);\n+\t\tin_pack = 1;\n+\t\tsideband = *buf == '\\1';\n+\t\tpacket_trace_pack(buf, len, sideband);\n \t}\n \telse {\n \t\t/* XXX we should really handle printable utf8 */\ndiff --git a/trace.c b/trace.c\nindex 3c3bd8f..7393926 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -120,6 +120,13 @@ static int prepare_trace_line(const char *file, int line,\n \treturn 1;\n }\n \n+void trace_verbatim(struct trace_key *key, const void *buf, unsigned len)\n+{\n+\tif (!trace_want(key))\n+\t\treturn;\n+\twrite_or_whine_pipe(get_trace_fd(key), buf, len, err_msg);\n+}\n+\n static void print_trace_line(struct trace_key *key, struct strbuf *buf)\n {\n \tstrbuf_complete_line(buf);\ndiff --git a/trace.h b/trace.h\nindex ae6a332..179b249 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -18,6 +18,7 @@ extern int trace_want(struct trace_key *key);\n extern void trace_disable(struct trace_key *key);\n extern uint64_t getnanotime(void);\n extern void trace_command_performance(const char **argv);\n+extern void trace_verbatim(struct trace_key *key, const void *buf, unsigned len);\n \n #ifndef HAVE_VARIADIC_MACROS\n \n"},{"id":"263701","messageId":"20150612212526.GA25447@peff.net","threadId":"39602","inReplyTo":"20150612180005.GA9242@peff.net","subject":"Re: [PATCH v2] fetch-pack: optionally save packs to disk","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-12T21:25:26Z","receivedAt":"2015-06-12T21:25:26Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Jun 12, 2015 at 02:00:05PM -0400, Jeff King wrote:\n\n> When I added GIT_TRACE_PACKET long ago, I had always intended to\n> follow-up with a GIT_TRACE_PACKFILE. The former stops tracing when we\n> get to the binary data, but I had intended the latter to store the pure\n> on-the-wire packfile transmission for later debugging to. I never got\n> around to it, but I think it is something like the patch below.\n\nHere it is, a bit more cleaned up. I think this is a nice improvement,\nand it does fix some minor issues in the existing GIT_TRACE_PACKET code.\nBut I don't think it will ever work for receive-pack, because we hand\noff the socket directly to index-pack.\n\nI can live with that. But another approach would be to make it easier to\ncapture the stdin of programs with GIT_TRACE, rather than just their\narguments. That makes it more generically usable (e.g., I have hacky\npatches on our servers for capturing \"pack-objects\" input so I can\nreplay expensive fetch requests). As Augie noted, that's not a full\npack-file due to the --pack-header stuff. But given a full trace (which\nhas both the arguments and stdin), you could reconstruct the packfile,\nwhich we could do as a post-processing step.\n\nI dunno. I prefer introducing a nicely generic mechanism, but it would\nprobably be a little more irritating to use in practice.\n\nI guess yet another way to do it would be to put the GIT_TRACE_PACK\nintelligence into index-pack and unpack-objects (rather than\nfetch-pack). Then it at least applies to both the pushing and fetching\nsides.\n\nAnyway, here are the patches I came up with:\n\n [1/3]: pkt-line: simplify starts_with checks in packet tracing\n [2/3]: pkt-line: tighten sideband PACK check when tracing\n [3/3]: pkt-line: support tracing verbatim pack contents\n\n-Peff\n"},{"id":"263703","messageId":"20150612212808.GA25757@peff.net","threadId":"39602","inReplyTo":"20150612212526.GA25447@peff.net","subject":"[PATCH 1/3] pkt-line: simplify starts_with checks in packet tracing","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-12T21:28:08Z","receivedAt":"2015-06-12T21:28:08Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"We carefully check that our pkt buffer has enough characters\nbefore seeing if it starts with \"PACK\". The intent is to\navoid reading random memory if we get a short buffer like\n\"PAC\".\n\nHowever, we know that the traced packets are always\nNUL-terminated. They come from one of these sources:\n\n 1. A string literal.\n\n 2. `format_packet`, which uses a strbuf.\n\n 3. `packet_read`, which defensively NUL-terminates what we\n read.\n\nWe can therefore drop the length checks, as we know we will\nhit the trailing NUL if we have a short input.\n\nSigned-off-by: Jeff King \n---\n pkt-line.c | 3 +--\n 1 file changed, 1 insertion(+), 2 deletions(-)\n\ndiff --git a/pkt-line.c b/pkt-line.c\nindex 187a229..0477d2e 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -24,8 +24,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n \tstrbuf_addf(&out, \"packet: %12s%c \",\n \t\t packet_trace_prefix, write ? '>' : '<');\n \n-\tif ((len >= 4 && starts_with(buf, \"PACK\")) ||\n-\t (len >= 5 && starts_with(buf+1, \"PACK\"))) {\n+\tif (starts_with(buf, \"PACK\") || starts_with(buf + 1, \"PACK\")) {\n \t\tstrbuf_addstr(&out, \"PACK ...\");\n \t\ttrace_disable(&trace_packet);\n \t}\n-- \n2.4.2.752.geeb594a\n"},{"id":"263702","messageId":"20150612212814.GB25757@peff.net","threadId":"39602","inReplyTo":"20150612212526.GA25447@peff.net","subject":"[PATCH 2/3] pkt-line: tighten sideband PACK check when tracing","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-12T21:28:14Z","receivedAt":"2015-06-12T21:28:14Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"To find the start of the pack data, we accept the word PACK\nat the beginning of any sideband channel, even though what\nwe really want is to find the pack data on channel 1. In\npractice this doesn't matter, as sideband-2 messages tend to\nstart with \"error:\" or similar, but it is a good idea to be\nexplicit (especially as we add more code in this area, we\nwill rely on this assumption).\n\nSigned-off-by: Jeff King \n---\n pkt-line.c | 2 +-\n 1 file changed, 1 insertion(+), 1 deletion(-)\n\ndiff --git a/pkt-line.c b/pkt-line.c\nindex 0477d2e..e75af02 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -24,7 +24,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n \tstrbuf_addf(&out, \"packet: %12s%c \",\n \t\t packet_trace_prefix, write ? '>' : '<');\n \n-\tif (starts_with(buf, \"PACK\") || starts_with(buf + 1, \"PACK\")) {\n+\tif (starts_with(buf, \"PACK\") || starts_with(buf, \"\\1PACK\")) {\n \t\tstrbuf_addstr(&out, \"PACK ...\");\n \t\ttrace_disable(&trace_packet);\n \t}\n-- \n2.4.2.752.geeb594a\n"},{"id":"263704","messageId":"20150612212827.GC25757@peff.net","threadId":"39602","inReplyTo":"20150612212526.GA25447@peff.net","subject":"[PATCH 3/3] pkt-line: support tracing verbatim pack contents","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-12T21:28:28Z","receivedAt":"2015-06-12T21:28:28Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"When debugging the pack protocol, it is sometimes useful to\nstore the verbatim pack that we sent or received on the\nwire. Looking at the on-disk result is often not helpful for\na few reasons:\n\n 1. If the operation is a clone, we destroy the repo on\n failure, leaving nothing on disk.\n\n 2. If the pack is small, we unpack it immediately, and the\n full pack never hits the disk.\n\n 3. If we feed the pack to \"index-pack --fix-thin\", the\n resulting pack has the extra delta bases added to it.\n\nWe already have a GIT_TRACE_PACKET mechanism for tracing\npackets. Let's extend it with GIT_TRACE_PACK to dump the\nverbatim packfile.\n\nThere are a few other positive fallouts that come from\nrearranging this code:\n\n - We currently disable the packet trace after seeing the\n PACK header, even though we may get human-readable lines\n on other sidebands; now we include them in the trace.\n\n - We currently try to print \"PACK ...\" in the trace to\n indicate that the packfile has started. But because we\n disable packet tracing, we never printed this line. We\n will now do so.\n\nSigned-off-by: Jeff King \n---\n Documentation/git.txt | 13 +++++++++++-\n pkt-line.c | 59 ++++++++++++++++++++++++++++++++++++++-------------\n t/t5601-clone.sh | 7 ++++++\n trace.c | 7 ++++++\n trace.h | 1 +\n 5 files changed, 71 insertions(+), 16 deletions(-)\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex 45b64a7..8c44d14 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -1000,9 +1000,20 @@ Unsetting the variable, or setting it to empty, \"0\" or\n \tEnables trace messages for all packets coming in or out of a\n \tgiven program. This can help with debugging object negotiation\n \tor other protocol issues. Tracing is turned off at a packet\n-\tstarting with \"PACK\".\n+\tstarting with \"PACK\" (but see 'GIT_TRACE_PACK' below).\n \tSee 'GIT_TRACE' for available trace output options.\n \n+'GIT_TRACE_PACK'::\n+\tEnables tracing of packfiles sent or received by a\n+\tgiven program. Unlike other trace output, this trace is\n+\tverbatim: no headers, and no quoting of binary data. You almost\n+\tcertainly want to direct into a file (e.g.,\n+\t`GIT_TRACE_PACK=/tmp/my.pack`) rather than displaying it on the\n+\tterminal or mixing it with other trace output.\n++\n+Note that this is currently only implemented for the client side\n+of clones and fetches.\n+\n 'GIT_TRACE_PERFORMANCE'::\n \tEnables performance related trace messages, e.g. total execution\n \ttime of each Git command.\ndiff --git a/pkt-line.c b/pkt-line.c\nindex e75af02..2e122c0 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -4,16 +4,51 @@\n char packet_buffer[LARGE_PACKET_MAX];\n static const char *packet_trace_prefix = \"git\";\n static struct trace_key trace_packet = TRACE_KEY_INIT(PACKET);\n+static struct trace_key trace_pack = TRACE_KEY_INIT(PACK);\n \n void packet_trace_identity(const char *prog)\n {\n \tpacket_trace_prefix = xstrdup(prog);\n }\n \n+static int packet_trace_pack(const char *buf, unsigned int len, int sideband)\n+{\n+\tif (!sideband) {\n+\t\ttrace_verbatim(&trace_pack, buf, len);\n+\t\treturn 1;\n+\t} else if (len && *buf == '\\1') {\n+\t\ttrace_verbatim(&trace_pack, buf + 1, len - 1);\n+\t\treturn 1;\n+\t} else {\n+\t\t/* it's another non-pack sideband */\n+\t\treturn 0;\n+\t}\n+}\n+\n static void packet_trace(const char *buf, unsigned int len, int write)\n {\n \tint i;\n \tstruct strbuf out;\n+\tstatic int in_pack, sideband;\n+\n+\tif (!trace_want(&trace_packet) && !trace_want(&trace_pack))\n+\t\treturn;\n+\n+\tif (in_pack) {\n+\t\tif (packet_trace_pack(buf, len, sideband))\n+\t\t\treturn;\n+\t} else if (starts_with(buf, \"PACK\") || starts_with(buf, \"\\1PACK\")) {\n+\t\tin_pack = 1;\n+\t\tsideband = *buf == '\\1';\n+\t\tpacket_trace_pack(buf, len, sideband);\n+\n+\t\t/*\n+\t\t * Make a note in the human-readable trace that the pack data\n+\t\t * started.\n+\t\t */\n+\t\tbuf = \"PACK ...\";\n+\t\tlen = strlen(buf);\n+\t}\n \n \tif (!trace_want(&trace_packet))\n \t\treturn;\n@@ -24,21 +59,15 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n \tstrbuf_addf(&out, \"packet: %12s%c \",\n \t\t packet_trace_prefix, write ? '>' : '<');\n \n-\tif (starts_with(buf, \"PACK\") || starts_with(buf, \"\\1PACK\")) {\n-\t\tstrbuf_addstr(&out, \"PACK ...\");\n-\t\ttrace_disable(&trace_packet);\n-\t}\n-\telse {\n-\t\t/* XXX we should really handle printable utf8 */\n-\t\tfor (i = 0; i < len; i++) {\n-\t\t\t/* suppress newlines */\n-\t\t\tif (buf[i] == '\\n')\n-\t\t\t\tcontinue;\n-\t\t\tif (buf[i] >= 0x20 && buf[i] <= 0x7e)\n-\t\t\t\tstrbuf_addch(&out, buf[i]);\n-\t\t\telse\n-\t\t\t\tstrbuf_addf(&out, \"\\\\%o\", buf[i]);\n-\t\t}\n+\t/* XXX we should really handle printable utf8 */\n+\tfor (i = 0; i < len; i++) {\n+\t\t/* suppress newlines */\n+\t\tif (buf[i] == '\\n')\n+\t\t\tcontinue;\n+\t\tif (buf[i] >= 0x20 && buf[i] <= 0x7e)\n+\t\t\tstrbuf_addch(&out, buf[i]);\n+\t\telse\n+\t\t\tstrbuf_addf(&out, \"\\\\%o\", buf[i]);\n \t}\n \n \tstrbuf_addch(&out, '\\n');\ndiff --git a/t/t5601-clone.sh b/t/t5601-clone.sh\nindex bfdaf75..795ece0 100755\n--- a/t/t5601-clone.sh\n+++ b/t/t5601-clone.sh\n@@ -496,4 +496,11 @@ test_expect_success 'shallow clone locally' '\n \t( cd ddsstt && git fsck )\n '\n \n+test_expect_success 'GIT_TRACE_PACK produces a usable pack' '\n+\trm -rf dst.git &&\n+\tGIT_TRACE_PACK=$PWD/tmp.pack git clone --no-local --bare src dst.git &&\n+\tgit init --bare replay.git &&\n+\tgit -C replay.git index-pack -v --stdin wrote:\n> We carefully check that our pkt buffer has enough characters\n> before seeing if it starts with \"PACK\". The intent is to\n> avoid reading random memory if we get a short buffer like\n> \"PAC\".\n>\n> However, we know that the traced packets are always\n> NUL-terminated. They come from one of these sources:\n>\n> 1. A string literal.\n>\n> 2. `format_packet`, which uses a strbuf.\n>\n> 3. `packet_read`, which defensively NUL-terminates what we\n> read.\n>\n> We can therefore drop the length checks, as we know we will\n> hit the trailing NUL if we have a short input.\n>\n> Signed-off-by: Jeff King \n> ---\n> pkt-line.c | 3 +--\n> 1 file changed, 1 insertion(+), 2 deletions(-)\n>\n> diff --git a/pkt-line.c b/pkt-line.c\n> index 187a229..0477d2e 100644\n> --- a/pkt-line.c\n> +++ b/pkt-line.c\n> @@ -24,8 +24,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n> strbuf_addf(&out, \"packet: %12s%c \",\n> packet_trace_prefix, write ? '>' : '<');\n>\n> - if ((len >= 4 && starts_with(buf, \"PACK\")) ||\n> - (len >= 5 && starts_with(buf+1, \"PACK\"))) {\n\nSo I wondered why there is a possible extra character in front of PACK.\nSo I run the blame machinery and ended up with bbc30f9963 (add\npacket tracing debug code, 2011-02-24), which was also authored\nby you. Where does the extra char come from?\n\nWould it be better for readability to write it as\n\n int offset = 0;\n if (*buf == CHARACTER_STEFAN_IS_WONDERING_ABOUT)\n /* ignore char foo because bar */\n offset++;\n if (starts_with(buf+offset, \"PACK\") {\n ...\n\n\n\n> + if (starts_with(buf, \"PACK\") || starts_with(buf + 1, \"PACK\")) {\n> strbuf_addstr(&out, \"PACK ...\");\n> trace_disable(&trace_packet);\n> }\n> --\n> 2.4.2.752.geeb594a\n>\n"},{"id":"263706","messageId":"CAGZ79kb+DBUqAy45+Bc=MTA6HuGrj9MzyODZGTvOcP_XefAu=A@mail.gmail.com","threadId":"39602","inReplyTo":"20150612212814.GB25757@peff.net","subject":"Re: [PATCH 2/3] pkt-line: tighten sideband PACK check when tracing","fromName":"Stefan Beller","fromEmail":"sbeller@google.com","sentAt":"2015-06-12T21:39:01Z","receivedAt":"2015-06-12T21:39:01Z","isPatch":true,"sender":{"key":"stefanbeller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/455868?v=4"},"body":"On Fri, Jun 12, 2015 at 2:28 PM, Jeff King wrote:\n> To find the start of the pack data, we accept the word PACK\n> at the beginning of any sideband channel, even though what\n> we really want is to find the pack data on channel 1. In\n> practice this doesn't matter, as sideband-2 messages tend to\n> start with \"error:\" or similar, but it is a good idea to be\n> explicit (especially as we add more code in this area, we\n> will rely on this assumption).\n>\n> Signed-off-by: Jeff King \n> ---\n> pkt-line.c | 2 +-\n> 1 file changed, 1 insertion(+), 1 deletion(-)\n>\n> diff --git a/pkt-line.c b/pkt-line.c\n> index 0477d2e..e75af02 100644\n> --- a/pkt-line.c\n> +++ b/pkt-line.c\n> @@ -24,7 +24,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n> strbuf_addf(&out, \"packet: %12s%c \",\n> packet_trace_prefix, write ? '>' : '<');\n>\n> - if (starts_with(buf, \"PACK\") || starts_with(buf + 1, \"PACK\")) {\n> + if (starts_with(buf, \"PACK\") || starts_with(buf, \"\\1PACK\")) {\n\nThis answers the question on the previous patch actually, maybe the\ncode could be improved to\n\n if (is_sidechannel(out, ...)\n out++;\n if (starts_with(buf, \"PACK\") {\n ...\n\n\n> strbuf_addstr(&out, \"PACK ...\");\n> trace_disable(&trace_packet);\n> }\n> --\n> 2.4.2.752.geeb594a\n>\n"},{"id":"263707","messageId":"20150612214152.GA26217@peff.net","threadId":"39602","inReplyTo":"CAGZ79kb+DBUqAy45+Bc=MTA6HuGrj9MzyODZGTvOcP_XefAu=A@mail.gmail.com","subject":"Re: [PATCH 2/3] pkt-line: tighten sideband PACK check when tracing","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-12T21:41:52Z","receivedAt":"2015-06-12T21:41:52Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Jun 12, 2015 at 02:39:01PM -0700, Stefan Beller wrote:\n\n> > - if (starts_with(buf, \"PACK\") || starts_with(buf + 1, \"PACK\")) {\n> > + if (starts_with(buf, \"PACK\") || starts_with(buf, \"\\1PACK\")) {\n> \n> This answers the question on the previous patch actually, maybe the\n> code could be improved to\n> \n> if (is_sidechannel(out, ...)\n> out++;\n> if (starts_with(buf, \"PACK\") {\n> ...\n\nIf it's not a PACK, then we don't want to skip past the side-channel\ncharacter (we show it as part of the trace).\n\nHopefully the end result after patch 3 reads well, as it sets an\nexplicit \"sideband\" flag.\n\n-Peff\n"},{"id":"263708","messageId":"CAGZ79kZs8snjB1Yi+Z3KctjHZN6VM6nRcHZ5Aa-iODcFxa7Gfg@mail.gmail.com","threadId":"39602","inReplyTo":"20150612214152.GA26217@peff.net","subject":"Re: [PATCH 2/3] pkt-line: tighten sideband PACK check when tracing","fromName":"Stefan Beller","fromEmail":"sbeller@google.com","sentAt":"2015-06-12T21:43:19Z","receivedAt":"2015-06-12T21:43:19Z","isPatch":true,"sender":{"key":"stefanbeller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/455868?v=4"},"body":"On Fri, Jun 12, 2015 at 2:41 PM, Jeff King wrote:\n> On Fri, Jun 12, 2015 at 02:39:01PM -0700, Stefan Beller wrote:\n>\n>> > - if (starts_with(buf, \"PACK\") || starts_with(buf + 1, \"PACK\")) {\n>> > + if (starts_with(buf, \"PACK\") || starts_with(buf, \"\\1PACK\")) {\n>>\n>> This answers the question on the previous patch actually, maybe the\n>> code could be improved to\n>>\n>> if (is_sidechannel(out, ...)\n>> out++;\n>> if (starts_with(buf, \"PACK\") {\n>> ...\n>\n> If it's not a PACK, then we don't want to skip past the side-channel\n> character (we show it as part of the trace).\n>\n> Hopefully the end result after patch 3 reads well, as it sets an\n> explicit \"sideband\" flag.\n\nYeah, I just looked at that, and realized I should not worry about\nthese first two patches\nas the line is deleted anyway. :( Writing faster than I can think.\n\n>\n> -Peff\n"},{"id":"263946","messageId":"CAHcr6HYvVR4uTmtegWHK0h+v_aVs4JVLsSwvjthGY3pb=-Q0yQ@mail.gmail.com","threadId":"39602","inReplyTo":"20150612212827.GC25757@peff.net","subject":"Re: [PATCH 3/3] pkt-line: support tracing verbatim pack contents","fromName":"Augie Fackler","fromEmail":"augie@google.com","sentAt":"2015-06-16T15:38:41Z","receivedAt":"2015-06-16T15:38:41Z","isPatch":true,"sender":{"key":"augie@google.com","avatar":null},"body":"On Fri, Jun 12, 2015 at 5:28 PM, Jeff King wrote:\n> When debugging the pack protocol, it is sometimes useful to\n> store the verbatim pack that we sent or received on the\n> wire. Looking at the on-disk result is often not helpful for\n> a few reasons:\n>\n> 1. If the operation is a clone, we destroy the repo on\n> failure, leaving nothing on disk.\n>\n> 2. If the pack is small, we unpack it immediately, and the\n> full pack never hits the disk.\n>\n> 3. If we feed the pack to \"index-pack --fix-thin\", the\n> resulting pack has the extra delta bases added to it.\n>\n> We already have a GIT_TRACE_PACKET mechanism for tracing\n> packets. Let's extend it with GIT_TRACE_PACK to dump the\n> verbatim packfile.\n\nFWIW, this also works for me - I have no preference between my patches\nand Jeff's. I suspect yours are much better given that you have a clue\nabout git internals ;).\n\nOne bit of feedback is that it might be worth mentioning (though I\ndon't feel strongly) that GIT_TRACE_PACK works with or without\nGIT_TRACE_PACKET - that wasn't immediately obvious to me, but it makes\nsense once I read the code.\n\nThanks!\n\n>\n> There are a few other positive fallouts that come from\n> rearranging this code:\n>\n> - We currently disable the packet trace after seeing the\n> PACK header, even though we may get human-readable lines\n> on other sidebands; now we include them in the trace.\n>\n> - We currently try to print \"PACK ...\" in the trace to\n> indicate that the packfile has started. But because we\n> disable packet tracing, we never printed this line. We\n> will now do so.\n>\n> Signed-off-by: Jeff King \n> ---\n> Documentation/git.txt | 13 +++++++++++-\n> pkt-line.c | 59 ++++++++++++++++++++++++++++++++++++++-------------\n> t/t5601-clone.sh | 7 ++++++\n> trace.c | 7 ++++++\n> trace.h | 1 +\n> 5 files changed, 71 insertions(+), 16 deletions(-)\n>\n> diff --git a/Documentation/git.txt b/Documentation/git.txt\n> index 45b64a7..8c44d14 100644\n> --- a/Documentation/git.txt\n> +++ b/Documentation/git.txt\n> @@ -1000,9 +1000,20 @@ Unsetting the variable, or setting it to empty, \"0\" or\n> Enables trace messages for all packets coming in or out of a\n> given program. This can help with debugging object negotiation\n> or other protocol issues. Tracing is turned off at a packet\n> - starting with \"PACK\".\n> + starting with \"PACK\" (but see 'GIT_TRACE_PACK' below).\n> See 'GIT_TRACE' for available trace output options.\n>\n> +'GIT_TRACE_PACK'::\n> + Enables tracing of packfiles sent or received by a\n> + given program. Unlike other trace output, this trace is\n> + verbatim: no headers, and no quoting of binary data. You almost\n> + certainly want to direct into a file (e.g.,\n> + `GIT_TRACE_PACK=/tmp/my.pack`) rather than displaying it on the\n> + terminal or mixing it with other trace output.\n> ++\n> +Note that this is currently only implemented for the client side\n> +of clones and fetches.\n> +\n> 'GIT_TRACE_PERFORMANCE'::\n> Enables performance related trace messages, e.g. total execution\n> time of each Git command.\n> diff --git a/pkt-line.c b/pkt-line.c\n> index e75af02..2e122c0 100644\n> --- a/pkt-line.c\n> +++ b/pkt-line.c\n> @@ -4,16 +4,51 @@\n> char packet_buffer[LARGE_PACKET_MAX];\n> static const char *packet_trace_prefix = \"git\";\n> static struct trace_key trace_packet = TRACE_KEY_INIT(PACKET);\n> +static struct trace_key trace_pack = TRACE_KEY_INIT(PACK);\n>\n> void packet_trace_identity(const char *prog)\n> {\n> packet_trace_prefix = xstrdup(prog);\n> }\n>\n> +static int packet_trace_pack(const char *buf, unsigned int len, int sideband)\n> +{\n> + if (!sideband) {\n> + trace_verbatim(&trace_pack, buf, len);\n> + return 1;\n> + } else if (len && *buf == '\\1') {\n> + trace_verbatim(&trace_pack, buf + 1, len - 1);\n> + return 1;\n> + } else {\n> + /* it's another non-pack sideband */\n> + return 0;\n> + }\n> +}\n> +\n> static void packet_trace(const char *buf, unsigned int len, int write)\n> {\n> int i;\n> struct strbuf out;\n> + static int in_pack, sideband;\n> +\n> + if (!trace_want(&trace_packet) && !trace_want(&trace_pack))\n> + return;\n> +\n> + if (in_pack) {\n> + if (packet_trace_pack(buf, len, sideband))\n> + return;\n> + } else if (starts_with(buf, \"PACK\") || starts_with(buf, \"\\1PACK\")) {\n> + in_pack = 1;\n> + sideband = *buf == '\\1';\n> + packet_trace_pack(buf, len, sideband);\n> +\n> + /*\n> + * Make a note in the human-readable trace that the pack data\n> + * started.\n> + */\n> + buf = \"PACK ...\";\n> + len = strlen(buf);\n> + }\n>\n> if (!trace_want(&trace_packet))\n> return;\n> @@ -24,21 +59,15 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n> strbuf_addf(&out, \"packet: %12s%c \",\n> packet_trace_prefix, write ? '>' : '<');\n>\n> - if (starts_with(buf, \"PACK\") || starts_with(buf, \"\\1PACK\")) {\n> - strbuf_addstr(&out, \"PACK ...\");\n> - trace_disable(&trace_packet);\n> - }\n> - else {\n> - /* XXX we should really handle printable utf8 */\n> - for (i = 0; i < len; i++) {\n> - /* suppress newlines */\n> - if (buf[i] == '\\n')\n> - continue;\n> - if (buf[i] >= 0x20 && buf[i] <= 0x7e)\n> - strbuf_addch(&out, buf[i]);\n> - else\n> - strbuf_addf(&out, \"\\\\%o\", buf[i]);\n> - }\n> + /* XXX we should really handle printable utf8 */\n> + for (i = 0; i < len; i++) {\n> + /* suppress newlines */\n> + if (buf[i] == '\\n')\n> + continue;\n> + if (buf[i] >= 0x20 && buf[i] <= 0x7e)\n> + strbuf_addch(&out, buf[i]);\n> + else\n> + strbuf_addf(&out, \"\\\\%o\", buf[i]);\n> }\n>\n> strbuf_addch(&out, '\\n');\n> diff --git a/t/t5601-clone.sh b/t/t5601-clone.sh\n> index bfdaf75..795ece0 100755\n> --- a/t/t5601-clone.sh\n> +++ b/t/t5601-clone.sh\n> @@ -496,4 +496,11 @@ test_expect_success 'shallow clone locally' '\n> ( cd ddsstt && git fsck )\n> '\n>\n> +test_expect_success 'GIT_TRACE_PACK produces a usable pack' '\n> + rm -rf dst.git &&\n> + GIT_TRACE_PACK=$PWD/tmp.pack git clone --no-local --bare src dst.git &&\n> + git init --bare replay.git &&\n> + git -C replay.git index-pack -v --stdin +'\n> +\n> test_done\n> diff --git a/trace.c b/trace.c\n> index 3c3bd8f..7393926 100644\n> --- a/trace.c\n> +++ b/trace.c\n> @@ -120,6 +120,13 @@ static int prepare_trace_line(const char *file, int line,\n> return 1;\n> }\n>\n> +void trace_verbatim(struct trace_key *key, const void *buf, unsigned len)\n> +{\n> + if (!trace_want(key))\n> + return;\n> + write_or_whine_pipe(get_trace_fd(key), buf, len, err_msg);\n> +}\n> +\n> static void print_trace_line(struct trace_key *key, struct strbuf *buf)\n> {\n> strbuf_complete_line(buf);\n> diff --git a/trace.h b/trace.h\n> index ae6a332..179b249 100644\n> --- a/trace.h\n> +++ b/trace.h\n> @@ -18,6 +18,7 @@ extern int trace_want(struct trace_key *key);\n> extern void trace_disable(struct trace_key *key);\n> extern uint64_t getnanotime(void);\n> extern void trace_command_performance(const char **argv);\n> +extern void trace_verbatim(struct trace_key *key, const void *buf, unsigned len);\n>\n> #ifndef HAVE_VARIADIC_MACROS\n>\n> --\n> 2.4.2.752.geeb594a\n"},{"id":"263953","messageId":"xmqqvben6214.fsf@gitster.dls.corp.google.com","threadId":"39602","inReplyTo":"CAHcr6HYvVR4uTmtegWHK0h+v_aVs4JVLsSwvjthGY3pb=-Q0yQ@mail.gmail.com","subject":"Re: [PATCH 3/3] pkt-line: support tracing verbatim pack contents","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2015-06-16T16:39:19Z","receivedAt":"2015-06-16T16:39:19Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Augie Fackler writes:\n\n> On Fri, Jun 12, 2015 at 5:28 PM, Jeff King wrote:\n>> When debugging the pack protocol, it is sometimes useful to\n>> store the verbatim pack that we sent or received on the\n>> wire. Looking at the on-disk result is often not helpful for\n>> a few reasons:\n>>\n>> 1. If the operation is a clone, we destroy the repo on\n>> failure, leaving nothing on disk.\n>>\n>> 2. If the pack is small, we unpack it immediately, and the\n>> full pack never hits the disk.\n>>\n>> 3. If we feed the pack to \"index-pack --fix-thin\", the\n>> resulting pack has the extra delta bases added to it.\n>>\n>> We already have a GIT_TRACE_PACKET mechanism for tracing\n>> packets. Let's extend it with GIT_TRACE_PACK to dump the\n>> verbatim packfile.\n>\n> FWIW, this also works for me - I have no preference between my patches\n> and Jeff's. I suspect yours are much better given that you have a clue\n> about git internals ;).\n>\n> One bit of feedback is that it might be worth mentioning (though I\n> don't feel strongly) that GIT_TRACE_PACK works with or without\n> GIT_TRACE_PACKET - that wasn't immediately obvious to me, but it makes\n> sense once I read the code.\n>\n> Thanks!\n\nThanks, both. I think this series makes sense.\n\nAs to the documentation, I have a feeling that, unless the reader\nand/or the user intimately knows that TRACE_PACK is implemented by\nhooking into the same mechanism that TRACE_PACKET needs to, s/he\nwould not even wonder if TRACE_PACKET needs to be enabled when\nasking for TRACE_PACK. Yes, one is a proper substring of the other,\nbut the similarity between the two stops there. While I do not\nthink it would hurt very much to mention that they are independent,\nI have a slight suspicion that it might make it more likely to get\nuser confused.\n"},{"id":"263954","messageId":"20150616164310.GA18667@peff.net","threadId":"39602","inReplyTo":"xmqqvben6214.fsf@gitster.dls.corp.google.com","subject":"Re: [PATCH 3/3] pkt-line: support tracing verbatim pack contents","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-16T16:43:11Z","receivedAt":"2015-06-16T16:43:11Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Jun 16, 2015 at 09:39:19AM -0700, Junio C Hamano wrote:\n\n> As to the documentation, I have a feeling that, unless the reader\n> and/or the user intimately knows that TRACE_PACK is implemented by\n> hooking into the same mechanism that TRACE_PACKET needs to, s/he\n> would not even wonder if TRACE_PACKET needs to be enabled when\n> asking for TRACE_PACK. Yes, one is a proper substring of the other,\n> but the similarity between the two stops there. While I do not\n> think it would hurt very much to mention that they are independent,\n> I have a slight suspicion that it might make it more likely to get\n> user confused.\n\nYes, I was just re-reading the documentation based on Augie's comment,\nand it seems pretty clear to me. Of course I wrote it, so that is not\nsaying much. Augie, I'd be happy to hear a proposed wording change if\nyou have one.\n\nI do kind of hate the name TRACE_PACK for two reasons:\n\n - it _is_ so close to TRACE_PACKET; maybe TRACE_PACKFILE would be\n better\n\n - it does not indicate that it is about on-the-wire packs. I.e., it\n has nothing to do with \"git repack\". But I could not think of a good\n succinct name to indicate that.\n\n-Peff\n"},{"id":"263955","messageId":"CAHcr6HbKfE=B502t9hJt601-mco+PK9s4uViFW3AkHABubiF0w@mail.gmail.com","threadId":"39602","inReplyTo":"20150616164310.GA18667@peff.net","subject":"Re: [PATCH 3/3] pkt-line: support tracing verbatim pack contents","fromName":"Augie Fackler","fromEmail":"augie@google.com","sentAt":"2015-06-16T16:52:46Z","receivedAt":"2015-06-16T16:52:46Z","isPatch":true,"sender":{"key":"augie@google.com","avatar":null},"body":"On Tue, Jun 16, 2015 at 12:43 PM, Jeff King wrote:\n> On Tue, Jun 16, 2015 at 09:39:19AM -0700, Junio C Hamano wrote:\n>\n>> As to the documentation, I have a feeling that, unless the reader\n>> and/or the user intimately knows that TRACE_PACK is implemented by\n>> hooking into the same mechanism that TRACE_PACKET needs to, s/he\n>> would not even wonder if TRACE_PACKET needs to be enabled when\n>> asking for TRACE_PACK. Yes, one is a proper substring of the other,\n>> but the similarity between the two stops there. While I do not\n>> think it would hurt very much to mention that they are independent,\n>> I have a slight suspicion that it might make it more likely to get\n>> user confused.\n>\n> Yes, I was just re-reading the documentation based on Augie's comment,\n> and it seems pretty clear to me. Of course I wrote it, so that is not\n> saying much. Augie, I'd be happy to hear a proposed wording change if\n> you have one.\n\nYeah, I don't have one - I may have been making assumptions because I\nknew something of the background on your implementation. i'd say let\nit live and if people provide feedback later figure out a reword\n(writing for humans is not a strong suit of mine, alas.)\n\n>\n> I do kind of hate the name TRACE_PACK for two reasons:\n>\n> - it _is_ so close to TRACE_PACKET; maybe TRACE_PACKFILE would be\n> better\n\n+1 on TRACE_PACKFILE - also makes it harder to accidentally leave off\nthe ET and get binary spew when one didn't expect that.\n\nAF\n"},{"id":"263956","messageId":"20150616171005.GB18667@peff.net","threadId":"39602","inReplyTo":"CAHcr6HYvVR4uTmtegWHK0h+v_aVs4JVLsSwvjthGY3pb=-Q0yQ@mail.gmail.com","subject":"Re: [PATCH 3/3] pkt-line: support tracing verbatim pack contents","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-16T17:10:06Z","receivedAt":"2015-06-16T17:10:06Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Jun 16, 2015 at 11:38:41AM -0400, Augie Fackler wrote:\n\n> > We already have a GIT_TRACE_PACKET mechanism for tracing\n> > packets. Let's extend it with GIT_TRACE_PACK to dump the\n> > verbatim packfile.\n> \n> FWIW, this also works for me - I have no preference between my patches\n> and Jeff's. I suspect yours are much better given that you have a clue\n> about git internals ;).\n\nI like mine better than yours, if only because it hooks into the\nexisting tracing mechanism. But I am sad that neither of our proposals\nworks for tracing pushed packs (something that is useful for the\nopposite situation: you have a sane git server, and some unknown\nmisbehaving _client_ is sending you bogus packs).\n\nHere's a rough cut at the \"trace stdin\" idea I mentioned earlier (which\nis essentially an internal \"tee\"). You can collect the incoming pack\nlike:\n\n GIT_TRACE=1 \\\n GIT_TRACE_STDIN=/tmp/foo.pack \\\n GIT_TRACE_STDIN_FOR=index-pack \\\n git fetch ...\n\nThe \"STDIN_FOR\" hack is there because otherwise you get the stdin for\nmultiple processes intermingled. I think a cleaner way to do it would be\nto allow something like:\n\n GIT_TRACE_STDIN=/tmp/stdin.%p\n\nand replace \"%p\" with the PID of the tracing process.\n\nI like this approach because it works everywhere (for pushed packs, but\nalso for any other git commands you may want to debug). The downside\nversus the other patches is that to replay the index-pack command, you\nneed to collect both its stdin and its arguments (which you can get from\nthe GIT_TRACE output). On the other hand, it gives you a more realistic\nreplay of what happened (e.g., if there is a bug triggered by the\n--pack-header code).\n\nHere is the patch:\n\n---\ndiff --git a/git.c b/git.c\nindex 44374b1..d58866e 100644\n--- a/git.c\n+++ b/git.c\n@@ -616,6 +616,80 @@ static void restore_sigpipe_to_default(void)\n \tsignal(SIGPIPE, SIG_DFL);\n }\n \n+static int copy_stdin(int in, int out, void *data)\n+{\n+\tstruct trace_key *key = data;\n+\twhile (1) {\n+\t\tchar buf[8192];\n+\t\tssize_t len = xread(in, buf, sizeof(buf));\n+\t\tif (!len)\n+\t\t\tbreak;\n+\t\tif (len < 0) {\n+\t\t\twarning(\"error reading stdin trace: %s\",\n+\t\t\t\tstrerror(errno));\n+\t\t\tbreak;\n+\t\t}\n+\n+\t\ttrace_verbatim(key, buf, len);\n+\t\tif (write_in_full(out, buf, len) < 0) {\n+\t\t\twarning(\"error writing stdin trace: %s\",\n+\t\t\t\tstrerror(errno));\n+\t\t\tbreak;\n+\t\t}\n+\t}\n+\tclose(in);\n+\tclose(out);\n+\treturn 0;\n+}\n+\n+static int trace_stdin_for(const char *cmd)\n+{\n+\tint ret = 1;\n+\tconst char *x = getenv(\"GIT_TRACE_STDIN_FOR\");\n+\n+\tif (x) {\n+\t\tstruct string_list items = STRING_LIST_INIT_DUP;\n+\t\tstring_list_split(&items, x, ':', -1);\n+\t\tret = unsorted_string_list_has_string(&items, cmd);\n+\t\tstring_list_clear(&items, 0);\n+\t}\n+\n+\treturn ret;\n+}\n+\n+static void trace_stdin(const char *cmd)\n+{\n+\tstatic struct trace_key key = TRACE_KEY_INIT(STDIN);\n+\tstatic struct async async;\n+\n+\tif (!trace_stdin_for(cmd) || !trace_want(&key))\n+\t\treturn;\n+\n+\tmemset(&async, 0, sizeof(async));\n+\tasync.proc = copy_stdin;\n+\tasync.data = &key;\n+\tasync.in = dup(0);\n+\tasync.out = -1;\n+\n+\tif (async.in < 0 || start_async(&async) < 0) {\n+\t\twarning(\"unable to trace stdin: %s\", strerror(errno));\n+\t\treturn ;\n+\t}\n+\n+\t/*\n+\t * At this point we've handed stdin off to the async process,\n+\t * so there we are past the point of no return.\n+\t */\n+\tif (dup2(async.out, 0))\n+\t\tdie_errno(\"unable to redirect stdin from async process\");\n+\tclose(async.out);\n+\n+\t/*\n+\t * leak async; we would know to finish_async() only when we are\n+\t * exiting, and there is no point then\n+\t */\n+}\n+\n int main(int argc, char **av)\n {\n \tconst char **argv = (const char **) av;\n@@ -674,6 +748,8 @@ int main(int argc, char **av)\n \t}\n \tcmd = argv[0];\n \n+\ttrace_stdin(cmd);\n+\n \t/*\n \t * We use PATH to find git commands, but we prepend some higher\n \t * precedence paths: the \"--exec-path\" option, the GIT_EXEC_PATH\n"},{"id":"263957","messageId":"CAHcr6HYA=gpMTaJ5WOOmtEp+J4wBMz9D59fbByzsdBkPRf4CZQ@mail.gmail.com","threadId":"39602","inReplyTo":"20150616171005.GB18667@peff.net","subject":"Re: [PATCH 3/3] pkt-line: support tracing verbatim pack contents","fromName":"Augie Fackler","fromEmail":"augie@google.com","sentAt":"2015-06-16T17:14:03Z","receivedAt":"2015-06-16T17:14:03Z","isPatch":true,"sender":{"key":"augie@google.com","avatar":null},"body":"On Tue, Jun 16, 2015 at 1:10 PM, Jeff King wrote:\n> On Tue, Jun 16, 2015 at 11:38:41AM -0400, Augie Fackler wrote:\n>\n>> > We already have a GIT_TRACE_PACKET mechanism for tracing\n>> > packets. Let's extend it with GIT_TRACE_PACK to dump the\n>> > verbatim packfile.\n>>\n>> FWIW, this also works for me - I have no preference between my patches\n>> and Jeff's. I suspect yours are much better given that you have a clue\n>> about git internals ;).\n>\n> I like mine better than yours, if only because it hooks into the\n> existing tracing mechanism. But I am sad that neither of our proposals\n> works for tracing pushed packs (something that is useful for the\n> opposite situation: you have a sane git server, and some unknown\n> misbehaving _client_ is sending you bogus packs).\n\nYeah, not having it for the push side is a slight bummer, but in\ngeneral I haven't had problems debugging git clients pushing bogus\ndata in the same way that I've had problems with weirdness in new\nserver features.\n\n>\n> Here's a rough cut at the \"trace stdin\" idea I mentioned earlier (which\n> is essentially an internal \"tee\"). You can collect the incoming pack\n> like:\n\nNeat, but not sure I like the extra overhead of having to grab the\nfull trace and then reconstruct some arguments to be able to diagnose\nthe pack. Having the verbatim pack just land on disk is really handy,\nbecause then any existing tools one has cooked up (my team has a few\nweird one-off ones by now) just work without extra fussing or looking\nup steps to reconstruct the whole file.\n"},{"id":"263958","messageId":"20150616171849.GD18667@peff.net","threadId":"39602","inReplyTo":"CAHcr6HYA=gpMTaJ5WOOmtEp+J4wBMz9D59fbByzsdBkPRf4CZQ@mail.gmail.com","subject":"Re: [PATCH 3/3] pkt-line: support tracing verbatim pack contents","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-16T17:18:49Z","receivedAt":"2015-06-16T17:18:49Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Jun 16, 2015 at 01:14:03PM -0400, Augie Fackler wrote:\n\n> Yeah, not having it for the push side is a slight bummer, but in\n> general I haven't had problems debugging git clients pushing bogus\n> data in the same way that I've had problems with weirdness in new\n> server features.\n\nBeing in charge of a large git server farm, I think I have the opposite\nproblem. :)\n\n> > Here's a rough cut at the \"trace stdin\" idea I mentioned earlier (which\n> > is essentially an internal \"tee\"). You can collect the incoming pack\n> > like:\n> \n> Neat, but not sure I like the extra overhead of having to grab the\n> full trace and then reconstruct some arguments to be able to diagnose\n> the pack. Having the verbatim pack just land on disk is really handy,\n> because then any existing tools one has cooked up (my team has a few\n> weird one-off ones by now) just work without extra fussing or looking\n> up steps to reconstruct the whole file.\n\nI guess there is really room for both. Just because you _can_ accomplish\nthe same thing with both does not mean we cannot have two ways to do it\n(an easy way, and a harder, more flexible way).\n\n-Peff\n"},{"id":"263960","messageId":"20150616172320.GE18667@peff.net","threadId":"39602","inReplyTo":"CAHcr6HbKfE=B502t9hJt601-mco+PK9s4uViFW3AkHABubiF0w@mail.gmail.com","subject":"Re: [PATCH 3/3] pkt-line: support tracing verbatim pack contents","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-16T17:23:20Z","receivedAt":"2015-06-16T17:23:20Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Jun 16, 2015 at 12:52:46PM -0400, Augie Fackler wrote:\n\n> Yeah, I don't have one - I may have been making assumptions because I\n> knew something of the background on your implementation. i'd say let\n> it live and if people provide feedback later figure out a reword\n> (writing for humans is not a strong suit of mine, alas.)\n\nOK, let's leave it as-is, then.\n\n> +1 on TRACE_PACKFILE - also makes it harder to accidentally leave off\n> the ET and get binary spew when one didn't expect that.\n\nHere's a re-roll of 3/3, using TRACE_PACKFILE. I think the documentation\nis enough to allay my other concern (that the name does not imply it is\nabout the network protocol).\n\n-- >8 --\nSubject: pkt-line: support tracing verbatim pack contents\n\nWhen debugging the pack protocol, it is sometimes useful to\nstore the verbatim pack that we sent or received on the\nwire. Looking at the on-disk result is often not helpful for\na few reasons:\n\n 1. If the operation is a clone, we destroy the repo on\n failure, leaving nothing on disk.\n\n 2. If the pack is small, we unpack it immediately, and the\n full pack never hits the disk.\n\n 3. If we feed the pack to \"index-pack --fix-thin\", the\n resulting pack has the extra delta bases added to it.\n\nWe already have a GIT_TRACE_PACKET mechanism for tracing\npackets. Let's extend it with GIT_TRACE_PACKFILE to dump the\nverbatim packfile.\n\nThere are a few other positive fallouts that come from\nrearranging this code:\n\n - We currently disable the packet trace after seeing the\n PACK header, even though we may get human-readable lines\n on other sidebands; now we include them in the trace.\n\n - We currently try to print \"PACK ...\" in the trace to\n indicate that the packfile has started. But because we\n disable packet tracing, we never printed this line. We\n will now do so.\n\nSigned-off-by: Jeff King \n---\n Documentation/git.txt | 13 +++++++++++-\n pkt-line.c | 59 ++++++++++++++++++++++++++++++++++++++-------------\n t/t5601-clone.sh | 7 ++++++\n trace.c | 7 ++++++\n trace.h | 1 +\n 5 files changed, 71 insertions(+), 16 deletions(-)\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex 45b64a7..3453669 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -1000,9 +1000,20 @@ Unsetting the variable, or setting it to empty, \"0\" or\n \tEnables trace messages for all packets coming in or out of a\n \tgiven program. This can help with debugging object negotiation\n \tor other protocol issues. Tracing is turned off at a packet\n-\tstarting with \"PACK\".\n+\tstarting with \"PACK\" (but see 'GIT_TRACE_PACKFILE' below).\n \tSee 'GIT_TRACE' for available trace output options.\n \n+'GIT_TRACE_PACKFILE'::\n+\tEnables tracing of packfiles sent or received by a\n+\tgiven program. Unlike other trace output, this trace is\n+\tverbatim: no headers, and no quoting of binary data. You almost\n+\tcertainly want to direct into a file (e.g.,\n+\t`GIT_TRACE_PACKFILE=/tmp/my.pack`) rather than displaying it on\n+\tthe terminal or mixing it with other trace output.\n++\n+Note that this is currently only implemented for the client side\n+of clones and fetches.\n+\n 'GIT_TRACE_PERFORMANCE'::\n \tEnables performance related trace messages, e.g. total execution\n \ttime of each Git command.\ndiff --git a/pkt-line.c b/pkt-line.c\nindex e75af02..08a1427 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -4,16 +4,51 @@\n char packet_buffer[LARGE_PACKET_MAX];\n static const char *packet_trace_prefix = \"git\";\n static struct trace_key trace_packet = TRACE_KEY_INIT(PACKET);\n+static struct trace_key trace_pack = TRACE_KEY_INIT(PACKFILE);\n \n void packet_trace_identity(const char *prog)\n {\n \tpacket_trace_prefix = xstrdup(prog);\n }\n \n+static int packet_trace_pack(const char *buf, unsigned int len, int sideband)\n+{\n+\tif (!sideband) {\n+\t\ttrace_verbatim(&trace_pack, buf, len);\n+\t\treturn 1;\n+\t} else if (len && *buf == '\\1') {\n+\t\ttrace_verbatim(&trace_pack, buf + 1, len - 1);\n+\t\treturn 1;\n+\t} else {\n+\t\t/* it's another non-pack sideband */\n+\t\treturn 0;\n+\t}\n+}\n+\n static void packet_trace(const char *buf, unsigned int len, int write)\n {\n \tint i;\n \tstruct strbuf out;\n+\tstatic int in_pack, sideband;\n+\n+\tif (!trace_want(&trace_packet) && !trace_want(&trace_pack))\n+\t\treturn;\n+\n+\tif (in_pack) {\n+\t\tif (packet_trace_pack(buf, len, sideband))\n+\t\t\treturn;\n+\t} else if (starts_with(buf, \"PACK\") || starts_with(buf, \"\\1PACK\")) {\n+\t\tin_pack = 1;\n+\t\tsideband = *buf == '\\1';\n+\t\tpacket_trace_pack(buf, len, sideband);\n+\n+\t\t/*\n+\t\t * Make a note in the human-readable trace that the pack data\n+\t\t * started.\n+\t\t */\n+\t\tbuf = \"PACK ...\";\n+\t\tlen = strlen(buf);\n+\t}\n \n \tif (!trace_want(&trace_packet))\n \t\treturn;\n@@ -24,21 +59,15 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n \tstrbuf_addf(&out, \"packet: %12s%c \",\n \t\t packet_trace_prefix, write ? '>' : '<');\n \n-\tif (starts_with(buf, \"PACK\") || starts_with(buf, \"\\1PACK\")) {\n-\t\tstrbuf_addstr(&out, \"PACK ...\");\n-\t\ttrace_disable(&trace_packet);\n-\t}\n-\telse {\n-\t\t/* XXX we should really handle printable utf8 */\n-\t\tfor (i = 0; i < len; i++) {\n-\t\t\t/* suppress newlines */\n-\t\t\tif (buf[i] == '\\n')\n-\t\t\t\tcontinue;\n-\t\t\tif (buf[i] >= 0x20 && buf[i] <= 0x7e)\n-\t\t\t\tstrbuf_addch(&out, buf[i]);\n-\t\t\telse\n-\t\t\t\tstrbuf_addf(&out, \"\\\\%o\", buf[i]);\n-\t\t}\n+\t/* XXX we should really handle printable utf8 */\n+\tfor (i = 0; i < len; i++) {\n+\t\t/* suppress newlines */\n+\t\tif (buf[i] == '\\n')\n+\t\t\tcontinue;\n+\t\tif (buf[i] >= 0x20 && buf[i] <= 0x7e)\n+\t\t\tstrbuf_addch(&out, buf[i]);\n+\t\telse\n+\t\t\tstrbuf_addf(&out, \"\\\\%o\", buf[i]);\n \t}\n \n \tstrbuf_addch(&out, '\\n');\ndiff --git a/t/t5601-clone.sh b/t/t5601-clone.sh\nindex bfdaf75..9b34f3c 100755\n--- a/t/t5601-clone.sh\n+++ b/t/t5601-clone.sh\n@@ -496,4 +496,11 @@ test_expect_success 'shallow clone locally' '\n \t( cd ddsstt && git fsck )\n '\n \n+test_expect_success 'GIT_TRACE_PACKFILE produces a usable pack' '\n+\trm -rf dst.git &&\n+\tGIT_TRACE_PACKFILE=$PWD/tmp.pack git clone --no-local --bare src dst.git &&\n+\tgit init --bare replay.git &&\n+\tgit -C replay.git index-pack -v --stdin wrote:\n> On Tue, Jun 16, 2015 at 01:14:03PM -0400, Augie Fackler wrote:\n>\n>> Yeah, not having it for the push side is a slight bummer, but in\n>> general I haven't had problems debugging git clients pushing bogus\n>> data in the same way that I've had problems with weirdness in new\n>> server features.\n>\n> Being in charge of a large git server farm, I think I have the opposite\n> problem. :)\n\nI've got plenty of servers too, but we haven't typically seen\npush-time problems. Maybe we're lucky, and now that I've said\nsomething and tempted Murphy I'll suffer torment. :)\n\n>\n>> > Here's a rough cut at the \"trace stdin\" idea I mentioned earlier (which\n>> > is essentially an internal \"tee\"). You can collect the incoming pack\n>> > like:\n>>\n>> Neat, but not sure I like the extra overhead of having to grab the\n>> full trace and then reconstruct some arguments to be able to diagnose\n>> the pack. Having the verbatim pack just land on disk is really handy,\n>> because then any existing tools one has cooked up (my team has a few\n>> weird one-off ones by now) just work without extra fussing or looking\n>> up steps to reconstruct the whole file.\n>\n> I guess there is really room for both. Just because you _can_ accomplish\n> the same thing with both does not mean we cannot have two ways to do it\n> (an easy way, and a harder, more flexible way).\n\n*nod* that might make the most sense - given that we both seem to have\nuse cases in mind for verbatim packs on pulls, that seems like a good\nthing to have easy to deploy.\n\n(It still seems to me more likely to write custom servers than\nclients, but then again custom VCS servers has been my life for a\nwhile, so I likely have a weird perspective on things.)\n\n>\n> -Peff\n"},{"id":"263964","messageId":"20150616193102.GA15856@peff.net","threadId":"39602","inReplyTo":"CAHcr6Hbajyx5RV10rv2PWEa9ZyzyxA7jCx=auKxpnv3xjSjq7Q@mail.gmail.com","subject":"[PATCH/RFC 0/3] add GIT_TRACE_STDIN","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-16T19:31:02Z","receivedAt":"2015-06-16T19:31:02Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Jun 16, 2015 at 01:23:31PM -0400, Augie Fackler wrote:\n\n> > I guess there is really room for both. Just because you _can_ accomplish\n> > the same thing with both does not mean we cannot have two ways to do it\n> > (an easy way, and a harder, more flexible way).\n> \n> *nod* that might make the most sense - given that we both seem to have\n> use cases in mind for verbatim packs on pulls, that seems like a good\n> thing to have easy to deploy.\n\nMy ulterior motive is that I actually already have a similar thing in\nplace _just_ for pack-objects, and I'd like to get rid of my custom\nhack. :)\n\nIn that case it is not about saving the packfile, but rather saving the\nparameters to create it (I was interested in finding out why git was\nspending so much CPU to serve some particular requests, and being able\nto run the same pack-generation repeatedly is helpful).\n\nHere are the patches I came up with:\n\n [1/3]: trace: implement %p placeholder for filenames\n [2/3]: trace: add pid to each output line\n [3/3]: trace: add GIT_TRACE_STDIN\n\nThey apply on top of the TRACE_PACKFILE patches, only because they also\nneed the new trace_verbatim(). But I am not altogether happy with the\nresult; see the comments I'll add to 3/3.\n\n-Peff\n"},{"id":"263965","messageId":"20150616193531.GA15931@peff.net","threadId":"39602","inReplyTo":"20150616193102.GA15856@peff.net","subject":"[PATCH 1/3] trace: implement %p placeholder for filenames","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-16T19:35:32Z","receivedAt":"2015-06-16T19:35:32Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"This lets you trace output on a per-process basis by naming\nthe trace file after the PID. This is probably not all that\nuseful for GIT_TRACE itself (which is about a global view of\nthe process hierarchy anyway), but will be useful for traces\nwhich produce large amounts of data (e.g., whole packfiles).\n\nSigned-off-by: Jeff King \n---\nThis is the bare minimum to let you distinguish between the stdin of\ndifferent processes. If we are going to use the trace subsystem to\ncollect more long-term debugging logs, it would probably make sense to\nadd placeholders for the program name and a timestamp. Then you could,\nfor example, leave more verbose debugging enabled on your servers all\nthe time.\n\n Documentation/git.txt | 3 ++-\n trace.c | 19 +++++++++++++++++--\n 2 files changed, 19 insertions(+), 3 deletions(-)\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex 3453669..80f6392 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -984,7 +984,8 @@ trace messages into this file descriptor.\n Alternatively, if the variable is set to an absolute path\n (starting with a '/' character), Git will interpret this\n as a file path and will try to write the trace messages\n-into it.\n+into it. If the filename contains the string `%p`, that string\n+will be replaced with the PID of the traced process.\n +\n Unsetting the variable, or setting it to empty, \"0\" or\n \"false\" (case insensitive) disables trace messages.\ndiff --git a/trace.c b/trace.c\nindex 7393926..e1d1360 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -25,6 +25,16 @@\n #include \"cache.h\"\n #include \"quote.h\"\n \n+static size_t expand_trace_name(struct strbuf *out, const char *fmt,\n+\t\t\t\tvoid *data)\n+{\n+\tif (*fmt == 'p') {\n+\t\tstrbuf_addf(out, \"%lu\", (unsigned long)getpid());\n+\t\treturn 1;\n+\t}\n+\treturn 0;\n+}\n+\n /* Get a trace file descriptor from \"key\" env variable. */\n static int get_trace_fd(struct trace_key *key)\n {\n@@ -49,17 +59,22 @@ static int get_trace_fd(struct trace_key *key)\n \telse if (strlen(trace) == 1 && isdigit(*trace))\n \t\tkey->fd = atoi(trace);\n \telse if (is_absolute_path(trace)) {\n-\t\tint fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666);\n+\t\tstruct strbuf name = STRBUF_INIT;\n+\t\tint fd;\n+\n+\t\tstrbuf_expand(&name, trace, expand_trace_name, NULL);\n+\t\tfd = open(name.buf, O_WRONLY | O_APPEND | O_CREAT, 0666);\n \t\tif (fd == -1) {\n \t\t\tfprintf(stderr,\n \t\t\t\t\"Could not open '%s' for tracing: %s\\n\"\n \t\t\t\t\"Defaulting to tracing on stderr...\\n\",\n-\t\t\t\ttrace, strerror(errno));\n+\t\t\t\tname.buf, strerror(errno));\n \t\t\tkey->fd = STDERR_FILENO;\n \t\t} else {\n \t\t\tkey->fd = fd;\n \t\t\tkey->need_close = 1;\n \t\t}\n+\t\tstrbuf_release(&name);\n \t} else {\n \t\tfprintf(stderr, \"What does '%s' for %s mean?\\n\"\n \t\t\t\"If you want to trace into a file, then please set \"\n-- \n2.4.3.699.g84b4da7\n"},{"id":"263966","messageId":"20150616193639.GB15931@peff.net","threadId":"39602","inReplyTo":"20150616193102.GA15856@peff.net","subject":"[PATCH 2/3] trace: add pid to each output line","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-16T19:36:39Z","receivedAt":"2015-06-16T19:36:39Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"When there are many git commands running, it can be\nconfusing which process is producing which message. And if\none is trying to correlate a specific invocation with a\ntrace-file created using \"%p\", it's rather impossible.\n\nLet's print the pid alongside each line. This does extend\nthe already-wide trace lines. We could make it optional, but\nit's probably not worth the complexity of extra knobs.\nLooking at trace output is already an exceptional thing to\nbe doing, and verbose output is not going to bother anyone.\n\nSigned-off-by: Jeff King \n---\nI think you can technically get by without this for most cases, as doing\nGIT_TRACE=base.%p will get you the \"built-in: ...\" line for index-pack,\npack-objects, etc, which you can then correlate with a matching\nGIT_TRACE_STDIN filename.\n\n trace.c | 5 +++--\n 1 file changed, 3 insertions(+), 2 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex e1d1360..a7ec484 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -123,12 +123,13 @@ static int prepare_trace_line(const char *file, int line,\n \tlocaltime_r(&secs, &tm);\n \tstrbuf_addf(buf, \"%02d:%02d:%02d.%06ld \", tm.tm_hour, tm.tm_min,\n \t\t tm.tm_sec, (long) tv.tv_usec);\n+\tstrbuf_addf(buf, \"[pid=%lu] \", (unsigned long)getpid());\n \n #ifdef HAVE_VARIADIC_MACROS\n \t/* print file:line */\n \tstrbuf_addf(buf, \"%s:%d \", file, line);\n-\t/* align trace output (column 40 catches most files names in git) */\n-\twhile (buf->len < 40)\n+\t/* align trace output (column 50 catches most files names in git) */\n+\twhile (buf->len < 50)\n \t\tstrbuf_addch(buf, ' ');\n #endif\n \n-- \n2.4.3.699.g84b4da7\n"},{"id":"263967","messageId":"20150616193716.GC15931@peff.net","threadId":"39602","inReplyTo":"20150616193102.GA15856@peff.net","subject":"[PATCH 3/3] trace: add GIT_TRACE_STDIN","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-16T19:37:16Z","receivedAt":"2015-06-16T19:37:16Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"Sometimes tracing the invocation of git programs with\nGIT_TRACE is not quite enough to replay a situation; the\ninteresting input to the program often comes over its\nstandard input. For instance, if you want to replay a\nparticular fetch (e.g., for performance analysis or\ndebugging), you would want both the arguments and stdin sent\nto pack-objects.\n\nThis patch lets you capture the stdin of any git process.\nFor instance:\n\n GIT_TRACE=/tmp/processes.out \\\n GIT_TRACE_STDIN=/tmp/stdin.%p \\\n git daemon ...\n\nAfter a fetch, processes.out will contain a line like:\n\n 15:19:08.275493 [pid=13196] git.c:348 trace:\n built-in: git 'pack-objects' '--revs' '--thin' '--stdout'\n '--progress' '--delta-base-offset'\n\nAnd stdin.13196 (the pid picked from the above line) will\ncontain its stdin.\n\nSigned-off-by: Jeff King \n---\n git.c | 60 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++\n 1 file changed, 60 insertions(+)\n\ndiff --git a/git.c b/git.c\nindex 44374b1..e7e58e3 100644\n--- a/git.c\n+++ b/git.c\n@@ -616,6 +616,65 @@ static void restore_sigpipe_to_default(void)\n \tsignal(SIGPIPE, SIG_DFL);\n }\n \n+static int copy_stdin(int in, int out, void *data)\n+{\n+\tstruct trace_key *key = data;\n+\twhile (1) {\n+\t\tchar buf[8192];\n+\t\tssize_t len = xread(in, buf, sizeof(buf));\n+\t\tif (!len)\n+\t\t\tbreak;\n+\t\tif (len < 0) {\n+\t\t\twarning(\"error reading stdin trace: %s\",\n+\t\t\t\tstrerror(errno));\n+\t\t\tbreak;\n+\t\t}\n+\n+\t\ttrace_verbatim(key, buf, len);\n+\t\tif (write_in_full(out, buf, len) < 0) {\n+\t\t\twarning(\"error writing stdin trace: %s\",\n+\t\t\t\tstrerror(errno));\n+\t\t\tbreak;\n+\t\t}\n+\t}\n+\tclose(in);\n+\tclose(out);\n+\treturn 0;\n+}\n+\n+static void trace_stdin(void)\n+{\n+\tstatic struct trace_key key = TRACE_KEY_INIT(STDIN);\n+\tstatic struct async async;\n+\n+\tif (!trace_want(&key))\n+\t\treturn;\n+\n+\tmemset(&async, 0, sizeof(async));\n+\tasync.proc = copy_stdin;\n+\tasync.data = &key;\n+\tasync.in = dup(0);\n+\tasync.out = -1;\n+\n+\tif (async.in < 0 || start_async(&async) < 0) {\n+\t\twarning(\"unable to trace stdin: %s\", strerror(errno));\n+\t\treturn ;\n+\t}\n+\n+\t/*\n+\t * At this point we've handed stdin off to the async process,\n+\t * so there we are past the point of no return.\n+\t */\n+\tif (dup2(async.out, 0))\n+\t\tdie_errno(\"unable to redirect stdin from async process\");\n+\tclose(async.out);\n+\n+\t/*\n+\t * leak async; we would know to finish_async() only when we are\n+\t * exiting, and there is no point then\n+\t */\n+}\n+\n int main(int argc, char **av)\n {\n \tconst char **argv = (const char **) av;\n@@ -640,6 +699,7 @@ int main(int argc, char **av)\n \tgit_setup_gettext();\n \n \ttrace_command_performance(argv);\n+\ttrace_stdin();\n \n \t/*\n \t * \"git-xxxx\" is the same as \"git xxxx\", but we obviously:\n-- \n2.4.3.699.g84b4da7\n"},{"id":"263968","messageId":"20150616194907.GA15988@peff.net","threadId":"39602","inReplyTo":"20150616193716.GC15931@peff.net","subject":"Re: [PATCH 3/3] trace: add GIT_TRACE_STDIN","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-16T19:49:08Z","receivedAt":"2015-06-16T19:49:08Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Jun 16, 2015 at 03:37:16PM -0400, Jeff King wrote:\n\n> For instance:\n> \n> GIT_TRACE=/tmp/processes.out \\\n> GIT_TRACE_STDIN=/tmp/stdin.%p \\\n> git daemon ...\n> \n> After a fetch, processes.out will contain a line like:\n> \n> 15:19:08.275493 [pid=13196] git.c:348 trace:\n> built-in: git 'pack-objects' '--revs' '--thin' '--stdout'\n> '--progress' '--delta-base-offset'\n> \n> And stdin.13196 (the pid picked from the above line) will\n> contain its stdin.\n\nSo this is the part that I don't like. Collecting stdin is expensive,\nand the commands above would be totally inappropriate for a production\nserver, for two reasons:\n\n 1. It requires restarting git-daemon to turn on debugging.\n\n 2. It logs for _everything_. Every repo, and every process.\n\nI mentioned before that I have a similar patch for logging pack-objects.\nThat is triggered via config, which solves both of these problems. What\nI'd really like is to be able to do:\n\n git config trace.pack-objects.stdin fetches/stdin.%p\n\nin a particular repository, collect data for a few minutes, and then\nturn it back off.\n\nThe patch below implements that, but it doesn't quite work as you might\nhope. The problem is that we cannot read the repository config so early\nin the git.c startup; we do not even know if we have a repository yet.\nPushing the config-reading later is too late; we may already have looked\nat GIT_TRACE_* and decided whether to trace (and possibly even written\ntrace records!).\n\nIt's possible we could hack around it by rearranging the startup\nsequence, but that sequence is notoriously fragile.\n\nAnother option would be to stop trying to intercept stdin in git.c, and\ninstead make this a feature of run-command.c. That is, right before we\nexec a process, tee its stdin there. That means that you cannot do:\n\n GIT_TRACE_STDIN=/tmp/foo.out git foo\n\nto collect the stdin of foo. But that is not really an interesting case\nanyway. You can run \"tee\" yourself if you want. The interesting cases\nare the ones where git is spawning a sub-process, and you want to\nintercept the data moving between the git processes.\n\n-Peff\n\n---\ndiff --git a/git.c b/git.c\nindex e7e58e3..cbb7e9b 100644\n--- a/git.c\n+++ b/git.c\n@@ -675,6 +675,38 @@ static void trace_stdin(void)\n \t */\n }\n \n+static int trace_config_cb(const char *var, const char *value, void *data)\n+{\n+\tconst char *want_cmd = data;\n+\tconst char *have_cmd, *key;\n+\tint have_len;\n+\n+\tif (!parse_config_key(var, \"trace\", &have_cmd, &have_len, &key) &&\n+\t have_cmd &&\n+\t !strncmp(want_cmd, have_cmd, have_len) &&\n+\t want_cmd[have_len] == '\\0') {\n+\t\tstruct strbuf buf = STRBUF_INIT;\n+\t\tstrbuf_addstr(&buf, \"GIT_TRACE_\");\n+\t\twhile (*key)\n+\t\t\tstrbuf_addch(&buf, toupper(*key++));\n+\t\tsetenv(buf.buf, value, 0);\n+\t\tstrbuf_release(&buf);\n+\t}\n+\treturn 0;\n+}\n+\n+static void load_trace_config(const char *cmd, const char **argv)\n+{\n+\t/* XXX we don't know the cmd for sure until we parse the options */\n+\tif (!strcmp(cmd, \"git\"))\n+\t\tcmd = argv[1];\n+\telse\n+\t\tskip_prefix(cmd, \"git-\", &cmd);\n+\n+\tif (cmd)\n+\t\tgit_config(trace_config_cb, (void *)cmd);\n+}\n+\n int main(int argc, char **av)\n {\n \tconst char **argv = (const char **) av;\n@@ -698,6 +730,7 @@ int main(int argc, char **av)\n \n \tgit_setup_gettext();\n \n+\tload_trace_config(cmd, argv);\n \ttrace_command_performance(argv);\n \ttrace_stdin();\n \n"},{"id":"263975","messageId":"20150616212039.GA11353@peff.net","threadId":"39602","inReplyTo":"20150616194907.GA15988@peff.net","subject":"Re: [PATCH 3/3] trace: add GIT_TRACE_STDIN","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-16T21:20:40Z","receivedAt":"2015-06-16T21:20:40Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Jun 16, 2015 at 03:49:07PM -0400, Jeff King wrote:\n\n> Another option would be to stop trying to intercept stdin in git.c, and\n> instead make this a feature of run-command.c. That is, right before we\n> exec a process, tee its stdin there. That means that you cannot do:\n> \n> GIT_TRACE_STDIN=/tmp/foo.out git foo\n> \n> to collect the stdin of foo. But that is not really an interesting case\n> anyway. You can run \"tee\" yourself if you want. The interesting cases\n> are the ones where git is spawning a sub-process, and you want to\n> intercept the data moving between the git processes.\n\nHmm. I guess we do not actually have to move the stdin interception\nthere. We can just move the config-checking there, like the patch below.\n\nIt basically just converts trace.foo.bar into GIT_TRACE_BAR when we are\nrunning \"foo\" as a git command. This does work, but is perhaps\npotentially confusing to the user, because it only kicks in when _git_\nruns \"foo\". IOW, this works:\n\n git config trace.upload-pack.foo /path/to/foo.out\n git daemon\n\nand will trace as you expect. But then running:\n\n git upload-pack\n\nyourself will do nothing.\n\nI dunno.\n\n---\n run-command.c | 17 +++++++++++++++++\n trace.c | 44 ++++++++++++++++++++++++++++++++++++++++++++\n trace.h | 9 +++++++++\n 3 files changed, 70 insertions(+)\n\ndiff --git a/run-command.c b/run-command.c\nindex 4d73e90..2febbb5 100644\n--- a/run-command.c\n+++ b/run-command.c\n@@ -284,6 +284,23 @@ int start_command(struct child_process *cmd)\n \n \tif (!cmd->argv)\n \t\tcmd->argv = cmd->args.argv;\n+\tif (cmd->git_cmd) {\n+\t\t/*\n+\t\t * Load any extra variables into env_array. But\n+\t\t * if we weren't going to use it (in favor of \"env\"),\n+\t\t * then consolidate the two. Make sure the original \"env\"\n+\t\t * goes after what we add, so that it can override.\n+\t\t *\n+\t\t * We cannot just keep two lists, because we may hand off the\n+\t\t * single list to a spawn() implementation.\n+\t\t */\n+\t\ttrace_config_for(cmd->argv[0], &cmd->env_array);\n+\t\tif (cmd->env_array.argc && cmd->env) {\n+\t\t\tfor (; *cmd->env; cmd->env++)\n+\t\t\t\targv_array_push(&cmd->env_array, *cmd->env);\n+\t\t\tcmd->env = NULL;\n+\t\t}\n+\t}\n \tif (!cmd->env)\n \t\tcmd->env = cmd->env_array.argv;\n \ndiff --git a/trace.c b/trace.c\nindex a7ec484..86c988e 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -24,6 +24,7 @@\n \n #include \"cache.h\"\n #include \"quote.h\"\n+#include \"argv-array.h\"\n \n static size_t expand_trace_name(struct strbuf *out, const char *fmt,\n \t\t\t\tvoid *data)\n@@ -449,3 +450,46 @@ void trace_command_performance(const char **argv)\n \tsq_quote_argv(&command_line, argv, 0);\n \tcommand_start_time = getnanotime();\n }\n+\n+struct trace_config_data {\n+\tconst char *want_cmd;\n+\tstruct argv_array *out;\n+};\n+\n+static int trace_config_cb(const char *var, const char *value, void *vdata)\n+{\n+\tstruct trace_config_data *data = vdata;\n+\tconst char *have_cmd, *key;\n+\tint have_len;\n+\n+\tif (!parse_config_key(var, \"trace\", &have_cmd, &have_len, &key) &&\n+\t have_cmd &&\n+\t !strncmp(data->want_cmd, have_cmd, have_len) &&\n+\t data->want_cmd[have_len] == '\\0') {\n+\t\tstruct strbuf buf = STRBUF_INIT;\n+\n+\t\tstrbuf_addstr(&buf, \"GIT_TRACE_\");\n+\t\twhile (*key)\n+\t\t\tstrbuf_addch(&buf, toupper(*key++));\n+\n+\t\t/*\n+\t\t * Environment always takes precedence over config, so do not\n+\t\t * override existing variables. We cannot rely on setenv()'s\n+\t\t * overwrite flag here, because we may pass the list off to\n+\t\t * a spawn() implementation, which always overwrites.\n+\t\t */\n+\t\tif (!getenv(buf.buf))\n+\t\t\targv_array_pushf(data->out, \"%s=%s\", buf.buf, value);\n+\n+\t\tstrbuf_release(&buf);\n+\t}\n+\treturn 0;\n+}\n+\n+void trace_config_for(const char *cmd, struct argv_array *out)\n+{\n+\tstruct trace_config_data data;\n+\tdata.want_cmd = cmd;\n+\tdata.out = out;\n+\tgit_config(trace_config_cb, &data);\n+}\ndiff --git a/trace.h b/trace.h\nindex 179b249..83618e9 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -4,6 +4,8 @@\n #include \"git-compat-util.h\"\n #include \"strbuf.h\"\n \n+struct argv_array;\n+\n struct trace_key {\n \tconst char * const key;\n \tint fd;\n@@ -20,6 +22,13 @@ extern uint64_t getnanotime(void);\n extern void trace_command_performance(const char **argv);\n extern void trace_verbatim(struct trace_key *key, const void *buf, unsigned len);\n \n+/**\n+ * Load any trace-related config for git command \"cmd\", and insert the matching\n+ * environment variables into \"out\", which is suitable for use by run-command\n+ * and friends.\n+ */\n+void trace_config_for(const char *cmd, struct argv_array *out);\n+\n #ifndef HAVE_VARIADIC_MACROS\n \n __attribute__((format (printf, 1, 2)))\n-- \n2.4.3.699.g84b4da7\n"},{"id":"263999","messageId":"CACsJy8DaJOOu7PA8jL+Mu3HQua-TRmzN378Mek1HuWVmRzT+ww@mail.gmail.com","threadId":"39602","inReplyTo":"20150616212039.GA11353@peff.net","subject":"Re: [PATCH 3/3] trace: add GIT_TRACE_STDIN","fromName":"Duy Nguyen","fromEmail":"pclouds@gmail.com","sentAt":"2015-06-17T10:04:04Z","receivedAt":"2015-06-17T10:04:04Z","isPatch":true,"sender":{"key":"pclouds@gmail.com","avatar":"https://avatars.githubusercontent.com/u/720?v=4"},"body":"On Wed, Jun 17, 2015 at 4:20 AM, Jeff King wrote:\n> On Tue, Jun 16, 2015 at 03:49:07PM -0400, Jeff King wrote:\n>\n>> Another option would be to stop trying to intercept stdin in git.c, and\n>> instead make this a feature of run-command.c. That is, right before we\n>> exec a process, tee its stdin there. That means that you cannot do:\n>>\n>> GIT_TRACE_STDIN=/tmp/foo.out git foo\n>>\n>> to collect the stdin of foo. But that is not really an interesting case\n>> anyway. You can run \"tee\" yourself if you want. The interesting cases\n>> are the ones where git is spawning a sub-process, and you want to\n>> intercept the data moving between the git processes.\n>\n> Hmm. I guess we do not actually have to move the stdin interception\n> there. We can just move the config-checking there, like the patch below.\n>\n> It basically just converts trace.foo.bar into GIT_TRACE_BAR when we are\n> running \"foo\" as a git command. This does work, but is perhaps\n> potentially confusing to the user, because it only kicks in when _git_\n> runs \"foo\". IOW, this works:\n>\n> git config trace.upload-pack.foo /path/to/foo.out\n> git daemon\n\nI wonder if we could do it a bit differently. Instead of\nGIT_TRACE_STDIN, I would add GIT_TRACE_HOOK that points to a script.\nWhenever a command is run via run-command interface, the actual\ncommand line to be executed would be \" \n\".\n\nBecause this script is given full command line, it can decide to trace\nsomething if the command name is matched (or arguments are matched) or\njust execute the original command. It's more flexible that trace.*\nconfig keys. We also have an opportunity to replace builtin commands,\nlike pack-objects, in command pipeline in fetch or push with something\nelse, to inject errors or whatever. It can be done manually, but it's\nnot easy or convenient.\n-- \nDuy\n"},{"id":"264055","messageId":"20150617191023.GA25304@peff.net","threadId":"39602","inReplyTo":"CACsJy8DaJOOu7PA8jL+Mu3HQua-TRmzN378Mek1HuWVmRzT+ww@mail.gmail.com","subject":"Re: [PATCH 3/3] trace: add GIT_TRACE_STDIN","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-06-17T19:10:23Z","receivedAt":"2015-06-17T19:10:23Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Jun 17, 2015 at 05:04:04PM +0700, Duy Nguyen wrote:\n\n> I wonder if we could do it a bit differently. Instead of\n> GIT_TRACE_STDIN, I would add GIT_TRACE_HOOK that points to a script.\n> Whenever a command is run via run-command interface, the actual\n> command line to be executed would be \" \n> \".\n\nHmm, yeah, I like that. It's even more flexible, and it is much more\nobvious why it works only for run-command. If we feed the resulting\n\"hooked\" command to the shell, I think you could do:\n\n GIT_TRACE_HOOK='\n f() {\n case \"$1 $2\" in\n git pack-objects)\n tee /tmp/foo.out | \"$@\"\n\t;;\n esac\n }; f\n '\n\nThat is not 100% correct (you would miss \"git --some-arg pack-objects\"),\nbut it is probably fine in practice for debugging sessions. It is a bit\nmore complicated to use, but I really like the flexibility (I can\nimagine that \"GIT_TRACE_HOOK=gdbserver localhost:1234\" would come in\nhandy).\n\n> Because this script is given full command line, it can decide to trace\n> something if the command name is matched (or arguments are matched) or\n> just execute the original command. It's more flexible that trace.*\n> config keys. We also have an opportunity to replace builtin commands,\n> like pack-objects, in command pipeline in fetch or push with something\n> else, to inject errors or whatever. It can be done manually, but it's\n> not easy or convenient.\n\nMy other motive for trace.* was that we could have something like\n\"trace.prune\", and have git-prune provide verbose debugging information.\nWe have custom patches like that on GitHub servers, which we've used to\ndebug occasional weirdness (e.g., you find that an object is missing\nfrom a repo, but you have no clue why it went away; was it never there,\ndid somebody prune it, did it get dropped from a pack?).\n\nI can send those upstream, but it would be nice not to introduce a\ntotally separate tracing facility when trace_* is so close. But it\nneeds:\n\n 1. To be enabled by config, not environment.\n\n 2. To support some basic output filename flexibility so the output can\n be organized (we write the equivalent of GIT_TRACE_FOO to\n $GIT_DIR/ghlog_foo/YYYY-MM-DD/YYYY-MM-DDTHH:MM:SS.PID).\n\nFor (1), we could just load trace.* in git_default_config; you couldn't\nuse it with any \"early\" tracing that happens before then, but I think in\npractice it would be fine for most traces.\n\nFor (2), I think we could accomplish that with %-placeholders (like my\nearlier patch), and the ability to write relative paths into $GIT_DIR\n(again, you couldn't do this for \"early\" traces, but you could for other\nstuff).\n\nOr we could just do nothing. I'm not sure if anybody else is actually\ninterested in verbose-logging patches like these.\n\n-Peff\n"},{"id":"264115","messageId":"CACsJy8Bh=GAaY0g3+Don5Cop_zAii0MF-y-bEkVP+NSrgKdKAg@mail.gmail.com","threadId":"39602","inReplyTo":"20150617191023.GA25304@peff.net","subject":"Re: [PATCH 3/3] trace: add GIT_TRACE_STDIN","fromName":"Duy Nguyen","fromEmail":"pclouds@gmail.com","sentAt":"2015-06-18T10:20:13Z","receivedAt":"2015-06-18T10:20:13Z","isPatch":true,"sender":{"key":"pclouds@gmail.com","avatar":"https://avatars.githubusercontent.com/u/720?v=4"},"body":"On Thu, Jun 18, 2015 at 2:10 AM, Jeff King wrote:\n> On Wed, Jun 17, 2015 at 05:04:04PM +0700, Duy Nguyen wrote:\n>\n>> I wonder if we could do it a bit differently. Instead of\n>> GIT_TRACE_STDIN, I would add GIT_TRACE_HOOK that points to a script.\n>> Whenever a command is run via run-command interface, the actual\n>> command line to be executed would be \" \n>> \".\n>\n> Hmm, yeah, I like that. It's even more flexible, and it is much more\n> obvious why it works only for run-command. If we feed the resulting\n> \"hooked\" command to the shell, I think you could do:\n>\n> GIT_TRACE_HOOK='\n> f() {\n> case \"$1 $2\" in\n> git pack-objects)\n> tee /tmp/foo.out | \"$@\"\n> ;;\n> esac\n> }; f\n> '\n>\n> That is not 100% correct (you would miss \"git --some-arg pack-objects\"),\n\nYeah, flexibility always comes with traps and pitfalls.\n\n> but it is probably fine in practice for debugging sessions. It is a bit\n> more complicated to use, but I really like the flexibility (I can\n> imagine that \"GIT_TRACE_HOOK=gdbserver localhost:1234\" would come in\n> handy).\n>\n>> Because this script is given full command line, it can decide to trace\n>> something if the command name is matched (or arguments are matched) or\n>> just execute the original command. It's more flexible that trace.*\n>> config keys. We also have an opportunity to replace builtin commands,\n>> like pack-objects, in command pipeline in fetch or push with something\n>> else, to inject errors or whatever. It can be done manually, but it's\n>> not easy or convenient.\n>\n> My other motive for trace.* was that we could have something like\n> \"trace.prune\", and have git-prune provide verbose debugging information.\n> We have custom patches like that on GitHub servers, which we've used to\n> debug occasional weirdness (e.g., you find that an object is missing\n> from a repo, but you have no clue why it went away; was it never there,\n> did somebody prune it, did it get dropped from a pack?).\n>\n> I can send those upstream, but it would be nice not to introduce a\n> totally separate tracing facility when trace_* is so close. But it\n> needs:\n>\n> 1. To be enabled by config, not environment.\n>\n> 2. To support some basic output filename flexibility so the output can\n> be organized (we write the equivalent of GIT_TRACE_FOO to\n> $GIT_DIR/ghlog_foo/YYYY-MM-DD/YYYY-MM-DDTHH:MM:SS.PID).\n>\n> For (1), we could just load trace.* in git_default_config; you couldn't\n> use it with any \"early\" tracing that happens before then, but I think in\n> practice it would be fine for most traces.\n>\n> For (2), I think we could accomplish that with %-placeholders (like my\n> earlier patch), and the ability to write relative paths into $GIT_DIR\n> (again, you couldn't do this for \"early\" traces, but you could for other\n> stuff).\n>\n> Or we could just do nothing. I'm not sure if anybody else is actually\n> interested in verbose-logging patches like these.\n\nI'm not stopping you from doing this, just to be clear. I was just\ntrying to convince you to do something extra that I wanted to use ;)\n-- \nDuy\n"},{"id":"264984","messageId":"xmqqoak2tihk.fsf@gitster.dls.corp.google.com","threadId":"39602","inReplyTo":"20150617191023.GA25304@peff.net","subject":"Re: [PATCH 3/3] trace: add GIT_TRACE_STDIN","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2015-06-26T18:47:03Z","receivedAt":"2015-06-26T18:47:03Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> My other motive for trace.* was that we could have something like\n> \"trace.prune\", and have git-prune provide verbose debugging information.\n> We have custom patches like that on GitHub servers, which we've used to\n> debug occasional weirdness (e.g., you find that an object is missing\n> from a repo, but you have no clue why it went away; was it never there,\n> did somebody prune it, did it get dropped from a pack?).\n>\n> I can send those upstream, but it would be nice not to introduce a\n> totally separate tracing facility when trace_* is so close. But it\n> needs:\n>\n> 1. To be enabled by config, not environment.\n>\n> 2. To support some basic output filename flexibility so the output can\n> be organized (we write the equivalent of GIT_TRACE_FOO to\n> $GIT_DIR/ghlog_foo/YYYY-MM-DD/YYYY-MM-DDTHH:MM:SS.PID).\n>\n> For (1), we could just load trace.* in git_default_config; you couldn't\n> use it with any \"early\" tracing that happens before then, but I think in\n> practice it would be fine for most traces.\n>\n> For (2), I think we could accomplish that with %-placeholders (like my\n> earlier patch), and the ability to write relative paths into $GIT_DIR\n> (again, you couldn't do this for \"early\" traces, but you could for other\n> stuff).\n\nBoth sounds like a sensible compromise to me.\n\nThanks, all, for an interesting discussion.\n"}]}