error: Unable to start server (community 3.18.0)

[Beto]

I installed community 3.18.0 and masterfiles 3.18.0.  cf-serverd fails with the  message in the subject and exits with rc 1, which I can't find documented.  No other errors appear in verbose output.

Anyone got a clue?  TIA

[craig.c...@northern.tech]

Can you include some basic information like OS name/version? Thanks!

Yes. This is likely a known issue we are working through right now.

Please remove or comment out this section of policy and try again.

https://github.com/cfengine/masterfiles/blob/3.18.x/controls/cf_serverd.cf#L73-L77

If it still fails, please start cf-serverd with strace

```

strace /var/cfengine/bin/cf-serverd -F

```

Hopefully the policy fix resolves the issue for you.

-Craig

[Beto]

That did it.  Thanks, Craig!

[Beto]

Oh btw this is RHEL7.

[craig.c...@northern.tech]

Perfect. Thank you. The issue is with the bind interface of "::" aka ipv6 wildcard address, if this fails then we don't fall back to ipv4.

Do you by chance have ipv6 disabled? I would suspect the answer is yes but would like to know for sure.

Thanks,

Craig

[craig.c...@northern.tech]

I created a public ticket so that community users can find the issue and apply the workaround.

https://tracker.mender.io/browse/CFE-3704

Cheers,

Craig

[Beto]

Yes sir, ipv6 is disabled..

On Wednesday, July 7, 2021 at 1:19:45 PM UTC-5 craig.c...@northern.tech wrote:

[Beto]

ut-oh, may have popped the cork a bit too quick.  Now cf-execd fails to start.  Looking at cf-execd.service, it contains the text of a symlink:

root@baker1 [cfengine3.service.wants]# cd /usr/lib/systemd/system/

root@baker1 [system]# ll cf*

-rw-r--r--. 1 root root  462 Jun 23 10:53 cf-apache.service

-rw-r--r--. 1 root root  864 Jun 23 10:53 cfengine3.service

-rw-r--r--. 1 root root  101 Jul  7 09:28 cf-execd.service

-rw-r--r--. 1 root root  443 Jun 23 10:53 cf-hub.service

-rw-r--r--. 1 root root  358 Jun 23 10:53 cf-monitord.service

-rw-r--r--. 1 root root 1150 Jun 23 10:53 cf-postgres.service

-rw-r--r--. 1 root root  664 Jun 23 10:53 cf-runalerts.service

-rw-r--r--. 1 root root  437 Jun 23 10:53 cf-serverd.service

root@baker1 [system]# cat cf-execd.service 

lrwxrwxrwx. 1 root root 40 Dec  8  2017 cf-execd.service -> /usr/lib/systemd/system/cf-execd.service

So I replaced this with cf-execd.service from github but still not working.  This is from the journal:

systemd: Cannot add dependency job for unit cf-execd.service, ignoring: Unit is not loaded properly: Invalid argument.

[craig.c...@northern.tech]

I checked an install of community on centos-7 and it would seem that the package is not corrupt but that somehow your cf-execd.service file did become corrupt.

```

cf-remote spawn --platform centos-7-x64 --count 1 --role client --name cent7

cf-remote --version 3.18.0 install --edition community --clients cent7

```

I bootstrap and seem to have no issues.

```

# grep cf-server /var/log/messages

...

Jul  8 14:15:58 ip-172-31-18-118 cf-serverd: notice: Server is starting...
Jul  8 14:15:58 ip-172-31-18-118 cf-serverd[11219]: CFEngine(server)  Server is starting...

```

Can you include the text of your cf-execd.service file?

Thanks,

Craig

[Beto]

root@baker1 [cfengine3.service.wants]# cat cf-execd.service 

[Unit]

Description=CFEngine Enterprise Execution Scheduler

After=syslog.target

ConditionPathExists=@bindir@/cf-execd

ConditionPathExists=@workdir@/inputs/promises.cf

PartOf=cfengine3.service

[Service]

Type=simple

ExecStart=@bindir@/cf-execd --no-fork

Restart=always

RestartSec=10

KillMode=process

[Install]

WantedBy=multi-user.target

WantedBy=cfengine3.service

[Beto]

I removed and reinstalled cfengine-community 3.18.0 and that seems to have fixed the cf-execd issue.  Weird.

[Beto]

Now I see this:

root@baker1 [outputs]# r ps

ps -ef|grep c[f]-

root      7878 22661  0 12:50 ?        00:00:00 [cf-execd] <defunct>

root     22660     1  1 11:59 ?        00:00:44 /var/cfengine/bin/cf-monitord --no-fork

root     22661     1  0 11:59 ?        00:00:00 /var/cfengine/bin/cf-execd --no-fork

root     22662     1  0 11:59 ?        00:00:00 /var/cfengine/bin/cf-serverd --no-fork

Which may be a result of this: (?)

root@baker1 [outputs]# cat previous 

   error: Could not open database txn /var/cfengine/state/cf_lock.lmdb: Invalid argument

[Beto]

The defunct cf-execd process goes away after a short period of time.  It reappears after the cf-agent process ends.  But now there is nothing logged in /var/cfengine/ouputs after multiple runs, although I know for a fact cf-agent did perform updates.

[Beto]

For fun  I stopped cfengine, wiped everything in /var/cfengine/state and restarted it.  Still nothing gets written to /var/cfengine/outputs although cf-agent did perform updates.  The last entry (which was from earlier today) is still

error: Could not open database txn /var/cfengine/state/cf_lock.lmdb: Invalid argument

Any ideas?

[craig.c...@northern.tech]

