]>
Commit | Line | Data |
---|---|---|
82b7abe3 | 1 | /* |
b8ae064d | 2 | * Copyright (C) 1996-2023 The Squid Software Foundation and contributors |
82b7abe3 | 3 | * |
bbc27441 AJ |
4 | * Squid software is distributed under GPLv2+ license and includes |
5 | * contributions from numerous individuals and organizations. | |
6 | * Please see the COPYING and CONTRIBUTORS files for details. | |
82b7abe3 AJ |
7 | */ |
8 | ||
bbc27441 AJ |
9 | /* DEBUG: section 50 Log file handling */ |
10 | ||
582c2af2 | 11 | #include "squid.h" |
82b7abe3 | 12 | #include "cbdata.h" |
d841c88d | 13 | #include "comm/Loops.h" |
ed6e9fb9 | 14 | #include "fatal.h" |
82b7abe3 | 15 | #include "fde.h" |
582c2af2 | 16 | #include "globals.h" |
82b7abe3 AJ |
17 | #include "log/Config.h" |
18 | #include "log/File.h" | |
19 | #include "log/ModDaemon.h" | |
4d5904f7 | 20 | #include "SquidConfig.h" |
602d9612 | 21 | #include "SquidIpc.h" |
82b7abe3 | 22 | |
1a30fdf5 | 23 | #include <cerrno> |
21d845b1 | 24 | |
82b7abe3 | 25 | /* How many buffers to keep before we say we've buffered too much */ |
f53969cc | 26 | #define LOGFILE_MAXBUFS 128 |
82b7abe3 AJ |
27 | |
28 | /* Size of the logfile buffer */ | |
9d65168e | 29 | /* |
82b7abe3 AJ |
30 | * For optimal performance this should match LOGFILE_BUFSIZ in logfile-daemon.c |
31 | */ | |
f53969cc | 32 | #define LOGFILE_BUFSZ 32768 |
82b7abe3 AJ |
33 | |
34 | /* How many seconds between warnings */ | |
f53969cc | 35 | #define LOGFILE_WARN_TIME 30 |
82b7abe3 AJ |
36 | |
37 | static LOGWRITE logfile_mod_daemon_writeline; | |
38 | static LOGLINESTART logfile_mod_daemon_linestart; | |
39 | static LOGLINEEND logfile_mod_daemon_lineend; | |
40 | static LOGROTATE logfile_mod_daemon_rotate; | |
41 | static LOGFLUSH logfile_mod_daemon_flush; | |
42 | static LOGCLOSE logfile_mod_daemon_close; | |
43 | ||
44 | static void logfile_mod_daemon_append(Logfile * lf, const char *buf, int len); | |
45 | ||
46 | struct _l_daemon { | |
47 | int rfd, wfd; | |
48 | char eol; | |
49 | pid_t pid; | |
50 | int flush_pending; | |
51 | dlink_list bufs; | |
52 | int nbufs; | |
53 | int last_warned; | |
54 | }; | |
55 | ||
56 | typedef struct _l_daemon l_daemon_t; | |
57 | ||
58 | /* Internal code */ | |
59 | static void | |
60 | logfileNewBuffer(Logfile * lf) | |
61 | { | |
62 | l_daemon_t *ll = (l_daemon_t *) lf->data; | |
63 | logfile_buffer_t *b; | |
64 | ||
65 | debugs(50, 5, "logfileNewBuffer: " << lf->path << ": new buffer"); | |
66 | ||
67 | b = static_cast<logfile_buffer_t*>(xcalloc(1, sizeof(logfile_buffer_t))); | |
aee3523a | 68 | assert(b != nullptr); |
82b7abe3 | 69 | b->buf = static_cast<char*>(xcalloc(1, LOGFILE_BUFSZ)); |
aee3523a | 70 | assert(b->buf != nullptr); |
82b7abe3 AJ |
71 | b->size = LOGFILE_BUFSZ; |
72 | b->written_len = 0; | |
73 | b->len = 0; | |
74 | dlinkAddTail(b, &b->node, &ll->bufs); | |
d7ae3534 | 75 | ++ ll->nbufs; |
82b7abe3 AJ |
76 | } |
77 | ||
78 | static void | |
79 | logfileFreeBuffer(Logfile * lf, logfile_buffer_t * b) | |
80 | { | |
81 | l_daemon_t *ll = (l_daemon_t *) lf->data; | |
aee3523a | 82 | assert(b != nullptr); |
82b7abe3 | 83 | dlinkDelete(&b->node, &ll->bufs); |
5e263176 | 84 | -- ll->nbufs; |
82b7abe3 AJ |
85 | xfree(b->buf); |
86 | xfree(b); | |
87 | } | |
88 | ||
89 | static void | |
ced8def3 | 90 | logfileHandleWrite(int, void *data) |
82b7abe3 | 91 | { |
98f484af AJ |
92 | Logfile *lf = static_cast<Logfile *>(data); |
93 | l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data); | |
82b7abe3 AJ |
94 | |
95 | /* | |
96 | * We'll try writing the first entry until its done - if we | |
97 | * get a partial write then we'll re-schedule until its completed. | |
98 | * Its naive but it'll do for now. | |
99 | */ | |
98f484af AJ |
100 | if (!ll->bufs.head) // abort if there is nothing pending right now. |
101 | return; | |
102 | ||
103 | logfile_buffer_t *b = static_cast<logfile_buffer_t*>(ll->bufs.head->data); | |
aee3523a | 104 | assert(b != nullptr); |
82b7abe3 AJ |
105 | ll->flush_pending = 0; |
106 | ||
98f484af | 107 | int ret = FD_WRITE_METHOD(ll->wfd, b->buf + b->written_len, b->len - b->written_len); |
b69e9ffa | 108 | int xerrno = errno; |
98f484af | 109 | debugs(50, 3, lf->path << ": write returned " << ret); |
82b7abe3 | 110 | if (ret < 0) { |
b69e9ffa | 111 | if (ignoreErrno(xerrno)) { |
9d65168e | 112 | /* something temporary */ |
98f484af AJ |
113 | Comm::SetSelect(ll->wfd, COMM_SELECT_WRITE, logfileHandleWrite, lf, 0); |
114 | ll->flush_pending = 1; | |
115 | return; | |
9d65168e | 116 | } |
d816f28d | 117 | debugs(50, DBG_IMPORTANT, "ERROR: logfileHandleWrite: " << lf->path << ": error writing (" << xstrerr(xerrno) << ")"); |
9d65168e A |
118 | /* XXX should handle this better */ |
119 | fatal("I don't handle this error well!"); | |
82b7abe3 AJ |
120 | } |
121 | if (ret == 0) { | |
9d65168e A |
122 | /* error? */ |
123 | debugs(50, DBG_IMPORTANT, "logfileHandleWrite: " << lf->path << ": wrote 0 bytes?"); | |
124 | /* XXX should handle this better */ | |
125 | fatal("I don't handle this error well!"); | |
82b7abe3 AJ |
126 | } |
127 | /* ret > 0, so something was written */ | |
128 | b->written_len += ret; | |
129 | assert(b->written_len <= b->len); | |
130 | if (b->written_len == b->len) { | |
9d65168e A |
131 | /* written the whole buffer! */ |
132 | logfileFreeBuffer(lf, b); | |
aee3523a | 133 | b = nullptr; |
82b7abe3 AJ |
134 | } |
135 | /* Is there more to write? */ | |
98f484af AJ |
136 | if (!ll->bufs.head) |
137 | return; | |
82b7abe3 AJ |
138 | /* there is, so schedule more */ |
139 | ||
d841c88d | 140 | Comm::SetSelect(ll->wfd, COMM_SELECT_WRITE, logfileHandleWrite, lf, 0); |
82b7abe3 | 141 | ll->flush_pending = 1; |
82b7abe3 AJ |
142 | return; |
143 | } | |
144 | ||
145 | static void | |
146 | logfileQueueWrite(Logfile * lf) | |
147 | { | |
148 | l_daemon_t *ll = (l_daemon_t *) lf->data; | |
aee3523a | 149 | if (ll->flush_pending || ll->bufs.head == nullptr) { |
9d65168e | 150 | return; |
82b7abe3 AJ |
151 | } |
152 | ll->flush_pending = 1; | |
153 | if (ll->bufs.head) { | |
9d65168e A |
154 | logfile_buffer_t *b = static_cast<logfile_buffer_t*>(ll->bufs.head->data); |
155 | if (b->len + 2 <= b->size) | |
156 | logfile_mod_daemon_append(lf, "F\n", 2); | |
82b7abe3 AJ |
157 | } |
158 | /* Ok, schedule a write-event */ | |
d841c88d | 159 | Comm::SetSelect(ll->wfd, COMM_SELECT_WRITE, logfileHandleWrite, lf, 0); |
82b7abe3 AJ |
160 | } |
161 | ||
162 | static void | |
163 | logfile_mod_daemon_append(Logfile * lf, const char *buf, int len) | |
164 | { | |
165 | l_daemon_t *ll = (l_daemon_t *) lf->data; | |
166 | logfile_buffer_t *b; | |
167 | int s; | |
168 | ||
169 | /* Is there a buffer? If not, create one */ | |
aee3523a | 170 | if (ll->bufs.head == nullptr) { |
9d65168e | 171 | logfileNewBuffer(lf); |
82b7abe3 AJ |
172 | } |
173 | debugs(50, 3, "logfile_mod_daemon_append: " << lf->path << ": appending " << len << " bytes"); | |
174 | /* Copy what can be copied */ | |
175 | while (len > 0) { | |
9d65168e A |
176 | b = static_cast<logfile_buffer_t*>(ll->bufs.tail->data); |
177 | debugs(50, 3, "logfile_mod_daemon_append: current buffer has " << b->len << " of " << b->size << " bytes before append"); | |
178 | s = min(len, (b->size - b->len)); | |
41d00cd3 | 179 | memcpy(b->buf + b->len, buf, s); |
9d65168e A |
180 | len = len - s; |
181 | buf = buf + s; | |
182 | b->len = b->len + s; | |
183 | assert(b->len <= LOGFILE_BUFSZ); | |
184 | assert(len >= 0); | |
185 | if (len > 0) { | |
186 | logfileNewBuffer(lf); | |
187 | } | |
82b7abe3 AJ |
188 | } |
189 | } | |
190 | ||
191 | /* | |
192 | * only schedule a flush (write) if one isn't scheduled. | |
193 | */ | |
194 | static void | |
195 | logfileFlushEvent(void *data) | |
196 | { | |
197 | Logfile *lf = static_cast<Logfile *>(data); | |
198 | ||
199 | /* | |
200 | * This might work better if we keep track of when we wrote last and only | |
201 | * schedule a write if we haven't done so in the last second or two. | |
202 | */ | |
203 | logfileQueueWrite(lf); | |
204 | eventAdd("logfileFlush", logfileFlushEvent, lf, 1.0, 1); | |
205 | } | |
206 | ||
82b7abe3 AJ |
207 | /* External code */ |
208 | ||
209 | int | |
ced8def3 | 210 | logfile_mod_daemon_open(Logfile * lf, const char *path, size_t, int) |
82b7abe3 AJ |
211 | { |
212 | const char *args[5]; | |
213 | char *tmpbuf; | |
214 | l_daemon_t *ll; | |
215 | ||
216 | lf->f_close = logfile_mod_daemon_close; | |
217 | lf->f_linewrite = logfile_mod_daemon_writeline; | |
218 | lf->f_linestart = logfile_mod_daemon_linestart; | |
219 | lf->f_lineend = logfile_mod_daemon_lineend; | |
220 | lf->f_flush = logfile_mod_daemon_flush; | |
221 | lf->f_rotate = logfile_mod_daemon_rotate; | |
222 | ||
223 | cbdataInternalLock(lf); // WTF? | |
e0236918 | 224 | debugs(50, DBG_IMPORTANT, "Logfile Daemon: opening log " << path); |
82b7abe3 AJ |
225 | ll = static_cast<l_daemon_t*>(xcalloc(1, sizeof(*ll))); |
226 | lf->data = ll; | |
227 | ll->eol = 1; | |
228 | { | |
b7ac5457 | 229 | Ip::Address localhost; |
9d65168e A |
230 | args[0] = "(logfile-daemon)"; |
231 | args[1] = path; | |
aee3523a | 232 | args[2] = nullptr; |
4dd643d5 | 233 | localhost.setLocalhost(); |
aee3523a | 234 | ll->pid = ipcCreate(IPC_STREAM, Log::TheConfig.logfile_daemon, args, "logfile-daemon", localhost, &ll->rfd, &ll->wfd, nullptr); |
9d65168e A |
235 | if (ll->pid < 0) |
236 | fatal("Couldn't start logfile helper"); | |
82b7abe3 AJ |
237 | } |
238 | ll->nbufs = 0; | |
239 | ||
240 | /* Queue the initial control data */ | |
241 | tmpbuf = static_cast<char*>(xmalloc(BUFSIZ)); | |
242 | snprintf(tmpbuf, BUFSIZ, "r%d\nb%d\n", Config.Log.rotateNumber, Config.onoff.buffered_logs); | |
243 | logfile_mod_daemon_append(lf, tmpbuf, strlen(tmpbuf)); | |
244 | xfree(tmpbuf); | |
245 | ||
246 | /* Start the flush event */ | |
247 | eventAdd("logfileFlush", logfileFlushEvent, lf, 1.0, 1); | |
248 | ||
249 | return 1; | |
250 | } | |
251 | ||
252 | static void | |
253 | logfile_mod_daemon_close(Logfile * lf) | |
254 | { | |
255 | l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data); | |
e0236918 | 256 | debugs(50, DBG_IMPORTANT, "Logfile Daemon: closing log " << lf->path); |
82b7abe3 AJ |
257 | logfileFlush(lf); |
258 | if (ll->rfd == ll->wfd) | |
9d65168e | 259 | comm_close(ll->rfd); |
82b7abe3 AJ |
260 | else { |
261 | comm_close(ll->rfd); | |
262 | comm_close(ll->wfd); | |
263 | } | |
264 | kill(ll->pid, SIGTERM); | |
265 | eventDelete(logfileFlushEvent, lf); | |
266 | xfree(ll); | |
aee3523a | 267 | lf->data = nullptr; |
82b7abe3 AJ |
268 | cbdataInternalUnlock(lf); // WTF?? |
269 | } | |
270 | ||
271 | static void | |
efc23871 | 272 | logfile_mod_daemon_rotate(Logfile * lf, const int16_t) |
82b7abe3 AJ |
273 | { |
274 | char tb[3]; | |
e0236918 | 275 | debugs(50, DBG_IMPORTANT, "logfileRotate: " << lf->path); |
82b7abe3 AJ |
276 | tb[0] = 'R'; |
277 | tb[1] = '\n'; | |
278 | tb[2] = '\0'; | |
279 | logfile_mod_daemon_append(lf, tb, 2); | |
280 | } | |
281 | ||
282 | /* | |
283 | * This routine assumes that up to one line is written. Don't try to | |
284 | * call this routine with more than one line or subsequent lines | |
285 | * won't be prefixed with the command type and confuse the logging | |
286 | * daemon somewhat. | |
287 | */ | |
288 | static void | |
289 | logfile_mod_daemon_writeline(Logfile * lf, const char *buf, size_t len) | |
290 | { | |
291 | l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data); | |
292 | /* Make sure the logfile buffer isn't too large */ | |
293 | if (ll->nbufs > LOGFILE_MAXBUFS) { | |
9d65168e A |
294 | if (ll->last_warned < squid_curtime - LOGFILE_WARN_TIME) { |
295 | ll->last_warned = squid_curtime; | |
296 | debugs(50, DBG_IMPORTANT, "Logfile: " << lf->path << ": queue is too large; some log messages have been lost."); | |
297 | } | |
298 | return; | |
82b7abe3 | 299 | } |
7b2bbcd6 | 300 | |
82b7abe3 | 301 | /* Are we eol? If so, prefix with our logfile command byte */ |
7b2bbcd6 | 302 | if (ll->eol == 1) { |
70ac5b29 | 303 | logfile_mod_daemon_append(lf, "L", 1); |
304 | ll->eol = 0; | |
7b2bbcd6 D |
305 | } |
306 | ||
307 | /* Append this data to the end buffer; create a new one if needed */ | |
82b7abe3 AJ |
308 | logfile_mod_daemon_append(lf, buf, len); |
309 | } | |
310 | ||
311 | static void | |
312 | logfile_mod_daemon_linestart(Logfile * lf) | |
313 | { | |
314 | l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data); | |
82b7abe3 | 315 | assert(ll->eol == 1); |
7b2bbcd6 | 316 | // logfile_mod_daemon_writeline() sends the starting command |
82b7abe3 AJ |
317 | } |
318 | ||
319 | static void | |
320 | logfile_mod_daemon_lineend(Logfile * lf) | |
321 | { | |
322 | l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data); | |
323 | logfile_buffer_t *b; | |
7b2bbcd6 D |
324 | if (ll->eol == 1) // logfile_mod_daemon_writeline() wrote nothing |
325 | return; | |
82b7abe3 AJ |
326 | ll->eol = 1; |
327 | /* Kick a write off if the head buffer is -full- */ | |
aee3523a | 328 | if (ll->bufs.head != nullptr) { |
9d65168e | 329 | b = static_cast<logfile_buffer_t*>(ll->bufs.head->data); |
aee3523a | 330 | if (b->node.next != nullptr || !Config.onoff.buffered_logs) |
9d65168e | 331 | logfileQueueWrite(lf); |
82b7abe3 AJ |
332 | } |
333 | } | |
334 | ||
335 | static void | |
336 | logfile_mod_daemon_flush(Logfile * lf) | |
337 | { | |
338 | l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data); | |
339 | if (commUnsetNonBlocking(ll->wfd)) { | |
d816f28d | 340 | debugs(50, DBG_IMPORTANT, "ERROR: Logfile Daemon: Could not set the pipe blocking for flush! You are now missing some log entries."); |
9d65168e | 341 | return; |
82b7abe3 | 342 | } |
aee3523a | 343 | while (ll->bufs.head != nullptr) { |
9d65168e | 344 | logfileHandleWrite(ll->wfd, lf); |
82b7abe3 AJ |
345 | } |
346 | if (commSetNonBlocking(ll->wfd)) { | |
9d65168e A |
347 | fatalf("Logfile Daemon: %s: Couldn't set the pipe non-blocking for flush!\n", lf->path); |
348 | return; | |
82b7abe3 AJ |
349 | } |
350 | } | |
f53969cc | 351 |