[devtools] Tweaks to log OSH usage during its own release.

- Add support for OSH_DEBUG_DIR in addition to --debug-file.  The former
  will have files named by PID.
- Expose the issue with subshells and the CrashDumper.  Add a PID to the
  crash dump filename for now.
- Make naming more consistent in demo/
- osh-debug.sh: Shell functions for doing the release interactively
  under OSH.

bin/oil.py

@@ -302,22 +302,39 @@ def ShellMain(lang, argv0, argv, login_shell):
   # - prompt_ev needs word_ev for $PS1, which needs prompt_ev for @P
   exec_deps = cmd_exec.Deps()
 
-  if opts.debug_file:
-    debug_f = util.DebugFile(fd_state.Open(opts.debug_file, mode='w'))
+  my_pid = posix.getpid()
+
+  debug_path = ''
+  debug_dir = posix.environ.get('OSH_DEBUG_DIR')
+  if opts.debug_file:  # --debug-file takes precedence over OSH_DEBUG_DIR
+    debug_path = opts.debug_file
+    debug_f = util.DebugFile(fd_state.Open(debug_path, mode='w'))
+  elif debug_dir:
+    debug_path = os_path.join(debug_dir, '%d-osh.log' % my_pid)
+    debug_f = util.DebugFile(fd_state.Open(debug_path, mode='w'))
   else:
     debug_f = util.NullDebugFile()
   exec_deps.debug_f = debug_f
 
-  debug_f.log('Debug file is %s', opts.debug_file)
+  # Not using datetime for dependency reasons.  TODO: maybe show the date at
+  # the beginning of the log, and then only show time afterward?  To save
+  # space, and make space for microseconds.  (datetime supports microseconds
+  # but time.strftime doesn't).
+  iso_stamp = time.strftime("%Y-%m-%d %H:%M:%S")
+  debug_f.log('%s [%d] OSH started with argv %s', iso_stamp, my_pid, argv)
+  if debug_path:
+    debug_f.log('Writing logs to %r', debug_path)
 
   interp = posix.environ.get('OSH_HIJACK_SHEBANG', '')
   exec_deps.ext_prog = process.ExternalProgram(interp, fd_state, debug_f)
 
   splitter = split.SplitContext(mem)
   exec_deps.splitter = splitter
 
-  # Controlled by env variable, flag, or hook?
-  exec_deps.dumper = dev.CrashDumper(posix.environ.get('OSH_CRASH_DUMP_DIR', ''))
+  # This could just be OSH_DEBUG_STREAMS='debug crash' ?  That might be
+  # stuffing too much into one, since a .json crash dump isn't a stream.
+  crash_dump_dir = posix.environ.get('OSH_CRASH_DUMP_DIR', '')
+  exec_deps.dumper = dev.CrashDumper(crash_dump_dir)
 
   if opts.xtrace_to_debug_file:
     trace_f = debug_f
@@ -360,7 +377,7 @@ def ShellMain(lang, argv0, argv, login_shell):
 
   spec_builder = builtin_comp.SpecBuilder(ex, parse_ctx, word_ev, splitter)
   # Add some builtins that depend on the executor!
-  complete_builtin = builtin_comp.Complete(spec_builder, comp_lookup)  # used later
+  complete_builtin = builtin_comp.Complete(spec_builder, comp_lookup)
   builtins[builtin_e.COMPLETE] = complete_builtin
   builtins[builtin_e.COMPGEN] = builtin_comp.CompGen(spec_builder)
 

build/oil-defs/Python-2.7.13/Modules/timemodule.c/time_methods.def

@@ -3,5 +3,6 @@
 static PyMethodDef time_methods[] = {
   {"time", time_time, METH_NOARGS},
   {"sleep", time_sleep, METH_VARARGS},
+  {"strftime", time_strftime, METH_VARARGS},
   {0},
 };

core/dev.py

