Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

XML: there is no way to obtain actual error message from libxml2 on parsing failures #2565

Open
defanator opened this issue May 5, 2021 · 0 comments
Open

XML: there is no way to obtain actual error message from libxml2 on parsing failures #2565

defanator opened this issue May 5, 2021 · 0 comments
Labels
3.x Related to ModSecurity version 3.x enhancement

Comments

@defanator
Copy link
Contributor

defanator commented May 5, 2021 •
edited
Loading

Describe the bug

It's impossible to get the actual error message produced by libxml2 when there's an issue with passed XML data.

While in some cases it's easy to get the required data by e.g. running xmllint against the payload (if it's known), in other cases it can be quite hard to understand what's went wrong (see e.g. owasp-modsecurity/ModSecurity-nginx#246).

To Reproduce

Let's consider inherently incorrect XML like this:

<?xml version="1.0" encoding="UTF-8" standalone="no" ?>

<gpx xmlns="http://www.topografix.com/GPX/1/1" xmlns:gpxx="http://www.garmin.com/xmlschemas/GpxExtensions/v3" xmlns:gpxtpx="http://www.garmin.com/xmlschemas/TrackPointExtension/v1" creator="Oregon 400t" version="1.1" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.topografix.com/GPX/1/1 http://www.topografix.com/GPX/1/1/gpx.xsd http://www.garmin.com/xmlschemas/GpxExtensions/v3 http://www.garmin.com/xmlschemas/GpxExtensionsv3.xsd http://www.garmin.com/xmlschemas/TrackPointExtension/v1 http://www.garmin.com/xmlschemas/TrackPointExtensionv1.xsd">
  <metadata>
    <link href="http://www.garmin.com">
      <text>Garmin International</text>
    </link>
    <time>2009-10-17T22:58:43Z</time>
  </metadata>
  <trk>
    <name>Example GPX Document</name>
    <trkseg>
      <trkpt lat="47.644548" lon="-122.326897">
        <ele>4.46</ele>
        <time>2009-10-17T18:37:26Z</time>
      </trkpt>
      <trkpt lat="47.644548" lon="-122.326897">
        <ele>4.94</ele>
        <time>2009-10-17T18:37:31Z</time>
      </trkpt>
      <trkpt lat="47.644548" lon="-122.326897">
        <ele>6.87</ele>
        <time>2009-10-17T18:37:34Z</time>
      </trkpt>
    </trkseg>
  </trk>
</gggpx>

Here's the output of xmllint:

vagrant@vagrant:~$ xmllint -noout test.xml
111:27: parser error : Opening and ending tag mismatch: gpx line 3 and gggpx
</gggpx>
        ^

Now we push it to the nginx with modsecurity enabled:

