]> git.ipfire.org Git - thirdparty/cups.git/blob - scheduler/log.c
License change: Apache License, Version 2.0.
[thirdparty/cups.git] / scheduler / log.c
1 /*
2 * Log file routines for the CUPS scheduler.
3 *
4 * Copyright 2007-2017 by Apple Inc.
5 * Copyright 1997-2007 by Easy Software Products, all rights reserved.
6 *
7 * Licensed under Apache License v2.0. See the file "LICENSE" for more information.
8 */
9
10 /*
11 * Include necessary headers...
12 */
13
14 #include "cupsd.h"
15 #include <stdarg.h>
16 #ifdef HAVE_ASL_H
17 # include <asl.h>
18 #elif defined(HAVE_SYSTEMD_SD_JOURNAL_H)
19 # define SD_JOURNAL_SUPPRESS_LOCATION
20 # include <systemd/sd-journal.h>
21 #endif /* HAVE_ASL_H */
22 #include <syslog.h>
23
24
25 /*
26 * Constants for log keys from PWG 5110.3 (PWG Common Log Format)...
27 */
28
29 #define PWG_DeviceUUID "DUU"
30 #define PWG_Event "E"
31 #define PWG_LogNaturalLanguage "NL"
32 #define PWG_Status "S"
33 #define PWG_ServiceURI "URI"
34 #define PWG_UserHost "UH"
35 #define PWG_UserName "UN"
36 #define PWG_UserURI "UU"
37 #define PWG_ServiceIsAcceptingJobs "IAJ"
38 #define PWG_ServiceState "ST"
39 #define PWG_ServiceStateReasons "SR"
40 #define PWG_ServiceUUID "SUU"
41 #define PWG_JobID "JID"
42 #define PWG_JobUUID "JUU"
43 #define PWG_JobImagesCompleted "JIM"
44 #define PWG_JobImpressionsCompleted "JIC"
45 #define PWG_JobDestinationURI "JD"
46 #define PWG_JobState "JS"
47 #define PWG_JobStateReasons "JR"
48 #define PWG_JobAccountingID "JA"
49 #define PWG_JobAcountingUserName "JAUN"
50 #define PWG_JobAccountingUserURI "JAUU"
51
52
53 /*
54 * Local globals...
55 */
56
57 static _cups_mutex_t log_mutex = _CUPS_MUTEX_INITIALIZER;
58 /* Mutex for logging */
59 static size_t log_linesize = 0; /* Size of line for output file */
60 static char *log_line = NULL; /* Line for output file */
61
62 #ifdef HAVE_ASL_H
63 static const int log_levels[] = /* ASL levels... */
64 {
65 ASL_LEVEL_EMERG,
66 ASL_LEVEL_EMERG,
67 ASL_LEVEL_ALERT,
68 ASL_LEVEL_CRIT,
69 ASL_LEVEL_ERR,
70 ASL_LEVEL_WARNING,
71 ASL_LEVEL_NOTICE,
72 ASL_LEVEL_INFO,
73 ASL_LEVEL_DEBUG,
74 ASL_LEVEL_DEBUG
75 };
76 #elif defined(HAVE_VSYSLOG) || defined(HAVE_SYSTEMD_SD_JOURNAL_H)
77 static const int log_levels[] = /* SYSLOG levels... */
78 {
79 0,
80 LOG_EMERG,
81 LOG_ALERT,
82 LOG_CRIT,
83 LOG_ERR,
84 LOG_WARNING,
85 LOG_NOTICE,
86 LOG_INFO,
87 LOG_DEBUG,
88 LOG_DEBUG
89 };
90 #endif /* HAVE_ASL_H */
91
92
93 /*
94 * Local functions...
95 */
96
97 static int format_log_line(const char *message, va_list ap);
98
99
100 /*
101 * 'cupsdCheckLogFile()' - Open/rotate a log file if it needs it.
102 */
103
104 int /* O - 1 if log file open */
105 cupsdCheckLogFile(cups_file_t **lf, /* IO - Log file */
106 const char *logname) /* I - Log filename */
107 {
108 char backname[1024], /* Backup log filename */
109 filename[1024], /* Formatted log filename */
110 *ptr; /* Pointer into filename */
111 const char *logptr; /* Pointer into log filename */
112
113
114 /*
115 * See if we have a log file to check...
116 */
117
118 if (!lf || !logname || !logname[0])
119 return (1);
120
121 /*
122 * Handle logging to stderr...
123 */
124
125 if (!strcmp(logname, "stderr"))
126 {
127 *lf = LogStderr;
128 return (1);
129 }
130
131 /*
132 * Format the filename as needed...
133 */
134
135 if (!*lf ||
136 (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
137 MaxLogSize > 0))
138 {
139 /*
140 * Handle format strings...
141 */
142
143 filename[sizeof(filename) - 1] = '\0';
144
145 if (logname[0] != '/')
146 {
147 strlcpy(filename, ServerRoot, sizeof(filename));
148 strlcat(filename, "/", sizeof(filename));
149 }
150 else
151 filename[0] = '\0';
152
153 for (logptr = logname, ptr = filename + strlen(filename);
154 *logptr && ptr < (filename + sizeof(filename) - 1);
155 logptr ++)
156 if (*logptr == '%')
157 {
158 /*
159 * Format spec...
160 */
161
162 logptr ++;
163 if (*logptr == 's')
164 {
165 /*
166 * Insert the server name...
167 */
168
169 strlcpy(ptr, ServerName, sizeof(filename) - (size_t)(ptr - filename));
170 ptr += strlen(ptr);
171 }
172 else
173 {
174 /*
175 * Otherwise just insert the character...
176 */
177
178 *ptr++ = *logptr;
179 }
180 }
181 else
182 *ptr++ = *logptr;
183
184 *ptr = '\0';
185 }
186
187 /*
188 * See if the log file is open...
189 */
190
191 if (!*lf)
192 {
193 /*
194 * Nope, open the log file...
195 */
196
197 if ((*lf = cupsFileOpen(filename, "a")) == NULL)
198 {
199 /*
200 * If the file is in CUPS_LOGDIR then try to create a missing directory...
201 */
202
203 if (!strncmp(filename, CUPS_LOGDIR, strlen(CUPS_LOGDIR)))
204 {
205 /*
206 * Try updating the permissions of the containing log directory, using
207 * the log file permissions as a basis...
208 */
209
210 mode_t log_dir_perm = (mode_t)(0300 | LogFilePerm);
211 /* LogFilePerm + owner write/search */
212 if (log_dir_perm & 0040)
213 log_dir_perm |= 0010; /* Add group search */
214 if (log_dir_perm & 0004)
215 log_dir_perm |= 0001; /* Add other search */
216
217 cupsdCheckPermissions(CUPS_LOGDIR, NULL, log_dir_perm, RunUser, Group, 1, -1);
218
219 *lf = cupsFileOpen(filename, "a");
220 }
221
222 if (*lf == NULL)
223 {
224 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
225 sd_journal_print(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
226 #else
227 syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
228 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
229
230 if (FatalErrors & CUPSD_FATAL_LOG)
231 cupsdEndProcess(getpid(), 0);
232
233 return (0);
234 }
235 }
236
237 if (strncmp(filename, "/dev/", 5))
238 {
239 /*
240 * Change ownership and permissions of non-device logs...
241 */
242
243 fchown(cupsFileNumber(*lf), RunUser, Group);
244 fchmod(cupsFileNumber(*lf), LogFilePerm);
245 }
246 }
247
248 /*
249 * Do we need to rotate the log?
250 */
251
252 if (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
253 MaxLogSize > 0)
254 {
255 /*
256 * Rotate log file...
257 */
258
259 cupsFileClose(*lf);
260
261 strlcpy(backname, filename, sizeof(backname));
262 strlcat(backname, ".O", sizeof(backname));
263
264 unlink(backname);
265 rename(filename, backname);
266
267 if ((*lf = cupsFileOpen(filename, "a")) == NULL)
268 {
269 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
270 sd_journal_print(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
271
272 #else
273 syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
274 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
275
276 if (FatalErrors & CUPSD_FATAL_LOG)
277 cupsdEndProcess(getpid(), 0);
278
279 return (0);
280 }
281
282 /*
283 * Change ownership and permissions of non-device logs...
284 */
285
286 fchown(cupsFileNumber(*lf), RunUser, Group);
287 fchmod(cupsFileNumber(*lf), LogFilePerm);
288 }
289
290 return (1);
291 }
292
293
294 /*
295 * 'cupsdGetDateTime()' - Returns a pointer to a date/time string.
296 */
297
298 char * /* O - Date/time string */
299 cupsdGetDateTime(struct timeval *t, /* I - Time value or NULL for current */
300 cupsd_time_t format) /* I - Format to use */
301 {
302 struct timeval curtime; /* Current time value */
303 struct tm *date; /* Date/time value */
304 static struct timeval last_time = { 0, 0 };
305 /* Last time we formatted */
306 static char s[1024]; /* Date/time string */
307 static const char * const months[12] =/* Months */
308 {
309 "Jan",
310 "Feb",
311 "Mar",
312 "Apr",
313 "May",
314 "Jun",
315 "Jul",
316 "Aug",
317 "Sep",
318 "Oct",
319 "Nov",
320 "Dec"
321 };
322
323
324 /*
325 * Make sure we have a valid time...
326 */
327
328 if (!t)
329 {
330 gettimeofday(&curtime, NULL);
331 t = &curtime;
332 }
333
334 if (t->tv_sec != last_time.tv_sec ||
335 (LogTimeFormat == CUPSD_TIME_USECS && t->tv_usec != last_time.tv_usec))
336 {
337 last_time = *t;
338
339 /*
340 * Get the date and time from the UNIX time value, and then format it
341 * into a string. Note that we *can't* use the strftime() function since
342 * it is localized and will seriously confuse automatic programs if the
343 * month names are in the wrong language!
344 *
345 * Also, we use the "timezone" variable that contains the current timezone
346 * offset from GMT in seconds so that we are reporting local time in the
347 * log files. If you want GMT, set the TZ environment variable accordingly
348 * before starting the scheduler.
349 *
350 * (*BSD and Darwin store the timezone offset in the tm structure)
351 */
352
353 date = localtime(&(t->tv_sec));
354
355 if (format == CUPSD_TIME_STANDARD)
356 snprintf(s, sizeof(s), "[%02d/%s/%04d:%02d:%02d:%02d %+03ld%02ld]",
357 date->tm_mday, months[date->tm_mon], 1900 + date->tm_year,
358 date->tm_hour, date->tm_min, date->tm_sec,
359 #ifdef HAVE_TM_GMTOFF
360 date->tm_gmtoff / 3600, (date->tm_gmtoff / 60) % 60);
361 #else
362 timezone / 3600, (timezone / 60) % 60);
363 #endif /* HAVE_TM_GMTOFF */
364 else
365 snprintf(s, sizeof(s), "[%02d/%s/%04d:%02d:%02d:%02d.%06d %+03ld%02ld]",
366 date->tm_mday, months[date->tm_mon], 1900 + date->tm_year,
367 date->tm_hour, date->tm_min, date->tm_sec, (int)t->tv_usec,
368 #ifdef HAVE_TM_GMTOFF
369 date->tm_gmtoff / 3600, (date->tm_gmtoff / 60) % 60);
370 #else
371 timezone / 3600, (timezone / 60) % 60);
372 #endif /* HAVE_TM_GMTOFF */
373 }
374
375 return (s);
376 }
377
378
379 /*
380 * 'cupsdLogFCMessage()' - Log a file checking message.
381 */
382
383 void
384 cupsdLogFCMessage(
385 void *context, /* I - Printer (if any) */
386 _cups_fc_result_t result, /* I - Check result */
387 const char *message) /* I - Message to log */
388 {
389 cupsd_printer_t *p = (cupsd_printer_t *)context;
390 /* Printer */
391 cupsd_loglevel_t level; /* Log level */
392
393
394 if (result == _CUPS_FILE_CHECK_OK)
395 level = CUPSD_LOG_DEBUG2;
396 else
397 level = CUPSD_LOG_ERROR;
398
399 if (p)
400 {
401 cupsdLogMessage(level, "%s: %s", p->name, message);
402
403 if (result == _CUPS_FILE_CHECK_MISSING ||
404 result == _CUPS_FILE_CHECK_WRONG_TYPE)
405 {
406 strlcpy(p->state_message, message, sizeof(p->state_message));
407
408 if (cupsdSetPrinterReasons(p, "+cups-missing-filter-warning"))
409 cupsdAddEvent(CUPSD_EVENT_PRINTER_STATE, p, NULL, "%s", message);
410 }
411 else if (result == _CUPS_FILE_CHECK_PERMISSIONS ||
412 result == _CUPS_FILE_CHECK_RELATIVE_PATH)
413 {
414 strlcpy(p->state_message, message, sizeof(p->state_message));
415
416 if (cupsdSetPrinterReasons(p, "+cups-insecure-filter-warning"))
417 cupsdAddEvent(CUPSD_EVENT_PRINTER_STATE, p, NULL, "%s", message);
418 }
419 }
420 else
421 cupsdLogMessage(level, "%s", message);
422 }
423
424
425 #ifdef HAVE_GSSAPI
426 /*
427 * 'cupsdLogGSSMessage()' - Log a GSSAPI error...
428 */
429
430 int /* O - 1 on success, 0 on error */
431 cupsdLogGSSMessage(
432 int level, /* I - Log level */
433 OM_uint32 major_status, /* I - Major GSSAPI status */
434 OM_uint32 minor_status, /* I - Minor GSSAPI status */
435 const char *message, /* I - printf-style message string */
436 ...) /* I - Additional args as needed */
437 {
438 OM_uint32 err_major_status, /* Major status code for display */
439 err_minor_status; /* Minor status code for display */
440 OM_uint32 msg_ctx; /* Message context */
441 gss_buffer_desc major_status_string = GSS_C_EMPTY_BUFFER,
442 /* Major status message */
443 minor_status_string = GSS_C_EMPTY_BUFFER;
444 /* Minor status message */
445 int ret; /* Return value */
446 char buffer[8192]; /* Buffer for vsnprintf */
447
448
449 if (strchr(message, '%'))
450 {
451 /*
452 * Format the message string...
453 */
454
455 va_list ap; /* Pointer to arguments */
456
457 va_start(ap, message);
458 vsnprintf(buffer, sizeof(buffer), message, ap);
459 va_end(ap);
460
461 message = buffer;
462 }
463
464 msg_ctx = 0;
465 err_major_status = gss_display_status(&err_minor_status,
466 major_status,
467 GSS_C_GSS_CODE,
468 GSS_C_NO_OID,
469 &msg_ctx,
470 &major_status_string);
471
472 if (!GSS_ERROR(err_major_status))
473 gss_display_status(&err_minor_status, minor_status, GSS_C_MECH_CODE,
474 GSS_C_NULL_OID, &msg_ctx, &minor_status_string);
475
476 ret = cupsdLogMessage(level, "%s: %s, %s", message,
477 (char *)major_status_string.value,
478 (char *)minor_status_string.value);
479 gss_release_buffer(&err_minor_status, &major_status_string);
480 gss_release_buffer(&err_minor_status, &minor_status_string);
481
482 return (ret);
483 }
484 #endif /* HAVE_GSSAPI */
485
486
487 /*
488 * 'cupsdLogClient()' - Log a client message.
489 */
490
491 int /* O - 1 on success, 0 on error */
492 cupsdLogClient(cupsd_client_t *con, /* I - Client connection */
493 int level, /* I - Log level */
494 const char *message, /* I - Printf-style message string */
495 ...) /* I - Additional arguments as needed */
496 {
497 va_list ap, ap2; /* Argument pointers */
498 char clientmsg[1024];/* Format string for client message */
499 int status; /* Formatting status */
500
501
502 /*
503 * See if we want to log this message...
504 */
505
506 if (TestConfigFile || !ErrorLog)
507 return (1);
508
509 if (level > LogLevel)
510 return (1);
511
512 /*
513 * Format and write the log message...
514 */
515
516 if (con)
517 snprintf(clientmsg, sizeof(clientmsg), "[Client %d] %s", con->number,
518 message);
519 else
520 strlcpy(clientmsg, message, sizeof(clientmsg));
521
522 va_start(ap, message);
523
524 do
525 {
526 va_copy(ap2, ap);
527 status = format_log_line(clientmsg, ap2);
528 va_end(ap2);
529 }
530 while (status == 0);
531
532 va_end(ap);
533
534 if (status > 0)
535 return (cupsdWriteErrorLog(level, log_line));
536 else
537 return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
538 "Unable to allocate memory for log line."));
539 }
540
541
542 /*
543 * 'cupsdLogJob()' - Log a job message.
544 */
545
546 int /* O - 1 on success, 0 on error */
547 cupsdLogJob(cupsd_job_t *job, /* I - Job */
548 int level, /* I - Log level */
549 const char *message, /* I - Printf-style message string */
550 ...) /* I - Additional arguments as needed */
551 {
552 va_list ap, ap2; /* Argument pointers */
553 char jobmsg[1024]; /* Format string for job message */
554 int status; /* Formatting status */
555
556
557 /*
558 * See if we want to log this message...
559 */
560
561 if (TestConfigFile || !ErrorLog)
562 return (1);
563
564 if (level > LogLevel && LogDebugHistory <= 0)
565 return (1);
566
567 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
568 if (!strcmp(ErrorLog, "syslog"))
569 {
570 cupsd_printer_t *printer = job ? (job->printer ? job->printer : (job->dest ? cupsdFindDest(job->dest) : NULL)) : NULL;
571 static const char * const job_states[] =
572 { /* job-state strings */
573 "Pending",
574 "PendingHeld",
575 "Processing",
576 "ProcessingStopped",
577 "Canceled",
578 "Aborted",
579 "Completed"
580 };
581
582 va_start(ap, message);
583
584 do
585 {
586 va_copy(ap2, ap);
587 status = format_log_line(message, ap2);
588 va_end(ap2);
589 }
590 while (status == 0);
591
592 va_end(ap);
593
594 if (job)
595 sd_journal_send("MESSAGE=%s", log_line,
596 "PRIORITY=%i", log_levels[level],
597 PWG_Event"=JobStateChanged",
598 PWG_ServiceURI"=%s", printer ? printer->uri : "",
599 PWG_JobID"=%d", job->id,
600 PWG_JobState"=%s", job->state_value < IPP_JSTATE_PENDING ? "" : job_states[job->state_value - IPP_JSTATE_PENDING],
601 PWG_JobImpressionsCompleted"=%d", ippGetInteger(job->impressions, 0),
602 NULL);
603 else
604 sd_journal_send("MESSAGE=%s", log_line,
605 "PRIORITY=%i", log_levels[level],
606 NULL);
607
608 return (1);
609 }
610 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
611
612 /*
613 * Format and write the log message...
614 */
615
616 if (job)
617 snprintf(jobmsg, sizeof(jobmsg), "[Job %d] %s", job->id, message);
618 else
619 strlcpy(jobmsg, message, sizeof(jobmsg));
620
621 va_start(ap, message);
622
623 do
624 {
625 va_copy(ap2, ap);
626 status = format_log_line(jobmsg, ap2);
627 va_end(ap2);
628 }
629 while (status == 0);
630
631 va_end(ap);
632
633 if (status > 0)
634 {
635 if (job && level > LogLevel && LogDebugHistory > 0)
636 {
637 /*
638 * Add message to the job history...
639 */
640
641 cupsd_joblog_t *temp; /* Copy of log message */
642 size_t log_len = strlen(log_line);
643 /* Length of log message */
644
645 if ((temp = malloc(sizeof(cupsd_joblog_t) + log_len)) != NULL)
646 {
647 temp->time = time(NULL);
648 memcpy(temp->message, log_line, log_len + 1);
649 }
650
651 if (!job->history)
652 job->history = cupsArrayNew(NULL, NULL);
653
654 if (job->history && temp)
655 {
656 cupsArrayAdd(job->history, temp);
657
658 if (cupsArrayCount(job->history) > LogDebugHistory)
659 {
660 /*
661 * Remove excess messages...
662 */
663
664 temp = cupsArrayFirst(job->history);
665 cupsArrayRemove(job->history, temp);
666 free(temp);
667 }
668 }
669 else if (temp)
670 free(temp);
671
672 return (1);
673 }
674 else if (level <= LogLevel)
675 return (cupsdWriteErrorLog(level, log_line));
676 else
677 return (1);
678 }
679 else
680 return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
681 "Unable to allocate memory for log line."));
682 }
683
684
685 /*
686 * 'cupsdLogMessage()' - Log a message to the error log file.
687 */
688
689 int /* O - 1 on success, 0 on error */
690 cupsdLogMessage(int level, /* I - Log level */
691 const char *message, /* I - printf-style message string */
692 ...) /* I - Additional args as needed */
693 {
694 va_list ap, ap2; /* Argument pointers */
695 int status; /* Formatting status */
696
697
698 /*
699 * See if we want to log this message...
700 */
701
702 if (TestConfigFile && level <= CUPSD_LOG_WARN)
703 {
704 va_start(ap, message);
705
706 vfprintf(stderr, message, ap);
707 putc('\n', stderr);
708
709 va_end(ap);
710
711 return (1);
712 }
713 else if (!ErrorLog && level <= CUPSD_LOG_WARN)
714 {
715 va_start(ap, message);
716
717 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
718 sd_journal_printv(log_levels[level], message, ap);
719
720 #elif defined(HAVE_VSYSLOG)
721 vsyslog(LOG_LPR | log_levels[level], message, ap);
722
723 #else
724 vfprintf(stderr, message, ap);
725 putc('\n', stderr);
726 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
727
728 va_end(ap);
729
730 return (1);
731 }
732 else if (level > LogLevel || !ErrorLog)
733 return (1);
734
735 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
736 else if (!strcmp(ErrorLog, "syslog"))
737 {
738 va_start(ap, message);
739 sd_journal_printv(log_levels[level], message, ap);
740 va_end(ap);
741 return (1);
742 }
743 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
744
745 /*
746 * Format and write the log message...
747 */
748
749 va_start(ap, message);
750
751 do
752 {
753 va_copy(ap2, ap);
754 status = format_log_line(message, ap2);
755 va_end(ap2);
756 }
757 while (status == 0);
758
759 va_end(ap);
760
761 if (status > 0)
762 return (cupsdWriteErrorLog(level, log_line));
763 else
764 return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
765 "Unable to allocate memory for log line!"));
766 }
767
768
769 /*
770 * 'cupsdLogPage()' - Log a page to the page log file.
771 */
772
773 int /* O - 1 on success, 0 on error */
774 cupsdLogPage(cupsd_job_t *job, /* I - Job being printed */
775 const char *page) /* I - Page being printed */
776 {
777 int i; /* Looping var */
778 char buffer[2048], /* Buffer for page log */
779 *bufptr, /* Pointer into buffer */
780 name[256]; /* Attribute name */
781 const char *format, /* Pointer into PageLogFormat */
782 *nameend; /* End of attribute name */
783 ipp_attribute_t *attr; /* Current attribute */
784 char number[256]; /* Page number */
785 int copies; /* Number of copies */
786
787
788 /*
789 * Format the line going into the page log...
790 */
791
792 if (!PageLogFormat)
793 return (1);
794
795 strlcpy(number, "1", sizeof(number));
796 copies = 1;
797 sscanf(page, "%255s%d", number, &copies);
798
799 for (format = PageLogFormat, bufptr = buffer; *format; format ++)
800 {
801 if (*format == '%')
802 {
803 format ++;
804
805 switch (*format)
806 {
807 case '%' : /* Literal % */
808 if (bufptr < (buffer + sizeof(buffer) - 1))
809 *bufptr++ = '%';
810 break;
811
812 case 'p' : /* Printer name */
813 strlcpy(bufptr, job->dest, sizeof(buffer) - (size_t)(bufptr - buffer));
814 bufptr += strlen(bufptr);
815 break;
816
817 case 'j' : /* Job ID */
818 snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", job->id);
819 bufptr += strlen(bufptr);
820 break;
821
822 case 'u' : /* Username */
823 strlcpy(bufptr, job->username ? job->username : "-", sizeof(buffer) - (size_t)(bufptr - buffer));
824 bufptr += strlen(bufptr);
825 break;
826
827 case 'T' : /* Date and time */
828 strlcpy(bufptr, cupsdGetDateTime(NULL, LogTimeFormat), sizeof(buffer) - (size_t)(bufptr - buffer));
829 bufptr += strlen(bufptr);
830 break;
831
832 case 'P' : /* Page number */
833 strlcpy(bufptr, number, sizeof(buffer) - (size_t)(bufptr - buffer));
834 bufptr += strlen(bufptr);
835 break;
836
837 case 'C' : /* Number of copies */
838 snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", copies);
839 bufptr += strlen(bufptr);
840 break;
841
842 case '{' : /* {attribute} */
843 if ((nameend = strchr(format, '}')) != NULL && (size_t)(nameend - format - 2) < (sizeof(name) - 1))
844 {
845 /*
846 * Pull the name from inside the brackets...
847 */
848
849 memcpy(name, format + 1, (size_t)(nameend - format - 1));
850 name[nameend - format - 1] = '\0';
851
852 format = nameend;
853
854 attr = ippFindAttribute(job->attrs, name, IPP_TAG_ZERO);
855 if (!attr && !strcmp(name, "job-billing"))
856 {
857 /*
858 * Handle alias "job-account-id" (which was standardized after
859 * "job-billing" was defined for CUPS...
860 */
861
862 attr = ippFindAttribute(job->attrs, "job-account-id", IPP_TAG_ZERO);
863 }
864 else if (!attr && !strcmp(name, "media"))
865 {
866 /*
867 * Handle alias "media-col" which uses dimensions instead of
868 * names...
869 */
870
871 attr = ippFindAttribute(job->attrs, "media-col/media-size", IPP_TAG_BEGIN_COLLECTION);
872 }
873
874 if (attr)
875 {
876 /*
877 * Add the attribute value...
878 */
879
880 for (i = 0;
881 i < attr->num_values &&
882 bufptr < (buffer + sizeof(buffer) - 1);
883 i ++)
884 {
885 if (i)
886 *bufptr++ = ',';
887
888 switch (attr->value_tag)
889 {
890 case IPP_TAG_INTEGER :
891 case IPP_TAG_ENUM :
892 snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", attr->values[i].integer);
893 bufptr += strlen(bufptr);
894 break;
895
896 case IPP_TAG_BOOLEAN :
897 snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", attr->values[i].boolean);
898 bufptr += strlen(bufptr);
899 break;
900
901 case IPP_TAG_TEXTLANG :
902 case IPP_TAG_NAMELANG :
903 case IPP_TAG_TEXT :
904 case IPP_TAG_NAME :
905 case IPP_TAG_KEYWORD :
906 case IPP_TAG_URI :
907 case IPP_TAG_URISCHEME :
908 case IPP_TAG_CHARSET :
909 case IPP_TAG_LANGUAGE :
910 case IPP_TAG_MIMETYPE :
911 strlcpy(bufptr, attr->values[i].string.text, sizeof(buffer) - (size_t)(bufptr - buffer));
912 bufptr += strlen(bufptr);
913 break;
914
915 case IPP_TAG_BEGIN_COLLECTION :
916 if (!strcmp(attr->name, "media-size"))
917 {
918 ipp_attribute_t *x_dimension = ippFindAttribute(ippGetCollection(attr, 0), "x-dimension", IPP_TAG_INTEGER);
919 ipp_attribute_t *y_dimension = ippFindAttribute(ippGetCollection(attr, 0), "y-dimension", IPP_TAG_INTEGER);
920 /* Media dimensions */
921
922 if (x_dimension && y_dimension)
923 {
924 pwg_media_t *pwg = pwgMediaForSize(ippGetInteger(x_dimension, 0), ippGetInteger(y_dimension, 0));
925 /* PWG media name */
926 strlcpy(bufptr, pwg->pwg, sizeof(buffer) - (size_t)(bufptr - buffer));
927 break;
928 }
929 }
930
931 default :
932 strlcpy(bufptr, "???", sizeof(buffer) - (size_t)(bufptr - buffer));
933 bufptr += strlen(bufptr);
934 break;
935 }
936 }
937 }
938 else if (bufptr < (buffer + sizeof(buffer) - 1))
939 *bufptr++ = '-';
940 break;
941 }
942
943 default :
944 if (bufptr < (buffer + sizeof(buffer) - 2))
945 {
946 *bufptr++ = '%';
947 *bufptr++ = *format;
948 }
949 break;
950 }
951 }
952 else if (bufptr < (buffer + sizeof(buffer) - 1))
953 *bufptr++ = *format;
954 }
955
956 *bufptr = '\0';
957
958 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
959 if (!strcmp(ErrorLog, "syslog"))
960 {
961 static const char * const job_states[] =
962 { /* job-state strings */
963 "Pending",
964 "PendingHeld",
965 "Processing",
966 "ProcessingStopped",
967 "Canceled",
968 "Aborted",
969 "Completed"
970 };
971
972 sd_journal_send("MESSAGE=%s", buffer,
973 "PRIORITY=%i", LOG_INFO,
974 PWG_Event"=JobStateChanged",
975 PWG_ServiceURI"=%s", job->printer->uri,
976 PWG_JobID"=%d", job->id,
977 PWG_JobState"=%s", job_states[job->state_value - IPP_JSTATE_PENDING],
978 PWG_JobImpressionsCompleted"=%d", ippGetInteger(job->impressions, 0),
979 NULL);
980 return (1);
981 }
982
983 #elif defined(HAVE_VSYSLOG)
984 /*
985 * See if we are logging pages via syslog...
986 */
987
988 if (!strcmp(PageLog, "syslog"))
989 {
990 syslog(LOG_INFO, "%s", buffer);
991
992 return (1);
993 }
994 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
995
996 /*
997 * Not using syslog; check the log file...
998 */
999
1000 if (!cupsdCheckLogFile(&PageFile, PageLog))
1001 return (0);
1002
1003 /*
1004 * Print a page log entry of the form:
1005 *
1006 * printer user job-id [DD/MON/YYYY:HH:MM:SS +TTTT] page num-copies \
1007 * billing hostname
1008 */
1009
1010 cupsFilePrintf(PageFile, "%s\n", buffer);
1011 cupsFileFlush(PageFile);
1012
1013 return (1);
1014 }
1015
1016
1017 /*
1018 * 'cupsdLogRequest()' - Log an HTTP request in Common Log Format.
1019 */
1020
1021 int /* O - 1 on success, 0 on error */
1022 cupsdLogRequest(cupsd_client_t *con, /* I - Request to log */
1023 http_status_t code) /* I - Response code */
1024 {
1025 char temp[2048]; /* Temporary string for URI */
1026 static const char * const states[] = /* HTTP client states... */
1027 {
1028 "WAITING",
1029 "OPTIONS",
1030 "GET",
1031 "GET",
1032 "HEAD",
1033 "POST",
1034 "POST",
1035 "POST",
1036 "PUT",
1037 "PUT",
1038 "DELETE",
1039 "TRACE",
1040 "CLOSE",
1041 "STATUS"
1042 };
1043
1044
1045 /*
1046 * Filter requests as needed...
1047 */
1048
1049 if (AccessLogLevel == CUPSD_ACCESSLOG_NONE)
1050 return (1);
1051 else if (AccessLogLevel < CUPSD_ACCESSLOG_ALL)
1052 {
1053 /*
1054 * Eliminate simple GET, POST, and PUT requests...
1055 */
1056
1057 if ((con->operation == HTTP_GET &&
1058 strncmp(con->uri, "/admin/conf", 11) &&
1059 strncmp(con->uri, "/admin/log", 10)) ||
1060 (con->operation == HTTP_POST && !con->request &&
1061 strncmp(con->uri, "/admin", 6)) ||
1062 (con->operation != HTTP_GET && con->operation != HTTP_POST &&
1063 con->operation != HTTP_PUT))
1064 return (1);
1065
1066 if (con->request && con->response &&
1067 (con->response->request.status.status_code < IPP_REDIRECTION_OTHER_SITE ||
1068 con->response->request.status.status_code == IPP_NOT_FOUND))
1069 {
1070 /*
1071 * Check successful requests...
1072 */
1073
1074 ipp_op_t op = con->request->request.op.operation_id;
1075 static cupsd_accesslog_t standard_ops[] =
1076 {
1077 CUPSD_ACCESSLOG_ALL, /* reserved */
1078 CUPSD_ACCESSLOG_ALL, /* reserved */
1079 CUPSD_ACCESSLOG_ACTIONS,/* Print-Job */
1080 CUPSD_ACCESSLOG_ACTIONS,/* Print-URI */
1081 CUPSD_ACCESSLOG_ACTIONS,/* Validate-Job */
1082 CUPSD_ACCESSLOG_ACTIONS,/* Create-Job */
1083 CUPSD_ACCESSLOG_ACTIONS,/* Send-Document */
1084 CUPSD_ACCESSLOG_ACTIONS,/* Send-URI */
1085 CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Job */
1086 CUPSD_ACCESSLOG_ALL, /* Get-Job-Attributes */
1087 CUPSD_ACCESSLOG_ALL, /* Get-Jobs */
1088 CUPSD_ACCESSLOG_ALL, /* Get-Printer-Attributes */
1089 CUPSD_ACCESSLOG_ACTIONS,/* Hold-Job */
1090 CUPSD_ACCESSLOG_ACTIONS,/* Release-Job */
1091 CUPSD_ACCESSLOG_ACTIONS,/* Restart-Job */
1092 CUPSD_ACCESSLOG_ALL, /* reserved */
1093 CUPSD_ACCESSLOG_CONFIG, /* Pause-Printer */
1094 CUPSD_ACCESSLOG_CONFIG, /* Resume-Printer */
1095 CUPSD_ACCESSLOG_CONFIG, /* Purge-Jobs */
1096 CUPSD_ACCESSLOG_CONFIG, /* Set-Printer-Attributes */
1097 CUPSD_ACCESSLOG_ACTIONS,/* Set-Job-Attributes */
1098 CUPSD_ACCESSLOG_CONFIG, /* Get-Printer-Supported-Values */
1099 CUPSD_ACCESSLOG_ACTIONS,/* Create-Printer-Subscription */
1100 CUPSD_ACCESSLOG_ACTIONS,/* Create-Job-Subscription */
1101 CUPSD_ACCESSLOG_ALL, /* Get-Subscription-Attributes */
1102 CUPSD_ACCESSLOG_ALL, /* Get-Subscriptions */
1103 CUPSD_ACCESSLOG_ACTIONS,/* Renew-Subscription */
1104 CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Subscription */
1105 CUPSD_ACCESSLOG_ALL, /* Get-Notifications */
1106 CUPSD_ACCESSLOG_ACTIONS,/* Send-Notifications */
1107 CUPSD_ACCESSLOG_ALL, /* reserved */
1108 CUPSD_ACCESSLOG_ALL, /* reserved */
1109 CUPSD_ACCESSLOG_ALL, /* reserved */
1110 CUPSD_ACCESSLOG_ALL, /* Get-Print-Support-Files */
1111 CUPSD_ACCESSLOG_CONFIG, /* Enable-Printer */
1112 CUPSD_ACCESSLOG_CONFIG, /* Disable-Printer */
1113 CUPSD_ACCESSLOG_CONFIG, /* Pause-Printer-After-Current-Job */
1114 CUPSD_ACCESSLOG_ACTIONS,/* Hold-New-Jobs */
1115 CUPSD_ACCESSLOG_ACTIONS,/* Release-Held-New-Jobs */
1116 CUPSD_ACCESSLOG_CONFIG, /* Deactivate-Printer */
1117 CUPSD_ACCESSLOG_CONFIG, /* Activate-Printer */
1118 CUPSD_ACCESSLOG_CONFIG, /* Restart-Printer */
1119 CUPSD_ACCESSLOG_CONFIG, /* Shutdown-Printer */
1120 CUPSD_ACCESSLOG_CONFIG, /* Startup-Printer */
1121 CUPSD_ACCESSLOG_ACTIONS,/* Reprocess-Job */
1122 CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Current-Job */
1123 CUPSD_ACCESSLOG_ACTIONS,/* Suspend-Current-Job */
1124 CUPSD_ACCESSLOG_ACTIONS,/* Resume-Job */
1125 CUPSD_ACCESSLOG_ACTIONS,/* Promote-Job */
1126 CUPSD_ACCESSLOG_ACTIONS /* Schedule-Job-After */
1127 };
1128 static cupsd_accesslog_t cups_ops[] =
1129 {
1130 CUPSD_ACCESSLOG_ALL, /* CUPS-Get-Default */
1131 CUPSD_ACCESSLOG_ALL, /* CUPS-Get-Printers */
1132 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Add-Modify-Printer */
1133 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Delete-Printer */
1134 CUPSD_ACCESSLOG_ALL, /* CUPS-Get-Classes */
1135 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Add-Modify-Class */
1136 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Delete-Class */
1137 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Accept-Jobs */
1138 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Reject-Jobs */
1139 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Set-Default */
1140 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Get-Devices */
1141 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Get-PPDs */
1142 CUPSD_ACCESSLOG_ACTIONS,/* CUPS-Move-Job */
1143 CUPSD_ACCESSLOG_ACTIONS,/* CUPS-Authenticate-Job */
1144 CUPSD_ACCESSLOG_ALL /* CUPS-Get-PPD */
1145 };
1146
1147
1148 if ((op <= IPP_SCHEDULE_JOB_AFTER && standard_ops[op] > AccessLogLevel) ||
1149 (op >= CUPS_GET_DEFAULT && op <= CUPS_GET_PPD &&
1150 cups_ops[op - CUPS_GET_DEFAULT] > AccessLogLevel))
1151 return (1);
1152 }
1153 }
1154
1155 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
1156 if (!strcmp(ErrorLog, "syslog"))
1157 {
1158 sd_journal_print(LOG_INFO, "REQUEST %s - %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s", con->http->hostname, con->username[0] != '\0' ? con->username : "-", states[con->operation], _httpEncodeURI(temp, con->uri, sizeof(temp)), con->http->version / 100, con->http->version % 100, code, CUPS_LLCAST con->bytes, con->request ? ippOpString(con->request->request.op.operation_id) : "-", con->response ? ippErrorString(con->response->request.status.status_code) : "-");
1159 return (1);
1160 }
1161
1162 #elif defined(HAVE_VSYSLOG)
1163 /*
1164 * See if we are logging accesses via syslog...
1165 */
1166
1167 if (!strcmp(AccessLog, "syslog"))
1168 {
1169 syslog(LOG_INFO,
1170 "REQUEST %s - %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
1171 con->http->hostname, con->username[0] != '\0' ? con->username : "-",
1172 states[con->operation], _httpEncodeURI(temp, con->uri, sizeof(temp)),
1173 con->http->version / 100, con->http->version % 100,
1174 code, CUPS_LLCAST con->bytes,
1175 con->request ?
1176 ippOpString(con->request->request.op.operation_id) : "-",
1177 con->response ?
1178 ippErrorString(con->response->request.status.status_code) : "-");
1179
1180 return (1);
1181 }
1182 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
1183
1184 /*
1185 * Not using syslog; check the log file...
1186 */
1187
1188 if (!cupsdCheckLogFile(&AccessFile, AccessLog))
1189 return (0);
1190
1191 /*
1192 * Write a log of the request in "common log format"...
1193 */
1194
1195 cupsFilePrintf(AccessFile,
1196 "%s - %s %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
1197 con->http->hostname,
1198 con->username[0] != '\0' ? con->username : "-",
1199 cupsdGetDateTime(&(con->start), LogTimeFormat),
1200 states[con->operation],
1201 _httpEncodeURI(temp, con->uri, sizeof(temp)),
1202 con->http->version / 100, con->http->version % 100,
1203 code, CUPS_LLCAST con->bytes,
1204 con->request ?
1205 ippOpString(con->request->request.op.operation_id) : "-",
1206 con->response ?
1207 ippErrorString(con->response->request.status.status_code) :
1208 "-");
1209
1210 cupsFileFlush(AccessFile);
1211
1212 return (1);
1213 }
1214
1215
1216 /*
1217 * 'cupsdWriteErrorLog()' - Write a line to the ErrorLog.
1218 */
1219
1220 int /* O - 1 on success, 0 on failure */
1221 cupsdWriteErrorLog(int level, /* I - Log level */
1222 const char *message) /* I - Message string */
1223 {
1224 int ret = 1; /* Return value */
1225 static const char levels[] = /* Log levels... */
1226 {
1227 ' ',
1228 'X',
1229 'A',
1230 'C',
1231 'E',
1232 'W',
1233 'N',
1234 'I',
1235 'D',
1236 'd'
1237 };
1238
1239
1240 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
1241 if (!strcmp(ErrorLog, "syslog"))
1242 {
1243 sd_journal_print(log_levels[level], "%s", message);
1244 return (1);
1245 }
1246
1247 #elif defined(HAVE_VSYSLOG)
1248 /*
1249 * See if we are logging errors via syslog...
1250 */
1251
1252 if (!strcmp(ErrorLog, "syslog"))
1253 {
1254 syslog(log_levels[level], "%s", message);
1255 return (1);
1256 }
1257 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
1258
1259 /*
1260 * Not using syslog; check the log file...
1261 */
1262
1263 _cupsMutexLock(&log_mutex);
1264
1265 if (!cupsdCheckLogFile(&ErrorFile, ErrorLog))
1266 {
1267 ret = 0;
1268 }
1269 else
1270 {
1271 /*
1272 * Write the log message...
1273 */
1274
1275 cupsFilePrintf(ErrorFile, "%c %s %s\n", levels[level],
1276 cupsdGetDateTime(NULL, LogTimeFormat), message);
1277 cupsFileFlush(ErrorFile);
1278 }
1279
1280 _cupsMutexUnlock(&log_mutex);
1281
1282 return (ret);
1283 }
1284
1285
1286 /*
1287 * 'format_log_line()' - Format a line for a log file.
1288 *
1289 * This function resizes a global string buffer as needed. Each call returns
1290 * a pointer to this buffer, so the contents are only good until the next call
1291 * to format_log_line()...
1292 */
1293
1294 static int /* O - -1 for fatal, 0 for retry, 1 for success */
1295 format_log_line(const char *message, /* I - Printf-style format string */
1296 va_list ap) /* I - Argument list */
1297 {
1298 ssize_t len; /* Length of formatted line */
1299
1300
1301 /*
1302 * Allocate the line buffer as needed...
1303 */
1304
1305 if (!log_linesize)
1306 {
1307 log_linesize = 8192;
1308 log_line = malloc(log_linesize);
1309
1310 if (!log_line)
1311 return (-1);
1312 }
1313
1314 /*
1315 * Format the log message...
1316 */
1317
1318 len = _cups_safe_vsnprintf(log_line, log_linesize, message, ap);
1319
1320 /*
1321 * Resize the buffer as needed...
1322 */
1323
1324 if ((size_t)len >= log_linesize && log_linesize < 65536)
1325 {
1326 char *temp; /* Temporary string pointer */
1327
1328 len ++;
1329
1330 if (len < 8192)
1331 len = 8192;
1332 else if (len > 65536)
1333 len = 65536;
1334
1335 temp = realloc(log_line, (size_t)len);
1336
1337 if (temp)
1338 {
1339 log_line = temp;
1340 log_linesize = (size_t)len;
1341
1342 return (0);
1343 }
1344 }
1345
1346 return (1);
1347 }