EasyCwmp
My View | View Issues | Change Log | Roadmap | My Account
  

View Issue Details [ Jump to Notes ] [ Issue History ] [ Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0000123easycwmp[All Projects] Helppublic2016-03-18 04:042016-05-11 13:02
Reporterwonderlive 
Assigned Tomohamed.kallel 
PriorityhighSeverityminorReproducibilityalways
StatusresolvedResolutionfixed 
PlatformAT91SAM9OSLinuxOS Version2.6.39
Summary0000123: HTTP SERVER CONNECTION FAILED
Description2016-03-18 10:11:50 [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=acs
config_init_local(77):: easycwmp.@local[0].password=Sct123
config_init_local(94):: easycwmp.@local[0].logging_level=4
config_init_acs(165):: easycwmp.@acs[0].username=acs
config_init_acs(190):: easycwmp.@acs[0].periodic_time=0001-01-01T00:00:00Z
config_init_acs(196):: easycwmp.@acs[0].http100continue_disable=1
config_init_acs(177):: easycwmp.@acs[0].periodic_enable=1
config_init_acs(171):: easycwmp.@acs[0].password=Sct123
config_init_acs(159):: easycwmp.@acs[0].url=http://192.168.169.108:80/acs [^]
config_init_acs(183):: easycwmp.@acs[0].periodic_interval=60
2016-03-18 10:11:51 [easycwmp] NOTICE - init periodic inform: reference time = n/a, interval = 60
2016-03-18 10:11:51 [easycwmp] NOTICE - external: execute update_value_change (null)
2016-03-18 10:11:53 [easycwmp] NOTICE - daemon started
2016-03-18 10:11:53 [easycwmp] NOTICE - external: execute inform device_id
2016-03-18 10:11:53 [easycwmp] NOTICE - external script exit
2016-03-18 10:11:53 [easycwmp] NOTICE - interface eth0 has ip 192.168.169.251
+++ HTTP SERVER CONFIGURATION +++
ip: '192.168.169.251'
port: '7547'
--- HTTP SERVER CONFIGURATION ---
2016-03-18 10:11:53 [easycwmp] NOTICE - http server initialized
2016-03-18 10:11:53 [easycwmp] NOTICE - entering main loop
+++ RECEIVED HTTP REQUEST +++
http_digest_auth_fail_response(335):: http_digest_auth_fail_response: header: Digest realm="realm@easycwmp",qop="auth",nonce="599002c19a8b35fe2970182c51d9a2a20000023f",opaque="328458fab28345ae87ab3210a8513b14eff452a2"--- RECEIVED HTTP REQUEST ---
+++ RECEIVED HTTP REQUEST +++
http_digest_auth_check(378):: http_digest_auth_check: header: username="acs", realm="realm@easycwmp", nonce="599002c19a8b35fe2970182c51d9a2a20000023f", uri="/", response="a3b97c6940a45876f571fe01c09e5eb3", qop=auth, nc=00000001, cnonce="981184409bb5d7096782306681f35a08", opaque="328458fab28345ae87ab3210a8513b14eff452a2"

--- RECEIVED HTTP REQUEST ---
+++ HTTP SERVER CONNECTION FAILED +++
+++ RECEIVED HTTP REQUEST +++
http_digest_auth_fail_response(335):: http_digest_auth_fail_response: header: Digest realm="realm@easycwmp",qop="auth",nonce="6f70de597eb161e72e21e5e65677106d00000267",opaque="328458fab28345ae87ab3210a8513b14eff452a2"--- RECEIVED HTTP REQUEST ---
+++ RECEIVED HTTP REQUEST +++
http_digest_auth_check(378):: http_digest_auth_check: header: username="acs", realm="realm@easycwmp", nonce="6f70de597eb161e72e21e5e65677106d00000267", uri="/", response="6f17488506469e6d9625827e283ea2af", qop=auth, nc=00000001, cnonce="e6d291990a740d6d03ea59ce3d984e59", opaque="328458fab28345ae87ab3210a8513b14eff452a2"

--- RECEIVED HTTP REQUEST ---
+++ HTTP SERVER CONNECTION FAILED +++
Steps To Reproduce1.run easycwmpd
2.acs initiate the connection actively
Additional Informationin http.c,i found this method,but i dont know how the condiction is false.

static void
http_del_client(struct uloop_process *uproc, int ret)
{
    wait(0);
    FREE(uproc);

    /* child terminated ; check return code */
    if (WIFEXITED(ret) && WEXITSTATUS(ret) == 0) {
        DDF("+++ HTTP SERVER CONNECTION SUCCESS +++\n");
        log_message(NAME, L_NOTICE, "acs initiated connection\n");
        cwmp_connection_request(EVENT_CONNECTION_REQUEST);
    } else {
        DDF("+++ HTTP SERVER CONNECTION FAILED +++\n");
    }
}
TagsNo tags attached.
Attached Files? file icon cpe_passive.pcapng [^] (1,192 bytes) 2016-03-18 04:04
pub file icon id_rsa.pub [^] (414 bytes) 2016-05-10 10:19
c file icon http.c [^] (8,570 bytes) 2016-05-10 13:46

- Relationships

-  Notes
(0000408)
mohamed.kallel (manager)
2016-03-18 23:17

 try to remove the FREE(uproc); in the line 299

done_child:
              fclose(fp);
              FREE(uproc); //<============== remove this line
              DDF("--- RECEIVED HTTP REQUEST ---\n");
              exit(status);
         }

and tes if your problem is fixed. Please let me know about the result
(0000409)
wonderlive (reporter)
2016-03-21 02:26

 hello mohamed.kallel,
i remove the line which you told me,and it seems not fixed.i print out the value of 'ret' and 'status' in the following,would it help?

+++ RECEIVED HTTP REQUEST +++
http_digest_auth_check(378):: http_digest_auth_check: header: username="acs", realm="realm@easycwmp", nonce="a852e1b405e404976c784bb1009745c90000011e", uri="/",
 response="b3ac3973abf96a1f86b13f8611eb088c", qop=auth, nc=00000001, cnonce="3d715b89c264584f49a72e8330cf4f7d", opaque="328458fab28345ae87ab3210a8513b14eff452a2
"
--- RECEIVED HTTP REQUEST ---status 0
--- http_del_client ---ret 3328
(0000411)
okraits (reporter)
2016-04-03 12:15

 I think i am experiencing the same issue, at least it's the same error message "HTTP SERVER CONNECTION FAILED" and thus same line of code.

I was testing the reliability of connection requests sent from GenieACS to easycwmp and i noticed that in quite a few cases easycwmp simply didn't initiate the requested connection and i didn't find a reason why. I already discussed this topic on the GenieACS mailinglist and the developer thinks it's an easycwmp issue:

http://lists.genieacs.com/pipermail/users/2016-March/000677.html [^]
(0000412)
okraits (reporter)
2016-04-03 12:18

 BTW, i got the same return value as wonderlive. If needed, i can provide easycwmp debug logs and a tcp dump.
(0000413)
mohamed.kallel (manager)
2016-04-04 11:59

 Lokks like a bug. I have to investigate more in order to confirm it.
Sorry, I can not do it right now since I m taken by other projects.
I will let you know when I will fix it
(0000437)
mohamed.kallel (manager)
2016-05-04 15:46

 It's not reporduced for me.
Could you add more debug message inorder to follow the reason.

Please add the following debug line in the http_new_client() function:

 else if (auth_digest = strstr(buffer, "Authorization: Digest ")) {
    if (http_digest_auth_check("GET", "/", auth_digest + strlen("Authorization: Digest "), REALM, username, password, 300) == MHD_YES)
            auth_status = 1;
    else
        auth_status = 0;
}
DDF("--- MORE DEBUG(1) auth_status = %d ---\n", auth_status); //<---- Add this line
(0000438)
mohamed.kallel (manager)
2016-05-04 15:53

 What's your linux system?
(0000439)
mohamed.kallel (manager)
2016-05-04 15:57

 Please try to remove the FREE(uproc); in the done_child: label

done_child:
            fclose(fp);
            FREE(uproc); //<---- remove this line
            DDF("--- RECEIVED HTTP REQUEST ---\n");
            exit(status);

 and remove also the FREE(uproc); from the http_del_client() function


http_del_client(struct uloop_process *uproc, int ret)
{
    wait(0);
    FREE(uproc); //<------ remove this line

    /* child terminated ; check return code */


And then check if your problem is reproduced
(0000442)
okraits (reporter)
2016-05-09 14:45

 +++ RECEIVED EMPTY HTTP RESPONSE +++
+++ RECEIVED HTTP REQUEST +++
--- MORE DEBUG(1) auth_status = 0 ---
--- MORE DEBUG(1) auth_status = 0 ---
--- MORE DEBUG(1) auth_status = 0 ---
--- MORE DEBUG(1) auth_status = 0 ---
http_digest_auth_fail_response(335):: http_digest_auth_fail_response: header: Digest realm="realm@easycwmp",qop="auth",nonce="",opaque=""--- RECEIVED HTTP REQUEST ---
+++ RECEIVED HTTP REQUEST +++
--- MORE DEBUG(1) auth_status = 0 ---
http_digest_auth_check(378):: http_digest_auth_check: header: username="tdt",realm="realm@easycwmp",nonce="",uri="/",qop=auth,nc=00000001,cnonce="",response="",opaque=""
--- MORE DEBUG(1) auth_status = 1 ---
--- MORE DEBUG(1) auth_status = 1 ---
--- MORE DEBUG(1) auth_status = 1 ---
--- MORE DEBUG(1) auth_status = 1 ---
--- RECEIVED HTTP REQUEST ---
+++ HTTP SERVER CONNECTION FAILED +++
(0000443)
okraits (reporter)
2016-05-09 14:52
edited on: 2016-05-09 14:53

 I commented out the FREE calls you mentioned and the issue still occurs.

I run easycwmp on OpenWRT chaos calmer.
(0000444)
mohamed.kallel (manager)
2016-05-09 15:48

 This is wierd,
I use also OpenWRT chaos calmer. And I did not get a such behaviour.
Could you provide to me a remote access to your equipment for tests. And also the make config to build the package according to your hardware
(0000445)
mohamed.kallel (manager)
2016-05-09 17:44

 does the problem always reproduced? Or it's rarely reproduced?
(0000446)
okraits (reporter)
2016-05-10 08:45

 The problem occurs with varying intensity. With a script, i create every 10 seconds a task in GenieACS which asks for a connection request to set a parameter. Here's my debugging output of the GenieACS REST interface:

10 May 08:27:37 - processed
10 May 08:27:48 - processed
10 May 08:27:59 - processed
10 May 08:28:10 - processed
10 May 08:28:23 - processed
10 May 08:28:38 - queued
10 May 08:28:49 - processed
10 May 08:29:03 - queued
10 May 08:29:17 - queued
10 May 08:29:28 - processed
10 May 08:29:39 - processed
10 May 08:29:53 - queued
10 May 08:30:04 - processed
10 May 08:30:15 - processed
10 May 08:30:26 - processed
10 May 08:30:37 - processed
10 May 08:30:51 - queued
10 May 08:31:05 - queued
10 May 08:31:16 - processed
10 May 08:31:31 - queued
10 May 08:31:42 - processed
10 May 08:31:56 - queued
10 May 08:32:07 - processed
10 May 08:32:21 - queued
10 May 08:32:32 - processed
10 May 08:32:43 - processed
10 May 08:32:54 - processed
10 May 08:33:08 - queued
10 May 08:33:22 - queued
10 May 08:33:36 - queued
10 May 08:33:47 - processed
10 May 08:33:58 - processed

All lines with "queued" are the cases in which the problem occurs.
(0000447)
okraits (reporter)
2016-05-10 08:50

 I can provide you remote access to the CPE. Could you please send me your public SSH key?
(0000448)
mohamed.kallel (manager)
2016-05-10 10:20

 public key attached
(0000449)
mohamed.kallel (manager)
2016-05-10 10:25

 what you get when you make Connection Request with your browser (FirFox, Chrome...).

Do you get the same error?


You can make Connection Request from your browser with the URL:

http://<address [^] of your router>:7547
(0000450)
okraits (reporter)
2016-05-10 10:51

 The error doesn't occur when i connect to easycwmp with a browser.

Can you please give me your mail address so i can send you the connection details for the CPE?
(0000451)
mohamed.kallel (manager)
2016-05-10 11:14

 my email address is in the headers of the source file of easycwmp
(0000452)
mohamed.kallel (manager)
2016-05-10 11:16

 could you remove the following line too and retry

http_del_client(struct uloop_process *uproc, int ret)
{
    wait(0); //<------ remove this line
    FREE(uproc); //<------ remove this line

    /* child terminated ; check return code */
(0000453)
okraits (reporter)
2016-05-10 12:50
edited on: 2016-05-10 12:54

 I removed the comments in front of the FREE calls and commented out the wait call in http_del_client().

THe problem didn't occur then. I tried for > 30 min in 10 second intervals as i mentioned above.

Should i send you the connection details for the CPE so you can do tests on it?
(0000454)
mohamed.kallel (manager)
2016-05-10 13:02

 OK, so the problem is solved when you removed the wait(0) ?!

So as summary to fix the problem you have to remove the following 2 lines:

1)

done_child:
              fclose(fp);
              FREE(uproc); //<============== remove this line
              DDF("--- RECEIVED HTTP REQUEST ---\n");
              exit(status);
         }

2)

