1 //
2 // Copyright (C) 2020 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 #include <signal.h>
17 #ifdef __linux__
18 #include <sys/signalfd.h>
19 #endif
20 
21 #include <regex>
22 
23 #include <android-base/logging.h>
24 #include <android-base/strings.h>
25 #include <gflags/gflags.h>
26 
27 #include "common/libs/fs/shared_fd.h"
28 #include "common/libs/utils/tee_logging.h"
29 #include "host/libs/config/cuttlefish_config.h"
30 
31 DEFINE_string(process_name, "", "The process to credit log messages to");
32 DEFINE_int32(log_fd_in, -1, "The file descriptor to read logs from.");
33 
34 // Crosvm formats logs starting with a local ISO 8601 timestamp and then a
35 // log level (based on external/crosvm/base/src/syslog.rs).
36 const std::regex kCrosvmLogPattern(
37     "^\\["
38     "\\d{4}" /* year */
39     "-"
40     "\\d{2}" /* month */
41     "-"
42     "\\d{2}" /* day */
43     "T"
44     "\\d{2}" /* hour */
45     ":"
46     "\\d{2}" /* minute*/
47     ":"
48     "\\d{2}" /* second */
49     "\\."
50     "\\d{9}"                          /* millisecond */
51     "(Z|[+-]\\d{2}(:\\d{2}|\\d{2})?)" /* timezone */
52     "\\s"
53     "(ERROR|WARN|INFO|DEBUG|TRACE)");
54 
main(int argc,char ** argv)55 int main(int argc, char** argv) {
56   ::android::base::InitLogging(argv, android::base::StderrLogger);
57   google::ParseCommandLineFlags(&argc, &argv, /* remove_flags */ true);
58 
59   CHECK(FLAGS_log_fd_in >= 0) << "-log_fd_in is required";
60 
61   auto config = cuttlefish::CuttlefishConfig::Get();
62 
63   CHECK(config) << "Could not open cuttlefish config";
64 
65   auto instance = config->ForDefaultInstance();
66 
67   if (instance.run_as_daemon()) {
68     android::base::SetLogger(
69         cuttlefish::LogToFiles({instance.launcher_log_path()}));
70   } else {
71     android::base::SetLogger(
72         cuttlefish::LogToStderrAndFiles({instance.launcher_log_path()}));
73   }
74 
75   auto log_fd = cuttlefish::SharedFD::Dup(FLAGS_log_fd_in);
76   CHECK(log_fd->IsOpen()) << "Failed to dup log_fd_in: " <<  log_fd->StrError();
77   close(FLAGS_log_fd_in);
78 
79   if (FLAGS_process_name.size() > 0) {
80     android::base::SetDefaultTag(FLAGS_process_name);
81   }
82 
83   // mask SIGINT and handle it using signalfd
84   sigset_t mask;
85   sigemptyset(&mask);
86   sigaddset(&mask, SIGINT);
87   CHECK(sigprocmask(SIG_BLOCK, &mask, NULL) == 0)
88       << "sigprocmask failed: " << strerror(errno);
89 #ifdef __linux__
90   int sfd = signalfd(-1, &mask, 0);
91   CHECK(sfd >= 0) << "signalfd failed: " << strerror(errno);
92   auto int_fd = cuttlefish::SharedFD::Dup(sfd);
93   close(sfd);
94 #endif
95 
96   auto poll_fds = std::vector<cuttlefish::PollSharedFd>{
97       cuttlefish::PollSharedFd{
98           .fd = log_fd,
99           .events = POLL_IN,
100           .revents = 0,
101       },
102 #ifdef __linux__
103       cuttlefish::PollSharedFd{
104           .fd = int_fd,
105           .events = POLL_IN,
106           .revents = 0,
107       },
108 #endif
109   };
110 
111   LOG(DEBUG) << "Starting to read from process " << FLAGS_process_name;
112 
113   char buf[1 << 16];
114   ssize_t chars_read = 0;
115   for (;;) {
116     // We can assume all writers to `log_fd` have completed before a SIGINT is
117     // sent, but we need to make sure we've actually read all the data before
118     // exiting. So, keep reading from `log_fd` until both (1) we get SIGINT and
119     // (2) `log_fd` is empty (but not necessarily EOF).
120     //
121     // This could be simpler if all the writers would close their FDs when they
122     // are finished. Then, we could just read until EOF. However that would
123     // require more work elsewhere in cuttlefish.
124     CHECK(cuttlefish::SharedFD::Poll(poll_fds, /*timeout=*/-1) >= 0)
125         << "poll failed: " << strerror(errno);
126     if (poll_fds[0].revents) {
127       chars_read = log_fd->Read(buf, sizeof(buf));
128       if (chars_read < 0) {
129         LOG(DEBUG) << "Failed to read from process " << FLAGS_process_name
130                    << ": " << log_fd->StrError();
131         break;
132       }
133       if (chars_read == 0) {
134         break;
135       }
136       auto trimmed = android::base::Trim(std::string_view(buf, chars_read));
137       // Newlines inside `trimmed` are handled by the android logging code.
138       // These checks attempt to determine the log severity coming from crosvm.
139       // There is no guarantee of success all the time since log line boundaries
140       // could be out sync with the reads, but that's ok.
141       if (android::base::StartsWith(trimmed, "[INFO")) {
142         LOG(DEBUG) << trimmed;
143       } else if (android::base::StartsWith(trimmed, "[ERROR")) {
144         LOG(ERROR) << trimmed;
145       } else if (android::base::StartsWith(trimmed, "[WARNING")) {
146         LOG(WARNING) << trimmed;
147       } else if (android::base::StartsWith(trimmed, "[VERBOSE")) {
148         LOG(VERBOSE) << trimmed;
149       } else {
150         std::smatch match_result;
151         if (std::regex_search(trimmed, match_result, kCrosvmLogPattern)) {
152           if (match_result.size() == 4) {
153             const auto& level = match_result[3];
154             if (level == "ERROR") {
155               LOG(ERROR) << trimmed;
156             } else if (level == "WARN") {
157               LOG(WARNING) << trimmed;
158             } else if (level == "INFO") {
159               if (trimmed.find("disk] Disk image file is hosted") !=
160                       std::string::npos ||
161                   trimmed.find("disk] disk size") != std::string::npos) {
162                 LOG(DEBUG) << trimmed;
163               } else {
164                 LOG(INFO) << trimmed;
165               }
166             } else if (level == "DEBUG") {
167               LOG(DEBUG) << trimmed;
168             } else if (level == "TRACE") {
169               LOG(VERBOSE) << trimmed;
170             } else {
171               LOG(DEBUG) << trimmed;
172             }
173           }
174         } else {
175           LOG(DEBUG) << trimmed;
176         }
177       }
178 
179       // Go back to polling immediately to see if there is more data, don't
180       // handle any signals yet.
181       continue;
182     }
183 #ifdef __linux__
184     if (poll_fds[1].revents) {
185       struct signalfd_siginfo siginfo;
186       int s = int_fd->Read(&siginfo, sizeof(siginfo));
187       CHECK(s == sizeof(siginfo)) << "bad read size on signalfd, expected "
188                                   << sizeof(siginfo) << " got " << s;
189       CHECK(siginfo.ssi_signo == SIGINT)
190           << "unexpected signal: " << siginfo.ssi_signo;
191       break;
192     }
193 #endif
194   }
195 
196   LOG(DEBUG) << "Finished reading from process " << FLAGS_process_name;
197 }
198