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