http_del_client(struct uloop_process *uproc, int ret)
{
    wait(0); //<------ remove this line
    FREE(uproc);

And the problme will be solved.
Could you confirm that

I will add that in the future deliveries.

And Thanks I do not need the Device connection details if the problem is solved
(0000455)
okraits (reporter)
2016-05-10 13:13

 To fix the issue, you have to remove only the "wait(0);" in http_del_client(). The FREE calls at the done_child: label and in http_del_client() are active again.
(0000456)
mohamed.kallel (manager)
2016-05-10 13:27

 You have to keep all FREE except this one

done_child:
              fclose(fp);
              FREE(uproc); //<============== remove this line
              DDF("--- RECEIVED HTTP REQUEST ---\n");
              exit(status);
         }


You have to remove it. It's buggy FREE. It could cause problems.

Could you please remove it and test again and provide the result of your test
(0000457)
okraits (reporter)
2016-05-10 13:27

 But can we safely remove the call of "wait(0);"? We don't wait for the child process to terminate then and the return value is not valid.

If yes, then why did that line exist in the first place?
(0000458)
okraits (reporter)
2016-05-10 13:48

 I removed the FREE call at the done_child: label and the "wait(0);" call in http_del_client() and the problem doesn't occur.

For reference i've attached the http.c i'm using and which works.
(0000459)
okraits (reporter)
2016-05-10 14:03

 See also https://github.com/pivasoftware/easycwmp/pull/24. [^]
