Got my hands on a device, which generally functions stable, but does produce this curious race condition in GenieACS CWMP service - not quite sure which is to blame - GenieACS or CPE, but looks like both are to blame.
Restart of genieacs CWMP service does fix the problem, until next time - which can occur in a 2 or 24 hours time.
My GenieACS “lives” behind nginx, so that I can manage SSL and non-SSL CWMP clients with ease. GenieACS itself is running in non-SSL mode (without certificates), nginx does SSL stuff.
Here are the details:
This is how nginx access log looks like just before and after the fault (when code 400 is introduced):
10.20.13.201 - - [15/Apr/2021:14:29:09 +0200] “POST / HTTP/1.1” 200 524 “-” “gSOAP/2.7”
10.20.13.201 - - [15/Apr/2021:14:29:09 +0200] “POST / HTTP/1.1” 204 0 “-” “gSOAP/2.7”
10.20.13.201 - - [15/Apr/2021:14:34:09 +0200] “POST / HTTP/1.1” 200 524 “-” “gSOAP/2.7”
10.20.13.201 - - [15/Apr/2021:14:34:09 +0200] “POST / HTTP/1.1” 400 15 “-” “gSOAP/2.7”
10.20.13.201 - - [15/Apr/2021:14:34:09 +0200] “POST / HTTP/1.1” 400 22 “-” “gSOAP/2.7”
10.20.13.201 - - [15/Apr/2021:14:34:09 +0200] “POST / HTTP/1.1” 400 22 “-” “gSOAP/2.7”
…
Above we can see that at 14:34:09 we get code 200 and then 400 (bad request).
GenieACS CWMP acces log:
(time with “Z” at the end means UTC time, so add 2 hour to match to nginx logs: 12:34 => 14:34, periodic inform set to 5 minutes)
2021-04-15T12:24:09.475Z [INFO] 10.20.13.201 34B5A3-G%2D97RG9-GPON01010082: Inform; cpeRequestId=“1234” informEvent=“2 PERIODIC” informRetryCount=0
2021-04-15T12:29:09.497Z [INFO] 10.20.13.201 34B5A3-G%2D97RG9-GPON01010082: Inform; cpeRequestId=“1234” informEvent=“2 PERIODIC” informRetryCount=0
2021-04-15T12:34:09.442Z [INFO] 10.20.13.201 34B5A3-G%2D97RG9-GPON01010082: Inform; cpeRequestId=“1234” informEvent=“2 PERIODIC” informRetryCount=0
2021-04-15T12:34:09.550Z [ERROR] 10.20.13.201: Invalid session
2021-04-15T12:34:09.737Z [ERROR] 10.20.13.201 34B5A3-G%2D97RG9-GPON01010082: XML parse error; parseError=“Missing detail element”
2021-04-15T12:34:09.863Z [ERROR] 10.20.13.201: XML parse error; parseError=“Missing detail element”
2021-04-15T12:34:09.969Z [ERROR] 10.20.13.201: XML parse error; parseError=“Missing detail element”
2021-04-15T12:34:10.075Z [ERROR] 10.20.13.201: XML parse error; parseError=“Missing detail element”
Device debug log has this to say:
--
event: outgoing HTTP response
timestamp: 2021-04-15T12:34:09.443Z
remoteAddress: 127.0.0.1
deviceId: 34B5A3-G%2D97RG9-GPON01010082
connection: 2021-04-15T12:34:09.424Z
statusCode: 200
headers:
content-length: 524
server: GenieACS/1.2.5+20210312233623
soapserver: GenieACS/1.2.5+20210312233623
content-type: text/xml; charset="utf-8"
set-cookie: session=b4c5448ede4a0c5b
body: >-
<?xml version="1.0" encoding="UTF-8"?>
<soap-env:Envelope xmlns:soap-enc="http://schemas.xmlsoap.org/soap/encoding/"
xmlns:soap-env="http://schemas.xmlsoap.org/soap/envelope/"
xmlns:xsd="http://www.w3.org/2001/XMLSchema"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:cwmp="urn:dslforum-org:cwmp-1-0"><soap-env:Header><cwmp:ID
soap-env:mustUnderstand="1">1234</cwmp:ID></soap-env:Header><soap-env:Body><cwmp:InformResponse><MaxEnvelopes>1</MaxEnvelopes></cwmp:InformResponse></soap-env:Body></soap-env:Envelope>
---
event: incoming HTTP request
timestamp: 2021-04-15T12:34:09.737Z
remoteAddress: 127.0.0.1
deviceId: 34B5A3-G%2D97RG9-GPON01010082
connection: 2021-04-15T12:34:09.737Z
localPort: 7547
method: POST
url: /
headers:
connection: upgrade
host: 10.20.128.47
forwarded: for=10.20.13.201
x-forwarded-for: 10.20.13.201
content-length: "607"
user-agent: gSOAP/2.7
content-type: text/xml; charset=utf-8
cookie: session=b4c5448ede4a0c5b
body: >
<SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"
xmlns:SOAP-ENC="http://schemas.xmlsoap.org/soap/encoding/"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:xsd="http://www.w3.org/2001/XMLSchema"
xmlns:cwmp="urn:dslforum-org:cwmp-1-0">
<SOAP-ENV:Header>
<cwmp:ID SOAP-ENV:mustUnderstand="1">1234</cwmp:ID>
</SOAP-ENV:Header>
<SOAP-ENV:Body>
<SOAP-ENV:Fault>
<faultcode>SOAP-ENV:VersionMismatch</faultcode>
<faultstring>SOAP version mismatch or invalid SOAP message</faultstring>
</SOAP-ENV:Fault>
</SOAP-ENV:Body>
</SOAP-ENV:Envelope>
---
event: outgoing HTTP response
timestamp: 2021-04-15T12:34:09.738Z
remoteAddress: 127.0.0.1
deviceId: 34B5A3-G%2D97RG9-GPON01010082
connection: 2021-04-15T12:34:09.737Z
statusCode: 400
headers:
content-length: 22
connection: close
body: Missing detail element
--
No other entry is added to device debug log until CWMP service is restarted.
I would say both parties are at fault here. Any suggestions?
P.S. This was tested on 1.2.0b and latest 1.2.5 version - later version changes message from “simple” “Invalid session” to “XML parse error; parseError=‘Missing detail element’”.
Regards,
Robert.
