diff mbox series

[v2] tr2: log parent process name

Message ID 20210520210546.4129620-1-emilyshaffer@google.com (mailing list archive)
State Superseded
Headers show
Series [v2] tr2: log parent process name | expand

Commit Message

Emily Shaffer May 20, 2021, 9:05 p.m. UTC
It can be useful to tell who invoked Git - was it invoked manually by a
user via CLI or script? By an IDE?  In some cases - like 'repo' tool -
we can influence the source code and set the GIT_TRACE2_PARENT_SID
environment variable from the caller process. In 'repo''s case, that
parent SID is manipulated to include the string "repo", which means we
can positively identify when Git was invoked by 'repo' tool. However,
identifying parents that way requires both that we know which tools
invoke Git and that we have the ability to modify the source code of
those tools. It cannot scale to keep up with the various IDEs and
wrappers which use Git, most of which we don't know about. Learning
which tools and wrappers invoke Git, and how, would give us insight to
decide where to improve Git's usability and performance.

Unfortunately, there's no cross-platform reliable way to gather the name
of the parent process. If procfs is present, we can use that; otherwise
we will need to discover the name another way. However, the process ID
should be sufficient regardless of platform.

Git for Windows gathers similar information and logs it as a "data_json"
event. However, since "data_json" has a variable format, it is difficult
to parse effectively in some languages; instead, let's pursue a
dedicated "cmd_ancestry" event to record information about the ancestry
of the current process and a consistent, parseable way.

Git for Windows also gathers information about more than one parent. In
Linux further ancestry info can be gathered with procfs, but it's
unwieldy to do so. In the interest of later moving Git for Windows
ancestry logging to the 'cmd_ancestry' event, and in the interest of
later adding more ancestry to the Linux implementation - or of adding
this functionality to other platforms which have an easier time walking
the process tree - let's make 'cmd_ancestry' accept an array of
parentage.

Signed-off-by: Emily Shaffer <emilyshaffer@google.com>
---

Hi folks, the comments I received in v1 were of two varieties:
1) "There are better ways to make this platform-safe", and
2) "Your commit message doesn't convince me".
Since I sent v1, though, I also learned a little more about procfs, and
about the trace2 structure overall, so there are some pretty significant
differences from v1:

- I took a look at Jeff H's advice on using a "data_json" event to log
  this and decided it would be a little more flexible to add a new event
  instead. If we want, it'd be feasible to then shoehorn the GfW parent
  tree stuff into this new event too. Doing it this way is definitely
  easier to parse for Google's trace analysis system (which for now
  completely skips "data_json" as it's polymorphic), and also - I think
  - means that we can add more fields later on if we need to (thread
  info, different fields than just /proc/n/comm like exec path, argv,
  whatever).
- Jonathan N also pointed out to me that /proc/n/comm exists, and logs
  the "command name" - excluding argv, excluding path, etc. It seems
  like this is a little more safe about excluding personal information
  from the traces which take the form of "myscript.sh
  --password=hunter2", but would still be worrisome for something like
  "mysupersecretproject.sh". I'm not sure whether that means we still
  want to guard it with a config flag, though.
- I also added a lot to the commit message; hopefully it's not too
  rambly, but I hoped to explain why just setting GIT_TRACE2_PARENT_SID
  wasn't going to cut it.
- As for testing, I followed the lead of GfW's parentage info - "this
  isn't portable so writing tests for it will suck, just scrub it from
  the tests". Maybe it makes sense to do some more
  platform-specific-ness in the test suite instead? I wasn't sure.

Thanks, all.
 - Emily

 Makefile                  |  5 ++++
 compat/procinfo.c         | 53 +++++++++++++++++++++++++++++++++++++++
 config.mak.uname          |  1 +
 git-compat-util.h         |  6 +++++
 t/t0210/scrub_normal.perl |  6 +++++
 t/t0211/scrub_perf.perl   |  5 ++++
 t/t0212/parse_events.perl |  5 +++-
 trace2.c                  | 13 ++++++++++
 trace2.h                  | 12 ++++++++-
 trace2/tr2_tgt.h          |  3 +++
 trace2/tr2_tgt_event.c    | 21 ++++++++++++++++
 trace2/tr2_tgt_normal.c   | 19 ++++++++++++++
 trace2/tr2_tgt_perf.c     | 16 ++++++++++++
 13 files changed, 163 insertions(+), 2 deletions(-)
 create mode 100644 compat/procinfo.c

Comments

Randall S. Becker May 20, 2021, 9:36 p.m. UTC | #1
On May 20, 2021 5:06 PM, Emily Shaffer wrote:
>To: git@vger.kernel.org
>Cc: Emily Shaffer <emilyshaffer@google.com>; Ævar Arnfjörð Bjarmason <avarab@gmail.com>; Junio C Hamano <gitster@pobox.com>;
>Jeff Hostetler <git@jeffhostetler.com>; Bagas Sanjaya <bagasdotme@gmail.com>
>Subject: [PATCH v2] tr2: log parent process name
>
>It can be useful to tell who invoked Git - was it invoked manually by a user via CLI or script? By an IDE?  In some cases - like 'repo' tool -
>we can influence the source code and set the GIT_TRACE2_PARENT_SID environment variable from the caller process. In 'repo''s case,
>that parent SID is manipulated to include the string "repo", which means we can positively identify when Git was invoked by 'repo' tool.
>However, identifying parents that way requires both that we know which tools invoke Git and that we have the ability to modify the source
>code of those tools. It cannot scale to keep up with the various IDEs and wrappers which use Git, most of which we don't know about.
>Learning which tools and wrappers invoke Git, and how, would give us insight to decide where to improve Git's usability and performance.
>
>Unfortunately, there's no cross-platform reliable way to gather the name of the parent process. If procfs is present, we can use that;
>otherwise we will need to discover the name another way. However, the process ID should be sufficient regardless of platform.

I like this idea, but there are some platforms where this is unlikely to work. NonStop, in particular, can initiate git - and I frequently do - from a non-POSIX environment where process name is entirely different. In fact, it is something like $ABC (always beginning with a $, which makes life very difficult for shell scripts and screws up GIT_SSH_COMMAND, but I digress). I'm going to need to plug in something very platform-specific to make this work. getppid() always returns 1 in this situation, which is extraordinarily meaningless on the platform and does not represent the actual parent.

I will try to put the appropriate compat hooks in once this moves into master but I can't promise it will be particularly efficient at this stage.

Regards,
Randall
Emily Shaffer May 20, 2021, 11:23 p.m. UTC | #2
On Thu, May 20, 2021 at 05:36:25PM -0400, Randall S. Becker wrote:
> 
> On May 20, 2021 5:06 PM, Emily Shaffer wrote:
> >To: git@vger.kernel.org
> >Cc: Emily Shaffer <emilyshaffer@google.com>; Ævar Arnfjörð Bjarmason <avarab@gmail.com>; Junio C Hamano <gitster@pobox.com>;
> >Jeff Hostetler <git@jeffhostetler.com>; Bagas Sanjaya <bagasdotme@gmail.com>
> >Subject: [PATCH v2] tr2: log parent process name
> >
> >It can be useful to tell who invoked Git - was it invoked manually by a user via CLI or script? By an IDE?  In some cases - like 'repo' tool -
> >we can influence the source code and set the GIT_TRACE2_PARENT_SID environment variable from the caller process. In 'repo''s case,
> >that parent SID is manipulated to include the string "repo", which means we can positively identify when Git was invoked by 'repo' tool.
> >However, identifying parents that way requires both that we know which tools invoke Git and that we have the ability to modify the source
> >code of those tools. It cannot scale to keep up with the various IDEs and wrappers which use Git, most of which we don't know about.
> >Learning which tools and wrappers invoke Git, and how, would give us insight to decide where to improve Git's usability and performance.
> >
> >Unfortunately, there's no cross-platform reliable way to gather the name of the parent process. If procfs is present, we can use that;
> >otherwise we will need to discover the name another way. However, the process ID should be sufficient regardless of platform.
> 
> I like this idea, but there are some platforms where this is unlikely to work. NonStop, in particular, can initiate git - and I frequently do - from a non-POSIX environment where process name is entirely different. In fact, it is something like $ABC (always beginning with a $, which makes life very difficult for shell scripts and screws up GIT_SSH_COMMAND, but I digress). I'm going to need to plug in something very platform-specific to make this work. getppid() always returns 1 in this situation, which is extraordinarily meaningless on the platform and does not represent the actual parent.

Ok. It sounds like you're saying I should be more conservative in the
commit message as well as in the #ifdef scope? Do you think this needs a
reroll to made the #ifdef more aggressive, or would you rather get to it
when you get to it?

It looks like the change in config.mak.uname won't affect NonStop; I
think also the compat/procinfo.c is probably indicative enough of "this
stuff is for procfs" that it won't look like it *should* work for
NonStop, which means that you should still get the stub for
'trace2_collect_process_info()'. But if you think the guards aren't
readable enough I can try to move them around a little more.

 - Emily
Junio C Hamano May 21, 2021, 2:09 a.m. UTC | #3
Emily Shaffer <emilyshaffer@google.com> writes:

> Unfortunately, there's no cross-platform reliable way to gather the name
> of the parent process. If procfs is present, we can use that; otherwise
> we will need to discover the name another way. However, the process ID
> should be sufficient regardless of platform.

Not a strong objection, but I wonder if seeing random integer(s) is
better than not having cmd_ancestry info at all.  The latter better
signals that the platform does not yet have the "parent process
name" feature, I would think.

> Git for Windows also gathers information about more than one parent. In
> Linux further ancestry info can be gathered with procfs, but it's
> unwieldy to do so. In the interest of later moving Git for Windows
> ancestry logging to the 'cmd_ancestry' event, and in the interest of
> later adding more ancestry to the Linux implementation - or of adding
> this functionality to other platforms which have an easier time walking
> the process tree - let's make 'cmd_ancestry' accept an array of
> parentage.

Could we rephrase "more than one parent" at the beginning to
clarify?  I initially had to wonder what "an array of parentage"
contains (father and mother, or a sole parent and its sole parent,
which is a sole grandparent).  Since there is no "multiple processes
meet and spawn a single process", I take it is the latter.  Perhaps
"more than one generation of" or something?

> +ifdef HAVE_PROCFS_LINUX
> +	BASIC_CFLAGS += -DHAVE_PROCFS_LINUX
> +	COMPAT_OBJS += compat/procinfo.o
> +endif
> +
>  ifdef HAVE_NS_GET_EXECUTABLE_PATH
>  	BASIC_CFLAGS += -DHAVE_NS_GET_EXECUTABLE_PATH
>  endif
> diff --git a/compat/procinfo.c b/compat/procinfo.c
> new file mode 100644
> index 0000000000..523600673f
> --- /dev/null
> +++ b/compat/procinfo.c
> @@ -0,0 +1,53 @@
> +#include "cache.h"
> +
> +#include "strbuf.h"
> +#include "trace2.h"
> +
> +char *get_process_name(int pid)
> +{
> +#ifdef HAVE_PROCFS_LINUX
> +	struct strbuf procfs_path = STRBUF_INIT;
> +	struct strbuf out = STRBUF_INIT;
> +	/* try to use procfs if it's present. */
> +	strbuf_addf(&procfs_path, "/proc/%d/comm", pid);
> +	if (!strbuf_read_file(&out, procfs_path.buf, 0))
> +	{

Place this opening brace at the end of the previous line.

> +		/* All done with file reads, clean up early */
> +		strbuf_release(&procfs_path);
> +		return strbuf_detach(&out, NULL);
> +	}
> +#endif
> +
> +	/* NEEDSWORK: add non-procfs implementations here. */
> +	return NULL;
> +}

