xref: /trafficserver/src/tscore/BaseLogFile.cc (revision 4cfd5a73)
1 /** @file
2 
3   Base class for log files implementation
4 
5   @section license License
6 
7   Licensed to the Apache Software Foundation (ASF) under one
8   or more contributor license agreements.  See the NOTICE file
9   distributed with this work for additional information
10   regarding copyright ownership.  The ASF licenses this file
11   to you under the Apache License, Version 2.0 (the
12   "License"); you may not use this file except in compliance
13   with the License.  You may obtain a copy of the License at
14 
15       http://www.apache.org/licenses/LICENSE-2.0
16 
17   Unless required by applicable law or agreed to in writing, software
18   distributed under the License is distributed on an "AS IS" BASIS,
19   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
20   See the License for the specific language governing permissions and
21   limitations under the License.
22  */
23 
24 #include "tscore/BaseLogFile.h"
25 
26 /*
27  * This constructor creates a BaseLogFile based on a given name.
28  * This is the most common way BaseLogFiles are created.
29  */
30 BaseLogFile::BaseLogFile(const char *name) : m_name(ats_strdup(name))
31 {
32   log_log_trace("exiting BaseLogFile constructor, m_name=%s, this=%p\n", m_name.get(), this);
33 }
34 
35 /*
36  * This constructor creates a BaseLogFile based on a given name.
37  * Similar to above constructor, but is overloaded with the object signature
38  */
39 BaseLogFile::BaseLogFile(const char *name, uint64_t sig) : m_name(ats_strdup(name)), m_signature(sig), m_has_signature(true)
40 {
41   log_log_trace("exiting BaseLogFile signature constructor, m_name=%s, m_signature=%ld, this=%p\n", m_name.get(), m_signature,
42                 this);
43 }
44 
45 /*
46  * This copy constructor creates a BaseLogFile based on a given copy.
47  */
48 BaseLogFile::BaseLogFile(const BaseLogFile &copy)
49   : m_start_time(copy.m_start_time),
50 
51     m_name(ats_strdup(copy.m_name)),
52     m_hostname(ats_strdup(copy.m_hostname)),
53 
54     m_is_init(copy.m_is_init),
55 
56     m_signature(copy.m_signature),
57     m_has_signature(copy.m_has_signature)
58 {
59   log_log_trace("exiting BaseLogFile copy constructor, m_name=%s, this=%p\n", m_name.get(), this);
60 }
61 
62 /*
63  * Destructor.
64  */
65 BaseLogFile::~BaseLogFile()
66 {
67   log_log_trace("entering BaseLogFile destructor, m_name=%s, this=%p\n", m_name.get(), this);
68 
69   if (m_is_regfile) {
70     close_file();
71   } else {
72     log_log_trace("not a regular file, not closing, m_name=%s, this=%p\n", m_name.get(), this);
73   }
74 
75   log_log_trace("exiting BaseLogFile destructor, this=%p\n", this);
76 }
77 
78 /*
79  * This function is called by a client of BaseLogFile to roll the underlying
80  * file  The tricky part to this routine is in coming up with the new file name,
81  * which contains the bounding timestamp interval for the entries
82  * within the file.
83 
84  * Under normal operating conditions, this BaseLogFile object was in existence
85  * for all writes to the file.  In this case, the LogFile members m_start_time
86  * and m_end_time will have the starting and ending times for the actual
87  * entries written to the file.
88 
89  * On restart situations, it is possible to re-open an existing BaseLogFile,
90  * which means that the m_start_time variable will be later than the actual
91  * entries recorded in the file.  In this case, we'll use the creation time
92  * of the file, which should be recorded in the meta-information located on
93  * disk.
94 
95  * If we can't use the meta-file, either because it's not there or because
96  * it's not valid, then we'll use timestamp 0 (Jan 1, 1970) as the starting
97  * bound.
98 
99  * Return 1 if file rolled, 0 otherwise
100  */
101 int
102 BaseLogFile::roll(long interval_start, long interval_end)
103 {
104   // First, let's see if a roll is even needed.
105   if (m_name == nullptr || !BaseLogFile::exists(m_name.get())) {
106     log_log_trace("Roll not needed for %s; file doesn't exist\n", (m_name.get()) ? m_name.get() : "no_name\n");
107     return 0;
108   }
109 
110   // Then, check if this object is backing a regular file
111   if (!m_is_regfile) {
112     log_log_trace("Roll not needed for %s; not regular file\n", (m_name.get()) ? m_name.get() : "no_name\n");
113     return 0;
114   }
115 
116   // Read meta info if needed (if file was not opened)
117   if (!m_meta_info) {
118     m_meta_info = new BaseMetaInfo(m_name.get());
119   }
120 
121   // Create the new file name, which consists of a timestamp and rolled
122   // extension added to the previous file name.  The timestamp format is
123   // ".%Y%m%d.%Hh%Mm%Ss-%Y%m%d.%Hh%Mm%Ss", where the two date/time values
124   // represent the starting and ending times for entries in the rolled
125   // log file.  In addition, we add the hostname.  So, the entire rolled
126   // format is something like:
127   //
128   //    "squid.log.mymachine.19980712.12h00m00s-19980713.12h00m00s.old"
129   char roll_name[LOGFILE_ROLL_MAXPATHLEN];
130   char start_time_ext[64];
131   char end_time_ext[64];
132   time_t start, end;
133 
134   // Start with conservative values for the start and end bounds, then
135   // try to refine.
136   start = 0L;
137   end   = (interval_end >= m_end_time) ? interval_end : m_end_time;
138 
139   if (m_meta_info->data_from_metafile()) {
140     // If the metadata came from the metafile, this means that
141     // the file was preexisting, so we can't use m_start_time for
142     // our starting bounds.  Instead, we'll try to use the file
143     // creation time stored in the metafile (if it's valid and we can
144     // read it).  If all else fails, we'll use 0 for the start time.
145     log_log_trace("in BaseLogFile::roll(..) used metadata starttime\n");
146     m_meta_info->get_creation_time(&start);
147   } else {
148     // The logfile was not preexisting (normal case), so we'll use
149     // earlier of the interval start time and the m_start_time.
150     //
151     // note that m_start_time is not the time of the first
152     // transaction, but the time of the creation of the first log
153     // buffer used by the file. These times may be different,
154     // especially under light load, and using the m_start_time may
155     // produce overlapping filenames (the problem is that we have
156     // no easy way of keeping track of the timestamp of the first
157     // transaction
158     log_log_trace("in BaseLogFile::roll(..), didn't use metadata starttime, used earliest available starttime\n");
159     if (interval_start == 0) {
160       start = m_start_time;
161     } else {
162       start = (m_start_time < interval_start) ? m_start_time : interval_start;
163     }
164   }
165   log_log_trace("in BaseLogFile::roll(..), start = %ld, m_start_time = %ld, interval_start = %ld\n", start, m_start_time,
166                 interval_start);
167 
168   // Now that we have our timestamp values, convert them to the proper
169   // timestamp formats and create the rolled file name.
170   timestamp_to_str(static_cast<long>(start), start_time_ext, sizeof(start_time_ext));
171   timestamp_to_str(static_cast<long>(end), end_time_ext, sizeof(start_time_ext));
172   snprintf(roll_name, LOGFILE_ROLL_MAXPATHLEN, "%s%s%s.%s-%s%s", m_name.get(), (m_hostname.get() ? LOGFILE_SEPARATOR_STRING : ""),
173            (m_hostname.get() ? m_hostname.get() : ""), start_time_ext, end_time_ext, LOGFILE_ROLLED_EXTENSION);
174 
175   // It may be possible that the file we want to roll into already
176   // exists.  If so, then we need to add a version tag to the rolled
177   // filename as well so that we don't clobber existing files.
178   int version = 1;
179   while (BaseLogFile::exists(roll_name)) {
180     log_log_trace("The rolled file %s already exists; adding version "
181                   "tag %d to avoid clobbering the existing file.\n",
182                   roll_name, version);
183     snprintf(roll_name, LOGFILE_ROLL_MAXPATHLEN, "%s%s%s.%s-%s.%d%s", m_name.get(),
184              (m_hostname.get() ? LOGFILE_SEPARATOR_STRING : ""), (m_hostname.get() ? m_hostname.get() : ""), start_time_ext,
185              end_time_ext, version, LOGFILE_ROLLED_EXTENSION);
186     ++version;
187   }
188 
189   // It's now safe to rename the file.
190   if (::rename(m_name.get(), roll_name) < 0) {
191     log_log_error("Traffic Server could not rename logfile %s to %s, error %d: "
192                   "%s.\n",
193                   m_name.get(), roll_name, errno, strerror(errno));
194     return 0;
195   }
196 
197   // reset m_start_time
198   m_start_time    = 0;
199   m_bytes_written = 0;
200 
201   log_log_trace("The logfile %s was rolled to %s.\n", m_name.get(), roll_name);
202 
203   return 1;
204 }
205 
206 /*
207  * The more convenient rolling function. Intended use is for less
208  * critical logs such as diags.log or traffic.out, since _exact_
209  * timestamps may be less important
210  *
211  * The function calls roll(long,long) with these parameters:
212  * Start time is either 0 or creation time stored in the metafile,
213  * whichever is greater
214  *
215  * End time is the current time
216  *
217  * Returns 1 on success, 0 otherwise
218  */
219 int
220 BaseLogFile::roll()
221 {
222   time_t start;
223   time_t now = time(nullptr);
224 
225   if (!m_meta_info || !m_meta_info->get_creation_time(&start)) {
226     start = 0L;
227   }
228 
229   return roll(start, now);
230 }
231 
232 /*
233  * This function will return true if the given filename corresponds to a
234  * rolled logfile.  We make this determination based on the file extension.
235  */
236 bool
237 BaseLogFile::rolled_logfile(char *path)
238 {
239   const int target_len = static_cast<int>(strlen(LOGFILE_ROLLED_EXTENSION));
240   int len              = static_cast<int>(strlen(path));
241   if (len > target_len) {
242     char *str = &path[len - target_len];
243     if (!strcmp(str, LOGFILE_ROLLED_EXTENSION)) {
244       return true;
245     }
246   }
247   return false;
248 }
249 
250 /*
251  * Returns if the provided file in 'pathname' exists or not
252  */
253 bool
254 BaseLogFile::exists(const char *pathname)
255 {
256   ink_assert(pathname != nullptr);
257   return (pathname && ::access(pathname, F_OK) == 0);
258 }
259 
260 /*
261  * Opens the BaseLogFile and associated BaseMetaInfo on disk if it exists
262  * Returns relevant exit status
263  */
264 int
265 BaseLogFile::open_file(int perm)
266 {
267   log_log_trace("BaseLogFile: entered open_file()\n");
268   if (is_open()) {
269     return LOG_FILE_NO_ERROR;
270   }
271 
272   if (!m_name.get()) {
273     log_log_error("BaseLogFile: m_name is nullptr, aborting open_file()\n");
274     return LOG_FILE_COULD_NOT_OPEN_FILE;
275   } else if (!strcmp(m_name.get(), "stdout")) {
276     log_log_trace("BaseLogFile: stdout opened\n");
277     m_fp      = stdout;
278     m_is_init = true;
279     return LOG_FILE_NO_ERROR;
280   } else if (!strcmp(m_name.get(), "stderr")) {
281     log_log_trace("BaseLogFile: stderr opened\n");
282     m_fp      = stderr;
283     m_is_init = true;
284     return LOG_FILE_NO_ERROR;
285   }
286 
287   // means this object is representing a real file on disk
288   m_is_regfile = true;
289 
290   // Check to see if the file exists BEFORE we try to open it, since
291   // opening it will also create it.
292   bool file_exists = BaseLogFile::exists(m_name.get());
293 
294   if (file_exists) {
295     if (!m_meta_info) {
296       // This object must be fresh since it has not built its MetaInfo
297       // so we create a new MetaInfo object that will read right away
298       // (in the constructor) the corresponding metafile
299       m_meta_info = new BaseMetaInfo(m_name.get());
300     }
301   } else {
302     // The log file does not exist, so we create a new MetaInfo object
303     //  which will save itself to disk right away (in the constructor)
304     if (m_has_signature) {
305       m_meta_info = new BaseMetaInfo(m_name.get(), static_cast<long>(time(nullptr)), m_signature);
306     } else {
307       m_meta_info = new BaseMetaInfo(m_name.get(), static_cast<long>(time(nullptr)));
308     }
309   }
310 
311   // open actual log file (not metainfo)
312   log_log_trace("BaseLogFile: attempting to open %s\n", m_name.get());
313 
314   m_fp = elevating_fopen(m_name.get(), "a+");
315 
316   // error check
317   if (m_fp) {
318     setlinebuf(m_fp);
319   } else {
320     log_log_error("Error opening log file %s: %s\n", m_name.get(), strerror(errno));
321     log_log_error("Actual error: %s\n", (errno == EINVAL ? "einval" : "something else"));
322     return LOG_FILE_COULD_NOT_OPEN_FILE;
323   }
324 
325   // set permissions if necessary
326   if (perm != -1) {
327     // means LogFile passed in some permissions we need to set
328     log_log_trace("BaseLogFile attempting to change %s's permissions to %o\n", m_name.get(), perm);
329     if (elevating_chmod(m_name.get(), perm) != 0) {
330       log_log_error("Error changing logfile=%s permissions: %s\n", m_name.get(), strerror(errno));
331     }
332   }
333 
334   // set m_bytes_written to force the rolling based on file size.
335   m_bytes_written = fseek(m_fp, 0, SEEK_CUR);
336 
337   log_log_trace("BaseLogFile %s is now open (fd=%d)\n", m_name.get(), fileno(m_fp));
338   m_is_init = true;
339   return LOG_FILE_NO_ERROR;
340 }
341 
342 /*
343  * Closes actual log file, not metainfo
344  */
345 void
346 BaseLogFile::close_file()
347 {
348   if (is_open()) {
349     fclose(m_fp);
350     log_log_trace("BaseLogFile %s is closed\n", m_name.get());
351     m_fp      = nullptr;
352     m_is_init = false;
353   }
354 }
355 
356 /*
357  * Changes names of the actual log file (not metainfo)
358  */
359 void
360 BaseLogFile::change_name(const char *new_name)
361 {
362   m_name = ats_strdup(new_name);
363 }
364 
365 void
366 BaseLogFile::display(FILE *fd)
367 {
368   fprintf(fd, "Logfile: %s, %s\n", get_name(), (is_open()) ? "file is open" : "file is not open");
369 }
370 
371 /*
372  * Lowest level internal logging facility for BaseLogFile
373  *
374  * Since BaseLogFiles can potentially be created before the bootstrap
375  * instance of Diags is ready, we cannot simply call something like Debug().
376  * However, we still need to log the creation of BaseLogFile, since the
377  * information is still useful. This function will print out log messages
378  * into traffic.out if we happen to be bootstrapping Diags. Since
379  * traffic_manager redirects stdout/stderr into traffic.out, that
380  * redirection is inherited by way of exec()/fork() all the way here.
381  *
382  * TODO use Debug() for non bootstrap instances
383  */
384 void
385 BaseLogFile::log_log(LogLogPriorityLevel priority, const char *format, ...)
386 {
387   va_list args;
388 
389   const char *priority_name = nullptr;
390   FILE *output              = stdout;
391   switch (priority) {
392   case LL_Debug:
393     priority_name = "DEBUG";
394     break;
395   case LL_Note:
396     priority_name = "NOTE";
397     break;
398   case LL_Warning:
399     priority_name = "WARNING";
400     output        = stderr;
401     break;
402   case LL_Error:
403     priority_name = "ERROR";
404     output        = stderr;
405     break;
406   case LL_Fatal:
407     priority_name = "FATAL";
408     output        = stderr;
409     break;
410   default:
411     priority_name = "unknown priority";
412   }
413 
414   va_start(args, format);
415   struct timeval now;
416   double now_f;
417 
418   gettimeofday(&now, nullptr);
419   now_f = now.tv_sec + now.tv_usec / 1000000.0f;
420 
421   fprintf(output, "<%.4f> [%s]: ", now_f, priority_name);
422   vfprintf(output, format, args);
423   fflush(output);
424 
425   va_end(args);
426 }
427 
428 /****************************************************************************
429 
430   BaseMetaInfo methods
431 
432 *****************************************************************************/
433 
434 /*
435  * Given a file name (with or without the full path, but without the extension name),
436  * this function creates appends the ".meta" extension and stores it in the local
437  * variable
438  */
439 void
440 BaseMetaInfo::_build_name(const char *filename)
441 {
442   int i = -1, l = 0;
443   char c;
444   while (c = filename[l], c != 0) {
445     if (c == '/') {
446       i = l;
447     }
448     ++l;
449   }
450 
451   // 7 = 1 (dot at beginning) + 5 (".meta") + 1 (null terminating)
452   //
453   _filename = static_cast<char *>(ats_malloc(l + 7));
454 
455   if (i < 0) {
456     ink_string_concatenate_strings(_filename, ".", filename, ".meta", nullptr);
457   } else {
458     memcpy(_filename, filename, i + 1);
459     ink_string_concatenate_strings(&_filename[i + 1], ".", &filename[i + 1], ".meta", nullptr);
460   }
461 }
462 
463 /*
464  * Reads in meta info into the local variables
465  */
466 void
467 BaseMetaInfo::_read_from_file()
468 {
469   _flags |= DATA_FROM_METAFILE; // mark attempt
470   int fd = elevating_open(_filename, O_RDONLY);
471   if (fd < 0) {
472     log_log_error("Could not open metafile %s for reading: %s\n", _filename, strerror(errno));
473   } else {
474     _flags |= FILE_OPEN_SUCCESSFUL;
475     SimpleTokenizer tok('=', SimpleTokenizer::OVERWRITE_INPUT_STRING);
476     int line_number = 1;
477     while (ink_file_fd_readline(fd, BUF_SIZE, _buffer) > 0) {
478       tok.setString(_buffer);
479       char *t = tok.getNext();
480       if (t) {
481         if (strcmp(t, "creation_time") == 0) {
482           t = tok.getNext();
483           if (t) {
484             _creation_time = static_cast<time_t>(ink_atoi64(t));
485             _flags |= VALID_CREATION_TIME;
486           }
487         } else if (strcmp(t, "object_signature") == 0) {
488           t = tok.getNext();
489           if (t) {
490             _log_object_signature = ink_atoi64(t);
491             _flags |= VALID_SIGNATURE;
492             log_log_trace("BaseMetaInfo::_read_from_file\n"
493                           "\tfilename = %s\n"
494                           "\tsignature string = %s\n"
495                           "\tsignature value = %" PRIu64 "\n",
496                           _filename, t, _log_object_signature);
497           }
498         } else if (line_number == 1) {
499           ink_release_assert(!"no panda support");
500         }
501       }
502       ++line_number;
503     }
504     close(fd);
505   }
506 }
507 
508 /*
509  * Writes out metadata info onto disk
510  */
511 void
512 BaseMetaInfo::_write_to_file()
513 {
514   int fd = elevating_open(_filename, O_WRONLY | O_CREAT | O_TRUNC, LOGFILE_DEFAULT_PERMS);
515   if (fd < 0) {
516     log_log_error("Could not open metafile %s for writing: %s\n", _filename, strerror(errno));
517     return;
518   }
519   log_log_trace("Successfully opened metafile=%s\n", _filename);
520 
521   int n;
522   if (_flags & VALID_CREATION_TIME) {
523     log_log_trace("Writing creation time to %s\n", _filename);
524     n = snprintf(_buffer, BUF_SIZE, "creation_time = %lu\n", static_cast<unsigned long>(_creation_time));
525     // TODO modify this runtime check so that it is not an assertion
526     ink_release_assert(n <= BUF_SIZE);
527     if (write(fd, _buffer, n) == -1) {
528       log_log_trace("Could not write creation_time");
529     }
530   }
531 
532   if (_flags & VALID_SIGNATURE) {
533     log_log_trace("Writing signature to %s\n", _filename);
534     n = snprintf(_buffer, BUF_SIZE, "object_signature = %" PRIu64 "\n", _log_object_signature);
535     // TODO modify this runtime check so that it is not an assertion
536     ink_release_assert(n <= BUF_SIZE);
537     if (write(fd, _buffer, n) == -1) {
538       log_log_error("Could not write object_signature\n");
539     }
540     log_log_trace("BaseMetaInfo::_write_to_file\n"
541                   "\tfilename = %s\n"
542                   "\tsignature value = %" PRIu64 "\n"
543                   "\tsignature string = %s\n",
544                   _filename, _log_object_signature, _buffer);
545   }
546 
547   close(fd);
548 }
549 
550 /*
551  * This routine will convert a timestamp (seconds) into a short string,
552  * of the format "%Y%m%d.%Hh%Mm%Ss".
553  *
554  * Since the resulting buffer is passed in, this routine is thread-safe.
555  * Return value is the number of characters placed into the array, not
556  * including the nullptr.
557  */
558 
559 int
560 BaseLogFile::timestamp_to_str(long timestamp, char *buf, int size)
561 {
562   static const char *format_str = "%Y%m%d.%Hh%Mm%Ss";
563   struct tm res;
564   struct tm *tms;
565   tms = ink_localtime_r((const time_t *)&timestamp, &res);
566   return strftime(buf, size, format_str, tms);
567 }
568