Add --log-subprocess for debugging

Author: eregon

doc/contributor/debugging.md

@@ -5,6 +5,8 @@ You've got many options for debugging the implementation of TruffleRuby.
 If you want to debug an application running on TruffleRuby, and don't suspect
 any bug in TruffleRuby itself, use GraalVM [tools](../user/tools.md) as usual.
 
+Also see [user debugging docs](../user/debugging.md).
+
 ## Print Debugging
 
 `System.err.println(...);` in Java and `p` in Ruby is a great first tool to use for

doc/user/debugging.md

@@ -40,3 +40,12 @@ When debugging you may want to see this information.
 An option to show more information is `--backtraces-interleave-java=true`, which shows you the Java methods involved in executing each Ruby method.
 
 When you are interoperating with other languages, including C extensions, backtraces for Java exceptions may be missing information, as the Java frames are gone by the time Ruby has a chance to format them into a backtrace.
+
+## Printing Subprocesses
+
+You can print all subprocesses created by TruffleRuby using the option `--log-subprocess`.
+
+```bash
+$ ruby --log-subprocess -e '`ls .`'
+[ruby] INFO: spawn: ls .
+```

src/main/java/org/truffleruby/debug/TruffleDebugNodes.java

@@ -330,36 +330,53 @@ protected int getCacheLimit() {
 
     }
 
