Escape and reformat XML errors/warnings to avoid breaking audit log format.

CHANGES

@@ -1,6 +1,9 @@
-29 May 2009 - 2.5.10-dev
+31 May 2009 - 2.5.10-dev
 ------------------------
 
+ * Removed extra newline from audit log message line when logging XML errors.
+   This was causing problems parsing audit logs.
+
  * Fixed @pm/@pmFromFile case insensitivity.
 
  * Truncate long parameters in log message for "Match of ... against ...

apache2/apache2_util.c

@@ -236,7 +236,6 @@ void internal_log(request_rec *r, directory_config *dcfg, modsec_rec *msr,
     apr_size_t nbytes, nbytes_written;
     apr_file_t *debuglog_fd = NULL;
     int filter_debug_level = 0;
-    int str2len;
     char str1[1024] = "";
     char str2[1256] = "";
 
@@ -257,20 +256,16 @@ void internal_log(request_rec *r, directory_config *dcfg, modsec_rec *msr,
      */
     if ((level > 3)&&( (debuglog_fd == NULL) || (level > filter_debug_level) )) return;
 
-    /* Construct the message (leaving a byte left for a newline if needed). */
+    /* Construct the message. */
     apr_vsnprintf(str1, sizeof(str1), text, ap);
-    str2len = apr_snprintf(str2, sizeof(str2) - 1, 
+
-        "[%s] [%s/sid#%pp][rid#%pp][%s][%d] %s",
+    /* Construct the log entry. */
+    apr_snprintf(str2, sizeof(str2), 
+        "[%s] [%s/sid#%pp][rid#%pp][%s][%d] %s\n",
         current_logtime(msr->mp), ap_get_server_name(r), (r->server),
         r, ((r->uri == NULL) ? "" : log_escape_nq(msr->mp, r->uri)),
         level, str1);
 
-    /* Add a newline if there is not one already (needed for msr_log_*) */
-    if (str2[str2len - 1] != '\n') {
-        str2[str2len] = '\n';
-        str2[str2len + 1] = '\0';
-    }
-
     /* Write to the debug log. */
     if ((debuglog_fd != NULL)&&(level <= filter_debug_level)) {
         nbytes = strlen(str2);
@@ -326,27 +321,59 @@ void msr_log(modsec_rec *msr, int level, const char *text, ...) {
 /**
  * Logs one message at level 3 to the debug log and to the
  * Apache error log. This is intended for error callbacks.
+ *
+ * The 'text' will first be escaped.
  */
 void msr_log_error(modsec_rec *msr, const char *text, ...) {
-    const char *str = text;
     va_list ap;
+    int len;
+    char *str;
 
+    /* Generate the string. */
     va_start(ap, text);
-    internal_log(msr->r, msr->txcfg, msr, 3, str, ap);
+    str = apr_pvsprintf(msr->mp, text, ap);
     va_end(ap);
+
+    /* Strip line ending. */
+    len = strlen(str);
+    if (len && str[len - 1] == '\n') {
+        str[len - 1] = '\0';
+    }
+    if (len > 1 && str[len - 2] == '\r') {
+        str[len - 1] = '\0';
+    }
+
+    /* Log the escaped string. */
+    internal_log(msr->r, msr->txcfg, msr, 3, log_escape_nq(msr->mp,str), NULL);
 }
 
 /**
  * Logs one message at level 4 to the debug log and to the
  * Apache error log. This is intended for warning callbacks.
+ *
+ * The 'text' will first be escaped.
  */
 void msr_log_warn(modsec_rec *msr, const char *text, ...) {
-    const char *str = text;
     va_list ap;
+    int len;
+    char *str;
 
+    /* Generate the string. */
     va_start(ap, text);
-    internal_log(msr->r, msr->txcfg, msr, 4, str, ap);
+    str = apr_pvsprintf(msr->mp, text, ap);
     va_end(ap);
+
+    /* Strip line ending. */
+    len = strlen(str);
+    if (len && str[len - 1] == '\n') {
+        str[len - 1] = '\0';
+    }
+    if (len > 1 && str[len - 2] == '\r') {
+        str[len - 1] = '\0';
+    }
+
+    /* Log the escaped string. */
+    internal_log(msr->r, msr->txcfg, msr, 4, log_escape_nq(msr->mp,str), NULL);
 }
 
 

apache2/t/regression/rule/10-xml.t

@@ -48,6 +48,55 @@
 		),
 	),
 },
+# Failed attribute value
+{
+	type => "rule",
+	comment => "validateSchema (validate attribute value failed)",
+	conf => qq(
+		SecRuleEngine On
+		SecRequestBodyAccess On
+		SecDebugLog $ENV{DEBUG_LOG}
+		SecDebugLogLevel 9
+		SecAuditEngine RelevantOnly
+		SecAuditLog "$ENV{AUDIT_LOG}"
+		SecRule REQUEST_HEADERS:Content-Type "^text/xml\$" \\
+		        "phase:1,t:none,t:lowercase,nolog,pass,ctl:requestBodyProcessor=XML"
+		SecRule REQBODY_PROCESSOR "!^XML\$" nolog,pass,skipAfter:12345
+		SecRule XML "\@validateSchema $ENV{CONF_DIR}/SoapEnvelope.xsd" \\
+		        "phase:2,deny,log,auditlog,id:12345"
+	),
+	match_log => {
+		debug => [ qr/XML: Initialising parser.*XML: Parsing complete \(well_formed 1\).*Target value: "\[XML document tree\]".*'badval' is not a valid value of the local atomic type.*Schema validation failed/s, 1 ],
+		-debug => [ qr/Successfully validated payload against Schema|\n\r?\n/, 1 ],
+		audit => [ qr/^Message: Element.*'badval' is not a valid value of the local atomic type\.\nMessage:/m, 1 ],
+	},
+	match_response => {
+		status => qr/^403$/,
+	},
+	request => new HTTP::Request(
+		POST => "http://$ENV{SERVER_NAME}:$ENV{SERVER_PORT}/test.txt",
+		[
+			"Content-Type" => "text/xml",
+		],
+		normalize_raw_request_data(
+			q(
+				<?xml version="1.0" encoding="utf-8"?>
+				<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/"
+				xmlns:soapenc="http://schemas.xmlsoap.org/soap/encoding/"
+				xmlns:tns="http://www.bluebank.example.com/axis/getBalance.jws"
+				xmlns:types="http://www.bluebank.example.com/axis/getBalance.jws/encodedTypes"
+				xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+				xmlns:xsd="http://www.w3.org/2001/XMLSchema">
+						<soap:Body soap:mustUnderstand="badval" soap:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
+								<q1:getInput xmlns:q1="http://DefaultNamespace">
+										<id xsi:type="xsd:string">12123</id>
+								</q1:getInput>
+						</soap:Body>
+				</soap:Envelope>
+			),
+		),
+	),
+},
 # Failed validation
 {
 	type => "rule",
@@ -57,6 +106,8 @@
 		SecRequestBodyAccess On
 		SecDebugLog $ENV{DEBUG_LOG}
 		SecDebugLogLevel 9
+		SecAuditEngine RelevantOnly
+		SecAuditLog "$ENV{AUDIT_LOG}"
 		SecRule REQUEST_HEADERS:Content-Type "^text/xml\$" \\
 		        "phase:1,t:none,t:lowercase,nolog,pass,ctl:requestBodyProcessor=XML"
 		SecRule REQBODY_PROCESSOR "!^XML\$" nolog,pass,skipAfter:12345
@@ -67,6 +118,7 @@
 		debug => [ qr/XML: Initialising parser.*XML: Parsing complete \(well_formed 1\).*Target value: "\[XML document tree\]".*element is not expected/s, 1 ],
 		-debug => [ qr/XML parser error|Failed to load/, 1 ],
 		-error => [ qr/XML parser error|Failed to load/, 1 ],
+		audit => [ qr/^Message: Element.*This element is not expected.*\nMessage:/m, 1 ],
 	},
 	match_response => {
 		status => qr/^403$/,
@@ -104,6 +156,8 @@
 		SecRequestBodyAccess On
 		SecDebugLog $ENV{DEBUG_LOG}
 		SecDebugLogLevel 9
+		SecAuditEngine RelevantOnly
+		SecAuditLog "$ENV{AUDIT_LOG}"
 		SecRule REQUEST_HEADERS:Content-Type "^text/xml\$" \\
 		        "phase:1,t:none,t:lowercase,nolog,pass,ctl:requestBodyProcessor=XML"
 		SecRule REQBODY_PROCESSOR "!^XML\$" nolog,pass,skipAfter:12345
@@ -114,6 +168,7 @@
 		debug => [ qr/XML: Initialising parser.*XML: Parsing complete \(well_formed 0\).*XML parser error.*validation failed because content is not well formed/s, 1 ],
 		-debug => [ qr/Failed to load|Successfully validated/, 1 ],
 		-error => [ qr/Failed to load|Successfully validated/, 1 ],
+		audit => [ qr/^Message: .*Failed parsing document.*\nMessage:/m, 1 ],
 	},
 	match_response => {
 		status => qr/^403$/,
@@ -151,6 +206,8 @@
 		SecRequestBodyAccess On
 		SecDebugLog $ENV{DEBUG_LOG}
 		SecDebugLogLevel 9
+		SecAuditEngine RelevantOnly
+		SecAuditLog "$ENV{AUDIT_LOG}"
 		SecRule REQUEST_HEADERS:Content-Type "^text/xml\$" \\
 		        "phase:1,t:none,t:lowercase,nolog,pass,ctl:requestBodyProcessor=XML"
 		SecRule REQBODY_PROCESSOR "!^XML\$" nolog,pass,skipAfter:12345
@@ -159,6 +216,7 @@
 	),
 	match_log => {
 		debug => [ qr/XML: Initialising parser.*XML: Parsing complete \(well_formed 1\).*Target value: "\[XML document tree\]".*Failed to parse the XML resource.*Failed to load Schema/s, 1 ],
+		audit => [ qr/^Message: .*Failed to parse the XML resource.*\nMessage: Rule processing failed/m, 1 ],
 	},
 	match_response => {
 		status => qr/^200$/,