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