cancel
Showing results for 
Search instead for 
Did you mean: 
Dode
Aspiring Expert
1,646 Views
Message 11 of 35

Re: Strange HH5 TR069 Log entries.

Yip, that would make sense since the minutes correspond. Thanks.

0 Ratings
Reply
Distinguished Expert
Distinguished Expert
1,618 Views
Message 12 of 35

Re: Strange HH5 TR069 Log entries.

More changes came through yesterday at ~ 9-00pm.

 

21:03:34, 09 Feb.(46443.270000) CWMP: Session start now. Event code(s): '7 TRANSFER COMPLETE,M Download,4 VALUE CHANGE'
21:03:34, 09 Feb.(46442.930000) CWMP: Initializing transaction for event code M Download
21:03:34, 09 Feb.(46442.930000) transfer completed successfully
21:03:31, 09 Feb.(46440.380000) CWMP: session completed successfully
21:03:31, 09 Feb.(46440.150000) CWMP: Download file, FileType=4, FileName=5a-​DR-​SpeedTester-​v1.6.tar.gz.aes.rsa.signed, Username=, CommandKey=1926829465
21:03:31, 09 Feb.(46439.940000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
 

 

The *"SpeedTester" is now at v1.6, up from v1.4.

 

The resulting change is that parameter updates are being authenticated. There are still the 1/2 hourly Set Parameter entries however.

The TR069 entries have now reached their limit, which results in newer entries being recorded and older entries overwritten, as predicted. The limit to the TR069 entry history is now approx 23 hours.

Still - there's progress, and the connection time is now approaching 24 hours, with no wifi disconnects either. 

0 Ratings
Reply
mossywell
Contributor
1,610 Views
Message 13 of 35

Re: Strange HH5 TR069 Log entries.

Unfortunately, things kicked off again for me one hour later! (2 = Media Disconnected, 7 = Connected). The IP is the monitoring host itself and the timespan is the time it was in the disconnected state.

 

192.168.1.42, 09/02/2015 21:55:47, 2-->7, 00:59:48
192.168.1.42, 09/02/2015 22:55:51, 2-->7, 00:00:20
192.168.1.42, 09/02/2015 22:58:59, 2-->7, 01:56:38
192.168.1.42, 10/02/2015 00:55:54, 2-->7, 00:00:24
192.168.1.42, 10/02/2015 00:58:32, 2-->7, 00:01:35
192.168.1.42, 10/02/2015 01:02:44, 2-->7, 00:57:41

 

Annoyingly, it has disconnected since I left for work, so I can't see if it coincides with TR069 but if it's following previous patterns, it does. No word from BT still - presumably "I will call you at 10am" translates across the miles to "I will not call you at 10am or any time thereafter". 

Was: BT Home Hub 5 (Type A) | Software version 4.7.5.1.83.8.204 | Last updated 21/01/15
Then: BT Home Hub 5 (Type A) | Software version 4.7.5.1.83.8.173.1.6 | Last updated Unknown
Now: BT Home Hub 5 (Type A) | Software version 4.7.5.1.83.8.204 | Last updated 17/02/15
0 Ratings
Reply
mossywell
Contributor
1,599 Views
Message 14 of 35

Re: Strange HH5 TR069 Log entries.

Long conversation with someone at BT (who was actually knowledgeable and not surly - cool!)...

 

He said that... the HH5 settings are synchronised with their servers when a local HH5 change is made. (So he can see that I have indeed tried every channel in the past.) The TR069 is basically saying that the settings on the HH5 don't match their servers and so it is trying to update their servers. He doesn't know why but it appears that this isn't working, so there is a permanent mismatch between the two configs (something he checked on the phone). He said that, with wifi settings mismatch, when it sees a mismatch, it disconnects the wifi temporarily [resets it - though not quite sure what that is intended to achieve!] and sets a flag to re-try the server update later. And so it goes on. The "fix" is based on the fact that my HH5 does connect immediately after a reboot of the HH5 (something he can see is working), so his suggestion is to make the wifi change, then reboot  the HH5 and check if the setting has stuck and if the HH5 makes a connection to their servers via the Event Log - something I should see happening. If so, it should connect once, do a full update of the servers and then stop - job done. What he couldn't answer is whether this is a temporary issue, but of course agreed that I should not have to reboot the HH5 after every config change. But let's crioss that bridge when we get to it....

 

Was: BT Home Hub 5 (Type A) | Software version 4.7.5.1.83.8.204 | Last updated 21/01/15
Then: BT Home Hub 5 (Type A) | Software version 4.7.5.1.83.8.173.1.6 | Last updated Unknown
Now: BT Home Hub 5 (Type A) | Software version 4.7.5.1.83.8.204 | Last updated 17/02/15
Distinguished Expert
Distinguished Expert
1,594 Views
Message 15 of 35

Re: Strange HH5 TR069 Log entries.


@mossywell wrote:

Long conversation with someone at BT (who was actually knowledgeable and not surly - cool!)...

 

He said that... the HH5 settings are synchronised with their servers when a local HH5 change is made. (So he can see that I have indeed tried every channel in the past.) The TR069 is basically saying that the settings on the HH5 don't match their servers and so it is trying to update their servers. He doesn't know why but it appears that this isn't working, so there is a permanent mismatch between the two configs (something he checked on the phone). He said that, with wifi settings mismatch, when it sees a mismatch, it disconnects the wifi temporarily [resets it - though not quite sure what that is intended to achieve!] and sets a flag to re-try the server update later. And so it goes on. The "fix" is based on the fact that my HH5 does connect immediately after a reboot of the HH5 (something he can see is working), so his suggestion is to make the wifi change, then reboot  the HH5 and check if the setting has stuck and if the HH5 makes a connection to their servers via the Event Log - something I should see happening. If so, it should connect once, do a full update of the servers and then stop - job done. What he couldn't answer is whether this is a temporary issue, but of course agreed that I should not have to reboot the HH5 after every config change. But let's crioss that bridge when we get to it....

 


Thanks for the post.

It seems that you have spoken to someone who knows. They seem to be aware that there's a problem and will rectify it.

It all seems to fit with what is actually happening, or what has happened in the past.

In my case, by pure chance, I did the factory reset, and then waited for a few minutes. Some updates followed (value change updates).

When the system settled I then set to my own preferences.

Unfortunately the exact sequence is now overwritten by the excessive number of "Parameter Set" events.

0 Ratings
Reply
mossywell
Contributor
1,564 Views
Message 16 of 35

Re: Strange HH5 TR069 Log entries.

Yeah - he was knowledgable but sadly, it didn't work. 😞 well, actually it did for about 5 hours, but then the TR069s came back every half an hour accompanied by the disconnects. 

 

Made yet another support call (5th including chats) but this time, rather curtly perhaps, just when he was about to run through all the same stuff over again, I asked him to escalate the call to the 2nd line team, which he has done. I'm awaiting a call tomorrow...

 

 

EDIT: Ironically, I had just hit "Post" and bang! - wifi went again. Checked the logs and our old friend is back but this time, it is accompanied by a whole reboot. 

 

01:17:20, 11 Feb. ( 41.980000) CWMP: Initializing transaction for event code 1 BOOT
00:15:45, 11 Feb. (21822.780000) CWMP: Set Parameter by TR069 Success
00:15:43, 11 Feb. (21820.590000) CWMP: Set Parameter by TR069 Success
00:15:06, 11 Feb. (21783.700000) CWMP: Set Parameter by TR069 Success

 

Was: BT Home Hub 5 (Type A) | Software version 4.7.5.1.83.8.204 | Last updated 21/01/15
Then: BT Home Hub 5 (Type A) | Software version 4.7.5.1.83.8.173.1.6 | Last updated Unknown
Now: BT Home Hub 5 (Type A) | Software version 4.7.5.1.83.8.204 | Last updated 17/02/15
0 Ratings
Reply
Distinguished Expert
Distinguished Expert
1,546 Views
Message 17 of 35

Re: Strange HH5 TR069 Log entries.


@mossywell wrote:

Yeah - he was knowledgable but sadly, it didn't work. 😞 well, actually it did for about 5 hours, but then the TR069s came back every half an hour accompanied by the disconnects. 

 

Made yet another support call (5th including chats) but this time, rather curtly perhaps, just when he was about to run through all the same stuff over again, I asked him to escalate the call to the 2nd line team, which he has done. I'm awaiting a call tomorrow...

 

 

EDIT: Ironically, I had just hit "Post" and bang! - wifi went again. Checked the logs and our old friend is back but this time, it is accompanied by a whole reboot. 

 

01:17:20, 11 Feb. ( 41.980000) CWMP: Initializing transaction for event code 1 BOOT
00:15:45, 11 Feb. (21822.780000) CWMP: Set Parameter by TR069 Success
00:15:43, 11 Feb. (21820.590000) CWMP: Set Parameter by TR069 Success
00:15:06, 11 Feb. (21783.700000) CWMP: Set Parameter by TR069 Success

 


There's good news and bad news here

 

05:37:12, 11 Feb.(163657.810000) CWMP: Set Parameter by TR069 Success
05:36:47, 11 Feb.(163632.860000) CWMP: Set Parameter by TR069 Success
05:07:34, 11 Feb.(161880.060000) CWMP: Set Parameter by TR069 Success
05:07:13, 11 Feb.(161858.760000) CWMP: Set Parameter by TR069 Success
05:07:11, 11 Feb.(161857.390000) CWMP: Set Parameter by TR069 Success
05:06:46, 11 Feb.(161832.040000) CWMP: Set Parameter by TR069 Success
04:49:04, 11 Feb.(160770.270000) CWMP: session closed due to error: HTTP authentication error
04:49:04, 11 Feb.(160770.270000) CWMP: HTTP authentication fail from https://pbthdm.bt.mo
04:49:02, 11 Feb.(160768.060000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
04:49:02, 11 Feb.(160768.050000) CWMP: Session start now. Event code(s): '2 PERIODIC,4 VALUE CHANGE'
04:37:39, 11 Feb.(160084.810000) CWMP: Set Parameter by TR069 Success
04:37:17, 11 Feb.(160063.510000) CWMP: Set Parameter by TR069 Success

 

I now have a connection time approaching 48 hours.

However the hub does'nt appear to be communicating with remote administration. Some may argue that this is a good thing.

But it's not such a good thing if another firmware update appears.

 

It's back to square one.

0 Ratings
Reply
scott_johnston
Contributor
1,528 Views
Message 18 of 35

Re: Strange HH5 TR069 Log entries.

Today I have being seeing the same TR069 logs entries that you have had

0 Ratings
Reply
scott_johnston
Contributor
1,515 Views
Message 19 of 35

Re: Strange HH5 TR069 Log entries.

21:53:07, 11 Feb. (212618.510000) CWMP: Set Parameter by TR069 Success
21:52:45, 11 Feb. (212596.860000) CWMP: Set Parameter by TR069 Success
21:52:44, 11 Feb. (212595.080000) CWMP: Set Parameter by TR069 Success
21:52:22, 11 Feb. (212573.730000) CWMP: Set Parameter by TR069 Success
19:22:58, 11 Feb. (203609.690000) CWMP: Set Parameter by TR069 Success
19:22:37, 11 Feb. (203588.380000) CWMP: Set Parameter by TR069 Success
19:22:35, 11 Feb. (203586.580000) CWMP: Set Parameter by TR069 Success
19:22:14, 11 Feb. (203565.270000) CWMP: Set Parameter by TR069 Success
18:52:58, 11 Feb. (201809.530000) CWMP: Set Parameter by TR069 Success
18:52:37, 11 Feb. (201788.170000) CWMP: Set Parameter by TR069 Success
18:52:35, 11 Feb. (201786.380000) CWMP: Set Parameter by TR069 Success
18:52:14, 11 Feb. (201765.070000) CWMP: Set Parameter by TR069 Success
18:22:37, 11 Feb. (199988.800000) CWMP: Set Parameter by TR069 Success
18:22:16, 11 Feb. (199967.450000) CWMP: Set Parameter by TR069 Success
17:22:58, 11 Feb. (196409.750000) CWMP: Set Parameter by TR069 Success
17:22:37, 11 Feb. (196388.420000) CWMP: Set Parameter by TR069 Success
17:22:35, 11 Feb. (196386.630000) CWMP: Set Parameter by TR069 Success
17:22:14, 11 Feb. (196365.280000) CWMP: Set Parameter by TR069 Success
16:52:56, 11 Feb. (194607.890000) CWMP: Set Parameter by TR069 Success
16:52:35, 11 Feb. (194586.570000) CWMP: Set Parameter by TR069 Success
16:52:33, 11 Feb. (194584.730000) CWMP: Set Parameter by TR069 Success
16:52:12, 11 Feb. (194563.420000) CWMP: Set Parameter by TR069 Success
16:22:35, 11 Feb. (192786.900000) CWMP: Set Parameter by TR069 Success
16:22:14, 11 Feb. (192765.570000) CWMP: Set Parameter by TR069 Success
14:52:54, 11 Feb. (187405.430000) CWMP: Set Parameter by TR069 Success
14:52:33, 11 Feb. (187384.130000) CWMP: Set Parameter by TR069 Success
14:52:31, 11 Feb. (187382.130000) CWMP: Set Parameter by TR069 Success
14:52:09, 11 Feb. (187360.760000) CWMP: Set Parameter by TR069 Success
14:22:57, 11 Feb. (185608.840000) CWMP: Set Parameter by TR069 Success
14:22:36, 11 Feb. (185587.540000) CWMP: Set Parameter by TR069 Success
14:22:34, 11 Feb. (185585.760000) CWMP: Set Parameter by TR069 Success
14:22:13, 11 Feb. (185564.430000) CWMP: Set Parameter by TR069 Success
13:52:57, 11 Feb. (183808.160000) CWMP: Set Parameter by TR069 Success
13:52:35, 11 Feb. (183786.840000) CWMP: Set Parameter by TR069 Success
13:52:33, 11 Feb. (183784.950000) CWMP: Set Parameter by TR069 Success
13:52:12, 11 Feb. (183763.640000) CWMP: Set Parameter by TR069 Success
12:52:53, 11 Feb. (180204.840000) CWMP: Set Parameter by TR069 Success
12:52:32, 11 Feb. (180183.540000) CWMP: Set Parameter by TR069 Success
12:52:30, 11 Feb. (180181.340000) CWMP: Set Parameter by TR069 Success
12:52:09, 11 Feb. (180160.030000) CWMP: Set Parameter by TR069 Success
12:22:57, 11 Feb. (178408.830000) CWMP: Set Parameter by TR069 Success
12:22:36, 11 Feb. (178387.460000) CWMP: Set Parameter by TR069 Success
12:22:34, 11 Feb. (178385.670000) CWMP: Set Parameter by TR069 Success
12:22:13, 11 Feb. (178364.360000) CWMP: Set Parameter by TR069 Success
11:52:55, 11 Feb. (176606.900000) CWMP: Set Parameter by TR069 Success
11:52:34, 11 Feb. (176585.530000) CWMP: Set Parameter by TR069 Success
11:52:32, 11 Feb. (176583.690000) CWMP: Set Parameter by TR069 Success
11:52:11, 11 Feb. (176562.380000) CWMP: Set Parameter by TR069 Success
10:55:49, 11 Feb. (173180.200000) CWMP: session completed successfully
10:55:46, 11 Feb. (173177.430000) CWMP: Set Parameter by TR069 Success
10:55:41, 11 Feb. (173172.490000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
10:55:37, 11 Feb. (173168.490000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
10:55:37, 11 Feb. (173168.480000) CWMP: Session start now. Event code(s): '6 CONNECTION REQUEST,4 VALUE CHANGE'
10:55:37, 11 Feb. (173168.100000) CWMP: Initializing transaction for event code 6 CONNECTION REQUEST
10:52:26, 11 Feb. (172977.850000) CWMP: session completed successfully
10:52:26, 11 Feb. (172977.610000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
10:52:22, 11 Feb. (172973.570000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
10:52:22, 11 Feb. (172973.570000) CWMP: Session start now. Event code(s): '4 VALUE CHANGE'
10:52:22, 11 Feb. (172973.180000) CWMP: Initializing transaction for event code 4 VALUE CHANGE
10:50:49, 11 Feb. (172880.260000) CWMP: session closed due to error: Timeout
10:50:17, 11 Feb. (172848.870000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
10:50:14, 11 Feb. (172845.790000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
10:50:14, 11 Feb. (172845.790000) CWMP: Session start now. Event code(s): '7 TRANSFER COMPLETE,M Download,4 VALUE CHANGE'
10:50:14, 11 Feb. (172845.400000) CWMP: Initializing transaction for event code M Download
10:50:14, 11 Feb. (172845.400000) transfer completed successfully
10:50:12, 11 Feb. (172843.460000) CWMP: session completed successfully
10:50:12, 11 Feb. (172843.000000) CWMP: Download file, FileType=4, FileName=5a-SpeedTestWiFi-Packagev1.4.tar.gz.aes.rsa.signed, Username=, CommandKey=1928900762
10:50:09, 11 Feb. (172840.560000) CWMP: Set Parameter by TR069 Success
10:50:07, 11 Feb. (172838.860000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
10:50:05, 11 Feb. (172836.040000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
10:50:05, 11 Feb. (172836.040000) CWMP: Session start now. Event code(s): '6 CONNECTION REQUEST,4 VALUE CHANGE'
10:50:04, 11 Feb. (172835.650000) CWMP: Initializing transaction for event code 6 CONNECTION REQUEST
10:50:02, 11 Feb. (172833.160000) CWMP: session completed successfully
10:50:01, 11 Feb. (172832.940000) CWMP: HTTP authentication success from https://pbthdm.bt.mo
10:49:58, 11 Feb. (172829.270000) CWMP: Server URL: https://pbthdm.bt.mo; Connecting as user: ACS username
10:49:58, 11 Feb. (172829.260000) CWMP: Session start now. Event code(s): '2 PERIODIC,4 VALUE CHANGE'
10:49:57, 11 Feb. (172828.880000) CWMP: Initializing transaction for event code 2 PERIODIC

0 Ratings
Reply
Distinguished Expert
Distinguished Expert
1,502 Views
Message 20 of 35

Re: Strange HH5 TR069 Log entries.

Thanks.

I was going to reply to your own thread.

So - yours is the first reply showing the "Set Parameter" events in a longer time span.

 

The connection held up here for 3 days, just up to 20 minutes ago and then there was a wifi disconnect and a simultaneous DSL disconnect.

3 days is something of a record here, from VDSL2 installation in July 2014, the connection rarely holds up long than 2 1/2 days.

There's just a chance that it's back to the usual routine - the odd wifi drop out and connection loss. Not encouraging though.

As with your listing the Event code(s): '2  PERIODIC,4 VALUE CHANGE event is now authenticating.

 

At least, when and if there's a firmware update, there's now more chance of it coming through. 

 

 Edit: wifi disconnection again, just 3 mins ago (08-09 am)

0 Ratings
Reply