cancel
Showing results for 
Show  only  | Search instead for 
Did you mean: 
L1NHH
Contributor
1,143 Views
Message 1 of 5

Can Someone Please Explain

This has been going on now for several weeks. Almost since the last firmware update on the hub I use.

Also so far today I am on my third ip address.

 

12:57:27, 03 Nov. (606004.290000) CWMP: session completed successfully
 
12:57:27, 03 Nov. (606004.110000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
 
12:57:20, 03 Nov. (605997.520000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
12:57:20, 03 Nov. (605997.510000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
12:57:17, 03 Nov. (605994.160000) PPP IPCP Receive Configuration ACK
 
12:57:17, 03 Nov. (605994.150000) PPP IPCP Send Configuration Request
 
12:57:17, 03 Nov. (605994.150000) PPP IPCP Receive Configuration NAK
 
12:57:17, 03 Nov. (605994.150000) PPP IPCP Send Configuration ACK
 
12:57:17, 03 Nov. (605994.150000) PPP IPCP Receive Configuration Request
 
12:57:16, 03 Nov. (605993.680000) PPP IPCP Send Configuration Request
 
12:57:16, 03 Nov. (605993.670000) WAN operating mode is Ethernet
 
12:57:16, 03 Nov. (605993.670000) Last WAN operating mode was Ethernet
 
12:57:15, 03 Nov. (605992.590000) PPPoE is up
 
12:57:15, 03 Nov. (605992.590000) CHAP authentication successful
 
12:57:15, 03 Nov. (605992.500000) CHAP Receive Challenge
 
12:57:15, 03 Nov. (605992.500000) Starting CHAP authentication with peer
 
12:57:15, 03 Nov. (605992.500000) PPP LCP Receive Configuration ACK
 
12:57:15, 03 Nov. (605992.490000) PPP LCP Send Configuration Request
 
12:57:15, 03 Nov. (605992.490000) PPP LCP Receive Configuration Reject
 
12:57:15, 03 Nov. (605992.490000) PPP LCP Send Configuration ACK
 
12:57:15, 03 Nov. (605992.490000) PPP LCP Receive Configuration Request
 
12:57:15, 03 Nov. (605992.490000) PPP LCP Send Configuration Request
 
12:57:06, 03 Nov. (605982.910000) CWMP: session closed due to error: Could not resolve host
 
12:57:06, 03 Nov. (605982.880000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
12:57:06, 03 Nov. (605982.880000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
12:56:35, 03 Nov. (605952.320000) CWMP: session closed due to error: Could not resolve host
 
12:56:35, 03 Nov. (605952.290000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
12:56:35, 03 Nov. (605952.280000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
12:56:34, 03 Nov. (605951.710000) CWMP: Initializing transaction for event code 4 VALUE CHANGE
 
12:56:33, 03 Nov. (605950.610000) PPPoE is down after 3 minutes uptime [Disconnected]
 
12:56:32, 03 Nov. (605948.780000) PPP LCP Send Termination Request [Peer not responding]
 
12:53:34, 03 Nov. (605770.830000) CWMP: session completed successfully
 
12:53:33, 03 Nov. (605770.660000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
 
12:53:26, 03 Nov. (605763.750000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
12:53:26, 03 Nov. (605763.750000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
12:53:23, 03 Nov. (605760.330000) PPP IPCP Receive Configuration ACK
 
12:53:23, 03 Nov. (605760.200000) PPP IPCP Send Configuration Request
 
12:53:23, 03 Nov. (605760.200000) PPP IPCP Receive Configuration NAK
 
12:53:23, 03 Nov. (605760.200000) PPP IPCP Send Configuration ACK
 
12:53:23, 03 Nov. (605760.200000) PPP IPCP Receive Configuration Request
 
12:53:22, 03 Nov. (605759.510000) PPP IPCP Send Configuration Request
 
12:53:22, 03 Nov. (605759.510000) WAN operating mode is Ethernet
 
12:53:22, 03 Nov. (605759.510000) Last WAN operating mode was Ethernet
 
12:53:21, 03 Nov. (605758.390000) PPPoE is up
 
12:53:21, 03 Nov. (605758.380000) CHAP authentication successful
 
12:53:21, 03 Nov. (605758.310000) CHAP Receive Challenge
 
12:53:21, 03 Nov. (605758.300000) Starting CHAP authentication with peer
 
12:53:21, 03 Nov. (605758.300000) PPP LCP Receive Configuration ACK
 
12:53:21, 03 Nov. (605758.300000) PPP LCP Send Configuration Request
 
12:53:21, 03 Nov. (605758.300000) PPP LCP Receive Configuration Reject
 
12:53:21, 03 Nov. (605758.290000) PPP LCP Send Configuration ACK
 
12:53:21, 03 Nov. (605758.290000) PPP LCP Receive Configuration Request
 
12:53:21, 03 Nov. (605758.290000) PPP LCP Send Configuration Request
 
12:53:18, 03 Nov. (605754.820000) CWMP: session closed due to error: Could not resolve host
 
12:53:18, 03 Nov. (605754.780000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
12:53:18, 03 Nov. (605754.770000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 

 
12:52:47, 03 Nov. (605724.210000) CWMP: session closed due to error: Could not resolve host
 
12:52:47, 03 Nov. (605724.170000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
12:52:47, 03 Nov. (605724.160000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
12:52:46, 03 Nov. (605723.590000) CWMP: Initializing transaction for event code 4 VALUE CHANGE
 
12:52:45, 03 Nov. (605722.490000) PPPoE is down after 58 minutes uptime [Disconnected]
 
12:52:43, 03 Nov. (605720.670000) PPP LCP Send Termination Request [Peer not responding]
 
12:37:55, 03 Nov. (604832.500000) CWMP: session completed successfully
 
12:37:55, 03 Nov. (604832.330000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
 
12:37:53, 03 Nov. (604830.490000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
12:37:53, 03 Nov. (604830.480000) CWMP: Session start now. Event code(s): '2 PERIODIC,4 VALUE CHANGE'
 
12:37:53, 03 Nov. (604829.910000) CWMP: Initializing transaction for event code 2 PERIODIC
 

 
11:54:45, 03 Nov. (602241.820000) CWMP: session completed successfully
 
11:54:44, 03 Nov. (602241.650000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
 
11:54:38, 03 Nov. (602234.860000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
11:54:38, 03 Nov. (602234.850000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
11:54:34, 03 Nov. (602231.420000) PPP IPCP Receive Configuration ACK
 
11:54:34, 03 Nov. (602231.420000) PPP IPCP Send Configuration Request
 
11:54:34, 03 Nov. (602231.410000) PPP IPCP Receive Configuration NAK
 
11:54:34, 03 Nov. (602231.410000) PPP IPCP Send Configuration ACK
 
11:54:34, 03 Nov. (602231.410000) PPP IPCP Receive Configuration Request
 
11:54:34, 03 Nov. (602230.940000) PPP IPCP Send Configuration Request
 
11:54:34, 03 Nov. (602230.940000) WAN operating mode is Ethernet
 
11:54:34, 03 Nov. (602230.940000) Last WAN operating mode was Ethernet

11:54:33, 03 Nov. (602229.820000) CHAP authentication successful
 
11:54:32, 03 Nov. (602229.710000) CHAP Receive Challenge
 
11:54:32, 03 Nov. (602229.710000) Starting CHAP authentication with peer
 
11:54:32, 03 Nov. (602229.710000) PPP LCP Receive Configuration ACK
 
11:54:32, 03 Nov. (602229.710000) PPP LCP Send Configuration Request
 
11:54:32, 03 Nov. (602229.710000) PPP LCP Receive Configuration Reject
 
11:54:32, 03 Nov. (602229.700000) PPP LCP Send Configuration ACK
 
11:54:32, 03 Nov. (602229.700000) PPP LCP Receive Configuration Request
 
11:54:32, 03 Nov. (602229.700000) PPP LCP Send Configuration Request
 
11:53:45, 03 Nov. (602182.230000) CWMP: session closed due to error: Could not resolve host
 
11:53:45, 03 Nov. (602182.210000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
11:53:45, 03 Nov. (602182.200000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
11:53:14, 03 Nov. (602151.640000) CWMP: session closed due to error: Could not resolve host
 
11:53:14, 03 Nov. (602151.620000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
11:53:14, 03 Nov. (602151.610000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
11:53:14, 03 Nov. (602151.040000) CWMP: Initializing transaction for event code 4 VALUE CHANGE
 
11:53:13, 03 Nov. (602149.940000) PPPoE is down after 208 minutes uptime [Disconnected]
 
11:53:11, 03 Nov. (602148.140000) PPP LCP Send Termination Request [Peer not responding]

 

08:24:55, 03 Nov. (589648.970000) CWMP: session completed successfully
 
08:24:55, 03 Nov. (589648.800000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
 
08:24:48, 03 Nov. (589641.710000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
08:24:48, 03 Nov. (589641.700000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
 
08:24:44, 03 Nov. (589638.300000) PPP IPCP Receive Configuration ACK
 
08:24:44, 03 Nov. (589638.300000) PPP IPCP Send Configuration Request
 
08:24:44, 03 Nov. (589638.290000) PPP IPCP Receive Configuration NAK
 
08:24:44, 03 Nov. (589638.290000) PPP IPCP Send Configuration ACK
 
08:24:44, 03 Nov. (589638.290000) PPP IPCP Receive Configuration Request
 
08:24:44, 03 Nov. (589637.830000) PPP IPCP Send Configuration Request
 
08:24:44, 03 Nov. (589637.830000) WAN operating mode is Ethernet
 
08:24:44, 03 Nov. (589637.830000) Last WAN operating mode was Ethernet
 
08:24:43, 03 Nov. (589636.730000) PPPoE is up
 
08:24:43, 03 Nov. (589636.720000) CHAP authentication successful
 
08:24:43, 03 Nov. (589636.600000) CHAP Receive Challenge
 
08:24:43, 03 Nov. (589636.600000) Starting CHAP authentication with peer
 
08:24:43, 03 Nov. (589636.600000) PPP LCP Receive Configuration ACK
 
08:24:43, 03 Nov. (589636.600000) PPP LCP Send Configuration Request
 
08:24:43, 03 Nov. (589636.600000) PPP LCP Receive Configuration Reject
 
08:24:43, 03 Nov. (589636.590000) PPP LCP Send Configuration ACK
 
08:24:43, 03 Nov. (589636.590000) PPP LCP Receive Configuration Request
 
08:24:43, 03 Nov. (589636.590000) PPP LCP Send Configuration Request
 
08:24:41, 03 Nov. (589635.000000) CWMP: session closed due to error: Could not resolve host
 
08:24:41, 03 Nov. (589634.980000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username

08:24:41, 03 Nov. (589634.970000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
08:24:12, 03 Nov. (589605.950000) PPP LCP Send Termination Request [PPPoE PADT received]
 
08:24:10, 03 Nov. (589604.400000) CWMP: session closed due to error: Could not resolve host
 
08:24:10, 03 Nov. (589604.380000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
 
08:24:10, 03 Nov. (589604.370000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
 
08:24:10, 03 Nov. (589603.800000) CWMP: Initializing transaction for event code 4 VALUE CHANGE
 
08:24:08, 03 Nov. (589602.010000) PPPoE is down after 77 minutes uptime [Disconnected]
 
08:24:06, 03 Nov. (589600.190000) PPP LCP Send Termination Request [Peer not responding]

 

 

BTW

 

Hub Info BT Home Hub 3

Software version 4.7.5.1.83.8.94.1.52 (Type A)

 

 

 

0 Ratings
4 REPLIES 4
licquorice
Distinguished Sage
Distinguished Sage
1,134 Views
Message 2 of 5

Re: Can Someone Please Explain

The CWMP sessions are BT tinkering with your hub. For some reason the sessions also seem to be causing the PPP session to drop.

0 Ratings
L1NHH
Contributor
1,082 Views
Message 3 of 5

Re: Can Someone Please Explain

As you can see this was from 8.30am until 12.57 lunchtime today.

I have pages and pages of these events so I wish to god that bt would stop tinkering.

The service that I pay for is getting disrupted time and time again web pages not responding so I look in the hub management and sure enough here we go again on cwmp ppoe etc.

 

 

Could someone confirm if this is the correct firmware update for my hub 3 as my problems coinsided with his update at the end of August.

Software version 4.7.5.1.83.8.94.1.52 (Type A)

0 Ratings
smf22
Recognised Expert
1,074 Views
Message 4 of 5

Re: Can Someone Please Explain


@licquorice wrote:

The CWMP sessions are BT tinkering with your hub. For some reason the sessions also seem to be causing the PPP session to drop.


Hmmmm.... not entirely sure I agree. To me this looks like the DSL is dropping and the hub is trying to inform the ACS of the event.

 

TR69 or CWMP is also used for status and performance monitoring "for a CPE to make available information that the ACS may use to monitor the CPE’s status and performance statistics".

 

All the CWMP events are "4 VALUE CHANGE" which means "the value of one or more Parameters with Passive or Active notification enabled [snip] has been modified". An "active" parameter is one in which the CPE must start a session and inform the ACS of a value change as soon as it occurs. I'd expect that the DSL uptime would be one of those parameters monitored as an active parameter.

 

If we follow an event we see the link drop at 08:24:06 (PPP LCP Send Termination Request [Peer not responding]) followed by the CWMP event at 08:24:10. This obviously fails as the link is down and so at 08:24:41 it gives up. Once the link is up at 08:24:44, CWMP kicks back in to report the value change.

 

What seems to be happening is the BRAS is not responding to the periodic keep alive messages that are part of PPP:

 

12:56:32, 03 Nov. (605948.780000) PPP LCP Send Termination Request [Peer not responding]
12:52:43, 03 Nov. (605720.670000) PPP LCP Send Termination Request [Peer not responding]
11:53:11, 03 Nov. (602148.140000) PPP LCP Send Termination Request [Peer not responding]
08:24:06, 03 Nov. (589600.190000) PPP LCP Send Termination Request [Peer not responding]

 

And so the PPP session is terminated by the Hub.

 

Has anything changed on the line in the last few weeks that might account for the line quality to have changed?

 

Perhaps start with with some basic troubleshooting and connect the Hub directly to the test socket etc., to see if that helps.

 

Regards

0 Ratings
licquorice
Distinguished Sage
Distinguished Sage
1,054 Views
Message 5 of 5

Re: Can Someone Please Explain

Yes, looking again at the sequence, it is the PPP dropping that is initiating the CWMP events.

 

DSL doesn't apppear to be dropping, just the PPPoE session

 

There is a history of the mysterious 'PPP LCP Send Termination Request' events that many people have experienced without explanation. It seems to be confined to HHs as changing to a third party router seems to have resolved the problem for many.

0 Ratings