> +void trace2_collect_process_info(enum trace2_process_info_reason reason)
> +{
> +	if (!trace2_is_enabled())
> +		return;
> +
> +	/* someday we may want to write something extra here, but not today */
> +	if (reason == TRACE2_PROCESS_INFO_EXIT)
> +		return;
> +
> +	if (reason == TRACE2_PROCESS_INFO_STARTUP)
> +	{

Ditto.

> +		/*
> +		 * NEEDSWORK: we could do the entire ptree in an array instead,
> +		 * see compat/win32/trace2_win32_process_info.c.
> +		 */
> +		char *names[2];
> +		names[0] = get_process_name(getppid());
> +		names[1] = NULL;
> +
> +		if (!names[0])
> +			return;

OK, so if there is no name given, we do not show pid as a
placeholder.

> +		trace2_cmd_ancestry((const char**)names);
> +
> +		free(names[0]);
> +	}
> +
> +	return;
> +}
> diff --git a/config.mak.uname b/config.mak.uname
> index cb443b4e02..7ad110a1d2 100644
> --- a/config.mak.uname
> +++ b/config.mak.uname
> @@ -58,6 +58,7 @@ ifeq ($(uname_S),Linux)
>  	FREAD_READS_DIRECTORIES = UnfortunatelyYes
>  	BASIC_CFLAGS += -DHAVE_SYSINFO
>  	PROCFS_EXECUTABLE_PATH = /proc/self/exe
> +	HAVE_PROCFS_LINUX = YesPlease

Have all Linux instances procfs enabled and mounted?  It might be
that we need to detect this at runtime anyway?

    ... goes and thinks ...

Ah, OK, that "try reading from proc/%d/comm" is the runtime
detection, so it is only this Makefile variable is slightly
misnamed (it is not "HAVE" but "is worth checking for it").

Makes sense.
Randall S. Becker May 21, 2021, 1:20 p.m. UTC | #4
On May 20, 2021 7:24 PM, Emily Shaffer wrote:
>
>On Thu, May 20, 2021 at 05:36:25PM -0400, Randall S. Becker wrote:
>>
>> On May 20, 2021 5:06 PM, Emily Shaffer wrote:
>> >To: git@vger.kernel.org
>> >Cc: Emily Shaffer <emilyshaffer@google.com>; Ævar Arnfjörð Bjarmason
>> ><avarab@gmail.com>; Junio C Hamano <gitster@pobox.com>; Jeff
>> >Hostetler <git@jeffhostetler.com>; Bagas Sanjaya
>> ><bagasdotme@gmail.com>
>> >Subject: [PATCH v2] tr2: log parent process name
>> >
>> >It can be useful to tell who invoked Git - was it invoked manually by
>> >a user via CLI or script? By an IDE?  In some cases - like 'repo'
>> >tool - we can influence the source code and set the GIT_TRACE2_PARENT_SID environment variable from the caller process. In
'repo''s
>case, that parent SID is manipulated to include the string "repo", which means we can positively identify when Git was invoked by
'repo'
>tool.
>> >However, identifying parents that way requires both that we know
>> >which tools invoke Git and that we have the ability to modify the source code of those tools. It cannot scale to keep up with
the various
>IDEs and wrappers which use Git, most of which we don't know about.
>> >Learning which tools and wrappers invoke Git, and how, would give us insight to decide where to improve Git's usability and
>performance.
>> >
>> >Unfortunately, there's no cross-platform reliable way to gather the
>> >name of the parent process. If procfs is present, we can use that; otherwise we will need to discover the name another way.
However,
>the process ID should be sufficient regardless of platform.
>>
>> I like this idea, but there are some platforms where this is unlikely to work. NonStop, in particular, can initiate git - and I
frequently do -
>from a non-POSIX environment where process name is entirely different. In fact, it is something like $ABC (always beginning with a
$,
>which makes life very difficult for shell scripts and screws up GIT_SSH_COMMAND, but I digress). I'm going to need to plug in
something
>very platform-specific to make this work. getppid() always returns 1 in this situation, which is extraordinarily meaningless on the
platform
>and does not represent the actual parent.
>
>Ok. It sounds like you're saying I should be more conservative in the commit message as well as in the #ifdef scope? Do you think
this
>needs a reroll to made the #ifdef more aggressive, or would you rather get to it when you get to it?

I'll get to it pretty quickly once it's rolled in.

>It looks like the change in config.mak.uname won't affect NonStop; I think also the compat/procinfo.c is probably indicative enough
of "this
>stuff is for procfs" that it won't look like it *should* work for NonStop, which means that you should still get the stub for
>'trace2_collect_process_info()'. But if you think the guards aren't readable enough I can try to move them around a little more.

Guards are fine. There's just a lot more work to do for me. We need to make sure that the rendering of ancestor processes are
generic enough not to be just pid_t through any interfaces where this is queried. In NonStop's case, char[25], should be sufficient
for the short term, but I would prefer something longer, say char[128] to be safe for the future in which to stick the ancestor. To
be completely unique, the ancestor is going to look like \node.$proc:sequence (where node is a 7 character name, proc is a 5
character name, and sequence is currently a long.

-Randall
Randall S. Becker May 21, 2021, 4:24 p.m. UTC | #5
On May 21, 2021 9:21 AM, I wrote:
>To: 'Emily Shaffer' <emilyshaffer@google.com>
>Cc: git@vger.kernel.org; 'Ævar Arnfjörð Bjarmason' <avarab@gmail.com>; 'Junio C Hamano' <gitster@pobox.com>; 'Jeff Hostetler'
><git@jeffhostetler.com>; 'Bagas Sanjaya' <bagasdotme@gmail.com>
>Subject: RE: [PATCH v2] tr2: log parent process name
>
>On May 20, 2021 7:24 PM, Emily Shaffer wrote:
>>
>>On Thu, May 20, 2021 at 05:36:25PM -0400, Randall S. Becker wrote:
>>>
>>> On May 20, 2021 5:06 PM, Emily Shaffer wrote:
>>> >To: git@vger.kernel.org
>>> >Cc: Emily Shaffer <emilyshaffer@google.com>; Ævar Arnfjörð Bjarmason
>>> ><avarab@gmail.com>; Junio C Hamano <gitster@pobox.com>; Jeff
>>> >Hostetler <git@jeffhostetler.com>; Bagas Sanjaya
>>> ><bagasdotme@gmail.com>
>>> >Subject: [PATCH v2] tr2: log parent process name
>>> >
>>> >It can be useful to tell who invoked Git - was it invoked manually
>>> >by a user via CLI or script? By an IDE?  In some cases - like 'repo'
>>> >tool - we can influence the source code and set the
>>> >GIT_TRACE2_PARENT_SID environment variable from the caller process.
>>> >In
>'repo''s
>>case, that parent SID is manipulated to include the string "repo",
>>which means we can positively identify when Git was invoked by
>'repo'
>>tool.
>>> >However, identifying parents that way requires both that we know
>>> >which tools invoke Git and that we have the ability to modify the
>>> >source code of those tools. It cannot scale to keep up with
>the various
>>IDEs and wrappers which use Git, most of which we don't know about.
>>> >Learning which tools and wrappers invoke Git, and how, would give us
>>> >insight to decide where to improve Git's usability and
>>performance.
>>> >
>>> >Unfortunately, there's no cross-platform reliable way to gather the
>>> >name of the parent process. If procfs is present, we can use that; otherwise we will need to discover the name another way.
>However,
>>the process ID should be sufficient regardless of platform.
>>>
>>> I like this idea, but there are some platforms where this is unlikely
>>> to work. NonStop, in particular, can initiate git - and I
>frequently do -
>>from a non-POSIX environment where process name is entirely different.
>>In fact, it is something like $ABC (always beginning with a
>$,
>>which makes life very difficult for shell scripts and screws up
>>GIT_SSH_COMMAND, but I digress). I'm going to need to plug in
>something
>>very platform-specific to make this work. getppid() always returns 1 in
>>this situation, which is extraordinarily meaningless on the
>platform
>>and does not represent the actual parent.
>>
>>Ok. It sounds like you're saying I should be more conservative in the
>>commit message as well as in the #ifdef scope? Do you think
>this
>>needs a reroll to made the #ifdef more aggressive, or would you rather get to it when you get to it?
>
>I'll get to it pretty quickly once it's rolled in.
>
>>It looks like the change in config.mak.uname won't affect NonStop; I
>>think also the compat/procinfo.c is probably indicative enough
>of "this
>>stuff is for procfs" that it won't look like it *should* work for
>>NonStop, which means that you should still get the stub for 'trace2_collect_process_info()'. But if you think the guards aren't
readable
>enough I can try to move them around a little more.
>
>Guards are fine. There's just a lot more work to do for me. We need to make sure that the rendering of ancestor processes are
generic
>enough not to be just pid_t through any interfaces where this is queried. In NonStop's case, char[25], should be sufficient for the
short
>term, but I would prefer something longer, say char[128] to be safe for the future in which to stick the ancestor. To be completely
unique,
>the ancestor is going to look like \node.$proc:sequence (where node is a 7 character name, proc is a 5 character name, and sequence
is
>currently a long.

Just so we know what's coming, the code snippet to get a parent on NonStop is as follows (roughly):
        pid_t ossParent = getppid();
        if (ossParent == 1) {
                short pHandle[10];
                short pAncestor[10];
                short ancestorLength;
                short error;
                short attributes[] = { 40 }; /* MOM Process */
                short processNameLength;
                char processName[64];

                PROCESSHANDLE_NULLIT_(pHandle);
                PROCESS_GETINFO_(pHandle);
                error = PROCESS_GETINFOLIST_(,,,, pHandle,
                        attributes, (short) sizeof(attributes)/sizeof(attributes[0]),
                        pAncestor, (short) sizeof(pAncestor), &ancestorLength);
                if (error) {
                        printf("Cannot process parent. Error %d\n", error);
                        return;
                }
                PROCESSHANDLE_TO_FILENAME_(pAncestor, processName, (short) sizeof(processName),
                        &processNameLength);
                processName[processNameLength] = '\0';
                printf("GUARDIAN Parent %s\n", processName);
        } else {
                printf("OSS Parent %d\n", ossParent);
        }

Which in the test program generates
GUARDIAN Parent \HPITUG.$:3:1100:583555076

Regards,
Randall
Emily Shaffer May 21, 2021, 7:02 p.m. UTC | #6
On Fri, May 21, 2021 at 11:09:49AM +0900, Junio C Hamano wrote:
> 
> Emily Shaffer <emilyshaffer@google.com> writes:
> 
> > Unfortunately, there's no cross-platform reliable way to gather the name
> > of the parent process. If procfs is present, we can use that; otherwise
> > we will need to discover the name another way. However, the process ID
> > should be sufficient regardless of platform.
> 
> Not a strong objection, but I wonder if seeing random integer(s) is
> better than not having cmd_ancestry info at all.  The latter better
> signals that the platform does not yet have the "parent process
> name" feature, I would think.

Hm, we could; I guess then analyzers could still correlate "all these
things were called by some kind of wrapper, even if we don't know if
that was an IDE or a script or just the user or what, we can guess based
on other heuristics". Ok.

> 
> > Git for Windows also gathers information about more than one parent. In
> > Linux further ancestry info can be gathered with procfs, but it's
> > unwieldy to do so. In the interest of later moving Git for Windows
> > ancestry logging to the 'cmd_ancestry' event, and in the interest of
> > later adding more ancestry to the Linux implementation - or of adding
> > this functionality to other platforms which have an easier time walking
> > the process tree - let's make 'cmd_ancestry' accept an array of
> > parentage.
> 
> Could we rephrase "more than one parent" at the beginning to
> clarify?  I initially had to wonder what "an array of parentage"
> contains (father and mother, or a sole parent and its sole parent,
> which is a sole grandparent).  Since there is no "multiple processes
> meet and spawn a single process", I take it is the latter.  Perhaps
> "more than one generation of" or something?

Good point, will refer to "more than one generation". Thanks.

> > +	if (!strbuf_read_file(&out, procfs_path.buf, 0))
> > +	{
> 
> Place this opening brace at the end of the previous line.

Will polish up this and others for v3, hopefully today.
> > +		if (!names[0])
> > +			return;
> 
> OK, so if there is no name given, we do not show pid as a
> placeholder.

Based on your suggestion above I think it will make sense to show pid as
placeholder after all, though. So I will change that for v3.

> >  	PROCFS_EXECUTABLE_PATH = /proc/self/exe
> > +	HAVE_PROCFS_LINUX = YesPlease
> 
> Have all Linux instances procfs enabled and mounted?  It might be
> that we need to detect this at runtime anyway?
> 
>     ... goes and thinks ...
> 
> Ah, OK, that "try reading from proc/%d/comm" is the runtime
> detection, so it is only this Makefile variable is slightly
> misnamed (it is not "HAVE" but "is worth checking for it").

I wonder what is better. "MAYBE_PROCFS_LINUX"? I don't see any other
vars in config.mak.uname that indicate "pretty sure but not totally
sure" in a quick scan. However, right above this line we seem to feel
certain in our guess about "PROCFS_EXECUTABLE_PATH"...

...but when it is used in exec-cmd.c:git_get_exec_path_procfs(), invoked
by exec-cmd.c:git_get_exec_path(), we're very tolerant to faults if it's
not there:

  static int git_get_exec_path(struct strbuf *buf, const char *argv0)
  {
  	/*
  	 * [snip]
  	 * Each of these functions returns 0 on success, so evaluation will stop
  	 * after the first successful method.
  	 */
  	if (
  #ifdef HAVE_BSD_KERN_PROC_SYSCTL
  		git_get_exec_path_bsd_sysctl(buf) &&
  #endif /* HAVE_BSD_KERN_PROC_SYSCTL */
  
  #ifdef HAVE_NS_GET_EXECUTABLE_PATH
  		git_get_exec_path_darwin(buf) &&
  #endif /* HAVE_NS_GET_EXECUTABLE_PATH */
  
  #ifdef PROCFS_EXECUTABLE_PATH
  		git_get_exec_path_procfs(buf) &&  /*** <- OK if fails ***/
  #endif /* PROCFS_EXECUTABLE_PATH */
  
  #ifdef HAVE_WPGMPTR
  		git_get_exec_path_wpgmptr(buf) &&
  #endif /* HAVE_WPGMPTR */
  
  		git_get_exec_path_from_argv0(buf, argv0)) {
  		return -1;
  	}
  
  [snip]
  
  #ifdef PROCFS_EXECUTABLE_PATH
  /*
   * Resolves the executable path by examining a procfs symlink.
   *
   * Returns 0 on success, -1 on failure.
   */
  static int git_get_exec_path_procfs(struct strbuf *buf)
  {
  	if (strbuf_realpath(buf, PROCFS_EXECUTABLE_PATH, 0)) {
  		trace_printf(
  			"trace: resolved executable path from procfs: %s\n",
  			buf->buf);
  		return 0;
  	}
  	return -1;
  }
  #endif /* PROCFS_EXECUTABLE_PATH */


So it seems this other procfs bit takes the "probably but not
definitely" step and is tolerant at runtime as well. Which doesn't help
me much to decide how to rename HAVE_PROCFS_LINUX.

I'll switch it to MAYBE_PROCFS_LINUX for v3 unless someone yells, I
guess.

 - Emily
Jeff Hostetler May 21, 2021, 7:15 p.m. UTC | #7
On 5/20/21 5:05 PM, Emily Shaffer wrote:
> It can be useful to tell who invoked Git - was it invoked manually by a
> user via CLI or script? By an IDE?  In some cases - like 'repo' tool -
> we can influence the source code and set the GIT_TRACE2_PARENT_SID
> environment variable from the caller process. In 'repo''s case, that
> parent SID is manipulated to include the string "repo", which means we
> can positively identify when Git was invoked by 'repo' tool. However,
> identifying parents that way requires both that we know which tools
> invoke Git and that we have the ability to modify the source code of
> those tools. It cannot scale to keep up with the various IDEs and
> wrappers which use Git, most of which we don't know about. Learning
> which tools and wrappers invoke Git, and how, would give us insight to
> decide where to improve Git's usability and performance.
> 
> Unfortunately, there's no cross-platform reliable way to gather the name
> of the parent process. If procfs is present, we can use that; otherwise
> we will need to discover the name another way. However, the process ID
> should be sufficient regardless of platform.
> 
> Git for Windows gathers similar information and logs it as a "data_json"
> event. However, since "data_json" has a variable format, it is difficult
> to parse effectively in some languages; instead, let's pursue a
> dedicated "cmd_ancestry" event to record information about the ancestry
> of the current process and a consistent, parseable way.
> 
> Git for Windows also gathers information about more than one parent. In
> Linux further ancestry info can be gathered with procfs, but it's
> unwieldy to do so. In the interest of later moving Git for Windows
> ancestry logging to the 'cmd_ancestry' event, and in the interest of
> later adding more ancestry to the Linux implementation - or of adding
> this functionality to other platforms which have an easier time walking
> the process tree - let's make 'cmd_ancestry' accept an array of
> parentage.
> 
> Signed-off-by: Emily Shaffer <emilyshaffer@google.com>
> ---
> 
> Hi folks, the comments I received in v1 were of two varieties:
> 1) "There are better ways to make this platform-safe", and
> 2) "Your commit message doesn't convince me".
> Since I sent v1, though, I also learned a little more about procfs, and
> about the trace2 structure overall, so there are some pretty significant
> differences from v1:
> 
> - I took a look at Jeff H's advice on using a "data_json" event to log
>    this and decided it would be a little more flexible to add a new event
>    instead. If we want, it'd be feasible to then shoehorn the GfW parent
>    tree stuff into this new event too. Doing it this way is definitely
>    easier to parse for Google's trace analysis system (which for now
>    completely skips "data_json" as it's polymorphic), and also - I think
>    - means that we can add more fields later on if we need to (thread
>    info, different fields than just /proc/n/comm like exec path, argv,
>    whatever).

I could argue both sides of this, so I guess it is fine either way.

In GFW I log a array of argv[0] strings in a generic "data_json" event.
I could also log additional "data_json" events with more structured
data if needed.

On the other hand, you're proposing a "cmd_ancestry" event with a
single array of strings.  You would have to expand the call signature
of the trace2_cmd_ancestry() API to add additional data and inside
tr2_tgt_event.c add additional fields to the JSON being composed.

So both are about equal.

(I'll avoid the temptation to make a snarky comment about fixing
your post processing. :-) :-) :-) )