The "cf_lock.lmdb: Invalid argument" is a known issue that shouldn't have too big of an impact. Mostly it occurs infrequently during bootstrap and no other time.

In regards to nothing in /var/cfengine/outputs, do you get anything logged if you do "cf-agent --no-lock"? cf-execd should be running cf-agent with default logging level of notice and above (critical, error and warning) so if a manual agent run with default logging doesn't output anything, nothing would be in outputs. If nothing is output from the agent run then a file will not be created.

A couple of things to debug the situation:

grep cf-execd /var/log/messages

or

systemctl stop cf-execd
/var/cfengine/bin/cf-execd --no-fork --verbose | less /tmp/cf-execd-verbose.log

or adding a simple report to your policy like in services/main.cf simply add

reports:

  "agent run at ${sys.date}";

As that should definitely be present in logs in /var/cfengine/outputs.

[Beto]

Well it did eventually log something:

root@baker1 [outputs]# cat previous 

   error: Could not open database txn /var/cfengine/state/cf_lock.lmdb: Invalid argument

   error: Unable to create 'last.snmpd.files.comment.copy_from_name.copy_from.servers.source.-baker1._srv_sysadmin_etc_persistent_snmpd_conf_8154_MD5=4c4718f83137308551d4b6c0c0c6af0f'. (create: Resource temporarily unavailable)

The only entries in /var/log/message are from before I removed/reinstalled cfengine.  Nothing since.

root@baker1 [outputs]# grep cf-execd /var/log/messages

Jul  8 07:54:16 baker1.dcpds.cpms.osd.mil systemd: Cannot add dependency job for unit cf-execd.service, ignoring: Unit is not loaded properly: Invalid argument.

Jul  8 11:56:45 baker1.dcpds.cpms.osd.mil systemd: [/usr/lib/systemd/system/cf-execd.service:4] Path in condition not absolute, ignoring: @bindir@/cf-execd

Jul  8 11:56:45 baker1.dcpds.cpms.osd.mil systemd: [/usr/lib/systemd/system/cf-execd.service:5] Path in condition not absolute, ignoring: @workdir@/inputs/promises.cf

Jul  8 11:56:45 baker1.dcpds.cpms.osd.mil systemd: [/usr/lib/systemd/system/cf-execd.service:10] Executable path is not absolute, ignoring: @bindir@/cf-execd --no-fork

Jul  8 11:56:45 baker1.dcpds.cpms.osd.mil systemd: cf-execd.service lacks both ExecStart= and ExecStop= setting. Refusing.

I updated main.cf and it DID log it.

root@baker1 [outputs]# cat previous 

R: agent run at Thu Jul  8 15:00:37 2021

Color me confused.

[Beto]

More confused.  I ran cf-agent --no-lock and the only output I got was the the date from main.cf.  Then I ran cf-agent -I --no-lock and I got thousand of lines of 'info' level loggings for stuff that was not modified and did not need modification.  Here's a tiny example of the output:

<snip>

    info: Inserted the promised line '#' into '/etc/audit/auditd.conf' after locator

    info: insert_lines promise '#' repaired

    info: Inserted the promised line '# This file controls the configuration of the audit daemon' into '/etc/audit/auditd.conf' after locator

    info: insert_lines promise '# This file controls the configuration of the audit daemon' repaired

    info: Inserted the promised line '#' into '/etc/audit/auditd.conf' after locator

    info: insert_lines promise '#' repaired

    info: Inserted the promised line '' into '/etc/audit/auditd.conf' after locator

    info: insert_lines promise '' repaired

    info: Inserted the promised line 'log_file = /var/log/audit/audit.log' into '/etc/audit/auditd.conf' after locator

    info: insert_lines promise 'log_file = /var/log/audit/audit.log' repaired

    info: Inserted the promised line 'log_format = RAW' into '/etc/audit/auditd.conf' after locator

</snip>

What the heck?

[vratislav...@northern.tech]

On Thu, 2021-07-08 at 13:23 -0700, Beto wrote:
> More confused.  I ran cf-agent --no-lock and the only output I got was the the date from main.cf. 
> Then I ran cf-agent -I --no-lock and I got thousand of lines of 'info' level loggings for stuff that
> was not modified and did not need modification.  Here's a tiny example of the output:
>
> <snip>
>     info: Inserted the promised line '#' into '/etc/audit/auditd.conf' after locator
>     info: insert_lines promise '#' repaired
>     info: Inserted the promised line '# This file controls the configuration of the audit daemon'
> into '/etc/audit/auditd.conf' after locator
>     info: insert_lines promise '# This file controls the configuration of the audit daemon' repaired
>     info: Inserted the promised line '#' into '/etc/audit/auditd.conf' after locator
>     info: insert_lines promise '#' repaired
>     info: Inserted the promised line '' into '/etc/audit/auditd.conf' after locator
>     info: insert_lines promise '' repaired
>     info: Inserted the promised line 'log_file = /var/log/audit/audit.log' into
> '/etc/audit/auditd.conf' after locator
>     info: insert_lines promise 'log_file = /var/log/audit/audit.log' repaired
>     info: Inserted the promised line 'log_format = RAW' into '/etc/audit/auditd.conf' after locator
> </snip>
>
> What the heck?

That's another known issue [1], actually. It's just harmless noise, but it can be annoying. Nothing
is being done in the system, CFEngine just overly informs about what it is doing *internally*.

[1] https://tracker.mender.io/browse/CFE-3708

--
Vratislav

[Beto]

Ok - good to know, thanks. This is a show stopper for us as we rely heavily on /var/log/outputs and this creates log files of several thousand lines every 5 minutes.  We'll need to wait for 3.18.1