(0000460)
mohamed.kallel (manager)
2016-05-10 15:00

 You can safely remove the call of "wait(0);".
It's a typo from old versions.
in fact the wait of child is done by the libubox functions.
(0000461)
mohamed.kallel (manager)
2016-05-10 15:01

 I merged your pull. Thank you for your contrbution!
(0000462)
okraits (reporter)
2016-05-10 15:04

 Thank you - you're welcome.
(0000470)
mohamed.kallel (manager)
2016-05-11 13:02

 fixed in EasyCwmp-1.2.8

- Issue History
Date Modified Username Field Change
2016-03-18 04:04 wonderlive New Issue
2016-03-18 04:04 wonderlive File Added: cpe_passive.pcapng
2016-03-18 23:17 mohamed.kallel Note Added: 0000408
2016-03-21 02:26 wonderlive Note Added: 0000409
2016-04-03 12:15 okraits Note Added: 0000411
2016-04-03 12:18 okraits Note Added: 0000412
2016-04-04 11:59 mohamed.kallel Note Added: 0000413
2016-05-04 15:46 mohamed.kallel Note Added: 0000437
2016-05-04 15:53 mohamed.kallel Note Added: 0000438
2016-05-04 15:57 mohamed.kallel Note Added: 0000439
2016-05-09 14:45 okraits Note Added: 0000442
2016-05-09 14:52 okraits Note Added: 0000443
2016-05-09 14:53 okraits Note Edited: 0000443 View Revisions
2016-05-09 15:48 mohamed.kallel Note Added: 0000444
2016-05-09 17:44 mohamed.kallel Note Added: 0000445
2016-05-10 08:45 okraits Note Added: 0000446
2016-05-10 08:50 okraits Note Added: 0000447
2016-05-10 10:19 mohamed.kallel File Added: id_rsa.pub
2016-05-10 10:20 mohamed.kallel Note Added: 0000448
2016-05-10 10:25 mohamed.kallel Note Added: 0000449
2016-05-10 10:51 okraits Note Added: 0000450
2016-05-10 11:14 mohamed.kallel Note Added: 0000451
2016-05-10 11:16 mohamed.kallel Note Added: 0000452
2016-05-10 12:50 okraits Note Added: 0000453
2016-05-10 12:54 okraits Note Edited: 0000453 View Revisions
2016-05-10 13:02 mohamed.kallel Note Added: 0000454
2016-05-10 13:13 okraits Note Added: 0000455
2016-05-10 13:27 mohamed.kallel Note Added: 0000456
2016-05-10 13:27 okraits Note Added: 0000457
2016-05-10 13:46 okraits File Added: http.c
2016-05-10 13:48 okraits Note Added: 0000458
2016-05-10 14:03 okraits Note Added: 0000459
2016-05-10 15:00 mohamed.kallel Note Added: 0000460
2016-05-10 15:01 mohamed.kallel Note Added: 0000461
2016-05-10 15:04 okraits Note Added: 0000462
2016-05-11 13:02 mohamed.kallel Note Added: 0000470
2016-05-11 13:02 mohamed.kallel Status new => resolved
2016-05-11 13:02 mohamed.kallel Resolution open => fixed
2016-05-11 13:02 mohamed.kallel Assigned To => mohamed.kallel

Copyright © 2000 - 2021 MantisBT Team
Powered by Mantis Bugtracker