]> git.ipfire.org Git - thirdparty/cups.git/blob - scheduler/log.c
Merge changes from CUPS 1.4svn-r7696.
[thirdparty/cups.git] / scheduler / log.c
1 /*
2 * "$Id: log.c 7697 2008-06-27 15:56:00Z mike $"
3 *
4 * Log file routines for the Common UNIX Printing System (CUPS).
5 *
6 * Copyright 2007-2008 by Apple Inc.
7 * Copyright 1997-2007 by Easy Software Products, all rights reserved.
8 *
9 * These coded instructions, statements, and computer programs are the
10 * property of Apple Inc. and are protected by Federal copyright
11 * law. Distribution and use rights are outlined in the file "LICENSE.txt"
12 * which should have been included with this file. If this file is
13 * file is missing or damaged, see the license at "http://www.cups.org/".
14 *
15 * Contents:
16 *
17 * cupsdGetDateTime() - Returns a pointer to a date/time string.
18 * cupsdLogGSSMessage() - Log a GSSAPI error...
19 * cupsdLogJob() - Log a job message.
20 * cupsdLogMessage() - Log a message to the error log file.
21 * cupsdLogPage() - Log a page to the page log file.
22 * cupsdLogRequest() - Log an HTTP request in Common Log Format.
23 * cupsdWriteErrorLog() - Write a line to the ErrorLog.
24 * check_log_file() - Open/rotate a log file if it needs it.
25 * format_log_line() - Format a line for a log file.
26 */
27
28 /*
29 * Include necessary headers...
30 */
31
32 #include "cupsd.h"
33 #include <stdarg.h>
34 #include <syslog.h>
35
36
37 /*
38 * Local globals...
39 */
40
41 static int log_linesize = 0; /* Size of line for output file */
42 static char *log_line = NULL; /* Line for output file */
43
44
45 /*
46 * Local functions...
47 */
48
49 static int check_log_file(cups_file_t **lf, const char *logname);
50 static char *format_log_line(const char *message, va_list ap);
51
52
53 /*
54 * 'cupsdGetDateTime()' - Returns a pointer to a date/time string.
55 */
56
57 char * /* O - Date/time string */
58 cupsdGetDateTime(time_t t) /* I - Time value */
59 {
60 struct tm *date; /* Date/time value */
61 static time_t last_time = -1; /* Last time value */
62 static char s[1024]; /* Date/time string */
63 static const char * const months[12] =/* Months */
64 {
65 "Jan",
66 "Feb",
67 "Mar",
68 "Apr",
69 "May",
70 "Jun",
71 "Jul",
72 "Aug",
73 "Sep",
74 "Oct",
75 "Nov",
76 "Dec"
77 };
78
79
80 /*
81 * Make sure we have a valid time...
82 */
83
84 if (!t)
85 t = time(NULL);
86
87 if (t != last_time)
88 {
89 last_time = t;
90
91 /*
92 * Get the date and time from the UNIX time value, and then format it
93 * into a string. Note that we *can't* use the strftime() function since
94 * it is localized and will seriously confuse automatic programs if the
95 * month names are in the wrong language!
96 *
97 * Also, we use the "timezone" variable that contains the current timezone
98 * offset from GMT in seconds so that we are reporting local time in the
99 * log files. If you want GMT, set the TZ environment variable accordingly
100 * before starting the scheduler.
101 *
102 * (*BSD and Darwin store the timezone offset in the tm structure)
103 */
104
105 date = localtime(&t);
106
107 snprintf(s, sizeof(s), "[%02d/%s/%04d:%02d:%02d:%02d %+03ld%02ld]",
108 date->tm_mday, months[date->tm_mon], 1900 + date->tm_year,
109 date->tm_hour, date->tm_min, date->tm_sec,
110 #ifdef HAVE_TM_GMTOFF
111 date->tm_gmtoff / 3600, (date->tm_gmtoff / 60) % 60);
112 #else
113 timezone / 3600, (timezone / 60) % 60);
114 #endif /* HAVE_TM_GMTOFF */
115 }
116
117 return (s);
118 }
119
120
121 #ifdef HAVE_GSSAPI
122 /*
123 * 'cupsdLogGSSMessage()' - Log a GSSAPI error...
124 */
125
126 int /* O - 1 on success, 0 on error */
127 cupsdLogGSSMessage(
128 int level, /* I - Log level */
129 int major_status, /* I - Major GSSAPI status */
130 int minor_status, /* I - Minor GSSAPI status */
131 const char *message, /* I - printf-style message string */
132 ...) /* I - Additional args as needed */
133 {
134 OM_uint32 err_major_status, /* Major status code for display */
135 err_minor_status; /* Minor status code for display */
136 OM_uint32 msg_ctx; /* Message context */
137 gss_buffer_desc major_status_string = GSS_C_EMPTY_BUFFER,
138 /* Major status message */
139 minor_status_string = GSS_C_EMPTY_BUFFER;
140 /* Minor status message */
141 int ret; /* Return value */
142
143
144 msg_ctx = 0;
145 err_major_status = gss_display_status(&err_minor_status,
146 major_status,
147 GSS_C_GSS_CODE,
148 GSS_C_NO_OID,
149 &msg_ctx,
150 &major_status_string);
151
152 if (!GSS_ERROR(err_major_status))
153 err_major_status = gss_display_status(&err_minor_status,
154 minor_status,
155 GSS_C_MECH_CODE,
156 GSS_C_NULL_OID,
157 &msg_ctx,
158 &minor_status_string);
159
160 ret = cupsdLogMessage(level, "%s: %s, %s", message,
161 (char *)major_status_string.value,
162 (char *)minor_status_string.value);
163 gss_release_buffer(&err_minor_status, &major_status_string);
164 gss_release_buffer(&err_minor_status, &minor_status_string);
165
166 return (ret);
167 }
168 #endif /* HAVE_GSSAPI */
169
170
171 /*
172 * 'cupsdLogJob()' - Log a job message.
173 */
174
175 int /* O - 1 on success, 0 on error */
176 cupsdLogJob(cupsd_job_t *job, /* I - Job */
177 int level, /* I - Log level */
178 const char *message, /* I - Printf-style message string */
179 ...) /* I - Additional arguments as needed */
180 {
181 va_list ap; /* Argument pointer */
182 char jobmsg[1024], /* Format string for job message */
183 *line; /* Message line */
184
185
186 /*
187 * See if we want to log this message...
188 */
189
190 if (TestConfigFile || level > LogLevel || !ErrorLog)
191 return (1);
192
193 if (level > LogLevel || !ErrorLog)
194 return (1);
195
196 /*
197 * Format and write the log message...
198 */
199
200 snprintf(jobmsg, sizeof(jobmsg), "[Job %d] %s", job->id, message);
201
202 va_start(ap, message);
203 line = format_log_line(jobmsg, ap);
204 va_end(ap);
205
206 if (line)
207 return (cupsdWriteErrorLog(level, line));
208 else
209 return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
210 "Unable to allocate memory for log line!"));
211 }
212
213
214 /*
215 * 'cupsdLogMessage()' - Log a message to the error log file.
216 */
217
218 int /* O - 1 on success, 0 on error */
219 cupsdLogMessage(int level, /* I - Log level */
220 const char *message, /* I - printf-style message string */
221 ...) /* I - Additional args as needed */
222 {
223 va_list ap; /* Argument pointer */
224 char *line; /* Message line */
225
226
227 /*
228 * See if we want to log this message...
229 */
230
231 if (TestConfigFile)
232 {
233 if (level <= CUPSD_LOG_WARN)
234 {
235 va_start(ap, message);
236 vfprintf(stderr, message, ap);
237 putc('\n', stderr);
238 va_end(ap);
239 }
240
241 return (1);
242 }
243
244 if (level > LogLevel || !ErrorLog)
245 return (1);
246
247 /*
248 * Format and write the log message...
249 */
250
251 va_start(ap, message);
252 line = format_log_line(message, ap);
253 va_end(ap);
254
255 if (line)
256 return (cupsdWriteErrorLog(level, line));
257 else
258 return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
259 "Unable to allocate memory for log line!"));
260 }
261
262
263 /*
264 * 'cupsdLogPage()' - Log a page to the page log file.
265 */
266
267 int /* O - 1 on success, 0 on error */
268 cupsdLogPage(cupsd_job_t *job, /* I - Job being printed */
269 const char *page) /* I - Page being printed */
270 {
271 int i; /* Looping var */
272 char buffer[2048], /* Buffer for page log */
273 *bufptr, /* Pointer into buffer */
274 name[256]; /* Attribute name */
275 const char *format, /* Pointer into PageLogFormat */
276 *nameend; /* End of attribute name */
277 ipp_attribute_t *attr; /* Current attribute */
278 int number; /* Page number */
279 char copies[256]; /* Number of copies */
280
281
282 /*
283 * Format the line going into the page log...
284 */
285
286 if (!PageLogFormat)
287 return (1);
288
289 number = 1;
290 strcpy(copies, "1");
291 sscanf(page, "%d%255s", &number, copies);
292
293 for (format = PageLogFormat, bufptr = buffer; *format; format ++)
294 {
295 if (*format == '%')
296 {
297 format ++;
298
299 switch (*format)
300 {
301 case '%' : /* Literal % */
302 if (bufptr < (buffer + sizeof(buffer) - 1))
303 *bufptr++ = '%';
304 break;
305
306 case 'p' : /* Printer name */
307 strlcpy(bufptr, job->printer->name,
308 sizeof(buffer) - (bufptr - buffer));
309 bufptr += strlen(bufptr);
310 break;
311
312 case 'j' : /* Job ID */
313 snprintf(bufptr, sizeof(buffer) - (bufptr - buffer), "%d", job->id);
314 bufptr += strlen(bufptr);
315 break;
316
317 case 'u' : /* Username */
318 strlcpy(bufptr, job->username ? job->username : "-",
319 sizeof(buffer) - (bufptr - buffer));
320 bufptr += strlen(bufptr);
321 break;
322
323 case 'T' : /* Date and time */
324 strlcpy(bufptr, cupsdGetDateTime(time(NULL)),
325 sizeof(buffer) - (bufptr - buffer));
326 bufptr += strlen(bufptr);
327 break;
328
329 case 'P' : /* Page number */
330 snprintf(bufptr, sizeof(buffer) - (bufptr - buffer), "%d", number);
331 bufptr += strlen(bufptr);
332 break;
333
334 case 'C' : /* Number of copies */
335 strlcpy(bufptr, copies, sizeof(buffer) - (bufptr - buffer));
336 bufptr += strlen(bufptr);
337 break;
338
339 case '{' : /* {attribute} */
340 if ((nameend = strchr(format, '}')) != NULL &&
341 (nameend - format - 2) < (sizeof(name) - 1))
342 {
343 /*
344 * Pull the name from inside the brackets...
345 */
346
347 memcpy(name, format + 1, nameend - format - 1);
348 name[nameend - format - 1] = '\0';
349
350 format = nameend;
351
352 if ((attr = ippFindAttribute(job->attrs, name,
353 IPP_TAG_ZERO)) != NULL)
354 {
355 /*
356 * Add the attribute value...
357 */
358
359 for (i = 0;
360 i < attr->num_values &&
361 bufptr < (buffer + sizeof(buffer) - 1);
362 i ++)
363 {
364 if (i)
365 *bufptr++ = ',';
366
367 switch (attr->value_tag)
368 {
369 case IPP_TAG_INTEGER :
370 case IPP_TAG_ENUM :
371 snprintf(bufptr, sizeof(buffer) - (bufptr - buffer),
372 "%d", attr->values[i].integer);
373 bufptr += strlen(bufptr);
374 break;
375
376 case IPP_TAG_BOOLEAN :
377 snprintf(bufptr, sizeof(buffer) - (bufptr - buffer),
378 "%d", attr->values[i].boolean);
379 bufptr += strlen(bufptr);
380 break;
381
382 case IPP_TAG_TEXTLANG :
383 case IPP_TAG_NAMELANG :
384 case IPP_TAG_TEXT :
385 case IPP_TAG_NAME :
386 case IPP_TAG_KEYWORD :
387 case IPP_TAG_URI :
388 case IPP_TAG_URISCHEME :
389 case IPP_TAG_CHARSET :
390 case IPP_TAG_LANGUAGE :
391 case IPP_TAG_MIMETYPE :
392 strlcpy(bufptr, attr->values[i].string.text,
393 sizeof(buffer) - (bufptr - buffer));
394 bufptr += strlen(bufptr);
395 break;
396
397 default :
398 strlcpy(bufptr, "???",
399 sizeof(buffer) - (bufptr - buffer));
400 bufptr += strlen(bufptr);
401 break;
402 }
403 }
404 }
405 else if (bufptr < (buffer + sizeof(buffer) - 1))
406 *bufptr++ = '-';
407 break;
408 }
409
410 default :
411 if (bufptr < (buffer + sizeof(buffer) - 2))
412 {
413 *bufptr++ = '%';
414 *bufptr++ = *format;
415 }
416 break;
417 }
418 }
419 else if (bufptr < (buffer + sizeof(buffer) - 1))
420 *bufptr++ = *format;
421 }
422
423 *bufptr = '\0';
424
425 #ifdef HAVE_VSYSLOG
426 /*
427 * See if we are logging pages via syslog...
428 */
429
430 if (!strcmp(PageLog, "syslog"))
431 {
432 syslog(LOG_INFO, "%s", buffer);
433
434 return (1);
435 }
436 #endif /* HAVE_VSYSLOG */
437
438 /*
439 * Not using syslog; check the log file...
440 */
441
442 if (!check_log_file(&PageFile, PageLog))
443 return (0);
444
445 /*
446 * Print a page log entry of the form:
447 *
448 * printer user job-id [DD/MON/YYYY:HH:MM:SS +TTTT] page num-copies \
449 * billing hostname
450 */
451
452 cupsFilePrintf(PageFile, "%s\n", buffer);
453 cupsFileFlush(PageFile);
454
455 return (1);
456 }
457
458
459 /*
460 * 'cupsdLogRequest()' - Log an HTTP request in Common Log Format.
461 */
462
463 int /* O - 1 on success, 0 on error */
464 cupsdLogRequest(cupsd_client_t *con, /* I - Request to log */
465 http_status_t code) /* I - Response code */
466 {
467 char temp[2048]; /* Temporary string for URI */
468 static const char * const states[] = /* HTTP client states... */
469 {
470 "WAITING",
471 "OPTIONS",
472 "GET",
473 "GET",
474 "HEAD",
475 "POST",
476 "POST",
477 "POST",
478 "PUT",
479 "PUT",
480 "DELETE",
481 "TRACE",
482 "CLOSE",
483 "STATUS"
484 };
485
486
487 #ifdef HAVE_VSYSLOG
488 /*
489 * See if we are logging accesses via syslog...
490 */
491
492 if (!strcmp(AccessLog, "syslog"))
493 {
494 syslog(LOG_INFO,
495 "REQUEST %s - %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
496 con->http.hostname, con->username[0] != '\0' ? con->username : "-",
497 states[con->operation], _httpEncodeURI(temp, con->uri, sizeof(temp)),
498 con->http.version / 100, con->http.version % 100,
499 code, CUPS_LLCAST con->bytes,
500 con->request ?
501 ippOpString(con->request->request.op.operation_id) : "-",
502 con->response ?
503 ippErrorString(con->response->request.status.status_code) : "-");
504
505 return (1);
506 }
507 #endif /* HAVE_VSYSLOG */
508
509 /*
510 * Not using syslog; check the log file...
511 */
512
513 if (!check_log_file(&AccessFile, AccessLog))
514 return (0);
515
516 /*
517 * Write a log of the request in "common log format"...
518 */
519
520 cupsFilePrintf(AccessFile,
521 "%s - %s %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
522 con->http.hostname, con->username[0] != '\0' ? con->username : "-",
523 cupsdGetDateTime(con->start), states[con->operation],
524 _httpEncodeURI(temp, con->uri, sizeof(temp)),
525 con->http.version / 100, con->http.version % 100,
526 code, CUPS_LLCAST con->bytes,
527 con->request ?
528 ippOpString(con->request->request.op.operation_id) : "-",
529 con->response ?
530 ippErrorString(con->response->request.status.status_code) :
531 "-");
532
533 cupsFileFlush(AccessFile);
534
535 return (1);
536 }
537
538
539 /*
540 * 'cupsdWriteErrorLog()' - Write a line to the ErrorLog.
541 */
542
543 int /* O - 1 on success, 0 on failure */
544 cupsdWriteErrorLog(int level, /* I - Log level */
545 const char *message) /* I - Message string */
546 {
547 static const char levels[] = /* Log levels... */
548 {
549 ' ',
550 'X',
551 'A',
552 'C',
553 'E',
554 'W',
555 'N',
556 'I',
557 'D',
558 'd'
559 };
560 #ifdef HAVE_VSYSLOG
561 static const int syslevels[] = /* SYSLOG levels... */
562 {
563 0,
564 LOG_EMERG,
565 LOG_ALERT,
566 LOG_CRIT,
567 LOG_ERR,
568 LOG_WARNING,
569 LOG_NOTICE,
570 LOG_INFO,
571 LOG_DEBUG,
572 LOG_DEBUG
573 };
574 #endif /* HAVE_VSYSLOG */
575
576
577 #ifdef HAVE_VSYSLOG
578 /*
579 * See if we are logging errors via syslog...
580 */
581
582 if (!strcmp(ErrorLog, "syslog"))
583 {
584 syslog(syslevels[level], "%s", message);
585 return (1);
586 }
587 #endif /* HAVE_VSYSLOG */
588
589 /*
590 * Not using syslog; check the log file...
591 */
592
593 if (!check_log_file(&ErrorFile, ErrorLog))
594 return (0);
595
596 /*
597 * Write the log message...
598 */
599
600 cupsFilePrintf(ErrorFile, "%c %s %s\n", levels[level],
601 cupsdGetDateTime(time(NULL)), message);
602 cupsFileFlush(ErrorFile);
603
604 return (1);
605 }
606
607
608 /*
609 * 'check_log_file()' - Open/rotate a log file if it needs it.
610 */
611
612 static int /* O - 1 if log file open */
613 check_log_file(cups_file_t **lf, /* IO - Log file */
614 const char *logname) /* I - Log filename */
615 {
616 char backname[1024], /* Backup log filename */
617 filename[1024], /* Formatted log filename */
618 *ptr; /* Pointer into filename */
619 const char *logptr; /* Pointer into log filename */
620
621
622 /*
623 * See if we have a log file to check...
624 */
625
626 if (!lf || !logname || !logname[0])
627 return (1);
628
629 /*
630 * Format the filename as needed...
631 */
632
633 if (!*lf ||
634 (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
635 MaxLogSize > 0))
636 {
637 /*
638 * Handle format strings...
639 */
640
641 filename[sizeof(filename) - 1] = '\0';
642
643 if (logname[0] != '/')
644 {
645 strlcpy(filename, ServerRoot, sizeof(filename));
646 strlcat(filename, "/", sizeof(filename));
647 }
648 else
649 filename[0] = '\0';
650
651 for (logptr = logname, ptr = filename + strlen(filename);
652 *logptr && ptr < (filename + sizeof(filename) - 1);
653 logptr ++)
654 if (*logptr == '%')
655 {
656 /*
657 * Format spec...
658 */
659
660 logptr ++;
661 if (*logptr == 's')
662 {
663 /*
664 * Insert the server name...
665 */
666
667 strlcpy(ptr, ServerName, sizeof(filename) - (ptr - filename));
668 ptr += strlen(ptr);
669 }
670 else
671 {
672 /*
673 * Otherwise just insert the character...
674 */
675
676 *ptr++ = *logptr;
677 }
678 }
679 else
680 *ptr++ = *logptr;
681
682 *ptr = '\0';
683 }
684
685 /*
686 * See if the log file is open...
687 */
688
689 if (!*lf)
690 {
691 /*
692 * Nope, open the log file...
693 */
694
695 if ((*lf = cupsFileOpen(filename, "a")) == NULL)
696 {
697 /*
698 * If the file is in CUPS_LOGDIR then try to create a missing directory...
699 */
700
701 if (!strncmp(filename, CUPS_LOGDIR, strlen(CUPS_LOGDIR)))
702 {
703 cupsdCheckPermissions(CUPS_LOGDIR, NULL, 0755, RunUser, Group, 1, -1);
704
705 *lf = cupsFileOpen(filename, "a");
706 }
707
708 if (*lf == NULL)
709 {
710 syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename,
711 strerror(errno));
712 return (0);
713 }
714 }
715
716 if (strncmp(filename, "/dev/", 5))
717 {
718 /*
719 * Change ownership and permissions of non-device logs...
720 */
721
722 fchown(cupsFileNumber(*lf), RunUser, Group);
723 fchmod(cupsFileNumber(*lf), LogFilePerm);
724 }
725 }
726
727 /*
728 * Do we need to rotate the log?
729 */
730
731 if (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
732 MaxLogSize > 0)
733 {
734 /*
735 * Rotate log file...
736 */
737
738 cupsFileClose(*lf);
739
740 strcpy(backname, filename);
741 strlcat(backname, ".O", sizeof(backname));
742
743 unlink(backname);
744 rename(filename, backname);
745
746 if ((*lf = cupsFileOpen(filename, "a")) == NULL)
747 {
748 syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename,
749 strerror(errno));
750
751 return (0);
752 }
753
754 /*
755 * Change ownership and permissions of non-device logs...
756 */
757
758 fchown(cupsFileNumber(*lf), RunUser, Group);
759 fchmod(cupsFileNumber(*lf), LogFilePerm);
760 }
761
762 return (1);
763 }
764
765
766 /*
767 * 'format_log_line()' - Format a line for a log file.
768 *
769 * This function resizes a global string buffer as needed. Each call returns
770 * a pointer to this buffer, so the contents are only good until the next call
771 * to format_log_line()...
772 */
773
774 static char * /* O - Text or NULL on error */
775 format_log_line(const char *message, /* I - Printf-style format string */
776 va_list ap) /* I - Argument list */
777 {
778 int len; /* Length of formatted line */
779
780
781 /*
782 * Allocate the line buffer as needed...
783 */
784
785 if (!log_linesize)
786 {
787 log_linesize = 8192;
788 log_line = malloc(log_linesize);
789
790 if (!log_line)
791 return (NULL);
792 }
793
794 /*
795 * Format the log message...
796 */
797
798 len = vsnprintf(log_line, log_linesize, message, ap);
799
800 /*
801 * Resize the buffer as needed...
802 */
803
804 if (len >= log_linesize)
805 {
806 char *temp; /* Temporary string pointer */
807
808
809 len ++;
810
811 if (len < 8192)
812 len = 8192;
813 else if (len > 65536)
814 len = 65536;
815
816 temp = realloc(log_line, len);
817
818 if (temp)
819 {
820 log_line = temp;
821 log_linesize = len;
822 }
823
824 len = vsnprintf(log_line, log_linesize, message, ap);
825 }
826
827 return (log_line);
828 }
829
830
831 /*
832 * End of "$Id: log.c 7697 2008-06-27 15:56:00Z mike $".
833 */