xref: /trafficserver/src/tscore/BaseLogFile.cc (revision 0db18c7a)
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  */
BaseLogFile(const char * name)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  */
BaseLogFile(const char * name,uint64_t sig)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  */
BaseLogFile(const BaseLogFile & copy)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  */
~BaseLogFile()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
roll(long interval_start,long interval_end)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
roll()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
rolled_logfile(char * path)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
exists(const char * pathname)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
open_file(int perm)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  * @brief Close the managed log file.
344  *
345  * @note This closes the actual log file, not its metainfo.
346  *
347  * @return The result of calling fclose on the file descriptor or 0 if the file
348  * was not open. If the result is non-zero, fclose failed and errno is set
349  * appropriately.
350  */
351 int
close_file()352 BaseLogFile::close_file()
353 {
354   int ret = 0;
355   if (is_open()) {
356     log_log_trace("BaseLogFile %s is closed\n", m_name.get());
357 
358     // Both log_log_trace and fclose may set errno. Thus, keep fclose after
359     // log_log_trace so that by the time this function completes if errno was
360     // set by fclose it will remain upon function return.
361     ret       = fclose(m_fp);
362     m_fp      = nullptr;
363     m_is_init = false;
364   }
365   return ret;
366 }
367 
368 /*
369  * Changes names of the actual log file (not metainfo)
370  */
371 void
change_name(const char * new_name)372 BaseLogFile::change_name(const char *new_name)
373 {
374   m_name = ats_strdup(new_name);
375 }
376 
377 void
display(FILE * fd)378 BaseLogFile::display(FILE *fd)
379 {
380   fprintf(fd, "Logfile: %s, %s\n", get_name(), (is_open()) ? "file is open" : "file is not open");
381 }
382 
383 /*
384  * Lowest level internal logging facility for BaseLogFile
385  *
386  * Since BaseLogFiles can potentially be created before the bootstrap
387  * instance of Diags is ready, we cannot simply call something like Debug().
388  * However, we still need to log the creation of BaseLogFile, since the
389  * information is still useful. This function will print out log messages
390  * into traffic.out if we happen to be bootstrapping Diags. Since
391  * traffic_manager redirects stdout/stderr into traffic.out, that
392  * redirection is inherited by way of exec()/fork() all the way here.
393  *
394  * TODO use Debug() for non bootstrap instances
395  */
396 void
log_log(LogLogPriorityLevel priority,const char * format,...)397 BaseLogFile::log_log(LogLogPriorityLevel priority, const char *format, ...)
398 {
399   va_list args;
400 
401   const char *priority_name = nullptr;
402   FILE *output              = stdout;
403   switch (priority) {
404   case LL_Debug:
405     priority_name = "DEBUG";
406     break;
407   case LL_Note:
408     priority_name = "NOTE";
409     break;
410   case LL_Warning:
411     priority_name = "WARNING";
412     output        = stderr;
413     break;
414   case LL_Error:
415     priority_name = "ERROR";
416     output        = stderr;
417     break;
418   case LL_Fatal:
419     priority_name = "FATAL";
420     output        = stderr;
421     break;
422   default:
423     priority_name = "unknown priority";
424   }
425 
426   va_start(args, format);
427   struct timeval now;
428   double now_f;
429 
430   gettimeofday(&now, nullptr);
431   now_f = now.tv_sec + now.tv_usec / 1000000.0f;
432 
433   fprintf(output, "<%.4f> [%s]: ", now_f, priority_name);
434   vfprintf(output, format, args);
435   fflush(output);
436 
437   va_end(args);
438 }
439 
440 /****************************************************************************
441 
442   BaseMetaInfo methods
443 
444 *****************************************************************************/
445 
446 /*
447  * Given a file name (with or without the full path, but without the extension name),
448  * this function creates appends the ".meta" extension and stores it in the local
449  * variable
450  */
451 void
_build_name(const char * filename)452 BaseMetaInfo::_build_name(const char *filename)
453 {
454   int i = -1, l = 0;
455   char c;
456   while (c = filename[l], c != 0) {
457     if (c == '/') {
458       i = l;
459     }
460     ++l;
461   }
462 
463   // 7 = 1 (dot at beginning) + 5 (".meta") + 1 (null terminating)
464   //
465   _filename = static_cast<char *>(ats_malloc(l + 7));
466 
467   if (i < 0) {
468     ink_string_concatenate_strings(_filename, ".", filename, ".meta", nullptr);
469   } else {
470     memcpy(_filename, filename, i + 1);
471     ink_string_concatenate_strings(&_filename[i + 1], ".", &filename[i + 1], ".meta", nullptr);
472   }
473 }
474 
475 /*
476  * Reads in meta info into the local variables
477  */
478 void
_read_from_file()479 BaseMetaInfo::_read_from_file()
480 {
481   _flags |= DATA_FROM_METAFILE; // mark attempt
482   int fd = elevating_open(_filename, O_RDONLY);
483   if (fd < 0) {
484     log_log_error("Could not open metafile %s for reading: %s\n", _filename, strerror(errno));
485   } else {
486     _flags |= FILE_OPEN_SUCCESSFUL;
487     SimpleTokenizer tok('=', SimpleTokenizer::OVERWRITE_INPUT_STRING);
488     int line_number = 1;
489     while (ink_file_fd_readline(fd, BUF_SIZE, _buffer) > 0) {
490       tok.setString(_buffer);
491       char *t = tok.getNext();
492       if (t) {
493         if (strcmp(t, "creation_time") == 0) {
494           t = tok.getNext();
495           if (t) {
496             _creation_time = static_cast<time_t>(ink_atoi64(t));
497             _flags |= VALID_CREATION_TIME;
498           }
499         } else if (strcmp(t, "object_signature") == 0) {
500           t = tok.getNext();
501           if (t) {
502             _log_object_signature = ink_atoi64(t);
503             _flags |= VALID_SIGNATURE;
504             log_log_trace("BaseMetaInfo::_read_from_file\n"
505                           "\tfilename = %s\n"
506                           "\tsignature string = %s\n"
507                           "\tsignature value = %" PRIu64 "\n",
508                           _filename, t, _log_object_signature);
509           }
510         } else if (line_number == 1) {
511           ink_release_assert(!"no panda support");
512         }
513       }
514       ++line_number;
515     }
516     close(fd);
517   }
518 }
519 
520 /*
521  * Writes out metadata info onto disk
522  */
523 void
_write_to_file()524 BaseMetaInfo::_write_to_file()
525 {
526   int fd = elevating_open(_filename, O_WRONLY | O_CREAT | O_TRUNC, LOGFILE_DEFAULT_PERMS);
527   if (fd < 0) {
528     log_log_error("Could not open metafile %s for writing: %s\n", _filename, strerror(errno));
529     return;
530   }
531   log_log_trace("Successfully opened metafile=%s\n", _filename);
532 
533   int n;
534   if (_flags & VALID_CREATION_TIME) {
535     log_log_trace("Writing creation time to %s\n", _filename);
536     n = snprintf(_buffer, BUF_SIZE, "creation_time = %lu\n", static_cast<unsigned long>(_creation_time));
537     // TODO modify this runtime check so that it is not an assertion
538     ink_release_assert(n <= BUF_SIZE);
539     if (write(fd, _buffer, n) == -1) {
540       log_log_trace("Could not write creation_time");
541     }
542   }
543 
544   if (_flags & VALID_SIGNATURE) {
545     log_log_trace("Writing signature to %s\n", _filename);
546     n = snprintf(_buffer, BUF_SIZE, "object_signature = %" PRIu64 "\n", _log_object_signature);
547     // TODO modify this runtime check so that it is not an assertion
548     ink_release_assert(n <= BUF_SIZE);
549     if (write(fd, _buffer, n) == -1) {
550       log_log_error("Could not write object_signature\n");
551     }
552     log_log_trace("BaseMetaInfo::_write_to_file\n"
553                   "\tfilename = %s\n"
554                   "\tsignature value = %" PRIu64 "\n"
555                   "\tsignature string = %s\n",
556                   _filename, _log_object_signature, _buffer);
557   }
558 
559   close(fd);
560 }
561 
562 /*
563  * This routine will convert a timestamp (seconds) into a short string,
564  * of the format "%Y%m%d.%Hh%Mm%Ss".
565  *
566  * Since the resulting buffer is passed in, this routine is thread-safe.
567  * Return value is the number of characters placed into the array, not
568  * including the nullptr.
569  */
570 
571 int
timestamp_to_str(long timestamp,char * buf,int size)572 BaseLogFile::timestamp_to_str(long timestamp, char *buf, int size)
573 {
574   static const char *format_str = "%Y%m%d.%Hh%Mm%Ss";
575   struct tm res;
576   struct tm *tms;
577   tms = ink_localtime_r((const time_t *)&timestamp, &res);
578   return strftime(buf, size, format_str, tms);
579 }
580