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 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
573 if (job && strcmp(ErrorLog, "syslog"))
574 #else
575 if (job)
576 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
577 snprintf(jobmsg, sizeof(jobmsg), "[Job %d] %s", job->id, message);
578 else
579 strlcpy(jobmsg, message, sizeof(jobmsg));
580
581 va_start(ap, message);
582
583 do
584 {
585 va_copy(ap2, ap);
586 status = format_log_line(jobmsg, ap2);
587 va_end(ap2);
588 }
589 while (status == 0);
590
591 va_end(ap);
592
593 if (status > 0)
594 {
595 if (job && level > LogLevel && LogDebugHistory > 0)
596 {
597 /*
598 * Add message to the job history...
599 */
600
601 cupsd_joblog_t *temp; /* Copy of log message */
602 size_t log_len = strlen(log_line);
603 /* Length of log message */
604
605 if ((temp = malloc(sizeof(cupsd_joblog_t) + log_len)) != NULL)
606 {
607 temp->time = time(NULL);
608 memcpy(temp->message, log_line, log_len + 1);
609 }
610
611 if (!job->history)
612 job->history = cupsArrayNew(NULL, NULL);
613
614 if (job->history && temp)
615 {
616 cupsArrayAdd(job->history, temp);
617
618 if (cupsArrayCount(job->history) > LogDebugHistory)
619 {
620 /*
621 * Remove excess messages...
622 */
623
624 temp = cupsArrayFirst(job->history);
625 cupsArrayRemove(job->history, temp);
626 free(temp);
627 }
628 }
629 else if (temp)
630 free(temp);
631
632 return (1);
633 }
634 else if (level <= LogLevel)
635 {
636 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
637 if (!strcmp(ErrorLog, "syslog"))
638 {
639 cupsd_printer_t *printer = job ? (job->printer ? job->printer : (job->dest ? cupsdFindDest(job->dest) : NULL)) : NULL;
640 static const char * const job_states[] =
641 { /* job-state strings */
642 "Pending",
643 "PendingHeld",
644 "Processing",
645 "ProcessingStopped",
646 "Canceled",
647 "Aborted",
648 "Completed"
649 };
650
651 if (job)
652 sd_journal_send("MESSAGE=%s", log_line,
653 "PRIORITY=%i", log_levels[level],
654 PWG_Event"=JobStateChanged",
655 PWG_ServiceURI"=%s", printer ? printer->uri : "",
656 PWG_JobID"=%d", job->id,
657 PWG_JobState"=%s", job->state_value < IPP_JSTATE_PENDING ? "" : job_states[job->state_value - IPP_JSTATE_PENDING],
658 PWG_JobImpressionsCompleted"=%d", ippGetInteger(job->impressions, 0),
659 NULL);
660 else
661 sd_journal_send("MESSAGE=%s", log_line,
662 "PRIORITY=%i", log_levels[level],
663 NULL);
664
665 return (1);
666 }
667 else
668 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
669
670 return (cupsdWriteErrorLog(level, log_line));
671 }
672 else
673 return (1);
674 }
675 else
676 return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
677 "Unable to allocate memory for log line."));
678 }
679
680
681 /*
682 * 'cupsdLogMessage()' - Log a message to the error log file.
683 */
684
685 int /* O - 1 on success, 0 on error */
cupsdLogMessage(int level,const char * message,...)686 cupsdLogMessage(int level, /* I - Log level */
687 const char *message, /* I - printf-style message string */
688 ...) /* I - Additional args as needed */
689 {
690 va_list ap, ap2; /* Argument pointers */
691 int status; /* Formatting status */
692
693
694 /*
695 * See if we want to log this message...
696 */
697
698 if (TestConfigFile && level <= CUPSD_LOG_WARN)
699 {
700 va_start(ap, message);
701
702 vfprintf(stderr, message, ap);
703 putc('\n', stderr);
704
705 va_end(ap);
706
707 return (1);
708 }
709 else if (!ErrorLog && level <= CUPSD_LOG_WARN)
710 {
711 va_start(ap, message);
712
713 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
714 sd_journal_printv(log_levels[level], message, ap);
715
716 #elif defined(HAVE_VSYSLOG)
717 vsyslog(LOG_LPR | log_levels[level], message, ap);
718
719 #else
720 vfprintf(stderr, message, ap);
721 putc('\n', stderr);
722 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
723
724 va_end(ap);
725
726 return (1);
727 }
728 else if (level > LogLevel || !ErrorLog)
729 return (1);
730
731 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
732 else if (!strcmp(ErrorLog, "syslog"))
733 {
734 va_start(ap, message);
735 sd_journal_printv(log_levels[level], message, ap);
736 va_end(ap);
737 return (1);
738 }
739 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
740
741 /*
742 * Format and write the log message...
743 */
744
745 va_start(ap, message);
746
747 do
748 {
749 va_copy(ap2, ap);
750 status = format_log_line(message, ap2);
751 va_end(ap2);
752 }
753 while (status == 0);
754
755 va_end(ap);
756
757 if (status > 0)
758 return (cupsdWriteErrorLog(level, log_line));
759 else
760 return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
761 "Unable to allocate memory for log line!"));
762 }
763
764
765 /*
766 * 'cupsdLogPage()' - Log a page to the page log file.
767 */
768
769 int /* O - 1 on success, 0 on error */
cupsdLogPage(cupsd_job_t * job,const char * page)770 cupsdLogPage(cupsd_job_t *job, /* I - Job being printed */
771 const char *page) /* I - Page being printed */
772 {
773 int i; /* Looping var */
774 char buffer[2048], /* Buffer for page log */
775 *bufptr, /* Pointer into buffer */
776 name[256]; /* Attribute name */
777 const char *format, /* Pointer into PageLogFormat */
778 *nameend; /* End of attribute name */
779 ipp_attribute_t *attr; /* Current attribute */
780 char number[256]; /* Page number */
781 int copies; /* Number of copies */
782
783
784 /*
785 * Format the line going into the page log...
786 */
787
788 if (!PageLogFormat)
789 return (1);
790
791 strlcpy(number, "1", sizeof(number));
792 copies = 1;
793 sscanf(page, "%255s%d", number, &copies);
794
795 for (format = PageLogFormat, bufptr = buffer; *format; format ++)
796 {
797 if (*format == '%')
798 {
799 format ++;
800
801 switch (*format)
802 {
803 case '%' : /* Literal % */
804 if (bufptr < (buffer + sizeof(buffer) - 1))
805 *bufptr++ = '%';
806 break;
807
808 case 'p' : /* Printer name */
809 strlcpy(bufptr, job->dest, sizeof(buffer) - (size_t)(bufptr - buffer));
810 bufptr += strlen(bufptr);
811 break;
812
813 case 'j' : /* Job ID */
814 snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", job->id);
815 bufptr += strlen(bufptr);
816 break;
817
818 case 'u' : /* Username */
819 strlcpy(bufptr, job->username ? job->username : "-", sizeof(buffer) - (size_t)(bufptr - buffer));
820 bufptr += strlen(bufptr);
821 break;
822
823 case 'T' : /* Date and time */
824 strlcpy(bufptr, cupsdGetDateTime(NULL, LogTimeFormat), sizeof(buffer) - (size_t)(bufptr - buffer));
825 bufptr += strlen(bufptr);
826 break;
827
828 case 'P' : /* Page number */
829 strlcpy(bufptr, number, sizeof(buffer) - (size_t)(bufptr - buffer));
830 bufptr += strlen(bufptr);
831 break;
832
833 case 'C' : /* Number of copies */
834 snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", copies);
835 bufptr += strlen(bufptr);
836 break;
837
838 case '{' : /* {attribute} */
839 if ((nameend = strchr(format, '}')) != NULL && (size_t)(nameend - format - 2) < (sizeof(name) - 1))
840 {
841 /*
842 * Pull the name from inside the brackets...
843 */
844
845 memcpy(name, format + 1, (size_t)(nameend - format - 1));
846 name[nameend - format - 1] = '\0';
847
848 format = nameend;
849
850 attr = ippFindAttribute(job->attrs, name, IPP_TAG_ZERO);
851 if (!attr && !strcmp(name, "job-billing"))
852 {
853 /*
854 * Handle alias "job-account-id" (which was standardized after
855 * "job-billing" was defined for CUPS...
856 */
857
858 attr = ippFindAttribute(job->attrs, "job-account-id", IPP_TAG_ZERO);
859 }
860 else if (!attr && !strcmp(name, "media"))
861 {
862 /*
863 * Handle alias "media-col" which uses dimensions instead of
864 * names...
865 */
866
867 attr = ippFindAttribute(job->attrs, "media-col/media-size", IPP_TAG_BEGIN_COLLECTION);
868 }
869
870 if (attr)
871 {
872 /*
873 * Add the attribute value...
874 */
875
876 for (i = 0;
877 i < attr->num_values &&
878 bufptr < (buffer + sizeof(buffer) - 1);
879 i ++)
880 {
881 if (i)
882 *bufptr++ = ',';
883
884 switch (attr->value_tag)
885 {
886 case IPP_TAG_INTEGER :
887 case IPP_TAG_ENUM :
888 snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", attr->values[i].integer);
889 bufptr += strlen(bufptr);
890 break;
891
892 case IPP_TAG_BOOLEAN :
893 snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", attr->values[i].boolean);
894 bufptr += strlen(bufptr);
895 break;
896
897 case IPP_TAG_TEXTLANG :
898 case IPP_TAG_NAMELANG :
899 case IPP_TAG_TEXT :
900 case IPP_TAG_NAME :
901 case IPP_TAG_KEYWORD :
902 case IPP_TAG_URI :
903 case IPP_TAG_URISCHEME :
904 case IPP_TAG_CHARSET :
905 case IPP_TAG_LANGUAGE :
906 case IPP_TAG_MIMETYPE :
907 strlcpy(bufptr, attr->values[i].string.text, sizeof(buffer) - (size_t)(bufptr - buffer));
908 bufptr += strlen(bufptr);
909 break;
910
911 case IPP_TAG_BEGIN_COLLECTION :
912 if (!strcmp(attr->name, "media-size"))
913 {
914 ipp_attribute_t *x_dimension = ippFindAttribute(ippGetCollection(attr, 0), "x-dimension", IPP_TAG_INTEGER);
915 ipp_attribute_t *y_dimension = ippFindAttribute(ippGetCollection(attr, 0), "y-dimension", IPP_TAG_INTEGER);
916 /* Media dimensions */
917
918 if (x_dimension && y_dimension)
919 {
920 pwg_media_t *pwg = pwgMediaForSize(ippGetInteger(x_dimension, 0), ippGetInteger(y_dimension, 0));
921 /* PWG media name */
922 strlcpy(bufptr, pwg->pwg, sizeof(buffer) - (size_t)(bufptr - buffer));
923 break;
924 }
925 }
926
927 default :
928 strlcpy(bufptr, "???", sizeof(buffer) - (size_t)(bufptr - buffer));
929 bufptr += strlen(bufptr);
930 break;
931 }
932 }
933 }
934 else if (bufptr < (buffer + sizeof(buffer) - 1))
935 *bufptr++ = '-';
936 break;
937 }
938
939 default :
940 if (bufptr < (buffer + sizeof(buffer) - 2))
941 {
942 *bufptr++ = '%';
943 *bufptr++ = *format;
944 }
945 break;
946 }
947 }
948 else if (bufptr < (buffer + sizeof(buffer) - 1))
949 *bufptr++ = *format;
950 }
951
952 *bufptr = '\0';
953
954 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
955 if (!strcmp(PageLog, "syslog"))
956 {
957 static const char * const job_states[] =
958 { /* job-state strings */
959 "Pending",
960 "PendingHeld",
961 "Processing",
962 "ProcessingStopped",
963 "Canceled",
964 "Aborted",
965 "Completed"
966 };
967
968 sd_journal_send("MESSAGE=%s", buffer,
969 "PRIORITY=%i", LOG_INFO,
970 PWG_Event"=JobStateChanged",
971 PWG_ServiceURI"=%s", job->printer->uri,
972 PWG_JobID"=%d", job->id,
973 PWG_JobState"=%s", job_states[job->state_value - IPP_JSTATE_PENDING],
974 PWG_JobImpressionsCompleted"=%d", ippGetInteger(job->impressions, 0),
975 NULL);
976 return (1);
977 }
978
979 #elif defined(HAVE_VSYSLOG)
980 /*
981 * See if we are logging pages via syslog...
982 */
983
984 if (!strcmp(PageLog, "syslog"))
985 {
986 syslog(LOG_INFO, "%s", buffer);
987
988 return (1);
989 }
990 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
991
992 /*
993 * Not using syslog; check the log file...
994 */
995
996 if (!cupsdCheckLogFile(&PageFile, PageLog))
997 return (0);
998
999 /*
1000 * Print a page log entry of the form:
1001 *
1002 * printer user job-id [DD/MON/YYYY:HH:MM:SS +TTTT] page num-copies \
1003 * billing hostname
1004 */
1005
1006 cupsFilePrintf(PageFile, "%s\n", buffer);
1007 cupsFileFlush(PageFile);
1008
1009 return (1);
1010 }
1011
1012
1013 /*
1014 * 'cupsdLogRequest()' - Log an HTTP request in Common Log Format.
1015 */
1016
1017 int /* O - 1 on success, 0 on error */
cupsdLogRequest(cupsd_client_t * con,http_status_t code)1018 cupsdLogRequest(cupsd_client_t *con, /* I - Request to log */
1019 http_status_t code) /* I - Response code */
1020 {
1021 char temp[2048]; /* Temporary string for URI */
1022 static const char * const states[] = /* HTTP client states... */
1023 {
1024 "WAITING",
1025 "OPTIONS",
1026 "GET",
1027 "GET",
1028 "HEAD",
1029 "POST",
1030 "POST",
1031 "POST",
1032 "PUT",
1033 "PUT",
1034 "DELETE",
1035 "TRACE",
1036 "CLOSE",
1037 "STATUS"
1038 };
1039
1040
1041 /*
1042 * Filter requests as needed...
1043 */
1044
1045 if (AccessLogLevel == CUPSD_ACCESSLOG_NONE || !AccessLog)
1046 return (1);
1047 else if (AccessLogLevel < CUPSD_ACCESSLOG_ALL)
1048 {
1049 /*
1050 * Eliminate simple GET, POST, and PUT requests...
1051 */
1052
1053 if ((con->operation == HTTP_GET &&
1054 strncmp(con->uri, "/admin/conf", 11) &&
1055 strncmp(con->uri, "/admin/log", 10)) ||
1056 (con->operation == HTTP_POST && !con->request &&
1057 strncmp(con->uri, "/admin", 6)) ||
1058 (con->operation != HTTP_GET && con->operation != HTTP_POST &&
1059 con->operation != HTTP_PUT))
1060 return (1);
1061
1062 if (con->request && con->response &&
1063 (con->response->request.status.status_code < IPP_REDIRECTION_OTHER_SITE ||
1064 con->response->request.status.status_code == IPP_NOT_FOUND))
1065 {
1066 /*
1067 * Check successful requests...
1068 */
1069
1070 ipp_op_t op = con->request->request.op.operation_id;
1071 static cupsd_accesslog_t standard_ops[] =
1072 {
1073 CUPSD_ACCESSLOG_ALL, /* reserved */
1074 CUPSD_ACCESSLOG_ALL, /* reserved */
1075 CUPSD_ACCESSLOG_ACTIONS,/* Print-Job */
1076 CUPSD_ACCESSLOG_ACTIONS,/* Print-URI */
1077 CUPSD_ACCESSLOG_ACTIONS,/* Validate-Job */
1078 CUPSD_ACCESSLOG_ACTIONS,/* Create-Job */
1079 CUPSD_ACCESSLOG_ACTIONS,/* Send-Document */
1080 CUPSD_ACCESSLOG_ACTIONS,/* Send-URI */
1081 CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Job */
1082 CUPSD_ACCESSLOG_ALL, /* Get-Job-Attributes */
1083 CUPSD_ACCESSLOG_ALL, /* Get-Jobs */
1084 CUPSD_ACCESSLOG_ALL, /* Get-Printer-Attributes */
1085 CUPSD_ACCESSLOG_ACTIONS,/* Hold-Job */
1086 CUPSD_ACCESSLOG_ACTIONS,/* Release-Job */
1087 CUPSD_ACCESSLOG_ACTIONS,/* Restart-Job */
1088 CUPSD_ACCESSLOG_ALL, /* reserved */
1089 CUPSD_ACCESSLOG_CONFIG, /* Pause-Printer */
1090 CUPSD_ACCESSLOG_CONFIG, /* Resume-Printer */
1091 CUPSD_ACCESSLOG_CONFIG, /* Purge-Jobs */
1092 CUPSD_ACCESSLOG_CONFIG, /* Set-Printer-Attributes */
1093 CUPSD_ACCESSLOG_ACTIONS,/* Set-Job-Attributes */
1094 CUPSD_ACCESSLOG_CONFIG, /* Get-Printer-Supported-Values */
1095 CUPSD_ACCESSLOG_ACTIONS,/* Create-Printer-Subscription */
1096 CUPSD_ACCESSLOG_ACTIONS,/* Create-Job-Subscription */
1097 CUPSD_ACCESSLOG_ALL, /* Get-Subscription-Attributes */
1098 CUPSD_ACCESSLOG_ALL, /* Get-Subscriptions */
1099 CUPSD_ACCESSLOG_ACTIONS,/* Renew-Subscription */
1100 CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Subscription */
1101 CUPSD_ACCESSLOG_ALL, /* Get-Notifications */
1102 CUPSD_ACCESSLOG_ACTIONS,/* Send-Notifications */
1103 CUPSD_ACCESSLOG_ALL, /* reserved */
1104 CUPSD_ACCESSLOG_ALL, /* reserved */
1105 CUPSD_ACCESSLOG_ALL, /* reserved */
1106 CUPSD_ACCESSLOG_ALL, /* Get-Print-Support-Files */
1107 CUPSD_ACCESSLOG_CONFIG, /* Enable-Printer */
1108 CUPSD_ACCESSLOG_CONFIG, /* Disable-Printer */
1109 CUPSD_ACCESSLOG_CONFIG, /* Pause-Printer-After-Current-Job */
1110 CUPSD_ACCESSLOG_ACTIONS,/* Hold-New-Jobs */
1111 CUPSD_ACCESSLOG_ACTIONS,/* Release-Held-New-Jobs */
1112 CUPSD_ACCESSLOG_CONFIG, /* Deactivate-Printer */
1113 CUPSD_ACCESSLOG_CONFIG, /* Activate-Printer */
1114 CUPSD_ACCESSLOG_CONFIG, /* Restart-Printer */
1115 CUPSD_ACCESSLOG_CONFIG, /* Shutdown-Printer */
1116 CUPSD_ACCESSLOG_CONFIG, /* Startup-Printer */
1117 CUPSD_ACCESSLOG_ACTIONS,/* Reprocess-Job */
1118 CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Current-Job */
1119 CUPSD_ACCESSLOG_ACTIONS,/* Suspend-Current-Job */
1120 CUPSD_ACCESSLOG_ACTIONS,/* Resume-Job */
1121 CUPSD_ACCESSLOG_ACTIONS,/* Promote-Job */
1122 CUPSD_ACCESSLOG_ACTIONS /* Schedule-Job-After */
1123 };
1124 static cupsd_accesslog_t cups_ops[] =
1125 {
1126 CUPSD_ACCESSLOG_ALL, /* CUPS-Get-Default */
1127 CUPSD_ACCESSLOG_ALL, /* CUPS-Get-Printers */
1128 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Add-Modify-Printer */
1129 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Delete-Printer */
1130 CUPSD_ACCESSLOG_ALL, /* CUPS-Get-Classes */
1131 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Add-Modify-Class */
1132 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Delete-Class */
1133 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Accept-Jobs */
1134 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Reject-Jobs */
1135 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Set-Default */
1136 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Get-Devices */
1137 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Get-PPDs */
1138 CUPSD_ACCESSLOG_ACTIONS,/* CUPS-Move-Job */
1139 CUPSD_ACCESSLOG_ACTIONS,/* CUPS-Authenticate-Job */
1140 CUPSD_ACCESSLOG_ALL /* CUPS-Get-PPD */
1141 };
1142
1143
1144 if ((op <= IPP_SCHEDULE_JOB_AFTER && standard_ops[op] > AccessLogLevel) ||
1145 (op >= CUPS_GET_DEFAULT && op <= CUPS_GET_PPD &&
1146 cups_ops[op - CUPS_GET_DEFAULT] > AccessLogLevel))
1147 return (1);
1148 }
1149 }
1150
1151 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
1152 if (!strcmp(AccessLog, "syslog"))
1153 {
1154 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) : "-");
1155 return (1);
1156 }
1157
1158 #elif defined(HAVE_VSYSLOG)
1159 /*
1160 * See if we are logging accesses via syslog...
1161 */
1162
1163 if (!strcmp(AccessLog, "syslog"))
1164 {
1165 syslog(LOG_INFO,
1166 "REQUEST %s - %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
1167 con->http->hostname, con->username[0] != '\0' ? con->username : "-",
1168 states[con->operation], _httpEncodeURI(temp, con->uri, sizeof(temp)),
1169 con->http->version / 100, con->http->version % 100,
1170 code, CUPS_LLCAST con->bytes,
1171 con->request ?
1172 ippOpString(con->request->request.op.operation_id) : "-",
1173 con->response ?
1174 ippErrorString(con->response->request.status.status_code) : "-");
1175
1176 return (1);
1177 }
1178 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
1179
1180 /*
1181 * Not using syslog; check the log file...
1182 */
1183
1184 if (!cupsdCheckLogFile(&AccessFile, AccessLog))
1185 return (0);
1186
1187 /*
1188 * Write a log of the request in "common log format"...
1189 */
1190
1191 cupsFilePrintf(AccessFile,
1192 "%s - %s %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
1193 con->http->hostname,
1194 con->username[0] != '\0' ? con->username : "-",
1195 cupsdGetDateTime(&(con->start), LogTimeFormat),
1196 states[con->operation],
1197 _httpEncodeURI(temp, con->uri, sizeof(temp)),
1198 con->http->version / 100, con->http->version % 100,
1199 code, CUPS_LLCAST con->bytes,
1200 con->request ?
1201 ippOpString(con->request->request.op.operation_id) : "-",
1202 con->response ?
1203 ippErrorString(con->response->request.status.status_code) :
1204 "-");
1205
1206 cupsFileFlush(AccessFile);
1207
1208 return (1);
1209 }
1210
1211
1212 /*
1213 * 'cupsdWriteErrorLog()' - Write a line to the ErrorLog.
1214 */
1215
1216 int /* O - 1 on success, 0 on failure */
cupsdWriteErrorLog(int level,const char * message)1217 cupsdWriteErrorLog(int level, /* I - Log level */
1218 const char *message) /* I - Message string */
1219 {
1220 int ret = 1; /* Return value */
1221 static const char levels[] = /* Log levels... */
1222 {
1223 ' ',
1224 'X',
1225 'A',
1226 'C',
1227 'E',
1228 'W',
1229 'N',
1230 'I',
1231 'D',
1232 'd'
1233 };
1234
1235
1236 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
1237 if (!strcmp(ErrorLog, "syslog"))
1238 {
1239 sd_journal_print(log_levels[level], "%s", message);
1240 return (1);
1241 }
1242
1243 #elif defined(HAVE_VSYSLOG)
1244 /*
1245 * See if we are logging errors via syslog...
1246 */
1247
1248 if (!strcmp(ErrorLog, "syslog"))
1249 {
1250 syslog(log_levels[level], "%s", message);
1251 return (1);
1252 }
1253 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
1254
1255 /*
1256 * Not using syslog; check the log file...
1257 */
1258
1259 _cupsMutexLock(&log_mutex);
1260
1261 if (!cupsdCheckLogFile(&ErrorFile, ErrorLog))
1262 {
1263 ret = 0;
1264 }
1265 else
1266 {
1267 /*
1268 * Write the log message...
1269 */
1270
1271 cupsFilePrintf(ErrorFile, "%c %s %s\n", levels[level],
1272 cupsdGetDateTime(NULL, LogTimeFormat), message);
1273 cupsFileFlush(ErrorFile);
1274 }
1275
1276 _cupsMutexUnlock(&log_mutex);
1277
1278 return (ret);
1279 }
1280
1281
1282 /*
1283 * 'format_log_line()' - Format a line for a log file.
1284 *
1285 * This function resizes a global string buffer as needed. Each call returns
1286 * a pointer to this buffer, so the contents are only good until the next call
1287 * to format_log_line()...
1288 */
1289
1290 static int /* O - -1 for fatal, 0 for retry, 1 for success */
format_log_line(const char * message,va_list ap)1291 format_log_line(const char *message, /* I - Printf-style format string */
1292 va_list ap) /* I - Argument list */
1293 {
1294 ssize_t len; /* Length of formatted line */
1295
1296
1297 /*
1298 * Allocate the line buffer as needed...
1299 */
1300
1301 if (!log_linesize)
1302 {
1303 log_linesize = 8192;
1304 log_line = malloc(log_linesize);
1305
1306 if (!log_line)
1307 return (-1);
1308 }
1309
1310 /*
1311 * Format the log message...
1312 */
1313
1314 len = _cups_safe_vsnprintf(log_line, log_linesize, message, ap);
1315
1316 /*
1317 * Resize the buffer as needed...
1318 */
1319
1320 if ((size_t)len >= log_linesize && log_linesize < 65536)
1321 {
1322 char *temp; /* Temporary string pointer */
1323
1324 len ++;
1325
1326 if (len < 8192)
1327 len = 8192;
1328 else if (len > 65536)
1329 len = 65536;
1330
1331 temp = realloc(log_line, (size_t)len);
1332
1333 if (temp)
1334 {
1335 log_line = temp;
1336 log_linesize = (size_t)len;
1337
1338 return (0);
1339 }
1340 }
1341
1342 return (1);
1343 }
1344