View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000061easycwmpQuestionpublic2015-06-24 19:482015-07-13 17:40
Reporterlferrarotti Assigned Tomohamed.kallel  
PrioritynormalSeveritymajorReproducibilityalways
Status resolvedResolutionfixed 
Summary0000061: Parse Inform xml message from ACS failed
DescriptionWhen 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.
TagsNo tags attached.

Activities

lferrarotti

2015-06-24 19:48

reporter  

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
easycwmp-soap.txt (3,336 bytes)   

mohamed.kallel

2015-06-25 00:48

administrator   ~0000207

Could you attach a traffic capture of your issue

lferrarotti

2015-06-25 01:27

reporter  

capture.pcap (40,732 bytes)

lferrarotti

2015-06-25 01:27

reporter   ~0000208

We have attached the capture

mohamed.kallel

2015-06-25 10:08

administrator   ~0000209

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.

lferrarotti

2015-06-25 11:22

reporter   ~0000210

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

lferrarotti

2015-06-25 11:22

reporter  

capture3.pcap (10,237 bytes)

mohamed.kallel

2015-06-25 12:06

administrator   ~0000211

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

lferrarotti

2015-06-25 12:27

reporter   ~0000212

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

lferrarotti

2015-06-25 12:28

reporter  

capture4.pcap (20,118 bytes)

mohamed.kallel

2015-06-25 13:18

administrator   ~0000213

Last edited: 2015-06-25 17:58

 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

lferrarotti

2015-06-25 18:04

reporter   ~0000214

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

mohamed.kallel

2015-06-25 19:47

administrator   ~0000215

Last edited: 2015-06-25 21:18

 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)

lferrarotti

2015-06-25 21:50

reporter   ~0000216

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

lferrarotti

2015-06-25 21:50

reporter  

capture5.pcap (14,742 bytes)

mohamed.kallel

2015-06-26 01:12

administrator   ~0000217

looks the same problem. looks an interoperability problem. looks an xml parse problem. I will investigate the problem in the next release

lferrarotti

2015-06-29 10:37

reporter   ~0000221

Last edited: 2015-06-29 10:38

 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

lferrarotti

2015-06-29 18:43

reporter   ~0000223

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.

lferrarotti

2015-06-29 18:43

reporter  

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
tr069-cli-log.txt (5,142 bytes)   

lferrarotti

2015-06-29 18:43

reporter  

capture6.pcap (11,450 bytes)

mohamed.kallel

2015-06-30 13:03

administrator   ~0000225

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.

lferrarotti

2015-06-30 16:20

reporter   ~0000227

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

mohamed.kallel

2015-07-13 17:40

administrator   ~0000241

fixed in EasyCwmp-1.1.4

Issue History

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