frr icon indicating copy to clipboard operation
frr copied to clipboard

"Extended Logging Target" broken/not working

Open corubba opened this issue 1 year ago • 7 comments

Describe the bug

PR #8458 added the "Extended Logging Target", which can be used for logging to syslog and/or journald among other things. As the doc for the log syslog option states the "Extended Logging Target" is the recommended way for logging to syslog. I was however unable to get it to work on a fresh Debian 12 installation, neither with the packages provided in the FRR Debian repo nor with self-built ones. The only configuration I changed after installing the package is frr.conf to the following:

no log stdout
no log syslog

log extended mytarget
  destination journald

Starting FRR using the systemd service unit results in the following log output in journald. Note the Unknown command lines.

Feb 02 00:39:03 anycast systemd[1]: Starting frr.service - FRRouting...
Feb 02 00:39:03 anycast frrinit.sh[34984]: Starting watchfrr with command: '  /usr/lib/frr/watchfrr  -d  -F traditional   zebra mgmtd staticd'.
Feb 02 00:39:04 anycast watchfrr[34993]: [T83RR-8SM5G] watchfrr 9.2-dev starting: vty@0
Feb 02 00:39:04 anycast watchfrr[34993]: [ZCJ3S-SPH5S] zebra state -> down : initial connection attempt failed
Feb 02 00:39:04 anycast watchfrr[34993]: [ZCJ3S-SPH5S] mgmtd state -> down : initial connection attempt failed
Feb 02 00:39:04 anycast watchfrr[34993]: [ZCJ3S-SPH5S] staticd state -> down : initial connection attempt failed
Feb 02 00:39:04 anycast watchfrr[34993]: [YFT0P-5Q5YX] Forked background command [pid 34994]: /usr/lib/frr/watchfrr.sh restart all
Feb 02 00:39:04 anycast frrinit.sh[35004]: 2024/02/02 00:39:04 ZEBRA: [NNACN-54BDA][EC 4043309110] Disabling MPLS support (no kernel support)
Feb 02 00:39:04 anycast frrinit.sh[35027]: [35027|mgmtd] sending configuration
Feb 02 00:39:04 anycast frrinit.sh[35028]: [35028|zebra] sending configuration
Feb 02 00:39:04 anycast frrinit.sh[35027]: line 4: % Unknown command[4]: log extended mytarget
Feb 02 00:39:04 anycast frrinit.sh[35027]: line 5: % Unknown command[4]:   destination journald
Feb 02 00:39:04 anycast frrinit.sh[35027]: [35027|mgmtd] Configuration file[/etc/frr/frr.conf] processing failure: 2
Feb 02 00:39:04 anycast frrinit.sh[35028]: line 4: % Unknown command[4]: log extended mytarget
Feb 02 00:39:04 anycast frrinit.sh[35028]: line 5: % Unknown command[4]:   destination journald
Feb 02 00:39:04 anycast frrinit.sh[35028]: [35028|zebra] Configuration file[/etc/frr/frr.conf] processing failure: 2
Feb 02 00:39:04 anycast frrinit.sh[35042]: [35042|watchfrr] sending configuration
Feb 02 00:39:04 anycast frrinit.sh[35044]: [35044|staticd] sending configuration
Feb 02 00:39:04 anycast frrinit.sh[35042]: line 4: % Unknown command[4]: log extended mytarget
Feb 02 00:39:04 anycast frrinit.sh[35042]: line 5: % Unknown command[4]:   destination journald
Feb 02 00:39:04 anycast watchfrr[34993]: [VTVCM-Y2NW3] Configuration Read in Took: 00:00:00
Feb 02 00:39:04 anycast frrinit.sh[35042]: [35042|watchfrr] Configuration file[/etc/frr/frr.conf] processing failure: 2
Feb 02 00:39:04 anycast frrinit.sh[35044]: line 4: % Unknown command[4]: log extended mytarget
Feb 02 00:39:04 anycast frrinit.sh[35044]: line 5: % Unknown command[4]:   destination journald
Feb 02 00:39:04 anycast frrinit.sh[35026]: Waiting for children to finish applying config...
Feb 02 00:39:04 anycast frrinit.sh[35044]: [35044|staticd] Configuration file[/etc/frr/frr.conf] processing failure: 2
Feb 02 00:39:04 anycast watchfrr[34993]: [ZJW5C-1EHNT] restart all process 34994 exited with non-zero status 2
Feb 02 00:39:08 anycast watchfrr[34993]: [QDG3Y-BY5TN] mgmtd state -> up : connect succeeded
Feb 02 00:39:08 anycast watchfrr[34993]: [QDG3Y-BY5TN] zebra state -> up : connect succeeded
Feb 02 00:39:09 anycast watchfrr[34993]: [QDG3Y-BY5TN] staticd state -> up : connect succeeded
Feb 02 00:39:09 anycast watchfrr[34993]: [KWE5Q-QNGFC] all daemons up, doing startup-complete notify
Feb 02 00:39:09 anycast frrinit.sh[34984]: Started watchfrr.
Feb 02 00:39:09 anycast systemd[1]: Started frr.service - FRRouting.

