Bug 768861 - ppp0e getting disconnected in every 30 min
Summary: ppp0e getting disconnected in every 30 min
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Fedora
Classification: Fedora
Component: ppp
Version: 16
Hardware: ia64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Michal Sekletar
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-12-19 08:17 UTC by Anshaj
Modified: 2013-02-13 19:13 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-02-13 19:13:24 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
pppoe config file (46 bytes, application/octet-stream)
2011-12-19 08:18 UTC, Anshaj
no flags Details
pppoe config file (1.76 KB, application/octet-stream)
2011-12-19 08:19 UTC, Anshaj
no flags Details
pppoe config file (105 bytes, application/octet-stream)
2011-12-19 08:19 UTC, Anshaj
no flags Details

Description Anshaj 2011-12-19 08:17:59 UTC
Description of problem:
I have configured my broadband setup using pppoe-setup utility. Internet continue to work for 30 min and they automatically gets disconnected. Then network manager automatically retires 3 times and then giveup permanently. I search alot in google and changed many parameters inside /etc/ppp directory but no change in behavior. In fact my observation is that pppd process is not reading config parameters from /etc/ppp directory. 

Process signature is 

root      1037   866  0 15:38 ?        00:00:00 /usr/sbin/pppd nodetach lock nodefaultroute user anshaj plugin rp-pppoe.so nic-p5p1 rp_pppoe_service netvigator noauth nodeflate usepeerdns mru 1492 mtu 1492 lcp-echo-failure 3 lcp-echo-interval 20 ipparam /org/freedesktop/NetworkManager/PPP/0 plugin /usr/lib64/pppd/2.4.5/nm-pppd-plugin.so

where value of lcp-echo-failure 3. I tried to change this value but it is not getting changed. 

System logs contains following 