It really doesn't matter one way or the other.

> - Jonathan N also pointed out to me that /proc/n/comm exists, and logs
>    the "command name" - excluding argv, excluding path, etc. It seems

So you're trying to log argv[0] of the process and not the full
command line.  That's what I'm doing.

>    like this is a little more safe about excluding personal information
>    from the traces which take the form of "myscript.sh
>    --password=hunter2", but would still be worrisome for something like
>    "mysupersecretproject.sh". I'm not sure whether that means we still
>    want to guard it with a config flag, though.

You might check whether you get the name of the script or just get
a lot of entries with just "/usr/bin/bash".

There's lots of PII in the data stream to worry about.
The name of the command is just one aspect, but I digress.

> - I also added a lot to the commit message; hopefully it's not too
>    rambly, but I hoped to explain why just setting GIT_TRACE2_PARENT_SID
>    wasn't going to cut it.
> - As for testing, I followed the lead of GfW's parentage info - "this
>    isn't portable so writing tests for it will suck, just scrub it from
>    the tests". Maybe it makes sense to do some more
>    platform-specific-ness in the test suite instead? I wasn't sure.

yeah, that's probably best.  Unless you can tokenize it properly
so that you can predict the results in a HEREDOC in the test source.

For example, you might try to test tracing a command (where a top-level
"git foo" (SPACE form) spawns a "git-foo" (DASHED form) and check the
output for the child.

> 
> Thanks, all.
>   - Emily
> 
>   Makefile                  |  5 ++++
>   compat/procinfo.c         | 53 +++++++++++++++++++++++++++++++++++++++
>   config.mak.uname          |  1 +
>   git-compat-util.h         |  6 +++++
>   t/t0210/scrub_normal.perl |  6 +++++
>   t/t0211/scrub_perf.perl   |  5 ++++
>   t/t0212/parse_events.perl |  5 +++-
>   trace2.c                  | 13 ++++++++++
>   trace2.h                  | 12 ++++++++-
>   trace2/tr2_tgt.h          |  3 +++
>   trace2/tr2_tgt_event.c    | 21 ++++++++++++++++
>   trace2/tr2_tgt_normal.c   | 19 ++++++++++++++
>   trace2/tr2_tgt_perf.c     | 16 ++++++++++++
>   13 files changed, 163 insertions(+), 2 deletions(-)
>   create mode 100644 compat/procinfo.c
> 
> diff --git a/Makefile b/Makefile
> index 93664d6714..330e4fa011 100644
> --- a/Makefile
> +++ b/Makefile
> @@ -1889,6 +1889,11 @@ ifneq ($(PROCFS_EXECUTABLE_PATH),)
>   	BASIC_CFLAGS += '-DPROCFS_EXECUTABLE_PATH="$(procfs_executable_path_SQ)"'
>   endif
>   
> +ifdef HAVE_PROCFS_LINUX
> +	BASIC_CFLAGS += -DHAVE_PROCFS_LINUX
> +	COMPAT_OBJS += compat/procinfo.o
> +endif
> +
>   ifdef HAVE_NS_GET_EXECUTABLE_PATH
>   	BASIC_CFLAGS += -DHAVE_NS_GET_EXECUTABLE_PATH
>   endif
> diff --git a/compat/procinfo.c b/compat/procinfo.c
> new file mode 100644
> index 0000000000..523600673f
> --- /dev/null
> +++ b/compat/procinfo.c
> @@ -0,0 +1,53 @@
> +#include "cache.h"
> +
> +#include "strbuf.h"
> +#include "trace2.h"
> +
> +char *get_process_name(int pid)
> +{
> +#ifdef HAVE_PROCFS_LINUX
> +	struct strbuf procfs_path = STRBUF_INIT;
> +	struct strbuf out = STRBUF_INIT;
> +	/* try to use procfs if it's present. */
> +	strbuf_addf(&procfs_path, "/proc/%d/comm", pid);
> +	if (!strbuf_read_file(&out, procfs_path.buf, 0))
> +	{
> +		/* All done with file reads, clean up early */
> +		strbuf_release(&procfs_path);
> +		return strbuf_detach(&out, NULL);
> +	}
> +#endif
> +
> +	/* NEEDSWORK: add non-procfs implementations here. */
> +	return NULL;
> +}
> +
> +void trace2_collect_process_info(enum trace2_process_info_reason reason)
> +{
> +	if (!trace2_is_enabled())
> +		return;
> +
> +	/* someday we may want to write something extra here, but not today */
> +	if (reason == TRACE2_PROCESS_INFO_EXIT)
> +		return;
> +
> +	if (reason == TRACE2_PROCESS_INFO_STARTUP)
> +	{
> +		/*
> +		 * NEEDSWORK: we could do the entire ptree in an array instead,
> +		 * see compat/win32/trace2_win32_process_info.c.
> +		 */
> +		char *names[2];
> +		names[0] = get_process_name(getppid());
> +		names[1] = NULL;

You're only logging 1 parent.  That's fine to get started.

I'm logging IIRC 10 parents on GFW.  That might seem overkill,
but there are lots of intermediate parents that hide what is
happening.  For example, a "git push" might spawn "git remote-https"
which spawns "git-remote-https" which spawn "git send-pack" which
spawns "git pack-objects".

And that doesn't include who called push.

And it's not uncommon to see 2 or 3 "bash" entries in the array
because of the bash scripts being run.

> +
> +		if (!names[0])
> +			return;
> +
> +		trace2_cmd_ancestry((const char**)names);
> +
> +		free(names[0]);
> +	}
> +
> +	return;
> +}
> diff --git a/config.mak.uname b/config.mak.uname
> index cb443b4e02..7ad110a1d2 100644
> --- a/config.mak.uname
> +++ b/config.mak.uname
> @@ -58,6 +58,7 @@ ifeq ($(uname_S),Linux)
>   	FREAD_READS_DIRECTORIES = UnfortunatelyYes
>   	BASIC_CFLAGS += -DHAVE_SYSINFO
>   	PROCFS_EXECUTABLE_PATH = /proc/self/exe
> +	HAVE_PROCFS_LINUX = YesPlease
>   endif
>   ifeq ($(uname_S),GNU/kFreeBSD)
>   	HAVE_ALLOCA_H = YesPlease
> diff --git a/git-compat-util.h b/git-compat-util.h
> index a508dbe5a3..cc7d5d8a2a 100644
> --- a/git-compat-util.h
> +++ b/git-compat-util.h
> @@ -1382,4 +1382,10 @@ static inline void *container_of_or_null_offset(void *ptr, size_t offset)
>   
>   void sleep_millisec(int millisec);
>   
> +/*
> + * Convert PID to process name (as would show in top/task manager). Returns
> + * NULL if unimplemented - be sure to check for NULL at callsite.
> + */
> +char *get_process_name(int pid);
> +
>   #endif
> diff --git a/t/t0210/scrub_normal.perl b/t/t0210/scrub_normal.perl
> index c65d1a815e..7cc4de392a 100644
> --- a/t/t0210/scrub_normal.perl
> +++ b/t/t0210/scrub_normal.perl
> @@ -42,6 +42,12 @@
>   	# so just omit it for testing purposes.
>   	# print "cmd_path _EXE_\n";
>       }
> +    elsif ($line =~ m/^cmd_ancestry/) {
> +	# 'cmd_ancestry' is not implemented everywhere, so for portability's
> +	# sake, skip it when parsing normal.
> +	#
> +	# print "$line";
> +    }
>       else {
>   	print "$line";
>       }
> diff --git a/t/t0211/scrub_perf.perl b/t/t0211/scrub_perf.perl
> index 351af7844e..d164b750ff 100644
> --- a/t/t0211/scrub_perf.perl
> +++ b/t/t0211/scrub_perf.perl
> @@ -44,6 +44,11 @@
>   	# $tokens[$col_rest] = "_EXE_";
>   	goto SKIP_LINE;
>       }
> +    elsif ($tokens[$col_event] =~ m/cmd_ancestry/) {
> +	# 'cmd_ancestry' is platform-specific and not implemented everywhere,
> +	# so skip it.
> +	goto SKIP_LINE;
> +    }
>       elsif ($tokens[$col_event] =~ m/child_exit/) {
>   	$tokens[$col_rest] =~ s/ pid:\d* / pid:_PID_ /;
>       }
> diff --git a/t/t0212/parse_events.perl b/t/t0212/parse_events.perl
> index 6584bb5634..b6408560c0 100644
> --- a/t/t0212/parse_events.perl
> +++ b/t/t0212/parse_events.perl
> @@ -132,7 +132,10 @@
>   	# just omit it for testing purposes.
>   	# $processes->{$sid}->{'path'} = "_EXE_";
>       }
> -
> +    elsif ($event eq 'cmd_ancestry') {
> +	# 'cmd_ancestry' is platform-specific and not implemented everywhere, so
> +	# just skip it for testing purposes.
> +    }
>       elsif ($event eq 'cmd_name') {
>   	$processes->{$sid}->{'name'} = $line->{'name'};
>   	$processes->{$sid}->{'hierarchy'} = $line->{'hierarchy'};
> diff --git a/trace2.c b/trace2.c
> index 256120c7fd..b9b154ac44 100644
> --- a/trace2.c
> +++ b/trace2.c
> @@ -260,6 +260,19 @@ void trace2_cmd_path_fl(const char *file, int line, const char *pathname)
>   			tgt_j->pfn_command_path_fl(file, line, pathname);
>   }
>   
> +void trace2_cmd_ancestry_fl(const char *file, int line, const char **parent_names)
> +{
> +	struct tr2_tgt *tgt_j;
> +	int j;
> +
> +	if (!trace2_enabled)
> +		return;
> +
> +	for_each_wanted_builtin (j, tgt_j)
> +		if (tgt_j->pfn_command_ancestry_fl)
> +			tgt_j->pfn_command_ancestry_fl(file, line, parent_names);
> +}
> +
>   void trace2_cmd_name_fl(const char *file, int line, const char *name)
>   {
>   	struct tr2_tgt *tgt_j;
> diff --git a/trace2.h b/trace2.h
> index ede18c2e06..23743ac62b 100644
> --- a/trace2.h
> +++ b/trace2.h
> @@ -133,6 +133,16 @@ void trace2_cmd_path_fl(const char *file, int line, const char *pathname);
>   
>   #define trace2_cmd_path(p) trace2_cmd_path_fl(__FILE__, __LINE__, (p))
>   
> +/*
> + * Emit an 'ancestry' event with the process name of the current process's
> + * parent process.
> + * This gives post-processors a way to determine what invoked the command and
> + * learn more about usage patterns.
> + */
> +void trace2_cmd_ancestry_fl(const char *file, int line, const char **parent_names);
> +
> +#define trace2_cmd_ancestry(v) trace2_cmd_ancestry_fl(__FILE__, __LINE__, (v))
> +
>   /*
>    * Emit a 'cmd_name' event with the canonical name of the command.
>    * This gives post-processors a simple field to identify the command
> @@ -492,7 +502,7 @@ enum trace2_process_info_reason {
>   	TRACE2_PROCESS_INFO_EXIT,
>   };
>   
> -#if defined(GIT_WINDOWS_NATIVE)
> +#if ( defined(GIT_WINDOWS_NATIVE) || defined(HAVE_PROCFS_LINUX) )
>   void trace2_collect_process_info(enum trace2_process_info_reason reason);
>   #else
>   #define trace2_collect_process_info(reason) \
> diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h
> index 7b90469212..1f66fd6573 100644
> --- a/trace2/tr2_tgt.h
> +++ b/trace2/tr2_tgt.h
> @@ -27,6 +27,8 @@ typedef void(tr2_tgt_evt_error_va_fl_t)(const char *file, int line,
>   
>   typedef void(tr2_tgt_evt_command_path_fl_t)(const char *file, int line,
>   					    const char *command_path);
> +typedef void(tr2_tgt_evt_command_ancestry_fl_t)(const char *file, int line,
> +						const char **parent_names);
>   typedef void(tr2_tgt_evt_command_name_fl_t)(const char *file, int line,
>   					    const char *name,
>   					    const char *hierarchy);
> @@ -108,6 +110,7 @@ struct tr2_tgt {
>   	tr2_tgt_evt_atexit_t                    *pfn_atexit;
>   	tr2_tgt_evt_error_va_fl_t               *pfn_error_va_fl;
>   	tr2_tgt_evt_command_path_fl_t           *pfn_command_path_fl;
> +	tr2_tgt_evt_command_ancestry_fl_t	*pfn_command_ancestry_fl;
>   	tr2_tgt_evt_command_name_fl_t           *pfn_command_name_fl;
>   	tr2_tgt_evt_command_mode_fl_t           *pfn_command_mode_fl;
>   	tr2_tgt_evt_alias_fl_t                  *pfn_alias_fl;
> diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c
> index 6353e8ad91..578a9a5287 100644
> --- a/trace2/tr2_tgt_event.c
> +++ b/trace2/tr2_tgt_event.c
> @@ -261,6 +261,26 @@ static void fn_command_path_fl(const char *file, int line, const char *pathname)
>   	jw_release(&jw);
>   }
>   
> +static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names)
> +{
> +	const char *event_name = "cmd_ancestry";
> +	const char *parent_name = NULL;
> +	struct json_writer jw = JSON_WRITER_INIT;
> +
> +	jw_object_begin(&jw, 0);
> +	event_fmt_prepare(event_name, file, line, NULL, &jw);
> +	jw_object_inline_begin_array(&jw, "ancestry");
> +
> +	while ((parent_name = *parent_names++))
> +		jw_array_string(&jw, parent_name);

You're building the array with the immediate parent in a[0]
and the grandparent in a[1], and etc.  This is the same as
I did in GFW.

Perhaps state this in the docs somewhere.

> +
> +	jw_end(&jw); /* 'ancestry' array */
> +	jw_end(&jw); /* event object */
> +
> +	tr2_dst_write_line(&tr2dst_event, &jw.json);
> +	jw_release(&jw);
> +}
> +
>   static void fn_command_name_fl(const char *file, int line, const char *name,
>   			       const char *hierarchy)
>   {
> @@ -584,6 +604,7 @@ struct tr2_tgt tr2_tgt_event = {
>   	fn_atexit,
>   	fn_error_va_fl,
>   	fn_command_path_fl,
> +	fn_command_ancestry_fl,
>   	fn_command_name_fl,
>   	fn_command_mode_fl,
>   	fn_alias_fl,
> diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c
> index 31b602c171..a5751c8864 100644
> --- a/trace2/tr2_tgt_normal.c
> +++ b/trace2/tr2_tgt_normal.c
> @@ -160,6 +160,24 @@ static void fn_command_path_fl(const char *file, int line, const char *pathname)
>   	strbuf_release(&buf_payload);
>   }
>   
> +static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names)
> +{
> +	const char *parent_name = NULL;
> +	struct strbuf buf_payload = STRBUF_INIT;
> +
> +	/* cmd_ancestry parent <- grandparent <- great-grandparent */
> +	strbuf_addstr(&buf_payload, "cmd_ancestry ");
> +	while ((parent_name = *parent_names++)) {
> +		strbuf_addstr(&buf_payload, parent_name);

Did you want to quote each parent's name?

> +		/* if we'll write another one after this, add a delimiter */
> +		if (parent_names && *parent_names)
> +			strbuf_addstr(&buf_payload, " <- ");
> +	}
> +
> +	normal_io_write_fl(file, line, &buf_payload);
> +	strbuf_release(&buf_payload);
> +}
> +
>   static void fn_command_name_fl(const char *file, int line, const char *name,
>   			       const char *hierarchy)
>   {
> @@ -306,6 +324,7 @@ struct tr2_tgt tr2_tgt_normal = {
>   	fn_atexit,
>   	fn_error_va_fl,
>   	fn_command_path_fl,
> +	fn_command_ancestry_fl,
>   	fn_command_name_fl,
>   	fn_command_mode_fl,
>   	fn_alias_fl,
> diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c
> index a8018f18cc..af4d65a0a5 100644
> --- a/trace2/tr2_tgt_perf.c
> +++ b/trace2/tr2_tgt_perf.c
> @@ -253,6 +253,21 @@ static void fn_command_path_fl(const char *file, int line, const char *pathname)
>   	strbuf_release(&buf_payload);
>   }
>   
> +static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names)
> +{
> +	const char *event_name = "cmd_ancestry";
> +	struct strbuf buf_payload = STRBUF_INIT;
> +
> +	strbuf_addstr(&buf_payload, "ancestry:[");
> +	/* It's not an argv but the rules are basically the same. */
> +	sq_append_quote_argv_pretty(&buf_payload, parent_names);

This will have whitespace delimiters between the quoted strings
rather than commas.  Just checking if that's what you wanted.

I'm not sure it matters, since this stream is intended for human
parsing.

> +	strbuf_addch(&buf_payload, ']');
> +
> +	perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
> +			 &buf_payload);
> +	strbuf_release(&buf_payload);
> +}
> +
>   static void fn_command_name_fl(const char *file, int line, const char *name,
>   			       const char *hierarchy)
>   {
> @@ -532,6 +547,7 @@ struct tr2_tgt tr2_tgt_perf = {
>   	fn_atexit,
>   	fn_error_va_fl,
>   	fn_command_path_fl,
> +	fn_command_ancestry_fl,
>   	fn_command_name_fl,
>   	fn_command_mode_fl,
>   	fn_alias_fl,
> 

We should update Documentation/technical/api-trace2.txt too.

Thanks,
Jeff
Emily Shaffer May 21, 2021, 8:05 p.m. UTC | #8
On Fri, May 21, 2021 at 03:15:16PM -0400, Jeff Hostetler wrote:
> On 5/20/21 5:05 PM, Emily Shaffer wrote:
> > - I took a look at Jeff H's advice on using a "data_json" event to log
> >    this and decided it would be a little more flexible to add a new event
> >    instead. If we want, it'd be feasible to then shoehorn the GfW parent
> >    tree stuff into this new event too. Doing it this way is definitely
> >    easier to parse for Google's trace analysis system (which for now
> >    completely skips "data_json" as it's polymorphic), and also - I think
> >    - means that we can add more fields later on if we need to (thread
> >    info, different fields than just /proc/n/comm like exec path, argv,
> >    whatever).
> 
> I could argue both sides of this, so I guess it is fine either way.
> 
> In GFW I log a array of argv[0] strings in a generic "data_json" event.
> I could also log additional "data_json" events with more structured
> data if needed.
> 
> On the other hand, you're proposing a "cmd_ancestry" event with a
> single array of strings.  You would have to expand the call signature
> of the trace2_cmd_ancestry() API to add additional data and inside
> tr2_tgt_event.c add additional fields to the JSON being composed.
> 
> So both are about equal.
> 
> (I'll avoid the temptation to make a snarky comment about fixing
> your post processing. :-) :-) :-) )