vagrant@vagrant:~$ curl -v -d @test.xml -H "Content-Type: text/xml" http://localhost/modsec-full/upload/
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 80 (#0)
> POST /modsec-full/upload/ HTTP/1.1
> Host: localhost
> User-Agent: curl/7.58.0
> Accept: */*
> Content-Type: text/xml
> Content-Length: 1252
> Expect: 100-continue
> 
< HTTP/1.1 100 Continue
* We are completely uploaded and fine
< HTTP/1.1 400 Bad Request
< Server: nginx/1.19.10
< Date: Wed, 05 May 2021 10:13:35 GMT
< Content-Type: text/html
< Content-Length: 158
< Connection: close
< 
<html>
<head><title>400 Bad Request</title></head>
<body>
<center><h1>400 Bad Request</h1></center>
<hr><center>nginx/1.19.10</center>
</body>
</html>
* Closing connection 0

Logs and dumps

Output of:

  1. DebugLogs (level 9)
[1620209639] [] [4] Initializing transaction
[1620209639] [] [4] Transaction context created.
[1620209639] [] [4] Starting phase CONNECTION. (SecRules 0)
[1620209639] [] [9] This phase consists of 0 rule(s).
[1620209639] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[1620209639] [/modsec-full/upload/] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[1620209639] [/modsec-full/upload/] [9] This phase consists of 2 rule(s).
[1620209639] [/modsec-full/upload/] [4] (Rule: 200000) Executing operator "Rx" with param "(?:application(?:/soap\+|/)|text/)xml" against REQUEST_HEADERS:Content-Type.
[1620209639] [/modsec-full/upload/] [9]  T (0) t:lowercase: "text/xml"
[1620209639] [/modsec-full/upload/] [9] Target value: "text/xml" (Variable: REQUEST_HEADERS:Content-Type)
[1620209639] [/modsec-full/upload/] [9] Matched vars updated.
[1620209639] [/modsec-full/upload/] [4] Rule returned 1.
[1620209639] [/modsec-full/upload/] [9] Running action: nolog
[1620209639] [/modsec-full/upload/] [9] Running action: ctl
[1620209639] [/modsec-full/upload/] [4] Running (disruptive)     action: pass.
[1620209639] [/modsec-full/upload/] [8] Running action pass
[1620209639] [/modsec-full/upload/] [4] (Rule: 200001) Executing operator "Rx" with param "application/json" against REQUEST_HEADERS:Content-Type.
[1620209639] [/modsec-full/upload/] [9]  T (0) t:lowercase: "text/xml"
[1620209639] [/modsec-full/upload/] [9] Target value: "text/xml" (Variable: REQUEST_HEADERS:Content-Type)
[1620209639] [/modsec-full/upload/] [4] Rule returned 0.
[1620209639] [/modsec-full/upload/] [9] Matched vars cleaned.
[1620209639] [/modsec-full/upload/] [9] Appending request body: 1252 bytes. Limit set to: 13107200.000000
[1620209639] [/modsec-full/upload/] [4] Starting phase REQUEST_BODY. (SecRules 2)
[1620209639] [/modsec-full/upload/] [4] XML: Initialising parser.
[1620209639] [/modsec-full/upload/] [4] XML: Parsing complete (well_formed 0).
[1620209639] [/modsec-full/upload/] [4] XML: Failed parsing document.
[1620209639] [/modsec-full/upload/] [9] This phase consists of 4 rule(s).
[1620209639] [/modsec-full/upload/] [4] (Rule: 200002) Executing operator "Eq" with param "0" against REQBODY_ERROR.
[1620209639] [/modsec-full/upload/] [9] Target value: "1" (Variable: REQBODY_ERROR)
[1620209639] [/modsec-full/upload/] [9] Matched vars updated.
[1620209639] [/modsec-full/upload/] [4] Rule returned 1.
[1620209639] [/modsec-full/upload/] [9] This rule severity is: 2 current transaction is: 255
[1620209639] [/modsec-full/upload/] [9] Saving msg: Failed to parse request body.
[1620209639] [/modsec-full/upload/] [9] Running action: log
[1620209639] [/modsec-full/upload/] [9] Saving transaction to logs
[1620209639] [/modsec-full/upload/] [9] Running action: status
[1620209639] [/modsec-full/upload/] [4] Running (disruptive)     action: deny.
[1620209639] [/modsec-full/upload/] [8] Running action deny
[1620209639] [/modsec-full/upload/] [8] Skipping this phase as this request was already intercepted.
[1620209639] [/modsec-full/upload/] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[1620209639] [/modsec-full/upload/] [9] This phase consists of 0 rule(s).
[1620209639] [/modsec-full/upload/] [9] Appending response body: 104 bytes. Limit set to: 524288.000000
[1620209639] [/modsec-full/upload/] [9] Appending response body: 158 bytes. Limit set to: 524288.000000
[1620209639] [/modsec-full/upload/] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[1620209639] [/modsec-full/upload/] [9] This phase consists of 0 rule(s).
[1620209639] [/modsec-full/upload/] [4] Starting phase LOGGING. (SecRules 5)
[1620209639] [/modsec-full/upload/] [9] This phase consists of 0 rule(s).
[1620209639] [/modsec-full/upload/] [8] Checking if this request is suitable to be saved as an audit log.
[1620209639] [/modsec-full/upload/] [8] Checking if this request is relevant to be part of the audit logs.
[1620209639] [/modsec-full/upload/] [5] Saving this request as part of the audit logs.
[1620209639] [/modsec-full/upload/] [8] Request was relevant to be saved. Parts: 6006
  1. AuditLogs
---sWcjvjKz---A--
[05/May/2021:10:13:59 +0000] 1620209639 127.0.0.1 10534 127.0.0.1 80
---sWcjvjKz---B--
POST /modsec-full/upload/ HTTP/1.1
Host: localhost
User-Agent: curl/7.58.0
Accept: */*
Content-Type: text/xml
Content-Length: 1252
Expect: 100-continue

---sWcjvjKz---D--

---sWcjvjKz---E--
<html>\x0d\x0a<head><title>400 Bad Request</title></head>\x0d\x0a<body>\x0d\x0a<center><h1>400 Bad Request</h1></center>\x0d\x0a<hr><center>nginx/1.19.10</center>\x0d\x0a</body>\x0d\x0a</html>\x0d\x0a

---sWcjvjKz---F--
HTTP/1.1 400
Server: nginx/1.19.10
Date: Wed, 05 May 2021 10:13:59 GMT
Content-Length: 158
Content-Type: text/html
Connection: close

---sWcjvjKz---H--
ModSecurity: Access denied with code 400 (phase 2). Matched "Operator `Eq' with parameter `0' against variable `REQBODY_ERROR' (Value: `1' ) [file "/etc/nginx/modsec/modsecurity.conf"] [line "10"] [id "200002"] [rev ""] [msg "Failed to parse request body."] [data "XML parsing error: XML: Failed parsing document."] [severity "2"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/modsec-full/upload/"] [unique_id "1620209639"] [ref "v152,1"]

