Bug 1649877

Summary: init script does not tell errors via correct syslog level
Product: Red Hat Enterprise Linux 7 Reporter: Tomas Dolezal <todoleza>
Component: ipsetAssignee: Stefano Brivio <sbrivio>
Status: CLOSED ERRATA QA Contact: Tomas Dolezal <todoleza>
Severity: medium Docs Contact: Marc Muehlfeld <mmuehlfe>
Priority: medium    
Version: 7.6CC: fgiudici, jmaxwell, pasik, sbrivio, todoleza
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: ipset-7.1-1 Doc Type: Bug Fix
Doc Text:
.Error logging in the `ipset` service has been improved Previously, the `ipset` service did not report configuration errors with a meaningful severity in the `systemd` logs. The severity level for invalid configuration entries was only `informational`, and the service did not report errors for an unusable configuration. As a consequence, it was difficult for administrators to identify and troubleshoot issues in the `ipset` service's configuration. With this update, `ipset` reports configuration issues as `warnings` in `systemd` logs and, if the service fails to start, it logs an entry with the `error` severity including further details. As a result, it is now easier to troubleshoot issues in the configuration of the `ipset` service.
Story Points: ---
Clone Of:
: 1683711 (view as bug list) Environment:
Last Closed: 2019-08-06 13:00:07 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1654714, 1709731    

Description Tomas Dolezal 2018-11-14 16:47:56 UTC
Description of problem:
Since release 6.38 the initscript started using configuration files in a directory without proper checking whether they are correctly applied.
Previously, any configuration error resulted in a failed service start.

The error is also not referring to any specific plase, there should be a pointer to file or command where the failure has occurred.

With unreliable (ref bz1649836) output of initscript on stderr/stdout, it would be safer to emit service failure. The service, if not running (or unsuccessfully started) it should be in failed state anyway.

(!) As seen bellow with '0file', configuration error may cause incomplete/none sets to be loaded while the service has successfully started.

There should be a filter for files so that custom backups or other files could reside in directory with configuration. currently all 'save' files have .set suffix, this could be the filter along with ignoring directories.

Version-Release number of selected component (if applicable):
ipset-6.38-3.el7_6.x86_64
ipset-6.38-2.el7.x86_64

How reproducible:
always

Steps to Reproduce:
ipset restore <<EOF
create asetlist list:set size 8
create set1 hash:net,port family inet hashsize 65536 maxelem 262144 counters
create set2 hash:net,port,net family inet hashsize 65536 maxelem 262144 counters
add asetlist set1
add asetlist set2
EOF
service ipset save
service ipset restart
systemctl status -l 

mkdir /etc/sysconfig/ipset.d/0dir
service ipset restart
systemctl status -l

echo 'add invalid entry' > /etc/sysconfig/ipset.d/0file
service ipset restart
systemctl status -l

Actual results:
>for unpatched -2 release:
● ipset.service - IP sets for iptables
   Loaded: loaded (/usr/lib/systemd/system/ipset.service; disabled; vendor preset: disabled)
   Active: active (exited) since Wed 2018-11-14 11:38:18 EST; 2s ago
  Process: 24377 ExecStop=/usr/libexec/ipset/ipset.start-stop stop (code=exited, status=0/SUCCESS)
  Process: 24388 ExecStart=/usr/libexec/ipset/ipset.start-stop start (code=exited, status=0/SUCCESS)
 Main PID: 24388 (code=exited, status=0/SUCCESS)

Nov 14 11:38:18 host-8-251-5.host.centralci.eng.rdu2.redhat.com systemd[1]: Stopped IP sets for iptables.
Nov 14 11:38:18 host-8-251-5.host.centralci.eng.rdu2.redhat.com systemd[1]: Starting IP sets for iptables...
Nov 14 11:38:18 host-8-251-5.host.centralci.eng.rdu2.redhat.com ipset.start-stop[24388]: ipset v6.38: Error in line 2: Set to be added/deleted/tested as element does not exist.
Nov 14 11:38:18 host-8-251-5.host.centralci.eng.rdu2.redhat.com ipset.start-stop[24388]: ipset: Failed to restore configured sets
Nov 14 11:38:18 host-8-251-5.host.centralci.eng.rdu2.redhat.com systemd[1]: Started IP sets for iptables.


>ipset-6.38-3.el7_6.x86_64 with 0dir:
● ipset.service - IP sets for iptables
   Loaded: loaded (/usr/lib/systemd/system/ipset.service; disabled; vendor preset: disabled)
   Active: active (exited) since Wed 2018-11-14 11:40:10 EST; 1min 2s ago
  Process: 24477 ExecStop=/usr/libexec/ipset/ipset.start-stop stop (code=exited, status=0/SUCCESS)
  Process: 24488 ExecStart=/usr/libexec/ipset/ipset.start-stop start (code=exited, status=0/SUCCESS)
 Main PID: 24488 (code=exited, status=0/SUCCESS)

