View Issue Details

IDProjectCategoryView StatusLast Update
0000114easycwmpHelppublic2016-01-20 11:11
Reporterwonderlive Assigned Tomohamed.kallel  
PriorityhighSeverityminorReproducibilityalways
Status resolvedResolutionno change required 
PlatformAT91SAM9OSLinuxOS Version2.6.39
Summary0000114: sending http message failed
DescriptionI use VigorACS.When I started up easycwmpd,my CPE appeared in VigorACS.But the ACS server's CPU used increased 25% everytime my CPE sent Inform.Then I use another kind of CPE, the CPU seems to be normal.And I found that,my CPE always 'sending http message failed',because the ACS didn't return http code 200.
My question is,did I have any problem in my config,or Send Inform message?

2007-01-11 16:11:30 [easycwmp] NOTICE - add event '0 BOOTSTRAP'
2007-01-11 16:11:30 [easycwmp] NOTICE - add event '1 BOOT'
2007-01-11 16:11:30 [easycwmp] NOTICE - add event '2 PERIODIC'
2007-01-11 16:11:30 [easycwmp] NOTICE - external script init
config_init_local(55):: easycwmp.@local[0].interface=eth0
config_init_local(65):: easycwmp.@local[0].port=7547
config_init_local(83):: easycwmp.@local[0].ubus_socket=/tmp/ubus.sock
config_init_local(71):: easycwmp.@local[0].username=easycwmp
config_init_local(77):: easycwmp.@local[0].password=easycwmp
config_init_local(94):: easycwmp.@local[0].logging_level=4
config_init_acs(159):: easycwmp.@acs[0].url=http://192.168.169.128:8080/ACSServer/services/UnAuthACSServlet
config_init_acs(165):: easycwmp.@acs[0].username=acs
config_init_acs(171):: easycwmp.@acs[0].password=password
config_init_acs(177):: easycwmp.@acs[0].periodic_enable=1
config_init_acs(183):: easycwmp.@acs[0].periodic_interval=100
config_init_acs(190):: easycwmp.@acs[0].periodic_time=0001-01-01T00:00:00Z
2007-01-11 16:11:30 [easycwmp] NOTICE - init periodic inform: reference time = n/a, interval = 100
2007-01-11 16:11:30 [easycwmp] NOTICE - external: execute update_value_change (null)
2007-01-11 16:11:32 [easycwmp] NOTICE - daemon started
2007-01-11 16:11:32 [easycwmp] NOTICE - external: execute inform device_id
2007-01-11 16:11:32 [easycwmp] NOTICE - external script exit
2007-01-11 16:11:32 [easycwmp] NOTICE - add event '1 BOOT'
2007-01-11 16:11:32 [easycwmp] NOTICE - interface eth0 has ip 192.168.169.251
+++ HTTP SERVER CONFIGURATION +++
ip: '192.168.169.251'
port: '7547'
--- HTTP SERVER CONFIGURATION ---
2007-01-11 16:11:32 [easycwmp] NOTICE - http server initialized
2007-01-11 16:11:32 [easycwmp] NOTICE - entering main loop
2007-01-11 16:11:32 [easycwmp] NOTICE - start session
+++ HTTP CLIENT CONFIGURATION +++
http_client_init(50):: url: http://192.168.169.128:8080/ACSServer/services/UnAuthACSServlet
http_client_init(56):: ssl_verify: SSL certificate validation disabled.
--- HTTP CLIENT CONFIGURATION ---
2007-01-11 16:11:32 [easycwmp] NOTICE - configured acs url http://192.168.169.128:8080/ACSServer/services/UnAuthACSServlet
2007-01-11 16:11:32 [easycwmp] NOTICE - external script init
2007-01-11 16:11:32 [easycwmp] NOTICE - external: execute inform parameter
2007-01-11 16:11:33 [easycwmp] NOTICE - send Inform
+++ SEND HTTP REQUEST +++
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
 <soap_env:Envelope
