Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
openwrt-bot opened this issue May 18, 2020 · 2 comments
Labels

Comments

@openwrt-bot
Copy link

n8v8R:

  • 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.

@openwrt-bot
Copy link
Author

n8v8R:

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

@openwrt-bot
Copy link
Author

n8v8R:

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

1 participant