]> git.ipfire.org Git - thirdparty/cups.git/blob - scheduler/log.c
Merge changes from CUPS 1.4svn-r7715.
[thirdparty/cups.git] / scheduler / log.c
1 /*
2 * "$Id: log.c 7699 2008-06-27 20:44:23Z 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 /*
194 * Format and write the log message...
195 */
196
197 snprintf(jobmsg, sizeof(jobmsg), "[Job %d] %s", job->id, message);
198
199 va_start(ap, message);
200 line = format_log_line(jobmsg, ap);
201 va_end(ap);
202
203 if (line)
204 return (cupsdWriteErrorLog(level, line));
205 else
206 return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
207 "Unable to allocate memory for log line!"));
208 }
209
210
211 /*
212 * 'cupsdLogMessage()' - Log a message to the error log file.
213 */
214
215 int /* O - 1 on success, 0 on error */
216 cupsdLogMessage(int level, /* I - Log level */
217 const char *message, /* I - printf-style message string */
218 ...) /* I - Additional args as needed */
219 {
220 va_list ap; /* Argument pointer */
221 char *line; /* Message line */
222
223
224 /*
225 * See if we want to log this message...
226 */
227
228 if (TestConfigFile)
229 {
230 if (level <= CUPSD_LOG_WARN)
231 {
232 va_start(ap, message);
233 vfprintf(stderr, message, ap);
234 putc('\n', stderr);
235 va_end(ap);
236 }
237
238 return (1);
239 }
240
241 if (level > LogLevel || !ErrorLog)
242 return (1);
243
244 /*
245 * Format and write the log message...
246 */
247
248 va_start(ap, message);
249 line = format_log_line(message, ap);
250 va_end(ap);
251
252 if (line)
253 return (cupsdWriteErrorLog(level, line));
254 else
255 return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
256 "Unable to allocate memory for log line!"));
257 }
258
259
260 /*
261 * 'cupsdLogPage()' - Log a page to the page log file.
262 */
263
264 int /* O - 1 on success, 0 on error */
265 cupsdLogPage(cupsd_job_t *job, /* I - Job being printed */
266 const char *page) /* I - Page being printed */
267 {
268 int i; /* Looping var */
269 char buffer[2048], /* Buffer for page log */
270 *bufptr, /* Pointer into buffer */
271 name[256]; /* Attribute name */
272 const char *format, /* Pointer into PageLogFormat */
273 *nameend; /* End of attribute name */
274 ipp_attribute_t *attr; /* Current attribute */
275 int number; /* Page number */
276 char copies[256]; /* Number of copies */
277
278
279 /*
280 * Format the line going into the page log...
281 */
282
283 if (!PageLogFormat)
284 return (1);
285
286 number = 1;
287 strcpy(copies, "1");
288 sscanf(page, "%d%255s", &number, copies);
289
290 for (format = PageLogFormat, bufptr = buffer; *format; format ++)
291 {
292 if (*format == '%')
293 {
294 format ++;
295
296 switch (*format)
297 {
298 case '%' : /* Literal % */
299 if (bufptr < (buffer + sizeof(buffer) - 1))
300 *bufptr++ = '%';
301 break;
302
303 case 'p' : /* Printer name */
304 strlcpy(bufptr, job->printer->name,
305 sizeof(buffer) - (bufptr - buffer));
306 bufptr += strlen(bufptr);
307 break;
308
309 case 'j' : /* Job ID */
310 snprintf(bufptr, sizeof(buffer) - (bufptr - buffer), "%d", job->id);
311 bufptr += strlen(bufptr);
312 break;
313
314 case 'u' : /* Username */
315 strlcpy(bufptr, job->username ? job->username : "-",
316 sizeof(buffer) - (bufptr - buffer));
317 bufptr += strlen(bufptr);
318 break;
319
320 case 'T' : /* Date and time */
321 strlcpy(bufptr, cupsdGetDateTime(time(NULL)),
322 sizeof(buffer) - (bufptr - buffer));
323 bufptr += strlen(bufptr);
324 break;
325
326 case 'P' : /* Page number */
327 snprintf(bufptr, sizeof(buffer) - (bufptr - buffer), "%d", number);
328 bufptr += strlen(bufptr);
329 break;
330
331 case 'C' : /* Number of copies */
332 strlcpy(bufptr, copies, sizeof(buffer) - (bufptr - buffer));
333 bufptr += strlen(bufptr);
334 break;
335
336 case '{' : /* {attribute} */
337 if ((nameend = strchr(format, '}')) != NULL &&
338 (nameend - format - 2) < (sizeof(name) - 1))
339 {
340 /*
341 * Pull the name from inside the brackets...
342 */
343
344 memcpy(name, format + 1, nameend - format - 1);
345 name[nameend - format - 1] = '\0';
346
347 format = nameend;
348
349 if ((attr = ippFindAttribute(job->attrs, name,
350 IPP_TAG_ZERO)) != NULL)
351 {
352 /*
353 * Add the attribute value...
354 */
355
356 for (i = 0;
357 i < attr->num_values &&
358 bufptr < (buffer + sizeof(buffer) - 1);
359 i ++)
360 {
361 if (i)
362 *bufptr++ = ',';
363
364 switch (attr->value_tag)
365 {
366 case IPP_TAG_INTEGER :
367 case IPP_TAG_ENUM :
368 snprintf(bufptr, sizeof(buffer) - (bufptr - buffer),
369 "%d", attr->values[i].integer);
370 bufptr += strlen(bufptr);
371 break;
372
373 case IPP_TAG_BOOLEAN :
374 snprintf(bufptr, sizeof(buffer) - (bufptr - buffer),
375 "%d", attr->values[i].boolean);
376 bufptr += strlen(bufptr);
377 break;
378
379 case IPP_TAG_TEXTLANG :
380 case IPP_TAG_NAMELANG :
381 case IPP_TAG_TEXT :
382 case IPP_TAG_NAME :
383 case IPP_TAG_KEYWORD :
384 case IPP_TAG_URI :
385 case IPP_TAG_URISCHEME :
386 case IPP_TAG_CHARSET :
387 case IPP_TAG_LANGUAGE :
388 case IPP_TAG_MIMETYPE :
389 strlcpy(bufptr, attr->values[i].string.text,
390 sizeof(buffer) - (bufptr - buffer));
391 bufptr += strlen(bufptr);
392 break;
393
394 default :
395 strlcpy(bufptr, "???",
396 sizeof(buffer) - (bufptr - buffer));
397 bufptr += strlen(bufptr);
398 break;
399 }
400 }
401 }
402 else if (bufptr < (buffer + sizeof(buffer) - 1))
403 *bufptr++ = '-';
404 break;
405 }
406
407 default :
408 if (bufptr < (buffer + sizeof(buffer) - 2))
409 {
410 *bufptr++ = '%';
411 *bufptr++ = *format;
412 }
413 break;
414 }
415 }
416 else if (bufptr < (buffer + sizeof(buffer) - 1))
417 *bufptr++ = *format;
418 }
419
420 *bufptr = '\0';
421
422 #ifdef HAVE_VSYSLOG
423 /*
424 * See if we are logging pages via syslog...
425 */
426
427 if (!strcmp(PageLog, "syslog"))
428 {
429 syslog(LOG_INFO, "%s", buffer);
430
431 return (1);
432 }
433 #endif /* HAVE_VSYSLOG */
434
435 /*
436 * Not using syslog; check the log file...
437 */
438
439 if (!check_log_file(&PageFile, PageLog))
440 return (0);
441
442 /*
443 * Print a page log entry of the form:
444 *
445 * printer user job-id [DD/MON/YYYY:HH:MM:SS +TTTT] page num-copies \
446 * billing hostname
447 */
448
449 cupsFilePrintf(PageFile, "%s\n", buffer);
450 cupsFileFlush(PageFile);
451
452 return (1);
453 }
454
455
456 /*
457 * 'cupsdLogRequest()' - Log an HTTP request in Common Log Format.
458 */
459
460 int /* O - 1 on success, 0 on error */
461 cupsdLogRequest(cupsd_client_t *con, /* I - Request to log */
462 http_status_t code) /* I - Response code */
463 {
464 char temp[2048]; /* Temporary string for URI */
465 static const char * const states[] = /* HTTP client states... */
466 {
467 "WAITING",
468 "OPTIONS",
469 "GET",
470 "GET",
471 "HEAD",
472 "POST",
473 "POST",
474 "POST",
475 "PUT",
476 "PUT",
477 "DELETE",
478 "TRACE",
479 "CLOSE",
480 "STATUS"
481 };
482
483
484 #ifdef HAVE_VSYSLOG
485 /*
486 * See if we are logging accesses via syslog...
487 */
488
489 if (!strcmp(AccessLog, "syslog"))
490 {
491 syslog(LOG_INFO,
492 "REQUEST %s - %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
493 con->http.hostname, con->username[0] != '\0' ? con->username : "-",
494 states[con->operation], _httpEncodeURI(temp, con->uri, sizeof(temp)),
495 con->http.version / 100, con->http.version % 100,
496 code, CUPS_LLCAST con->bytes,
497 con->request ?
498 ippOpString(con->request->request.op.operation_id) : "-",
499 con->response ?
500 ippErrorString(con->response->request.status.status_code) : "-");
501
502 return (1);
503 }
504 #endif /* HAVE_VSYSLOG */
505
506 /*
507 * Not using syslog; check the log file...
508 */
509
510 if (!check_log_file(&AccessFile, AccessLog))
511 return (0);
512
513 /*
514 * Write a log of the request in "common log format"...
515 */
516
517 cupsFilePrintf(AccessFile,
518 "%s - %s %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
519 con->http.hostname, con->username[0] != '\0' ? con->username : "-",
520 cupsdGetDateTime(con->start), states[con->operation],
521 _httpEncodeURI(temp, con->uri, sizeof(temp)),
522 con->http.version / 100, con->http.version % 100,
523 code, CUPS_LLCAST con->bytes,
524 con->request ?
525 ippOpString(con->request->request.op.operation_id) : "-",
526 con->response ?
527 ippErrorString(con->response->request.status.status_code) :
528 "-");
529
530 cupsFileFlush(AccessFile);
531
532 return (1);
533 }
534
535
536 /*
537 * 'cupsdWriteErrorLog()' - Write a line to the ErrorLog.
538 */
539
540 int /* O - 1 on success, 0 on failure */
541 cupsdWriteErrorLog(int level, /* I - Log level */
542 const char *message) /* I - Message string */
543 {
544 static const char levels[] = /* Log levels... */
545 {
546 ' ',
547 'X',
548 'A',
549 'C',
550 'E',
551 'W',
552 'N',
553 'I',
554 'D',
555 'd'
556 };
557 #ifdef HAVE_VSYSLOG
558 static const int syslevels[] = /* SYSLOG levels... */
559 {
560 0,
561 LOG_EMERG,
562 LOG_ALERT,
563 LOG_CRIT,
564 LOG_ERR,
565 LOG_WARNING,
566 LOG_NOTICE,
567 LOG_INFO,
568 LOG_DEBUG,
569 LOG_DEBUG
570 };
571 #endif /* HAVE_VSYSLOG */
572
573
574 #ifdef HAVE_VSYSLOG
575 /*
576 * See if we are logging errors via syslog...
577 */
578
579 if (!strcmp(ErrorLog, "syslog"))
580 {
581 syslog(syslevels[level], "%s", message);
582 return (1);
583 }
584 #endif /* HAVE_VSYSLOG */
585
586 /*
587 * Not using syslog; check the log file...
588 */
589
590 if (!check_log_file(&ErrorFile, ErrorLog))
591 return (0);
592
593 /*
594 * Write the log message...
595 */
596
597 cupsFilePrintf(ErrorFile, "%c %s %s\n", levels[level],
598 cupsdGetDateTime(time(NULL)), message);
599 cupsFileFlush(ErrorFile);
600
601 return (1);
602 }
603
604
605 /*
606 * 'check_log_file()' - Open/rotate a log file if it needs it.
607 */
608
609 static int /* O - 1 if log file open */
610 check_log_file(cups_file_t **lf, /* IO - Log file */
611 const char *logname) /* I - Log filename */
612 {
613 char backname[1024], /* Backup log filename */
614 filename[1024], /* Formatted log filename */
615 *ptr; /* Pointer into filename */
616 const char *logptr; /* Pointer into log filename */
617
618
619 /*
620 * See if we have a log file to check...
621 */
622
623 if (!lf || !logname || !logname[0])
624 return (1);
625
626 /*
627 * Format the filename as needed...
628 */
629
630 if (!*lf ||
631 (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
632 MaxLogSize > 0))
633 {
634 /*
635 * Handle format strings...
636 */
637
638 filename[sizeof(filename) - 1] = '\0';
639
640 if (logname[0] != '/')
641 {
642 strlcpy(filename, ServerRoot, sizeof(filename));
643 strlcat(filename, "/", sizeof(filename));
644 }
645 else
646 filename[0] = '\0';
647
648 for (logptr = logname, ptr = filename + strlen(filename);
649 *logptr && ptr < (filename + sizeof(filename) - 1);
650 logptr ++)
651 if (*logptr == '%')
652 {
653 /*
654 * Format spec...
655 */
656
657 logptr ++;
658 if (*logptr == 's')
659 {
660 /*
661 * Insert the server name...
662 */
663
664 strlcpy(ptr, ServerName, sizeof(filename) - (ptr - filename));
665 ptr += strlen(ptr);
666 }
667 else
668 {
669 /*
670 * Otherwise just insert the character...
671 */
672
673 *ptr++ = *logptr;
674 }
675 }
676 else
677 *ptr++ = *logptr;
678
679 *ptr = '\0';
680 }
681
682 /*
683 * See if the log file is open...
684 */
685
686 if (!*lf)
687 {
688 /*
689 * Nope, open the log file...
690 */
691
692 if ((*lf = cupsFileOpen(filename, "a")) == NULL)
693 {
694 /*
695 * If the file is in CUPS_LOGDIR then try to create a missing directory...
696 */
697
698 if (!strncmp(filename, CUPS_LOGDIR, strlen(CUPS_LOGDIR)))
699 {
700 cupsdCheckPermissions(CUPS_LOGDIR, NULL, 0755, RunUser, Group, 1, -1);
701
702 *lf = cupsFileOpen(filename, "a");
703 }
704
705 if (*lf == NULL)
706 {
707 syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename,
708 strerror(errno));
709 return (0);
710 }
711 }
712
713 if (strncmp(filename, "/dev/", 5))
714 {
715 /*
716 * Change ownership and permissions of non-device logs...
717 */
718
719 fchown(cupsFileNumber(*lf), RunUser, Group);
720 fchmod(cupsFileNumber(*lf), LogFilePerm);
721 }
722 }
723
724 /*
725 * Do we need to rotate the log?
726 */
727
728 if (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
729 MaxLogSize > 0)
730 {
731 /*
732 * Rotate log file...
733 */
734
735 cupsFileClose(*lf);
736
737 strcpy(backname, filename);
738 strlcat(backname, ".O", sizeof(backname));
739
740 unlink(backname);
741 rename(filename, backname);
742
743 if ((*lf = cupsFileOpen(filename, "a")) == NULL)
744 {
745 syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename,
746 strerror(errno));
747
748 return (0);
749 }
750
751 /*
752 * Change ownership and permissions of non-device logs...
753 */
754
755 fchown(cupsFileNumber(*lf), RunUser, Group);
756 fchmod(cupsFileNumber(*lf), LogFilePerm);
757 }
758
759 return (1);
760 }
761
762
763 /*
764 * 'format_log_line()' - Format a line for a log file.
765 *
766 * This function resizes a global string buffer as needed. Each call returns
767 * a pointer to this buffer, so the contents are only good until the next call
768 * to format_log_line()...
769 */
770
771 static char * /* O - Text or NULL on error */
772 format_log_line(const char *message, /* I - Printf-style format string */
773 va_list ap) /* I - Argument list */
774 {
775 int len; /* Length of formatted line */
776
777
778 /*
779 * Allocate the line buffer as needed...
780 */
781
782 if (!log_linesize)
783 {
784 log_linesize = 8192;
785 log_line = malloc(log_linesize);
786
787 if (!log_line)
788 return (NULL);
789 }
790
791 /*
792 * Format the log message...
793 */
794
795 len = vsnprintf(log_line, log_linesize, message, ap);
796
797 /*
798 * Resize the buffer as needed...
799 */
800
801 if (len >= log_linesize)
802 {
803 char *temp; /* Temporary string pointer */
804
805
806 len ++;
807
808 if (len < 8192)
809 len = 8192;
810 else if (len > 65536)
811 len = 65536;
812
813 temp = realloc(log_line, len);
814
815 if (temp)
816 {
817 log_line = temp;
818 log_linesize = len;
819 }
820
821 len = vsnprintf(log_line, log_linesize, message, ap);
822 }
823
824 return (log_line);
825 }
826
827
828 /*
829 * End of "$Id: log.c 7699 2008-06-27 20:44:23Z mike $".
830 */