1 // Copyright 2023 The Android Open Source Project
2 //
3 // Licensed under the Apache License, Version 2.0 (the "License");
4 // you may not use this file except in compliance with the License.
5 // You may obtain a copy of the License at
6 //
7 // http://www.apache.org/licenses/LICENSE-2.0
8 //
9 // Unless required by applicable law or agreed to in writing, software
10 // distributed under the License is distributed on an "AS IS" BASIS,
11 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 // See the License for the specific language governing permissions and
13 // limitations under the License.
14 #include <gmock/gmock.h>
15 #include <gtest/gtest.h>
16
17 #include <string>
18 #include <thread>
19 #include <vector>
20
21 #include "absl/log/globals.h"
22 #include "absl/log/log.h"
23 #include "absl/log/log_sink_registry.h"
24 #include "absl/strings/str_format.h"
25 #include "absl/strings/string_view.h"
26 #include "absl/time/civil_time.h"
27 #include "absl/time/clock.h"
28 #include "absl/time/time.h"
29 #include "aemu/base/testing/TestUtils.h"
30 #include "host-common/logging.h"
31
32 namespace {
33
34 using ::testing::EndsWith;
35 using ::testing::HasSubstr;
36 using ::testing::Not;
37 using ::testing::StartsWith;
38
39 class CaptureLogSink : public absl::LogSink {
40 public:
Send(const absl::LogEntry & entry)41 void Send(const absl::LogEntry& entry) override {
42 char level = 'I';
43 switch (entry.log_severity()) {
44 case absl::LogSeverity::kInfo:
45 level = 'I';
46 break;
47 case absl::LogSeverity::kError:
48 level = 'E';
49 break;
50 case absl::LogSeverity::kWarning:
51 level = 'W';
52 break;
53
54 case absl::LogSeverity::kFatal:
55 level = 'F';
56 break;
57 }
58 captured_log_ = absl::StrFormat("%c %s:%d |%s|- %s", level, entry.source_filename(),
59 entry.source_line(), absl::FormatTime(entry.timestamp()),
60 entry.text_message());
61 }
62
63 std::string captured_log_;
64 };
65
66 // Returns the microseconds since the Unix epoch for Sep 13, 2020 12:26:40.123456 in the machine's
67 // local timezone.
defaultTimestamp()68 absl::Time defaultTimestamp() {
69 absl::CivilSecond cs(2020, 9, 13, 12, 26, 40);
70 return absl::FromCivil(cs, absl::UTCTimeZone());
71 }
72
73 class OutputLogTest : public ::testing::Test {
74 protected:
SetUp()75 void SetUp() override {
76 // Add the CaptureLogSink
77 log_sink_ = std::make_unique<CaptureLogSink>();
78 absl::AddLogSink(log_sink_.get());
79
80 absl::SetVLogLevel("*", 2);
81 set_gfxstream_enable_verbose_logs();
82
83 // Set log level to capture everything (adjust as needed)
84 absl::SetStderrThreshold(absl::LogSeverity::kInfo);
85 }
86
TearDown()87 void TearDown() override {
88 // Remove the CaptureLogSink
89 absl::RemoveLogSink(log_sink_.get());
90 }
91
92 // Common test parameters
93 const char* file = "test_file.cc";
94 int line = 42;
95 const char* format = "This is a %s message";
96
97 // Helper to create a formatted log message string
FormattedLog(absl::Time timestamp,absl::LogSeverity severity,const std::string & msg)98 std::string FormattedLog(absl::Time timestamp, absl::LogSeverity severity,
99 const std::string& msg) {
100 std::string formatted =
101 absl::FormatTime("%Y-%m-%d %H:%M:%S", timestamp, absl::UTCTimeZone());
102 return absl::StrFormat("%s: %s:%d] %s", formatted, file, line, msg);
103 }
104
105 std::unique_ptr<CaptureLogSink> log_sink_;
106 };
107
108 // Test INFO log level with timestamp
TEST_F(OutputLogTest,InfoLogWithTimestamp)109 TEST_F(OutputLogTest, InfoLogWithTimestamp) {
110 auto timestamp_us = absl::ToUnixMicros(defaultTimestamp());
111 OutputLog(nullptr, 'I', file, line, timestamp_us, format, "INFO");
112 EXPECT_EQ(log_sink_->captured_log_,
113 "I test_file.cc:42 |2020-09-13T12:26:40+00:00|- This is a INFO message");
114 }
115
116 // Test WARNING log level with timestamp
TEST_F(OutputLogTest,WarningLogWithTimestamp)117 TEST_F(OutputLogTest, WarningLogWithTimestamp) {
118 auto timestamp_us = absl::ToUnixMicros(defaultTimestamp());
119 OutputLog(nullptr, 'W', file, line, timestamp_us, format, "WARNING");
120 EXPECT_EQ(log_sink_->captured_log_,
121 "W test_file.cc:42 |2020-09-13T12:26:40+00:00|- This is a WARNING message");
122 }
123
124 // Test ERROR log level with timestamp
TEST_F(OutputLogTest,ErrorLogWithTimestamp)125 TEST_F(OutputLogTest, ErrorLogWithTimestamp) {
126 auto timestamp_us = absl::ToUnixMicros(defaultTimestamp());
127 OutputLog(nullptr, 'E', file, line, timestamp_us, format, "ERROR");
128 EXPECT_EQ(log_sink_->captured_log_,
129 "E test_file.cc:42 |2020-09-13T12:26:40+00:00|- This is a ERROR message");
130 }
131
132 // Test VERBOSE log level with timestamp
TEST_F(OutputLogTest,VerboseLogWithTimestamp)133 TEST_F(OutputLogTest, VerboseLogWithTimestamp) {
134 auto timestamp_us = absl::ToUnixMicros(defaultTimestamp());
135 OutputLog(nullptr, 'V', file, line, timestamp_us, format, "VERBOSE");
136 EXPECT_EQ(log_sink_->captured_log_,
137 "I test_file.cc:42 |2020-09-13T12:26:40+00:00|- This is a VERBOSE message");
138 }
139
140 // Test VERBOSE log level with timestamp
TEST_F(OutputLogTest,DebugLogWithTimestamp)141 TEST_F(OutputLogTest, DebugLogWithTimestamp) {
142 auto timestamp_us = absl::ToUnixMicros(defaultTimestamp());
143 OutputLog(nullptr, 'D', file, line, timestamp_us, format, "DEBUG");
144 EXPECT_EQ(log_sink_->captured_log_,
145 "I test_file.cc:42 |2020-09-13T12:26:40+00:00|- This is a DEBUG message");
146 }
147
148 // Test truncation when message exceeds buffer size
TEST_F(OutputLogTest,Truncation)149 TEST_F(OutputLogTest, Truncation) {
150 std::string long_msg(4100, 'x'); // Exceeds buffer size
151 auto now = absl::ToUnixMicros(defaultTimestamp());
152 OutputLog(nullptr, 'I', file, line, now, "%s", long_msg.c_str());
153
154 std::string expected_msg = long_msg.substr(0, 4093) + "...";
155 EXPECT_THAT(log_sink_->captured_log_, testing::HasSubstr(expected_msg));
156 }
157
158 } // namespace
159