These log extended commands are also not available when starting an interactive vtysh.

I read the developer documentation and did some debugging, but couldn't figure out why this isn't working. clippy does find/show it as log extended-syslog, which is expected because that's what the sourcecode defines. The command matcher should still be able to correctly match it because it is still unambigious, but it doesn't. The inconsistency between doc and source exists already in the original PR. The commands are also missing from the command graph, which might indicate they are not properly registered/installed.

At least I could confirm that the described upgrade to native journald using log stdout is working.

  • [x] Did you check if this is a duplicate issue?
  • [x] Did you test it on the latest FRRouting/frr master branch?

To Reproduce

  1. Install FRR v9+ using a Debian package
  2. Adjust frr.conf to include a log extended command, like the doc suggest
  3. Start FRR as a systemd service

Expected behavior

FRR should start, and properly read and apply the "Extended Logging Target" configuration.

Versions

  • OS Version: Debian 12.4 "bookworm"
  • Kernel: 6.1.0-17-amd64
  • FRR Version: 9.0.1-0~deb12u1, 9.1-0~deb12u1, 9.2~dev-1 built from 9d8fd14b

corubba avatar Feb 02 '24 01:02 corubba

This issue is stale because it has been open 180 days with no activity. Comment or remove the autoclose label in order to avoid having this issue closed.

github-actions[bot] avatar Aug 01 '24 01:08 github-actions[bot]

This issue will be automatically closed in the specified period unless there is further activity.

frrbot[bot] avatar Aug 01 '24 01:08 frrbot[bot]

Issue still reproducible on Debian "bookworm" 12.6 (Kernel 6.1.0-23-amd64), with both FRR 9.1.1 and 10.0.1 from the FRR debian mirror.

corubba avatar Aug 02 '24 20:08 corubba

This issue will no longer be automatically closed.

frrbot[bot] avatar Aug 02 '24 20:08 frrbot[bot]

Also not available in 10.1.1, nor on master@HEAD as of 20 Sep 2024, on any version. Not even the official Docker images.

Cerebus avatar Sep 23 '24 13:09 Cerebus

It looks to me like the command isn't defined for vtysh at all; there's no trace of it in vtysh.c. EXTLOG_NODE is defined, DEFPY_NOSH for the node is in zlog_5424_cli.c, but there's no EXTLOG_NODE in vtysh.c.

Cerebus avatar Sep 23 '24 14:09 Cerebus

There is a compilation error without VTYSH_LIB defined. After adding VTYSH_LIB in vtysh.h, compilation through. Further vtysh execution failed because EXTLOG_NODE is not defined in vtysh.c

Is it ok to release these errors as released 10.1 Version!!!!!!!

Manikandaprab avatar Oct 07 '24 11:10 Manikandaprab