Nov 14 11:40:10 host-8-251-5.host.centralci.eng.rdu2.redhat.com systemd[1]: Stopped IP sets for iptables.
Nov 14 11:40:10 host-8-251-5.host.centralci.eng.rdu2.redhat.com systemd[1]: Starting IP sets for iptables...
Nov 14 11:40:10 host-8-251-5.host.centralci.eng.rdu2.redhat.com ipset.start-stop[24488]: head: error reading ‘/etc/sysconfig/ipset.d/0dir’: Is a directory
Nov 14 11:40:10 host-8-251-5.host.centralci.eng.rdu2.redhat.com ipset.start-stop[24488]: tail: error reading ‘/etc/sysconfig/ipset.d/0dir’: Is a directory
Nov 14 11:40:10 host-8-251-5.host.centralci.eng.rdu2.redhat.com systemd[1]: Started IP sets for iptables.

>ipset-6.38-3.el7_6.x86_64 with 0dir and 0file:
>NO IPSETS ARE LOADED
● ipset.service - IP sets for iptables
   Loaded: loaded (/usr/lib/systemd/system/ipset.service; disabled; vendor preset: disabled)
   Active: active (exited) since Wed 2018-11-14 11:42:21 EST; 11s ago
  Process: 24526 ExecStop=/usr/libexec/ipset/ipset.start-stop stop (code=exited, status=0/SUCCESS)
  Process: 24537 ExecStart=/usr/libexec/ipset/ipset.start-stop start (code=exited, status=0/SUCCESS)
 Main PID: 24537 (code=exited, status=0/SUCCESS)

Nov 14 11:42:21 host-8-251-5.host.centralci.eng.rdu2.redhat.com systemd[1]: Stopped IP sets for iptables.
Nov 14 11:42:21 host-8-251-5.host.centralci.eng.rdu2.redhat.com systemd[1]: Starting IP sets for iptables...
Nov 14 11:42:21 host-8-251-5.host.centralci.eng.rdu2.redhat.com ipset.start-stop[24537]: head: error reading ‘/etc/sysconfig/ipset.d/0dir’: Is a directory
Nov 14 11:42:21 host-8-251-5.host.centralci.eng.rdu2.redhat.com ipset.start-stop[24537]: tail: error reading ‘/etc/sysconfig/ipset.d/0dir’: Is a directory
Nov 14 11:42:21 host-8-251-5.host.centralci.eng.rdu2.redhat.com ipset.start-stop[24537]: ipset v6.38: Error in line 1: The set with the given name does not exist
Nov 14 11:42:21 host-8-251-5.host.centralci.eng.rdu2.redhat.com ipset.start-stop[24537]: ipset: Failed to restore configured sets
Nov 14 11:42:21 host-8-251-5.host.centralci.eng.rdu2.redhat.com systemd[1]: Started IP sets for iptables.


Expected results:
ipset-6.29-1.el7.x86_64:
● ipset.service - IP sets for iptables
   Loaded: loaded (/usr/lib/systemd/system/ipset.service; disabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Tue 2018-11-13 14:01:07 EST; 2s ago
  Process: 21405 ExecStop=/usr/libexec/ipset/ipset.start-stop stop (code=exited, status=0/SUCCESS)
  Process: 21414 ExecStart=/usr/libexec/ipset/ipset.start-stop start (code=exited, status=1/FAILURE)
 Main PID: 21414 (code=exited, status=1/FAILURE)

Nov 13 14:01:07 host-8-240-104.host.centralci.eng.rdu2.redhat.com systemd[1]: Stopped IP sets for iptables.
Nov 13 14:01:07 host-8-240-104.host.centralci.eng.rdu2.redhat.com systemd[1]: Starting IP sets for iptables...
Nov 13 14:01:07 host-8-240-104.host.centralci.eng.rdu2.redhat.com ipset.start-stop[21414]: ipset v6.29: Error in line 1: The set with the given name does not exist
Nov 13 14:01:07 host-8-240-104.host.centralci.eng.rdu2.redhat.com systemd[1]: ipset.service: main process exited, code=exited, status=1/FAILURE
Nov 13 14:01:07 host-8-240-104.host.centralci.eng.rdu2.redhat.com systemd[1]: Failed to start IP sets for iptables.
Nov 13 14:01:07 host-8-240-104.host.centralci.eng.rdu2.redhat.com systemd[1]: Unit ipset.service entered failed state.
Nov 13 14:01:07 host-8-240-104.host.centralci.eng.rdu2.redhat.com systemd[1]: ipset.service failed.


Additional info:

Comment 4 Tomas Dolezal 2018-11-14 17:23:53 UTC
ref bug 1649836 comment 4:
As msekletar suggested, journalctl --sync should be used before the script ends with newer kernel/systemd to prevent journal loosing connection of produced output with the ipset.service

Comment 9 Tomas Dolezal 2018-11-15 18:52:49 UTC
as per comment 6 and irc communication, i've created bug 1650297 for issue with errors in configuration preventing a best-effort load of the correct rest of it.

this bug is to fix logging in a way that messages are shown with correct level of 'error' in journal of associated 'ipset.service' systemd service.

the service also should fail if the sets are not correctly loaded, but this is yet to be decided.

Comment 20 errata-xmlrpc 2019-08-06 13:00:07 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2019:2158