1 /*
2 * Log file routines for the CUPS scheduler.
3 *
4 * Copyright © 2020-2024 by OpenPrinting.
5 * Copyright © 2007-2018 by Apple Inc.
6 * Copyright © 1997-2007 by Easy Software Products, all rights reserved.
7 *
8 * Licensed under Apache License v2.0. See the file "LICENSE" for more
9 * information.
10 */
11
12 /*
13 * Include necessary headers...
14 */
15
16 #include "cupsd.h"
17 #include <stdarg.h>
18 #ifdef HAVE_ASL_H
19 # include <asl.h>
20 #elif defined(HAVE_SYSTEMD_SD_JOURNAL_H)
21 # define SD_JOURNAL_SUPPRESS_LOCATION
22 # include <systemd/sd-journal.h>
23 #endif /* HAVE_ASL_H */
24 #include <syslog.h>
25 #ifndef va_copy
26 # define va_copy(__list1, __list2) ((void)(__list1 = __list2))
27 #endif
28
29
30 /*
31 * Constants for log keys from PWG 5110.3 (PWG Common Log Format)...
32 */
33
34 #define PWG_DeviceUUID "DUU"
35 #define PWG_Event "E"
36 #define PWG_LogNaturalLanguage "NL"
37 #define PWG_Status "S"
38 #define PWG_ServiceURI "URI"
39 #define PWG_UserHost "UH"
40 #define PWG_UserName "UN"
41 #define PWG_UserURI "UU"
42 #define PWG_ServiceIsAcceptingJobs "IAJ"
43 #define PWG_ServiceState "ST"
44 #define PWG_ServiceStateReasons "SR"
45 #define PWG_ServiceUUID "SUU"
46 #define PWG_JobID "JID"
47 #define PWG_JobUUID "JUU"
48 #define PWG_JobImagesCompleted "JIM"
49 #define PWG_JobImpressionsCompleted "JIC"
50 #define PWG_JobDestinationURI "JD"
51 #define PWG_JobState "JS"
52 #define PWG_JobStateReasons "JR"
53 #define PWG_JobAccountingID "JA"
54 #define PWG_JobAcountingUserName "JAUN"
55 #define PWG_JobAccountingUserURI "JAUU"
56
57
58 /*
59 * Local globals...
60 */
61
62 static _cups_mutex_t log_mutex = _CUPS_MUTEX_INITIALIZER;
63 /* Mutex for logging */
64 static size_t log_linesize = 0; /* Size of line for output file */
65 static char *log_line = NULL; /* Line for output file */
66
67 #ifdef HAVE_ASL_H
68 static const int log_levels[] = /* ASL levels... */
69 {
70 ASL_LEVEL_EMERG,
71 ASL_LEVEL_EMERG,
72 ASL_LEVEL_ALERT,
73 ASL_LEVEL_CRIT,
74 ASL_LEVEL_ERR,
75 ASL_LEVEL_WARNING,
76 ASL_LEVEL_NOTICE,
77 ASL_LEVEL_INFO,
78 ASL_LEVEL_DEBUG,
79 ASL_LEVEL_DEBUG
80 };
81 #elif defined(HAVE_VSYSLOG) || defined(HAVE_SYSTEMD_SD_JOURNAL_H)
82 static const int log_levels[] = /* SYSLOG levels... */
83 {
84 0,
85 LOG_EMERG,
86 LOG_ALERT,
87 LOG_CRIT,
88 LOG_ERR,
89 LOG_WARNING,
90 LOG_NOTICE,
91 LOG_INFO,
92 LOG_DEBUG,
93 LOG_DEBUG
94 };
95 #endif /* HAVE_ASL_H */
96
97
98 /*
99 * Local functions...
100 */
101
102 static int format_log_line(const char *message, va_list ap);
103
104
105 /*
106 * 'cupsdCheckLogFile()' - Open/rotate a log file if it needs it.
107 */
108
109 int /* O - 1 if log file open */
cupsdCheckLogFile(cups_file_t ** lf,const char * logname)110 cupsdCheckLogFile(cups_file_t **lf, /* IO - Log file */
111 const char *logname) /* I - Log filename */
112 {
113 char backname[1024], /* Backup log filename */
114 filename[1024], /* Formatted log filename */
115 *ptr; /* Pointer into filename */
116 const char *logptr; /* Pointer into log filename */
117
118
119 /*
120 * See if we have a log file to check...
121 */
122
123 if (!lf || !logname || !logname[0])
124 return (1);
125
126 /*
127 * Handle logging to stderr...
128 */
129
130 if (!strcmp(logname, "stderr"))
131 {
132 *lf = LogStderr;
133 return (1);
134 }
135
136 /*
137 * Format the filename as needed...
138 */
139
140 if (!*lf ||
141 (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
142 MaxLogSize > 0))
143 {
144 /*
145 * Handle format strings...
146 */
147
148 filename[sizeof(filename) - 1] = '\0';
149
150 if (logname[0] != '/')
151 {
152 strlcpy(filename, ServerRoot, sizeof(filename));
153 strlcat(filename, "/", sizeof(filename));
154 }
155 else
156 filename[0] = '\0';
157
158 for (logptr = logname, ptr = filename + strlen(filename);
159 *logptr && ptr < (filename + sizeof(filename) - 1);
160 logptr ++)
161 if (*logptr == '%')
162 {
163 /*
164 * Format spec...
165 */
166
167 logptr ++;
168 if (*logptr == 's')
169 {
170 /*
171 * Insert the server name...
172 */
173
174 strlcpy(ptr, ServerName, sizeof(filename) - (size_t)(ptr - filename));
175 ptr += strlen(ptr);
176 }
177 else
178 {
179 /*
180 * Otherwise just insert the character...
181 */
182
183 *ptr++ = *logptr;
184 }
185 }
186 else
187 *ptr++ = *logptr;
188
189 *ptr = '\0';
190 }
191
192 /*
193 * See if the log file is open...
194 */
195
196 if (!*lf)
197 {
198 /*
199 * Nope, open the log file...
200 */
201
202 if ((*lf = cupsFileOpen(filename, "a")) == NULL)
203 {
204 /*
205 * If the file is in CUPS_LOGDIR then try to create a missing directory...
206 */
207
208 if (!strncmp(filename, CUPS_LOGDIR, strlen(CUPS_LOGDIR)))
209 {
210 /*
211 * Try updating the permissions of the containing log directory, using
212 * the log file permissions as a basis...
213 */
214
215 mode_t log_dir_perm = (mode_t)(0300 | LogFilePerm);
216 /* LogFilePerm + owner write/search */
217 if (log_dir_perm & 0040)
218 log_dir_perm |= 0010; /* Add group search */
219 if (log_dir_perm & 0004)
220 log_dir_perm |= 0001; /* Add other search */
221
222 cupsdCheckPermissions(CUPS_LOGDIR, NULL, log_dir_perm, RunUser, Group, 1, -1);
223
224 *lf = cupsFileOpen(filename, "a");
225 }
226
227 if (*lf == NULL)
228 {
229 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
230 sd_journal_print(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
231 #else
232 syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
233 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
234
235 if (FatalErrors & CUPSD_FATAL_LOG)
236 cupsdEndProcess(getpid(), 0);
237
238 return (0);
239 }
240 }
241
242 if (strncmp(filename, "/dev/", 5))
243 {
244 /*
245 * Change ownership and permissions of non-device logs...
246 */
247
248 fchown(cupsFileNumber(*lf), RunUser, LogFileGroup);
249 fchmod(cupsFileNumber(*lf), LogFilePerm);
250 }
251 }
252
253 /*
254 * Do we need to rotate the log?
255 */
256
257 if (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
258 MaxLogSize > 0)
259 {
260 /*
261 * Rotate log file...
262 */
263
264 cupsFileClose(*lf);
265
266 strlcpy(backname, filename, sizeof(backname));
267 strlcat(backname, ".O", sizeof(backname));
268
269 unlink(backname);
270 rename(filename, backname);
271
272 if ((*lf = cupsFileOpen(filename, "a")) == NULL)
273 {
274 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
275 sd_journal_print(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
276
277 #else
278 syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
279 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
280
281 if (FatalErrors & CUPSD_FATAL_LOG)
282 cupsdEndProcess(getpid(), 0);
283
284 return (0);
285 }
286
287 /*
288 * Change ownership and permissions of non-device logs...
289 */
290
291 fchown(cupsFileNumber(*lf), RunUser, LogFileGroup);
292 fchmod(cupsFileNumber(*lf), LogFilePerm);
293 }
294
295 return (1);
296 }
297
298
299 /*
300 * 'cupsdGetDateTime()' - Returns a pointer to a date/time string.
301 */
302
303 char * /* O - Date/time string */
cupsdGetDateTime(struct timeval * t,cupsd_time_t format)304 cupsdGetDateTime(struct timeval *t, /* I - Time value or NULL for current */
305 cupsd_time_t format) /* I - Format to use */
306 {
307 struct timeval curtime; /* Current time value */
308 struct tm date; /* Date/time value */
309 static struct timeval last_time = { 0, 0 };
310 /* Last time we formatted */
311 static char s[1024]; /* Date/time string */
312 static const char * const months[12] =/* Months */
313 {
314 "Jan",
315 "Feb",
316 "Mar",
317 "Apr",
318 "May",
319 "Jun",
320 "Jul",
321 "Aug",
322 "Sep",
323 "Oct",
324 "Nov",
325 "Dec"
326 };
327
328
329 /*
330 * Make sure we have a valid time...
331 */
332
333 if (!t)
334 {
335 gettimeofday(&curtime, NULL);
336 t = &curtime;
337 }
338
339 if (t->tv_sec != last_time.tv_sec ||
340 (LogTimeFormat == CUPSD_TIME_USECS && t->tv_usec != last_time.tv_usec))
341 {
342 last_time = *t;
343
344 /*
345 * Get the date and time from the UNIX time value, and then format it
346 * into a string. Note that we *can't* use the strftime() function since
347 * it is localized and will seriously confuse automatic programs if the
348 * month names are in the wrong language!
349 *
350 * Also, we use the "timezone" variable that contains the current timezone
351 * offset from GMT in seconds so that we are reporting local time in the
352 * log files. If you want GMT, set the TZ environment variable accordingly
353 * before starting the scheduler.
354 *
355 * (*BSD and Darwin store the timezone offset in the tm structure)
356 */
357
358 localtime_r(&(t->tv_sec), &date);
359
360 if (format == CUPSD_TIME_STANDARD)
361 snprintf(s, sizeof(s), "[%02d/%s/%04d:%02d:%02d:%02d %+03ld%02ld]",
362 date.tm_mday, months[date.tm_mon], 1900 + date.tm_year,
363 date.tm_hour, date.tm_min, date.tm_sec,
364 #ifdef HAVE_TM_GMTOFF
365 date.tm_gmtoff / 3600, (date.tm_gmtoff / 60) % 60);
366 #else
367 timezone / 3600, (timezone / 60) % 60);
368 #endif /* HAVE_TM_GMTOFF */
369 else
370 snprintf(s, sizeof(s), "[%02d/%s/%04d:%02d:%02d:%02d.%06d %+03ld%02ld]",
371 date.tm_mday, months[date.tm_mon], 1900 + date.tm_year,
372 date.tm_hour, date.tm_min, date.tm_sec, (int)t->tv_usec,
373 #ifdef HAVE_TM_GMTOFF
374 date.tm_gmtoff / 3600, (date.tm_gmtoff / 60) % 60);
375 #else
376 timezone / 3600, (timezone / 60) % 60);
377 #endif /* HAVE_TM_GMTOFF */
378 }
379
380 return (s);
381 }
382
383
384 /*
385 * 'cupsdLogFCMessage()' - Log a file checking message.
386 */
387
388 void
cupsdLogFCMessage(void * context,_cups_fc_result_t result,const char * message)389 cupsdLogFCMessage(
390 void *context, /* I - Printer (if any) */
391 _cups_fc_result_t result, /* I - Check result */
392 const char *message) /* I - Message to log */
393 {
394 cupsd_printer_t *p = (cupsd_printer_t *)context;
395 /* Printer */
396 cupsd_loglevel_t level; /* Log level */
397
398
399 if (result == _CUPS_FILE_CHECK_OK)
400 level = CUPSD_LOG_DEBUG2;
401 else
402 level = CUPSD_LOG_ERROR;
403
404 if (p)
405 {
406 cupsdLogMessage(level, "%s: %s", p->name, message);
407
408 if (result == _CUPS_FILE_CHECK_MISSING ||
409 result == _CUPS_FILE_CHECK_WRONG_TYPE)
410 {
411 strlcpy(p->state_message, message, sizeof(p->state_message));
412
413 if (cupsdSetPrinterReasons(p, "+cups-missing-filter-warning"))
414 cupsdAddEvent(CUPSD_EVENT_PRINTER_STATE, p, NULL, "%s", message);
415 }
416 else if (result == _CUPS_FILE_CHECK_PERMISSIONS ||
417 result == _CUPS_FILE_CHECK_RELATIVE_PATH)
418 {
419 strlcpy(p->state_message, message, sizeof(p->state_message));
420
421 if (cupsdSetPrinterReasons(p, "+cups-insecure-filter-warning"))
422 cupsdAddEvent(CUPSD_EVENT_PRINTER_STATE, p, NULL, "%s", message);
423 }
424 }
425 else
426 cupsdLogMessage(level, "%s", message);
427 }
428
429
430 #ifdef HAVE_GSSAPI
431 /*
432 * 'cupsdLogGSSMessage()' - Log a GSSAPI error...
433 */
434
435 int /* O - 1 on success, 0 on error */
cupsdLogGSSMessage(int level,OM_uint32 major_status,OM_uint32 minor_status,const char * message,...)436 cupsdLogGSSMessage(
437 int level, /* I - Log level */
438 OM_uint32 major_status, /* I - Major GSSAPI status */
439 OM_uint32 minor_status, /* I - Minor GSSAPI status */
440 const char *message, /* I - printf-style message string */
441 ...) /* I - Additional args as needed */
442 {
443 OM_uint32 err_major_status, /* Major status code for display */
444 err_minor_status; /* Minor status code for display */
445 OM_uint32 msg_ctx; /* Message context */
446 gss_buffer_desc major_status_string = GSS_C_EMPTY_BUFFER,
447 /* Major status message */
448 minor_status_string = GSS_C_EMPTY_BUFFER;
449 /* Minor status message */
450 int ret; /* Return value */
451 char buffer[8192]; /* Buffer for vsnprintf */
452
453
454 if (strchr(message, '%'))
455 {
456 /*
457 * Format the message string...
458 */
459
460 va_list ap; /* Pointer to arguments */
461
462 va_start(ap, message);
463 vsnprintf(buffer, sizeof(buffer), message, ap);
464 va_end(ap);
465
466 message = buffer;
467 }
468
469 msg_ctx = 0;
470 err_major_status = gss_display_status(&err_minor_status,
471 major_status,
472 GSS_C_GSS_CODE,
473 GSS_C_NO_OID,
474 &msg_ctx,
475 &major_status_string);
476
477 if (!GSS_ERROR(err_major_status))
478 gss_display_status(&err_minor_status, minor_status, GSS_C_MECH_CODE,
479 GSS_C_NULL_OID, &msg_ctx, &minor_status_string);
480
481 ret = cupsdLogMessage(level, "%s: %s, %s", message,
482 (char *)major_status_string.value,
483 (char *)minor_status_string.value);
484 gss_release_buffer(&err_minor_status, &major_status_string);
485 gss_release_buffer(&err_minor_status, &minor_status_string);
486
487 return (ret);
488 }
489 #endif /* HAVE_GSSAPI */
490
491
492 /*
493 * 'cupsdLogClient()' - Log a client message.
494 */
495
496 int /* O - 1 on success, 0 on error */
cupsdLogClient(cupsd_client_t * con,int level,const char * message,...)497 cupsdLogClient(cupsd_client_t *con, /* I - Client connection */
498 int level, /* I - Log level */
499 const char *message, /* I - Printf-style message string */
500 ...) /* I - Additional arguments as needed */
501 {
502 va_list ap, ap2; /* Argument pointers */
503 char clientmsg[1024];/* Format string for client message */
504 int status; /* Formatting status */
505
506
507 /*
508 * See if we want to log this message...
509 */
510
511 if (TestConfigFile || !ErrorLog)
512 return (1);
513
514 if (level > LogLevel)
515 return (1);
516
517 /*
518 * Format and write the log message...
519 */
520
521 if (con)
522 snprintf(clientmsg, sizeof(clientmsg), "[Client %d] %s", con->number,
523 message);
524 else
525 strlcpy(clientmsg, message, sizeof(clientmsg));
526
527 va_start(ap, message);
528
529 do
530 {
531 va_copy(ap2, ap);
532 status = format_log_line(clientmsg, ap2);
533 va_end(ap2);
534 }
535 while (status == 0);
536
537 va_end(ap);
538
539 if (status > 0)
540 return (cupsdWriteErrorLog(level, log_line));
541 else
542 return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
543 "Unable to allocate memory for log line."));
544 }
545
546
547 /*
548 * 'cupsdLogJob()' - Log a job message.
549 */
550
551 int /* O - 1 on success, 0 on error */
cupsdLogJob(cupsd_job_t * job,int level,const char * message,...)552 cupsdLogJob(cupsd_job_t *job, /* I - Job */
553 int level, /* I - Log level */
554 const char *message, /* I - Printf-style message string */
555 ...) /* I - Additional arguments as needed */
556 {
557 va_list ap, ap2; /* Argument pointers */
558 char jobmsg[1024]; /* Format string for job message */
559 int status; /* Formatting status */
560
561
562 /*
563 * See if we want to log this message...
564 */
565
566 if (TestConfigFile || !ErrorLog)
567 return (1);
568
569 if (level > LogLevel && LogDebugHistory <= 0)
570 return (1);
571
572 /*
573 * Format and write the log message...
574 */
575
576 if (job)
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 if (pwg)
923 {
924 strlcpy(bufptr, pwg->pwg, sizeof(buffer) - (size_t)(bufptr - buffer));
925 break;
926 }
927 }
928 }
929
930 default :
931 strlcpy(bufptr, "???", sizeof(buffer) - (size_t)(bufptr - buffer));
932 bufptr += strlen(bufptr);
933 break;
934 }
935 }
936 }
937 else if (bufptr < (buffer + sizeof(buffer) - 1))
938 *bufptr++ = '-';
939 break;
940 }
941
942 default :
943 if (bufptr < (buffer + sizeof(buffer) - 2))
944 {
945 *bufptr++ = '%';
946 *bufptr++ = *format;
947 }
948 break;
949 }
950 }
951 else if (bufptr < (buffer + sizeof(buffer) - 1))
952 *bufptr++ = *format;
953 }
954
955 *bufptr = '\0';
956
957 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
958 if (!strcmp(PageLog, "syslog"))
959 {
960 static const char * const job_states[] =
961 { /* job-state strings */
962 "Pending",
963 "PendingHeld",
964 "Processing",
965 "ProcessingStopped",
966 "Canceled",
967 "Aborted",
968 "Completed"
969 };
970
971 sd_journal_send("MESSAGE=%s", buffer,
972 "PRIORITY=%i", LOG_INFO,
973 PWG_Event"=JobStateChanged",
974 PWG_ServiceURI"=%s", job->printer->uri,
975 PWG_JobID"=%d", job->id,
976 PWG_JobState"=%s", job_states[job->state_value - IPP_JSTATE_PENDING],
977 PWG_JobImpressionsCompleted"=%d", ippGetInteger(job->impressions, 0),
978 NULL);
979 return (1);
980 }
981
982 #elif defined(HAVE_VSYSLOG)
983 /*
984 * See if we are logging pages via syslog...
985 */
986
987 if (!strcmp(PageLog, "syslog"))
988 {
989 syslog(LOG_INFO, "%s", buffer);
990
991 return (1);
992 }
993 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
994
995 /*
996 * Not using syslog; check the log file...
997 */
998
999 if (!cupsdCheckLogFile(&PageFile, PageLog))
1000 return (0);
1001
1002 /*
1003 * Print a page log entry of the form:
1004 *
1005 * printer user job-id [DD/MON/YYYY:HH:MM:SS +TTTT] page num-copies \
1006 * billing hostname
1007 */
1008
1009 cupsFilePrintf(PageFile, "%s\n", buffer);
1010 cupsFileFlush(PageFile);
1011
1012 return (1);
1013 }
1014
1015
1016 /*
1017 * 'cupsdLogRequest()' - Log an HTTP request in Common Log Format.
1018 */
1019
1020 int /* O - 1 on success, 0 on error */
cupsdLogRequest(cupsd_client_t * con,http_status_t code)1021 cupsdLogRequest(cupsd_client_t *con, /* I - Request to log */
1022 http_status_t code) /* I - Response code */
1023 {
1024 char temp[2048]; /* Temporary string for URI */
1025 static const char * const states[] = /* HTTP client states... */
1026 {
1027 "WAITING",
1028 "OPTIONS",
1029 "GET",
1030 "GET",
1031 "HEAD",
1032 "POST",
1033 "POST",
1034 "POST",
1035 "PUT",
1036 "PUT",
1037 "DELETE",
1038 "TRACE",
1039 "CLOSE",
1040 "STATUS"
1041 };
1042
1043
1044 /*
1045 * Filter requests as needed...
1046 */
1047
1048 if (AccessLogLevel == CUPSD_ACCESSLOG_NONE || !AccessLog)
1049 return (1);
1050 else if (AccessLogLevel < CUPSD_ACCESSLOG_ALL)
1051 {
1052 /*
1053 * Eliminate simple GET, POST, and PUT requests...
1054 */
1055
1056 if ((con->operation == HTTP_GET &&
1057 strncmp(con->uri, "/admin/conf", 11) &&
1058 strncmp(con->uri, "/admin/log", 10)) ||
1059 (con->operation == HTTP_POST && !con->request &&
1060 strncmp(con->uri, "/admin", 6)) ||
1061 (con->operation != HTTP_GET && con->operation != HTTP_POST &&
1062 con->operation != HTTP_PUT))
1063 return (1);
1064
1065 if (con->request && con->response &&
1066 (con->response->request.status.status_code < IPP_REDIRECTION_OTHER_SITE ||
1067 con->response->request.status.status_code == IPP_NOT_FOUND))
1068 {
1069 /*
1070 * Check successful requests...
1071 */
1072
1073 ipp_op_t op = con->request->request.op.operation_id;
1074 static cupsd_accesslog_t standard_ops[] =
1075 {
1076 CUPSD_ACCESSLOG_ALL, /* reserved */
1077 CUPSD_ACCESSLOG_ALL, /* reserved */
1078 CUPSD_ACCESSLOG_ACTIONS,/* Print-Job */
1079 CUPSD_ACCESSLOG_ACTIONS,/* Print-URI */
1080 CUPSD_ACCESSLOG_ACTIONS,/* Validate-Job */
1081 CUPSD_ACCESSLOG_ACTIONS,/* Create-Job */
1082 CUPSD_ACCESSLOG_ACTIONS,/* Send-Document */
1083 CUPSD_ACCESSLOG_ACTIONS,/* Send-URI */
1084 CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Job */
1085 CUPSD_ACCESSLOG_ALL, /* Get-Job-Attributes */
1086 CUPSD_ACCESSLOG_ALL, /* Get-Jobs */
1087 CUPSD_ACCESSLOG_ALL, /* Get-Printer-Attributes */
1088 CUPSD_ACCESSLOG_ACTIONS,/* Hold-Job */
1089 CUPSD_ACCESSLOG_ACTIONS,/* Release-Job */
1090 CUPSD_ACCESSLOG_ACTIONS,/* Restart-Job */
1091 CUPSD_ACCESSLOG_ALL, /* reserved */
1092 CUPSD_ACCESSLOG_CONFIG, /* Pause-Printer */
1093 CUPSD_ACCESSLOG_CONFIG, /* Resume-Printer */
1094 CUPSD_ACCESSLOG_CONFIG, /* Purge-Jobs */
1095 CUPSD_ACCESSLOG_CONFIG, /* Set-Printer-Attributes */
1096 CUPSD_ACCESSLOG_ACTIONS,/* Set-Job-Attributes */
1097 CUPSD_ACCESSLOG_CONFIG, /* Get-Printer-Supported-Values */
1098 CUPSD_ACCESSLOG_ACTIONS,/* Create-Printer-Subscription */
1099 CUPSD_ACCESSLOG_ACTIONS,/* Create-Job-Subscription */
1100 CUPSD_ACCESSLOG_ALL, /* Get-Subscription-Attributes */
1101 CUPSD_ACCESSLOG_ALL, /* Get-Subscriptions */
1102 CUPSD_ACCESSLOG_ACTIONS,/* Renew-Subscription */
1103 CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Subscription */
1104 CUPSD_ACCESSLOG_ALL, /* Get-Notifications */
1105 CUPSD_ACCESSLOG_ACTIONS,/* Send-Notifications */
1106 CUPSD_ACCESSLOG_ALL, /* reserved */
1107 CUPSD_ACCESSLOG_ALL, /* reserved */
1108 CUPSD_ACCESSLOG_ALL, /* reserved */
1109 CUPSD_ACCESSLOG_ALL, /* Get-Print-Support-Files */
1110 CUPSD_ACCESSLOG_CONFIG, /* Enable-Printer */
1111 CUPSD_ACCESSLOG_CONFIG, /* Disable-Printer */
1112 CUPSD_ACCESSLOG_CONFIG, /* Pause-Printer-After-Current-Job */
1113 CUPSD_ACCESSLOG_ACTIONS,/* Hold-New-Jobs */
1114 CUPSD_ACCESSLOG_ACTIONS,/* Release-Held-New-Jobs */
1115 CUPSD_ACCESSLOG_CONFIG, /* Deactivate-Printer */
1116 CUPSD_ACCESSLOG_CONFIG, /* Activate-Printer */
1117 CUPSD_ACCESSLOG_CONFIG, /* Restart-Printer */
1118 CUPSD_ACCESSLOG_CONFIG, /* Shutdown-Printer */
1119 CUPSD_ACCESSLOG_CONFIG, /* Startup-Printer */
1120 CUPSD_ACCESSLOG_ACTIONS,/* Reprocess-Job */
1121 CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Current-Job */
1122 CUPSD_ACCESSLOG_ACTIONS,/* Suspend-Current-Job */
1123 CUPSD_ACCESSLOG_ACTIONS,/* Resume-Job */
1124 CUPSD_ACCESSLOG_ACTIONS,/* Promote-Job */
1125 CUPSD_ACCESSLOG_ACTIONS /* Schedule-Job-After */
1126 };
1127 static cupsd_accesslog_t cups_ops[] =
1128 {
1129 CUPSD_ACCESSLOG_ALL, /* CUPS-Get-Default */
1130 CUPSD_ACCESSLOG_ALL, /* CUPS-Get-Printers */
1131 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Add-Modify-Printer */
1132 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Delete-Printer */
1133 CUPSD_ACCESSLOG_ALL, /* CUPS-Get-Classes */
1134 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Add-Modify-Class */
1135 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Delete-Class */
1136 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Accept-Jobs */
1137 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Reject-Jobs */
1138 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Set-Default */
1139 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Get-Devices */
1140 CUPSD_ACCESSLOG_CONFIG, /* CUPS-Get-PPDs */
1141 CUPSD_ACCESSLOG_ACTIONS,/* CUPS-Move-Job */
1142 CUPSD_ACCESSLOG_ACTIONS,/* CUPS-Authenticate-Job */
1143 CUPSD_ACCESSLOG_ALL /* CUPS-Get-PPD */
1144 };
1145
1146
1147 if ((op <= IPP_SCHEDULE_JOB_AFTER && standard_ops[op] > AccessLogLevel) ||
1148 (op >= CUPS_GET_DEFAULT && op <= CUPS_GET_PPD &&
1149 cups_ops[op - CUPS_GET_DEFAULT] > AccessLogLevel))
1150 return (1);
1151 }
1152 }
1153
1154 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
1155 if (!strcmp(AccessLog, "syslog"))
1156 {
1157 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) : "-");
1158 return (1);
1159 }
1160
1161 #elif defined(HAVE_VSYSLOG)
1162 /*
1163 * See if we are logging accesses via syslog...
1164 */
1165
1166 if (!strcmp(AccessLog, "syslog"))
1167 {
1168 syslog(LOG_INFO,
1169 "REQUEST %s - %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
1170 con->http->hostname, con->username[0] != '\0' ? con->username : "-",
1171 states[con->operation], _httpEncodeURI(temp, con->uri, sizeof(temp)),
1172 con->http->version / 100, con->http->version % 100,
1173 code, CUPS_LLCAST con->bytes,
1174 con->request ?
1175 ippOpString(con->request->request.op.operation_id) : "-",
1176 con->response ?
1177 ippErrorString(con->response->request.status.status_code) : "-");
1178
1179 return (1);
1180 }
1181 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
1182
1183 /*
1184 * Not using syslog; check the log file...
1185 */
1186
1187 if (!cupsdCheckLogFile(&AccessFile, AccessLog))
1188 return (0);
1189
1190 /*
1191 * Write a log of the request in "common log format"...
1192 */
1193
1194 cupsFilePrintf(AccessFile,
1195 "%s - %s %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
1196 con->http->hostname,
1197 con->username[0] != '\0' ? con->username : "-",
1198 cupsdGetDateTime(&(con->start), LogTimeFormat),
1199 states[con->operation],
1200 _httpEncodeURI(temp, con->uri, sizeof(temp)),
1201 con->http->version / 100, con->http->version % 100,
1202 code, CUPS_LLCAST con->bytes,
1203 con->request ?
1204 ippOpString(con->request->request.op.operation_id) : "-",
1205 con->response ?
1206 ippErrorString(con->response->request.status.status_code) :
1207 "-");
1208
1209 cupsFileFlush(AccessFile);
1210
1211 return (1);
1212 }
1213
1214
1215 /*
1216 * 'cupsdWriteErrorLog()' - Write a line to the ErrorLog.
1217 */
1218
1219 int /* O - 1 on success, 0 on failure */
cupsdWriteErrorLog(int level,const char * message)1220 cupsdWriteErrorLog(int level, /* I - Log level */
1221 const char *message) /* I - Message string */
1222 {
1223 int ret = 1; /* Return value */
1224 static const char levels[] = /* Log levels... */
1225 {
1226 ' ',
1227 'X',
1228 'A',
1229 'C',
1230 'E',
1231 'W',
1232 'N',
1233 'I',
1234 'D',
1235 'd'
1236 };
1237
1238
1239 #ifdef HAVE_SYSTEMD_SD_JOURNAL_H
1240 if (!strcmp(ErrorLog, "syslog"))
1241 {
1242 sd_journal_print(log_levels[level], "%s", message);
1243 return (1);
1244 }
1245
1246 #elif defined(HAVE_VSYSLOG)
1247 /*
1248 * See if we are logging errors via syslog...
1249 */
1250
1251 if (!strcmp(ErrorLog, "syslog"))
1252 {
1253 syslog(log_levels[level], "%s", message);
1254 return (1);
1255 }
1256 #endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
1257
1258 /*
1259 * Not using syslog; check the log file...
1260 */
1261
1262 _cupsMutexLock(&log_mutex);
1263
1264 if (!cupsdCheckLogFile(&ErrorFile, ErrorLog))
1265 {
1266 ret = 0;
1267 }
1268 else
1269 {
1270 /*
1271 * Write the log message...
1272 */
1273
1274 cupsFilePrintf(ErrorFile, "%c %s %s\n", levels[level],
1275 cupsdGetDateTime(NULL, LogTimeFormat), message);
1276 cupsFileFlush(ErrorFile);
1277 }
1278
1279 _cupsMutexUnlock(&log_mutex);
1280
1281 return (ret);
1282 }
1283
1284
1285 /*
1286 * 'format_log_line()' - Format a line for a log file.
1287 *
1288 * This function resizes a global string buffer as needed. Each call returns
1289 * a pointer to this buffer, so the contents are only good until the next call
1290 * to format_log_line()...
1291 */
1292
1293 static int /* O - -1 for fatal, 0 for retry, 1 for success */
format_log_line(const char * message,va_list ap)1294 format_log_line(const char *message, /* I - Printf-style format string */
1295 va_list ap) /* I - Argument list */
1296 {
1297 ssize_t len; /* Length of formatted line */
1298
1299
1300 /*
1301 * Allocate the line buffer as needed...
1302 */
1303
1304 if (!log_linesize)
1305 {
1306 log_linesize = 8192;
1307 log_line = malloc(log_linesize);
1308
1309 if (!log_line)
1310 return (-1);
1311 }
1312
1313 /*
1314 * Format the log message...
1315 */
1316
1317 len = _cups_safe_vsnprintf(log_line, log_linesize, message, ap);
1318
1319 /*
1320 * Resize the buffer as needed...
1321 */
1322
1323 if ((size_t)len >= log_linesize && log_linesize < 65536)
1324 {
1325 char *temp; /* Temporary string pointer */
1326
1327 len ++;
1328
1329 if (len < 8192)
1330 len = 8192;
1331 else if (len > 65536)
1332 len = 65536;
1333
1334 temp = realloc(log_line, (size_t)len);
1335
1336 if (temp)
1337 {
1338 log_line = temp;
1339 log_linesize = (size_t)len;
1340
1341 return (0);
1342 }
1343 }
1344
1345 return (1);
1346 }
1347