1 /*
2 * Copyright (C) 2018 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "netdutils/Log.h"
18 #include "netdutils/Slice.h"
19
20 #include <chrono>
21 #include <ctime>
22 #include <iomanip>
23 #include <mutex>
24 #include <sstream>
25
26 #include <android-base/strings.h>
27 #include <log/log.h>
28
29 using ::android::base::Join;
30 using ::android::base::StringPrintf;
31
32 namespace android {
33 namespace netdutils {
34
35 namespace {
36
makeTimestampedEntry(const std::string & entry)37 std::string makeTimestampedEntry(const std::string& entry) {
38 using ::std::chrono::duration_cast;
39 using ::std::chrono::milliseconds;
40 using ::std::chrono::system_clock;
41
42 std::stringstream tsEntry;
43 const auto now = system_clock::now();
44 const auto time_sec = system_clock::to_time_t(now);
45 tsEntry << std::put_time(std::localtime(&time_sec), "%m-%d %H:%M:%S.") << std::setw(3)
46 << std::setfill('0')
47 << duration_cast<milliseconds>(now - system_clock::from_time_t(time_sec)).count() << " "
48 << entry;
49
50 return tsEntry.str();
51 }
52
53 } // namespace
54
toString() const55 std::string LogEntry::toString() const {
56 std::vector<std::string> text;
57
58 if (!mMsg.empty()) text.push_back(mMsg);
59 if (!mFunc.empty()) {
60 text.push_back(StringPrintf("%s(%s)", mFunc.c_str(), Join(mArgs, ", ").c_str()));
61 }
62 if (!mReturns.empty()) {
63 text.push_back("->");
64 text.push_back(StringPrintf("(%s)", Join(mReturns, ", ").c_str()));
65 }
66 if (!mUid.empty()) text.push_back(mUid);
67 if (!mDuration.empty()) text.push_back(StringPrintf("(%s)", mDuration.c_str()));
68
69 return Join(text, " ");
70 }
71
message(const std::string & message)72 LogEntry& LogEntry::message(const std::string& message) {
73 mMsg = message;
74 return *this;
75 }
76
function(const std::string & function_name)77 LogEntry& LogEntry::function(const std::string& function_name) {
78 mFunc = function_name;
79 return *this;
80 }
81
prettyFunction(const std::string & pretty_function)82 LogEntry& LogEntry::prettyFunction(const std::string& pretty_function) {
83 // __PRETTY_FUNCTION__ generally seems to be of the form:
84 //
85 // qualifed::returnType qualified::function(args...)
86 //
87 // where the qualified forms include "(anonymous namespace)" in the
88 // "::"-delimited list and keywords like "virtual" (where applicable).
89 //
90 // Here we try to convert strings like:
91 //
92 // virtual binder::Status android::net::NetdNativeService::isAlive(bool *)
93 // netdutils::LogEntry android::netd::(anonymous namespace)::AAA::BBB::function()
94 //
95 // into just "NetdNativeService::isAlive" or "BBB::function". Note that
96 // without imposing convention, how to easily identify any namespace/class
97 // name boundary is not obvious.
98 const size_t endFuncName = pretty_function.rfind('(');
99 const size_t precedingSpace = pretty_function.rfind(' ', endFuncName);
100 size_t substrStart = (precedingSpace != std::string::npos) ? precedingSpace + 1 : 0;
101
102 const size_t beginFuncName = pretty_function.rfind("::", endFuncName);
103 if (beginFuncName != std::string::npos && substrStart < beginFuncName) {
104 const size_t previousNameBoundary = pretty_function.rfind("::", beginFuncName - 1);
105 if (previousNameBoundary < beginFuncName && substrStart < previousNameBoundary) {
106 substrStart = previousNameBoundary + 2;
107 } else {
108 substrStart = beginFuncName + 2;
109 }
110 }
111
112 mFunc = pretty_function.substr(substrStart, endFuncName - substrStart);
113 return *this;
114 }
115
arg(const std::string & val)116 LogEntry& LogEntry::arg(const std::string& val) {
117 mArgs.push_back(val.empty() ? "\"\"" : val);
118 return *this;
119 }
120
121 template <>
arg(bool val)122 LogEntry& LogEntry::arg<>(bool val) {
123 mArgs.push_back(val ? "true" : "false");
124 return *this;
125 }
126
arg(const std::vector<int32_t> & val)127 LogEntry& LogEntry::arg(const std::vector<int32_t>& val) {
128 mArgs.push_back(StringPrintf("[%s]", Join(val, ", ").c_str()));
129 return *this;
130 }
131
arg(const std::vector<uint8_t> & val)132 LogEntry& LogEntry::arg(const std::vector<uint8_t>& val) {
133 mArgs.push_back('{' + toHex(makeSlice(val)) + '}');
134 return *this;
135 }
136
arg(const std::vector<std::string> & val)137 LogEntry& LogEntry::arg(const std::vector<std::string>& val) {
138 mArgs.push_back(StringPrintf("[%s]", Join(val, ", ").c_str()));
139 return *this;
140 }
141
returns(const std::string & rval)142 LogEntry& LogEntry::returns(const std::string& rval) {
143 mReturns.push_back(rval);
144 return *this;
145 }
146
returns(bool rval)147 LogEntry& LogEntry::returns(bool rval) {
148 mReturns.push_back(rval ? "true" : "false");
149 return *this;
150 }
151
returns(const Status & status)152 LogEntry& LogEntry::returns(const Status& status) {
153 mReturns.push_back(status.msg());
154 return *this;
155 }
156
withUid(uid_t uid)157 LogEntry& LogEntry::withUid(uid_t uid) {
158 mUid = StringPrintf("(uid=%d)", uid);
159 return *this;
160 }
161
withAutomaticDuration()162 LogEntry& LogEntry::withAutomaticDuration() {
163 using ms = std::chrono::duration<float, std::ratio<1, 1000>>;
164
165 const std::chrono::steady_clock::time_point end = std::chrono::steady_clock::now();
166 std::stringstream duration;
167 duration << std::setprecision(1) << std::chrono::duration_cast<ms>(end - mStart).count()
168 << "ms";
169 mDuration = duration.str();
170 return *this;
171 }
172
withDuration(const std::string & duration)173 LogEntry& LogEntry::withDuration(const std::string& duration) {
174 mDuration = duration;
175 return *this;
176 }
177
~Log()178 Log::~Log() {
179 // TODO: dump the last N entries to the android log for possible posterity.
180 info(LogEntry().function(__FUNCTION__));
181 }
182
forEachEntry(const std::function<void (const std::string &)> & perEntryFn) const183 void Log::forEachEntry(const std::function<void(const std::string&)>& perEntryFn) const {
184 // We make a (potentially expensive) copy of the log buffer (including
185 // all strings), in case the |perEntryFn| takes its sweet time.
186 std::deque<std::string> entries;
187 {
188 std::shared_lock<std::shared_mutex> guard(mLock);
189 entries.assign(mEntries.cbegin(), mEntries.cend());
190 }
191
192 for (const std::string& entry : entries) perEntryFn(entry);
193 }
194
record(Log::Level lvl,const std::string & entry)195 void Log::record(Log::Level lvl, const std::string& entry) {
196 switch (lvl) {
197 case Level::LOG:
198 break;
199 case Level::INFO:
200 ALOG(LOG_INFO, mTag.c_str(), "%s", entry.c_str());
201 break;
202 case Level::WARN:
203 ALOG(LOG_WARN, mTag.c_str(), "%s", entry.c_str());
204 break;
205 case Level::ERROR:
206 ALOG(LOG_ERROR, mTag.c_str(), "%s", entry.c_str());
207 break;
208 }
209
210 std::lock_guard guard(mLock);
211 mEntries.push_back(makeTimestampedEntry(entry));
212 while (mEntries.size() > mMaxEntries) mEntries.pop_front();
213 }
214
215 } // namespace netdutils
216 } // namespace android
217