radvd configuration failure

[arcivanov]

Jul 17 14:36:27 host nm-dispatcher[4062]: + read -r line
Jul 17 14:36:27 host nm-dispatcher[4062]: + lstrip line '    MinRtrAdvInterval 30;'
Jul 17 14:36:27 host nm-dispatcher[4062]: + debug3 line '    MinRtrAdvInterval 30;'
Jul 17 14:36:27 host nm-dispatcher[4062]: + :
Jul 17 14:36:27 host nm-dispatcher[4062]: + local -l '_s=    MinRtrAdvInterval 30;'
Jul 17 14:36:27 host nm-dispatcher[4062]: + _s='minrtradvinterval 30;'
Jul 17 14:36:27 host nm-dispatcher[4062]: + _s='minrtradvinterval 30;'
Jul 17 14:36:27 host nm-dispatcher[4062]: + printf -v line %s 'minrtradvinterval 30;'
Jul 17 14:36:27 host nm-dispatcher[4062]: + case $state in
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ minrtradvinterval 30; =~ ^}; ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ minrtradvinterval 30; =~ ^prefix ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ minrtradvinterval 30; =~ ^@prefix@ ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + read -r line
Jul 17 14:36:27 host nm-dispatcher[4062]: + lstrip line '    @PREFIX@ {'
Jul 17 14:36:27 host nm-dispatcher[4062]: + debug3 line '    @PREFIX@ {'
Jul 17 14:36:27 host nm-dispatcher[4062]: + :
Jul 17 14:36:27 host nm-dispatcher[4062]: + local -l '_s=    @PREFIX@ {'
Jul 17 14:36:27 host nm-dispatcher[4062]: + _s='@prefix@ {'
Jul 17 14:36:27 host nm-dispatcher[4062]: + case $state in
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ minrtradvinterval 30; =~ ^}; ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ minrtradvinterval 30; =~ ^prefix ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ minrtradvinterval 30; =~ ^@prefix@ ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + read -r line
Jul 17 14:36:27 host nm-dispatcher[4062]: + lstrip line '    @PREFIX@ {'
Jul 17 14:36:27 host nm-dispatcher[4062]: + debug3 line '    @PREFIX@ {'
Jul 17 14:36:27 host nm-dispatcher[4062]: + :
Jul 17 14:36:27 host nm-dispatcher[4062]: + local -l '_s=    @PREFIX@ {'
Jul 17 14:36:27 host nm-dispatcher[4062]: + _s='@prefix@ {'
Jul 17 14:36:27 host nm-dispatcher[4062]: + _s='@prefix@ {'
Jul 17 14:36:27 host nm-dispatcher[4062]: + printf -v line %s '@prefix@ {'
Jul 17 14:36:27 host nm-dispatcher[4062]: + case $state in
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ @prefix@ { =~ ^}; ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ @prefix@ { =~ ^prefix ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ @prefix@ { =~ ^@prefix@ ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + '[' src '!=' src ']'
Jul 17 14:36:27 host nm-dispatcher[4062]: + verbose '    Found dynamic prefix'
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ -n '' ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + return 0
Jul 17 14:36:27 host nm-dispatcher[4062]: + [[ @prefix@ { =~ \{ ]]
Jul 17 14:36:27 host nm-dispatcher[4062]: + state=prefix
Jul 17 14:36:27 host nm-dispatcher[4062]: + prefix=dynamic
Jul 17 14:36:27 host nm-dispatcher[4062]: + valid=
Jul 17 14:36:27 host nm-dispatcher[4062]: req:6 'up' [eno2], "/etc/NetworkManager/dispatcher.d/95-radvd-gen": complete: failed with Script '/etc/NetworkManager/dispatcher.d/95-radvd-gen' exited with error status 1.

[arcivanov]

Same script generates successfully if running it directly from bash by hand.

[arcivanov]

Jul 17 15:22:26 host nm-dispatcher[6934]: Parsing src file "/etc/NetworkManager/radvd.conf.templ"
Jul 17 15:22:26 host nm-dispatcher[6934]: Found interface eno2
Jul 17 15:22:26 host nm-dispatcher[6934]: Found dynamic prefix
Jul 17 15:22:26 host nm-dispatcher[6934]: Adding dynamic valid= pref= decr=1 has_decr=
Jul 17 15:22:26 host nm-dispatcher[6934]: Looking for addresses on interfaces
Jul 17 15:22:26 host nm-dispatcher[6934]: Looking for prefixes on interface eno2
Jul 17 15:22:26 host nm-dispatcher[6934]: Looking for significant changes on interface eno2
Jul 17 15:22:26 host nm-dispatcher[6934]: No action required
Jul 17 15:22:26 host nm-dispatcher[6934]: req:4 'up' [eno1], "/etc/NetworkManager/dispatcher.d/95-radvd-gen": complete: failed with Script '/etc/NetworkManager/dispatcher.d/95-radvd-gen' exited with error status 1.
Jul 17 15:22:26 host nm-dispatcher[6934]: req:5 'connectivity-change': start running ordered scripts...
Jul 17 15:22:26 host NetworkManager[796]: <warn>  [1531855346.3806] dispatcher: (65) 95-radvd-gen failed (failed): Script '/etc/NetworkManager/dispatcher.d/95-radvd-gen' exited with error status 1.

Jul 17 15:22:26 host nm-dispatcher[6934]: No action required

Now this is not true. I don't have /etc/radvd.conf, so changes are required if file does not exist.

[arcivanov]

Also nmg_show_debug=3 does not seem to affect the actual 95-radvd-gen script at all.

[sshambar]

Yeah, the radvd-gen script doesn't use the nmutil utilities settings (I made it standalone, and submitted it to radvd :)

Hmm.. just tried with missing radvd.conf and bounced the interface, and radvd.conf was re-created. Could you post your template? (also, you can update 95-radvd-gen and set verbose=1, and even debug=1, in the script for a better idea of what's going on...)

[sshambar]

I see the reason for NM showing the error though.... last line of setup_radvd is

[ $debug -gt 2 ] && ds_dump

which causes it to return 1 by default... I'll push a fix for that :)

[arcivanov]

also, you can update 95-radvd-gen and set verbose=1, and even debug=1, in the script for a better idea of what's going on...

I did. :)

Could you post your template?

eno1 is WAN, eno2 is LAN

# cat radvd.conf.templ 
interface eno2 {
    AdvSendAdvert on;
    MinRtrAdvInterval 30;

    @PREFIX@
};

Also tried with @PREFIX@ {}. When running directly from shell by hand it generates /etc/radvd.conf and works. When undergoing service network restart and /etc/radvd.conf doesn't exist it fails.

[sshambar]

OK, there's definitely some bugs in the file parser (doesn't handle some interface options correctly, but don't appear to be related to your file above :)

Could you update the function lstrip() to use debug (rather than debug3) and post the output?

[arcivanov]

I was running with debug=3 already

[arcivanov]

let me send you the full one

[arcivanov]

While I'm getting this to you, I noticed that verbose=1 and debug=3 suppress these errors:

Jul 17 19:14:22 host nm-dispatcher[3989]: req:6 'up' [eno2], "/etc/NetworkManager/dispatcher.d/95-radvd-gen": complete: failed with Script '/etc/NetworkManager/dispatcher.d/95-radvd-gen' exited with error status 1.
Jul 17 19:14:22 host NetworkManager[797]: <warn>  [1531869262.5731] dispatcher: (38) 95-radvd-gen failed (failed): Script '/etc/NetworkManager/dispatcher.d/95-radvd-gen' exited with error status 1.

[arcivanov]

Hardcoded verbose=1, debug=3

Jul 17 19:16:17 host nm-dispatcher[4897]: read_file: src /etc/NetworkManager/radvd.conf.templ
Jul 17 19:16:17 host nm-dispatcher[4897]: Parsing src file "/etc/NetworkManager/radvd.conf.templ"
Jul 17 19:16:17 host nm-dispatcher[4897]: lstrip: line interface eno2 {
Jul 17 19:16:17 host nm-dispatcher[4897]: Found interface eno2
Jul 17 19:16:17 host nm-dispatcher[4897]: set_iface: eno2
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_nset: \IFACES\eno2=-
Jul 17 19:16:17 host nm-dispatcher[4897]: set_iface_key: eno2 src 1
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_nset: \IFACES\eno2\src=1
Jul 17 19:16:17 host nm-dispatcher[4897]: lstrip: line     AdvSendAdvert on;
Jul 17 19:16:17 host nm-dispatcher[4897]: lstrip: line     MinRtrAdvInterval 30;
Jul 17 19:16:17 host nm-dispatcher[4897]: lstrip: line
Jul 17 19:16:17 host nm-dispatcher[4897]: lstrip: line     @PREFIX@
Jul 17 19:16:17 host nm-dispatcher[4897]: Found dynamic prefix
Jul 17 19:16:17 host nm-dispatcher[4897]: set_dynamic: src eno2 dynamic   1
Jul 17 19:16:17 host nm-dispatcher[4897]: Adding dynamic valid= pref= decr=1 has_decr=
Jul 17 19:16:17 host nm-dispatcher[4897]: set_prefix: eno2 dynamic
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_nset: \IFACES\eno2\prefix\dynamic=-
Jul 17 19:16:17 host nm-dispatcher[4897]: set_prefix_key: eno2 dynamic src_decr 1
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_nset: \IFACES\eno2\prefix\dynamic\src_decr=1
Jul 17 19:16:17 host nm-dispatcher[4897]: set_iface_key: eno2 dynamic 1
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_nset: \IFACES\eno2\dynamic=1
Jul 17 19:16:17 host nm-dispatcher[4897]: set_iface_key: eno2 decr 1
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_nset: \IFACES\eno2\decr=1
Jul 17 19:16:17 host nm-dispatcher[4897]: set_prefix_key: eno2 dynamic decr 1
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_nset: \IFACES\eno2\prefix\dynamic\decr=1
Jul 17 19:16:17 host nm-dispatcher[4897]: lstrip: line };
Jul 17 19:16:17 host nm-dispatcher[4897]: read_file: cur /etc/radvd.conf
Jul 17 19:16:17 host nm-dispatcher[4897]: Looking for addresses on interfaces
Jul 17 19:16:17 host nm-dispatcher[4897]: get_iface: if 0
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_ngeti: \IFACES#0 => eno2
Jul 17 19:16:17 host nm-dispatcher[4897]: is_iface_key: eno2 dynamic
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_nget: \IFACES\eno2\dynamic => 1
Jul 17 19:16:17 host nm-dispatcher[4897]: Looking for prefixes on interface eno2
Jul 17 19:16:17 host nm-dispatcher[4897]: get_iface: if 1
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_ngeti: \IFACES#1 =>
Jul 17 19:16:17 host nm-dispatcher[4897]: get_iface: iface 0
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_ngeti: \IFACES#0 => eno2
Jul 17 19:16:17 host nm-dispatcher[4897]: check_iface: eno2
Jul 17 19:16:17 host nm-dispatcher[4897]: is_iface_key: eno2 src
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_nget: \IFACES\eno2\src => 1
Jul 17 19:16:17 host nm-dispatcher[4897]: Looking for significant changes on interface eno2
Jul 17 19:16:17 host nm-dispatcher[4897]: get_prefix: pfx eno2 0
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_ngeti: \IFACES\eno2\prefix#0 => dynamic
Jul 17 19:16:17 host nm-dispatcher[4897]: get_prefix: pfx eno2 1
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_ngeti: \IFACES\eno2\prefix#1 =>
Jul 17 19:16:17 host nm-dispatcher[4897]: get_iface: iface 1
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_ngeti: \IFACES#1 =>
Jul 17 19:16:17 host nm-dispatcher[4897]: ds_nget: \RESET =>
Jul 17 19:16:17 host nm-dispatcher[4897]: No action required
Jul 17 19:16:17 host nm-dispatcher[4897]: [547B blob data]

[sshambar]

yeah, as I mentioned above, the "[ $debug -gt 2 ] && ds_dump" in setup_radvd causes the function to return an error by default (if debug < 3 :)... that's an easy fix, the other issues I have to track down...

[sshambar]

OK, appears that when the script is run, there aren't any (non-local) ipv6 addresses on interface eno2... does

ip -6 addr show dev eno2 scope global

give you an prefix address?

[arcivanov]

That is correct. In the blank slate, eno2 is the LAN interface and has only link-local addresses. I'm using this package to get PD delegation and to acquire a delegated address that way. Currently there is a delegated interface address:

# ip -6 addr show dev eno2 scope global
3: eno2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 state UP qlen 1000
    inet6 2601:18a:xxxxxxxxx/64 scope global noprefixroute 
       valid_lft forever preferred_lft forever

[arcivanov]

This is reproducible 100% on service network restart, where the interfaces are cleared.

[sshambar]

I'm wondering if the dispatcher not called with the address is added to the interface?

I might be seeing something different as my test has a static ipv6 address in addition to the PD... I'll have to setup a VM to test the "blank slate" case to see if that's the issue.

[arcivanov]

I'm on CentOS 7 latest updates.

[arcivanov]

Would you like some variable dumps from the dispatcher?

[sshambar]

I was thinking along the lines of the output a dispatcher script similar to

ip -6 addr show dev eno2 scope global

(anonymized if you're concerned :)... that way I can see why the radvd-gen isn't seeing the delegated prefix (possibly still in duplicate address detect state?)

[arcivanov]

Sure, I'll put it into the script and dump it there.

[arcivanov]

Well, that's interesting:

Jul 18 13:57:14 host nm-dispatcher[8245]: Looking for prefixes on interface eno2
Jul 18 13:57:14 host nm-dispatcher[8245]: ip addr returned:
Jul 18 13:57:14 host nm-dispatcher[8245]: Looking for significant changes on interface eno2

Code in question:

check_iface() {
  # <iface>, look for changes on <iface>, true if differences
 ....
  verbose "ip addr returned: $(ip -6 addr show dev $if scope global)"
  verbose "Looking for significant changes on interface $if"

[sshambar]

Well, I'm still not sure why your dispatcher isn't triggering when a new prefix is added to the interface, but I've updated the radvd-gen to fix the other issues you found (should no longer always fail, and creates missing radvd.conf).

I also re-wrote the parser as I found it had several serious limitations handling nested options (and files w/o a trailing newline)... and fixed a few other issues i found.

Let me know if it makes things work a little better.

[arcivanov]

Thanks @sshambar! What about the above logs I sent? If it expected?

[arcivanov]

The file that is being generated is incomplete with latest master:

# cat /etc/radvd.conf 
interface eno2 {
    AdvSendAdvert on;
    MinRtrAdvInterval 30;

[arcivanov]

Jul 18 21:19:00 host nm-dispatcher[13181]: req:6 'up' [eno2]: start running ordered scripts...
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: src /etc/NetworkManager/radvd.conf.templ
Jul 18 21:19:00 host nm-dispatcher[13181]: Parsing src file "/etc/NetworkManager/radvd.conf.templ"
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: state=text prefix= sub=error end=error
Jul 18 21:19:00 host nm-dispatcher[13181]: lstrip: line interface eno2 {
Jul 18 21:19:00 host nm-dispatcher[13181]: Found interface eno2
Jul 18 21:19:00 host nm-dispatcher[13181]: set_iface: eno2
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nset: \IFACES\eno2=-
Jul 18 21:19:00 host nm-dispatcher[13181]: set_iface_key: eno2 src 1
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nset: \IFACES\eno2\src=1
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: state=interface prefix= sub=interface end=text
Jul 18 21:19:00 host nm-dispatcher[13181]: lstrip: line     AdvSendAdvert on;
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: state=interface prefix= sub=int_option end=text
Jul 18 21:19:00 host nm-dispatcher[13181]: lstrip: line     MinRtrAdvInterval 30;
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: state=interface prefix= sub=int_option end=text
Jul 18 21:19:00 host nm-dispatcher[13181]: lstrip: line
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: state=interface prefix= sub=int_option end=text
Jul 18 21:19:00 host nm-dispatcher[13181]: lstrip: line     @PREFIX@
Jul 18 21:19:00 host nm-dispatcher[13181]: Found dynamic prefix
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: state=interface prefix=dynamic sub=int_option end=text
Jul 18 21:19:00 host nm-dispatcher[13181]: lstrip: line };
Jul 18 21:19:00 host nm-dispatcher[13181]: set_dynamic: src eno2 dynamic   1
Jul 18 21:19:00 host nm-dispatcher[13181]: Adding dynamic valid= pref= decr=1 has_decr=
Jul 18 21:19:00 host nm-dispatcher[13181]: set_prefix: eno2 dynamic
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nset: \IFACES\eno2\prefix\dynamic=-
Jul 18 21:19:00 host nm-dispatcher[13181]: set_prefix_key: eno2 dynamic src_decr 1
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nset: \IFACES\eno2\prefix\dynamic\src_decr=1
Jul 18 21:19:00 host nm-dispatcher[13181]: set_iface_key: eno2 dynamic 1
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nset: \IFACES\eno2\dynamic=1
Jul 18 21:19:00 host nm-dispatcher[13181]: set_iface_key: eno2 decr 1
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nset: \IFACES\eno2\decr=1
Jul 18 21:19:00 host nm-dispatcher[13181]: set_prefix_key: eno2 dynamic decr 1
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nset: \IFACES\eno2\prefix\dynamic\decr=1
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: cur /etc/radvd.conf
Jul 18 21:19:00 host nm-dispatcher[13181]: Parsing cur file "/etc/radvd.conf"
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: state=text prefix= sub=error end=error
Jul 18 21:19:00 host nm-dispatcher[13181]: lstrip: line interface eno2 {
Jul 18 21:19:00 host nm-dispatcher[13181]: Found interface eno2
Jul 18 21:19:00 host nm-dispatcher[13181]: set_iface: eno2
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nset: \IFACES\eno2=-
Jul 18 21:19:00 host nm-dispatcher[13181]: set_iface_key: eno2 cur 1
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nset: \IFACES\eno2\cur=1
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: state=interface prefix= sub=interface end=text
Jul 18 21:19:00 host nm-dispatcher[13181]: lstrip: line     AdvSendAdvert on;
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: state=interface prefix= sub=int_option end=text
Jul 18 21:19:00 host nm-dispatcher[13181]: lstrip: line     MinRtrAdvInterval 30;
Jul 18 21:19:00 host nm-dispatcher[13181]: read_file: state=interface prefix= sub=int_option end=text
Jul 18 21:19:00 host nm-dispatcher[13181]: lstrip: line
Jul 18 21:19:00 host nm-dispatcher[13181]: Parse error in cur file "/etc/radvd.conf":4
Jul 18 21:19:00 host nm-dispatcher[13181]: Looking for addresses on interfaces
Jul 18 21:19:00 host nm-dispatcher[13181]: get_iface: if 0
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_ngeti: \IFACES#0 => eno2
Jul 18 21:19:00 host nm-dispatcher[13181]: is_iface_key: eno2 dynamic
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nget: \IFACES\eno2\dynamic => 1
Jul 18 21:19:00 host nm-dispatcher[13181]: Looking for prefixes on interface eno2
Jul 18 21:19:00 host nm-dispatcher[13181]: get_iface: if 1
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_ngeti: \IFACES#1 =>
Jul 18 21:19:00 host nm-dispatcher[13181]: get_iface: iface 0
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_ngeti: \IFACES#0 => eno2
Jul 18 21:19:00 host nm-dispatcher[13181]: check_iface: eno2
Jul 18 21:19:00 host nm-dispatcher[13181]: is_iface_key: eno2 src
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nget: \IFACES\eno2\src => 1
Jul 18 21:19:00 host nm-dispatcher[13181]: Looking for significant changes on interface eno2
Jul 18 21:19:00 host nm-dispatcher[13181]: get_prefix: pfx eno2 0
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_ngeti: \IFACES\eno2\prefix#0 => dynamic
Jul 18 21:19:00 host nm-dispatcher[13181]: get_prefix: pfx eno2 1
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_ngeti: \IFACES\eno2\prefix#1 =>
Jul 18 21:19:00 host nm-dispatcher[13181]: get_iface: iface 1
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_ngeti: \IFACES#1 =>
Jul 18 21:19:00 host nm-dispatcher[13181]: ds_nget: \RESET =>
Jul 18 21:19:00 host nm-dispatcher[13181]: No action required
Jul 18 21:19:00 host nm-dispatcher[13181]: [595B blob data]

[arcivanov]

Jul 18 21:19:00 host nm-dispatcher[13181]: Parse error in cur file "/etc/radvd.conf":4

[sshambar]

I'd expect a parse error with that file, but could you post the logs of radvd-gen creating the file? (remove the current ravd.conf, and re-run)... that way I can see why it's not generating the full file :)

[sshambar]

nevermind... I can re-produce the error... I'll see what's going on

[arcivanov]

Cool. It was the generated file that was incomplete.

[sshambar]

OK, a quick and dirty fix for the edge-case... hopefully this will work :)