;P

(I don't have much to add - this is an accurate summary of what I
thought about, too. Thanks for writing it out.)

> 
> It really doesn't matter one way or the other.
> 
> > - Jonathan N also pointed out to me that /proc/n/comm exists, and logs
> >    the "command name" - excluding argv, excluding path, etc. It seems
> 
> So you're trying to log argv[0] of the process and not the full
> command line.  That's what I'm doing.

It's close to argv[0], yeah. POSIX docs indicate it might be truncated
in a way that argv[0] hasn't been, but it also doesn't include the
leading path (as far as I've seen). For example, a long-running helper
script I use with mutt, right now (gaffing on line length in email to
help with argv clarity, sorry):

  $ ps aux | grep mutt
  emilysh+ 4119883  0.0  0.0   6892  3600 pts/6    S+   12:44   0:00 /bin/bash /usr/local/google/home/emilyshaffer/dotfiles/open-vim-in-new-split.sh /var/tmp/mutt-podkayne-413244-1263002-7433772284891386689
  # comm is truncated to 15ch, except apparently in the cases of some
  # kernel worker processes I saw with much longer names?
  $ cat /proc/4119883/comm
  open-vim-in-new
  # exe is a link to the executable, which means bash as this is a
  # script
  $ ls -lha /proc/4119883/exe
  lrwxrwxrwx 1 emilyshaffer primarygroup 0 May 21 12:44
  /proc/4119883/exe -> /usr/bin/bash
  # cmdline has the whole argv, separated on NUL so it runs together in
  # editor
  $ cat /proc/4119883/cmdline
  /bin/bash/usr/local/google/home/emilyshaffer/dotfiles/open-vim-in-new-split.sh/var/tmp/mutt-podkayne-413244-1263002-7433772284891386689

Jonathan N pointed out that the process name (the thing in 'comm') can
also be manually manipulated by the process itself, and 'man procfs'
also talks about 'PR_SET_NAME' and 'PR_GET_NAME' operations in
'prctl()', so that tracks. (It doesn't look like we can use prctl() to
find out the names of processes besides the current process, though, so
the procfs stuff is still needed. Dang.)

> 
> >    like this is a little more safe about excluding personal information
> >    from the traces which take the form of "myscript.sh
> >    --password=hunter2", but would still be worrisome for something like
> >    "mysupersecretproject.sh". I'm not sure whether that means we still
> >    want to guard it with a config flag, though.
> 
> You might check whether you get the name of the script or just get
> a lot of entries with just "/usr/bin/bash".

See above :)

