test_listening_ports failure on Focal #5635

kushaldas · 2020-11-17T10:20:27Z

Description

Steps to Reproduce

molecule test -s libvirt-staging-focal

Expected Behavior

All tests should pass

Actual Behavior

    __________ test_listening_ports[ansible://mon-staging-ossec_service1] __________                                                                                                                      [126/1908]
    [gw1] linux -- Python 3.7.3 /root/code/securedrop/.venv/bin/python3                                                                                                                                             
                                                                                                                                                                                                                    
    host = <testinfra.host.Host ansible://mon-staging>                                                                                                                                                              
    ossec_service = {'host': '0.0.0.0', 'listening': True, 'port': 1514, 'proto': 'udp'}                                                                                                                            
                                                                                                                                                                                                                    
        @pytest.mark.skip_in_prod                                                                                                                                                                                   
        @pytest.mark.parametrize('ossec_service', [                                                                                                                                                                 
            dict(host="0.0.0.0", proto="tcp", port=22, listening=True),                                                                                                                                             
            dict(host="0.0.0.0", proto="udp", port=1514, listening=True),                                                                                                                                           
            dict(host="0.0.0.0", proto="tcp", port=1515, listening=False),                                                                                                                                          
        ])                                                                                                                                                                                                          
        def test_listening_ports(host, ossec_service):                                                                                                                                                              
            """                                                                                                                                                                                                     
            Ensure the OSSEC-related services are listening on the                                                                                                                                                  
            expected sockets. Services to check include ossec-remoted                                                                                                                                               
            and ossec-authd. Helper services such as postfix are checked                                                                                                                                            
            separately.                                                                                                                                                                                             
                                                                                                                                                                                                                    
            Note that the SSH check will fail if run against a prod host, due                                                                                                                                       
            to the SSH-over-Tor strategy. We can port the parametrized values                                                                                                                                       
            to config test YAML vars at that point.                                                                                                                                                                 
            """                                                                                                                                                                                                     
            socket = "{proto}://{host}:{port}".format(**ossec_service)                                                                                                                                              
            with host.sudo():                                                                                                                                                                                       
                # Really hacky work-around for bug found in testinfra 1.12.0                                                                                                                                        
                # https://github.com/philpep/testinfra/issues/311                                                                                                                                                   
                if "udp" in socket:                                                                                                                                                                                 
                    lsof_socket = "{proto}@{host}:{port}".format(**ossec_service)                                                                                                                                   
                    udp_check = host.run("lsof -n -i"+lsof_socket)                                                                                                                                                  
                                                                                                                                                                                                                    
                    if ossec_service['listening']:                                                                                                                                                                  
    >                   assert udp_check.rc == 0                                                                                                                                                                    
    E                   assert 1 == 0                                                                                                                                                                               
    E                     +1
    E                     -0

    ../testinfra/mon/test_mon_network.py:76: AssertionError

The text was updated successfully, but these errors were encountered:

kushaldas · 2020-11-19T11:37:41Z

From mon-staging

root@mon-staging:/home/vagrant# systemctl status ossec
● ossec.service
     Loaded: loaded (/etc/init.d/ossec; generated)
     Active: inactive (dead)
       Docs: man:systemd-sysv-generator(8)
root@mon-staging:/home/vagrant# /etc/init.d/ossec 
*** Usage: /etc/init.d/ossec {start|stop|restart|status|force-reload}
root@mon-staging:/home/vagrant# /etc/init.d/ossec statrt
*** Usage: /etc/init.d/ossec {start|stop|restart|status|force-reload}
root@mon-staging:/home/vagrant# /etc/init.d/ossec start
Starting OSSEC HIDS v3.6.0...
Started ossec-maild...
Started ossec-execd...
Started ossec-analysisd...
Started ossec-logcollector...
Started ossec-remoted...
Started ossec-syscheckd...
Started ossec-monitord...
Completed.
root@mon-staging:/home/vagrant# /etc/init.d/ossec status
ossec-monitord is running...
ossec-logcollector is running...
ossec-remoted is running...
ossec-syscheckd is running...
ossec-analysisd is running...
ossec-maild is running...
ossec-execd not running...
root@mon-staging:/home/vagrant# lsof -n | grep 1514
ossec-rem 1058                         ossecr    4u     IPv6              19272      0t0        UDP *:1514 
ossec-rem 1058 1060 ossec-rem          ossecr    4u     IPv6              19272      0t0        UDP *:1514 
ossec-rem 1058 1061 ossec-rem          ossecr    4u     IPv6              19272      0t0        UDP *:1514

Now have to figure out why the service is not starting. Digging into it.

kushaldas · 2020-11-24T13:51:47Z

There is nothing wrong in the ansible roles.

 Nov 24 11:34:45 mon-staging python3[3965]: ansible-command Invoked with _raw_params=/etc/init.d/ossec restart warn=True _uses_shell=False stdin_add_newline=True strip_empty_ends=True argv=None chdir=None executab
le=None creates=None removes=None stdin=None

If I start the service via /etc/init.d/ossec start, it shows running, but then the test fail on the same server. If I login and check the status again, it is dead.

Looking at the systemd log, I can find:

Nov 24 11:34:41 mon-staging ossec[3796]: OSSEC HIDS v3.6.0 Stopped
Nov 24 11:34:41 mon-staging systemd[1]: ossec.service: Succeeded.
Nov 24 11:34:41 mon-staging systemd[1]: Stopped ossec.service.

Digging more on why systemd and ossec are not friends, I found this blog post explaining issue, and how to use service templates to solve our issue.

After manually adding the service file and restarting the service, now things are running on the mon-staging. Our test still fails.
Verified that the port is open via both nmap and lsof.

root@mon-staging:/home/vagrant# nmap -sU -p 1000-2000 127.0.0.1
Starting Nmap 7.80 ( https://nmap.org ) at 2020-11-24 12:12 UTC
Nmap scan report for localhost (127.0.0.1)
Host is up (0.0000060s latency).
Not shown: 1000 closed ports
PORT     STATE         SERVICE
1514/udp open|filtered fujitsu-dtcns

Nmap done: 1 IP address (1 host up) scanned in 1.29 seconds

root@mon-staging:/home/vagrant# lsof -n -i
COMMAND    PID            USER   FD   TYPE     DEVICE SIZE/OFF NODE NAME
systemd      1            root   39u  IPv4       3666      0t0  TCP *:sunrpc (LISTEN)
systemd      1            root   40u  IPv4       3667      0t0  UDP *:sunrpc 
systemd      1            root   41u  IPv6       3668      0t0  TCP *:sunrpc (LISTEN)
systemd      1            root   42u  IPv6       3669      0t0  UDP *:sunrpc 
systemd-n  415 systemd-network   20u  IPv4 1062446837      0t0  UDP 192.168.121.55:bootpc 
rpcbind    588            _rpc    4u  IPv4       3666      0t0  TCP *:sunrpc (LISTEN)
rpcbind    588            _rpc    5u  IPv4       3667      0t0  UDP *:sunrpc 
rpcbind    588            _rpc    6u  IPv6       3668      0t0  TCP *:sunrpc (LISTEN)
rpcbind    588            _rpc    7u  IPv6       3669      0t0  UDP *:sunrpc 
systemd-r  591 systemd-resolve   12u  IPv4       9817      0t0  UDP 127.0.0.53:domain 
systemd-r  591 systemd-resolve   13u  IPv4       9820      0t0  TCP 127.0.0.53:domain (LISTEN)
ntpd       808             ntp   16u  IPv6      12359      0t0  UDP *:ntp 
ntpd       808             ntp   17u  IPv4      12362      0t0  UDP *:ntp 
ntpd       808             ntp   18u  IPv4      12366      0t0  UDP 127.0.0.1:ntp 
ntpd       808             ntp   19u  IPv4      12368      0t0  UDP 192.168.121.55:ntp 
ntpd       808             ntp   20u  IPv4      12370      0t0  UDP 10.0.1.3:ntp 
ntpd       808             ntp   21u  IPv6      12374      0t0  UDP [fe80::5054:ff:fe90:9922]:ntp 
ntpd       808             ntp   25u  IPv6      13182      0t0  UDP [fe80::5054:ff:fe2e:334b]:ntp 
sshd       833            root    3u  IPv4      12718      0t0  TCP *:ssh (LISTEN)
ossec-rem 1074          ossecr    4u  IPv6      15130      0t0  UDP *:1514

Now, if modify the actual test command to lsof -n -i udp:1514, the command just works. I will wait for the standup to discuss this and then work on a patch.

kushaldas · 2020-11-26T09:46:54Z

This is log from the app-staging even if the server is running in the mon server.

2020/11/26 09:02:44 ossec-agentd: INFO: Trying to connect to server 10.0.1.3, port 1514.
2020/11/26 09:02:44 INFO: Connected to 10.0.1.3 at address 10.0.1.3, port 1514
2020/11/26 09:02:44 ossec-agentd: DEBUG: agt->sock: 131
2020/11/26 09:03:05 ossec-agentd(4101): WARN: Waiting for server reply (not started). Tried: '10.0.1.3'.
2020/11/26 09:15:07 ossec-agentd: INFO: Trying to connect to server 10.0.1.3, port 1514.
2020/11/26 09:15:07 INFO: Connected to 10.0.1.3 at address 10.0.1.3, port 1514
2020/11/26 09:15:07 ossec-agentd: DEBUG: agt->sock: 134
2020/11/26 09:15:28 ossec-agentd(4101): WARN: Waiting for server reply (not started). Tried: '10.0.1.3'.
2020/11/26 09:27:48 ossec-agentd: INFO: Trying to connect to server 10.0.1.3, port 1514.
2020/11/26 09:27:48 INFO: Connected to 10.0.1.3 at address 10.0.1.3, port 1514
2020/11/26 09:27:48 ossec-agentd: DEBUG: agt->sock: 137
2020/11/26 09:28:09 ossec-agentd(4101): WARN: Waiting for server reply (not started). Tried: '10.0.1.3'.
2020/11/26 09:40:47 ossec-agentd: INFO: Trying to connect to server 10.0.1.3, port 1514.
2020/11/26 09:40:47 INFO: Connected to 10.0.1.3 at address 10.0.1.3, port 1514
2020/11/26 09:40:47 ossec-agentd: DEBUG: agt->sock: 140
2020/11/26 09:41:08 ossec-agentd(4101): WARN: Waiting for server reply (not started). Tried: '10.0.1.3'.

kushaldas · 2020-11-26T09:48:54Z

From the mon-staging:

2020/11/26 04:37:14 ossec-syscheckd(1124): ERROR: Could not rename file '/etc/systemd/system/dbus-org.freedesktop.timesync1.service' to '/var/ossec/queue/diff/local/etc/systemd/system/dbus-org.freedesktop.timesync1.service/last-entry' due to [(2)-(No such file or directory)].
2020/11/26 04:37:16 ossec-syscheckd(1124): ERROR: Could not rename file '/etc/systemd/system/sysinit.target.wants/systemd-timesyncd.service' to '/var/ossec/queue/diff/local/etc/systemd/system/sysinit.target.wants/systemd-timesyncd.service/last-entry' due to [(2)-(No such file or directory)].
2020/11/26 04:37:36 ossec-syscheckd(1124): ERROR: Could not rename file '/etc/resolvconf/resolv.conf.d/original' to '/var/ossec/queue/diff/local/etc/resolvconf/resolv.conf.d/original/last-entry' due to [(2)-(No such file or directory)].
2020/11/26 04:46:25 ossec-syscheckd: INFO: Real time file monitoring started.
2020/11/26 04:46:25 ossec-syscheckd: INFO: Finished creating syscheck database (pre-scan completed).
2020/11/26 04:46:37 ossec-syscheckd: INFO: Ending syscheck scan (forwarding database).
2020/11/26 04:46:57 rootcheck: INFO: Starting rootcheck scan.
2020/11/26 04:50:59 rootcheck: INFO: Ending rootcheck scan.
2020/11/26 05:00:59 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 05:13:08 ossec-syscheckd: INFO: Ending syscheck scan.
2020/11/26 05:28:08 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 05:40:17 ossec-syscheckd: INFO: Ending syscheck scan.
2020/11/26 05:55:17 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 06:07:25 ossec-syscheckd: INFO: Ending syscheck scan.
2020/11/26 06:22:25 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 06:34:34 ossec-syscheckd: INFO: Ending syscheck scan.
2020/11/26 06:49:34 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 07:01:43 ossec-syscheckd: INFO: Ending syscheck scan.
2020/11/26 07:16:43 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 07:28:51 ossec-syscheckd: INFO: Ending syscheck scan.
2020/11/26 07:43:51 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 07:56:00 ossec-syscheckd: INFO: Ending syscheck scan.
2020/11/26 08:11:00 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 08:23:09 ossec-syscheckd: INFO: Ending syscheck scan.
2020/11/26 08:38:09 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 08:50:17 ossec-syscheckd: INFO: Ending syscheck scan.
2020/11/26 09:00:18 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 09:12:26 ossec-syscheckd: INFO: Ending syscheck scan.
2020/11/26 09:27:26 ossec-syscheckd: INFO: Starting syscheck scan.
2020/11/26 09:39:35 ossec-syscheckd: INFO: Ending syscheck scan.

kushaldas · 2020-11-26T10:13:50Z

From the app-staging:

root@app-staging:/home/vagrant# nmap -p 1514 -sU 10.0.1.3
Starting Nmap 7.80 ( https://nmap.org ) at 2020-11-26 10:12 UTC
Nmap scan report for mon-staging (10.0.1.3)
Host is up (0.00036s latency).

PORT     STATE         SERVICE
1514/udp open|filtered fujitsu-dtcns
MAC Address: 52:54:00:90:99:22 (QEMU virtual NIC)

Nmap done: 1 IP address (1 host up) scanned in 0.40 seconds

Tried to verify to make sure that we are following the guide from upstream.

kushaldas · 2020-11-26T11:01:25Z

root@app-staging:/home/vagrant# /var/ossec/bin/ossec-control enable debug
Usage: /var/ossec/bin/ossec-control {start|stop|reload|restart|status}

But https://ossec-docs.readthedocs.io/en/latest/docs/programs/ossec-control.html says it is there :(
Update:

works on mon-staging, but no service is with -d because systemd service :(

emkll · 2020-11-26T14:42:46Z

If you look at /var/ossec/alerts/alert.log on the mon server, you will be able to confirm if the logs are flowing to the mon server, if you see any app entries in there, that means the logs are being sent

The errors

2020/11/26 04:37:14 ossec-syscheckd(1124): ERROR: Could not rename file '/etc/systemd/system/dbus-org.freedesktop.timesync1.service' to '/var/ossec/queue/diff/local/etc/systemd/system/dbus-org.freedesktop.timesync1.service/last-entry' due to [(2)-(No such file or directory)].
2020/11/26 04:37:16 ossec-syscheckd(1124): ERROR: Could not rename file '/etc/systemd/system/sysinit.target.wants/systemd-timesyncd.service' to '/var/ossec/queue/diff/local/etc/systemd/system/sysinit.target.wants/systemd-timesyncd.service/last-entry' due to [(2)-(No such file or directory)].

Look like generic error when starting a service.

On mon, /var/ossec/bin/list-agents -c will return you all the active agents, to confirm (or not) if the agent is connected.

2020/11/26 09:40:47 INFO: Connected to 10.0.1.3 at address 10.0.1.3, port 1514
2020/11/26 09:40:47 ossec-agentd: DEBUG: agt->sock: 140
2020/11/26 09:41:08 ossec-agentd(4101): WARN: Waiting for server reply (not started). Tried: '10.0.1.3'

This looks like the agent is running correctly, but the mon server isn't receiving the message.

In other words, looks like the agent is working, but the server is getting killed. This seems to corroborate your initial hypothesis the ossec services on mon are being killed, other than that it looks like most functionality is working.

@kushaldas can you please push your systemd changes to the working branch, it will help in debugging the issue.

kushaldas · 2020-11-26T15:58:58Z

I am yet to move the systemd changes into the ansible role as I was doing debugging by hand. I will do so in the morning, and push here.

kushaldas · 2020-12-01T04:19:02Z

The work is getting done on the #5638 PR.

emkll · 2020-12-09T16:41:54Z

Closed via #5638

kushaldas mentioned this issue Dec 1, 2020

Add staging-with-rebase-focal to CI and fix testinfra tests #5638

Merged

9 tasks

emkll closed this as completed Dec 9, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test_listening_ports failure on Focal #5635

test_listening_ports failure on Focal #5635

kushaldas commented Nov 17, 2020

kushaldas commented Nov 19, 2020

kushaldas commented Nov 24, 2020

kushaldas commented Nov 26, 2020

kushaldas commented Nov 26, 2020

kushaldas commented Nov 26, 2020 •

edited

Loading

kushaldas commented Nov 26, 2020 •

edited

Loading

emkll commented Nov 26, 2020

kushaldas commented Nov 26, 2020

kushaldas commented Dec 1, 2020

emkll commented Dec 9, 2020

test_listening_ports failure on Focal #5635

test_listening_ports failure on Focal #5635

Comments

kushaldas commented Nov 17, 2020

Description

Steps to Reproduce

Expected Behavior

Actual Behavior

kushaldas commented Nov 19, 2020

kushaldas commented Nov 24, 2020

kushaldas commented Nov 26, 2020

kushaldas commented Nov 26, 2020

kushaldas commented Nov 26, 2020 • edited Loading

kushaldas commented Nov 26, 2020 • edited Loading

emkll commented Nov 26, 2020

kushaldas commented Nov 26, 2020

kushaldas commented Dec 1, 2020

emkll commented Dec 9, 2020

kushaldas commented Nov 26, 2020 •

edited

Loading

kushaldas commented Nov 26, 2020 •

edited

Loading