Modify

Opened 5 years ago

Closed 2 years ago

#12573 closed defect (fixed)

PPPoE reconnect not working

Reported by: anonymous Owned by: developers
Priority: normal Milestone: Chaos Calmer 15.05
Component: packages Version: Trunk
Keywords: ppp pppoe reconnect ifup wan Cc:

Description

ar71xx (WZR-HP-AG300H)
r34432

I have a cron script which does a "ifup wan" to reconnect at a specified time every 24 hours.
After compiling and installing r34432 (before: r32xxx) it won't work properly anymore.

These messages and errors repeat for every re-connect the router tries, so it repeats about every 3 seconds or so.

Dec  4 07:06:54 router daemon.notice netifd: Interface 'wan' is now down
Dec  4 07:06:54 router kern.info kernel: [82702.260000] eth1: link down
Dec  4 07:06:54 router kern.info kernel: [82702.300000] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
Dec  4 07:06:54 router kern.debug kernel: [82702.560000] ar71xx: pll_reg 0xb8050014: 0x1099
Dec  4 07:06:54 router kern.info kernel: [82702.560000] eth1: link up (100Mbps/Full duplex)
Dec  4 07:06:54 router kern.info kernel: [82702.560000] IPv6: ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
Dec  4 07:06:55 router daemon.info pppd[30119]: Plugin rp-pppoe.so loaded.
Dec  4 07:06:55 router daemon.info pppd[30119]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.5
Dec  4 07:06:55 router daemon.notice pppd[30119]: pppd 2.4.5 started by root, uid 0
Dec  4 07:06:56 router daemon.info pppd[30119]: PPP session is 5206
Dec  4 07:06:56 router daemon.warn pppd[30119]: Connected to 00:90:1a:a1:15:c3 via interface eth1
Dec  4 07:06:56 router daemon.err pppd[30119]: Couldn't rename ppp1 to pppoe-wan
Dec  4 07:06:56 router daemon.info pppd[30119]: Exit.

It can't rename ppp1 to pppoe-wan?

This error only appears and repeats after "ifup wan". The first connection after a reboot connects without any problems.
Also if I do a reboot, wait for PPP and then do "ifup wan" it properly reconnects - so this problem doesn't appear immediately.

When the error occurred I did "ifdown wan", confirmed with "logread" that it stopped to try to reconnect, and then did "ifconfig pppoe-wan":

pppoe-wan Link encap:Point-to-Point Protocol
          inet addr:<my ip>  P-t-P:<remote ip>  Mask:255.255.255.255
          POINTOPOINT NOARP MULTICAST  MTU:1492  Metric:1
          RX packets:9421550 errors:0 dropped:0 overruns:0 frame:0
          TX packets:1479004 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:3
          RX bytes:1105973728 (1.0 GiB)  TX bytes:87839013 (83.7 MiB)

So, the connection is still up? Why's that? And 1 GB in RX bytes? That must be an old connection, definitely not a recent one! pppoe-wan doesnt get shut down properly?

No idea if it might be the new kernels fault. If someone of you knows more, please help me! :)
Thank you very much!

Attachments (0)

Change History (15)

comment:1 Changed 5 years ago by anonymous

Additionally, it only appears to be randomly. I had this problem 2 days in a row after sysupgrading. Today, it didn't happen for some reason (I haven't changed anything, didn't even SSH into the router at all after the last reboot).
Strange.

comment:2 Changed 5 years ago by anonymous

Happened today again.
The old connection is just sitting there at pppoe-wan, doing nothing.
I'll try "ifdown wan; sleep 10; ifup wan" or something, instead of just "ifup wan". Perhaps that helps.

comment:3 Changed 5 years ago by anonymous

Looks like ifdown, then sleep, then ifup, helps. No problems at all so far.
So... I'm not sure why that happens but this solves it at least.

comment:4 Changed 5 years ago by anonymous

Additional:
Perhaps it's related to this ticket #12612, I don't know. It didn't create a core file in /tmp as asked in #12612, though.

comment:5 Changed 3 years ago by FrancYescO

