croslog/log_parser_audit_test.cc

// Copyright 2020 The Chromium OS Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "croslog/log_parser_audit.h"

#include <memory>
#include <string>
#include <utility>

#include "base/files/file_path.h"
#include "gtest/gtest.h"

#include "croslog/log_line_reader.h"

namespace croslog {

namespace {
constexpr char kTimezoneEnvName[] = "TZ";
}

class LogParserAuditTest : public ::testing::Test {
 public:
  LogParserAuditTest() = default;
  LogParserAuditTest(const LogParserAuditTest&) = delete;
  LogParserAuditTest& operator=(const LogParserAuditTest&) = delete;

  static base::Time TimeFromExploded(int year,
                                     int month,
                                     int day_of_month,
                                     int hour,
                                     int minute,
                                     int second,
                                     int microsec) {
    base::Time time;
    EXPECT_TRUE(base::Time::FromUTCExploded(
        base::Time::Exploded{year, month, 0, day_of_month, hour, minute, second,
                             0},
        &time));
    time += base::TimeDelta::FromMicroseconds(microsec);
    return time;
  }

  static void SetTimeZone(const char* time_zone) {
    // tzset() distinguishes between the TZ variable being present and empty
    // and not being present, so we have to consider the case of time_zone
    // being NULL.
    if (time_zone) {
      setenv(kTimezoneEnvName, time_zone, 1);
    } else {
      unsetenv(kTimezoneEnvName);
    }
    tzset();
  }

 private:
  const char* saved_tz_ = nullptr;

  void SetUp() override {
    saved_tz_ =
        getenv(kTimezoneEnvName) ? strdup(getenv(kTimezoneEnvName)) : nullptr;

    // Set up UTC as the default timezone in this test.
    SetTimeZone("UTC+00");
  }

