Ruby: Model what is written to the log from stdlib Logger methods

Author: alexrford

ruby/ql/lib/codeql/ruby/Concepts.qll

@@ -644,3 +644,32 @@ module Path {
     abstract class Range extends DataFlow::Node { }
   }
 }
+
+/**
+ * A data-flow node that logs data.
+ *
+ * Extend this class to refine existing API models. If you want to model new APIs,
+ * extend `Logging::Range` instead.
+ */
+class Logging extends DataFlow::Node {
+  Logging::Range range;
+
+  Logging() { this = range }
+
+  /** Gets an input that is logged. */
+  DataFlow::Node getAnInput() { result = range.getAnInput() }
+}
+
+/** Provides a class for modeling new logging mechanisms. */
+module Logging {
+  /**
+   * A data-flow node that logs data.
+   *
+   * Extend this class to model new APIs. If you want to refine existing API models,
+   * extend `Logging` instead.
+   */
+  abstract class Range extends DataFlow::Node {
+    /** Gets an input that is logged. */
+    abstract DataFlow::Node getAnInput();
+  }
+}

ruby/ql/lib/codeql/ruby/frameworks/StandardLibrary.qll

@@ -3,6 +3,8 @@ private import codeql.ruby.Concepts
 private import codeql.ruby.DataFlow
 private import codeql.ruby.ApiGraphs
 private import codeql.ruby.dataflow.FlowSummary
+private import codeql.ruby.dataflow.internal.DataFlowDispatch
+private import codeql.ruby.CFG
 
 /**
  * The `Kernel` module is included by the `Object` class, so its methods are available
@@ -347,3 +349,103 @@ class RegexpEscapeSummary extends SummarizedCallable {
     preservesValue = false
   }
 }
+
+/** A reference to a `Logger` instance */
+private DataFlow::Node loggerInstance() {
+  result = API::getTopLevelMember("Logger").getAnInstantiation()
+  or
+  exists(DataFlow::Node inst |
+    inst = loggerInstance() and
+    inst.(DataFlow::LocalSourceNode).flowsTo(result)
+  )
+  or
+  // Assume that a variable assigned as a `Logger` instance is always a
+  // `Logger` instance. This covers class and instance variables where we can't
+  // necessarily trace a dataflow path from assignment to use.
+  exists(Variable v, Assignment a |
+    a.getLeftOperand().getAVariable() = v and
+    a.getRightOperand() = loggerInstance().asExpr().getExpr() and
+    result.asExpr().getExpr().(VariableReadAccess).getVariable() = v
+  )
+}
+
+/**
+ * A call to a `Logger` instance method that causes a message to be logged.
+ */
+abstract class LoggerLoggingCall extends Logging::Range, DataFlow::CallNode {
+  LoggerLoggingCall() { this.getReceiver() = loggerInstance() }
+}
+
+/**
+ * A call to `Logger#add` or its alias `Logger#log`.
+ */
+private class LoggerAddCall extends LoggerLoggingCall {
+  LoggerAddCall() { this.getMethodName() = ["add", "log"] }
+
+  override DataFlow::Node getAnInput() {
+    // Both the message and the progname are form part of the log output:
+    // Logger#add(severity, message) / Logger#add(severity, message, progname)
+    result = this.getArgument(1)
+    or
+    result = this.getArgument(2)
+    or
+    // a return value from the block in Logger#add(severity) <block> or in
+    // Logger#add(severity, nil, progname) <block>
+    (
+      this.getNumberOfArguments() = 1
+      or
+      // TODO: this could track the value of the `message` argument to make
+      // this check more accurate
+      this.getArgument(1).asExpr().getExpr() instanceof NilLiteral
+    ) and
+    exprNodeReturnedFrom(result, this.getBlock().asExpr().getExpr())
+  }
+}
+
+/**
+ * A call to `Logger#<<`.
+ */
+private class LoggerPushCall extends LoggerLoggingCall {
+  LoggerPushCall() { this.getMethodName() = "<<" }
+
+  override DataFlow::Node getAnInput() {
+    // Logger#<<(msg)
+    result = this.getArgument(0)
+  }
+}
+
+/**
+ * A call to a `Logger` method that logs at a preset severity level.
+ *
+ * Specifically, these methods are `debug`, `error`, `fatal`, `info`,
+ * `unknown`, and `warn`.
+ */
+private class LoggerInfoStyleCall extends LoggerLoggingCall {
+  LoggerInfoStyleCall() {
+    this.getMethodName() = ["debug", "error", "fatal", "info", "unknown", "warn"]
+  }
+
+  override DataFlow::Node getAnInput() {
+    // `msg` from `Logger#info(msg)`,
+    // or `progname` from `Logger#info(progname) <block>`
+    result = this.getArgument(0)
+    or
+    // a return value from the block in `Logger#info(progname) <block>`
+    exprNodeReturnedFrom(result, this.getBlock().asExpr().getExpr())
+  }
+}
+
+/**
+ * A call to `Logger#progname=`. This sets a default progname.
+ * This call does not log anything directly, but the assigned value can appear
+ * in future log messages that do not specify a `progname` argument.
+ */
+private class LoggerSetPrognameCall extends LoggerLoggingCall {
+  LoggerSetPrognameCall() { this.getMethodName() = "progname=" }
+
+  override DataFlow::Node getAnInput() {
+    exists(CfgNodes::ExprNodes::AssignExprCfgNode a | this.getArgument(0).asExpr() = a |
+      result.asExpr() = a.getRhs()
+    )
+  }
+}

ruby/ql/test/library-tests/frameworks/Logging.rb

