Certificate request from satellite over and over again

Icinga 2
1

I have Icinga on Linux monitoring about 50 clients no problem- they’re all about the same. One of them I added today is having a problem. Setting up the client worked fine, no certificate errors or anything, and I checked the zone file configuration, it looks fine.

The monitors I have set up for this one node works fine, but over and over again in the debug log on the master I see these messages:

On master:

[2020-03-25 17:43:55 -0700] information/ApiListener: Finished sending runtime config updates for endpoint '<CLIENT>' in zone '<CLIENT>'.
[2020-03-25 17:43:55 -0700] notice/JsonRpcConnection: Received 'icinga::Hello' message from identity '<CLIENT>'.
[2020-03-25 17:43:55 -0700] notice/JsonRpcConnection: Received 'pki::RequestCertificate' message from identity '<CLIENT>'.
[2020-03-25 17:43:55 -0700] information/JsonRpcConnection: Received certificate request for CN '<CLIENT>' signed by our CA.
[2020-03-25 17:43:55 -0700] information/JsonRpcConnection: The certificate for CN '<CLIENT>' is valid and uptodate. Skipping automated renewal.

On the client, I keep seeing these messages over and over. What should I check next? I’ve tried reinstalling icinga a couple of times on the client but it does the same thing. Everything has been working fine for months, it’s just this one client that’s having a problem. We haven’t made any changes and I’ve restarted the master and client multiple times.

On client:

[2020-03-25 17:43:55 -0700] information/ApiListener: Syncing runtime objects to endpoint '<MASTER>'.
[2020-03-25 17:43:55 -0700] information/ApiListener: Finished syncing runtime objects to endpoint '<MASTER>'.
[2020-03-25 17:43:55 -0700] information/ApiListener: Finished sending runtime config updates for endpoint '<MASTER>' in zone 'master'.
[2020-03-25 17:43:55 -0700] information/ApiListener: Sending replay log for endpoint '<MASTER>' in zone 'master'.
[2020-03-25 17:43:55 -0700] notice/ApiListener: Replaying log: /var/lib/icinga2/api/log/current
[2020-03-25 17:43:55 -0700] notice/ApiListener: Replayed 0 messages.
[2020-03-25 17:43:55 -0700] notice/ApiListener: Replaying log: /var/lib/icinga2/api/log/current
[2020-03-25 17:43:55 -0700] notice/ApiListener: Replayed 0 messages.
[2020-03-25 17:43:55 -0700] information/ApiListener: Finished sending replay log for endpoint '<MASTER>' in zone 'master'.
[2020-03-25 17:43:55 -0700] information/ApiListener: Finished syncing endpoint '<MASTER>' in zone 'master'.
[2020-03-25 17:43:55 -0700] information/ApiListener: Finished reconnecting to endpoint '<MASTER>' via host '<MASTER>' and port '5665'
[2020-03-25 17:43:55 -0700] notice/JsonRpcConnection: Received 'config::Update' message from identity '<MASTER>'.
[2020-03-25 17:43:55 -0700] information/ApiListener: Applying config update from endpoint '<MASTER>' of zone 'master'.
[2020-03-25 17:43:55 -0700] information/ApiListener: Received configuration updates (0) from endpoint '<MASTER>' do not qualify for production, not triggering reload.
[2020-03-25 17:43:56 -0700] notice/JsonRpcConnection: Error while reading JSON-RPC message for identity '<MASTER>': Error: short read


        (0) icinga2: icinga::JsonRpc::ReadMessage(std::shared_ptr<icinga::AsioTlsStream> const&, boost::asio::basic_yield_context<boost::asio::executor_binder<void (*)(), boost::asio::executor> >, long) (+0x95) [0x92e165]
        (1) icinga2: icinga::JsonRpcConnection::HandleIncomingMessages(boost::asio::basic_yield_context<boost::asio::executor_binder<void (*)(), boost::asio::executor> >) (+0xf4) [0xbc26e4]
        (2) /usr/lib64/icinga2/sbin/icinga2() [0xbc2e51]
        (3) libboost_context.so.1.69.0: make_fcontext (+0x2f) [0x7f18605ba18f]



[2020-03-25 17:43:56 -0700] warning/JsonRpcConnection: API client disconnected for identity '<MASTER>'
[2020-03-25 17:43:56 -0700] warning/ApiListener: Removing API client for endpoint '<MASTER>'. 0 API clients left.
[2020-03-25 17:43:56 -0700] debug/EndpointDbObject: update is_connected=0 for endpoint '<MASTER>'
[2020-03-25 17:44:00 -0700] notice/CheckerComponent: Pending checkables: 0; Idle checkables: 0; Checks/s: 0
[2020-03-25 17:44:05 -0700] notice/CheckerComponent: Pending checkables: 0; Idle checkables: 0; Checks/s: 0
[2020-03-25 17:44:05 -0700] notice/ApiListener: Updating object authority for objects at endpoint '<CLIENT>'.
[2020-03-25 17:44:05 -0700] debug/ApiListener: Not connecting to Endpoint '<CLIENT>' because that's us.
[2020-03-25 17:44:05 -0700] information/ApiListener: Reconnecting to endpoint '<MASTER>' via host '<MASTER>' and port '5665'
[2020-03-25 17:44:05 -0700] notice/ApiListener: Current zone master: <CLIENT>
[2020-03-25 17:44:05 -0700] notice/ApiListener: Connected endpoints:
[2020-03-25 17:44:05 -0700] information/ApiListener: New client connection for identity '<MASTER>' to [10.125.0.213]:5665
[2020-03-25 17:44:05 -0700] notice/ApiListener: New JSON-RPC client