> There's lots of PII in the data stream to worry about.
> The name of the command is just one aspect, but I digress.

Yes, that's what we've noticed too, so a process name isn't worrying us
that much more.

> 
> > - I also added a lot to the commit message; hopefully it's not too
> >    rambly, but I hoped to explain why just setting GIT_TRACE2_PARENT_SID
> >    wasn't going to cut it.
> > - As for testing, I followed the lead of GfW's parentage info - "this
> >    isn't portable so writing tests for it will suck, just scrub it from
> >    the tests". Maybe it makes sense to do some more
> >    platform-specific-ness in the test suite instead? I wasn't sure.
> 
> yeah, that's probably best.  Unless you can tokenize it properly
> so that you can predict the results in a HEREDOC in the test source.
> 
> For example, you might try to test tracing a command (where a top-level
> "git foo" (SPACE form) spawns a "git-foo" (DASHED form) and check the
> output for the child.

Yeah, I had trouble with even deciding when to attempt such a check or
not.
> > +	if (reason == TRACE2_PROCESS_INFO_STARTUP)
> > +	{
> > +		/*
> > +		 * NEEDSWORK: we could do the entire ptree in an array instead,
> > +		 * see compat/win32/trace2_win32_process_info.c.
> > +		 */
> > +		char *names[2];
> > +		names[0] = get_process_name(getppid());
> > +		names[1] = NULL;
> 
> You're only logging 1 parent.  That's fine to get started.
> 
> I'm logging IIRC 10 parents on GFW.  That might seem overkill,
> but there are lots of intermediate parents that hide what is
> happening.  For example, a "git push" might spawn "git remote-https"
> which spawns "git-remote-https" which spawn "git send-pack" which
> spawns "git pack-objects".
> 
> And that doesn't include who called push.
> 
> And it's not uncommon to see 2 or 3 "bash" entries in the array
> because of the bash scripts being run.

Agree. But it's expensive - I didn't find a handy library call to find
"parent ID of given process ID", so I think we'd have to manipulate
procfs; and so far I only see parent ID in summary infos like
/proc/n/status or /proc/n/stat, which contain lots of other info too and
would need parsing.

We could reduce the cost a little bit by grabbing the process name from
the status or stat as well, and therefore still only opening one file per
process, but I'd want to check whether the formats are expected to be
stable for those things.

> > +static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names)
> > +{
> > +	const char *event_name = "cmd_ancestry";
> > +	const char *parent_name = NULL;
> > +	struct json_writer jw = JSON_WRITER_INIT;
> > +
> > +	jw_object_begin(&jw, 0);
> > +	event_fmt_prepare(event_name, file, line, NULL, &jw);
> > +	jw_object_inline_begin_array(&jw, "ancestry");
> > +
> > +	while ((parent_name = *parent_names++))
> > +		jw_array_string(&jw, parent_name);
> 
> You're building the array with the immediate parent in a[0]
> and the grandparent in a[1], and etc.  This is the same as
> I did in GFW.
> 
> Perhaps state this in the docs somewhere.

Sure, makes sense. I think I neglected any doc work whatsoever in this
patch anyways, whoops :)

> > +	/* cmd_ancestry parent <- grandparent <- great-grandparent */
> > +	strbuf_addstr(&buf_payload, "cmd_ancestry ");
> > +	while ((parent_name = *parent_names++)) {
> > +		strbuf_addstr(&buf_payload, parent_name);
> 
> Did you want to quote each parent's name?

I'd rather not - since they're going into an array anyway, I'd expect
the array delimiters to be enough. Am I being naive? 'normal' looks to
me like it's supposed to be mostly human readable anyways, rather than
parseable?

> > +	strbuf_addstr(&buf_payload, "ancestry:[");
> > +	/* It's not an argv but the rules are basically the same. */
> > +	sq_append_quote_argv_pretty(&buf_payload, parent_names);
> 
> This will have whitespace delimiters between the quoted strings
> rather than commas.  Just checking if that's what you wanted.
> 
> I'm not sure it matters, since this stream is intended for human
> parsing.

Yeah, it seems fine to me as is.

> 
> We should update Documentation/technical/api-trace2.txt too.

Yep, thanks.

I appreciate the review, Jeff.

 - Emily
Randall S. Becker May 21, 2021, 8:23 p.m. UTC | #9
<emilyshaffer@google.com>
On May 21, 2021 4:05 PM, Emily Shaffer wrote:
>On Fri, May 21, 2021 at 03:15:16PM -0400, Jeff Hostetler wrote:
>> On 5/20/21 5:05 PM, Emily Shaffer wrote:
>> > - I took a look at Jeff H's advice on using a "data_json" event to log
>> >    this and decided it would be a little more flexible to add a new event
>> >    instead. If we want, it'd be feasible to then shoehorn the GfW parent
>> >    tree stuff into this new event too. Doing it this way is definitely
>> >    easier to parse for Google's trace analysis system (which for now
>> >    completely skips "data_json" as it's polymorphic), and also - I think
>> >    - means that we can add more fields later on if we need to (thread
>> >    info, different fields than just /proc/n/comm like exec path, argv,
>> >    whatever).
>>
>> I could argue both sides of this, so I guess it is fine either way.
>>
>> In GFW I log a array of argv[0] strings in a generic "data_json" event.
>> I could also log additional "data_json" events with more structured
>> data if needed.
>>
>> On the other hand, you're proposing a "cmd_ancestry" event with a
>> single array of strings.  You would have to expand the call signature
>> of the trace2_cmd_ancestry() API to add additional data and inside
>> tr2_tgt_event.c add additional fields to the JSON being composed.
>>
>> So both are about equal.
>>
>> (I'll avoid the temptation to make a snarky comment about fixing your
>> post processing. :-) :-) :-) )
>
>;P
>
>(I don't have much to add - this is an accurate summary of what I thought about, too. Thanks for writing it out.)
>
>>
>> It really doesn't matter one way or the other.
>>
>> > - Jonathan N also pointed out to me that /proc/n/comm exists, and logs
>> >    the "command name" - excluding argv, excluding path, etc. It
>> > seems
>>
>> So you're trying to log argv[0] of the process and not the full
>> command line.  That's what I'm doing.
>
>It's close to argv[0], yeah. POSIX docs indicate it might be truncated in a way that argv[0] hasn't been, but it also doesn't
include the
>leading path (as far as I've seen). For example, a long-running helper script I use with mutt, right now (gaffing on line length in
email to
>help with argv clarity, sorry):
>
>  $ ps aux | grep mutt
>  emilysh+ 4119883  0.0  0.0   6892  3600 pts/6    S+   12:44   0:00 /bin/bash
/usr/local/google/home/emilyshaffer/dotfiles/open-vim-in-
>new-split.sh /var/tmp/mutt-podkayne-413244-1263002-7433772284891386689
>  # comm is truncated to 15ch, except apparently in the cases of some
>  # kernel worker processes I saw with much longer names?
>  $ cat /proc/4119883/comm
>  open-vim-in-new
>  # exe is a link to the executable, which means bash as this is a
>  # script
>  $ ls -lha /proc/4119883/exe
>  lrwxrwxrwx 1 emilyshaffer primarygroup 0 May 21 12:44
>  /proc/4119883/exe -> /usr/bin/bash
>  # cmdline has the whole argv, separated on NUL so it runs together in
>  # editor
>  $ cat /proc/4119883/cmdline
>  /bin/bash/usr/local/google/home/emilyshaffer/dotfiles/open-vim-in-new-split.sh/var/tmp/mutt-podkayne-413244-1263002-
>7433772284891386689
>
>Jonathan N pointed out that the process name (the thing in 'comm') can also be manually manipulated by the process itself, and 'man
>procfs'
>also talks about 'PR_SET_NAME' and 'PR_GET_NAME' operations in 'prctl()', so that tracks. (It doesn't look like we can use prctl()
to find
>out the names of processes besides the current process, though, so the procfs stuff is still needed. Dang.)
>
>>
>> >    like this is a little more safe about excluding personal information
>> >    from the traces which take the form of "myscript.sh
>> >    --password=hunter2", but would still be worrisome for something like
>> >    "mysupersecretproject.sh". I'm not sure whether that means we still
>> >    want to guard it with a config flag, though.
>>
>> You might check whether you get the name of the script or just get a
>> lot of entries with just "/usr/bin/bash".
>
>See above :)
>
>> There's lots of PII in the data stream to worry about.
>> The name of the command is just one aspect, but I digress.
>
>Yes, that's what we've noticed too, so a process name isn't worrying us that much more.
>
>>
>> > - I also added a lot to the commit message; hopefully it's not too
>> >    rambly, but I hoped to explain why just setting GIT_TRACE2_PARENT_SID
>> >    wasn't going to cut it.
>> > - As for testing, I followed the lead of GfW's parentage info - "this
>> >    isn't portable so writing tests for it will suck, just scrub it from
>> >    the tests". Maybe it makes sense to do some more
>> >    platform-specific-ness in the test suite instead? I wasn't sure.
>>
>> yeah, that's probably best.  Unless you can tokenize it properly so
>> that you can predict the results in a HEREDOC in the test source.
>>
>> For example, you might try to test tracing a command (where a
>> top-level "git foo" (SPACE form) spawns a "git-foo" (DASHED form) and
>> check the output for the child.
>
>Yeah, I had trouble with even deciding when to attempt such a check or not.
>> > +	if (reason == TRACE2_PROCESS_INFO_STARTUP)
>> > +	{
>> > +		/*
>> > +		 * NEEDSWORK: we could do the entire ptree in an array instead,
>> > +		 * see compat/win32/trace2_win32_process_info.c.
>> > +		 */
>> > +		char *names[2];
>> > +		names[0] = get_process_name(getppid());
>> > +		names[1] = NULL;
>>
>> You're only logging 1 parent.  That's fine to get started.
>>
>> I'm logging IIRC 10 parents on GFW.  That might seem overkill, but
>> there are lots of intermediate parents that hide what is happening.
>> For example, a "git push" might spawn "git remote-https"
>> which spawns "git-remote-https" which spawn "git send-pack" which
>> spawns "git pack-objects".
>>
>> And that doesn't include who called push.
>>
>> And it's not uncommon to see 2 or 3 "bash" entries in the array
>> because of the bash scripts being run.
>
>Agree. But it's expensive - I didn't find a handy library call to find "parent ID of given process ID", so I think we'd have to
manipulate
>procfs; and so far I only see parent ID in summary infos like /proc/n/status or /proc/n/stat, which contain lots of other info too
and would
>need parsing.
>
>We could reduce the cost a little bit by grabbing the process name from the status or stat as well, and therefore still only
opening one file
>per process, but I'd want to check whether the formats are expected to be stable for those things.
>
>> > +static void fn_command_ancestry_fl(const char *file, int line,
>> > +const char **parent_names) {
>> > +	const char *event_name = "cmd_ancestry";
>> > +	const char *parent_name = NULL;
>> > +	struct json_writer jw = JSON_WRITER_INIT;
>> > +
>> > +	jw_object_begin(&jw, 0);
>> > +	event_fmt_prepare(event_name, file, line, NULL, &jw);
>> > +	jw_object_inline_begin_array(&jw, "ancestry");
>> > +
>> > +	while ((parent_name = *parent_names++))
>> > +		jw_array_string(&jw, parent_name);
>>
>> You're building the array with the immediate parent in a[0] and the
>> grandparent in a[1], and etc.  This is the same as I did in GFW.
>>
>> Perhaps state this in the docs somewhere.
>
>Sure, makes sense. I think I neglected any doc work whatsoever in this patch anyways, whoops :)
>
>> > +	/* cmd_ancestry parent <- grandparent <- great-grandparent */
>> > +	strbuf_addstr(&buf_payload, "cmd_ancestry ");
>> > +	while ((parent_name = *parent_names++)) {
>> > +		strbuf_addstr(&buf_payload, parent_name);
>>
>> Did you want to quote each parent's name?
>
>I'd rather not - since they're going into an array anyway, I'd expect the array delimiters to be enough. Am I being naive? 'normal'
looks to
>me like it's supposed to be mostly human readable anyways, rather than parseable?
>
>> > +	strbuf_addstr(&buf_payload, "ancestry:[");
>> > +	/* It's not an argv but the rules are basically the same. */
>> > +	sq_append_quote_argv_pretty(&buf_payload, parent_names);
>>
>> This will have whitespace delimiters between the quoted strings rather
>> than commas.  Just checking if that's what you wanted.
>>
>> I'm not sure it matters, since this stream is intended for human
>> parsing.
>
>Yeah, it seems fine to me as is.
>
>>
>> We should update Documentation/technical/api-trace2.txt too.
>
>Yep, thanks.
>
>I appreciate the review, Jeff.

I checked the performance of my NonStop parent lookup implementation. It's fast enough that no one would notice (8 microseconds on
the oldest slowest machine I could find).

Just an FYI.
-Randall
Junio C Hamano May 21, 2021, 11:22 p.m. UTC | #10
Emily Shaffer <emilyshaffer@google.com> writes:

>> > we will need to discover the name another way. However, the process ID
>> > should be sufficient regardless of platform.
>> 
>> Not a strong objection, but I wonder if seeing random integer(s) is
>> better than not having cmd_ancestry info at all.  The latter better
>> signals that the platform does not yet have the "parent process
>> name" feature, I would think.
>
> Hm, we could...

Please don't.  There is a misreading here.

You mentioned "However, the process ID should be sufficient" and I
read it as "In the worst case we can emit the process ID if we do
not know how to turn it into name", and to that I said "showing
process IDs is not all that useful as they are random integers
without extra info on processes that were running back when the log
entry was taken".  Similarly, my later "OK, we do not show pid as a
placeholder." is "Contrary to what I thought you said earlier, you
do not give raw process IDs and instead honestly say we do not have
that information by omitting the record.  I am happy to see what the
actual patch does".

Thanks.
Jeff Hostetler May 22, 2021, 11:18 a.m. UTC | #11
On 5/21/21 4:05 PM, Emily Shaffer wrote:
> On Fri, May 21, 2021 at 03:15:16PM -0400, Jeff Hostetler wrote:
>> On 5/20/21 5:05 PM, Emily Shaffer wrote:
>>> - I took a look at Jeff H's advice on using a "data_json" event to log
>>>     this and decided it would be a little more flexible to add a new event
>>>     instead. If we want, it'd be feasible to then shoehorn the GfW parent
>>>     tree stuff into this new event too. Doing it this way is definitely
>>>     easier to parse for Google's trace analysis system (which for now
>>>     completely skips "data_json" as it's polymorphic), and also - I think
>>>     - means that we can add more fields later on if we need to (thread
>>>     info, different fields than just /proc/n/comm like exec path, argv,
>>>     whatever).
>>
>> I could argue both sides of this, so I guess it is fine either way.
>>
>> In GFW I log a array of argv[0] strings in a generic "data_json" event.
>> I could also log additional "data_json" events with more structured
>> data if needed.
>>
>> On the other hand, you're proposing a "cmd_ancestry" event with a
>> single array of strings.  You would have to expand the call signature
>> of the trace2_cmd_ancestry() API to add additional data and inside
>> tr2_tgt_event.c add additional fields to the JSON being composed.
>>
>> So both are about equal.
>>
>> (I'll avoid the temptation to make a snarky comment about fixing
>> your post processing. :-) :-) :-) )
> 
> ;P
> 
> (I don't have much to add - this is an accurate summary of what I
> thought about, too. Thanks for writing it out.)
> 
>>
>> It really doesn't matter one way or the other.
>>
>>> - Jonathan N also pointed out to me that /proc/n/comm exists, and logs
>>>     the "command name" - excluding argv, excluding path, etc. It seems
>>
>> So you're trying to log argv[0] of the process and not the full
>> command line.  That's what I'm doing.
> 
> It's close to argv[0], yeah. POSIX docs indicate it might be truncated
> in a way that argv[0] hasn't been, but it also doesn't include the
> leading path (as far as I've seen). For example, a long-running helper
> script I use with mutt, right now (gaffing on line length in email to
> help with argv clarity, sorry):
> 
>    $ ps aux | grep mutt
>    emilysh+ 4119883  0.0  0.0   6892  3600 pts/6    S+   12:44   0:00 /bin/bash /usr/local/google/home/emilyshaffer/dotfiles/open-vim-in-new-split.sh /var/tmp/mutt-podkayne-413244-1263002-7433772284891386689
>    # comm is truncated to 15ch, except apparently in the cases of some
>    # kernel worker processes I saw with much longer names?
>    $ cat /proc/4119883/comm
>    open-vim-in-new
>    # exe is a link to the executable, which means bash as this is a
>    # script
>    $ ls -lha /proc/4119883/exe
>    lrwxrwxrwx 1 emilyshaffer primarygroup 0 May 21 12:44
>    /proc/4119883/exe -> /usr/bin/bash
>    # cmdline has the whole argv, separated on NUL so it runs together in
>    # editor
>    $ cat /proc/4119883/cmdline
>    /bin/bash/usr/local/google/home/emilyshaffer/dotfiles/open-vim-in-new-split.sh/var/tmp/mutt-podkayne-413244-1263002-7433772284891386689
> 
> Jonathan N pointed out that the process name (the thing in 'comm') can
> also be manually manipulated by the process itself, and 'man procfs'
> also talks about 'PR_SET_NAME' and 'PR_GET_NAME' operations in
> 'prctl()', so that tracks. (It doesn't look like we can use prctl() to
> find out the names of processes besides the current process, though, so
> the procfs stuff is still needed. Dang.)
> 
>>
>>>     like this is a little more safe about excluding personal information
>>>     from the traces which take the form of "myscript.sh
>>>     --password=hunter2", but would still be worrisome for something like
>>>     "mysupersecretproject.sh". I'm not sure whether that means we still
>>>     want to guard it with a config flag, though.
>>
>> You might check whether you get the name of the script or just get
>> a lot of entries with just "/usr/bin/bash".
> 
> See above :)
> 
>> There's lots of PII in the data stream to worry about.
>> The name of the command is just one aspect, but I digress.
> 
> Yes, that's what we've noticed too, so a process name isn't worrying us
> that much more.
> 
>>
>>> - I also added a lot to the commit message; hopefully it's not too
>>>     rambly, but I hoped to explain why just setting GIT_TRACE2_PARENT_SID
>>>     wasn't going to cut it.
>>> - As for testing, I followed the lead of GfW's parentage info - "this
>>>     isn't portable so writing tests for it will suck, just scrub it from
>>>     the tests". Maybe it makes sense to do some more
>>>     platform-specific-ness in the test suite instead? I wasn't sure.
>>
>> yeah, that's probably best.  Unless you can tokenize it properly
>> so that you can predict the results in a HEREDOC in the test source.
>>
>> For example, you might try to test tracing a command (where a top-level
>> "git foo" (SPACE form) spawns a "git-foo" (DASHED form) and check the
>> output for the child.
> 
> Yeah, I had trouble with even deciding when to attempt such a check or
> not.
>>> +	if (reason == TRACE2_PROCESS_INFO_STARTUP)
>>> +	{
>>> +		/*
>>> +		 * NEEDSWORK: we could do the entire ptree in an array instead,
>>> +		 * see compat/win32/trace2_win32_process_info.c.
>>> +		 */
>>> +		char *names[2];
>>> +		names[0] = get_process_name(getppid());
>>> +		names[1] = NULL;
>>
>> You're only logging 1 parent.  That's fine to get started.
>>
>> I'm logging IIRC 10 parents on GFW.  That might seem overkill,
>> but there are lots of intermediate parents that hide what is
>> happening.  For example, a "git push" might spawn "git remote-https"
>> which spawns "git-remote-https" which spawn "git send-pack" which
>> spawns "git pack-objects".
>>
>> And that doesn't include who called push.
>>
>> And it's not uncommon to see 2 or 3 "bash" entries in the array
>> because of the bash scripts being run.
> 
> Agree. But it's expensive - I didn't find a handy library call to find
> "parent ID of given process ID", so I think we'd have to manipulate
> procfs; and so far I only see parent ID in summary infos like
> /proc/n/status or /proc/n/stat, which contain lots of other info too and
> would need parsing.
> 
> We could reduce the cost a little bit by grabbing the process name from
> the status or stat as well, and therefore still only opening one file per
> process, but I'd want to check whether the formats are expected to be
> stable for those things.

Yeah, don't force it collect a bunch of data for n parents that you
don't need.  I guess my point was that there were lots of time when
there were too many "unhelpful" parents in the ancestry chain.  So
maybe confirm that you can get what you need from just 1 parent.
I needed more than 1 to tell that a particular command was interactive
vs launched by VS or VSCode or etc.


> 
>>> +static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names)
>>> +{
>>> +	const char *event_name = "cmd_ancestry";
>>> +	const char *parent_name = NULL;
>>> +	struct json_writer jw = JSON_WRITER_INIT;
>>> +
>>> +	jw_object_begin(&jw, 0);
>>> +	event_fmt_prepare(event_name, file, line, NULL, &jw);
>>> +	jw_object_inline_begin_array(&jw, "ancestry");
>>> +
>>> +	while ((parent_name = *parent_names++))
>>> +		jw_array_string(&jw, parent_name);
>>
>> You're building the array with the immediate parent in a[0]
>> and the grandparent in a[1], and etc.  This is the same as
>> I did in GFW.
>>
>> Perhaps state this in the docs somewhere.
> 
> Sure, makes sense. I think I neglected any doc work whatsoever in this
> patch anyways, whoops :)
> 
>>> +	/* cmd_ancestry parent <- grandparent <- great-grandparent */
>>> +	strbuf_addstr(&buf_payload, "cmd_ancestry ");
>>> +	while ((parent_name = *parent_names++)) {
>>> +		strbuf_addstr(&buf_payload, parent_name);
>>
>> Did you want to quote each parent's name?
> 
> I'd rather not - since they're going into an array anyway, I'd expect
> the array delimiters to be enough. Am I being naive? 'normal' looks to
> me like it's supposed to be mostly human readable anyways, rather than
> parseable?
> 
>>> +	strbuf_addstr(&buf_payload, "ancestry:[");
>>> +	/* It's not an argv but the rules are basically the same. */
>>> +	sq_append_quote_argv_pretty(&buf_payload, parent_names);
>>
>> This will have whitespace delimiters between the quoted strings
>> rather than commas.  Just checking if that's what you wanted.
>>
>> I'm not sure it matters, since this stream is intended for human
>> parsing.
> 
> Yeah, it seems fine to me as is.
> 
>>
>> We should update Documentation/technical/api-trace2.txt too.
> 
> Yep, thanks.
> 
> I appreciate the review, Jeff.
> 
>   - Emily
>
Emily Shaffer May 24, 2021, 6:37 p.m. UTC | #12
On Sat, May 22, 2021 at 08:22:46AM +0900, Junio C Hamano wrote:
> 
> Emily Shaffer <emilyshaffer@google.com> writes:
> 
> >> > we will need to discover the name another way. However, the process ID
> >> > should be sufficient regardless of platform.
> >> 
> >> Not a strong objection, but I wonder if seeing random integer(s) is
> >> better than not having cmd_ancestry info at all.  The latter better
> >> signals that the platform does not yet have the "parent process
> >> name" feature, I would think.
> >
> > Hm, we could...
> 
> Please don't.  There is a misreading here.
> 
> You mentioned "However, the process ID should be sufficient" and I
> read it as "In the worst case we can emit the process ID if we do
> not know how to turn it into name", and to that I said "showing
> process IDs is not all that useful as they are random integers
> without extra info on processes that were running back when the log
> entry was taken".  Similarly, my later "OK, we do not show pid as a
> placeholder." is "Contrary to what I thought you said earlier, you
> do not give raw process IDs and instead honestly say we do not have
> that information by omitting the record.  I am happy to see what the
> actual patch does".

Ah, thanks for clarifying. I'll see if I can make the "PID should be
enough" statement less confusing, instead - what I meant was "on all
systems, the result of getppid() should be sufficient to look up the
process name, so this code is probably shareable", and Randall has
pointed out elsewhere to me that that's false.

 - Emily
Ævar Arnfjörð Bjarmason May 24, 2021, 11:33 p.m. UTC | #13
On Fri, May 21 2021, Emily Shaffer wrote:

> On Fri, May 21, 2021 at 03:15:16PM -0400, Jeff Hostetler wrote:
>> On 5/20/21 5:05 PM, Emily Shaffer wrote:
>> > - I took a look at Jeff H's advice on using a "data_json" event to log
>> >    this and decided it would be a little more flexible to add a new event
>> >    instead. If we want, it'd be feasible to then shoehorn the GfW parent
>> >    tree stuff into this new event too. Doing it this way is definitely
>> >    easier to parse for Google's trace analysis system (which for now
>> >    completely skips "data_json" as it's polymorphic), and also - I think
>> >    - means that we can add more fields later on if we need to (thread
>> >    info, different fields than just /proc/n/comm like exec path, argv,
>> >    whatever).
>> 
>> I could argue both sides of this, so I guess it is fine either way.
>> 
>> In GFW I log a array of argv[0] strings in a generic "data_json" event.
>> I could also log additional "data_json" events with more structured
>> data if needed.
>> 
>> On the other hand, you're proposing a "cmd_ancestry" event with a
>> single array of strings.  You would have to expand the call signature
>> of the trace2_cmd_ancestry() API to add additional data and inside
>> tr2_tgt_event.c add additional fields to the JSON being composed.
>> 
>> So both are about equal.
>> 
>> (I'll avoid the temptation to make a snarky comment about fixing
>> your post processing. :-) :-) :-) )
>
> ;P
>
> (I don't have much to add - this is an accurate summary of what I
> thought about, too. Thanks for writing it out.)
>
>> 
>> It really doesn't matter one way or the other.
>> 
>> > - Jonathan N also pointed out to me that /proc/n/comm exists, and logs
>> >    the "command name" - excluding argv, excluding path, etc. It seems
>> 
>> So you're trying to log argv[0] of the process and not the full
>> command line.  That's what I'm doing.
>
> It's close to argv[0], yeah. POSIX docs indicate it might be truncated
> in a way that argv[0] hasn't been, but it also doesn't include the
> leading path (as far as I've seen). For example, a long-running helper
> script I use with mutt, right now (gaffing on line length in email to
> help with argv clarity, sorry):
>
>   $ ps aux | grep mutt
>   emilysh+ 4119883 0.0 0.0 6892 3600 pts/6 S+ 12:44 0:00 /bin/bash
> /usr/local/google/home/emilyshaffer/dotfiles/open-vim-in-new-split.sh
> /var/tmp/mutt-podkayne-413244-1263002-7433772284891386689
>   # comm is truncated to 15ch, except apparently in the cases of some
>   # kernel worker processes I saw with much longer names?
>   $ cat /proc/4119883/comm
>   open-vim-in-new
>   # exe is a link to the executable, which means bash as this is a
>   # script
>   $ ls -lha /proc/4119883/exe
>   lrwxrwxrwx 1 emilyshaffer primarygroup 0 May 21 12:44
>   /proc/4119883/exe -> /usr/bin/bash
>   # cmdline has the whole argv, separated on NUL so it runs together in
>   # editor
>   $ cat /proc/4119883/cmdline
>   /bin/bash/usr/local/google/home/emilyshaffer/dotfiles/open-vim-in-new-split.sh/var/tmp/mutt-podkayne-413244-1263002-7433772284891386689
>
> Jonathan N pointed out that the process name (the thing in 'comm') can
> also be manually manipulated by the process itself, and 'man procfs'
> also talks about 'PR_SET_NAME' and 'PR_GET_NAME' operations in
> 'prctl()', so that tracks. (It doesn't look like we can use prctl() to
> find out the names of processes besides the current process, though, so
> the procfs stuff is still needed. Dang.)
>
>> 
>> >    like this is a little more safe about excluding personal information
>> >    from the traces which take the form of "myscript.sh
>> >    --password=hunter2", but would still be worrisome for something like
>> >    "mysupersecretproject.sh". I'm not sure whether that means we still
>> >    want to guard it with a config flag, though.
>> 
>> You might check whether you get the name of the script or just get
>> a lot of entries with just "/usr/bin/bash".
>
> See above :)
>
>> There's lots of PII in the data stream to worry about.
>> The name of the command is just one aspect, but I digress.
>
> Yes, that's what we've noticed too, so a process name isn't worrying us
> that much more.
>
>> 
>> > - I also added a lot to the commit message; hopefully it's not too
>> >    rambly, but I hoped to explain why just setting GIT_TRACE2_PARENT_SID
>> >    wasn't going to cut it.
>> > - As for testing, I followed the lead of GfW's parentage info - "this
>> >    isn't portable so writing tests for it will suck, just scrub it from
>> >    the tests". Maybe it makes sense to do some more
>> >    platform-specific-ness in the test suite instead? I wasn't sure.
>> 
>> yeah, that's probably best.  Unless you can tokenize it properly
>> so that you can predict the results in a HEREDOC in the test source.
>> 
>> For example, you might try to test tracing a command (where a top-level
>> "git foo" (SPACE form) spawns a "git-foo" (DASHED form) and check the
>> output for the child.
>
> Yeah, I had trouble with even deciding when to attempt such a check or
> not.
>> > +	if (reason == TRACE2_PROCESS_INFO_STARTUP)
>> > +	{
>> > +		/*
>> > +		 * NEEDSWORK: we could do the entire ptree in an array instead,
>> > +		 * see compat/win32/trace2_win32_process_info.c.
>> > +		 */
>> > +		char *names[2];
>> > +		names[0] = get_process_name(getppid());
>> > +		names[1] = NULL;
>> 
>> You're only logging 1 parent.  That's fine to get started.
>> 
>> I'm logging IIRC 10 parents on GFW.  That might seem overkill,
>> but there are lots of intermediate parents that hide what is
>> happening.  For example, a "git push" might spawn "git remote-https"
>> which spawns "git-remote-https" which spawn "git send-pack" which
>> spawns "git pack-objects".
>> 
>> And that doesn't include who called push.
>> 
>> And it's not uncommon to see 2 or 3 "bash" entries in the array
>> because of the bash scripts being run.
>
> Agree. But it's expensive - I didn't find a handy library call to find
> "parent ID of given process ID", so I think we'd have to manipulate
> procfs; and so far I only see parent ID in summary infos like
> /proc/n/status or /proc/n/stat, which contain lots of other info too and
> would need parsing.

It sounds a bit like you're fumbling your way towards (re?)discovering:

    pstree -s <pid>

You can look at its implementation (or strace it) to see what it does,
and yes, on Linux there's no handy C library for this, iterating over
procfs is the library.

Aside from the privacy, PII, usefulness of this data etc. discussions in
this & related threads I don't think that per-se should be an issue on a
modern Linux system. After all we'd just need to do it once on
startup. For any sub-process we spawn we'd carry it forward after the
initial /usr/bin/git invocation.
diff mbox series

Patch

diff --git a/Makefile b/Makefile
index 93664d6714..330e4fa011 100644
--- a/Makefile
+++ b/Makefile
@@ -1889,6 +1889,11 @@  ifneq ($(PROCFS_EXECUTABLE_PATH),)
 	BASIC_CFLAGS += '-DPROCFS_EXECUTABLE_PATH="$(procfs_executable_path_SQ)"'
 endif
 
+ifdef HAVE_PROCFS_LINUX
+	BASIC_CFLAGS += -DHAVE_PROCFS_LINUX
+	COMPAT_OBJS += compat/procinfo.o
+endif
+
 ifdef HAVE_NS_GET_EXECUTABLE_PATH
 	BASIC_CFLAGS += -DHAVE_NS_GET_EXECUTABLE_PATH
 endif
diff --git a/compat/procinfo.c b/compat/procinfo.c
new file mode 100644
index 0000000000..523600673f
--- /dev/null
+++ b/compat/procinfo.c
@@ -0,0 +1,53 @@ 
+#include "cache.h"
+
+#include "strbuf.h"
+#include "trace2.h"
+
+char *get_process_name(int pid)
+{
+#ifdef HAVE_PROCFS_LINUX
+	struct strbuf procfs_path = STRBUF_INIT;
+	struct strbuf out = STRBUF_INIT;
+	/* try to use procfs if it's present. */
+	strbuf_addf(&procfs_path, "/proc/%d/comm", pid);
+	if (!strbuf_read_file(&out, procfs_path.buf, 0))
+	{
+		/* All done with file reads, clean up early */
+		strbuf_release(&procfs_path);
+		return strbuf_detach(&out, NULL);
+	}
+#endif
+
+	/* NEEDSWORK: add non-procfs implementations here. */
+	return NULL;
+}
+
+void trace2_collect_process_info(enum trace2_process_info_reason reason)
+{
+	if (!trace2_is_enabled())
+		return;
+
+	/* someday we may want to write something extra here, but not today */
+	if (reason == TRACE2_PROCESS_INFO_EXIT)
+		return;
+
+	if (reason == TRACE2_PROCESS_INFO_STARTUP)
+	{
+		/*
+		 * NEEDSWORK: we could do the entire ptree in an array instead,
+		 * see compat/win32/trace2_win32_process_info.c.
+		 */
+		char *names[2];
+		names[0] = get_process_name(getppid());
+		names[1] = NULL;
+
+		if (!names[0])
+			return;
+
+		trace2_cmd_ancestry((const char**)names);
+
+		free(names[0]);
+	}
+
+	return;
+}
diff --git a/config.mak.uname b/config.mak.uname
index cb443b4e02..7ad110a1d2 100644
--- a/config.mak.uname
+++ b/config.mak.uname
@@ -58,6 +58,7 @@  ifeq ($(uname_S),Linux)
 	FREAD_READS_DIRECTORIES = UnfortunatelyYes
 	BASIC_CFLAGS += -DHAVE_SYSINFO
 	PROCFS_EXECUTABLE_PATH = /proc/self/exe
+	HAVE_PROCFS_LINUX = YesPlease
 endif
 ifeq ($(uname_S),GNU/kFreeBSD)
 	HAVE_ALLOCA_H = YesPlease
diff --git a/git-compat-util.h b/git-compat-util.h
index a508dbe5a3..cc7d5d8a2a 100644
--- a/git-compat-util.h
+++ b/git-compat-util.h
@@ -1382,4 +1382,10 @@  static inline void *container_of_or_null_offset(void *ptr, size_t offset)
 
 void sleep_millisec(int millisec);
 
+/*
+ * Convert PID to process name (as would show in top/task manager). Returns
+ * NULL if unimplemented - be sure to check for NULL at callsite.
+ */
+char *get_process_name(int pid);
+
 #endif
diff --git a/t/t0210/scrub_normal.perl b/t/t0210/scrub_normal.perl
index c65d1a815e..7cc4de392a 100644
--- a/t/t0210/scrub_normal.perl
+++ b/t/t0210/scrub_normal.perl
@@ -42,6 +42,12 @@ 
 	# so just omit it for testing purposes.
 	# print "cmd_path _EXE_\n";
     }
+    elsif ($line =~ m/^cmd_ancestry/) {
+	# 'cmd_ancestry' is not implemented everywhere, so for portability's
+	# sake, skip it when parsing normal.
+	#
+	# print "$line";
+    }
     else {
 	print "$line";
     }
diff --git a/t/t0211/scrub_perf.perl b/t/t0211/scrub_perf.perl
index 351af7844e..d164b750ff 100644
--- a/t/t0211/scrub_perf.perl
+++ b/t/t0211/scrub_perf.perl
@@ -44,6 +44,11 @@ 
 	# $tokens[$col_rest] = "_EXE_";
 	goto SKIP_LINE;
     }