@@ -0,0 +1,76 @@
+require 'logger'
+
+class LoggerTest
+  @@cls_logger = Logger.new STDERR
+  @@cls_logger.progname = "LoggerTest"
+
+  def init_logger
+    if @logger == nil
+      @logger = Logger.new STDOUT
+    end
+  end
+
+  def debug_log(msg)
+    init_logger
+    @logger.debug msg
+  end
+
+  def error_log(msg)
+    init_logger
+    @logger.error do
+      msg + "!"
+    end
+  end
+
+  def fatal_log(msg)
+    init_logger
+    @logger.fatal msg
+  end
+
+  def warn_log(msg)
+    init_logger
+    @logger.warn msg
+  end
+
+  def unknown_log(msg)
+    init_logger
+    @logger.unknown("unknown prog") { msg }
+  end
+
+  def info_log(msg)
+    init_logger
+    @logger.info do
+      if msg.size > 100
+        msg[0..91] + "..." + msg[-5..msg.size]
+      else
+        msg
+      end
+    end
+  end
+
+  def push_log(msg)
+    logger = Logger.new STDERR
+    logger_alias = logger
+    logger_alias << ("test message: " + msg)
+  end
+
+  def add_log(msg)
+    @@cls_logger.add(Logger::INFO) { "block" }
+    # Includes both progname and block return if 'message' is 'nil'
+    @@cls_logger.add(Logger::INFO, nil, "progname1") { "block" }
+
+    # block return value is ignored if `message` is specified
+    @@cls_logger.add(Logger::WARN, "message1") { "not logged" }
+    @@cls_logger.add(Logger::WARN, "message2", "progname2") { "not logged" }
+  end
+
+  def log_log(msg)
+    @@cls_logger.log(Logger::INFO) { "block" }
+    # Includes both progname and block return if 'message' is 'nil'
+    @@cls_logger.log(Logger::INFO, nil, "progname1") { "block" }
+
+    # block return value is ignored if `message` is specified
+    @@cls_logger.log(Logger::WARN, "message1") { "not logged" }
+    @@cls_logger.log(Logger::WARN, "message2", "progname2") { "not logged" }
+  end
+end

ruby/ql/test/library-tests/frameworks/StandardLibrary.expected

@@ -69,3 +69,27 @@ classEvalCallCodeExecutions
 | Eval.rb:25:1:25:47 | call to class_eval | Eval.rb:25:16:25:32 | "def foo; 1; end" |
 moduleEvalCallCodeExecutions
 | Eval.rb:26:1:26:54 | call to module_eval | Eval.rb:26:17:26:33 | "def bar; 1; end" |
+loggerLoggingCallInputs
+| Logging.rb:5:3:5:23 | call to progname= | Logging.rb:5:27:5:38 | "LoggerTest" |
+| Logging.rb:15:5:15:21 | call to debug | Logging.rb:15:19:15:21 | msg |
+| Logging.rb:20:5:22:7 | call to error | Logging.rb:21:7:21:15 | ... + ... |
+| Logging.rb:27:5:27:21 | call to fatal | Logging.rb:27:19:27:21 | msg |
+| Logging.rb:32:5:32:20 | call to warn | Logging.rb:32:18:32:20 | msg |
+| Logging.rb:37:5:37:43 | call to unknown | Logging.rb:37:21:37:34 | "unknown prog" |
+| Logging.rb:37:5:37:43 | call to unknown | Logging.rb:37:39:37:41 | msg |
+| Logging.rb:42:5:48:7 | call to info | Logging.rb:43:7:47:9 | if ... |
+| Logging.rb:54:5:54:44 | ... << ... | Logging.rb:54:21:54:44 | ( ... ) |
+| Logging.rb:58:5:58:46 | call to add | Logging.rb:58:38:58:44 | "block" |
+| Logging.rb:60:5:60:64 | call to add | Logging.rb:60:36:60:38 | nil |
+| Logging.rb:60:5:60:64 | call to add | Logging.rb:60:41:60:51 | "progname1" |
+| Logging.rb:60:5:60:64 | call to add | Logging.rb:60:56:60:62 | "block" |
+| Logging.rb:63:5:63:63 | call to add | Logging.rb:63:36:63:45 | "message1" |
+| Logging.rb:64:5:64:76 | call to add | Logging.rb:64:36:64:45 | "message2" |
+| Logging.rb:64:5:64:76 | call to add | Logging.rb:64:48:64:58 | "progname2" |
+| Logging.rb:68:5:68:46 | call to log | Logging.rb:68:38:68:44 | "block" |
+| Logging.rb:70:5:70:64 | call to log | Logging.rb:70:36:70:38 | nil |
+| Logging.rb:70:5:70:64 | call to log | Logging.rb:70:41:70:51 | "progname1" |
+| Logging.rb:70:5:70:64 | call to log | Logging.rb:70:56:70:62 | "block" |
+| Logging.rb:73:5:73:63 | call to log | Logging.rb:73:36:73:45 | "message1" |
+| Logging.rb:74:5:74:76 | call to log | Logging.rb:74:36:74:45 | "message2" |
+| Logging.rb:74:5:74:76 | call to log | Logging.rb:74:48:74:58 | "progname2" |

ruby/ql/test/library-tests/frameworks/StandardLibrary.ql

@@ -30,3 +30,5 @@ query DataFlow::Node classEvalCallCodeExecutions(ClassEvalCallCodeExecution e) {
 query DataFlow::Node moduleEvalCallCodeExecutions(ModuleEvalCallCodeExecution e) {
   result = e.getCode()
 }
+
+query DataFlow::Node loggerLoggingCallInputs(LoggerLoggingCall c) { result = c.getAnInput() }