View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000183 | easycwmp | Bug | public | 2016-11-25 17:17 | 2016-11-30 10:06 |
| Reporter | dgr999 | Assigned To | mohamed.kallel | ||
| Priority | high | Severity | major | Reproducibility | always |
| Status | resolved | Resolution | fixed | ||
| Platform | VM | OS | Ubuntu Server | OS Version | 16.04 LTS |
| Summary | 0000183: ACS Retry timeout incorrect | ||||
| Description | I was testing the retry and noticed that sometimes when watching the easycwmpd output on the console, there was no timeout. So I allowed it go on for 10 retries and could also see that the timeouts were too short when they are longer than 60 seconds. I've tried this a number of times and it always happens. I believe the problem could be the Periodic Interval timeout which I've left as 100 seconds. The maximium timeout I'm seeing is 70 seconds which with the timeout of 30 seconds curl timeout is the 100 seconds timeout. I'm also seeing timeout of zero seconds, see attached syslog and here are the results of my last test. Retry 1 - 8 seconds Retry 2 - 15 seconds Retry 3 - 0 (zero) seconds Retry 4 - 60 seconds Retry 5 - 0 (zero) seconds Retry 6 - 70 seconds Retry 7 - 70 seconds Retry 8 - 70 seconds Retry 9 - 70 seconds Retry 10 70 seconds I took the measurement between the lines "retry session" and "start session" in the syslog. | ||||
| Steps To Reproduce | Turn off ACS Start easycwmpd -f -b After 10 Retries stop easycwmpd and collect syslog | ||||
| Tags | No tags attached. | ||||
| e-mail notification | |||||
|
|
cwmp-retry-error.txt (9,878 bytes)
Nov 25 15:17:29 easycwmp easycwmpd: daemon started Nov 25 15:17:29 easycwmp easycwmpd: external: execute inform device_id Nov 25 15:17:29 easycwmp easycwmpd: external script exit Nov 25 15:17:29 easycwmp easycwmpd: add event '1 BOOT' Nov 25 15:17:29 easycwmp easycwmpd: interface eth0 has ip 172.16.2.212 Nov 25 15:17:29 easycwmp easycwmpd: http server initialized Nov 25 15:17:29 easycwmp easycwmpd: entering main loop Nov 25 15:17:29 easycwmp easycwmpd: start session Nov 25 15:17:29 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:17:29 easycwmp easycwmpd: external script init Nov 25 15:17:29 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:17:29 easycwmp easycwmpd: send Inform Nov 25 15:17:59 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30000 milliseconds Nov 25 15:17:59 easycwmp easycwmpd: sending http message failed Nov 25 15:17:59 easycwmp easycwmpd: sending Inform failed Nov 25 15:17:59 easycwmp easycwmpd: external: execute apply service Nov 25 15:17:59 easycwmp easycwmpd: external script exit Nov 25 15:17:59 easycwmp easycwmpd: end session failed Nov 25 15:17:59 easycwmp easycwmpd: retry session in 7 sec, RetryCount = 1 Nov 25 15:18:07 easycwmp easycwmpd: start session Nov 25 15:18:07 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:18:07 easycwmp easycwmpd: external script init Nov 25 15:18:07 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:18:07 easycwmp easycwmpd: send Inform Nov 25 15:18:37 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30000 milliseconds Nov 25 15:18:37 easycwmp easycwmpd: sending http message failed Nov 25 15:18:37 easycwmp easycwmpd: sending Inform failed Nov 25 15:18:37 easycwmp easycwmpd: external: execute apply service Nov 25 15:18:37 easycwmp easycwmpd: external script exit Nov 25 15:18:37 easycwmp easycwmpd: end session failed Nov 25 15:18:37 easycwmp easycwmpd: retry session in 15 sec, RetryCount = 2 Nov 25 15:18:52 easycwmp easycwmpd: start session Nov 25 15:18:52 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:18:52 easycwmp easycwmpd: external script init Nov 25 15:18:52 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:18:52 easycwmp easycwmpd: send Inform Nov 25 15:19:22 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30001 milliseconds Nov 25 15:19:22 easycwmp easycwmpd: sending http message failed Nov 25 15:19:22 easycwmp easycwmpd: sending Inform failed Nov 25 15:19:22 easycwmp easycwmpd: external: execute apply service Nov 25 15:19:22 easycwmp easycwmpd: external script exit Nov 25 15:19:22 easycwmp easycwmpd: end session failed Nov 25 15:19:22 easycwmp easycwmpd: retry session in 30 sec, RetryCount = 3 Nov 25 15:19:22 easycwmp easycwmpd: add event '2 PERIODIC' Nov 25 15:19:22 easycwmp easycwmpd: start session Nov 25 15:19:22 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:19:22 easycwmp easycwmpd: external script init Nov 25 15:19:22 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:19:22 easycwmp easycwmpd: send Inform Nov 25 15:19:52 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30001 milliseconds Nov 25 15:19:52 easycwmp easycwmpd: sending http message failed Nov 25 15:19:52 easycwmp easycwmpd: sending Inform failed Nov 25 15:19:52 easycwmp easycwmpd: external: execute apply service Nov 25 15:19:52 easycwmp easycwmpd: external script exit Nov 25 15:19:52 easycwmp easycwmpd: end session failed Nov 25 15:19:52 easycwmp easycwmpd: retry session in 60 sec, RetryCount = 4 Nov 25 15:20:52 easycwmp easycwmpd: start session Nov 25 15:20:52 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:20:52 easycwmp easycwmpd: external script init Nov 25 15:20:52 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:20:52 easycwmp easycwmpd: send Inform Nov 25 15:21:22 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30001 milliseconds Nov 25 15:21:22 easycwmp easycwmpd: sending http message failed Nov 25 15:21:22 easycwmp easycwmpd: sending Inform failed Nov 25 15:21:22 easycwmp easycwmpd: external: execute apply service Nov 25 15:21:22 easycwmp easycwmpd: external script exit Nov 25 15:21:22 easycwmp easycwmpd: end session failed Nov 25 15:21:22 easycwmp easycwmpd: retry session in 120 sec, RetryCount = 5 Nov 25 15:21:22 easycwmp easycwmpd: add event '2 PERIODIC' Nov 25 15:21:22 easycwmp easycwmpd: start session Nov 25 15:21:22 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:21:22 easycwmp easycwmpd: external script init Nov 25 15:21:22 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:21:22 easycwmp easycwmpd: send Inform Nov 25 15:21:52 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30001 milliseconds Nov 25 15:21:52 easycwmp easycwmpd: sending http message failed Nov 25 15:21:52 easycwmp easycwmpd: sending Inform failed Nov 25 15:21:52 easycwmp easycwmpd: external: execute apply service Nov 25 15:21:52 easycwmp easycwmpd: external script exit Nov 25 15:21:52 easycwmp easycwmpd: end session failed Nov 25 15:21:52 easycwmp easycwmpd: retry session in 240 sec, RetryCount = 6 Nov 25 15:23:02 easycwmp easycwmpd: add event '2 PERIODIC' Nov 25 15:23:02 easycwmp easycwmpd: start session Nov 25 15:23:02 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:23:02 easycwmp easycwmpd: external script init Nov 25 15:23:02 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:23:02 easycwmp easycwmpd: send Inform Nov 25 15:23:32 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30001 milliseconds Nov 25 15:23:32 easycwmp easycwmpd: sending http message failed Nov 25 15:23:32 easycwmp easycwmpd: sending Inform failed Nov 25 15:23:32 easycwmp easycwmpd: external: execute apply service Nov 25 15:23:32 easycwmp easycwmpd: external script exit Nov 25 15:23:32 easycwmp easycwmpd: end session failed Nov 25 15:23:32 easycwmp easycwmpd: retry session in 480 sec, RetryCount = 7 Nov 25 15:24:42 easycwmp easycwmpd: add event '2 PERIODIC' Nov 25 15:24:42 easycwmp easycwmpd: start session Nov 25 15:24:42 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:24:42 easycwmp easycwmpd: external script init Nov 25 15:24:42 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:24:42 easycwmp easycwmpd: send Inform Nov 25 15:25:12 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30001 milliseconds Nov 25 15:25:12 easycwmp easycwmpd: sending http message failed Nov 25 15:25:12 easycwmp easycwmpd: sending Inform failed Nov 25 15:25:12 easycwmp easycwmpd: external: execute apply service Nov 25 15:25:12 easycwmp easycwmpd: external script exit Nov 25 15:25:12 easycwmp easycwmpd: end session failed Nov 25 15:25:12 easycwmp easycwmpd: retry session in 960 sec, RetryCount = 8 Nov 25 15:26:22 easycwmp easycwmpd: add event '2 PERIODIC' Nov 25 15:26:22 easycwmp easycwmpd: start session Nov 25 15:26:22 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:26:22 easycwmp easycwmpd: external script init Nov 25 15:26:22 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:26:22 easycwmp easycwmpd: send Inform Nov 25 15:26:52 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30001 milliseconds Nov 25 15:26:52 easycwmp easycwmpd: sending http message failed Nov 25 15:26:52 easycwmp easycwmpd: sending Inform failed Nov 25 15:26:52 easycwmp easycwmpd: external: execute apply service Nov 25 15:26:52 easycwmp easycwmpd: external script exit Nov 25 15:26:52 easycwmp easycwmpd: end session failed Nov 25 15:26:52 easycwmp easycwmpd: retry session in 1920 sec, RetryCount = 9 Nov 25 15:28:02 easycwmp easycwmpd: add event '2 PERIODIC' Nov 25 15:28:02 easycwmp easycwmpd: start session Nov 25 15:28:02 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:28:02 easycwmp easycwmpd: external script init Nov 25 15:28:02 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:28:02 easycwmp easycwmpd: send Inform Nov 25 15:28:32 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30000 milliseconds Nov 25 15:28:32 easycwmp easycwmpd: sending http message failed Nov 25 15:28:32 easycwmp easycwmpd: sending Inform failed Nov 25 15:28:32 easycwmp easycwmpd: external: execute apply service Nov 25 15:28:32 easycwmp easycwmpd: external script exit Nov 25 15:28:32 easycwmp easycwmpd: end session failed Nov 25 15:28:32 easycwmp easycwmpd: retry session in 3840 sec, RetryCount = 10 Nov 25 15:29:42 easycwmp easycwmpd: add event '2 PERIODIC' Nov 25 15:29:42 easycwmp easycwmpd: start session Nov 25 15:29:42 easycwmp easycwmpd: configured acs url http://172.16.2.188:7547 Nov 25 15:29:42 easycwmp easycwmpd: external script init Nov 25 15:29:42 easycwmp easycwmpd: external: execute inform parameter Nov 25 15:29:42 easycwmp easycwmpd: send Inform Nov 25 15:30:12 easycwmp easycwmpd: LibCurl Error: Connection timed out after 30001 milliseconds Nov 25 15:30:12 easycwmp easycwmpd: sending http message failed Nov 25 15:30:12 easycwmp easycwmpd: sending Inform failed Nov 25 15:30:12 easycwmp easycwmpd: external: execute apply service Nov 25 15:30:12 easycwmp easycwmpd: error occured when trying to write to the pipe Nov 25 15:30:12 easycwmp easycwmpd: error occured when trying to write to the pipe Nov 25 15:30:12 easycwmp easycwmpd: external script exit Nov 25 15:30:12 easycwmp easycwmpd: error occured when trying to write to the pipe Nov 25 15:30:12 easycwmp easycwmpd: end session failed Nov 25 15:30:12 easycwmp easycwmpd: retry session in 3840 sec, RetryCount = 11 Nov 25 15:30:12 easycwmp easycwmpd: exiting |
|
|
this because you are using a small periodic interval. The "start session" causes are the periodic events and not related to the retry. Please set a big periodic interval in the /etc/config/easycwmp and you will see the right timeout of retry interval. |
|
|
I don't see changing the retry interval to a larger one as a fix, it should be able to handle any length of periodic interval. What should be done in the code is to cancel the periodic interval if the curl timeout has occurred. or Only start the periodic interval when the communications with ACS has finished successfully. Then it wouldn't matter what the periodic interval was. |
|
|
Please note it's not a bug! It's a normal behaviour and it's compliant with the standrad. And I suggested to set a big periodic interval in order to see the right retry timeout and not to fix it. Sorry, but your both proposals are not compliant with the TR-069 standard. You can always customize your easycwmp version according to your need. But please note that they are out of the standard |
|
|
OK, Can you let me know where this is in the standard? Page number would be helpful. Thanks |
|
|
From the Standard: https://www.broadband-forum.org/technical/download/TR-069_Amendment-5.pdf Page 34 (3.2.1.1 Session Retry Policy): "A CPE MUST retry a failed Session after waiting for an interval of time specified in Table 3 or when a new event occurs, whichever comes first." |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2016-11-25 17:17 | dgr999 | New Issue | |
| 2016-11-25 17:17 | dgr999 | File Added: cwmp-retry-error.txt | |
| 2016-11-29 10:13 | mohamed.kallel | Note Added: 0000575 | |
| 2016-11-29 11:12 | dgr999 | Note Added: 0000576 | |
| 2016-11-29 11:49 | mohamed.kallel | Note Added: 0000577 | |
| 2016-11-29 11:52 | mohamed.kallel | Note Edited: 0000577 | |
| 2016-11-29 14:18 | dgr999 | Note Added: 0000578 | |
| 2016-11-29 16:44 | mohamed.kallel | Note Added: 0000579 | |
| 2016-11-30 10:06 | mohamed.kallel | Status | new => resolved |
| 2016-11-30 10:06 | mohamed.kallel | Resolution | open => fixed |
| 2016-11-30 10:06 | mohamed.kallel | Assigned To | => mohamed.kallel |