+    elsif ($tokens[$col_event] =~ m/cmd_ancestry/) {
+	# 'cmd_ancestry' is platform-specific and not implemented everywhere,
+	# so skip it.
+	goto SKIP_LINE;
+    }
     elsif ($tokens[$col_event] =~ m/child_exit/) {
 	$tokens[$col_rest] =~ s/ pid:\d* / pid:_PID_ /;
     }
diff --git a/t/t0212/parse_events.perl b/t/t0212/parse_events.perl
index 6584bb5634..b6408560c0 100644
--- a/t/t0212/parse_events.perl
+++ b/t/t0212/parse_events.perl
@@ -132,7 +132,10 @@ 
 	# just omit it for testing purposes.
 	# $processes->{$sid}->{'path'} = "_EXE_";
     }
-    
+    elsif ($event eq 'cmd_ancestry') {
+	# 'cmd_ancestry' is platform-specific and not implemented everywhere, so
+	# just skip it for testing purposes.
+    }
     elsif ($event eq 'cmd_name') {
 	$processes->{$sid}->{'name'} = $line->{'name'};
 	$processes->{$sid}->{'hierarchy'} = $line->{'hierarchy'};
diff --git a/trace2.c b/trace2.c
index 256120c7fd..b9b154ac44 100644
--- a/trace2.c
+++ b/trace2.c
@@ -260,6 +260,19 @@  void trace2_cmd_path_fl(const char *file, int line, const char *pathname)
 			tgt_j->pfn_command_path_fl(file, line, pathname);
 }
 