i'm having the same issue... seems some conflict with pptpd daemon .... solutions?

comment:6 Changed 3 years ago by FrancYescO

i'm having the same issue... seems some conflict with pptpd daemon .... solutions?

comment:7 Changed 3 years ago by anonymous

Tue Dec 2 21:24:54 2014 daemon.err pppd[18975]: Couldn't rename ppp1 to pppoe-p2

comment:8 Changed 3 years ago by anonymous

DISTRIB_DESCRIPTION="OpenWrt Barrier Breaker r42887"
LOOP:

Tue Dec 2 21:32:33 2014 daemon.notice netifd: Interface 'p2' is now down
Tue Dec 2 21:32:33 2014 kern.info kernel: [509786.720000] IPv6: ADDRCONF(NETDEV_UP): eth0.2: link is not ready
Tue Dec 2 21:32:34 2014 daemon.notice netifd: Interface 'p2' is disabled
Tue Dec 2 21:32:34 2014 daemon.notice netifd: Interface 'p2' is enabled
Tue Dec 2 21:32:34 2014 daemon.notice netifd: Interface 'p2' is setting up now
Tue Dec 2 21:32:34 2014 daemon.notice netifd: VLAN 'eth0.2' link is down
Tue Dec 2 21:32:34 2014 daemon.notice netifd: Interface 'p2' has link connectivity loss
Tue Dec 2 21:32:34 2014 daemon.notice netifd: VLAN 'eth0.2' link is up
Tue Dec 2 21:32:34 2014 daemon.notice netifd: Interface 'p2' has link connectivity
Tue Dec 2 21:32:34 2014 daemon.info pppd[13864]: Plugin rp-pppoe.so loaded.
Tue Dec 2 21:32:34 2014 daemon.info pppd[13864]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Tue Dec 2 21:32:34 2014 daemon.notice pppd[13864]: pppd 2.4.7 started by root, uid 0
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: dst ff:ff:ff:ff:ff:ff src d4:ca:6d:21:59:1c
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: [service-name] [host-uniq 00 00 36 28]
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 50
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: dst d4:ca:6d:21:59:1c src 00:90:1a:42:68:70
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: [AC-name ARC-RJ-E320-02] [host-uniq 00 00 36 28] [service-name] [AC-cookie ce da f2 a4 7e 0c c9 5f 91 1b 66 a3 23 4b f6 82]
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: Send PPPOE Discovery V1T1 PADR session 0x0 length 32
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: dst 00:90:1a:42:68:70 src d4:ca:6d:21:59:1c
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: [service-name] [host-uniq 00 00 36 28] [AC-cookie ce da f2 a4 7e 0c c9 5f 91 1b 66 a3 23 4b f6 82]
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: Recv PPPOE Discovery V1T1 PADS session 0x1a1 length 12
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: dst d4:ca:6d:21:59:1c src 00:90:1a:42:68:70
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: [service-name] [host-uniq 00 00 36 28]
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: PADS: Service-Name:
Tue Dec 2 21:32:34 2014 daemon.info pppd[13864]: PPP session is 417
Tue Dec 2 21:32:34 2014 daemon.warn pppd[13864]: Connected to 00:90:1a:42:68:70 via interface eth0.2
Tue Dec 2 21:32:34 2014 daemon.debug pppd[13864]: using channel 113256
Tue Dec 2 21:32:34 2014 daemon.err pppd[13864]: Couldn't rename ppp1 to pppoe-p2
Tue Dec 2 21:32:34 2014 daemon.info pppd[13864]: Exit.
Tue Dec 2 21:32:35 2014 daemon.notice netifd: Interface 'p2' is now down
Tue Dec 2 21:32:35 2014 kern.info kernel: [509787.880000] IPv6: ADDRCONF(NETDEV_UP): eth0.2: link is not ready
Tue Dec 2 21:32:35 2014 daemon.notice netifd: Interface 'p2' is disabled
Tue Dec 2 21:32:35 2014 daemon.notice netifd: Interface 'p2' is enabled
Tue Dec 2 21:32:35 2014 daemon.notice netifd: Interface 'p2' is setting up now
Tue Dec 2 21:32:35 2014 daemon.notice netifd: VLAN 'eth0.2' link is down
Tue Dec 2 21:32:35 2014 daemon.notice netifd: Interface 'p2' has link connectivity loss
Tue Dec 2 21:32:35 2014 daemon.notice netifd: VLAN 'eth0.2' link is up
Tue Dec 2 21:32:35 2014 daemon.notice netifd: Interface 'p2' has link connectivity
Tue Dec 2 21:32:35 2014 daemon.info pppd[13958]: Plugin rp-pppoe.so loaded.
Tue Dec 2 21:32:35 2014 daemon.info pppd[13958]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Tue Dec 2 21:32:35 2014 daemon.notice pppd[13958]: pppd 2.4.7 started by root, uid 0
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: dst ff:ff:ff:ff:ff:ff src d4:ca:6d:21:59:1c
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: [service-name] [host-uniq 00 00 36 86]
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 50
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: dst d4:ca:6d:21:59:1c src 00:90:1a:42:68:70
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: [AC-name ARC-RJ-E320-02] [host-uniq 00 00 36 86] [service-name] [AC-cookie ce da f2 a4 7e 0c c9 5f 91 1b 66 a3 23 4b f6 82]
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: Send PPPOE Discovery V1T1 PADR session 0x0 length 32
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: dst 00:90:1a:42:68:70 src d4:ca:6d:21:59:1c
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: [service-name] [host-uniq 00 00 36 86] [AC-cookie ce da f2 a4 7e 0c c9 5f 91 1b 66 a3 23 4b f6 82]
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: Recv PPPOE Discovery V1T1 PADS session 0x1a1 length 12
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: dst d4:ca:6d:21:59:1c src 00:90:1a:42:68:70
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: [service-name] [host-uniq 00 00 36 86]
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: PADS: Service-Name:

Tue Dec 2 21:32:35 2014 daemon.info pppd[13958]: PPP session is 417
Tue Dec 2 21:32:35 2014 daemon.warn pppd[13958]: Connected to 00:90:1a:42:68:70 via interface eth0.2
Tue Dec 2 21:32:35 2014 daemon.debug pppd[13958]: using channel 113257
Tue Dec 2 21:32:35 2014 daemon.err pppd[13958]: Couldn't rename ppp1 to pppoe-p2
Tue Dec 2 21:32:35 2014 daemon.info pppd[13958]: Exit.

comment:9 Changed 3 years ago by anonymous

Continue: the pppoe-p2 (ghost) is hang .
ip link
1245: pppoe-p2: <POINTOPOINT,MULTICAST,NOARP> mtu 1500 qdisc noop state DOWN mode DEFAULT group default qlen 3 link/ppp

ip li delete dev pppoe-p2
RTNETLINK answers: Operation not supported

comment:10 Changed 3 years ago by anonymous

Continue: I can rename it
ip li set dev pppoe-p2 name pppoe-p2h1

Now I have ppp link UP and work and the ghost interface:
366354: pppoe-p2: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc fq_codel state UNKNOWN mode DEFAULT group default qlen 3 link/ppp
1245: pppoe-p2h1: <POINTOPOINT,MULTICAST,NOARP> mtu 1500 qdisc noop state DOWN mode DEFAULT group default qlen 3 link/ppp

comment:11 Changed 3 years ago by anonymous

pppd hang again:

4795 root 0 DW [pppd]

17055 root 0 DW [pppd]

Again, I rename ppp interface. OR reboot
506897: pppoe-p2: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc fq_codel state UNKNOWN mode DEFAULT group default qlen 3 link/ppp
366362: pppoe-p2h2: <POINTOPOINT,MULTICAST,NOARP> mtu 1500 qdisc noop state DOWN mode DEFAULT group default qlen 3 link/ppp
1245: pppoe-p2h1: <POINTOPOINT,MULTICAST,NOARP> mtu 1500 qdisc noop state DOWN mode DEFAULT group default qlen 3 link/ppp

comment:12 Changed 2 years ago by Panderine