Dec 19 16:11:45 unforgiven pppd[1037]: No response to 3 echo-requests
Dec 19 16:11:45 unforgiven pppd[1037]: Serial link appears to be disconnected.
Dec 19 16:11:45 unforgiven NetworkManager[866]: No response to 3 echo-requests
Dec 19 16:11:45 unforgiven NetworkManager[866]: Serial link appears to be disconnected.
Dec 19 16:11:45 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate'
Dec 19 16:11:45 unforgiven pppd[1037]: Connect time 33.1 minutes.
Dec 19 16:11:45 unforgiven pppd[1037]: Sent 2620718 bytes, received 32867178 bytes.
Dec 19 16:11:45 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Dec 19 16:11:45 unforgiven NetworkManager[866]: Connect time 33.1 minutes.
Dec 19 16:11:45 unforgiven NetworkManager[866]: Sent 2620718 bytes, received 32867178 bytes.
Dec 19 16:11:45 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Dec 19 16:11:45 unforgiven pppd[1037]: Connection terminated.
Dec 19 16:11:45 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_phasechange): status 11 / phase 'disconnect'
Dec 19 16:11:45 unforgiven NetworkManager[866]: Connection terminated.
Dec 19 16:11:45 unforgiven avahi-daemon[884]: Withdrawing workstation service for ppp0.
Dec 19 16:11:45 unforgiven kernel: [ 1997.630960] libfcoe_device_notification: NETDEV_UNREGISTER ppp0
Dec 19 16:11:45 unforgiven NetworkManager[866]: <info> (p5p1): device state change: activated -> failed (reason 'ppp-disconnect') [100 120 13]
Dec 19 16:11:45 unforgiven NetworkManager[866]: NetworkManager[866]: <info> (p5p1): device state change: activated -> failed (reason 'ppp-disconnect') [100 120 13]
Dec 19 16:11:45 unforgiven NetworkManager[866]: <warn> Activation (p5p1) failed.
Dec 19 16:11:45 unforgiven NetworkManager[866]: NetworkManager[866]: <warn> Activation (p5p1) failed.
Dec 19 16:11:45 unforgiven NetworkManager[866]: <info> (p5p1): device state change: failed -> disconnected (reason 'none') [120 30 0]
Dec 19 16:11:45 unforgiven NetworkManager[866]: <info> (p5p1): deactivating device (reason 'none') [0]
Dec 19 16:11:45 unforgiven NetworkManager[866]: NetworkManager[866]: <info> (p5p1): device state change: failed -> disconnected (reason 'none') [120 30 0]
Dec 19 16:11:45 unforgiven NetworkManager[866]: NetworkManager[866]: <info> (p5p1): deactivating device (reason 'none') [0]
Dec 19 16:11:45 unforgiven dbus[910]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Dec 19 16:11:45 unforgiven dbus-daemon[910]: dbus[910]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Dec 19 16:11:45 unforgiven dbus[910]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 19 16:11:45 unforgiven dbus-daemon[910]: dbus[910]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 19 16:11:45 unforgiven NetworkManager[866]: <warn> could not read ppp stats: No such device
Dec 19 16:11:45 unforgiven NetworkManager[866]: NetworkManager[866]: <warn> could not read ppp stats: No such device
Dec 19 16:11:45 unforgiven lldpad[953]: netlink: 20 bytes leftover after parsing attributes.
Dec 19 16:11:45 unforgiven pppd[1037]: Terminating on signal 15
Dec 19 16:11:45 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_phasechange): status 1 / phase 'dead'
Dec 19 16:11:45 unforgiven NetworkManager[866]: Terminating on signal 15
Dec 19 16:11:45 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_exit_notify): cleaning up
Dec 19 16:11:45 unforgiven pppd[1037]: Exit.
Dec 19 16:11:45 unforgiven systemd[1]: PID 1815 read from file /run/sm-client.pid does not exist. Your service or init script might be broken.
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Auto-activating connection 'DSL connection 1'.
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) starting connection 'DSL connection 1'
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> (p5p1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Auto-activating connection 'DSL connection 1'.
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) starting connection 'DSL connection 1'
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> (p5p1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 1 of 5 (Device Prepare) scheduled...
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 1 of 5 (Device Prepare) scheduled...
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 1 of 5 (Device Prepare) started...
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 2 of 5 (Device Configure) scheduled...
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 1 of 5 (Device Prepare) complete.
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 2 of 5 (Device Configure) starting...
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> (p5p1): device state change: prepare -> config (reason 'none') [40 50 0]
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 1 of 5 (Device Prepare) started...
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 2 of 5 (Device Configure) scheduled...
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 1 of 5 (Device Prepare) complete.
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 2 of 5 (Device Configure) starting...
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> (p5p1): device state change: prepare -> config (reason 'none') [40 50 0]
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 2 of 5 (Device Configure) successful.
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 3 of 5 (IP Configure Start) scheduled.
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 2 of 5 (Device Configure) complete.
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 3 of 5 (IP Configure Start) started...
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 2 of 5 (Device Configure) successful.
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> (p5p1): device state change: config -> ip-config (reason 'none') [50 70 0]
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 3 of 5 (IP Configure Start) scheduled.
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 2 of 5 (Device Configure) complete.
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 3 of 5 (IP Configure Start) started...
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> (p5p1): device state change: config -> ip-config (reason 'none') [50 70 0]
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> starting PPP connection
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> starting PPP connection
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> pppd started with pid 3058
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> pppd started with pid 3058
Dec 19 16:11:48 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 3 of 5 (IP Configure Start) complete.
Dec 19 16:11:48 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 3 of 5 (IP Configure Start) complete.
Dec 19 16:11:48 unforgiven pppd[3058]: Plugin rp-pppoe.so loaded.
Dec 19 16:11:48 unforgiven pppd[3058]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.5
Dec 19 16:11:48 unforgiven NetworkManager[866]: Plugin rp-pppoe.so loaded.
Dec 19 16:11:48 unforgiven NetworkManager[866]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.5
Dec 19 16:11:48 unforgiven pppd[3058]: Plugin /usr/lib64/pppd/2.4.5/nm-pppd-plugin.so loaded.
Dec 19 16:11:48 unforgiven NetworkManager[866]: Plugin /usr/lib64/pppd/2.4.5/nm-pppd-plugin.so loaded.
Dec 19 16:11:48 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (plugin_init): initializing
Dec 19 16:11:48 unforgiven pppd[3058]: pppd 2.4.5 started by root, uid 0
Dec 19 16:11:48 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Dec 19 16:11:54 unforgiven pppd[3058]: PPP session is 2925
Dec 19 16:11:54 unforgiven pppd[3058]: Connected to 00:30:88:14:ef:d9 via interface p5p1
Dec 19 16:11:54 unforgiven NetworkManager[866]: PPP session is 2925
Dec 19 16:11:54 unforgiven NetworkManager[866]: Connected to 00:30:88:14:ef:d9 via interface p5p1
Dec 19 16:11:54 unforgiven pppd[3058]: Using interface ppp0
Dec 19 16:11:54 unforgiven pppd[3058]: Connect: ppp0 <--> p5p1
Dec 19 16:11:54 unforgiven NetworkManager[866]: Using interface ppp0
Dec 19 16:11:54 unforgiven NetworkManager[866]: Connect: ppp0 <--> p5p1
Dec 19 16:11:54 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Dec 19 16:11:54 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
Dec 19 16:11:54 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (get_credentials): passwd-hook, requesting credentials...
Dec 19 16:11:54 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (get_credentials): got credentials from NetworkManager
Dec 19 16:11:54 unforgiven pppd[3058]: PAP authentication succeeded
Dec 19 16:11:54 unforgiven pppd[3058]: peer from calling number 00:30:88:14:EF:D9 authorized
Dec 19 16:11:54 unforgiven NetworkManager[866]: PAP authentication succeeded
Dec 19 16:11:54 unforgiven NetworkManager[866]: peer from calling number 00:30:88:14:EF:D9 authorized
Dec 19 16:11:54 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Dec 19 16:11:54 unforgiven pppd[3058]: local  IP address 1.64.57.88
Dec 19 16:11:54 unforgiven pppd[3058]: remote IP address 112.119.198.254
Dec 19 16:11:54 unforgiven pppd[3058]: primary   DNS address 218.102.52.81
Dec 19 16:11:54 unforgiven pppd[3058]: secondary DNS address 218.102.23.77
Dec 19 16:11:54 unforgiven NetworkManager[866]: local  IP address 1.64.57.88
Dec 19 16:11:54 unforgiven NetworkManager[866]: remote IP address 112.119.198.254
Dec 19 16:11:54 unforgiven NetworkManager[866]: primary   DNS address 218.102.52.81
Dec 19 16:11:54 unforgiven NetworkManager[866]: secondary DNS address 218.102.23.77
Dec 19 16:11:54 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_phasechange): status 9 / phase 'running'
Dec 19 16:11:54 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_ip_up): ip-up event
Dec 19 16:11:54 unforgiven NetworkManager[866]: ** Message: nm-ppp-plugin: (nm_ip_up): sending Ip4Config to NetworkManager...
Dec 19 16:11:54 unforgiven NetworkManager[866]: <info> PPP manager(IP Config Get) reply received.
Dec 19 16:11:54 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 4 of 5 (IP4 Configure Get) scheduled...
Dec 19 16:11:54 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 4 of 5 (IP4 Configure Get) started...
Dec 19 16:11:54 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 5 of 5 (IP Configure Commit) scheduled...
Dec 19 16:11:54 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 4 of 5 (IP4 Configure Get) complete.
Dec 19 16:11:54 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 5 of 5 (IP Configure Commit) started...
Dec 19 16:11:54 unforgiven NetworkManager[866]: NetworkManager[866]: <info> PPP manager(IP Config Get) reply received.
Dec 19 16:11:54 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 4 of 5 (IP4 Configure Get) scheduled...
Dec 19 16:11:54 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 4 of 5 (IP4 Configure Get) started...
Dec 19 16:11:54 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 5 of 5 (IP Configure Commit) scheduled...
Dec 19 16:11:54 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 4 of 5 (IP4 Configure Get) complete.
Dec 19 16:11:54 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 5 of 5 (IP Configure Commit) started...
Dec 19 16:11:55 unforgiven NetworkManager[866]: <info> (p5p1): device state change: ip-config -> activated (reason 'none') [70 100 0]
Dec 19 16:11:55 unforgiven NetworkManager[866]: NetworkManager[866]: <info> (p5p1): device state change: ip-config -> activated (reason 'none') [70 100 0]
Dec 19 16:11:55 unforgiven NetworkManager[866]: <info> Policy set 'DSL connection 1' (ppp0) as default for IPv4 routing and DNS.
Dec 19 16:11:55 unforgiven NetworkManager[866]: <info> Activation (p5p1) successful, device activated.
Dec 19 16:11:55 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Policy set 'DSL connection 1' (ppp0) as default for IPv4 routing and DNS.
Dec 19 16:11:55 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) successful, device activated.
Dec 19 16:11:55 unforgiven NetworkManager[866]: <info> Activation (p5p1) Stage 5 of 5 (IP Configure Commit) complete.
Dec 19 16:11:55 unforgiven NetworkManager[866]: NetworkManager[866]: <info> Activation (p5p1) Stage 5 of 5 (IP Configure Commit) complete.


