OpenWrt/LEDE Project

  • Status Closed
  • Percent Complete
    100%
  • Task Type Bug Report
  • Category Packages
  • Assigned To No-one
  • Operating System All
  • Severity High
  • Priority Very Low
  • Reported Version Trunk
  • Due in Version Undecided
  • Due Date Undecided
  • Private
Attached to Project: OpenWrt/LEDE Project
Opened by n8v8R - 18.05.2020
Last edited by Petr Štetiar - 05.08.2020

FS#3107 - [netifd] wan Command failed: Permission denied | repeated ppp module loads

- Master 5.4.41
- mvebu → cortex-A9
- upstream connectivity VDSL2 dual-stack | PPPoE | IPv4 via PPPoE | IPv6 via DHCP (only after PPPoE is completed)
- SFP VDSL modem residing in router’s SFP cage


ifup wan

produces

40:49  netifd: Interface 'wan' is enabled
40:49  kernel: [ 4539.310854] mvneta f1034000.ethernet eth2: configuring for inband/1000base-x link mode
40:49  kernel: [ 4539.629747] sfp sfp: module transmit fault indicated
40:51  netifd: Network device 'eth2' link is up
40:51  netifd: Interface 'wan' has link connectivity
40:51  netifd: Interface 'wan' is setting up now
40:51  kernel: [ 4541.699901] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
40:51  kernel: [ 4541.699917] IPv6: ADDRCONF(NETDEV_CHANGE): eth2: link becomes ready
40:51  insmod: module is already loaded - slhc
40:51  insmod: module is already loaded - ppp_generic
40:51  insmod: module is already loaded - pppox
40:51  insmod: module is already loaded - pppoe
40:51  pppd[29207]: Plugin rp-pppoe.so loaded.
40:51  pppd[29207]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.8
40:51  pppd[29207]: pppd 2.4.8 started by root, uid 0
41:06  pppd[29207]: Timeout waiting for PADO packets
41:06  pppd[29207]: Unable  complete PPPoE Discovery
41:06  pppd[29207]: Exit.
41:06  netifd: Interface 'wan' is now down
41:06  kernel: [ 4556.940117] mvneta f1034000.ethernet eth2: Link is Down
41:06  netifd: Interface 'wan' is disabled
41:06  netifd: Interface 'wan' is enabled
41:06  netifd: Interface 'wan' is setting up now
41:06  kernel: [ 4556.954502] mvneta f1034000.ethernet eth2: configuring for inband/1000base-x link mode
41:06  netifd: Network device 'eth2' link is down
41:06  netifd: Interface 'wan' has link connectivity loss
41:06  insmod: module is already loaded - slhc
41:06  insmod: module is already loaded - ppp_generic
41:06  insmod: module is already loaded - pppox
41:06  insmod: module is already loaded - pppoe
41:07  netifd: wan (29306): Command failed: Permission denied
41:07  netifd: Interface 'wan' is now down
41:07  netifd: Interface 'wan' is disabled
41:07  netifd: Interface 'wan' is enabled
41:07  kernel: [ 4557.042474] mvneta f1034000.ethernet eth2: configuring for inband/1000base-x link mode
41:07  netifd: Network device 'eth2' link is up
41:07  netifd: Interface 'wan' has link connectivity
41:07  netifd: Interface 'wan' is setting up now
41:07  kernel: [ 4557.209931] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
41:07  kernel: [ 4557.209948] IPv6: ADDRCONF(NETDEV_CHANGE): eth2: link becomes ready
41:07  insmod: module is already loaded - slhc
41:07  insmod: module is already loaded - ppp_generic
41:07  insmod: module is already loaded - pppox
41:07  insmod: module is already loaded - pppoe
41:07  pppd[29362]: Plugin rp-pppoe.so loaded.
41:07  pppd[29362]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.8
41:07  pppd[29362]: pppd 2.4.8 started by root, uid 0
41:22  pppd[29362]: Timeout waiting for PADO packets
41:22  pppd[29362]: Unable  complete PPPoE Discovery
41:22  pppd[29362]: Exit.
41:22  netifd: Interface 'wan' is now down
41:22  kernel: [ 4572.446438] mvneta f1034000.ethernet eth2: Link is Down
41:22  netifd: Interface 'wan' is disabled
41:22  netifd: Interface 'wan' is enabled
41:22  netifd: Interface 'wan' is setting up now
41:22  netifd: Network device 'eth2' link is down
41:22  netifd: Interface 'wan' has link connectivity loss
41:22  kernel: [ 4572.459786] mvneta f1034000.ethernet eth2: configuring for inband/1000base-x link mode
41:22  insmod: module is already loaded - slhc
41:22  insmod: module is already loaded - ppp_generic
41:22  insmod: module is already loaded - pppox
41:22  insmod: module is already loaded - pppoe
41:22  netifd: wan (29492): Command failed: Permission denied
41:22  netifd: Interface 'wan' is now down
41:22  netifd: Interface 'wan' is disabled
41:22  netifd: Interface 'wan' is enabled
41:22  kernel: [ 4572.544765] mvneta f1034000.ethernet eth2: configuring for inband/1000base-x link mode
41:22  netifd: Network device 'eth2' link is up
41:22  netifd: Interface 'wan' has link connectivity
41:22  netifd: Interface 'wan' is setting up now
41:22  kernel: [ 4572.712631] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
41:22  kernel: [ 4572.712647] IPv6: ADDRCONF(NETDEV_CHANGE): eth2: link becomes ready
41:22  insmod: module is already loaded - slhc
41:22  insmod: module is already loaded - ppp_generic
41:22  insmod: module is already loaded - pppox
41:22  insmod: module is already loaded - pppoe
41:22  pppd[29549]: Plugin rp-pppoe.so loaded.
41:22  pppd[29549]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.8
41:22  pppd[29549]: pppd 2.4.8 started by root, uid 0
41:29  pppd[29549]: PPP session is 31713
41:29  pppd[29549]: Connected  78:ba:f9:73:f5:74 via interface eth2
41:29  kernel: [ 4579.318874] pppoe-wan: renamed from ppp0
41:29  pppd[29549]: Renamed interface ppp0  pppoe-wan
41:29  pppd[29549]: Using interface pppoe-wan
41:29  pppd[29549]: Connect: pppoe-wan <--> eth2
41:35  pppd[29549]: PAP authentication succeeded
41:35  pppd[29549]: peer from calling number 78:BA:F9:73:F5:74 authorized
41:35  pppd[29549]: local  IP address 
41:35  pppd[29549]: remote IP address 
41:35  pppd[29549]: primary   DNS address 
41:35  pppd[29549]: secondary DNS address 
41:35  pppd[29549]: local  LL address fe80::b931:4e21:f7f2:a0ad
41:35  pppd[29549]: remote LL address fe80::7aba:f9ff:fe73:f574
41:35  netifd: Network device 'pppoe-wan' link is up
41:35  netifd: Interface 'wan' is now up
41:35  netifd: Network alias 'pppoe-wan' link is up
41:35  netifd: Interface 'wan_6' is enabled
41:35  netifd: Interface 'wan_6' has link connectivity
41:35  netifd: Interface 'wan_6' is setting up now

