1 /* AirScan (a.k.a. eSCL) backend for SANE
2 *
3 * Copyright (C) 2019 and up by Alexander Pevzner (pzz@apevzner.com)
4 * See LICENSE for license terms and conditions
5 *
6 * Logging
7 */
8
9 #include "airscan.h"
10
11 #include <ctype.h>
12 #include <time.h>
13 #include <stdarg.h>
14 #include <stdlib.h>
15 #include <unistd.h>
16
17 /* Static variables */
18 static char *log_buffer;
19 static bool log_configured;
20 static uint64_t log_start_time;
21 static pthread_mutex_t log_mutex = PTHREAD_MUTEX_INITIALIZER;
22
23 /* Get time for logging purposes
24 */
25 static uint64_t
log_get_time(void)26 log_get_time (void)
27 {
28 struct timespec tms;
29
30 clock_gettime(CLOCK_MONOTONIC, &tms);
31 return ((uint64_t) tms.tv_nsec) + 1000000000 * (uint64_t) tms.tv_sec;
32 }
33
34 /* Initialize logging
35 *
36 * No log messages should be generated before this call
37 */
38 void
log_init(void)39 log_init (void)
40 {
41 log_buffer = str_new();
42 log_configured = false;
43 log_start_time = log_get_time();
44 }
45
46 /* Cleanup logging
47 *
48 * No log messages should be generated after this call
49 */
50 void
log_cleanup(void)51 log_cleanup (void)
52 {
53 mem_free(log_buffer);
54 log_buffer = NULL;
55 }
56
57 /* Flush buffered log to file
58 */
59 static void
log_flush(void)60 log_flush (void)
61 {
62 int rc = write(1, log_buffer, mem_len(log_buffer));
63 (void) rc;
64 str_trunc(log_buffer);
65 }
66
67 /* Notify logger that configuration is loaded and
68 * logger can configure itself
69 *
70 * This is safe to generate log messages before log_configure()
71 * is called. These messages will be buffered, and after
72 * logger is configured, either written or abandoned, depending
73 * on configuration
74 */
75 void
log_configure(void)76 log_configure (void)
77 {
78 log_configured = true;
79 if (conf.dbg_enabled) {
80 log_flush();
81 } else {
82 str_trunc(log_buffer);
83 }
84 }
85
86 /* Format time elapsed since logging began
87 */
88 static void
log_fmt_time(char * buf,size_t size)89 log_fmt_time (char *buf, size_t size)
90 {
91 uint64_t t = log_get_time() - log_start_time;
92 int hour, min, sec, msec;
93
94 sec = (int) (t / 1000000000);
95 msec = ((int) (t % 1000000000)) / 1000000;
96 hour = sec / 3600;
97 sec = sec % 3600;
98 min = sec / 60;
99 sec = sec % 60;
100
101 snprintf(buf, size, "%2.2d:%2.2d:%2.2d.%3.3d", hour, min, sec, msec);
102 }
103
104 /* log_ctx represents logging context
105 */
106 struct log_ctx {
107 const char *name; /* Log name */
108 trace *trace; /* Associated trace */
109 };
110
111 /* log_ctx_new creates new logging context
112 * If parent != NULL, new logging context will have its own prefix,
113 * but trace file will be inherited from parent
114 */
115 log_ctx*
log_ctx_new(const char * name,log_ctx * parent)116 log_ctx_new (const char *name, log_ctx *parent)
117 {
118 log_ctx *log = mem_new(log_ctx, 1);
119
120 log->name = str_trim(str_dup(name));
121
122 if (parent != NULL) {
123 log->trace = trace_ref(parent->trace);
124 } else {
125 log->trace = trace_open(name);
126 }
127
128 return log;
129 }
130
131 /* log_ctx_free destroys logging context
132 */
133 void
log_ctx_free(log_ctx * log)134 log_ctx_free (log_ctx *log)
135 {
136 trace_unref(log->trace);
137 mem_free((char*) log->name);
138 mem_free(log);
139 }
140
141 /* Get protocol trace associated with logging context
142 */
143 trace*
log_ctx_trace(log_ctx * log)144 log_ctx_trace (log_ctx *log)
145 {
146 return log->trace;
147 }
148
149 /* Write a log message
150 */
151 static void
log_message(log_ctx * log,bool trace_only,bool force,const char * fmt,va_list ap)152 log_message (log_ctx *log, bool trace_only, bool force,
153 const char *fmt, va_list ap)
154 {
155 trace *t = log ? log->trace : NULL;
156 char msg[4096];
157 int len = 0, namelen = 0, required_bytes = 0;
158 bool dont_log = trace_only ||
159 (log_configured && !conf.dbg_enabled && !force);
160
161 /* If logs suppressed and trace not in use, we have nothing
162 * to do */
163 if ((t == NULL) && dont_log) {
164 return;
165 }
166
167 /* Format a log message */
168 if (log != NULL) {
169 len += sprintf(msg, "%.64s: ", log->name);
170 namelen = len;
171 }
172
173 required_bytes = vsnprintf(msg + len, sizeof(msg) - len, fmt, ap);
174
175 /* vsnprintf returns the number of bytes required for the whole message,
176 * even if that exceeds the buffer size.
177 * If required_bytes exceeds space remaining in msg, we know msg is full.
178 * Otherwise, we can increment len by required_bytes.
179 */
180 if (required_bytes >= (int) sizeof(msg) - len) {
181 len = sizeof(msg) - 1;
182 } else {
183 len += required_bytes;
184 }
185
186 while (len > 0 && isspace((unsigned char) msg[len-1])) {
187 len --;
188 }
189
190 msg[len] = '\0';
191
192 /* Write to log */
193 if (!dont_log) {
194 pthread_mutex_lock(&log_mutex);
195
196 log_buffer = str_append(log_buffer, msg);
197 log_buffer = str_append_c(log_buffer, '\n');
198
199 if ((log_configured && conf.dbg_enabled) || force) {
200 log_flush();
201 }
202
203 pthread_mutex_unlock(&log_mutex);
204 }
205
206 /* Write to trace */
207 if (t != NULL) {
208 if (len > namelen) {
209 char prefix[64];
210 log_fmt_time(prefix, sizeof(prefix));
211 trace_printf(t, "%s: %s", prefix, msg);
212 } else {
213 trace_printf(t, "");
214 }
215 }
216 }
217
218 /* Write a debug message.
219 */
220 void
log_debug(log_ctx * log,const char * fmt,...)221 log_debug (log_ctx *log, const char *fmt, ...)
222 {
223 va_list ap;
224 va_start(ap, fmt);
225 log_message(log, false, false, fmt, ap);
226 va_end(ap);
227 }
228
229 /* Write a protocol trace message
230 */
231 void
log_trace(log_ctx * log,const char * fmt,...)232 log_trace (log_ctx *log, const char *fmt, ...)
233 {
234 va_list ap;
235 va_start(ap, fmt);
236 log_message(log, true, false, fmt, ap);
237 va_end(ap);
238 }
239
240 /* Write a block of data into protocol trace
241 */
242 void
log_trace_data(log_ctx * log,const char * content_type,const void * bytes,size_t size)243 log_trace_data (log_ctx *log, const char *content_type,
244 const void *bytes, size_t size)
245 {
246 http_data data = {
247 .content_type = content_type,
248 .bytes = bytes,
249 .size = size
250 };
251
252 trace_dump_body(log->trace, &data);
253 }
254
255 /* Write an error message and terminate a program.
256 */
257 void
log_panic(log_ctx * log,const char * fmt,...)258 log_panic (log_ctx *log, const char *fmt, ...)
259 {
260 va_list ap;
261
262 /* Note, log_buffer is not empty only if logger is not
263 * configured yet, but there are pending debug messages.
264 * At this case we discard these messages, but panic
265 * message is written anyway
266 */
267 pthread_mutex_lock(&log_mutex);
268 str_trunc(log_buffer);
269 pthread_mutex_unlock(&log_mutex);
270
271 va_start(ap, fmt);
272 log_message(log, false, true, fmt, ap);
273 va_end(ap);
274 abort();
275 }
276
277 /* vim:ts=8:sw=4:et
278 */
279