View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000183easycwmpBugpublic2016-11-25 17:172016-11-30 10:06
Reporterdgr999 Assigned Tomohamed.kallel  
PriorityhighSeveritymajorReproducibilityalways
Status resolvedResolutionfixed 
PlatformVMOSUbuntu ServerOS Version16.04 LTS
Summary0000183: ACS Retry timeout incorrect
DescriptionI 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 ReproduceTurn off ACS
Start easycwmpd -f -b
After 10 Retries stop easycwmpd and collect syslog
TagsNo tags attached.

Activities

dgr999

2016-11-25 17:17

reporter  

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
cwmp-retry-error.txt (9,878 bytes)   

mohamed.kallel

2016-11-29 10:13

administrator   ~0000575

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.

dgr999

2016-11-29 11:12

reporter   ~0000576

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.

mohamed.kallel

2016-11-29 11:49

administrator   ~0000577

Last edited: 2016-11-29 11:52

 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

dgr999

2016-11-29 14:18

reporter   ~0000578

OK,

Can you let me know where this is in the standard?

Page number would be helpful.

Thanks

mohamed.kallel

2016-11-29 16:44

administrator   ~0000579

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."

Issue History

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