Unclear how this could be debugged. With the repeated loading of ppp modules it looks like a timing issue.

 


Closed by  Petr ┼átetiar
05.08.2020 10:16
Reason for closing:  Not a bug
Additional comments about closing:  

Requested

n8v8R commented on 18.05.2020 18:15

found the -l debug level toggle for netifd with when set to 5 revealed that */etc/hotplug.d/iface/00-netstate* had the wrong file permission (644), though I have no recollection of ever having touched that file. As a consequence is caused

/sbin/hotplug-call: line 20: /etc/hotplug.d/iface/00-netstate: Permission denied

Having rectified the file permission (755) the debug output then shows:

netifd: /etc/hotplug.d/iface/00-netstate: line 2: uci_toggle_state: not found
netifd: /etc/hotplug.d/iface/00-netstate: line 4: uci_toggle_state: not found

and still present

wan (5015): Command failed: Permission denied

which however is absent with

option force_link '1'

set for the WAN iface.

It would indicate that the hotplug script failing subsequently link carrier sensing fails, causing the *netid* error and the repeated loading of *pppd*.

With with

option force_link '1'

in place the log then reads:

31:39 pppd[3413]: Timeout waiting for PADO packets
31:39 pppd[3413]: Unable to complete PPPoE Discovery
31:39 pppd[3413]: Exit.
31:39 netifd: Interface 'wan' is now down
31:39 kernel: [   35.963084] mvneta f1034000.ethernet eth2: Link is Down
31:39 netifd: Interface 'wan' is disabled
31:39 kernel: [   35.978105] mvneta f1034000.ethernet eth2: configuring for inband/1000base-x link mode
31:39 kernel: [   35.978869] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
31:39 netifd: Interface 'wan' is enabled
31:39 netifd: Interface 'wan' is setting up now
31:39 netifd: Network device 'eth2' link is down
31:39 netifd: Interface 'wan' has link connectivity loss
31:39 insmod: module is already loaded - slhc
31:39 insmod: module is already loaded - ppp_generic
31:39 insmod: module is already loaded - pppox
31:39 insmod: module is already loaded - pppoe
31:39 pppd[5067]: Plugin rp-pppoe.so loaded.
31:39 pppd[5067]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.8
31:39 pppd[5067]: pppd 2.4.8 started by root, uid 0
31:39 netifd: Network device 'eth2' link is up
31:39 netifd: Interface 'wan' has link connectivity 
31:39 kernel: [   36.145795] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
31:39 kernel: [   36.145811] IPv6: ADDRCONF(NETDEV_CHANGE): eth2: link becomes ready
31:54 pppd[5067]: Timeout waiting for PADO packets
31:54 pppd[5067]: Unable to complete PPPoE Discovery
31:54 pppd[5067]: Exit.
31:54 netifd: Interface 'wan' is now down
31:54 kernel: [   51.233186] mvneta f1034000.ethernet eth2: Link is Down
31:54 netifd: Interface 'wan' is disabled
31:54 netifd: Interface 'wan' is enabled
31:54 netifd: Interface 'wan' is setting up now
31:54 netifd: Network device 'eth2' link is down
31:54 netifd: Interface 'wan' has link connectivity loss
31:54 kernel: [   51.247694] mvneta f1034000.ethernet eth2: configuring for inband/1000base-x link mode
31:54 kernel: [   51.248466] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
31:54 insmod: module is already loaded - slhc
31:54 insmod: module is already loaded - ppp_generic
31:54 insmod: module is already loaded - pppox
31:54 insmod: module is already loaded - pppoe
31:54 pppd[5147]: Plugin rp-pppoe.so loaded.
31:54 pppd[5147]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.8
31:54 pppd[5147]: pppd 2.4.8 started by root, uid 0
31:54 netifd: Network device 'eth2' link is up
31:54 netifd: Interface 'wan' has link connectivity 
31:54 kernel: [   51.415158] mvneta f1034000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
31:54 kernel: [   51.415175] IPv6: ADDRCONF(NETDEV_CHANGE): eth2: link becomes ready
32:06 pppd[5147]: PPP session is 31993
32:06 pppd[5147]: Connected to 78:ba:f9:73:f5:74 via interface eth2
32:06 kernel: [   63.127258] pppoe-wan: renamed from ppp0
32:06 pppd[5147]: Renamed interface ppp0 to pppoe-wan
32:06 pppd[5147]: Using interface pppoe-wan
32:06 pppd[5147]: Connect: pppoe-wan <--> eth2
32:12 pppd[5147]: PAP authentication succeeded
32:12 pppd[5147]: peer from calling number 78:BA:F9:73:F5:74 authorized
32:12 pppd[5147]: local  LL address fe80::b8cd:aea3:b0ab:2430
32:12 pppd[5147]: remote LL address fe80::7aba:f9ff:fe73:f574
32:12 pppd[5147]: local  IP address 
32:12 pppd[5147]: remote IP address 
32:12 pppd[5147]: primary   DNS address 
32:12 pppd[5147]: secondary DNS address 
32:12 netifd: Network device 'pppoe-wan' link is up
32:12 netifd: Interface 'wan' is now up
32:12 netifd[3108]: /etc/hotplug.d/iface/00-netstate: line 2: uci_toggle_state: not found
32:12 netifd[3108]: /etc/hotplug.d/iface/00-netstate: line 4: uci_toggle_state: not found
32:12 netifd[3108]: /etc/hotplug.d/iface/00-netstate: line 5: uci_toggle_state: not found
32:12 netifd: Network alias 'pppoe-wan' link is up
32:12 netifd: Interface 'wan_6' is enabled
32:12 netifd: Interface 'wan_6' has link connectivity 
32:12 netifd: Interface 'wan_6' is setting up now
32:15 netifd: Interface 'wan_6' is now up
32:15 netifd[3108]: /etc/hotplug.d/iface/00-netstate: line 2: uci_toggle_state: not found
32:15 netifd[3108]: /etc/hotplug.d/iface/00-netstate: line 4: uci_toggle_state: not found
32:15 netifd[3108]: /etc/hotplug.d/iface/00-netstate: line 5: uci_toggle_state: not found
n8v8R commented on 18.05.2020 19:02

adding

. /lib/functions.sh

to etc/hotplug.d/iface/00-netstate at least sorts

netifd: /etc/hotplug.d/iface/00-netstate: line 2: uci_toggle_state: not found

but not

[netifd] wan Command failed: Permission denied

Loading...

Available keyboard shortcuts

Tasklist

Task Details

Task Editing