@@ -4,6 +4,8 @@
 """
 from __future__ import print_function
 
+import posix
+
 from asdl import const
 from core import util
 from osh import word
@@ -115,6 +117,8 @@ def MaybeDump(self, status):
     if not self.collected:
       return
 
+    my_pid = posix.getpid()  # Get fresh PID here
+
     # Other things we need: the reason for the crash!  _ErrorWithLocation is
     # required I think.
     d = {
@@ -123,12 +127,13 @@ def MaybeDump(self, status):
         'debug_stack': self.debug_stack,
         'error': self.error,
         'status': status,
+        'pid': my_pid,
     }
 
     # TODO: Add PID here
-    path = os_path.join(self.crash_dump_dir, 'osh-crash-dump.json')
+    path = os_path.join(self.crash_dump_dir, '%d-osh-crash-dump.json' % my_pid)
     with open(path, 'w') as f:
       import json
       json.dump(d, f, indent=2)
       #print(repr(d), file=f)
-    util.log('Wrote crash dump to %s', path)
+    util.log('[%d] Wrote crash dump to %s', my_pid, path)

core/process.py

@@ -404,7 +404,7 @@ def Exec(self, argv, environ):
         # consistent with mksh and zsh.
         status = 127
 
-      sys.exit(status)
+      sys.exit(status)  # raises SystemExit
     # NO RETURN
 
 
@@ -436,7 +436,9 @@ def Run(self):
     if self.disable_errexit:
       self.ex.exec_opts.errexit.Disable()
     self.ex.ExecuteAndCatch(self.node, fork_external=False)
-    sys.exit(self.ex.LastStatus())  # Must exit!
+
+    # Raises SystemExit, so we still have time to write a crash dump.
+    sys.exit(self.ex.LastStatus())
 
 
 class _HereDocWriterThunk(Thunk):

demo/osh-crash.sh

@@ -0,0 +1,49 @@
+#!/bin/bash
+#
+# Usage:
+#   ./crash.sh <function name>
+
+set -o nounset
+set -o pipefail
+set -o errexit
+
+g() {
+  local g=1
+  echo foo > $bar
+}
+
+f() {
+  shift
+  local flocal=flocal
+  FOO=bar g A B
+}
+
+main() {
+  f a b c
+}
+
+run-with-osh() {
+  OSH_CRASH_DUMP_DIR=_tmp bin/osh $0 main "$@"
+}
+
+_do-subshell() {
+  echo PID=$$
+  ( f a b c )
+}
+
+# Problem: we get two difference crash dumps, with two different stacks.
+# It would be nice to unify these somehow.
+#
+# Could we add a URL to link related crash dumps?  Maybe do it with PPID?  If a
+# subshell exits with 1, and we have OSH_CRASH_DUMP_DIR, then we know it should
+# have exited?
+#
+# MaybeCollect is done on fatal errors in several places.  MaybeDump is done on
+# ExecuteAndCatch.  Subshells raise SystemExit?
+
+do-subshell() {
+  # clear environment so it's smaller
+  env -i OSH_CRASH_DUMP_DIR=_tmp bin/osh $0 _do-subshell "$@"
+}
+
+"$@"

demo/osh-debug.sh

@@ -0,0 +1,55 @@
+#!/bin/bash
+#
+# Usage:
+#   ./osh-debug.sh <function name>
+
+set -o nounset
+set -o pipefail
+set -o errexit
+
+func() {
+  metrics/source-code.sh osh-cloc
+}
+
+# Make sure it works recursively
+#
+# Problem: xargs, find -exec, make, etc. won't respect this!  They will use the
+# real shebang.
+
+recursive() {
+  echo ===
+  $0 func
+  echo ===
+}
+
+hijack-recursive() {
+  # $(which osh)
+
+  local dir=_tmp/osh-debug
+  mkdir -p $dir
+
+  OSH_DEBUG_DIR=$dir \
+  OSH_HIJACK_SHEBANG=bin/osh \
+    bin/osh $0 recursive
+}
+
+#
+# For the release
+#
+
+readonly RELEASE_LOGS_DIR=_tmp/osh-debug-release
+
+osh-for-release() {
+  mkdir -p $RELEASE_LOGS_DIR
+  rm -f $RELEASE_LOGS_DIR/*
+
+  # NOTE: This runs the SYSTEM osh, because running bin/osh while doing the
+  # release doesn't work!
+  OSH_DEBUG_DIR=$RELEASE_LOGS_DIR OSH_HIJACK_SHEBANG=$(which osh) osh
+}
+
+analyze() {
+  grep '^Hijacked' $RELEASE_LOGS_DIR/*
+}
+
+"$@"

spec/osh-only.test.sh

@@ -2,7 +2,7 @@
 
 #### --debug-file
 $SH --debug-file $TMP/debug.txt -c 'true'
-grep 'Debug file' $TMP/debug.txt >/dev/null && echo yes
+grep 'OSH started with' $TMP/debug.txt >/dev/null && echo yes
 ## stdout: yes
 
 #### debug-completion option