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 <fbl/algorithm.h> 6#include <fbl/auto_lock.h> 7#include <fbl/string_buffer.h> 8#include <zircon/assert.h> 9 10#include <syslog/logger.h> 11#include <syslog/wire_format.h> 12 13#include "fx_logger.h" 14 15namespace { 16 17// This thread's koid. 18// Initialized on first use. 19thread_local zx_koid_t tls_thread_koid{ZX_KOID_INVALID}; 20 21zx_koid_t GetCurrentThreadKoid() { 22 if (unlikely(tls_thread_koid == ZX_KOID_INVALID)) { 23 tls_thread_koid = GetKoid(zx_thread_self()); 24 } 25 ZX_DEBUG_ASSERT(tls_thread_koid != ZX_KOID_INVALID); 26 return tls_thread_koid; 27} 28 29} // namespace 30 31void fx_logger::ActivateFallback(int fallback_fd) { 32 fbl::AutoLock lock(&fallback_mutex_); 33 if (logger_fd_.load(fbl::memory_order_relaxed) != -1) { 34 return; 35 } 36 ZX_DEBUG_ASSERT(fallback_fd >= -1); 37 if (tagstr_.empty()) { 38 for (size_t i = 0; i < tags_.size(); i++) { 39 if (tagstr_.empty()) { 40 tagstr_ = tags_[i]; 41 } else { 42 tagstr_ = fbl::String::Concat({tagstr_, ", ", tags_[i]}); 43 } 44 } 45 } 46 if (fallback_fd == -1) { 47 fallback_fd = STDERR_FILENO; 48 } 49 // Do not change fd_to_close_ as we don't want to close fallback_fd. 50 // We will still close original cosole_fd_ 51 logger_fd_.store(fallback_fd, fbl::memory_order_relaxed); 52} 53 54zx_status_t fx_logger::VLogWriteToSocket(fx_log_severity_t severity, 55 const char* tag, const char* msg, 56 va_list args, bool perform_format) { 57 zx_time_t time = zx_clock_get_monotonic(); 58 fx_log_packet_t packet; 59 memset(&packet, 0, sizeof(packet)); 60 constexpr size_t kDataSize = sizeof(packet.data); 61 packet.metadata.pid = pid_; 62 packet.metadata.tid = GetCurrentThreadKoid(); 63 packet.metadata.time = time; 64 packet.metadata.severity = severity; 65 packet.metadata.dropped_logs = dropped_logs_.load(); 66 67 // Write tags 68 size_t pos = 0; 69 for (size_t i = 0; i < tags_.size(); i++) { 70 size_t len = tags_[i].length(); 71 ZX_DEBUG_ASSERT(len < 128); 72 packet.data[pos++] = static_cast<char>(len); 73 memcpy(packet.data + pos, tags_[i].c_str(), len); 74 pos += len; 75 } 76 if (tag != NULL) { 77 size_t len = strlen(tag); 78 if (len > 0) { 79 size_t write_len = 80 fbl::min(len, static_cast<size_t>(FX_LOG_MAX_TAG_LEN - 1)); 81 ZX_DEBUG_ASSERT(write_len < 128); 82 packet.data[pos++] = static_cast<char>(write_len); 83 memcpy(packet.data + pos, tag, write_len); 84 pos += write_len; 85 } 86 } 87 packet.data[pos++] = 0; 88 ZX_DEBUG_ASSERT(pos < kDataSize); 89 // Write msg 90 int n = static_cast<int>(kDataSize - pos); 91 int count = 0; 92 size_t msg_pos = pos; 93 if (!perform_format) { 94 size_t write_len = 95 fbl::min(strlen(msg), static_cast<size_t>(n - 1)); 96 memcpy(packet.data + pos, msg, write_len); 97 pos += write_len; 98 packet.data[pos] = 0; 99 count = static_cast<int>(write_len + 1); 100 } else { 101 count = vsnprintf(packet.data + pos, n, msg, args); 102 if (count < 0) { 103 return ZX_ERR_INVALID_ARGS; 104 } 105 } 106 if (count >= n) { 107 // truncated 108 constexpr char kEllipsis[] = "..."; 109 constexpr size_t kEllipsisSize = sizeof(kEllipsis) - 1; 110 memcpy(packet.data + kDataSize - 1 - kEllipsisSize, kEllipsis, 111 kEllipsisSize); 112 count = n - 1; 113 } 114 auto size = sizeof(packet.metadata) + msg_pos + count + 1; 115 ZX_DEBUG_ASSERT(size <= sizeof(packet)); 116 auto status = socket_.write(0, &packet, size, nullptr); 117 if (status == ZX_ERR_BAD_STATE || status == ZX_ERR_PEER_CLOSED) { 118 ActivateFallback(-1); 119 return VLogWriteToFd(logger_fd_.load(fbl::memory_order_relaxed), 120 severity, tag, packet.data + msg_pos, args, false); 121 } 122 if (status != ZX_OK) { 123 dropped_logs_.fetch_add(1); 124 } 125 return status; 126} 127 128zx_status_t fx_logger::VLogWriteToFd(int fd, fx_log_severity_t severity, 129 const char* tag, const char* msg, 130 va_list args, bool perform_format) { 131 zx_time_t time = zx_clock_get_monotonic(); 132 constexpr char kEllipsis[] = "..."; 133 constexpr size_t kEllipsisSize = sizeof(kEllipsis) - 1; 134 constexpr size_t kMaxMessageSize = 2043; 135 136 fbl::StringBuffer<kMaxMessageSize + kEllipsisSize + 1 /*\n*/> buf; 137 buf.AppendPrintf("[%05ld.%06ld]", time / 1000000000UL, (time / 1000UL) % 1000000UL); 138 buf.AppendPrintf("[%ld]", pid_); 139 buf.AppendPrintf("[%ld]", GetCurrentThreadKoid()); 140 141 buf.Append("["); 142 if (!tagstr_.empty()) { 143 buf.Append(tagstr_); 144 } 145 146 if (tag != NULL) { 147 size_t len = strlen(tag); 148 if (len > 0) { 149 if (!tagstr_.empty()) { 150 buf.Append(", "); 151 } 152 buf.Append(tag, 153 fbl::min(len, static_cast<size_t>(FX_LOG_MAX_TAG_LEN - 1))); 154 } 155 } 156 buf.Append("]"); 157 switch (severity) { 158 case FX_LOG_INFO: 159 buf.Append(" INFO"); 160 break; 161 case FX_LOG_WARNING: 162 buf.Append(" WARNING"); 163 break; 164 case FX_LOG_ERROR: 165 buf.Append(" ERROR"); 166 break; 167 case FX_LOG_FATAL: 168 buf.Append(" FATAL"); 169 break; 170 default: 171 buf.AppendPrintf(" VLOG(%d)", -severity); 172 } 173 buf.Append(": "); 174 175 if (!perform_format) { 176 buf.Append(msg); 177 } else { 178 buf.AppendVPrintf(msg, args); 179 } 180 if (buf.size() > kMaxMessageSize) { 181 buf.Resize(kMaxMessageSize); 182 buf.Append(kEllipsis); 183 } 184 buf.Append('\n'); 185 ssize_t status = write(fd, buf.data(), buf.size()); 186 if (status < 0) { 187 return ZX_ERR_IO; 188 } 189 return ZX_OK; 190} 191 192zx_status_t fx_logger::VLogWrite(fx_log_severity_t severity, const char* tag, 193 const char* msg, va_list args, bool perform_format) { 194 if (msg == NULL || severity > FX_LOG_FATAL) { 195 return ZX_ERR_INVALID_ARGS; 196 } 197 if (GetSeverity() > severity) { 198 return ZX_OK; 199 } 200 201 zx_status_t status; 202 int fd = logger_fd_.load(fbl::memory_order_relaxed); 203 if (fd != -1) { 204 status = VLogWriteToFd(fd, severity, tag, msg, args, perform_format); 205 } else if (socket_.is_valid()) { 206 status = VLogWriteToSocket(severity, tag, msg, args, perform_format); 207 } else { 208 return ZX_ERR_BAD_STATE; 209 } 210 if (severity == FX_LOG_FATAL) { 211 abort(); 212 } 213 return status; 214} 215 216// This function is not thread safe 217zx_status_t fx_logger::AddTags(const char** tags, size_t ntags) { 218 if (ntags > FX_LOG_MAX_TAGS) { 219 return ZX_ERR_INVALID_ARGS; 220 } 221 222 auto fd_mode = logger_fd_.load(fbl::memory_order_relaxed) != -1; 223 for (size_t i = 0; i < ntags; i++) { 224 auto len = strlen(tags[i]); 225 fbl::String str( 226 tags[i], len > FX_LOG_MAX_TAG_LEN - 1 ? FX_LOG_MAX_TAG_LEN - 1 : len); 227 if (fd_mode) { 228 if (tagstr_.empty()) { 229 tagstr_ = str; 230 } else { 231 tagstr_ = fbl::String::Concat({tagstr_, ", ", str}); 232 } 233 } else { 234 tags_.push_back(str); 235 } 236 } 237 return ZX_OK; 238} 239