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