1
// Copyright (c) 2017-2022 Cloudflare, Inc.
2
// Licensed under the Apache 2.0 license found in the LICENSE file or at:
3
//     https://opensource.org/licenses/Apache-2.0
4
 
5
#if __linux__
6
#include "json-logger.h"
7
 
8
#include <workerd/server/log-schema.capnp.h>
9
 
10
#include <fcntl.h>
11
#include <unistd.h>
12
 
13
#include <capnp/compat/json.h>
14
#include <capnp/message.h>
15
#include <kj/async-unix.h>
16
#include <kj/io.h>
17
 
18
#include <cstdio>
19
#endif  // __linux__
20
#include <kj/test.h>
21
 
22
namespace workerd::server {
23
namespace {
24
#if __linux__
25
// This test uses pipe2 and dup2 to capture stdout which is far easier on linux.
26
 
27
struct FdPair {
28
  kj::AutoCloseFd output;
29
  kj::AutoCloseFd input;
30
};
31
 
32
auto makePipeFds() {
33
  int pipeFds[2];
34
  KJ_SYSCALL(pipe2(pipeFds, O_CLOEXEC));
35
 
36
  return FdPair{
37
    .output = kj::AutoCloseFd(pipeFds[0]),
38
    .input = kj::AutoCloseFd(pipeFds[1]),
39
  };
40
}
41
 
42
class OutputCapture {
43
 public:
44
  OutputCapture(int fd): targetFd(fd), originalFd(dup(fd)) {
45
    auto pipe = makePipeFds();
46
    KJ_SYSCALL(dup2(pipe.input.get(), targetFd));
47
    readFd = kj::mv(pipe.output);
48
  }
49
 
50
  ~OutputCapture() {
51
    KJ_SYSCALL(dup2(originalFd, targetFd));
52
    close(originalFd);
53
  }
54
 
55
  kj::String readOutput() {
56
    fflush(targetFd == STDOUT_FILENO ? stdout : stderr);
57
 
58
    char buffer[4096];
59
    ssize_t n;
60
    KJ_SYSCALL(n = read(readFd.get(), buffer, sizeof(buffer) - 1));
61
    buffer[n] = '\0';
62
 
63
    return kj::str(buffer, n);
64
  }
65
 
66
 private:
67
  int targetFd;
68
  int originalFd;
69
  kj::AutoCloseFd readFd;
70
};
71
 
72
kj::Maybe<kj::String> findJsonEntryContaining(kj::StringPtr output, kj::StringPtr searchText) {
73
  size_t start = 0;
74
 
75
  while (start < output.size()) {
76
    KJ_IF_SOME(nlPos, output.slice(start).findFirst('\n')) {
77
      auto line = output.slice(start, start + nlPos);
78
      kj::String lineStr = kj::str(line);
79
      if (lineStr.contains(searchText)) {
80
        return kj::mv(lineStr);
81
      }
82
      start = start + nlPos + 1;
83
    } else {
84
      auto line = output.slice(start);
85
      kj::String lineStr = kj::str(line);
86
      if (lineStr.contains(searchText)) {
87
        return kj::mv(lineStr);
88
      }
89
      break;
90
    }
91
  }
92
 
93
  return kj::none;
94
}
95
 
96
void validateJsonLogEntry(kj::StringPtr jsonString,
97
    log_schema::LogEntry::LogLevel expectedLevel,
98
    kj::StringPtr expectedMessage) {
99
  capnp::JsonCodec codec;
100
  codec.handleByAnnotation<log_schema::LogEntry>();
101
 
102
  capnp::MallocMessageBuilder message;
103
  auto logEntry = message.initRoot<log_schema::LogEntry>();
104
  codec.decode(jsonString, logEntry);
105
 
106
  KJ_EXPECT(logEntry.getLevel() == expectedLevel);
107
  KJ_EXPECT(logEntry.getMessage() == expectedMessage);
108
  KJ_EXPECT(logEntry.getTimestamp() > 0);
109
}
110
 
111
KJ_TEST("JsonLogger stdout validation") {
112
  JsonLogger logger;
113
  OutputCapture capture(STDOUT_FILENO);
114
 
115
  KJ_LOG(ERROR, "Test JSON message");
116
 
117
  auto output = capture.readOutput();
118
  auto jsonEntry = KJ_ASSERT_NONNULL(findJsonEntryContaining(output, "Test JSON message"));
119
  validateJsonLogEntry(jsonEntry, log_schema::LogEntry::LogLevel::ERROR, "Test JSON message");
120
 
121
  capnp::JsonCodec codec;
122
  codec.handleByAnnotation<log_schema::LogEntry>();
123
  capnp::MallocMessageBuilder message;
124
  auto logEntry = message.initRoot<log_schema::LogEntry>();
125
  codec.decode(jsonEntry, logEntry);
126
 
127
  auto source = logEntry.getSource();
128
  KJ_EXPECT(kj::StringPtr(source.begin(), source.size()).contains("json-logger-test.c++"));
129
}
130
 
131
KJ_TEST("StructuredLoggingProcessContext - plain text mode by default") {
132
  StructuredLoggingProcessContext context("test-program");
133
 
134
  KJ_EXPECT(context.getProgramName() == "test-program");
135
 
136
  OutputCapture capture(STDERR_FILENO);
137
  context.warning("Test warning message");
138
 
139
  auto output = capture.readOutput();
140
 
141
  KJ_EXPECT(output.contains("Test warning message"));
142
  KJ_EXPECT(!output.contains("{"));
143
}
144
 
145
KJ_TEST("StructuredLoggingProcessContext - structured logging mode") {
146
  StructuredLoggingProcessContext context("test-program");
147
  context.enableStructuredLogging();
148
 
149
  OutputCapture capture(STDERR_FILENO);
150
  context.warning("Test structured warning");
151
 
152
  auto output = capture.readOutput();
153
  auto jsonEntry = KJ_ASSERT_NONNULL(findJsonEntryContaining(output, "Test structured warning"));
154
  validateJsonLogEntry(
155
      jsonEntry, log_schema::LogEntry::LogLevel::WARNING, "Test structured warning");
156
}
157
 
158
KJ_TEST("StructuredLoggingProcessContext - error handling in structured mode") {
159
  StructuredLoggingProcessContext context("test-program");
160
  context.enableStructuredLogging();
161
 
162
  OutputCapture capture(STDERR_FILENO);
163
  context.error("Test structured error");
164
 
165
  auto output = capture.readOutput();
166
  auto jsonEntry = KJ_ASSERT_NONNULL(findJsonEntryContaining(output, "Test structured error"));
167
  validateJsonLogEntry(jsonEntry, log_schema::LogEntry::LogLevel::ERROR, "Test structured error");
168
}
169
 
170
#endif  // __linux__
171
 
172
KJ_TEST("Blank test because KJ fails when 0 tests are enabled") {}
173
 
174
}  // namespace
175
}  // namespace workerd::server