-    @CoreMethod(names = "log_config", onSingleton = true, required = 1)
-    public abstract static class LogConfigNode extends CoreMethodArrayArgumentsNode {
+    @CoreMethod(names = "log_warning", onSingleton = true, required = 1)
+    public abstract static class LogWarningNode extends CoreMethodArrayArgumentsNode {
 
         @Specialization
-        protected Object logConfig(Object value,
+        protected Object logWarning(Object value,
+                @Cached ToJavaStringNode toJavaStringNode) {
+            warning(toJavaStringNode.executeToJavaString(value));
+            return nil;
+        }
+
+        @TruffleBoundary
+        static void warning(String message) {
+            RubyLanguage.LOGGER.warning(message);
+        }
+
+    }
+
+    @CoreMethod(names = "log_info", onSingleton = true, required = 1)
+    public abstract static class LogInfoNode extends CoreMethodArrayArgumentsNode {
+
+        @Specialization
+        protected Object logInfo(Object value,
                 @Cached ToJavaStringNode toJavaStringNode) {
             config(toJavaStringNode.executeToJavaString(value));
             return nil;
         }
 
         @TruffleBoundary
         static void config(String message) {
-            RubyLanguage.LOGGER.config(message);
+            RubyLanguage.LOGGER.info(message);
         }
 
     }
 
-    @CoreMethod(names = "log_warning", onSingleton = true, required = 1)
-    public abstract static class LogWarningNode extends CoreMethodArrayArgumentsNode {
+    @CoreMethod(names = "log_config", onSingleton = true, required = 1)
+    public abstract static class LogConfigNode extends CoreMethodArrayArgumentsNode {
 
         @Specialization
-        protected Object logWarning(Object value,
+        protected Object logConfig(Object value,
                 @Cached ToJavaStringNode toJavaStringNode) {
-            warning(toJavaStringNode.executeToJavaString(value));
+            config(toJavaStringNode.executeToJavaString(value));
             return nil;
         }
 
         @TruffleBoundary
-        static void warning(String message) {
-            RubyLanguage.LOGGER.warning(message);
+        static void config(String message) {
+            RubyLanguage.LOGGER.config(message);
         }
 
     }

src/main/java/org/truffleruby/language/TruffleBootNodes.java

@@ -319,7 +319,8 @@ protected Object getOption(Object optionName,
             if (descriptor == null) {
                 throw new RaiseException(
                         getContext(),
-                        coreExceptions().nameError("option not defined", nil, optionNameString, this));
+                        coreExceptions()
+                                .nameError("option not defined: " + optionNameString, nil, optionNameString, this));
             }
 
             Object value = getContext().getOptions().fromDescriptor(descriptor);

src/main/java/org/truffleruby/options/Options.java

@@ -71,6 +71,8 @@ public class Options {
     public final boolean HASHING_DETERMINISTIC;
     /** --fiber-leave-context=true */
     public final boolean FIBER_LEAVE_CONTEXT;
+    /** --log-subprocess=false */
+    public final boolean LOG_SUBPROCESS;
     /** --exceptions-store-java=false */
     public final boolean EXCEPTIONS_STORE_JAVA;
     /** --exceptions-print-java=false */
@@ -215,6 +217,7 @@ public Options(Env env, OptionValues options, LanguageOptions languageOptions) {
         PATCHING = options.get(OptionsCatalog.PATCHING_KEY);
         HASHING_DETERMINISTIC = options.get(OptionsCatalog.HASHING_DETERMINISTIC_KEY);
         FIBER_LEAVE_CONTEXT = options.get(OptionsCatalog.FIBER_LEAVE_CONTEXT_KEY);
+        LOG_SUBPROCESS = options.get(OptionsCatalog.LOG_SUBPROCESS_KEY);
         EXCEPTIONS_STORE_JAVA = options.get(OptionsCatalog.EXCEPTIONS_STORE_JAVA_KEY);
         EXCEPTIONS_PRINT_JAVA = options.get(OptionsCatalog.EXCEPTIONS_PRINT_JAVA_KEY);
         EXCEPTIONS_PRINT_UNCAUGHT_JAVA = options.get(OptionsCatalog.EXCEPTIONS_PRINT_UNCAUGHT_JAVA_KEY);
@@ -326,6 +329,8 @@ public Object fromDescriptor(OptionDescriptor descriptor) {
                 return HASHING_DETERMINISTIC;
             case "ruby.fiber-leave-context":
                 return FIBER_LEAVE_CONTEXT;
+            case "ruby.log-subprocess":
+                return LOG_SUBPROCESS;
             case "ruby.exceptions-store-java":
                 return EXCEPTIONS_STORE_JAVA;
             case "ruby.exceptions-print-java":

src/main/ruby/truffleruby/core/truffle/process_operations.rb

@@ -350,7 +350,8 @@ def convert_env_value(value)
 
       def spawn_setup(alter_process)
         env = @options.delete(:unsetenv_others) ? {} : ENV.to_hash
-        if add_to_env = @options.delete(:env)
+        @add_to_env = add_to_env = @options.delete(:env)
+        if add_to_env
           add_to_env.each do |key, value|
             if value
               env[key] = value
@@ -415,6 +416,7 @@ def redirect_file_descriptor(from, to, alter_process)
       end
 
       def spawn
+        log_command 'spawn'
         pid = posix_spawnp @command, @argv, @env_array, @options
         # Check if the command exists *after* invoking posix_spawn so we have a pid
         if not resolve_in_path(@command)
@@ -497,6 +499,7 @@ def posix_spawnp(command, args, env_array, options)
       end
 
       def exec
+        log_command('exec')
         # exec validates the command only if it searches in $PATH
         if should_search_path?(@command)
           if resolved = resolve_in_path(@command)
@@ -516,6 +519,17 @@ def exec
         raise SystemCallError.new('execve() should not return', 0)
       end
 
+      Truffle::Boot.delay do
+        LOG_SUBPROCESS = Truffle::Boot.get_option 'log-subprocess'
+      end
+
+      def log_command(type)
+        if LOG_SUBPROCESS
+          env = (@add_to_env || {}).map { |k,v| "#{k}=#{v}" }.join(' ')
+          Truffle::Debug.log_info "#{type}: #{env}#{' ' unless env.empty?}#{@argv.join(' ')}"
+        end
+      end
+
       def should_use_shell?(command)
         command.b.match?(SHELL_META_CHAR_PATTERN)
       end

src/options.yml

@@ -101,6 +101,7 @@ EXPERT:
     PATCHING: [patching, boolean, true, Use patching]
     HASHING_DETERMINISTIC: [hashing-deterministic, boolean, false, Produce deterministic hash values]
     FIBER_LEAVE_CONTEXT: [fiber-leave-context, boolean, true, 'Leave the TruffleContext when suspending a Fiber (avoids triggering multithreading)']
+    LOG_SUBPROCESS: [log-subprocess, boolean, false, 'Log whenever a subprocess is created']
 
     # Options to tweak backtraces
     EXCEPTIONS_STORE_JAVA: [exceptions-store-java, boolean, false, Store the Java exception with the Ruby backtrace]

src/shared/java/org/truffleruby/shared/options/OptionsCatalog.java

@@ -53,6 +53,7 @@ public class OptionsCatalog {
     public static final OptionKey<Boolean> PATCHING_KEY = new OptionKey<>(true);
     public static final OptionKey<Boolean> HASHING_DETERMINISTIC_KEY = new OptionKey<>(false);
     public static final OptionKey<Boolean> FIBER_LEAVE_CONTEXT_KEY = new OptionKey<>(true);
+    public static final OptionKey<Boolean> LOG_SUBPROCESS_KEY = new OptionKey<>(false);
     public static final OptionKey<Boolean> EXCEPTIONS_STORE_JAVA_KEY = new OptionKey<>(false);
     public static final OptionKey<Boolean> EXCEPTIONS_PRINT_JAVA_KEY = new OptionKey<>(false);
     public static final OptionKey<Boolean> EXCEPTIONS_PRINT_UNCAUGHT_JAVA_KEY = new OptionKey<>(false);
@@ -385,6 +386,13 @@ public class OptionsCatalog {
             .stability(OptionStability.EXPERIMENTAL)
             .build();
 
+    public static final OptionDescriptor LOG_SUBPROCESS = OptionDescriptor
+            .newBuilder(LOG_SUBPROCESS_KEY, "ruby.log-subprocess")
+            .help("Log whenever a subprocess is created")
+            .category(OptionCategory.EXPERT)
+            .stability(OptionStability.EXPERIMENTAL)
+            .build();
+
     public static final OptionDescriptor EXCEPTIONS_STORE_JAVA = OptionDescriptor
             .newBuilder(EXCEPTIONS_STORE_JAVA_KEY, "ruby.exceptions-store-java")
             .help("Store the Java exception with the Ruby backtrace")
@@ -1153,6 +1161,8 @@ public static OptionDescriptor fromName(String name) {
                 return HASHING_DETERMINISTIC;
             case "ruby.fiber-leave-context":
                 return FIBER_LEAVE_CONTEXT;
+            case "ruby.log-subprocess":
+                return LOG_SUBPROCESS;
             case "ruby.exceptions-store-java":
                 return EXCEPTIONS_STORE_JAVA;
             case "ruby.exceptions-print-java":
@@ -1393,6 +1403,7 @@ public static OptionDescriptor[] allDescriptors() {
             PATCHING,
             HASHING_DETERMINISTIC,
             FIBER_LEAVE_CONTEXT,
+            LOG_SUBPROCESS,
             EXCEPTIONS_STORE_JAVA,
             EXCEPTIONS_PRINT_JAVA,
             EXCEPTIONS_PRINT_UNCAUGHT_JAVA,