icinga2 pki request does not invoke JSON RPC

[kbabioch]

I've noticed that getting certificates signed using the pki subcommand and the API on the master node, is unreliable and often times out. Invoking the same command multiple times will eventually work.

The basic setup looks like this. I'm not using any tickets here on purpose, to keep it as simple as possible.

Icinga 2 running on mon1 with api feature, which looks something like this:

• Install icinga2 on mon1
• Enable debuglog icinga2 feature enable debuglog
• Enable mainlog icinga2 feature enable mainlog
• Run icinga2 api setup
• Start icinga2

On the client node (client1), I'm essentially doing this:

• Install icinga2 on client1
• Create certificate and get it signed
  • icinga2 pki save-cert --host mon1 --trustedcert trusted-master.crt
  • icinga2 pki new-cert --cn client1 --key client1.key --cert client1.crt
  • icinga2 pki request --host mon1 --key client1.key --cert client1.crt --ca ca.crt --trustedcert trusted-master.crt

The last command seems to be not working reliable. Sometimes it works, sometimes it times out.

Expected Behavior

I expect to have a CSR request on the master node (icinga ca list), which I can then manually sign. On the client this looks something like this:

icinga2 pki request --host mon1 --key client1.key --cert client1.crt --ca ca.crt --trustedcert trusted-master.crt  -x debug
information/cli: Writing CA certificate to file 'ca.crt'.
information/cli: !!!!!!
information/cli: !!! Certificate request for CN 'client1' is pending. Waiting for approval from the parent Icinga instance.
information/cli: !!!!!!

On the server this is happening:

[2019-02-26 23:16:18 +0100] information/ApiListener: New client connection for identity 'client1' from [10.24.0.10]:45528 (certificate validation failed: code 18: self signed certificate)
[2019-02-26 23:16:18 +0100] notice/ApiListener: New JSON-RPC client
[2019-02-26 23:16:18 +0100] notice/WorkQueue: Spawning WorkQueue threads for 'JsonRpcConnection, #0'
[2019-02-26 23:16:18 +0100] notice/JsonRpcConnection: Received 'pki::RequestCertificate' message from 'client1'
[2019-02-26 23:16:18 +0100] information/JsonRpcConnection: Received certificate request for CN 'client1' not signed by our CA.
[2019-02-26 23:16:18 +0100] notice/WorkQueue: Spawning WorkQueue threads for 'ApiListener, RelayQueue'
[2019-02-26 23:16:18 +0100] information/JsonRpcConnection: Certificate request for CN 'client1' is pending. Waiting for approval.
[2019-02-26 23:16:18 +0100] notice/ApiListener: Relaying 'pki::RequestCertificate' message
[2019-02-26 23:16:18 +0100] warning/JsonRpcConnection: API client disconnected for identity 'client1'

Note that in this case, after the initial handshake the JSON RPC request for signing a certificate can be seen.

Current Behavior

Most of the time there will be no such request, though. The command simply times out on the client after 10 seconds, with the following error message:

icinga2 pki request --host mon1 --key client1.key --cert client1.crt --ca ca.crt --trustedcert trusted-master.crt  -x debug
notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 0ms; Threads: 4; Pool utilization: 0%
critical/cli: Could not fetch valid response. Please check the master log.

The debug log on the server looks like this:

[2019-02-26 23:11:12 +0100] information/ApiListener: New client connection for identity 'client' from [10.24.0.10]:45520 (certificate validation failed: code 18: self signed certificate)
[2019-02-26 23:11:12 +0100] notice/ThreadPool: Thread pool; current: 2; adjustment: -1
[2019-02-26 23:11:12 +0100] debug/ThreadPool: Killing worker thread.
[2019-02-26 23:11:16 +0100] notice/CheckerComponent: Pending checkables: 0; Idle checkables: 0; Checks/s: 0
[2019-02-26 23:11:20 +0100] notice/ThreadPool: Thread pool; current: 1; adjustment: 1
[2019-02-26 23:11:20 +0100] debug/ThreadPool: Spawning worker thread.
[2019-02-26 23:11:21 +0100] notice/CheckerComponent: Pending checkables: 0; Idle checkables: 0; Checks/s: 0
[2019-02-26 23:11:21 +0100] debug/ApiListener: Not connecting to Endpoint 'mon1' because that's us.
[2019-02-26 23:11:21 +0100] notice/ApiListener: Current zone master: mon1
[2019-02-26 23:11:21 +0100] notice/ApiListener: Connected endpoints: 
[2019-02-26 23:11:21 +0100] notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 0ms; Threads: 4; Pool utilization: 0.00321909%
[2019-02-26 23:11:22 +0100] notice/ThreadPool: Pool #2: Pending tasks: 0; Average latency: 0ms; Threads: 5; Pool utilization: 10.8781%
[2019-02-26 23:11:22 +0100] warning/ApiListener: No data received on new API connection for identity 'client'. Ensure that the remote endpoints are properly configured in a cluster setup.
Context:
        (0) Handling new API client connection

Note that after the initial handshare there is no JSON RPC request, and nothing seems to happen.

Possible Solution

Sometimes it helps to restart the server and re-running the same command multiple times. Usually it will work after a couple of times.

Context

I've initially stumbled upon this bug, since the icinga2 node wizard command was not working for me in some cases. I could narrow it down to the instructions mentioned above.

Your Environment

• Operating System and version: 2.10.2 on Arch Linux

[Al2Klimov]

Hello @kbabioch and thank you for reporting!

It sounds like we've already done the solution for your problem.
I'll let you test snapshot packages as soon as the solution have been merged into master.

Best,
AK

[kbabioch]

Ok, just let me know if there is something for me to test. I'm really interested in what is causing this ;-).

[Al2Klimov]

This issue seems to have been addressed by #7005.

[dnsmichi]

@kbabioch snapshot packages are available, in order to test please follow the instructions at https://icinga.com/docs/icinga2/snapshot/doc/21-development/#snapshot-packages-nightly-builds

[dnsmichi]

I consider this being fixed with 2.11.