I have a BT Home Hub 5A running OpenWrt 18.06.1 r7258-5eb055306f with 4.9.120 kernel.
Sometime it restarts by itself the network and I don't understand the reason when I check logs (I copy/paste log of one of this restart moment below). Does anyone would have any idea on that matter and could help me?
The DSL Status is as following : DSL Status
Line State: UP [0x0] Line Mode: G.992.5 (ADSL2+) Line Uptime: 7d 19h 12m 48s Annex: A Profile: - Data Rate: 10.272 Mb/s / 1.018 Mb/s Max. Attainable Data Rate (ATTNDR): 11.540 Mb/s / 993 Kb/s Latency: 7.50 ms / 4.0 ms Line Attenuation (LATN): 41.0 dB / 21.5 dB Signal Attenuation (SATN): 38.6 dB / 21.1 dB Noise Margin (SNR): 6.9 dB / 4.5 dB Aggregate Transmit Power(ACTATP): 17.4 dB / 12.1 dB Forward Error Correction Seconds (FECS): 17561774 / 8683476 Errored seconds (ES): 3600 / 1054 Severely Errored Seconds (SES): 938 / 17 Loss of Signal Seconds (LOSS): 0 / 0 Unavailable Seconds (UAS): 55 / 55 Header Error Code Errors (HEC): 839852 / 9643 Non Pre-emtive CRC errors (CRC_P): 0 / 0 Pre-emtive CRC errors (CRCP_P): 0 / 0 ATU-C System Vendor ID: Broadcom 161.242 Power Management Mode: L0 - Synchronized
The DSL config is :
Annex : Annex A + L + M (all)
Tone : auto
Encapsulation mode : auto
DSL line mode : auto
Downstream SNR offset : 0.0 dB
Wed Jan 30 15:26:29 2019 daemon.info pppd[5634]: LCP terminated by peer
Wed Jan 30 15:26:29 2019 daemon.info pppd[5634]: Connect time 10080.1 minutes.
Wed Jan 30 15:26:29 2019 daemon.info pppd[5634]: Sent 1174239031 bytes, received 2089951092 bytes.
Wed Jan 30 15:26:29 2019 daemon.err odhcp6c[5793]: Failed to send DHCPV6 message to xxxx::x:x (Permission denied)
Wed Jan 30 15:26:29 2019 daemon.err odhcp6c[5778]: Failed to send RS (Permission denied)
Wed Jan 30 15:26:29 2019 daemon.notice netifd: Network device 'pppoa-wan' link is down
Wed Jan 30 15:26:29 2019 daemon.notice netifd: Network alias 'pppoa-wan' link is down
Wed Jan 30 15:26:29 2019 daemon.notice netifd: Interface 'wan6' has link connectivity loss
Wed Jan 30 15:26:29 2019 daemon.notice netifd: Interface 'wan_6' has link connectivity loss
Wed Jan 30 15:26:29 2019 daemon.notice netifd: Interface 'wan' has lost the connection
Wed Jan 30 15:26:29 2019 daemon.notice netifd: Interface 'wan6' is disabled
Wed Jan 30 15:26:29 2019 daemon.notice netifd: Interface 'wan_6' is disabled
Wed Jan 30 15:26:29 2019 daemon.warn dnsmasq[2095]: no servers found in /tmp/resolv.conf.auto, will retry
Wed Jan 30 15:26:30 2019 daemon.notice netifd: wan_6 (5793): Command failed: Permission denied
Wed Jan 30 15:26:30 2019 daemon.info dnsmasq[2095]: read /etc/hosts - 4 addresses
Wed Jan 30 15:26:30 2019 daemon.info dnsmasq[2095]: read /tmp/hosts/odhcpd - 5 addresses
Wed Jan 30 15:26:30 2019 daemon.info dnsmasq[2095]: read /tmp/hosts/dhcp.cfg01411c - 14 addresses
Wed Jan 30 15:26:30 2019 daemon.info dnsmasq-dhcp[2095]: read /etc/ethers - 0 addresses
Wed Jan 30 15:26:30 2019 daemon.err odhcp6c[5793]: Failed to send DHCPV6 message to xxxx::x:x (Permission denied)
Wed Jan 30 15:26:30 2019 daemon.err odhcp6c[5778]: Failed to send DHCPV6 message to xxxx::x:x (Permission denied)
Wed Jan 30 15:26:32 2019 daemon.notice pppd[5634]: Connection terminated.
Wed Jan 30 15:26:32 2019 daemon.info pppd[5634]: Connect time 10080.1 minutes.
Wed Jan 30 15:26:32 2019 daemon.info pppd[5634]: Sent 1174239031 bytes, received 2089951092 bytes.
Wed Jan 30 15:26:32 2019 daemon.notice pppd[5634]: Modem hangup
Wed Jan 30 15:26:32 2019 daemon.info pppd[5634]: Exit.
Wed Jan 30 15:26:32 2019 daemon.notice netifd: Interface 'wan' is now down
Wed Jan 30 15:26:32 2019 daemon.notice netifd: Interface 'wan' is setting up now
Wed Jan 30 15:26:33 2019 daemon.err insmod: module is already loaded - slhc
Wed Jan 30 15:26:33 2019 daemon.err insmod: module is already loaded - ppp_generic
Wed Jan 30 15:26:33 2019 daemon.err insmod: module is already loaded - pppox
Wed Jan 30 15:26:33 2019 daemon.err insmod: module is already loaded - pppoatm
Wed Jan 30 15:26:33 2019 daemon.info pppd[18158]: Plugin pppoatm.so loaded.
Wed Jan 30 15:26:33 2019 daemon.info pppd[18158]: PPPoATM plugin_init
Wed Jan 30 15:26:33 2019 daemon.info pppd[18158]: PPPoATM setdevname_pppoatm - SUCCESS:0.8.35
Wed Jan 30 15:26:33 2019 daemon.notice pppd[18158]: pppd 2.4.7 started by root, uid 0
Wed Jan 30 15:26:33 2019 kern.info kernel: [605040.557487] pppoa-wan: renamed from ppp0
Wed Jan 30 15:26:33 2019 daemon.info pppd[18158]: Using interface pppoa-wan
Wed Jan 30 15:26:33 2019 daemon.notice pppd[18158]: Connect: pppoa-wan <--> 0.8.35
Wed Jan 30 15:26:33 2019 daemon.notice pppd[18158]: PAP authentication succeeded
Wed Jan 30 15:26:34 2019 daemon.notice pppd[18158]: local LL address dddd::dddd:dddd:dddd:dddd
Wed Jan 30 15:26:34 2019 daemon.notice pppd[18158]: remote LL address eeee::eeee:eeee:eeee:eeee
Wed Jan 30 15:26:34 2019 daemon.notice pppd[18158]: local IP address yy.yy.yy.yy
Wed Jan 30 15:26:34 2019 daemon.notice pppd[18158]: remote IP address zz.zz.zz.zz
Wed Jan 30 15:26:34 2019 daemon.notice pppd[18158]: primary DNS address bb.bb.bb.bb
Wed Jan 30 15:26:34 2019 daemon.notice pppd[18158]: secondary DNS address bb.bb.bb.cc
Wed Jan 30 15:26:34 2019 daemon.notice netifd: Network device 'pppoa-wan' link is up
Wed Jan 30 15:26:34 2019 daemon.notice netifd: Interface 'wan6' is enabled
Wed Jan 30 15:26:34 2019 daemon.notice netifd: Interface 'wan_6' is enabled
Wed Jan 30 15:26:34 2019 daemon.notice netifd: Network alias 'pppoa-wan' link is up
Wed Jan 30 15:26:34 2019 daemon.notice netifd: Interface 'wan6' has link connectivity
Wed Jan 30 15:26:34 2019 daemon.notice netifd: Interface 'wan6' is setting up now
Wed Jan 30 15:26:34 2019 daemon.notice netifd: Interface 'wan_6' has link connectivity
Wed Jan 30 15:26:34 2019 daemon.notice netifd: Interface 'wan_6' is setting up now
Wed Jan 30 15:26:34 2019 daemon.notice netifd: Interface 'wan' is now up
Wed Jan 30 15:26:34 2019 daemon.info dnsmasq[2095]: reading /tmp/resolv.conf.auto
Wed Jan 30 15:26:34 2019 daemon.info dnsmasq[2095]: using local addresses only for domain test
Wed Jan 30 15:26:34 2019 daemon.info dnsmasq[2095]: using local addresses only for domain onion
Wed Jan 30 15:26:34 2019 daemon.info dnsmasq[2095]: using local addresses only for domain localhost
Wed Jan 30 15:26:34 2019 daemon.info dnsmasq[2095]: using local addresses only for domain local
Wed Jan 30 15:26:34 2019 daemon.info dnsmasq[2095]: using local addresses only for domain invalid
Wed Jan 30 15:26:34 2019 daemon.info dnsmasq[2095]: using local addresses only for domain bind
Wed Jan 30 15:26:34 2019 daemon.info dnsmasq[2095]: using local addresses only for domain lan
Wed Jan 30 15:26:34 2019 daemon.info dnsmasq[2095]: using nameserver bb.bb.bb.bb#53
Wed Jan 30 15:26:34 2019 daemon.info dnsmasq[2095]: using nameserver bb.bb.bb.cc#53
Wed Jan 30 15:26:35 2019 user.notice SQM: Stopping SQM on pppoa-wan
Wed Jan 30 15:26:36 2019 daemon.notice netifd: Interface 'wan_6' is now up
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: reading /tmp/resolv.conf.auto
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using local addresses only for domain test
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using local addresses only for domain onion
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using local addresses only for domain localhost
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using local addresses only for domain local
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using local addresses only for domain invalid
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using local addresses only for domain bind
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using local addresses only for domain lan
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using nameserver bb.bb.bb.bb#53
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using nameserver bb.bb.bb.cc#53
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using nameserver bbbb:bbb:bbb::bb#53
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: using nameserver bbbb:bbb:bbb::cc#53
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: read /etc/hosts - 4 addresses
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: read /tmp/hosts/odhcpd - 10 addresses
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq[2095]: read /tmp/hosts/dhcp.cfg01411c - 14 addresses
Wed Jan 30 15:26:36 2019 daemon.info dnsmasq-dhcp[2095]: read /etc/ethers - 0 addresses
Wed Jan 30 15:26:36 2019 user.notice SQM: Starting SQM script: piece_of_cake.qos on pppoa-wan, in: 7500 Kbps, out: 750 Kbps
Wed Jan 30 15:26:38 2019 user.notice SQM: piece_of_cake.qos was started on pppoa-wan successfully
Wed Jan 30 15:26:38 2019 user.notice firewall: Reloading firewall due to ifup of wan (pppoa-wan)
Wed Jan 30 15:26:39 2019 daemon.notice netifd: Interface 'wan6' is now up
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: reading /tmp/resolv.conf.auto
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using local addresses only for domain test
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using local addresses only for domain onion
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using local addresses only for domain localhost
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using local addresses only for domain local
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using local addresses only for domain invalid
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using local addresses only for domain bind
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using local addresses only for domain lan
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using nameserver bb.bb.bb.bb#53
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using nameserver bb.bb.bb.cc#53
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using nameserver bbbb:bbb:bbb::bb#53
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using nameserver bbbb:bbb:bbb::cc#53
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using nameserver bbbb:bbb:bbb::bb#53
Wed Jan 30 15:26:39 2019 daemon.info dnsmasq[2095]: using nameserver bbbb:bbb:bbb::cc#53
Wed Jan 30 15:26:39 2019 user.notice firewall: Reloading firewall due to ifupdate of wan (pppoa-wan)
Wed Jan 30 15:26:40 2019 user.notice SQM: Stopping SQM on pppoa-wan
Wed Jan 30 15:26:41 2019 user.notice SQM: Starting SQM script: piece_of_cake.qos on pppoa-wan, in: 7500 Kbps, out: 750 Kbps
Wed Jan 30 15:26:43 2019 user.notice SQM: piece_of_cake.qos was started on pppoa-wan successfully
Wed Jan 30 15:26:43 2019 user.notice firewall: Reloading firewall due to ifup of wan_6 (pppoa-wan)
Wed Jan 30 15:26:44 2019 user.notice SQM: Stopping SQM on pppoa-wan
Wed Jan 30 15:26:45 2019 user.notice SQM: Starting SQM script: piece_of_cake.qos on pppoa-wan, in: 7500 Kbps, out: 750 Kbps
Wed Jan 30 15:26:46 2019 user.notice SQM: piece_of_cake.qos was started on pppoa-wan successfully
It looks like a routine restart of the ppp session by your ISP. They usually take place in order to change your dynamic public IP address.
In my case it happens every 3 days, so it is not so terrible. How often does it happen to you?
Not so often, it's not really bothering me. I'm more curious to understand and this answer would satisfy my curiosity if I had a dynamic public IP address but it's not the case. My public IP is fix. I don't change IP...
My ISP told me it could come either from my modem or from rusted connection or bad cables.
So, from what I can read in your answer and their answer, I guess I have to blame some cable or plug...
What do you think?
It doesn't look like a hardware issue.
Changing dynamic IP address was an example. In another site that I manage there is static IP address, however the session is restarted periodically. My guess is that it is a common practice to eliminate stuck connections. If you notice a pattern in the restart frequency it is definitely a restart initiated by the ISP.
I would guess that bad cables would result in sync losses, but your DL-link stays up and only the ppp-. goes away. Can you by any chance post a screen shot of your DSL error counters just from before and after such a disconnect? An increase in errors (ES, SES, CRC_P, CRCP_P) around the ppp disconncet might indicate that the relevant LCP (link control protocol AFAIR) packets might have been dropped and the upstream end terminated you thinking it lost its connection to you. I do not believe this to be likely though.
Could you please post the output of cat /etc/config/sqm
and tc -s qdisc
please just to rule out issues with sqm (that, given that sqm is instantiated on pppoa-wan should also not affect the LCP packets as these are "injected"/'extracted" transparently to sqm, so sqm will not be able to drop those packets...)
But other than that this looks good, and configuring more overhead than necessary will leave even more room for LCP packets, so this is orthogonal to your issue.
Oh, they are included in the "DSL Status" as shown in your forst post. The point really is to collect a pair tightly around one of these "Wed Jan 30 15:26:29 2019 daemon.info pppd[5634]: LCP terminated by peer" events.
But I can't go back in time and make a screenshot of DSL Status the Wed Jan 30 15:26:29 2019 ? Can I?
Or should I predict the next "restart". I don't know how...
I followed your advised @moeller0 , and I reduced overhead to 14 first and then 13,12,11 and finally 10 and tests (from dslreports.com) are indeed good with it too.
If you may, I have a question and hope you have the answer.
Below you can see several graph of my tests and if all downloads are quiet smooth, uploads are all going up and down like teeth of a saw... You actually need to click on the link to see graphs on the result page.
Is it normal upload test does that? If not, any idea where it comes from, why upload is unstable? and how to solve the issue?
If I ask the question is because we never experience any issue dowloading things, but when we want to call with our SIIP phone from OVH, sometime people can't hear us and OVH is blaming our upload capacity. But at the same time, I never experience the same thing with matrix/riot or whatsapp calls... only with the SIP phone (Cisco SPA112).
So I'm thinking maybe this up and down graph and our SIP phone problem are linked. I'm trying to understand and I'm looking for ideas or better explanations.
I believe that this is most likely caused by you using only two streams for the upload measurement, but 8 for the upstream. The ripples most likely are caused by TCP's bandwidth probing mechanism.
So I believe these to not be indicative of anything.
I just tested this again, I see small ripples both with 2 and with 16 upload streams, but I have no VoIP issues (but also more bandwidth, so not sure what this proves).
Mmmh, you might want to look at the instantaneous traffic rates while this happens to figure out whether this theory has merits. You could look in the GUI under Status -> Realtime Graphs -> Traffic -> pppoa-wan or if this is too coarse, you could install iftop (opkg update ; opkg install iftop) and then run iftop -i pppoa-wan on the router's command line interface.
Thank you @moeller0 and doing so, I could make a link between the silence moment (for our correspondent, we always can hear them) and our upload.
However, silent moment don't happen during a drop of upload capacity (as we can't see any on the graph) but always match to these pic of upload we can observe on these attached graph.
I guess these pic could correspond to some activities from our yunohost server (nothing else was connected to the router at that time but the phone and the yunohost server that contain an email server, nextcloud and a matrix server for 7 people only, not supposed to work that much).
What I don't understand is why we never experience any discomfort using Internet (even using videocall on matrix/riot, whatsapp or telegram, neither for our emails, or handling our cloud) but when we use this SIP phone...
Once that said, I need to find a solution.
Would it be possible to give a priority to its connection? Is it possible for me to tell OpenWrt to keep wide open the upload to the Cisco SPA112 when it is on use? or at least to dedicate 30% capacity of it all the time maybe (we'll loose on other aspect I suppose if we do so but it is important my parents can keep using a landline). Or, would it be possible to limit the upload of one machine (the yunohost server) by saying "this local IP (or MAC address) can use at maximum 0.400Mbps of pppoa-wan upload"?
It is actually the reason I installed SQM, I thought that was the point of QoS but I don't understand how to express that in the settings...
Thank you in advance for your help,
OVH is not helping at all, rejecting the problem on me. And my parents, they put pressure for us to go back to a closed SIP with closed hardware and no fixed IP... just to get the landline working whereas we gain so much quitting these SIP (but they don't see it).
Trying to do the right thing, to put back freedom at the centre of internet and fight against the easy plug&play of big, closed companies is somehow, sometime, hard and a lonely task...
Again thank you for reading me and helping me. It is thanks to help of all communities of FOSS that people like me keep trying and reach so far... and that's how freedom will win!