I'm having same issue on CC-R3

comment:13 Changed 2 years ago by edwin

I have this issue as well on CHAOS CALMER (15.05, r46767), Linux gw 3.18.20 #1 Fri Sep 4 21:55:57 CEST 2015 mips GNU/Linux.
pppd just hangs and the interface is not renamable by pppd itself. I can ifdown wan and rename it manually, but its only a matter of time until it hangs again in DW state.

Whenever pppd hangs it prints this message to kernel log, and indeed only a reboot makes it go away.
However few minutes after the reboot problems are starting to happen again.

[ 30.280000] CPU: 0 PID: 1407 Comm: pppd Not tainted 3.18.20 #1
[ 30.280000] task: 83909d10 ti: 82f04000 task.ti: 82f04000
[ 30.280000] $ 0 : 00000000 00000001 00000001 00000000
[ 30.280000] $ 4 : 802300d8 00000000 82f6cb48 00000001
[ 30.280000] $ 8 : 001d003c 835442a8 0000001e 001d003c
[ 30.280000] $12 : 00000000 772ae3a0 00000000 00000000
[ 30.280000] $16 : 83273400 00000000 8353cdc0 83544088
[ 30.280000] $20 : 838133d0 82f6cb48 80360000 80350000
[ 30.280000] $24 : 00000000 8022c934
[ 30.280000] $28 : 82f04000 82f05d00 802f8e2c 8320f8f0
[ 30.280000] Hi : 00000389
[ 30.280000] Lo : 000352cd
[ 30.280000] epc : 8320f930 0x8320f930 [pppoe@8320e000+0x1f60]
[ 30.280000] Not tainted
[ 30.280000] ra : 8320f8f0 0x8320f8f0 [pppoe@8320e000+0x1f60]
[ 30.280000] Status: 1000fc02 KERNEL EXL
[ 30.280000] Cause : 00800008
[ 30.280000] BadVA : 00000264
[ 30.280000] PrId : 00019374 (MIPS 24Kc)
[ 30.280000] Modules linked in: ath9k ath9k_common pppoe ppp_async iptable_nat ath9k_hw ath pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 mac80211 ip
t_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_tcpmss xt_statistic xt_state xt_recent xt_nat xt_multiport xt_mark xt_mac xt_limit xt_length xt_id xt_hl xt_helper xt
_ecn xt_dscp xt_conntrack xt_connmark xt_connlimit xt_connbytes xt_comment xt_TCPMSS xt_REDIRECT xt_NETMAP xt_LOG xt_HL xt_DSCP xt_CT xt_CLASSIFY slhc nf_reject_ipv4 nf_na
t_masquerade_ipv4 nf_nat_ftp nf_nat nf_log_ipv4 nf_defrag_ipv6 nf_defrag_ipv4 nf_conntrack_rtcache nf_conntrack_ftp nf_conntrack iptable_raw iptable_mangle iptable_filter
ipt_ECN ip_tables crc_ccitt compat sch_teql sch_tbf sch_sfq sch_red sch_prio sch_pie sch_netem sch_htb sch_gred sch_fq sch_dsmark sch_codel em_text em_nbyte em_meta em_cmp

cls_basic act_police act_ipt act_skbedit act_mirred em_u32 cls_u32 cls_tcindex cls_flow cls_route cls_fw sch_hfsc sch_ingress ledtrig_usbdev xt_set ip_set_list_set ip_set

