[ntp] traceback during ntp start due to 'MGMT_VRF_CONFIG' is not defined

[stepanblyschak]

Description

Steps to reproduce the issue:

1. Usual start flow

Describe the results you received:

Sep 25 14:54:01.468793 r-boxer-sw01 INFO ntp[14876]: Starting NTP server: ntpdTraceback (most recent call last):
Sep 25 14:54:01.469503 r-boxer-sw01 INFO ntp[14876]:   File "/usr/local/bin/sonic-cfggen", line 294, in <module>
Sep 25 14:54:01.470163 r-boxer-sw01 INFO ntp[14876]:     main()
Sep 25 14:54:01.470726 r-boxer-sw01 INFO ntp[14876]:   File "/usr/local/bin/sonic-cfggen", line 272, in main
Sep 25 14:54:01.471243 r-boxer-sw01 INFO ntp[14876]:     print(template.render(data))
Sep 25 14:54:01.471729 r-boxer-sw01 INFO ntp[14876]:   File "/usr/local/lib/python2.7/dist-packages/jinja2/environment.py", line 1008, in render
Sep 25 14:54:01.472269 r-boxer-sw01 INFO ntp[14876]:     return self.environment.handle_exception(exc_info, True)
Sep 25 14:54:01.472759 r-boxer-sw01 INFO ntp[14876]:   File "/usr/local/lib/python2.7/dist-packages/jinja2/environment.py", line 780, in handle_exception
Sep 25 14:54:01.473245 r-boxer-sw01 INFO ntp[14876]:     reraise(exc_type, exc_value, tb)
Sep 25 14:54:01.473778 r-boxer-sw01 INFO ntp[14876]:   File "<template>", line 1, in top-level template code
Sep 25 14:54:01.474272 r-boxer-sw01 INFO ntp[14876]:   File "/usr/local/lib/python2.7/dist-packages/jinja2/environment.py", line 411, in getitem
Sep 25 14:54:01.474754 r-boxer-sw01 INFO ntp[14876]:     return obj[argument]
Sep 25 14:54:01.475234 r-boxer-sw01 INFO ntp[14876]: jinja2.exceptions.UndefinedError: 'MGMT_VRF_CONFIG' is undefined

Describe the results you expected:

no traceback

Additional information you deem important (e.g. issue happens only occasionally):

**Output of `show version`:**

```
(paste your output here)
```

**Attach debug file `sudo generate_dump`:**

```
(paste your output here)
```

[wangxin]

Observed similar issue of generating /etc/ntp.conf:

Oct 12 02:32:00.094083 arc-mtbc-1001 INFO systemd[1]: Starting Update NTP configuration...
Oct 12 02:32:00.209883 arc-mtbc-1001 INFO swss#supervisord: start.sh vrfmgrd: started
Oct 12 02:32:00.322427 arc-mtbc-1001 NOTICE swss#swssconfig: :- main: Loading config from JSON file:/etc/swss/config.d/ipinip.json...
Oct 12 02:32:00.336533 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:51,295 INFO success: rsyslogd entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Oct 12 02:32:00.336610 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:51,907 INFO spawned: 'orchagent' with pid 41
Oct 12 02:32:00.336653 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:52,910 INFO success: orchagent entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Oct 12 02:32:00.336692 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:53,731 INFO spawned: 'restore_neighbors' with pid 53
Oct 12 02:32:00.336730 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:53,734 INFO success: restore_neighbors entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
Oct 12 02:32:00.336768 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:55,129 INFO spawned: 'portsyncd' with pid 64
Oct 12 02:32:00.336805 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:55,671 INFO exited: restore_neighbors (exit status 0; expected)
Oct 12 02:32:00.336843 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:56,675 INFO success: portsyncd entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Oct 12 02:32:00.336880 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:56,973 INFO spawned: 'neighsyncd' with pid 71
Oct 12 02:32:00.336916 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:57,985 INFO success: neighsyncd entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Oct 12 02:32:00.336953 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:58,386 INFO spawned: 'swssconfig' with pid 74
Oct 12 02:32:00.336991 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:58,391 INFO success: swssconfig entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
Oct 12 02:32:00.337384 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:31:59,185 INFO spawned: 'vrfmgrd' with pid 81
Oct 12 02:32:00.337449 arc-mtbc-1001 INFO swss#supervisord 2019-10-12 02:32:00,198 INFO success: vrfmgrd entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Oct 12 02:32:00.561151 arc-mtbc-1001 NOTICE swss#vlanmgrd: :- main: --- Starting vlanmgrd ---
Oct 12 02:32:00.561151 arc-mtbc-1001 NOTICE swss#vlanmgrd: :- loadRedisScript: lua script loaded, sha: 88270a7c5c90583e56425aca8af8a4b8c39fe757
Oct 12 02:32:00.597154 arc-mtbc-1001 WARNING systemd-udevd[6200]: Could not generate persistent MAC address for Bridge: No such file or directory
Oct 12 02:32:00.617378 arc-mtbc-1001 WARNING systemd-udevd[6214]: Could not generate persistent MAC address for dummy0: No such file or directory
Oct 12 02:32:00.627136 arc-mtbc-1001 WARNING systemd-udevd[6213]: Could not generate persistent MAC address for dummy: No such file or directory
Oct 12 02:32:00.628582 arc-mtbc-1001 INFO kernel: [   47.099531] Bridge: port 1(dummy) entered blocking state
Oct 12 02:32:00.628602 arc-mtbc-1001 INFO kernel: [   47.099533] Bridge: port 1(dummy) entered disabled state
Oct 12 02:32:00.628604 arc-mtbc-1001 INFO kernel: [   47.100151] device dummy entered promiscuous mode
Oct 12 02:32:00.631874 arc-mtbc-1001 NOTICE swss#vlanmgrd: :- main: starting main loop
Oct 12 02:32:00.863677 arc-mtbc-1001 INFO ntp-config.sh[6160]: Traceback (most recent call last):
Oct 12 02:32:00.864333 arc-mtbc-1001 INFO ntp-config.sh[6160]:   File "/usr/local/bin/sonic-cfggen", line 263, in <module>
Oct 12 02:32:00.864827 arc-mtbc-1001 INFO ntp-config.sh[6160]:     main()
Oct 12 02:32:00.865289 arc-mtbc-1001 INFO ntp-config.sh[6160]:   File "/usr/local/bin/sonic-cfggen", line 239, in main
Oct 12 02:32:00.865804 arc-mtbc-1001 INFO ntp-config.sh[6160]:     template = env.get_template(template_file)
Oct 12 02:32:00.866260 arc-mtbc-1001 INFO ntp-config.sh[6160]:   File "/usr/local/lib/python2.7/dist-packages/jinja2/environment.py", line 830, in get_template
Oct 12 02:32:00.866712 arc-mtbc-1001 INFO ntp-config.sh[6160]:     return self._load_template(name, self.make_globals(globals))
Oct 12 02:32:00.867158 arc-mtbc-1001 INFO ntp-config.sh[6160]:   File "/usr/local/lib/python2.7/dist-packages/jinja2/environment.py", line 804, in _load_template
Oct 12 02:32:00.867763 arc-mtbc-1001 INFO ntp-config.sh[6160]:     template = self.loader.load(self, name, globals)
Oct 12 02:32:00.868240 arc-mtbc-1001 INFO ntp-config.sh[6160]:   File "/usr/local/lib/python2.7/dist-packages/jinja2/loaders.py", line 125, in load
Oct 12 02:32:00.868772 arc-mtbc-1001 INFO ntp-config.sh[6160]:     code = environment.compile(source, name, filename)
Oct 12 02:32:00.869241 arc-mtbc-1001 INFO ntp-config.sh[6160]:   File "/usr/local/lib/python2.7/dist-packages/jinja2/environment.py", line 591, in compile
Oct 12 02:32:00.869701 arc-mtbc-1001 INFO ntp-config.sh[6160]:     self.handle_exception(exc_info, source_hint=source_hint)
Oct 12 02:32:00.870163 arc-mtbc-1001 INFO ntp-config.sh[6160]:   File "/usr/local/lib/python2.7/dist-packages/jinja2/environment.py", line 780, in handle_exception
Oct 12 02:32:00.870663 arc-mtbc-1001 INFO ntp-config.sh[6160]:     reraise(exc_type, exc_value, tb)
Oct 12 02:32:00.871143 arc-mtbc-1001 INFO ntp-config.sh[6160]:   File "/usr/share/sonic/templates/ntp.conf.j2", line 38, in template
Oct 12 02:32:00.872282 arc-mtbc-1001 INFO ntp-config.sh[6160]:     {% for (name, prefix) in LOOPBACK_INTERFACE|pfx_filter %}
Oct 12 02:32:00.872784 arc-mtbc-1001 INFO ntp-config.sh[6160]: jinja2.exceptions.TemplateAssertionError: no filter named 'pfx_filter'
Oct 12 02:32:00.910284 arc-mtbc-1001 INFO systemd[1]: Stopping LSB: Start NTP daemon...
Oct 12 02:32:00.929488 arc-mtbc-1001 NOTICE ntpd[1714]: ntpd exiting on signal 15 (Terminated)

As a result, the /etc/ntp.conf file is empty.

[kannankvs]

@stepanblyschak : We checked this issue.
Following is the result from our analysis.

1. This issue is observed in latest master image also.
2. Traceback will be seen when MGMT_VRF_CONFIG does not exist in the database. Traceback is coming from the script “/etc/init.d/ntp”.
3. Traceback does not affect the NTP functionality with/without management VRF. When MGMT_VRF_CONFIG does not exist or when MGMT_VRF_CONFIG’s mgmtVrfEnabled is configured to “false”, “NTP” will be started in the “default VRF” context, which is working fine even with this traceback.
4. This traceback error will be hidden by redirecting the error to /dev/null without affecting functionality.
5. In file “files/image_config/ntp/ntp”, line “vrfEnabled=$(/usr/local/bin/sonic-cfggen -d -v 'MGMT_VRF_CONFIG["vrf_global"]["mgmtVrfEnabled"]' )” is changed to “vrfEnabled=$(/usr/local/bin/sonic-cfggen -d -v 'MGMT_VRF_CONFIG["vrf_global"]["mgmtVrfEnabled"]' 2> /dev/null)” to resolve this.
6. PR3745 has been raised for the same.

[kannankvs]

@wangxin The issue that you have reported is not related to this issue reported by @stepanblyschak . The traceback that you see is related to LOOPBACK_INTERFACE|pfx_filter which is not related to management VRF. Also, the issue is not observed in the recent master images. Request you to kindly recheck the issue and raise a new issue if it still exist.