xmlns:soap_env="http://schemas.xmlsoap.org/soap/envelope/"
xmlns:soap_enc="http://schemas.xmlsoap.org/soap/encoding/"
xmlns:xsd="http://www.w3.org/2001/XMLSchema"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:cwmp="urn:dslforum-org:cwmp-1-2">
  <soap_env:Header>
   <cwmp:ID soap_env:mustUnderstand="1">1</cwmp:ID>
  </soap_env:Header>
  <soap_env:Body>
   <cwmp:Inform>
    <DeviceId>
     <Manufacturer>SCT</Manufacturer>
     <OUI>654323</OUI>
     <ProductClass>tau</ProductClass>
     <SerialNumber>654321123452</SerialNumber>
    </DeviceId>
    <Event soap_enc:arrayType="cwmp:EventStruct[3]">
     <EventStruct>
      <EventCode>0 BOOTSTRAP</EventCode>
      <CommandKey />
     </EventStruct>
     <EventStruct>
      <EventCode>1 BOOT</EventCode>
      <CommandKey />
     </EventStruct>
     <EventStruct>
      <EventCode>2 PERIODIC</EventCode>
      <CommandKey />
     </EventStruct>
    </Event>
    <MaxEnvelopes>1</MaxEnvelopes>
    <CurrentTime>2007-01-11T16:11:32+08:00</CurrentTime>
    <RetryCount>0</RetryCount>
    <ParameterList soap_enc:arrayType="cwmp:ParameterValueStruct[11]">
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.DeviceInfo.HardwareVersion</Name>
      <Value xsi:type="xsd:string">1.0</Value>
     </ParameterValueStruct>
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.DeviceInfo.Manufacturer</Name>
      <Value xsi:type="xsd:string">SCT</Value>
     </ParameterValueStruct>
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.DeviceInfo.ManufacturerOUI</Name>
      <Value xsi:type="xsd:string">654323</Value>
     </ParameterValueStruct>
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.DeviceInfo.ProductClass</Name>
      <Value xsi:type="xsd:string">tau</Value>
     </ParameterValueStruct>
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.DeviceInfo.ProvisioningCode</Name>
      <Value xsi:type="xsd:string"></Value>
     </ParameterValueStruct>
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.DeviceInfo.SerialNumber</Name>
      <Value xsi:type="xsd:string">654321123452</Value>
     </ParameterValueStruct>
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.DeviceInfo.SoftwareVersion</Name>
      <Value xsi:type="xsd:string">1.2</Value>
     </ParameterValueStruct>
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.DeviceInfo.SpecVersion</Name>
      <Value xsi:type="xsd:string">1.0</Value>
     </ParameterValueStruct>
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.ManagementServer.ConnectionRequestURL</Name>
      <Value xsi:type="xsd:string">http://192.168.169.251:7547/</Value>
     </ParameterValueStruct>
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.ManagementServer.ParameterKey</Name>
      <Value xsi:type="xsd:string"></Value>
     </ParameterValueStruct>
     <ParameterValueStruct>
      <Name>InternetGatewayDevice.WANDevice.1.WANConnectionDevice.1.WANIPConnection.1.ExternalIPAddress</Name>
      <Value xsi:type="xsd:string"></Value>
     </ParameterValueStruct>
    </ParameterList>
   </cwmp:Inform>
  </soap_env:Body>
 </soap_env:Envelope>
