View Issue Details
ID | Project | Category | View Status | Date Submitted | Last Update |
---|---|---|---|---|---|
0000061 | easycwmp | Question | public | 2015-06-24 19:48 | 2015-07-13 17:40 |
Reporter | lferrarotti | Assigned To | mohamed.kallel | ||
Priority | normal | Severity | major | Reproducibility | always |
Status | resolved | Resolution | fixed | ||
Summary | 0000061: Parse Inform xml message from ACS failed | ||||
Description | When we connect to an ACS server that is using basic authentication, after authorization we received a parse error. The FaultCode is 8003 with an invalid arguments. The problem is related to an error in configuration of easycwmp or the ACS server. | ||||
Tags | No tags attached. | ||||
e-mail notification | |||||
|
easycwmp-soap.txt (3,336 bytes)
config_init_local(63):: easycwmp.@local[0].port=7547 config_init_local(81):: easycwmp.@local[0].ubus_socket=/var/run/ubus.sock config_init_local(53):: easycwmp.@local[0].interface=eth2 config_init_local(69):: easycwmp.@local[0].username=ftacs config_init_local(75):: easycwmp.@local[0].password=ftacs config_init_acs(147):: easycwmp.@acs[0].scheme=http config_init_acs(187):: easycwmp.@acs[0].periodic_enable=1 config_init_acs(193):: easycwmp.@acs[0].periodic_interval=100 config_init_acs(153):: easycwmp.@acs[0].username=tr069 config_init_acs(159):: easycwmp.@acs[0].password=tr069 config_init_acs(165):: easycwmp.@acs[0].hostname=xx.xxx.xxx.xxx config_init_acs(175):: easycwmp.@acs[0].port=8080 config_init_acs(181):: easycwmp.@acs[0].path=/ftacs-basic/ACS/ cwmp_init_deviceid(665): in device you must define serial_number +++ HTTP SERVER CONFIGURATION +++ ip: 'xx.xxx.xxx.xxx' port: '7547' --- HTTP SERVER CONFIGURATION --- +++ HTTP CLIENT CONFIGURATION +++ http_client_init(55):: url: http://tr069:tr069@xx.xxx.xxx.xxx:8080/ftacs-basic/ACS/ http_client_init(61):: ssl_verify: SSL certificate validation disabled. --- HTTP CLIENT CONFIGURATION --- > POST /ftacs-basic/ACS/ HTTP/1.1 Host: xx.xxx.xxx.xxx:8080 Accept: */* User-Agent: easycwmp Content-Type: text/xml Content-Length: 3160 < HTTP/1.1 401 Unauthorized < Server: Apache-Coyote/1.1 < X-Powered-By: Servlet 2.5; JBoss-5.0/JBossWeb-2.1 < WWW-Authenticate: Basic realm="CPEBasicLogin" < Content-Type: text/html;charset=utf-8 < Content-Length: 950 < Date: Wed, 24 Jun 2015 17:08:06 GMT < > POST /ftacs-basic/ACS/ HTTP/1.1 Authorization: Basic dHIwNjk6dHIwNjk= Host: xx.xxx.xxx.xxx:8080 Accept: */* User-Agent: easycwmp Content-Type: text/xml Content-Length: 3160 < HTTP/1.1 200 OK < Server: Apache-Coyote/1.1 < X-Powered-By: Servlet 2.5; JBoss-5.0/JBossWeb-2.1 < Set-Cookie: JSESSIONID=A98532711E362ACC513843DE9634F500.W; Path=/ < SOAPAction: "" < Content-Type: text/xml;charset=UTF-8 < Content-Length: 565 < Date: Wed, 24 Jun 2015 17:08:06 GMT < +++ RECEIVED HTTP RESPONSE (PART) +++ <env:Envelope xmlns:cwmp="urn:dslforum-org:cwmp-1-0" xmlns:env="http://schemas.xmlsoap.org/soap/envelope/" xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/"><env:Header><cwmp:ID env:mustUnderstand="1"></cwmp:ID></env:Header><env:Body><env:Fault xmlns:env="http://schemas.xmlsoap.org/soap/envelope/"><faultcode>env:Server</faultcode><faultstring>CWMP fault</faultstring><detail><cwmp:Fault xmlns:cwmp="urn:dslforum-org:cwmp-1-0"><FaultCode>8003</FaultCode><FaultString>Invalid arguments</FaultString></cwmp:Fault></detail></env:Fault></env:Body></env:Envelope> --- RECEIVED HTTP RESPONSE (PART) --- +++ RECEIVED HTTP RESPONSE +++ <env:Envelope xmlns:cwmp="urn:dslforum-org:cwmp-1-0" xmlns:env="http://schemas.xmlsoap.org/soap/envelope/" xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/"><env:Header><cwmp:ID env:mustUnderstand="1"></cwmp:ID></env:Header><env:Body><env:Fault xmlns:env="http://schemas.xmlsoap.org/soap/envelope/"><faultcode>env:Server</faultcode><faultstring>CWMP fault</faultstring><detail><cwmp:Fault xmlns:cwmp="urn:dslforum-org:cwmp-1-0"><FaultCode>8003</FaultCode><FaultString>Invalid arguments</FaultString></cwmp:Fault></detail></env:Fault></env:Body></env:Envelope> --- RECEIVED HTTP RESPONSE --- rpc_inform(228): parse Inform xml message from ACS failed |
|
Could you attach a traffic capture of your issue |
|
|
|
We have attached the capture |
|
The OUI and the serial number are empty in your inform message. and this is the cause of the fault you got from the ACS. you have to put them in the easycwmp config or you should update your data model scripts. |
|
Thanks, I've checked the data model source code and corrected. Now in the tcpdump both the value were passed with data. But at the end we received the same error. You can check on the new capture uploaded. Thanks |
|
|
|
it's not empty for params, but it's still empty for DeviceId <DeviceId> <Manufacturer>GL-CONNECT</Manufacturer> <OUI></OUI> <ProductClass>gl-inet</ProductClass> <SerialNumber></SerialNumber> </DeviceId> You have to update also the function "common_get_inform_deviceid()" in the common script |
|
Thankd for your support. I changed also that part, and now the last message received from the server is different. +++ RECEIVED HTTP RESPONSE (PART) +++ <env:Envelope xmlns:cwmp="urn:dslforum-org:cwmp-1-2" xmlns:env="http://schemas.xmlsoap.org/soap/envelope/"><env:Header></env:Header><env:Body><cwmp:InformResponse xmlns:cwmp="urn:dslforum-org:cwmp-1-2"><MaxEnvelopes>1</MaxEnvelopes></cwmp:InformResponse></env:Body></env:Envelope> --- RECEIVED HTTP RESPONSE (PART) --- +++ RECEIVED HTTP RESPONSE +++ <env:Envelope xmlns:cwmp="urn:dslforum-org:cwmp-1-2" xmlns:env="http://schemas.xmlsoap.org/soap/envelope/"><env:Header></env:Header><env:Body><cwmp:InformResponse xmlns:cwmp="urn:dslforum-org:cwmp-1-2"><MaxEnvelopes>1</MaxEnvelopes></cwmp:InformResponse></env:Body></env:Envelope> --- RECEIVED HTTP RESPONSE --- rpc_inform(228): parse Inform xml message from ACS failed Still parse problem, but different from before. You can also check everything in the new capture file : capture4.pcap |
|
|
|
I m not sure if it's a bug or an interoperability problem. I do not have the time now to investigate this problem. I will check it when I will treat the next release. as a quik solution you can avoid the check of the received inform response. Just add return 0 at the beginning of the function: int xml_parse_inform_response_message(char *msg_in) This should fix your problem but not in a proper way |
|
After applied that fix you suggested, we are able to make a step forward on the xml process of the tr-069 transaction. Now we received this error : rpc_get_rpc_methods(188): parse GetRPCMethods xml message from ACS failed But it is always related to the SOAPAction that we received from the ACS server. Comparing the capture between the same CPE and different ACS server, we saw this difference : 1) receiveing from ACS SOAPAction: is working 2) receiveing from ACS SOAPAction: "" is not working |
|
This issue will be treated in the next release (inchea allah) But I have a quick solution to fix this las problem. Like the inform, you can avoid the GgetRpcMethodResponse check by adding a return 0 at the beginning of the function: int xml_parse_get_rpc_methods_response_message(char *msg_in) |
|
I know that you do not have time for investigation. After applying both the two fixes suggested, we made a step over. We are able to receive these data from the server : <env:Envelope xmlns:SOAP-ENC="http://schemas.xmlsoap.org/soap/encoding/" xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/" xmlns:cwmp="urn:dslforum-org:cwmp-1-2" xmlns:env="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"> <env:Header> <cwmp:ID env:mustUnderstand="1">6357545</cwmp:ID> </env:Header> <env:Body> <cwmp:SetParameterValues xmlns:cwmp="urn:dslforum-org:cwmp-1-2"> <ParameterList SOAP-ENC:arrayType="cwmp:ParameterValueStruct[4]" xmlns:SOAP-ENC="http://schemas.xmlsoap.org/soap/encoding/"> <ParameterValueStruct> <Name>InternetGatewayDevice.ManagementServer.PeriodicInformEnable</Name> <Value xsi:type="xsd:boolean">1</Value> </ParameterValueStruct> <ParameterValueStruct> <Name>InternetGatewayDevice.ManagementServer.PeriodicInformInterval</Name> <Value xsi:type="xsd:unsignedInt">300</Value> </ParameterValueStruct> <ParameterValueStruct> <Name>InternetGatewayDevice.ManagementServer.ConnectionRequestUsername</Name> <Value xsi:type="xsd:string">ftacs</Value> </ParameterValueStruct> <ParameterValueStruct> <Name>InternetGatewayDevice.ManagementServer.ConnectionRequestPassword</Name> <Value xsi:type="xsd:string">ftacs</Value> </ParameterValueStruct> </ParameterList> <ParameterKey>6357545</ParameterKey> </cwmp:SetParameterValues> </env:Body> </env:Envelope> At the end we had still some errors : cwmp_handle_messages(369): acs response message is empty cwmp_inform(314): handling xml message failed Could be still something wrong at the server side? In attachment the last capture. Thanks |
|
|
|
looks the same problem. looks an interoperability problem. looks an xml parse problem. I will investigate the problem in the next release |
|
Thanks for your response. Could you please confirm me that this last part in not related to the http but to the cwmp protocol? In case of positive response I think would be necessary to manage this response inside the cwmp.c. Best Regards |
|
I had applied the same approach also on the cwmp.c file with a return 0 at the beginning of the function: int cwmp_handle_messages(void) At the end of the transaction I received this at cli session : Mon Jun 29 16:33:46 2015 daemon.debug easycwmpd: receive InformResponse from the ACS Mon Jun 29 16:33:46 2015 daemon.debug easycwmpd: external: execute apply service Mon Jun 29 16:33:46 2015 daemon.debug easycwmpd: external script exit Mon Jun 29 16:33:46 2015 daemon.debug easycwmpd: end session success Could you please confirm that could be a possible fix, for the moment? In addition I also uploaded both cli logs and capture from the device. |
|
tr069-cli-log.txt (5,142 bytes)
Mon Jun 29 16:29:26 2015 daemon.debug easycwmpd: daemon started Mon Jun 29 16:29:26 2015 daemon.debug easycwmpd: configuration (re)load Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_local(63):: easycwmp.@local[0].port=7547 Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_local(81):: easycwmp.@local[0].ubus_socket=/var/run/ubus.sock Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_local(53):: easycwmp.@local[0].interface=eth0 Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_local(69):: easycwmp.@local[0].username=ftacs Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_local(75):: easycwmp.@local[0].password=ftacs Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_acs(147):: easycwmp.@acs[0].scheme=http Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_acs(187):: easycwmp.@acs[0].periodic_enable=1 Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_acs(193):: easycwmp.@acs[0].periodic_interval=100 Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_acs(153):: easycwmp.@acs[0].username=luca Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_acs(159):: easycwmp.@acs[0].password=luca Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_acs(165):: easycwmp.@acs[0].hostname=testacs.friendly-tech.com Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_acs(175):: easycwmp.@acs[0].port=8080 Mon Jun 29 16:29:26 2015 user.emerg syslog: config_init_acs(181):: easycwmp.@acs[0].path=/ftacs-basic/ACS Mon Jun 29 16:29:26 2015 daemon.debug easycwmpd: init periodic event: interval = 100 Mon Jun 29 16:29:26 2015 daemon.debug easycwmpd: external script init Mon Jun 29 16:29:27 2015 daemon.debug easycwmpd: external: execute inform device_id Mon Jun 29 16:29:27 2015 daemon.debug easycwmpd: external script exit Mon Jun 29 16:29:27 2015 daemon.debug easycwmpd: add event '2 PERIODIC' Mon Jun 29 16:29:27 2015 daemon.debug easycwmpd: interface eth0 has ip 192.168.110.141 Mon Jun 29 16:29:27 2015 user.emerg syslog: +++ HTTP SERVER CONFIGURATION +++ Mon Jun 29 16:29:27 2015 user.emerg syslog: ip: '192.168.110.141' Mon Jun 29 16:29:27 2015 user.emerg syslog: port: '7547' Mon Jun 29 16:29:27 2015 user.emerg syslog: --- HTTP SERVER CONFIGURATION --- Mon Jun 29 16:29:27 2015 daemon.debug easycwmpd: http server initialized Mon Jun 29 16:29:27 2015 daemon.debug easycwmpd: entering main loop Mon Jun 29 16:29:27 2015 daemon.debug easycwmpd: start session Mon Jun 29 16:29:27 2015 user.emerg syslog: +++ HTTP CLIENT CONFIGURATION +++ Mon Jun 29 16:29:27 2015 user.emerg syslog: http_client_init(55):: url: http://luca:luca@testacs.friendly-tech.com:8080/ftacs-basic/ACS Mon Jun 29 16:29:27 2015 user.emerg syslog: http_client_init(61):: ssl_verify: SSL certificate validation disabled. Mon Jun 29 16:29:27 2015 user.emerg syslog: --- HTTP CLIENT CONFIGURATION --- Mon Jun 29 16:29:27 2015 daemon.debug easycwmpd: configured acs url http://luca:luca@testacs.friendly-tech.com:8080/ftacs-basic/ACS Mon Jun 29 16:29:27 2015 daemon.debug easycwmpd: external script init Mon Jun 29 16:29:35 2015 daemon.debug easycwmpd: receive InformResponse from the ACS Mon Jun 29 16:29:35 2015 daemon.debug easycwmpd: send RPC ACS GetRPCMethods Mon Jun 29 16:29:35 2015 daemon.debug easycwmpd: receive GetRPCMethodsResponse from the ACS Mon Jun 29 16:29:35 2015 daemon.debug easycwmpd: external: execute apply service Mon Jun 29 16:29:35 2015 daemon.debug easycwmpd: external script exit Mon Jun 29 16:29:35 2015 daemon.debug easycwmpd: end session success Mon Jun 29 16:31:59 2015 daemon.debug easycwmpd: add event '2 PERIODIC' Mon Jun 29 16:31:59 2015 daemon.debug easycwmpd: start session Mon Jun 29 16:31:59 2015 daemon.debug easycwmpd: configured acs url http://luca:luca@testacs.friendly-tech.com:8080/ftacs-basic/ACS Mon Jun 29 16:31:59 2015 daemon.debug easycwmpd: external script init Mon Jun 29 16:32:00 2015 daemon.debug easycwmpd: external: execute inform parameter Mon Jun 29 16:32:00 2015 daemon.debug easycwmpd: send Inform Mon Jun 29 16:32:06 2015 daemon.debug easycwmpd: receive InformResponse from the ACS Mon Jun 29 16:32:06 2015 daemon.debug easycwmpd: external: execute apply service Mon Jun 29 16:32:06 2015 daemon.debug easycwmpd: external script exit Mon Jun 29 16:32:06 2015 daemon.debug easycwmpd: end session success Mon Jun 29 16:33:39 2015 daemon.debug easycwmpd: add event '2 PERIODIC' Mon Jun 29 16:33:39 2015 daemon.debug easycwmpd: start session Mon Jun 29 16:33:39 2015 daemon.debug easycwmpd: configured acs url http://luca:luca@testacs.friendly-tech.com:8080/ftacs-basic/ACS Mon Jun 29 16:33:39 2015 daemon.debug easycwmpd: external script init Mon Jun 29 16:33:40 2015 daemon.debug easycwmpd: external: execute inform parameter Mon Jun 29 16:33:40 2015 daemon.debug easycwmpd: send Inform Mon Jun 29 16:33:46 2015 daemon.debug easycwmpd: receive InformResponse from the ACS Mon Jun 29 16:33:46 2015 daemon.debug easycwmpd: external: execute apply service Mon Jun 29 16:33:46 2015 daemon.debug easycwmpd: external script exit Mon Jun 29 16:33:46 2015 daemon.debug easycwmpd: end session success |
|
|
|
I can not confirm if it's a http problem or xml parser problem now, I have to investigate. But it's very likely an xml parser problem. And you can noht fix the problem wirth the same way (by adding return 0) because the cwmp should parse the cwmp request from the acs. |
|
Thanks for the update. If you will want to test this release or the next one here the references of the demo/test server that you can use for verifying interoperability: http://testacs.friendly-tech.com:8080/ftacs-basic/ACS login : luca password : luca Thanks and Regards |
|
fixed in EasyCwmp-1.1.4 |
Date Modified | Username | Field | Change |
---|---|---|---|
2015-06-24 19:48 | lferrarotti | New Issue | |
2015-06-24 19:48 | lferrarotti | File Added: easycwmp-soap.txt | |
2015-06-25 00:48 | mohamed.kallel | Note Added: 0000207 | |
2015-06-25 01:27 | lferrarotti | File Added: capture.pcap | |
2015-06-25 01:27 | lferrarotti | Note Added: 0000208 | |
2015-06-25 10:08 | mohamed.kallel | Note Added: 0000209 | |
2015-06-25 11:22 | lferrarotti | Note Added: 0000210 | |
2015-06-25 11:22 | lferrarotti | File Added: capture3.pcap | |
2015-06-25 12:06 | mohamed.kallel | Note Added: 0000211 | |
2015-06-25 12:27 | lferrarotti | Note Added: 0000212 | |
2015-06-25 12:28 | lferrarotti | File Added: capture4.pcap | |
2015-06-25 13:18 | mohamed.kallel | Note Added: 0000213 | |
2015-06-25 13:18 | mohamed.kallel | Note Edited: 0000213 | |
2015-06-25 17:58 | mohamed.kallel | Note Edited: 0000213 | |
2015-06-25 18:04 | lferrarotti | Note Added: 0000214 | |
2015-06-25 19:47 | mohamed.kallel | Note Added: 0000215 | |
2015-06-25 21:18 | mohamed.kallel | Note Edited: 0000215 | |
2015-06-25 21:50 | lferrarotti | Note Added: 0000216 | |
2015-06-25 21:50 | lferrarotti | File Added: capture5.pcap | |
2015-06-26 01:12 | mohamed.kallel | Note Added: 0000217 | |
2015-06-29 10:37 | lferrarotti | Note Added: 0000221 | |
2015-06-29 10:38 | lferrarotti | Note Edited: 0000221 | |
2015-06-29 18:43 | lferrarotti | Note Added: 0000223 | |
2015-06-29 18:43 | lferrarotti | File Added: tr069-cli-log.txt | |
2015-06-29 18:43 | lferrarotti | File Added: capture6.pcap | |
2015-06-30 13:03 | mohamed.kallel | Note Added: 0000225 | |
2015-06-30 16:20 | lferrarotti | Note Added: 0000227 | |
2015-07-13 17:40 | mohamed.kallel | Note Added: 0000241 | |
2015-07-13 17:40 | mohamed.kallel | Status | new => resolved |
2015-07-13 17:40 | mohamed.kallel | Resolution | open => fixed |
2015-07-13 17:40 | mohamed.kallel | Assigned To | => mohamed.kallel |