Branch data Line data Source code
1 : : /* zxlog.c - Liberty oriented logging facility with log signing and encryption
2 : : * Copyright (c) 2010 Sampo Kellomaki (sampo@iki.fi), All Rights Reserved.
3 : : * Copyright (c) 2006-2009 Symlabs (symlabs@symlabs.com), All Rights Reserved.
4 : : * Author: Sampo Kellomaki (sampo@iki.fi)
5 : : * This is confidential unpublished proprietary source code of the author.
6 : : * NO WARRANTY, not even implied warranties. Contains trade secrets.
7 : : * Distribution prohibited unless authorized in writing.
8 : : * Licensed under Apache License 2.0, see file COPYING.
9 : : * $Id: zxlog.c,v 1.32 2009-11-24 23:53:40 sampo Exp $
10 : : *
11 : : * 18.11.2006, created --Sampo
12 : : * 10.10.2007, added ipport --Sampo
13 : : * 7.10.2008, added inline documentation --Sampo
14 : : * 29.8.2009, added hmac chaining field --Sampo
15 : : * 12.3.2010, added per user logging facility --Sampo
16 : : *
17 : : * See also: Logging chapter in README.zxid
18 : : */
19 : :
20 : : #include "platform.h" /* needed on Win32 for pthread_mutex_lock() et al. */
21 : :
22 : : #include <fcntl.h>
23 : : #include <string.h>
24 : : #include <stdarg.h>
25 : : #include <stdio.h>
26 : : #include <stdlib.h>
27 : : #include <errno.h>
28 : : #include <time.h>
29 : : #include <sys/types.h>
30 : : #include <sys/stat.h>
31 : :
32 : : #ifdef USE_OPENSSL
33 : : #include <openssl/x509.h>
34 : : #include <openssl/rsa.h>
35 : : #include <openssl/evp.h>
36 : : #include <openssl/aes.h>
37 : : #endif
38 : :
39 : : #include "errmac.h"
40 : : #include "zxid.h"
41 : : #include "zxidutil.h" /* for zx_zlib_raw_deflate(), safe_basis_64, and name_from_path */
42 : : #include "zxidconf.h"
43 : : #include "c/zx-data.h" /* Generated. If missing, run `make dep ENA_GEN=1' */
44 : :
45 : : #define ZXID_LOG_DIR "log/"
46 : : #define ZXLOG_TIME_FMT "%04d%02d%02d-%02d%02d%02d.%03ld"
47 : : #define ZXLOG_TIME_ARG(t,usec) t.tm_year + 1900, t.tm_mon + 1, t.tm_mday, \
48 : : t.tm_hour, t.tm_min, t.tm_sec, usec/1000
49 : :
50 : : /*() Allocate memory for logging purpose.
51 : : * Generally memory allocation goes via zx_alloc() family of functions. However
52 : : * dues to special requirements of cryptographically implemeted logging,
53 : : * we maintain this special allocation function (which backends to zx_alloc()).
54 : : * Among the special features: This functin makes sure the buffer size is
55 : : * rounded up to multiple of nonce to accommodate block ciphers.
56 : : *
57 : : * This function is considered internal. Do not use unless you know what you are doing. */
58 : :
59 : : /* Called by: zxlog_write_line x3 */
60 : : static char* zxlog_alloc_zbuf(zxid_conf* cf, int *zlen, char* zbuf, int len, char* sig, int nonce)
61 : 9 : {
62 : : char* p;
63 : 9 : int siz = nonce + 2 + len + *zlen;
64 [ + + + - ]: 9 : ROUND_UP(siz, nonce); /* Round up to block size */
65 : 9 : p = ZX_ALLOC(cf->ctx, siz);
66 [ + + ]: 9 : if (nonce)
67 : 6 : zx_rand(p, nonce);
68 : 9 : p[nonce] = (len >> 8) & 0xff;
69 : 9 : p[nonce+1] = len & 0xff;
70 [ + + ]: 9 : if (len) {
71 : 6 : memcpy(p+nonce+2, sig, len);
72 : 6 : ZX_FREE(cf->ctx, sig);
73 : : }
74 : 9 : memcpy(p+nonce+2+len, zbuf, *zlen);
75 : 9 : ZX_FREE(cf->ctx, zbuf);
76 : 9 : *zlen += nonce + 2 + len;
77 : 9 : return p;
78 : : }
79 : :
80 : : /*() Write a line to a log, taking care of all formalities of locking and
81 : : * observing all special options for signing and encryption of the logs.
82 : : * Not usually called directly (but you can if you want to), this is the
83 : : * work horse behind zxlog().
84 : : *
85 : : * cf:: ZXID configuration object, used for memory allocation.
86 : : * c_path:: Path to the log file, as C string
87 : : * encflags:: Encryption flags. See LOG_ERR or LOG_ACT configuration options in zxidconf.h
88 : : * n:: length of log data
89 : : * logbuf:: The data that should be logged
90 : : */
91 : :
92 : : /* Called by: test_mode x12, zxlog_output x2 */
93 : : void zxlog_write_line(zxid_conf* cf, char* c_path, int encflags, int n, const char* logbuf)
94 : 5575 : {
95 : : EVP_PKEY* log_sign_pkey;
96 : : struct rsa_st* rsa_pkey;
97 : : struct aes_key_st aes_key;
98 : 5575 : int len = 0, blen, zlen;
99 : 5575 : char sigletter = 'P';
100 : 5575 : char encletter = 'P';
101 : : char* p;
102 : 5575 : char* sig = 0;
103 : : char* zbuf;
104 : : char* b64;
105 : : char sigbuf[28+4]; /* Space for "SP " and sha1 */
106 : : char keybuf[16];
107 : : char ivec[16];
108 [ + + ]: 5575 : if (n == -2)
109 : 12 : n = strlen(logbuf);
110 [ + + ]: 5575 : if (encflags & 0x70) { /* Encrypt check */
111 : 9 : zbuf = zx_zlib_raw_deflate(cf->ctx, n-1, logbuf, &zlen);
112 [ + + - + ]: 9 : switch (encflags & 0x06) { /* Sign check */
113 : : case 0x02: /* Sx plain sha1 */
114 : 3 : sigletter = 'S';
115 : 3 : sig = ZX_ALLOC(cf->ctx, 20);
116 : 3 : SHA1((unsigned char*)zbuf, zlen, (unsigned char*)sig);
117 : 3 : len = 20;
118 : 3 : break;
119 : : case 0x04: /* Rx RSA-SHA1 signature */
120 : 3 : sigletter = 'R';
121 [ - + # # ]: 3 : LOCK(cf->mx, "logsign wrln");
122 [ - + ]: 3 : if (!(log_sign_pkey = cf->log_sign_pkey))
123 : 0 : log_sign_pkey = cf->log_sign_pkey = zxid_read_private_key(cf, "logsign-nopw-cert.pem");
124 [ - + # # ]: 3 : UNLOCK(cf->mx, "logsign wrln");
125 [ - + ]: 3 : if (!log_sign_pkey)
126 : 0 : break;
127 : 3 : len = zxsig_data(cf->ctx, zlen, zbuf, &sig, log_sign_pkey, "enc log line");
128 : 3 : break;
129 : : case 0x06: /* Dx DSA-SHA1 signature */
130 : 0 : ERR("DSA-SHA1 sig not implemented in encrypted mode. Use RSA-SHA1 or none. %x", encflags);
131 : : break;
132 : : case 0: break; /* Px no signing */
133 : : }
134 : :
135 [ + + - + : 9 : switch (encflags & 0x70) {
- - ]
136 : : case 0x10: /* xZ RFC1951 zip + safe base64 */
137 : 3 : encletter = 'Z';
138 : 3 : zbuf = zxlog_alloc_zbuf(cf, &zlen, zbuf, len, sig, 0);
139 : 3 : break;
140 : : case 0x20: /* xA RSA-AES */
141 : 3 : encletter = 'A';
142 : 3 : zbuf = zxlog_alloc_zbuf(cf, &zlen, zbuf, len, sig, 16);
143 : 3 : zx_rand(keybuf, 16);
144 : 3 : AES_set_encrypt_key((unsigned char*)keybuf, 128, &aes_key);
145 : 3 : memcpy(ivec, zbuf, sizeof(ivec));
146 : 3 : AES_cbc_encrypt((unsigned char*)zbuf+16, (unsigned char*)zbuf+16, zlen-16, &aes_key, (unsigned char*)ivec, 1);
147 [ + - ]: 3 : ROUND_UP(zlen, 16); /* Round up to block size */
148 : :
149 [ - + # # ]: 3 : LOCK(cf->mx, "logenc wrln");
150 [ - + ]: 3 : if (!cf->log_enc_cert)
151 : 0 : cf->log_enc_cert = zxid_read_cert(cf, "logenc-nopw-cert.pem");
152 : 3 : rsa_pkey = zx_get_rsa_pub_from_cert(cf->log_enc_cert, "log_enc_cert");
153 [ - + # # ]: 3 : UNLOCK(cf->mx, "logenc wrln");
154 [ - + ]: 3 : if (!rsa_pkey)
155 : 0 : break;
156 : :
157 : 3 : len = RSA_size(rsa_pkey);
158 : 3 : sig = ZX_ALLOC(cf->ctx, len);
159 [ - + ]: 3 : if (RSA_public_encrypt(16, (unsigned char*)keybuf, (unsigned char*)sig, rsa_pkey, RSA_PKCS1_OAEP_PADDING) < 0) {
160 : 0 : ERR("RSA enc fail %x", encflags);
161 : 0 : zx_report_openssl_error("zxlog rsa enc");
162 : 0 : return;
163 : : }
164 : 3 : p = ZX_ALLOC(cf->ctx, 2 + len + zlen);
165 : 3 : p[0] = (len >> 8) & 0xff;
166 : 3 : p[1] = len & 0xff;
167 : 3 : memcpy(p+2, sig, len);
168 : 3 : memcpy(p+2+len, zbuf, zlen);
169 : 3 : ZX_FREE(cf->ctx, sig);
170 : 3 : ZX_FREE(cf->ctx, zbuf);
171 : 3 : zbuf = p;
172 : 3 : zlen += 2 + len;
173 : 3 : break;
174 : : case 0x30: /* xT RSA-3DES */
175 : 0 : encletter = 'T';
176 : 0 : ERR("Enc not implemented %x", encflags);
177 : 0 : break;
178 : : case 0x40: /* xB AES */
179 : 3 : encletter = 'B';
180 : 3 : zbuf = zxlog_alloc_zbuf(cf, &zlen, zbuf, len, sig, 16);
181 [ - + ]: 3 : if (!cf->log_symkey[0])
182 : 0 : zx_get_symkey(cf, "logenc.key", cf->log_symkey);
183 : 3 : AES_set_encrypt_key((unsigned char*)cf->log_symkey, 128, &aes_key);
184 : 3 : memcpy(ivec, zbuf, sizeof(ivec));
185 : 3 : AES_cbc_encrypt((unsigned char*)zbuf+16, (unsigned char*)zbuf+16, zlen-16, &aes_key, (unsigned char*)ivec, 1);
186 [ + - ]: 3 : ROUND_UP(zlen, 16); /* Round up to block size */
187 : 3 : break;
188 : : case 0x50: /* xU 3DES */
189 : 0 : encletter = 'U';
190 : 0 : ERR("Enc not implemented %x", encflags);
191 : 0 : break;
192 : : default:
193 : 0 : ERR("Enc not implemented %x", encflags);
194 : : break;
195 : : }
196 : :
197 : 9 : blen = SIMPLE_BASE64_LEN(zlen) + 3 + 1;
198 : 9 : b64 = ZX_ALLOC(cf->ctx, blen);
199 : 9 : b64[0] = sigletter;
200 : 9 : b64[1] = encletter;
201 : 9 : b64[2] = ' ';
202 : 9 : p = base64_fancy_raw(zbuf, zlen, b64+3, safe_basis_64, 1<<31, 0, 0, '.');
203 : 9 : blen = p-b64 + 1;
204 : 9 : *p = '\n';
205 : 9 : write2_or_append_lock_c_path(c_path, 0, 0, blen, b64, "zxlog enc", SEEK_END, O_APPEND);
206 : 9 : return;
207 : : }
208 : :
209 : : /* Plain text, possibly signed. */
210 : :
211 [ + + - + : 5566 : switch (encflags & 0x06) {
- ]
212 : : case 0x02: /* SP plain sha1 */
213 : 1 : strcpy(sigbuf, "SP ");
214 : 1 : sha1_safe_base64(sigbuf+3, n-1, logbuf);
215 : 1 : sigbuf[3+27] = ' ';
216 : 1 : len = 3+27+1;
217 : 1 : p = sigbuf;
218 : 1 : break;
219 : : case 0x04: /* RP RSA-SHA1 signature */
220 [ - + # # ]: 1 : LOCK(cf->mx, "logsign wrln");
221 [ - + ]: 1 : if (!(log_sign_pkey = cf->log_sign_pkey))
222 : 0 : log_sign_pkey = cf->log_sign_pkey = zxid_read_private_key(cf, "logsign-nopw-cert.pem");
223 [ - + # # ]: 1 : UNLOCK(cf->mx, "logsign wrln");
224 [ - + ]: 1 : if (!log_sign_pkey)
225 : 0 : break;
226 : 1 : zlen = zxsig_data(cf->ctx, n-1, logbuf, &zbuf, log_sign_pkey, "log line");
227 : 1 : len = SIMPLE_BASE64_LEN(zlen) + 4;
228 : 1 : sig = ZX_ALLOC(cf->ctx, len);
229 : 1 : strcpy(sig, "RP ");
230 : 1 : p = base64_fancy_raw(zbuf, zlen, sig+3, safe_basis_64, 1<<31, 0, 0, '.');
231 : 1 : len = p-sig + 1;
232 : 1 : *p = ' ';
233 : 1 : p = sig;
234 : 1 : break;
235 : : case 0x06: /* DP DSA-SHA1 signature */
236 : 0 : ERR("DSA-SHA1 signature not implemented %x", encflags);
237 : 0 : break;
238 : : case 0: /* Plain logging, no signing, no encryption. */
239 : 5564 : len = 5;
240 : 5564 : p = "PP - ";
241 : : break;
242 : : }
243 : 5566 : write2_or_append_lock_c_path(c_path, len, p, n, logbuf, "zxlog sig", SEEK_END, O_APPEND);
244 [ + + ]: 5566 : if (sig)
245 : 1 : ZX_FREE(cf->ctx, sig);
246 : : }
247 : :
248 : : /*() Helper function for formatting all kinds of logs. */
249 : :
250 : : static int zxlog_fmt(zxid_conf* cf, /* 1 */
251 : : int len, char* logbuf,
252 : : struct timeval* ourts, /* 2 null allowed, will use current time */
253 : : struct timeval* srcts, /* 3 null allowed, will use start of unix epoch... */
254 : : const char* ipport, /* 4 null allowed, -:- or cf->ipport if not given */
255 : : struct zx_str* entid, /* 5 null allowed, - if not given */
256 : : struct zx_str* msgid, /* 6 null allowed, - if not given */
257 : : struct zx_str* a7nid, /* 7 null allowed, - if not given */
258 : : struct zx_str* nid, /* 8 null allowed, - if not given */
259 : : const char* sigval, /* 9 null allowed, - if not given */
260 : : const char* res, /* 10 */
261 : : const char* op, /* 11 */
262 : : const char* arg, /* 12 null allowed, - if not given */
263 : : const char* fmt, /* 13 null allowed as format, ends the line */
264 : : va_list ap)
265 : 3199 : {
266 : : int n;
267 : : char* p;
268 : : char sha1_name[28];
269 : : struct tm ot;
270 : : struct tm st;
271 : : struct timeval ourtsdefault;
272 : : struct timeval srctsdefault;
273 : :
274 : : /* Prepare values */
275 : :
276 [ + + ]: 3199 : if (!ourts) {
277 : 1523 : ourts = &ourtsdefault;
278 : 1523 : GETTIMEOFDAY(ourts, 0);
279 : : }
280 [ + + ]: 3199 : if (!srcts) {
281 : 1174 : srcts = &srctsdefault;
282 : 1174 : srctsdefault.tv_sec = 0;
283 : 1174 : srctsdefault.tv_usec = 501000;
284 : : }
285 : 3199 : GMTIME_R(ourts->tv_sec, ot);
286 : 3199 : GMTIME_R(srcts->tv_sec, st);
287 : :
288 [ + + + - : 5110 : if (entid && entid->len && entid->s) {
+ - ]
289 : 1911 : sha1_safe_base64(sha1_name, entid->len, entid->s);
290 : 1911 : sha1_name[27] = 0;
291 : : } else {
292 : 1288 : sha1_name[0] = '-';
293 : 1288 : sha1_name[1] = 0;
294 : : }
295 : :
296 [ + + ]: 3199 : if (!ipport) {
297 : 3012 : ipport = cf->ipport;
298 [ + + ]: 3012 : if (!ipport)
299 : 378 : ipport = "-:-";
300 : : }
301 : :
302 : : /* Format */
303 : :
304 [ + + + + : 3199 : n = snprintf(logbuf, len-3, ZXLOG_TIME_FMT " " ZXLOG_TIME_FMT
+ + + + +
+ + + + +
+ + ]
305 : : " %s %s" /* ipport sha1_name-of-ent */
306 : : " %.*s"
307 : : " %.*s"
308 : : " %.*s"
309 : : " %s %s %s %s %s ",
310 : : ZXLOG_TIME_ARG(ot, ourts->tv_usec), ZXLOG_TIME_ARG(st, srcts->tv_usec),
311 : : ipport, sha1_name,
312 : : msgid?msgid->len:1, msgid?msgid->s:"-",
313 : : a7nid?a7nid->len:1, a7nid?a7nid->s:"-",
314 : : nid?nid->len:1, nid?nid->s:"-",
315 : : zx_instance, STRNULLCHKD(sigval), res, op, arg?arg:"-");
316 : 3199 : logbuf[len-1] = 0; /* must terminate manually as on win32 nul is not guaranteed */
317 [ + - - + ]: 3199 : if (n <= 0 || n >= len-3) {
318 [ # # ]: 0 : if (n < 0) {
319 : 0 : perror("snprintf");
320 [ # # # # ]: 0 : D("Broken snprintf? Impossible to compute length of string. Be sure to `export LANG=C' if you get errors about multibyte characters. Length returned: %d", n);
321 : : }
322 [ # # # # ]: 0 : D("Log buffer too short: %d chars needed", n);
323 [ # # ]: 0 : if (n <= 0)
324 : 0 : n = 0;
325 : : else
326 : 0 : n = len-3;
327 : : } else { /* Space left: try printing the format string as well! */
328 : 3199 : p = logbuf+n;
329 [ + + + + ]: 3948 : if (fmt && fmt[0]) {
330 : 749 : n = vsnprintf(p, len-n-2, fmt, ap);
331 : 749 : logbuf[len-1] = 0; /* must terminate manually as on win32 nul term is not guaranteed */
332 [ + - - + ]: 749 : if (n <= 0 || n >= len-(p-logbuf)-2) {
333 [ # # ]: 0 : if (n < 0) {
334 : 0 : perror("vsnprintf");
335 [ # # # # ]: 0 : D("Broken vsnprintf? Impossible to compute length of string. Be sure to `export LANG=C' if you get errors about multibyte characters. Length returned: %d", n);
336 : : }
337 [ # # # # ]: 0 : D("Log buffer truncated during format print: %d chars needed", n);
338 [ # # ]: 0 : if (n <= 0)
339 : 0 : n = p-logbuf;
340 : : else
341 : 0 : n = len-(p-logbuf)-2;
342 : : } else
343 : 749 : n += p-logbuf;
344 : : } else {
345 : 2450 : logbuf[n++] = '-';
346 : : }
347 : : }
348 : 3199 : logbuf[n++] = '\n';
349 : 3199 : logbuf[n] = 0;
350 : : /*logbuf[len-1] = 0;*/
351 : 3199 : return n;
352 : : }
353 : :
354 : : /*() Figure out which log file should receive the message */
355 : :
356 : : /* Called by: */
357 : : static int zxlog_output(zxid_conf* cf, int n, const char* logbuf, const char* res)
358 : 2364 : {
359 : : char c_path[ZXID_MAX_BUF];
360 : : DD("LOG(%.*s)", n-1, logbuf);
361 [ - + # # : 2364 : if ((cf->log_err_in_act || res[0] == 'K') && cf->log_act) {
+ - ]
362 : 2364 : name_from_path(c_path, sizeof(c_path), "%s" ZXID_LOG_DIR "act", cf->path);
363 : 2364 : zxlog_write_line(cf, c_path, cf->log_act, n, logbuf);
364 : : }
365 [ + - - + : 2364 : if (cf->log_err && (cf->log_act_in_err || res[0] != 'K')) { /* If enabled, everything goes to err */
# # ]
366 : 2364 : name_from_path(c_path, sizeof(c_path), "%s" ZXID_LOG_DIR "err", cf->path);
367 : 2364 : zxlog_write_line(cf, c_path, cf->log_err, n, logbuf);
368 : : }
369 : 2364 : return 0;
370 : : }
371 : :
372 : : /*(i) Log to activity and/or error log depending on ~res~ and configuration settings.
373 : : * This is the main audit logging function you should call. Please see <<link:../../html/zxid-log.html: zxid-log.pd>>
374 : : * for detailed description of the log format and features. See <<link:../../html/zxid-conf.html: zxid-conf.pd>> for
375 : : * configuration options governing the logging. (*** check the links)
376 : : *
377 : : * Proper audit trail is essential for any high value transactions based on SSO. Also
378 : : * some SAML protocol Processing Rules, such as duplicate detection, depend on the
379 : : * logging.
380 : : *
381 : : * cf (1):: ZXID configuration object, used for configuration options and memory allocation
382 : : * ourts (2):: Timestamp as observed by localhost. Typically the wall clock
383 : : * time. See gettimeofday(3)
384 : : * srcts (3):: Timestamp claimed by the message to which the log entry pertains
385 : : * ipport (4):: IP address and port number from which the message appears to have originated
386 : : * entid (5):: Entity ID to which the message pertains, usually the issuer. Null ok.
387 : : * msgid (6):: Message ID, can be used for correlation to establish audit trail continuity
388 : : * from request to response. Null ok.
389 : : * a7nid (7):: Assertion ID, if message contained assertion (outermost and first
390 : : * assertion if there are multiple relevant assertions). Null ok.
391 : : * nid (8):: Name ID pertaining to the message
392 : : * sigval (9):: Signature validation letters
393 : : * res (10):: Result letters
394 : : * op (11):: Operation code for the message
395 : : * arg (12):: Operation specific argument
396 : : * fmt, ... :: Free format message conveying additional information
397 : : * return:: 0 on success, nonzero on failure (often ignored as zxlog() is very
398 : : * robust and rarely fails - and when it does, situation is so hopeless that
399 : : * you would not be able to report its failure anyway)
400 : : */
401 : :
402 : : /* Called by: zxid_an_page_cf, zxid_anoint_sso_a7n, zxid_anoint_sso_resp, zxid_chk_sig, zxid_decode_redir_or_post x2, zxid_fed_mgmt_cf, zxid_get_ent_by_sha1_name, zxid_get_ent_ss, zxid_get_meta x2, zxid_idp_dispatch, zxid_idp_select_zxstr_cf_cgi, zxid_idp_soap_dispatch x2, zxid_idp_soap_parse, zxid_parse_conf_raw, zxid_parse_meta, zxid_saml_ok x2, zxid_simple_render_ses, zxid_simple_ses_active_cf, zxid_sp_anon_finalize, zxid_sp_deref_art x5, zxid_sp_dig_sso_a7n x2, zxid_sp_dispatch, zxid_sp_meta, zxid_sp_mni_redir, zxid_sp_mni_soap, zxid_sp_slo_redir, zxid_sp_slo_soap, zxid_sp_soap_dispatch x2, zxid_sp_soap_parse, zxid_sp_sso_finalize x2, zxid_start_sso_url x3 */
403 : : int zxlog(zxid_conf* cf, /* 1 */
404 : : struct timeval* ourts, /* 2 null allowed, will use current time */
405 : : struct timeval* srcts, /* 3 null allowed, will use start of unix epoch + 501 usec */
406 : : const char* ipport, /* 4 null allowed, -:- or cf->ipport if not given */
407 : : struct zx_str* entid, /* 5 null allowed, - if not given */
408 : : struct zx_str* msgid, /* 6 null allowed, - if not given */
409 : : struct zx_str* a7nid, /* 7 null allowed, - if not given */
410 : : struct zx_str* nid, /* 8 null allowed, - if not given */
411 : : const char* sigval, /* 9 null allowed, - if not given */
412 : : const char* res, /* 10 */
413 : : const char* op, /* 11 */
414 : : const char* arg, /* 12 null allowed, - if not given */
415 : : const char* fmt, ...) /* 13 null allowed as format, ends the line w/o further ado */
416 : 2165 : {
417 : : int n;
418 : : char logbuf[1024];
419 : : va_list ap;
420 : :
421 : : /* Avoid computation if logging is hopeless. */
422 : :
423 [ - + # # : 2165 : if (!((cf->log_err_in_act || res[0] == 'K') && cf->log_act)
- + # # #
# ]
424 : : && !(cf->log_err && res[0] != 'K')) {
425 : 0 : return 0;
426 : : }
427 : :
428 : 2165 : va_start(ap, fmt);
429 : 2165 : n = zxlog_fmt(cf, sizeof(logbuf), logbuf,
430 : : ourts, srcts, ipport, entid, msgid, a7nid, nid, sigval, res,
431 : : op, arg, fmt, ap);
432 : 2165 : va_end(ap);
433 : 2165 : return zxlog_output(cf, n, logbuf, res);
434 : : }
435 : :
436 : : /*() Log to activity and/or error log depending on ~res~ and configuration settings.
437 : : * This variant uses the ses object to extract many of the log fields. These fields
438 : : * were populated to ses by zxid_wsp_validate()
439 : : */
440 : :
441 : : int zxlogwsp(zxid_conf* cf, /* 1 */
442 : : zxid_ses* ses, /* 2 */
443 : : const char* res, /* 3 */
444 : : const char* op, /* 4 */
445 : : const char* arg, /* 5 null allowed, - if not given */
446 : : const char* fmt, ...) /* 13 null allowed as format, ends the line w/o further ado */
447 : 199 : {
448 : : int n;
449 : : char logbuf[1024];
450 : : va_list ap;
451 : :
452 : : /* Avoid computation if logging is hopeless. */
453 : :
454 [ - + # # : 199 : if (!((cf->log_err_in_act || res[0] == 'K') && cf->log_act)
- + # # #
# ]
455 : : && !(cf->log_err && res[0] != 'K')) {
456 : 0 : return 0;
457 : : }
458 : :
459 : 199 : va_start(ap, fmt);
460 [ + - - + : 199 : n = zxlog_fmt(cf, sizeof(logbuf), logbuf,
+ - + + +
- + - + -
+ + + - +
- + - +
- ]
461 : : 0, ses?&ses->srcts:0, ses?ses->ipport:0,
462 : : ses?ses->issuer:0, ses?ses->wsp_msgid:0,
463 : : ses&&ses->a7n?&ses->a7n->ID->g:0,
464 : : ses?ZX_GET_CONTENT(ses->nameid):0,
465 : : ses&&ses->sigres?&ses->sigres:"-", res,
466 : : op, arg, fmt, ap);
467 : 199 : va_end(ap);
468 : 199 : return zxlog_output(cf, n, logbuf, res);
469 : : }
470 : :
471 : : /*() Log user specific data */
472 : :
473 : : int zxlogusr(zxid_conf* cf, /* 1 */
474 : : const char* uid,
475 : : struct timeval* ourts, /* 2 null allowed, will use current time */
476 : : struct timeval* srcts, /* 3 null allowed, will use start of unix epoch + 501 usec */
477 : : const char* ipport, /* 4 null allowed, -:- or cf->ipport if not given */
478 : : struct zx_str* entid, /* 5 null allowed, - if not given */
479 : : struct zx_str* msgid, /* 6 null allowed, - if not given */
480 : : struct zx_str* a7nid, /* 7 null allowed, - if not given */
481 : : struct zx_str* nid, /* 8 null allowed, - if not given */
482 : : const char* sigval, /* 9 null allowed, - if not given */
483 : : const char* res, /* 10 */
484 : : const char* op, /* 11 */
485 : : const char* arg, /* 12 null allowed, - if not given */
486 : : const char* fmt, ...) /* 13 null allowed as format, ends the line w/o further ado */
487 : 835 : {
488 : : int n;
489 : : char logbuf[1024];
490 : : char c_path[ZXID_MAX_BUF];
491 : : va_list ap;
492 : :
493 [ - + ]: 835 : if (!uid) {
494 : 0 : ERR("NULL uid argument %p", cf);
495 : 0 : return 1;
496 : : }
497 : :
498 : 835 : va_start(ap, fmt);
499 : 835 : n = zxlog_fmt(cf, sizeof(logbuf), logbuf,
500 : : ourts, srcts, ipport, entid, msgid, a7nid, nid, sigval, res,
501 : : op, arg, fmt, ap);
502 : 835 : va_end(ap);
503 : :
504 : : /* Output stage */
505 : :
506 [ + - - + ]: 835 : D("UID(%s) LOG(%.*s)", uid, n-1, logbuf);
507 : 835 : name_from_path(c_path, sizeof(c_path), "%s" ZXID_UID_DIR "%s/.log", cf->path, uid);
508 : 835 : zxlog_write_line(cf, c_path, cf->log_act, n, logbuf);
509 : 835 : return 0;
510 : : }
511 : :
512 : : /*() Compute path for logging. Optionally attempt to create the necessary
513 : : * directories if they are missing (you should do `make dirs' rather than
514 : : * depend on this).
515 : : *
516 : : * cf:: ZXID configuration object uded for deternining root if the logging
517 : : * hierarchy, see PATH configuration option. Also used for memory allocation.
518 : : * entid:: Issuer or target entity ID. For wire messages the URL.
519 : : * objid:: AssertionID or MessageID. For wire messages the payload.
520 : : * dir:: Directory prefix indicating branch of audit trail ("rely/" or "issue/")
521 : : * kind:: Kind of object, used as path component ("/a7n/" or "/msg/")
522 : : * create_dirs:: Flag: should creating directories be attempted. Usually 1 if intent
523 : : * is to write a file to the computed path. Usually 0 if the intent is to read.
524 : : * return:: The path, as zx_str or 0 if failure */
525 : :
526 : : /* Called by: zxid_anoint_a7n, zxid_anoint_sso_resp, zxid_decode_redir_or_post x2, zxid_saml2_post_enc, zxid_saml2_redir_enc, zxid_soap_cgi_resp_body, zxid_sp_sso_finalize, zxid_wsc_valid_re_env, zxid_wsf_validate_a7n, zxid_wsp_validate */
527 : : struct zx_str* zxlog_path(zxid_conf* cf,
528 : : struct zx_str* entid, /* issuer or target entity ID */
529 : : struct zx_str* objid, /* AssertionID or MessageID */
530 : : const char* dir, /* rely/ or issue/ */
531 : : const char* kind, /* /a7n/ or /msg/ */
532 : : int create_dirs)
533 : 1060 : {
534 : : struct stat st;
535 : 1060 : int dir_len = strlen(dir);
536 : 1060 : int kind_len = strlen(kind);
537 : 1060 : int len = cf->path_len + sizeof("log/")-1 + dir_len + 27 + kind_len + 27;
538 : 1060 : char* s = ZX_ALLOC(cf->ctx, len+1);
539 : : char* p;
540 : :
541 [ + + ]: 1060 : if (!entid) {
542 [ + - + - ]: 18 : ERR("No EntityID supplied %p dir(%s) kind(%s)", objid, STRNULLCHK(dir), STRNULLCHK(kind));
543 : 18 : ZX_FREE(cf->ctx, s);
544 : 18 : return 0;
545 : : }
546 : :
547 : 1042 : memcpy(s, cf->path, cf->path_len);
548 : 1042 : p = s + cf->path_len;
549 : 1042 : memcpy(p, "log/", sizeof("log/"));
550 : 1042 : p += sizeof("log/")-1;
551 [ - + ]: 1042 : if (stat(s, &st)) {
552 [ # # ]: 0 : ERR("zxid log directory missing path(%s): giving up (%d %s)", s, errno, STRERROR(errno));
553 : 0 : ZX_FREE(cf->ctx, s);
554 : 0 : return 0;
555 : : }
556 : :
557 : 1042 : memcpy(p, dir, dir_len+1);
558 : 1042 : p += dir_len;
559 [ - + ]: 1042 : if (stat(s, &st)) {
560 [ # # ]: 0 : if (create_dirs) {
561 [ # # ]: 0 : if (MKDIR(s, 0777)) {
562 [ # # ]: 0 : ERR("mkdir path(%s) failed: %d %s", s, errno, STRERROR(errno));
563 : 0 : ZX_FREE(cf->ctx, s);
564 : 0 : return 0;
565 : : }
566 : : } else {
567 [ # # ]: 0 : ERR("directory missing path(%s) and no create_dirs (%d %s)", s, errno, STRERROR(errno));
568 : 0 : ZX_FREE(cf->ctx, s);
569 : 0 : return 0;
570 : : }
571 : : }
572 : :
573 : 1042 : sha1_safe_base64(p, entid->len, entid->s);
574 : 1042 : p[27] = 0;
575 : 1042 : p+=27;
576 [ - + ]: 1042 : if (stat(s, &st)) {
577 [ # # ]: 0 : if (create_dirs) {
578 [ # # ]: 0 : if (MKDIR(s, 0777)) {
579 [ # # ]: 0 : ERR("mkdir path(%s) failed: %d %s", s, errno, STRERROR(errno));
580 : 0 : ZX_FREE(cf->ctx, s);
581 : 0 : return 0;
582 : : }
583 : : } else {
584 [ # # ]: 0 : ERR("directory missing path(%s) and no create_dirs (%d %s)", s, errno, STRERROR(errno));
585 : 0 : ZX_FREE(cf->ctx, s);
586 : 0 : return 0;
587 : : }
588 : : }
589 : :
590 : 1042 : memcpy(p, kind, kind_len+1);
591 : 1042 : p += kind_len;
592 [ - + ]: 1042 : if (stat(s, &st)) {
593 [ # # ]: 0 : if (create_dirs) {
594 [ # # ]: 0 : if (MKDIR(s, 0777)) {
595 [ # # ]: 0 : ERR("mkdir path(%s) failed: %d %s", s, errno, STRERROR(errno));
596 : 0 : ZX_FREE(cf->ctx, s);
597 : 0 : return 0;
598 : : }
599 : : } else {
600 [ # # ]: 0 : ERR("zxid directory missing path(%s) and no create_dirs (%d %s)", s, errno, STRERROR(errno));
601 : 0 : ZX_FREE(cf->ctx, s);
602 : 0 : return 0;
603 : : }
604 : : }
605 : :
606 : 1042 : sha1_safe_base64(p, objid->len, objid->s);
607 : 1042 : p[27] = 0;
608 : 1042 : p+=27;
609 : 1042 : return zx_ref_len_str(cf->ctx, len, s);
610 : : }
611 : :
612 : : /*() Check if file by path already exist.
613 : : * Since each uniquely ID'd object has unique path, mere existence of a file
614 : : * serves as duplicate ID check. This is used to satisfy some SAML processing rule
615 : : * requirements such as duplicate ID check for assertions.
616 : : *
617 : : * cf:: ZXID configuration object, used for memory allocation
618 : : * path:: Path where file is to be written, usually from zxlog_path()
619 : : * logkey:: String that will help to identify reason of failure
620 : : * return:: 0 if no duplicate (success), 1 if duplicate (failure)
621 : : */
622 : :
623 : : /* Called by: zxid_anoint_a7n, zxid_anoint_sso_resp, zxid_decode_redir_or_post x2, zxid_saml2_post_enc, zxid_saml2_redir_enc, zxid_soap_cgi_resp_body, zxid_sp_sso_finalize, zxid_wsc_valid_re_env, zxid_wsf_validate_a7n, zxid_wsp_validate */
624 : : int zxlog_dup_check(zxid_conf* cf, struct zx_str* path, const char* logkey)
625 : 1042 : {
626 : : struct stat st;
627 : : /* We need a c path, but get zx_str. However, the zx_str will come from zxlog_path()
628 : : * so we should be having the nul termination as needed. Just checking. */
629 [ - + # # ]: 1042 : ASSERTOP(path->s[path->len], ==, 0);
630 [ + + ]: 1042 : if (!stat(path->s, &st)) {
631 : 11 : ERR("Duplicate %s path(%.*s)", logkey, path->len, path->s);
632 : 11 : zxlog(cf, 0, 0, 0, 0, 0, 0, 0, "N", "C", "EDUP", path->s, "%s", logkey);
633 : 11 : return 1;
634 : : }
635 : 1031 : return 0;
636 : : }
637 : :
638 : : /*() Write a blob of content to log file according to logflag (see zxidconf.h). If
639 : : * the file already exists, i.e. there is a duplicate, the data is simply appended.
640 : : * When logging objects such as assertions, the duplicate check should be done
641 : : * as preprocessing step, see example below.
642 : : *
643 : : * cf:: ZXID configuration object, used for memory allocation
644 : : * logflag:: 0 if logging should not happen, 1 for normal logging, other values reserved
645 : : * path:: Path where file is to be written, usually from zxlog_path()
646 : : * blob:: The data to be logged.
647 : : * lk:: Log key. Indicates which part of the program invoked the logging function.
648 : : * return:: 0 if no log written (failure or logflag false), 1 if log written. Often ignored.
649 : : *
650 : : * *Example*
651 : : *
652 : : * logpath = zxlog_path(cf, issuer, a7n->ID, "rely/", "/a7n/", 1);
653 : : * if (logpath) {
654 : : * if (zxlog_dup_check(cf, logpath, "SSO assertion")) {
655 : : * zxlog_blob(cf, cf->log_rely_a7n, logpath, zx_easy_enc_elem_sig(cf,&a7n->gg), "E");
656 : : * goto erro;
657 : : * }
658 : : * zxlog_blob(cf, cf->log_rely_a7n, logpath, zx_easy_enc_elem_sig(cf, a7n), "OK");
659 : : * }
660 : : *
661 : : * In the above example we determine the logpath and check for the duplicate and then log even
662 : : * if duplicate. The logic of this is that in case of duplicate, the audit trail
663 : : * captures both the original and the duplicate assertion (the logging is an append),
664 : : * which may have forensic value. */
665 : :
666 : : /* Called by: zxid_anoint_a7n x2, zxid_anoint_sso_resp x2, zxid_decode_redir_or_post x2, zxid_saml2_post_enc x2, zxid_saml2_redir_enc x2, zxid_soap_cgi_resp_body x2, zxid_sp_sso_finalize x2, zxid_wsc_valid_re_env x2, zxid_wsf_validate_a7n x2, zxid_wsp_validate x2 */
667 : : int zxlog_blob(zxid_conf* cf, int logflag, struct zx_str* path, struct zx_str* blob, const char* lk)
668 : 1042 : {
669 [ + - - + ]: 1042 : if (!logflag || !blob)
670 : 0 : return 0;
671 [ - + ]: 1042 : if (logflag != 1) {
672 : 0 : ERR("Unimplemented blob logging format: %x", logflag);
673 : 0 : return 0;
674 : : }
675 : :
676 : : /* We need a c path, but get zx_str. However, the zx_str will come from zxlog_path()
677 : : * so we should be having the nul termination as needed. Just checking. */
678 [ + + - + ]: 1042 : D("%s: LOGBLOB15(%.*s) len=%d path(%.*s)", lk, MIN(blob->len,15), blob->s, blob->len, path->len, path->s);
679 : : DD("%s: LOGBLOB(%.*s)", lk, blob->len, blob->s);
680 [ - + # # ]: 1042 : ASSERTOP(path->s[path->len], ==, 0);
681 [ - + ]: 1042 : if (!write2_or_append_lock_c_path(path->s, blob->len, blob->s, 0, 0, "zxlog blob", SEEK_END,O_APPEND)) {
682 : 0 : zxlog(cf, 0, 0, 0, 0, 0, 0, 0, "N", "S", "EFILE", 0, "Could not write blob. Permissions?");
683 : : }
684 : 1042 : return 1;
685 : : }
686 : :
687 : : #define XML_LOG_FILE ZXID_PATH "log/xml.dbg"
688 : : FILE* zx_xml_debug_log = 0;
689 : : int zx_xml_debug_log_err = 0;
690 : : int zxlog_seq = 0;
691 : :
692 : : #if !defined(USE_STDIO) && !defined(MINGW)
693 : : /* *** Static initialization of struct flock is suspect since man fcntl() documentation
694 : : * does not guarantee ordering of the fields, or that they would be the first fields.
695 : : * On Linux-2.4 and 2.6 as well as Solaris-8 the ordering is as follows, but this needs
696 : : * to be checked on other platforms.
697 : : * l_type, l_whence, l_start, l_len */
698 : : extern struct flock zx_rdlk; /* = { F_RDLCK, SEEK_SET, 0, 1 };*/
699 : : extern struct flock zx_wrlk; /* = { F_WRLCK, SEEK_SET, 0, 1 };*/
700 : : extern struct flock zx_unlk; /* = { F_UNLCK, SEEK_SET, 0, 1 };*/
701 : : #endif
702 : :
703 : : /*() Log a blob of XML data to auxiliary log file. This avoids
704 : : * mega clutter in the main debug logs. You are supposed
705 : : * to view this file with:
706 : : * tailf /var/zxid/log/xml.dbg | ./xml-pretty.pl */
707 : :
708 : : /* Called by: */
709 : : void zxlog_debug_xml_blob(zxid_conf* cf, const char* file, int line, const char* func, const char* lk, int len, const char* xml)
710 : 3840 : {
711 : : int bdy_len;
712 : : const char* bdy;
713 : : const char* p;
714 : : const char* q;
715 [ + + + - : 3840 : if (!zx_debug || len == -1 || !xml)
- + ]
716 : 157 : return;
717 [ + + ]: 3683 : if (len == -2)
718 : 129 : len = strlen(xml);
719 : :
720 : : /* Detect body */
721 : :
722 [ + - ]: 3686 : for (p = xml; p; p+=4) {
723 : 3686 : p = strstr(p, "Body");
724 [ + + ]: 3686 : if (!p) {
725 : 3084 : nobody:
726 : 3084 : bdy = xml;
727 : 3084 : bdy_len = 40;
728 : 3084 : goto print_it;
729 : : }
730 [ + - + - : 602 : if (p > xml && ONE_OF_2(p[-1], '<', ':') && ONE_OF_5(p[4], '>', ' ', '\t', '\r', '\n'))
+ + + + +
+ + - + -
+ - ]
731 : : break; /* Opening <Body> detected. */
732 : : }
733 [ - + ]: 599 : if (!p)
734 : 0 : goto nobody;
735 : :
736 : 599 : p = strchr(p+4, '>'); /* Scan for close of opening <Body */
737 [ - + ]: 599 : if (!p)
738 : 0 : goto nobody;
739 : :
740 [ + - ]: 599 : for (q = ++p; q; q+=5) {
741 : 599 : q = strstr(q, "Body>");
742 [ - + ]: 599 : if (!q)
743 : 0 : goto nobody; /* Missing closing </Body> tag */
744 [ + - - + ]: 599 : if (ONE_OF_2(q[-1], '<', ':'))
745 : : break;
746 : : }
747 [ + + ]: 599 : for (--q; *q != '<'; --q) ; /* Scan for the start of </Body>, skipping any namespace prefix */
748 : 599 : bdy = p;
749 : 599 : bdy_len = MIN(q-p, 100);
750 : :
751 : 3683 : print_it:
752 : 3683 : ++zxlog_seq;
753 : 3683 : fprintf(stderr, "t %10s:%-3d %-16s %s d %s%s(%.*s) len=%d %d:%d\n", file, line, func, ERRMAC_INSTANCE, zx_indent, lk, bdy_len, bdy, len, getpid(), zxlog_seq);
754 : :
755 [ + + ]: 3683 : if (!zx_xml_debug_log) {
756 [ - + ]: 171 : if (zx_xml_debug_log_err)
757 : 0 : return;
758 : 171 : zx_xml_debug_log = fopen(XML_LOG_FILE, "a+");
759 [ - + ]: 171 : if (!zx_xml_debug_log) { /* If it did not work out, do not insist. */
760 : 0 : perror(XML_LOG_FILE);
761 : 0 : ERR("Can't open for appending %s: %d", XML_LOG_FILE, errno);
762 : 0 : zx_xml_debug_log_err = 1;
763 : 0 : return;
764 : : }
765 [ + - - + ]: 171 : D("OPEN BLOB LOG: tailf %s | ./xml-pretty.pl", XML_LOG_FILE);
766 : : }
767 : :
768 [ - + ]: 3683 : if (FLOCKEX(fileno(zx_xml_debug_log)) == -1) {
769 [ # # ]: 0 : ERR("Locking exclusively file `%s' failed: %d %s. Check permissions and that the file system supports locking. euid=%d egid=%d", XML_LOG_FILE, errno, STRERROR(errno), geteuid(), getegid());
770 : : /* Fall thru to print without locking */
771 : : }
772 : 3683 : ++zxlog_seq;
773 : 3683 : fprintf(zx_xml_debug_log, "<!-- XMLBEG %d:%d %10s:%-3d %-16s %s d %s %s len=%d -->\n%.*s\n<!-- XMLEND %d:%d -->\n", getpid(), zxlog_seq, file, line, func, ERRMAC_INSTANCE, zx_indent, lk, len, len, xml, getpid(), zxlog_seq);
774 : 3683 : fflush(zx_xml_debug_log);
775 : 3683 : FUNLOCK(fileno(zx_xml_debug_log));
776 : : }
777 : :
778 : : /* EOF -- zxlog.c */
|