This is no ISP issue as same connection works fine with windows..


Version-Release number of selected component (if applicable):

Linux unforgiven 3.1.5-1.fc16.x86_64 #1 SMP Fri Dec 9 18:11:10 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux

How reproducible:

Keep the internet running and it automatically gets disconnected after 30 min

Steps to Reproduce:
1.
2.
3.
  
Actual results:

Internet gets disconnected

Expected results:
Internet should continue to work. Or If possible let me know how to change the config so that I can incrase retry to high number. I am attaching pppoe config files. 

Additional info:

Comment 1 Anshaj 2011-12-19 08:18:35 UTC
Created attachment 548509 [details]
pppoe config file

Comment 2 Anshaj 2011-12-19 08:19:03 UTC
Created attachment 548510 [details]
pppoe config file

Comment 3 Anshaj 2011-12-19 08:19:34 UTC
Created attachment 548511 [details]
pppoe config file

Comment 4 Anshaj 2011-12-19 08:20:32 UTC
Same ISP connection used to work with Fedora 12. At that time I used asdl gui to setup the internet connection.

Comment 5 Jirka Klimes 2012-05-23 13:29:40 UTC
The connection is teared out because the peer doesn't reply to ECHO packets:
Dec 19 16:11:45 unforgiven pppd[1037]: No response to 3 echo-requests
Dec 19 16:11:45 unforgiven pppd[1037]: Serial link appears to be disconnected.

So you should probably disable the ECHO packets. You can do that by unchecking
"Send PPP echo packets" checkbox on 'PPP setings' tab in nm-connection-editor.

see 'man pppd' for lcp-echo-failure and lcp-echo-interval
NM passes the parameters to pppd on command-line.

What NM version do you use?
$ rpm -q NetworkManager
Values 3 and 20 suggest you use older NM version. There was a change on this: https://bugzilla.gnome.org/show_bug.cgi?id=663970

When "Send PPP echo packets" is unchecked, lcp-echo-failure and lcp-echo-interval parameters in [ppp] section in /etc/NetworkManager/system-connections/<your_connection_name> file are removed, which is equivalent to 
[ppp]
lcp-echo-failure=0
lcp-echo-interval=0

Comment 6 Fedora End Of Life 2013-01-16 15:58:14 UTC
This message is a reminder that Fedora 16 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 16. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '16'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 16's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 16 is end of life. If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora, you are encouraged to click on 
"Clone This Bug" and open it against that version of Fedora.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 7 Fedora End Of Life 2013-02-13 19:13:27 UTC
Fedora 16 changed to end-of-life (EOL) status on 2013-02-12. Fedora 16 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.


Note You need to log in before you can comment on or make changes to this bug.