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