1 // Copyright 2018 The Fuchsia Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4 
5 #include <runtests-utils/log-exporter.h>
6 
7 #include <errno.h>
8 #include <stdint.h>
9 
10 #include <fuchsia/logger/c/fidl.h>
11 #include <lib/fdio/util.h>
12 #include <lib/fidl/cpp/message_buffer.h>
13 #include <lib/zx/channel.h>
14 #include <zircon/status.h>
15 
16 #include <utility>
17 
18 namespace runtests {
19 namespace {
20 
ToFblString(fidl_string_t string)21 fbl::String ToFblString(fidl_string_t string) {
22     return fbl::String(string.data, string.size);
23 }
24 
25 } // namespace
26 
LogExporter(zx::channel channel,FILE * output_file)27 LogExporter::LogExporter(zx::channel channel, FILE* output_file)
28     : loop_(&kAsyncLoopConfigNoAttachToThread),
29       channel_(std::move(channel)),
30       wait_(this, channel_.get(), ZX_CHANNEL_READABLE | ZX_CHANNEL_PEER_CLOSED),
31       output_file_(output_file) {
32     wait_.Begin(loop_.dispatcher());
33 }
34 
~LogExporter()35 LogExporter::~LogExporter() {
36     // Quit so that current work is completed and loop can stop.
37     loop_.Quit();
38 
39     // wait for current work to be completed.
40     loop_.JoinThreads();
41 
42     // Run one more time until there are no more messages.
43     loop_.ResetQuit();
44     RunUntilIdle();
45 
46     // Shutdown
47     loop_.Shutdown();
48     if (output_file_ != nullptr) {
49         fclose(output_file_);
50     }
51 };
52 
StartThread()53 zx_status_t LogExporter::StartThread() {
54     return loop_.StartThread();
55 }
56 
RunUntilIdle()57 zx_status_t LogExporter::RunUntilIdle() {
58     return loop_.RunUntilIdle();
59 }
60 
OnHandleReady(async_dispatcher_t * dispatcher,async::WaitBase * wait,zx_status_t status,const zx_packet_signal_t * signal)61 void LogExporter::OnHandleReady(async_dispatcher_t* dispatcher, async::WaitBase* wait, zx_status_t status,
62                                 const zx_packet_signal_t* signal) {
63     if (status != ZX_OK) {
64         NotifyError(status);
65         return;
66     }
67 
68     if (signal->observed & ZX_CHANNEL_READABLE) {
69         fidl::MessageBuffer buffer;
70         for (uint64_t i = 0; i < signal->count; i++) {
71             status = ReadAndDispatchMessage(&buffer);
72             if (status == ZX_ERR_SHOULD_WAIT) {
73                 break;
74             } else if (status != ZX_OK) {
75                 NotifyError(status);
76                 return;
77             }
78         }
79         status = wait_.Begin(dispatcher);
80         if (status != ZX_OK) {
81             NotifyError(status);
82         }
83         return;
84     }
85 
86     ZX_DEBUG_ASSERT(signal->observed & ZX_CHANNEL_PEER_CLOSED);
87 
88     // We don't notify an error until we've drained all the messages.
89     NotifyError(ZX_ERR_PEER_CLOSED);
90 }
91 
ReadAndDispatchMessage(fidl::MessageBuffer * buffer)92 zx_status_t LogExporter::ReadAndDispatchMessage(fidl::MessageBuffer* buffer) {
93     fidl::Message message = buffer->CreateEmptyMessage();
94     zx_status_t status = message.Read(channel_.get(), 0);
95     if (status != ZX_OK) {
96         return status;
97     }
98     if (!message.has_header()) {
99         return ZX_ERR_INVALID_ARGS;
100     }
101     switch (message.ordinal()) {
102     case fuchsia_logger_LogListenerLogOrdinal:
103         return Log(std::move(message));
104     case fuchsia_logger_LogListenerLogManyOrdinal:
105         return LogMany(std::move(message));
106     default:
107         return ZX_ERR_NOT_SUPPORTED;
108     }
109 }
110 
111 // Returns only seconds part
GetSeconds(uint64_t nanoseconds)112 uint64_t GetSeconds(uint64_t nanoseconds) {
113     return nanoseconds / 1000000000UL;
114 }
115 
116 // Returns only nano seconds part
GetNanoSeconds(uint64_t nanoseconds)117 uint64_t GetNanoSeconds(uint64_t nanoseconds) {
118     return (nanoseconds / 1000UL) % 1000000UL;
119 }
120 
121 #define RETURN_IF_ERROR(expr) \
122     do {                      \
123         int n = (expr);       \
124         if (n < 0) {          \
125             return n;         \
126         }                     \
127     } while (false)
128 
WriteSeverity(int32_t severity)129 int LogExporter::WriteSeverity(int32_t severity) {
130     switch (severity) {
131     case fuchsia_logger_LogLevelFilter_INFO:
132         return fputs(" INFO", output_file_);
133     case fuchsia_logger_LogLevelFilter_WARN:
134         return fputs(" WARNING", output_file_);
135     case fuchsia_logger_LogLevelFilter_ERROR:
136         return fputs(" ERROR", output_file_);
137     case fuchsia_logger_LogLevelFilter_FATAL:
138         return fputs(" FATAL", output_file_);
139     default:
140         // all other cases severity would be a negative nuber so print it as
141         // VLOG(n) where severity=-n
142         return fprintf(output_file_, " VLOG(%d)", -severity);
143     }
144 }
145 
LogMessage(fuchsia_logger_LogMessage * log_message)146 int LogExporter::LogMessage(fuchsia_logger_LogMessage* log_message) {
147     RETURN_IF_ERROR(fprintf(output_file_, "[%05ld.%06ld][%lu][%lu]", GetSeconds(log_message->time),
148                             GetNanoSeconds(log_message->time), log_message->pid, log_message->tid));
149     RETURN_IF_ERROR(fputs("[", output_file_));
150     fidl_string_t* tags = static_cast<fidl_string_t*>(log_message->tags.data);
151     for (size_t i = 0; i < log_message->tags.count; ++i) {
152         RETURN_IF_ERROR(fprintf(output_file_, "%s", ToFblString(tags[i]).c_str()));
153         if (i < log_message->tags.count - 1) {
154             RETURN_IF_ERROR(fputs(", ", output_file_));
155         }
156     }
157     RETURN_IF_ERROR(fputs("]", output_file_));
158 
159     RETURN_IF_ERROR(WriteSeverity(log_message->severity));
160 
161     RETURN_IF_ERROR(fprintf(output_file_, ": %s\n", ToFblString(log_message->msg).c_str()));
162     if (log_message->dropped_logs > 0) {
163         bool log = true;
164         bool found = false;
165         for (DroppedLogs& dl : dropped_logs_) {
166             if (dl.pid == log_message->pid) {
167                 found = true;
168                 // only update our vector when we get new dropped_logs value.
169                 if (dl.dropped_logs < log_message->dropped_logs) {
170                     dl.dropped_logs = log_message->dropped_logs;
171                 } else {
172                     log = false;
173                 }
174                 break;
175             }
176         }
177         if (!found) {
178             dropped_logs_.push_back(DroppedLogs{log_message->pid, log_message->dropped_logs});
179         }
180         if (log) {
181             RETURN_IF_ERROR(fprintf(output_file_, "[%05ld.%06ld][%lu][%lu]", GetSeconds(log_message->time),
182                                     GetNanoSeconds(log_message->time), log_message->pid,
183                                     log_message->tid));
184             RETURN_IF_ERROR(fputs("[", output_file_));
185             fidl_string_t* tags = static_cast<fidl_string_t*>(log_message->tags.data);
186             for (size_t i = 0; i < log_message->tags.count; ++i) {
187                 RETURN_IF_ERROR(fprintf(output_file_, "%s", ToFblString(tags[i]).c_str()));
188                 if (i < log_message->tags.count - 1) {
189                     RETURN_IF_ERROR(fputs(", ", output_file_));
190                 }
191             }
192             RETURN_IF_ERROR(fputs("]", output_file_));
193             RETURN_IF_ERROR(fprintf(output_file_, " WARNING: Dropped logs count:%d\n",
194                                     log_message->dropped_logs));
195         }
196     }
197     return 0;
198 }
199 
Log(fidl::Message message)200 zx_status_t LogExporter::Log(fidl::Message message) {
201     const char* error_msg = nullptr;
202     zx_status_t status = message.Decode(&fuchsia_logger_LogListenerLogRequestTable, &error_msg);
203     if (status != ZX_OK) {
204         fprintf(stderr, "log-listener: error: Log: %s\n", error_msg);
205         return status;
206     }
207 
208     fuchsia_logger_LogMessage* log_message = message.GetPayloadAs<fuchsia_logger_LogMessage>();
209     if (LogMessage(log_message) < 0) {
210         NotifyFileError(strerror(errno));
211     }
212     return ZX_OK;
213 }
214 
LogMany(fidl::Message message)215 zx_status_t LogExporter::LogMany(fidl::Message message) {
216     const char* error_msg = nullptr;
217     zx_status_t status = message.Decode(&fuchsia_logger_LogListenerLogManyRequestTable, &error_msg);
218     if (status != ZX_OK) {
219         fprintf(stderr, "log-listener: error: LogMany: %s\n", error_msg);
220         return status;
221     }
222 
223     fidl_vector_t* log_messages = message.GetPayloadAs<fidl_vector_t>();
224     fuchsia_logger_LogMessage* msgs = static_cast<fuchsia_logger_LogMessage*>(log_messages->data);
225     for (size_t i = 0; i < log_messages->count; ++i) {
226         if (LogMessage(&msgs[i]) < 0) {
227             NotifyFileError(strerror(errno));
228             return ZX_OK;
229         }
230     }
231     return ZX_OK;
232 }
233 
NotifyError(zx_status_t error)234 void LogExporter::NotifyError(zx_status_t error) {
235     channel_.reset();
236     fclose(output_file_);
237     output_file_ = nullptr;
238     if (error_handler_) {
239         error_handler_(error);
240     }
241 }
242 
NotifyFileError(const char * error)243 void LogExporter::NotifyFileError(const char* error) {
244     channel_.reset();
245     fclose(output_file_);
246     output_file_ = nullptr;
247     if (file_error_handler_) {
248         file_error_handler_(error);
249     }
250 }
251 
LaunchLogExporter(const fbl::StringPiece syslog_path,ExporterLaunchError * error)252 fbl::unique_ptr<LogExporter> LaunchLogExporter(const fbl::StringPiece syslog_path,
253                                                ExporterLaunchError* error) {
254     *error = NO_ERROR;
255     fbl::String syslog_path_str = fbl::String(syslog_path.data());
256     FILE* syslog_file = fopen(syslog_path_str.c_str(), "w");
257     if (syslog_file == nullptr) {
258         fprintf(stderr, "Error: Could not open syslog file: %s.\n", syslog_path_str.c_str());
259         *error = OPEN_FILE;
260         return nullptr;
261     }
262 
263     // Try and connect to logger service if available. It would be only
264     // available in garnet and above layer
265     zx::channel logger, logger_request;
266     zx_status_t status;
267 
268     status = zx::channel::create(0, &logger, &logger_request);
269     if (status != ZX_OK) {
270         fprintf(stderr, "LaunchLogExporter: cannot create channel for logger service: %d (%s).\n",
271                status, zx_status_get_string(status));
272         *error = CREATE_CHANNEL;
273         return nullptr;
274     }
275 
276     status = fdio_service_connect("/svc/fuchsia.logger.Log", logger_request.release());
277     if (status != ZX_OK) {
278         fprintf(stderr, "LaunchLogExporter: cannot connect to logger service: %d (%s).\n",
279                status, zx_status_get_string(status));
280         *error = CONNECT_TO_LOGGER_SERVICE;
281         return nullptr;
282     }
283 
284     // Create a log exporter channel and pass it to logger service.
285     zx::channel listener, listener_request;
286     status = zx::channel::create(0, &listener, &listener_request);
287     if (status != ZX_OK) {
288         fprintf(stderr, "LaunchLogExporter: cannot create channel for listener: %d (%s).\n",
289                status, zx_status_get_string(status));
290         *error = CREATE_CHANNEL;
291         return nullptr;
292     }
293     fuchsia_logger_LogListenRequest req = {};
294     req.hdr.ordinal = fuchsia_logger_LogListenOrdinal;
295     req.log_listener = FIDL_HANDLE_PRESENT;
296     zx_handle_t listener_handle = listener.release();
297     status = logger.write(0, &req, sizeof(req), &listener_handle, 1);
298     if (status != ZX_OK) {
299         fprintf(stderr, "LaunchLogExporter: cannot pass listener to logger service: %d (%s).\n",
300                status, zx_status_get_string(status));
301         *error = FIDL_ERROR;
302         return nullptr;
303     }
304 
305     // Connect log exporter channel to object and start message loop on it.
306     auto log_exporter = fbl::make_unique<LogExporter>(std::move(listener_request),
307                                                       syslog_file);
308     log_exporter->set_error_handler([](zx_status_t status) {
309         if (status != ZX_ERR_CANCELED) {
310             fprintf(stderr, "log exporter: Failed: %d (%s).\n",
311                    status, zx_status_get_string(status));
312         }
313     });
314     log_exporter->set_file_error_handler([](const char* error) {
315         fprintf(stderr, "log exporter: Error writing to file: %s.\n", error);
316     });
317     status = log_exporter->StartThread();
318     if (status != ZX_OK) {
319         fprintf(stderr, "LaunchLogExporter: Failed to start log exporter: %d (%s).\n",
320                status, zx_status_get_string(status));
321         *error = START_LISTENER;
322         return nullptr;
323     }
324     return log_exporter;
325 }
326 
327 } // namespace runtests
328