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