My config:

Icinga2 2.11.2-1
icinga2 feature list
Disabled features: compatlog debuglog elasticsearch gelf graphite influxdb livestatus opentsdb perfdata statusdata syslog
Enabled features: api checker command ido-mysql mainlog notification

icinga2 daemon -C
[2020-03-25 17:48:46 -0700] information/cli: Icinga application loader (version: 2.11.2-1)
[2020-03-25 17:48:46 -0700] information/cli: Loading configuration file(s).
[2020-03-25 17:48:46 -0700] information/ConfigItem: Committing config item(s).
[2020-03-25 17:48:46 -0700] information/ApiListener: My API identity: <MASTER>
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 1 FileLogger.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 3 NotificationCommands.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 1 NotificationComponent.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 235 Notifications.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 1 IcingaApplication.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 4 HostGroups.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 52 Hosts.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 8 Downtimes.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 1 CheckerComponent.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 54 Zones.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 52 Endpoints.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 1 ExternalCommandListener.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 1 ApiUser.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 1 UserGroup.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 1 ApiListener.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 1 IdoMysqlConnection.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 239 CheckCommands.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 3 TimePeriods.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 1 User.
[2020-03-25 17:48:46 -0700] information/ConfigItem: Instantiated 285 Services.
[2020-03-25 17:48:46 -0700] information/ScriptGlobal: Dumping variables to file '/var/cache/icinga2/icinga2.vars'
[2020-03-25 17:48:46 -0700] information/cli: Finished validating the configuration file(s).
2

Hi Chris,

Welcome to our Community. Thanks for sharing the problem you seem to encounter with us.
As far as i can tell from the information you gave us the most unusual thing you encounter at the moment is the re-occuring ‘info’ log of the certificate check-non-renewal.

This is a completly normal message, the only unusual thing i see here is that it fills the logfile.

Is it possible to upgrade from 2.11.2-1 to 2.11.3 on the systems … also i see that an error ‘Error while reading JSON-RPC message for identity’ is the connection unstable between the system and the master ?

Maybe you can share some more information about the system with us

Regards

David

1 Like
3

Thanks for your reply. I ran the diagnostics script (attached) and didn’t see much, and connectivity between the node and the master seems fine otherwise.

It is actually causing a problem- the load on the monitored client seems to make my monitors time out even if I set the monitored interval long. It’s strange, there are many nodes with exactly the same config and networking setup and this is the only node with the problem.

Do recommend upgrading Icinga2?

diag-out.txt (2.1 KB)

4

Hi Chris,

Sure we recommend the upgrade, we had a large json/rpc issue and it seems like your node is busy with itself logging the whole certificate renewal stuff.

There is no incompatibility between the 2.11.2 and the 2.11.3 so it doesn’t hurt to upgrade the system to see if it fixes that behaviour.
I think it is worth a try.

Regards

David

5

I have upgraded my clients and master to 2.11.3, but I am still having problems with one of the monitored clients we have. We have gone so far as to not only upgrade Icinga but reinstall the node from our golden image. I am still getting these messages many times a minute on the client:

[2020-04-08 14:20:48 -0700] debug/Checkable: Update checkable 'd0014.hpc.edu!http' with check interval '60' from last check time at 2020-04-08 14:20:48 -0700 (1.58638e+09) to next check time at 2020-04-08 14:21:45 -0700 (1.58638e+09).
[2020-04-08 14:20:48 -0700] notice/ApiListener: Relaying 'event::SetNextCheck' message
[2020-04-08 14:20:48 -0700] notice/ApiListener: Sending message 'event::SetNextCheck' to 'hpc-monitoring.hpc.edu'
[2020-04-08 14:20:48 -0700] notice/ApiListener: Relaying 'event::CheckResult' message
[2020-04-08 14:20:48 -0700] notice/ApiListener: Sending message 'event::CheckResult' to 'hpc-monitoring.hpc.edu'
[2020-04-08 14:20:49 -0700] notice/JsonRpcConnection: Error while reading JSON-RPC message for identity 'hpc-monitoring.hpc.edu': Error: End of file


        (0) icinga2: icinga::JsonRpc::ReadMessage(std::shared_ptr<icinga::AsioTlsStream> const&, boost::asio::basic_yield_context<boost::asio::executor_binder<void (*)(), boost::asio::executor> >, long) (+0x95) [0x951b45]
        (1) icinga2: icinga::JsonRpcConnection::HandleIncomingMessages(boost::asio::basic_yield_context<boost::asio::executor_binder<void (*)(), boost::asio::executor> >) (+0xf4) [0xb89fe4]
        (2) /usr/lib64/icinga2/sbin/icinga2() [0xb8a5da]
        (3) /usr/lib64/icinga2/sbin/icinga2() [0xb8aab8]
        (4) libboost_context.so.1.69.0: make_fcontext (+0x2f) [0x7f240e58218f]



[2020-04-08 14:20:49 -0700] warning/JsonRpcConnection: API client disconnected for identity 'hpc-monitoring.hpc.edu'
[2020-04-08 14:20:49 -0700] warning/ApiListener: Removing API client for endpoint 'hpc-monitoring.hpc.edu'. 0 API clients left.
[2020-04-08 14:20:49 -0700] debug/EndpointDbObject: update is_connected=0 for endpoint 'hpc-monitoring.hpc.edu'

Does anybody have any ideas?

6

Very strange. The only reconnect loop I can think of occurs only in v2.12-rc1 (we’ve already built a fix), but not in v2.11.

Are your nodes’ clocks in sync? Are you sure there’s nothing different in the problematic client’s setup?