_hash_netiface ip_set_hash_netport ip_set_hash_netnet ip_set_hash_net ip_set_hash_netportnet ip_set_hash_mac ip_set_hash_ipportnet ip_set_hash_ipportip ip_set_hash_ipport
ip_set_hash_ipmark ip_set_hash_ip ip_set_bitmap_port ip_set_bitmap_ipmac ip_set_bitmap_ip ip_set nfnetlink ip6t_REJECT nf_reject_ipv6 nf_log_ipv6 nf_log_common ip6table_ra
w ip6table_mangle ip6table_filter ip6_tables x_tables ifb ipv6 arc4 crypto_blkcipher ohci_platform ohci_hcd ehci_platform ehci_hcd gpio_button_hotplug usbcore nls_base usb
_common
[ 30.280000] Process pppd (pid: 1407, threadinfo=82f04000, task=83909d10, tls=77f66440)
[ 30.280000] Stack : 83544220 83544220 83544220 001c003c 8353cdc0 8320fe34 00000008 8022cb68
[ 30.280000] 82f00780 001f0040 82ee0180 83544220 82f6cb40 82f6cb40 8353cde0 8022cc18
[ 30.280000] 82f6cb40 8353cde0 00000008 83544088 838133d0 800fb4dc 81052bc0 810545a0
[ 30.280000] 82f6cb48 00000001 00000000 00000000 00000000 83909d10 82f6c780 803a0000
[ 30.280000] 82f007b4 8319a880 00000001 80094568 82e77dc0 801224cc 83909d10 82f00780
[ 30.280000] ...
[ 30.280000] Call Trace:[<8022cb68>] 0x8022cb68
[ 30.280000] [<8022cc18>] 0x8022cc18
[ 30.280000] [<800fb4dc>] 0x800fb4dc
[ 30.280000] [<80094568>] 0x80094568
[ 30.280000] [<801224cc>] 0x801224cc
[ 30.280000] [<80080df0>] 0x80080df0
[ 30.280000] [<80081f20>] 0x80081f20
[ 30.280000] [<8008a424>] 0x8008a424
[ 30.280000] [<8006f554>] 0x8006f554
[ 30.280000] [<80088608>] 0x80088608
[ 30.280000] [<8010aea4>] 0x8010aea4
[ 30.280000] [<8010bd40>] 0x8010bd40
[ 30.280000] [<800aa47c>] 0x800aa47c
[ 30.280000] [<80070260>] 0x80070260
[ 30.280000] [<800609ac>] 0x800609ac
[ 30.280000]
[ 30.280000]
[ 30.280000] Code: 41626000 30420001 000000c0 <8c630264> 8c640000 2484ffff ac640000 10400002 41606000
[ 30.620000] ---[ end trace d2a525ccd0dacab2 ]---
[ 30.630000] Fixing recursive fault but reboot is needed!

Probably because the ethernet WAN link keeps going up and down:

Mon Jan 11 12:14:17 2016 kern.info kernel: [ 935.260000] eth1: link down
Mon Jan 11 12:14:18 2016 kern.info kernel: [ 936.260000] eth1: link up (100Mbps/Full duplex)
Mon Jan 11 12:14:21 2016 kern.info kernel: [ 938.550000] eth1: link down
Mon Jan 11 12:14:21 2016 kern.info kernel: [ 939.260000] eth1: link up (100Mbps/Full duplex)
Mon Jan 11 12:15:19 2016 kern.info kernel: [ 997.270000] eth1: link down
Mon Jan 11 12:15:21 2016 kern.info kernel: [ 999.270000] eth1: link up (100Mbps/Full duplex)
Mon Jan 11 12:15:23 2016 kern.info kernel: [ 1001.270000] eth1: link down
Mon Jan 11 12:15:24 2016 kern.info kernel: [ 1002.270000] eth1: link up (100Mbps/Full duplex)
Mon Jan 11 12:15:24 2016 kern.info kernel: [ 1002.290000] eth1: link down
Mon Jan 11 12:15:27 2016 kern.info kernel: [ 1005.270000] eth1: link up (100Mbps/Full duplex)

comment:14 Changed 2 years ago by edwin

this is the oops message:
[ 29.490000] pppoe-wan: renamed from ppp0
[ 30.270000] eth1: link down
[ 30.280000] CPU 0 Unable to handle kernel paging request at virtual address 00000264, epc == 8320f930, ra == 8320f8f0
[ 30.280000] Oops#1:

comment:15 Changed 2 years ago by nbd

  • Resolution set to fixed
  • Status changed from new to closed

fixed in the chaos calmer branch as of r47964

Add Comment

Modify Ticket

Action
as closed .
The resolution will be deleted. Next status will be 'reopened'.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.