--- SEND HTTP REQUEST ---
* Trying 192.168.169.128...
* Connected to 192.168.169.128 (192.168.169.128) port 8080 (#0)
> POST /ACSServer/services/UnAuthACSServlet HTTP/1.1

Host: 192.168.169.128:8080

User-Agent: easycwmp

Content-Type: text/html; charset="utf-8"

SOAPAction:

Content-Length: 3239

Expect: 100-continue



< HTTP/1.1 100 Continue

* We are completely uploaded and fine
* Operation timed out after 30001 milliseconds with 0 bytes received
* Closing connection 0
2007-01-11 16:12:03 [easycwmp] NOTICE - sending http message failed
rpc_inform(218): sending Inform http message failed
2007-01-11 16:12:03 [easycwmp] NOTICE - sending Inform failed
2007-01-11 16:12:03 [easycwmp] NOTICE - external: execute apply service
2007-01-11 16:12:03 [easycwmp] NOTICE - external script exit
2007-01-11 16:12:03 [easycwmp] NOTICE - end session failed
2007-01-11 16:12:03 [easycwmp] NOTICE - retry session in 7 sec, RetryCount = 1
TagsNo tags attached.
e-mail notification

Activities

mohamed.kallel

2016-01-19 09:23

administrator   ~0000384

Could you please attach the traffic capture (a pcap file).

mohamed.kallel

2016-01-19 09:28

administrator   ~0000385

Last edited: 2016-01-19 09:49

Could you try to add the following config in your easycwmp config:

uci set easycwmp.@acs[0].http100continue_disable=1

And check if your problem is reproduced.

wonderlive

2016-01-20 02:44

reporter  

tau_cwmp.pcap (4,280 bytes)

wonderlive

2016-01-20 03:15

reporter   ~0000387

Thanks for your help.the pcap is uploaded.

i have tried uci set easycwmp.@acs[0].http100continue_disable=1,it didn't work.
i think this might be the acs's problem.i tried OpenACS,but it didn't go well,some exceptions occured,the acs response http error 500.Dont't mind,i will try it later.

i found a simulator acs,and tried it.
When cpe received < HTTP/1.1 401 Unauthorized,why cpe close the connection 0,and create another?the simulator acs refused the second connection.

log:
* Connected to 192.168.169.108 (192.168.169.108) port 9099 (#0)
> POST /acs HTTP/1.1
Host: 192.168.169.108:9099
User-Agent: easycwmp
Content-Type: text/html; charset="utf-8"
SOAPAction:
Content-Length: 3138
                                                                                
* upload completely sent off: 3138 out of 3138 bytes
< HTTP/1.1 401 Unauthorized
< Date: Wed, 20-Jan-16 10:05:46 GMT
< Server: NCSA/1.3
< MIME-version: 1.0
< Content-type: text/html
< WWW-Authenticate: Digest realm="ACSSimTool",nonce="VHVlIE5vdiAyOCAxNDo0Nzo1MC
AyMDA2MS4xLjEuMTI1",opaque="5ccc069c403ebaf9f0171e9517f40e41",qop="auth"
* no chunk, no close, no size. Assume close to signal end
<
* Closing connection 0
* Issue another request to this URL: 'http://192.168.169.108:9099/acs'
* Hostname 192.168.169.108 was found in DNS cache
* Trying 192.168.169.108...
* connect to 192.168.169.108 port 9099 failed: Connection refused
* Failed to connect to 192.168.169.108 port 9099: Connection refused
* Closing connection 1

wonderlive

2016-01-20 03:17

reporter  

ar_cwmp_ok.pcap (93,012 bytes)

wonderlive

2016-01-20 03:26

reporter   ~0000388

tau_cwmp.pcap,packets between easycwmp and VigorACS

ar_cwmp_ok.pcap,another cpe,using their own cwmp client.it can received http code 200 after sending Inform.

wonderlive

2016-01-20 08:27

reporter   ~0000389

I have found the cause of the problem,it's my ACS.
I use xacs,and it works.
Thanks for helping.

Issue History

Date Modified Username Field Change
2016-01-19 05:28 wonderlive New Issue
2016-01-19 09:23 mohamed.kallel Note Added: 0000384
2016-01-19 09:28 mohamed.kallel Note Added: 0000385
2016-01-19 09:49 mohamed.kallel Note Edited: 0000385
2016-01-20 02:44 wonderlive File Added: tau_cwmp.pcap
2016-01-20 03:15 wonderlive Note Added: 0000387
2016-01-20 03:17 wonderlive File Added: ar_cwmp_ok.pcap
2016-01-20 03:26 wonderlive Note Added: 0000388
2016-01-20 08:27 wonderlive Note Added: 0000389
2016-01-20 11:11 mohamed.kallel Status new => resolved
2016-01-20 11:11 mohamed.kallel Resolution open => no change required
2016-01-20 11:11 mohamed.kallel Assigned To => mohamed.kallel