1// Copyright 2017 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 "handler_impl.h"
6
7#include <inttypes.h>
8#include <stdio.h>
9
10#include <zircon/assert.h>
11#include <zircon/status.h>
12#include <zircon/syscalls.h>
13
14#include <trace-provider/provider.h>
15#include <lib/zx/vmar.h>
16#include <fbl/type_support.h>
17
18#include "utils.h"
19
20namespace trace {
21namespace internal {
22
23TraceHandlerImpl::TraceHandlerImpl(void* buffer, size_t buffer_num_bytes,
24                                   zx::fifo fifo,
25                                   fbl::Vector<fbl::String> enabled_categories)
26    : buffer_(buffer),
27      buffer_num_bytes_(buffer_num_bytes),
28      fifo_(fbl::move(fifo)),
29      fifo_wait_(this, fifo_.get(),
30                 ZX_FIFO_READABLE | ZX_FIFO_PEER_CLOSED),
31      enabled_categories_(fbl::move(enabled_categories)) {
32    // Build a quick lookup table for IsCategoryEnabled().
33    for (const auto& cat : enabled_categories_) {
34        auto entry = fbl::make_unique<StringSetEntry>(cat.c_str());
35        enabled_category_set_.insert_or_find(fbl::move(entry));
36    }
37}
38
39TraceHandlerImpl::~TraceHandlerImpl() {
40    zx_status_t status = zx::vmar::root_self()->unmap(
41        reinterpret_cast<uintptr_t>(buffer_), buffer_num_bytes_);
42    ZX_DEBUG_ASSERT(status == ZX_OK);
43    status = fifo_wait_.Cancel();
44    ZX_DEBUG_ASSERT(status == ZX_OK || status == ZX_ERR_NOT_FOUND);
45}
46
47void TraceHandlerImpl::StartEngine(async_dispatcher_t* dispatcher,
48                                   trace_buffering_mode_t buffering_mode,
49                                   zx::vmo buffer, zx::fifo fifo,
50                                   fbl::Vector<fbl::String> enabled_categories) {
51    ZX_DEBUG_ASSERT(buffer);
52    ZX_DEBUG_ASSERT(fifo);
53
54    // If the engine isn't stopped flag an error. No one else should be
55    // starting/stopping the engine so testing this here is ok.
56    switch (trace_state()) {
57    case TRACE_STOPPED:
58        break;
59    case TRACE_STOPPING:
60        fprintf(stderr, "TraceHandler for process %" PRIu64
61                ": cannot start engine, still stopping from previous trace\n",
62                GetPid());
63        return;
64    case TRACE_STARTED:
65        // We can get here if the app errantly tried to create two providers.
66        // This is a bug in the app, provide extra assistance for diagnosis.
67        // Including the pid here has been extraordinarily helpful.
68        fprintf(stderr, "TraceHandler for process %" PRIu64
69                ": engine is already started. Is there perchance two"
70                " providers in this app?\n",
71                GetPid());
72        return;
73    default:
74        __UNREACHABLE;
75    }
76
77    uint64_t buffer_num_bytes;
78    zx_status_t status = buffer.get_size(&buffer_num_bytes);
79    if (status != ZX_OK) {
80        fprintf(stderr, "TraceHandler: error getting buffer size, status=%d(%s)\n",
81                status, zx_status_get_string(status));
82        return;
83    }
84
85    uintptr_t buffer_ptr;
86    status = zx::vmar::root_self()->map(
87        0u, buffer, 0u, buffer_num_bytes,
88        ZX_VM_PERM_READ | ZX_VM_PERM_WRITE, &buffer_ptr);
89    if (status != ZX_OK) {
90        fprintf(stderr, "TraceHandler: error mapping buffer, status=%d(%s)\n",
91                status, zx_status_get_string(status));
92        return;
93    }
94
95    auto handler = new TraceHandlerImpl(reinterpret_cast<void*>(buffer_ptr),
96                                        buffer_num_bytes, fbl::move(fifo),
97                                        fbl::move(enabled_categories));
98
99    status = handler->fifo_wait_.Begin(dispatcher);
100    if (status != ZX_OK) {
101        fprintf(stderr, "TraceHandler: error starting fifo wait, status=%d(%s)\n",
102                status, zx_status_get_string(status));
103        delete handler;
104        return;
105    }
106
107    status = trace_start_engine(dispatcher, handler, buffering_mode,
108                                handler->buffer_, handler->buffer_num_bytes_);
109    if (status != ZX_OK) {
110        fprintf(stderr, "TraceHandler: error starting engine, status=%d(%s)\n",
111                status, zx_status_get_string(status));
112        delete handler;
113        return;
114    }
115
116    // The handler will be destroyed in |TraceStopped()|.
117}
118
119void TraceHandlerImpl::StopEngine() {
120    auto status = trace_stop_engine(ZX_OK);
121    if (status != ZX_OK) {
122        // During shutdown this can happen twice: once for the Stop() request
123        // and once when the channel is closed. Don't print anything for this
124        // case, it suggests an error that isn't there. We could keep track of
125        // this ourselves, but that has its own problems: Best just have one
126        // place that records engine state: in the engine.
127        if (status == ZX_ERR_BAD_STATE && trace_state() == TRACE_STOPPED) {
128            // this is ok
129        } else {
130            fprintf(stderr, "TraceHandler: Failed to stop engine, status=%d(%s)\n",
131                    status, zx_status_get_string(status));
132        }
133    }
134}
135
136void TraceHandlerImpl::HandleFifo(async_dispatcher_t* dispatcher,
137                                  async::WaitBase* wait,
138                                  zx_status_t status,
139                                  const zx_packet_signal_t* signal) {
140    if (status == ZX_ERR_CANCELED) {
141        // The wait could be canceled if we're shutting down, e.g., the
142        // program is exiting.
143        return;
144    }
145    if (status != ZX_OK) {
146        fprintf(stderr, "TraceHandler: FIFO wait failed: status=%d(%s)\n",
147                status, zx_status_get_string(status));
148    } else if (signal->observed & ZX_FIFO_READABLE) {
149        if (ReadFifoMessage()) {
150            if (wait->Begin(dispatcher) == ZX_OK) {
151                return;
152            }
153            fprintf(stderr, "TraceHandler: Error re-registering FIFO wait\n");
154        }
155    } else {
156        ZX_DEBUG_ASSERT(signal->observed & ZX_FIFO_PEER_CLOSED);
157    }
158
159    // TraceManager is gone or other error with the fifo.
160    StopEngine();
161}
162
163bool TraceHandlerImpl::ReadFifoMessage() {
164    trace_provider_packet_t packet;
165    auto status = fifo_.read(sizeof(packet), &packet, 1u, nullptr);
166    ZX_DEBUG_ASSERT(status == ZX_OK);
167    if (packet.reserved != 0) {
168        fprintf(stderr, "TraceHandler: Reserved field non-zero from TraceManager: %u\n",
169               packet.reserved);
170        return false;
171    }
172    switch (packet.request) {
173    case TRACE_PROVIDER_BUFFER_SAVED: {
174        auto wrapped_count = packet.data32;
175        auto durable_data_end = packet.data64;
176#if 0 // TODO(DX-367): Don't delete this, save for conversion to syslog.
177        fprintf(stderr, "TraceHandler: Received buffer_saved message"
178                ", wrapped_count=%u, durable_data_end=0x%" PRIx64 "\n",
179                wrapped_count, durable_data_end);
180#endif
181        status = MarkBufferSaved(wrapped_count, durable_data_end);
182        if (status == ZX_ERR_BAD_STATE) {
183            // This happens when tracing has stopped. Ignore it.
184        } else if (status != ZX_OK) {
185            fprintf(stderr, "TraceHandler: MarkBufferSaved failed: status=%d\n",
186                    status);
187            return false;
188        }
189        break;
190    }
191    default:
192        fprintf(stderr, "TraceHandler: Bad request from TraceManager: %u\n",
193                packet.request);
194        return false;
195    }
196
197    return true;
198}
199
200zx_status_t TraceHandlerImpl::MarkBufferSaved(uint32_t wrapped_count,
201                                              uint64_t durable_data_end) {
202    return trace_engine_mark_buffer_saved(wrapped_count,
203                                          durable_data_end);
204}
205
206bool TraceHandlerImpl::IsCategoryEnabled(const char* category) {
207    if (enabled_categories_.size() == 0) {
208      // If none are specified, enable all categories.
209      return true;
210    }
211    return enabled_category_set_.find(category) != enabled_category_set_.end();
212}
213
214void TraceHandlerImpl::TraceStarted() {
215    trace_provider_packet_t packet{};
216    packet.request = TRACE_PROVIDER_STARTED;
217    packet.data32 = TRACE_PROVIDER_FIFO_PROTOCOL_VERSION;
218    auto status = fifo_.write(sizeof(packet), &packet, 1, nullptr);
219    ZX_DEBUG_ASSERT(status == ZX_OK ||
220                    status == ZX_ERR_PEER_CLOSED);
221}
222
223void TraceHandlerImpl::TraceStopped(async_dispatcher_t* dispatcher, zx_status_t disposition,
224                                    size_t buffer_bytes_written) {
225    // There's no need to notify the trace manager that records were dropped
226    // here. That can be determined from the buffer header.
227    delete this;
228}
229
230void TraceHandlerImpl::NotifyBufferFull(uint32_t wrapped_count,
231                                        uint64_t durable_data_end) {
232    trace_provider_packet_t packet{};
233    packet.request = TRACE_PROVIDER_SAVE_BUFFER;
234    packet.data32 = wrapped_count;
235    packet.data64 = durable_data_end;
236    auto status = fifo_.write(sizeof(packet), &packet, 1, nullptr);
237    // There's something wrong in our protocol or implementation if we fill
238    // the fifo buffer.
239    ZX_DEBUG_ASSERT(status == ZX_OK ||
240                    status == ZX_ERR_PEER_CLOSED);
241}
242
243} // namespace internal
244} // namespace trace
245