  void TearDown() override {
    SetTimeZone(saved_tz_);
    free(const_cast<char*>(saved_tz_));
    saved_tz_ = nullptr;
  }
};

TEST_F(LogParserAuditTest, Parse) {
  LogParserAudit parser;
  LogLineReader reader(LogLineReader::Backend::FILE);
  reader.OpenFile(base::FilePath("./testdata/TEST_AUDIT_LOG"));

  {
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-01-18T23:17:27.098000+00:00", s.substr(0, 32));
    EXPECT_EQ(TimeFromExploded(2020, 1, 18, 23, 17, 27, 98000), e->time());
    EXPECT_EQ(0, e->pid());
    EXPECT_EQ("audit", e->tag());

    EXPECT_EQ("INFO audit[0]: SECCOMP pid=0 auid=4294967296 uid=1000 gid=1000",
              s.substr(33, s.size()));
  }

  {
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-06-21T23:15:49.018000+00:00", s.substr(0, 32));
    EXPECT_EQ(TimeFromExploded(2020, 6, 21, 23, 15, 49, 18000), e->time());
    EXPECT_EQ(476, e->pid());
    EXPECT_EQ("audit", e->tag());

    EXPECT_EQ(
        "INFO audit[476]: DAEMON_START op=start ver=2.8.4 format=raw "
        "kernel=4.4.221-17496-g92f60640939f auid=4294967295 pid=476 uid=0 "
        "ses=4294967295 subj=u:r:cros_auditd:s0 res=success",
        s.substr(33, s.size()));
  }

  {
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-06-21T23:15:50.925000+00:00", s.substr(0, 32));
    EXPECT_EQ(TimeFromExploded(2020, 6, 21, 23, 15, 50, 925000), e->time());
    EXPECT_EQ(655360, e->pid());
    EXPECT_EQ("audit", e->tag());

    EXPECT_EQ(
        "INFO audit[655360]: AVC avc:  denied  { search } for  pid=655360 "
        "comm=\"bootstat\" name=\"dm-0\" dev=\"sysfs\" ino=17352 "
        "scontext=u:r:cros_bootstat:s0 tcontext=u:object_r:sysfs_dm:s0 "
        "tclass=dir permissive=0",
        s.substr(33, s.size()));
  }

  {
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-06-21T23:17:27.098000+00:00", s.substr(0, 32));
    EXPECT_EQ(TimeFromExploded(2020, 6, 21, 23, 17, 27, 98000), e->time());
    EXPECT_EQ("test", e->tag());
    EXPECT_EQ(4844, e->pid());

    EXPECT_EQ(
        "INFO test[4844]: SECCOMP auid=4294967295 uid=1000 gid=1000 "
        "ses=4294967295 subj=u:r:cros_browser:s0 ppid=4843 pid=4844 "
        "comm=\"nacl_helper\" exe=\"/opt/google/chrome/nacl_helper\" "
        "sig=0 arch=c000003e syscall=273 compat=0 ip=0x7b7aefb1949d "
        "code=0x50000",
        s.substr(33, s.size()));
  }

  {
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-06-21T23:17:27.098000+00:00", s.substr(0, 32));
    EXPECT_EQ(TimeFromExploded(2020, 6, 21, 23, 17, 27, 98000), e->time());
    EXPECT_EQ(4845, e->pid());
    EXPECT_EQ("audit", e->tag());

    EXPECT_EQ(
        "INFO audit[4845]: SECCOMP auid=4294967296 uid=1000 gid=1000 "
        "ses=4294967296 subj=u:r:cros_browser:s0 pid=4845 ppid=4844 "
        "comm=\"nacl_helper\" exe=\"/opt/google/chrome/nacl_helper\" "
        "sig=0 arch=c000003e syscall=273 compat=0 ip=0x7b7aefb1949d "
        "code=0x50000",
        s.substr(33, s.size()));
  }

  {
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-06-21T23:17:30.000000+00:00", s.substr(0, 32));
    EXPECT_EQ(TimeFromExploded(2020, 6, 21, 23, 17, 30, 00000), e->time());
    EXPECT_EQ(-1, e->pid());
    EXPECT_EQ("audit", e->tag());

    EXPECT_EQ(
        "INFO audit: SECCOMP auid=4294967296 uid=1000 gid=1000 "
        "ses=4294967296 subj=u:r:cros_browser:s0 comm=\"nacl_helper\" "
        "exe=\"/opt/google/chrome/nacl_helper\" sig=0 arch=c000003e "
        "syscall=273 compat=0 ip=0x7b7aefb1949d code=0x50000",
        s.substr(33, s.size()));
  }

  {
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    const std::string& s = e->entire_line();
    EXPECT_EQ("2019-09-16T14:21:41.984000+00:00", s.substr(0, 32));
    EXPECT_EQ(TimeFromExploded(2019, 9, 16, 14, 21, 41, 984000), e->time());
    EXPECT_EQ(493, e->pid());
    EXPECT_EQ("audit", e->tag());

    EXPECT_EQ(
        "INFO audit[493]: DAEMON_START op=start ver=2.8.4 format=raw "
        "kernel=3.18.0-19732-gf84df209b0a1 auid=4294967295 pid=493 uid=0 "
        "ses=4294967295 subj=u:r:cros_auditd:s0 res=success",
        s.substr(33, s.size()));
  }

  {
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_FALSE(maybe_line.has_value());
  }
}

TEST_F(LogParserAuditTest, ParseWithTimezone) {
  LogLineReader reader(LogLineReader::Backend::FILE);
  reader.OpenFile(base::FilePath("./testdata/TEST_AUDIT_LOG"));

  // MEZ (UTC+01, during non-DST)
  SetTimeZone("Europe/Berlin");
  {
    LogParserAudit parser;
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    // Compare times in UTC
    EXPECT_EQ(TimeFromExploded(2020, 1, 18, 23, 17, 27, 98000), e->time());

    // Compare time strings in the local timezone
    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-01-19T00:17:27.098000+01:00", s.substr(0, 32));
  }

  // JST (UTC+09)
  SetTimeZone("Asia/Tokyo");
  {
    LogParserAudit parser;
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    // Compare times in UTC
    EXPECT_EQ(TimeFromExploded(2020, 6, 21, 23, 15, 49, 18000), e->time());

    // Compare time strings in the local timezone
    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-06-22T08:15:49.018000+09:00", s.substr(0, 32));
  }

  // PDT (UTC-07)
  SetTimeZone("America/Los_Angeles");
  {
    LogParserAudit parser;
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    // Compare times in UTC
    EXPECT_EQ(TimeFromExploded(2020, 6, 21, 23, 15, 50, 925000), e->time());

    // Compare time strings in the local timezone
    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-06-21T16:15:50.925000-07:00", s.substr(0, 32));
  }

  // MESZ (UTC+02, during DST)
  SetTimeZone("Europe/Berlin");
  {
    LogParserAudit parser;
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    // Compare times in UTC
    EXPECT_EQ(TimeFromExploded(2020, 6, 21, 23, 17, 27, 98000), e->time());

    // Compare time strings in the local timezone
    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-06-22T01:17:27.098000+02:00", s.substr(0, 32));
  }

  // UTC
  SetTimeZone("UTC+00");
  {
    LogParserAudit parser;
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    // Compare times in UTC
    EXPECT_EQ(TimeFromExploded(2020, 6, 21, 23, 17, 27, 98000), e->time());

    // Compare time strings in the local timezone
    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-06-21T23:17:27.098000+00:00", s.substr(0, 32));
  }
}

TEST_F(LogParserAuditTest, ParseLeadingNull) {
  LogParserAudit parser;
  LogLineReader reader(LogLineReader::Backend::FILE);
  reader.OpenFile(base::FilePath("./testdata/TEST_AUDIT_LOG_LEADING_NULL"));

  {
    base::Optional<std::string> maybe_line = reader.Forward();
    EXPECT_TRUE(maybe_line.has_value());
    MaybeLogEntry e = parser.Parse(std::move(maybe_line.value()));
    EXPECT_TRUE(e.has_value());

    const std::string& s = e->entire_line();
    EXPECT_EQ("2020-01-18T23:17:27.098000+00:00", s.substr(0, 32));
    EXPECT_EQ(TimeFromExploded(2020, 1, 18, 23, 17, 27, 98000), e->time());
    EXPECT_EQ(0, e->pid());
    EXPECT_EQ("audit", e->tag());

    EXPECT_EQ("INFO audit[0]: SECCOMP pid=0 auid=4294967296 uid=1000 gid=1000",
              s.substr(33, s.size()));
  }
}

}  // namespace croslog