+void trace2_cmd_ancestry_fl(const char *file, int line, const char **parent_names)
+{
+	struct tr2_tgt *tgt_j;
+	int j;
+
+	if (!trace2_enabled)
+		return;
+
+	for_each_wanted_builtin (j, tgt_j)
+		if (tgt_j->pfn_command_ancestry_fl)
+			tgt_j->pfn_command_ancestry_fl(file, line, parent_names);
+}
+
 void trace2_cmd_name_fl(const char *file, int line, const char *name)
 {
 	struct tr2_tgt *tgt_j;
diff --git a/trace2.h b/trace2.h
index ede18c2e06..23743ac62b 100644
--- a/trace2.h
+++ b/trace2.h
@@ -133,6 +133,16 @@  void trace2_cmd_path_fl(const char *file, int line, const char *pathname);
 
 #define trace2_cmd_path(p) trace2_cmd_path_fl(__FILE__, __LINE__, (p))
 
+/*
+ * Emit an 'ancestry' event with the process name of the current process's
+ * parent process.
+ * This gives post-processors a way to determine what invoked the command and
+ * learn more about usage patterns.
+ */
+void trace2_cmd_ancestry_fl(const char *file, int line, const char **parent_names);
+
+#define trace2_cmd_ancestry(v) trace2_cmd_ancestry_fl(__FILE__, __LINE__, (v))
+
 /*
  * Emit a 'cmd_name' event with the canonical name of the command.
  * This gives post-processors a simple field to identify the command
@@ -492,7 +502,7 @@  enum trace2_process_info_reason {
 	TRACE2_PROCESS_INFO_EXIT,
 };
 
-#if defined(GIT_WINDOWS_NATIVE)
+#if ( defined(GIT_WINDOWS_NATIVE) || defined(HAVE_PROCFS_LINUX) )
 void trace2_collect_process_info(enum trace2_process_info_reason reason);
 #else
 #define trace2_collect_process_info(reason) \
diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h
index 7b90469212..1f66fd6573 100644
--- a/trace2/tr2_tgt.h
+++ b/trace2/tr2_tgt.h
@@ -27,6 +27,8 @@  typedef void(tr2_tgt_evt_error_va_fl_t)(const char *file, int line,
 
 typedef void(tr2_tgt_evt_command_path_fl_t)(const char *file, int line,
 					    const char *command_path);
+typedef void(tr2_tgt_evt_command_ancestry_fl_t)(const char *file, int line,
+						const char **parent_names);
 typedef void(tr2_tgt_evt_command_name_fl_t)(const char *file, int line,
 					    const char *name,
 					    const char *hierarchy);
@@ -108,6 +110,7 @@  struct tr2_tgt {
 	tr2_tgt_evt_atexit_t                    *pfn_atexit;
 	tr2_tgt_evt_error_va_fl_t               *pfn_error_va_fl;
 	tr2_tgt_evt_command_path_fl_t           *pfn_command_path_fl;
+	tr2_tgt_evt_command_ancestry_fl_t	*pfn_command_ancestry_fl;
 	tr2_tgt_evt_command_name_fl_t           *pfn_command_name_fl;
 	tr2_tgt_evt_command_mode_fl_t           *pfn_command_mode_fl;
 	tr2_tgt_evt_alias_fl_t                  *pfn_alias_fl;
diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c
index 6353e8ad91..578a9a5287 100644
--- a/trace2/tr2_tgt_event.c
+++ b/trace2/tr2_tgt_event.c
@@ -261,6 +261,26 @@  static void fn_command_path_fl(const char *file, int line, const char *pathname)
 	jw_release(&jw);
 }
 
+static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names)
+{
+	const char *event_name = "cmd_ancestry";
+	const char *parent_name = NULL;
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_inline_begin_array(&jw, "ancestry");
+
+	while ((parent_name = *parent_names++))
+		jw_array_string(&jw, parent_name);
+
+	jw_end(&jw); /* 'ancestry' array */
+	jw_end(&jw); /* event object */
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
 static void fn_command_name_fl(const char *file, int line, const char *name,
 			       const char *hierarchy)
 {
@@ -584,6 +604,7 @@  struct tr2_tgt tr2_tgt_event = {
 	fn_atexit,
 	fn_error_va_fl,
 	fn_command_path_fl,
+	fn_command_ancestry_fl,
 	fn_command_name_fl,
 	fn_command_mode_fl,
 	fn_alias_fl,
diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c
index 31b602c171..a5751c8864 100644
--- a/trace2/tr2_tgt_normal.c
+++ b/trace2/tr2_tgt_normal.c
@@ -160,6 +160,24 @@  static void fn_command_path_fl(const char *file, int line, const char *pathname)
 	strbuf_release(&buf_payload);
 }
 
+static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names)
+{
+	const char *parent_name = NULL;
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	/* cmd_ancestry parent <- grandparent <- great-grandparent */
+	strbuf_addstr(&buf_payload, "cmd_ancestry ");
+	while ((parent_name = *parent_names++)) {
+		strbuf_addstr(&buf_payload, parent_name);
+		/* if we'll write another one after this, add a delimiter */
+		if (parent_names && *parent_names)
+			strbuf_addstr(&buf_payload, " <- ");
+	}
+
+	normal_io_write_fl(file, line, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
 static void fn_command_name_fl(const char *file, int line, const char *name,
 			       const char *hierarchy)
 {
@@ -306,6 +324,7 @@  struct tr2_tgt tr2_tgt_normal = {
 	fn_atexit,
 	fn_error_va_fl,
 	fn_command_path_fl,
+	fn_command_ancestry_fl,
 	fn_command_name_fl,
 	fn_command_mode_fl,
 	fn_alias_fl,
diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c
index a8018f18cc..af4d65a0a5 100644
--- a/trace2/tr2_tgt_perf.c
+++ b/trace2/tr2_tgt_perf.c
@@ -253,6 +253,21 @@  static void fn_command_path_fl(const char *file, int line, const char *pathname)
 	strbuf_release(&buf_payload);
 }
 
+static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names)
+{
+	const char *event_name = "cmd_ancestry";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addstr(&buf_payload, "ancestry:[");
+	/* It's not an argv but the rules are basically the same. */
+	sq_append_quote_argv_pretty(&buf_payload, parent_names);
+	strbuf_addch(&buf_payload, ']');
+
+	perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
+			 &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
 static void fn_command_name_fl(const char *file, int line, const char *name,
 			       const char *hierarchy)
 {
@@ -532,6 +547,7 @@  struct tr2_tgt tr2_tgt_perf = {
 	fn_atexit,
 	fn_error_va_fl,
 	fn_command_path_fl,
+	fn_command_ancestry_fl,
 	fn_command_name_fl,
 	fn_command_mode_fl,
 	fn_alias_fl,