---sWcjvjKz---I--

---sWcjvjKz---J--

---sWcjvjKz---Z--
  1. Error logs
2021/05/05 10:13:59 [error] 20269#20269: *3 [client 127.0.0.1] ModSecurity: Access denied with code 400 (phase 2). Matched "Operator `Eq' with parameter `0' against variable `REQBODY_ERROR' (Value: `1' ) [file "/etc/nginx/modsec/modsecurity.conf"] [line "10"] [id "200002"] [rev ""] [msg "Failed to parse request body."] [data "XML parsing error: XML: Failed parsing document."] [severity "2"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/modsec-full/upload/"] [unique_id "1620209639"] [ref "v152,1"], client: 127.0.0.1, server: , request: "POST /modsec-full/upload/ HTTP/1.1", host: "localhost"

Expected behavior

Clear and unambiguous message (parser error : Opening and ending tag mismatch [..]) as emitted by xmllint instead of cryptic "Failed to parse request body" or "XML: failed parsing document".

Server (please complete the following information):

  • ModSecurity version (and connector): v3/master (v3.0.4-119-g1376882f), ModSecurity-nginx (v1.0.1-23-g21bc821)
  • WebServer: nginx/1.19.10

Rule Set (please complete the following information):

No actual ruleset involved, just plain modsecurity.conf from the v3/master.

Additional context

With the following dummy patch I was able to get the actual error message to a file:

diff --git a/src/request_body_processor/xml.cc b/src/request_body_processor/xml.cc
index 6d8a5ec1..6df70e86 100644
--- a/src/request_body_processor/xml.cc
+++ b/src/request_body_processor/xml.cc
@@ -106,7 +106,10 @@ bool XML::processChunk(const char *buf, unsigned int size,
     }
 
     /* Not a first invocation. */
+    ms_dbg_a(m_transaction, 4, "XML: calling xmlParseChunk for buf size " + std::to_string(size));
     xmlParseChunk(m_data.parsing_ctx, buf, size, 0);
+
+
     if (m_data.parsing_ctx->wellFormed != 1) {
         error->assign("XML: Failed to create parsing context.");
         ms_dbg_a(m_transaction, 4, "XML: Failed parsing document.");
diff --git a/src/request_body_processor/xml.h b/src/request_body_processor/xml.h
index 1d29f62f..3540e8a4 100644
--- a/src/request_body_processor/xml.h
+++ b/src/request_body_processor/xml.h
@@ -20,6 +20,7 @@
 
 #include <string>
 #include <iostream>
+#include <fstream>
 
 #include "modsecurity/transaction.h"
 #include "modsecurity/rules_set.h"
@@ -54,6 +55,16 @@ class XML {
         xmlCharEncoding enc);
 
     static void null_error(void *ctx, const char *msg, ...) {
+	    char buf[512];
+	    std::ofstream f;
+	    va_list args;
+	    va_start (args, msg);
+	    vsprintf(buf, msg, args);
+	    va_end (args);
+
+	    f.open("/tmp/xml.err", std::ios_base::app);
+	    f << buf;
+	    f.close();
     }

File contents:

body.xml:1: parser error : Opening and ending tag mismatch: gpx line 0 and gggpx
    <time>2009-10-17T18:37:34Z</time>      </trkpt>    </trkseg>  </trk></gggpx>
                                                                               ^

(It's just for a demo, of course I'm sure there must be a better way of handling this so the error(s) would go to appropriate context / loggers.)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
3.x Related to ModSecurity version 3.x enhancement
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@zimmerle @defanator