search

Icinga / icinga2

The core of our monitoring platform with a powerful configuration language and REST API.
https://icinga.com/docs/icinga2/latest
GNU General Public License v2.0
2.01k stars 577 forks source link

Problem with daemonize (init scripts, -d) on Debian 8 / CentOS 6 / Ubuntu 14 / SLES 11 in 2.9 #6445

Closed yoshi314 closed 6 years ago

yoshi314 commented 6 years ago

I just upgraded 2.8.4 to 2.9.0 on jessie. The majority of changes were in features-available/*.conf files where i had to remove "library (...)" lines, as the updates suggested. Rest of the config is unchanged

Icingaweb cannot connect to icinga2 instance. Icinga2 seems to run, but does not execute any checks whatsoever.

This was tested on master and satellite.

yoshi314 commented 6 years ago

It seems that everything is disabled, for some reason. Despite icinga2 feature list saying they are enabled.

dnsmichi commented 6 years ago

Can you please provide a little more detail on your setup, logs from startup, specific configuration in /etc/default/icinga2 and anything else which helps to reproduce the problem?

yoshi314 commented 6 years ago

I'll try breaking one of my 2.8 instances again. It seems i only updated the feature-available/* files by removing the library lines for 2.9 and that was it.

I downgraded to 2.8 and restored those lines and it works again.

yoshi314 commented 6 years ago

What exactly would be useful? I assume i should collect debug log, just not sure how long should i leave it running.

dnsmichi commented 6 years ago

Everything which is mentioned in the GH issue template. You should fill that in the first place. https://raw.githubusercontent.com/Icinga/icinga2/master/.github/ISSUE_TEMPLATE.md

I've fired up a Debian 8 Vagrant VM, installed the packages, enabled the debug log and it just begins to check. So, your problem must be specific to your configuration and/or activated features. The default installation works fine for me, not able to reproduce.

root@icinga2-debian8:~# icinga2 feature enable debuglog
Enabling feature debuglog. Make sure to restart Icinga 2 for these changes to take effect.
root@icinga2-debian8:~# service icinga2 restart
root@icinga2-debian8:~# tail -f /var/log/icinga2/debug.log
[2018-07-18 00:56:21 -0700] debug/TimePeriod: Adding segment 'Thu Jul 19 09:00:00 2018' <-> 'Thu Jul 19 17:00:00 2018' to TimePeriod '9to5'
[2018-07-18 00:56:21 -0700] debug/LegacyTimePeriod: Legacy timeperiod update returned 0 segments.
[2018-07-18 00:56:21 -0700] debug/TimePeriod: Removing segment 'Wed Jul 18 00:56:21 2018' <-> 'Thu Jul 19 00:56:21 2018' from TimePeriod 'never'
[2018-07-18 00:56:21 -0700] information/CheckerComponent: 'checker' started.
[2018-07-18 00:56:21 -0700] information/NotificationComponent: 'notification' started.
[2018-07-18 00:56:21 -0700] information/ConfigItem: Activated all objects.
[2018-07-18 00:56:21 -0700] notice/WorkQueue: Stopped WorkQueue threads for 'DaemonCommand::Run'
[2018-07-18 00:56:21 -0700] debug/IcingaApplication: In IcingaApplication::Main()
[2018-07-18 00:56:21 -0700] notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 0ms; Threads: 4; Pool utilization: 1.86352e-05%
[2018-07-18 00:56:26 -0700] notice/CheckerComponent: Pending checkables: 0; Idle checkables: 13; Checks/s: 0
[2018-07-18 00:56:31 -0700] notice/CheckerComponent: Pending checkables: 0; Idle checkables: 13; Checks/s: 0
[2018-07-18 00:56:32 -0700] debug/CheckerComponent: Scheduling info for checkable 'icinga2-debian8.vagrant.demo.icinga.com!http' (2018-07-18 00:56:32 -0700): Object 'icinga2-debian8.vagrant.demo.icinga.com!http', Next Check: 2018-07-18 00:56:32 -0700(1.5319e+09).
[2018-07-18 00:56:32 -0700] debug/CheckerComponent: Executing check for 'icinga2-debian8.vagrant.demo.icinga.com!http'
[2018-07-18 00:56:32 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!http' with check interval '60' from last check time at 2018-07-18 00:55:18 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:32 -0700(1.5319e+09).
[2018-07-18 00:56:32 -0700] notice/Process: Running command '/usr/lib/nagios/plugins/check_http' '-I' '127.0.0.1' '-u' '/': PID 4448
[2018-07-18 00:56:32 -0700] debug/CheckerComponent: Check finished for object 'icinga2-debian8.vagrant.demo.icinga.com!http'
[2018-07-18 00:56:32 -0700] notice/Process: PID 4448 ('/usr/lib/nagios/plugins/check_http' '-I' '127.0.0.1' '-u' '/') terminated with exit code 2
[2018-07-18 00:56:32 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!http' with check interval '60' from last check time at 2018-07-18 00:56:32 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:32 -0700(1.5319e+09).
[2018-07-18 00:56:32 -0700] debug/DbEvents: add checkable check history for 'icinga2-debian8.vagrant.demo.icinga.com!http'
[2018-07-18 00:56:36 -0700] notice/CheckerComponent: Pending checkables: 0; Idle checkables: 13; Checks/s: 0.0166667
[2018-07-18 00:56:36 -0700] notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 0ms; Threads: 4; Pool utilization: 0.00624567%
[2018-07-18 00:56:37 -0700] debug/CheckerComponent: Scheduling info for checkable 'icinga2-debian8.vagrant.demo.icinga.com!icinga' (2018-07-18 00:56:37 -0700): Object 'icinga2-debian8.vagrant.demo.icinga.com!icinga', Next Check: 2018-07-18 00:56:37 -0700(1.5319e+09).
[2018-07-18 00:56:37 -0700] debug/CheckerComponent: Executing check for 'icinga2-debian8.vagrant.demo.icinga.com!icinga'
[2018-07-18 00:56:37 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!icinga' with check interval '60' from last check time at 2018-07-18 00:55:22 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:36 -0700(1.5319e+09).
[2018-07-18 00:56:37 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!icinga' with check interval '60' from last check time at 2018-07-18 00:56:37 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:36 -0700(1.5319e+09).
[2018-07-18 00:56:37 -0700] debug/DbEvents: add checkable check history for 'icinga2-debian8.vagrant.demo.icinga.com!icinga'
[2018-07-18 00:56:37 -0700] debug/CheckerComponent: Check finished for object 'icinga2-debian8.vagrant.demo.icinga.com!icinga'
[2018-07-18 00:56:41 -0700] notice/CheckerComponent: Pending checkables: 0; Idle checkables: 13; Checks/s: 0.0333333
[2018-07-18 00:56:41 -0700] debug/CheckerComponent: Scheduling info for checkable 'icinga2-debian8.vagrant.demo.icinga.com!disk' (2018-07-18 00:56:41 -0700): Object 'icinga2-debian8.vagrant.demo.icinga.com!disk', Next Check: 2018-07-18 00:56:41 -0700(1.5319e+09).
[2018-07-18 00:56:41 -0700] debug/CheckerComponent: Executing check for 'icinga2-debian8.vagrant.demo.icinga.com!disk'
[2018-07-18 00:56:41 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!disk' with check interval '60' from last check time at 2018-07-18 00:55:26 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:38 -0700(1.5319e+09).
[2018-07-18 00:56:41 -0700] notice/Process: Running command '/usr/lib/nagios/plugins/check_disk' '-c' '10%' '-w' '20%' '-X' 'none' '-X' 'tmpfs' '-X' 'sysfs' '-X' 'proc' '-X' 'configfs' '-X' 'devtmpfs' '-X' 'devfs' '-X' 'mtmfs' '-X' 'tracefs' '-X' 'cgroup' '-X' 'fuse.gvfsd-fuse' '-X' 'fuse.gvfs-fuse-daemon' '-X' 'fdescfs' '-X' 'overlay' '-X' 'nsfs' '-m': PID 4449
[2018-07-18 00:56:41 -0700] debug/CheckerComponent: Check finished for object 'icinga2-debian8.vagrant.demo.icinga.com!disk'
[2018-07-18 00:56:41 -0700] notice/Process: PID 4449 ('/usr/lib/nagios/plugins/check_disk' '-c' '10%' '-w' '20%' '-X' 'none' '-X' 'tmpfs' '-X' 'sysfs' '-X' 'proc' '-X' 'configfs' '-X' 'devtmpfs' '-X' 'devfs' '-X' 'mtmfs' '-X' 'tracefs' '-X' 'cgroup' '-X' 'fuse.gvfsd-fuse' '-X' 'fuse.gvfs-fuse-daemon' '-X' 'fdescfs' '-X' 'overlay' '-X' 'nsfs' '-m') terminated with exit code 1
[2018-07-18 00:56:41 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!disk' with check interval '60' from last check time at 2018-07-18 00:56:41 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:38 -0700(1.5319e+09).
[2018-07-18 00:56:41 -0700] debug/DbEvents: add checkable check history for 'icinga2-debian8.vagrant.demo.icinga.com!disk'
[2018-07-18 00:56:42 -0700] debug/CheckerComponent: Scheduling info for checkable 'icinga2-debian8.vagrant.demo.icinga.com!users' (2018-07-18 00:56:42 -0700): Object 'icinga2-debian8.vagrant.demo.icinga.com!users', Next Check: 2018-07-18 00:56:42 -0700(1.5319e+09).
[2018-07-18 00:56:42 -0700] debug/CheckerComponent: Executing check for 'icinga2-debian8.vagrant.demo.icinga.com!users'
[2018-07-18 00:56:42 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!users' with check interval '60' from last check time at 2018-07-18 00:55:28 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:40 -0700(1.5319e+09).
[2018-07-18 00:56:42 -0700] notice/Process: Running command '/usr/lib/nagios/plugins/check_users' '-c' '50' '-w' '20': PID 4450
[2018-07-18 00:56:42 -0700] debug/CheckerComponent: Check finished for object 'icinga2-debian8.vagrant.demo.icinga.com!users'
[2018-07-18 00:56:42 -0700] notice/Process: PID 4450 ('/usr/lib/nagios/plugins/check_users' '-c' '50' '-w' '20') terminated with exit code 0
[2018-07-18 00:56:42 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!users' with check interval '60' from last check time at 2018-07-18 00:56:42 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:40 -0700(1.5319e+09).
[2018-07-18 00:56:42 -0700] debug/DbEvents: add checkable check history for 'icinga2-debian8.vagrant.demo.icinga.com!users'
[2018-07-18 00:56:44 -0700] debug/CheckerComponent: Scheduling info for checkable 'icinga2-debian8.vagrant.demo.icinga.com!apt' (2018-07-18 00:56:44 -0700): Object 'icinga2-debian8.vagrant.demo.icinga.com!apt', Next Check: 2018-07-18 00:56:44 -0700(1.5319e+09).
[2018-07-18 00:56:44 -0700] debug/CheckerComponent: Executing check for 'icinga2-debian8.vagrant.demo.icinga.com!apt'
[2018-07-18 00:56:44 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!apt' with check interval '60' from last check time at 2018-07-18 00:55:30 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:43 -0700(1.5319e+09).
[2018-07-18 00:56:44 -0700] notice/Process: Running command '/usr/lib/nagios/plugins/check_apt': PID 4451
[2018-07-18 00:56:44 -0700] debug/CheckerComponent: Check finished for object 'icinga2-debian8.vagrant.demo.icinga.com!apt'
[2018-07-18 00:56:45 -0700] notice/Process: PID 4451 ('/usr/lib/nagios/plugins/check_apt') terminated with exit code 2
[2018-07-18 00:56:45 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!apt' with check interval '60' from last check time at 2018-07-18 00:56:45 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:44 -0700(1.5319e+09).
[2018-07-18 00:56:45 -0700] debug/DbEvents: add checkable check history for 'icinga2-debian8.vagrant.demo.icinga.com!apt'
[2018-07-18 00:56:46 -0700] notice/CheckerComponent: Pending checkables: 0; Idle checkables: 13; Checks/s: 0.0833333
[2018-07-18 00:56:49 -0700] debug/CheckerComponent: Scheduling info for checkable 'icinga2-debian8.vagrant.demo.icinga.com!procs' (2018-07-18 00:56:49 -0700): Object 'icinga2-debian8.vagrant.demo.icinga.com!procs', Next Check: 2018-07-18 00:56:49 -0700(1.5319e+09).
[2018-07-18 00:56:49 -0700] debug/CheckerComponent: Executing check for 'icinga2-debian8.vagrant.demo.icinga.com!procs'
[2018-07-18 00:56:49 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!procs' with check interval '60' from last check time at 2018-07-18 00:54:31 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:47 -0700(1.5319e+09).
[2018-07-18 00:56:49 -0700] notice/Process: Running command '/usr/lib/nagios/plugins/check_procs' '-c' '400' '-w' '250': PID 4456
[2018-07-18 00:56:49 -0700] debug/CheckerComponent: Check finished for object 'icinga2-debian8.vagrant.demo.icinga.com!procs'
[2018-07-18 00:56:49 -0700] notice/Process: PID 4456 ('/usr/lib/nagios/plugins/check_procs' '-c' '400' '-w' '250') terminated with exit code 0
[2018-07-18 00:56:49 -0700] debug/Checkable: Update checkable 'icinga2-debian8.vagrant.demo.icinga.com!procs' with check interval '60' from last check time at 2018-07-18 00:56:49 -0700 (1.5319e+09) to next check time at 2018-07-18 00:57:47 -0700(1.5319e+09).
[2018-07-18 00:56:49 -0700] debug/DbEvents: add checkable check history for 'icinga2-debian8.vagrant.demo.icinga.com!procs'

root@icinga2-debian8:~# icinga2 --version
icinga2 - The Icinga 2 network monitoring daemon (version: r2.9.0-1)

Copyright (c) 2012-2018 Icinga Development Team (https://www.icinga.com/)
License GPLv2+: GNU GPL version 2 or later <http://gnu.org/licenses/gpl2.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Application information:
  Installation root: /usr
  Sysconf directory: /etc
  Run directory: /run
  Local state directory: /var
  Package data directory: /usr/share/icinga2
  State path: /var/lib/icinga2/icinga2.state
  Modified attributes path: /var/lib/icinga2/modified-attributes.conf
  Objects path: /var/cache/icinga2/icinga2.debug
  Vars path: /var/cache/icinga2/icinga2.vars
  PID path: /run/icinga2/icinga2.pid

System information:
  Platform: Debian GNU/Linux
  Platform version: 8 (jessie)
  Kernel: Linux
  Kernel version: 3.16.0-6-amd64
  Architecture: x86_64

Build information:
  Compiler: GNU 4.9.2
  Build host: e11ae8f0f5d1

root@icinga2-debian8:~# icinga2 feature list
Disabled features: api command compatlog elasticsearch gelf graphite influxdb livestatus opentsdb perfdata statusdata syslog
Enabled features: checker debuglog mainlog notification
BarbUk commented 6 years ago

Hello,

I have the same issue after upgrading.

Expected Behavior

Current Behavior

Possible Solution

Starting icinga2 without the -d flags, eg:

Environment

# icinga2 --version
icinga2 - The Icinga 2 network monitoring daemon (version: r2.9.0-1)

Copyright (c) 2012-2018 Icinga Development Team (https://www.icinga.com/)
License GPLv2+: GNU GPL version 2 or later <http://gnu.org/licenses/gpl2.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Application information:
  Installation root: /usr
  Sysconf directory: /etc
  Run directory: /run
  Local state directory: /var
  Package data directory: /usr/share/icinga2
  State path: /var/lib/icinga2/icinga2.state
  Modified attributes path: /var/lib/icinga2/modified-attributes.conf
  Objects path: /var/cache/icinga2/icinga2.debug
  Vars path: /var/cache/icinga2/icinga2.vars
  PID path: /run/icinga2/icinga2.pid

System information:
  Platform: Debian GNU/Linux
  Platform version: 9 (stretch)
  Kernel: Linux
  Kernel version: 4.4.30-mod-std-ipv6-64
  Architecture: x86_64

Build information:
  Compiler: GNU 6.3.0
  Build host: 75ce47a53df9
chrostek commented 6 years ago

Same problem with ubuntu 14.04 i have a satellite with this os and as BarbUk wrote:

Starting icinga2 without the -d flags, eg:

icinga2 daemon -d is not working
icinga2 daemon works ok

with -d flag the log stops at

[2018-07-18 10:23:52 +0200] information/ConfigItem: Activated all objects.

without -d flag it continues with

[2018-07-18 10:25:10 +0200] information/ApiListener: New client connection for identity 'XXXXXX' to [XXX.XXX.XXX.XXX]:5665

nbuchwitz commented 6 years ago

I observed the same behavior (won't run as daemon, but in foreground) as @BarbUk and @chrostek on CentOS 6(#6448).

dgoetz commented 6 years ago

So if Debian jessie, Ubuntu 14.4 and CentOS 6 are affected, it is likely something all non-systemd systems are affected by daemonizing being broken. Can someone test if daemonizing works on a systemd system? Systemd's unitfile is running it in foreground, so systems will not be affected and noone will notice if daemonizing is broken on those systems.

dnsmichi commented 6 years ago

My Debian 8 VM runs also with the API enabled, and it executes checks. We need more details on the specific setups, anything which has been modified from the default installation, e.g. zones.conf, enabled features, etc.

At the moment I would blankly guess this might happen when a cluster connection happens. Still needs a reproducer.

widhalmt commented 6 years ago

On my CentOS 6 daemonizing works as expected. Although Icinga 2 doesn't write into IDO even though it logs that it starts the ido worker.

I'm still investigating the IDO issue and will open a seperate issue. I just wanted you to know that my CentOS 6 at least daemonizes like it should. (This installation was installed with a pre 2.4 version and got regular upgrades so it's no new setup)

dnsmichi commented 6 years ago

Can you install 

yum -y install gdb icinga2-debuginfo

apt-get -y install gdb icinga2-dbg

then attach to the running process (the first pid from pidof icinga2) with gdb and generate a full backtrace?

gdb -p <PID>

> thread apply all bt full

and paste that here.

neubi4 commented 6 years ago

We have the same problem in our Centos 7 Container, we are running Icinga2 in an entrypoint bash script using icinga2 daemon -d.

zones.conf:

object Endpoint "master1-local-domon.testing.mms-at-work.de"  {
  host = "master1-local-domon.testing.mms-at-work.de"
}

object Endpoint "master2-local-domon.testing.mms-at-work.de"  {
  host = "master2-local-domon.testing.mms-at-work.de"
}

object Zone "master"  {
  endpoints = [ "master1-local-domon.testing.mms-at-work.de", "master2-local-domon.testing.mms-at-work.de", ]
}

object Zone "director-global"  {
  global = true
}

object Zone "global-templates"  {
  global = true
}

Environment

Copyright (c) 2012-2018 Icinga Development Team (https://www.icinga.com/) License GPLv2+: GNU GPL version 2 or later http://gnu.org/licenses/gpl2.html This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law.

Application information: Installation root: /usr Sysconf directory: /etc Run directory: /run Local state directory: /var Package data directory: /usr/share/icinga2 State path: /var/lib/icinga2/icinga2.state Modified attributes path: /var/lib/icinga2/modified-attributes.conf Objects path: /var/cache/icinga2/icinga2.debug Vars path: /var/cache/icinga2/icinga2.vars PID path: /run/icinga2/icinga2.pid

System information: Platform: CentOS Linux Platform version: 7 (Core) Kernel: Linux Kernel version: 3.10.0-693.21.1.el7.x86_64 Architecture: x86_64

Build information: Compiler: GNU 4.8.5 Build host: unknown

* Operating System and version:

bash-4.2$ cat /etc/*release CentOS Linux release 7.5.1804 (Core) NAME="CentOS Linux" VERSION="7 (Core)" ID="centos" ID_LIKE="rhel fedora" VERSION_ID="7" PRETTY_NAME="CentOS Linux 7 (Core)" ANSI_COLOR="0;31" CPE_NAME="cpe:/o:centos:centos:7" HOME_URL="https://www.centos.org/" BUG_REPORT_URL="https://bugs.centos.org/"

CENTOS_MANTISBT_PROJECT="CentOS-7" CENTOS_MANTISBT_PROJECT_VERSION="7" REDHAT_SUPPORT_PRODUCT="centos" REDHAT_SUPPORT_PRODUCT_VERSION="7"

CentOS Linux release 7.5.1804 (Core) CentOS Linux release 7.5.1804 (Core)

* Enabled features (`icinga2 feature list`):

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


* Icinga Web 2 version and modules (System - About):
Not important here

* Config validation (`icinga2 daemon -C`):

bash-4.2$ icinga2 daemon -C [2018-07-18 11:22:56 +0200] information/cli: Icinga application loader (version: r2.9.0-1) [2018-07-18 11:22:56 +0200] information/cli: Loading configuration file(s). [2018-07-18 11:22:56 +0200] information/ConfigItem: Committing config item(s). [2018-07-18 11:22:56 +0200] information/ApiListener: My API identity: master1-local-domon.testing.mms-at-work.de [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 6 Services. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 1 InfluxdbWriter. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 2 FileLoggers. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 1 NotificationComponent. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 1 IcingaApplication. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 2 Hosts. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 1 ApiListener. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 1 CheckerComponent. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 3 Zones. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 2 Endpoints. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 1 ApiUser. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 1 IdoMysqlConnection. [2018-07-18 11:22:56 +0200] information/ConfigItem: Instantiated 213 CheckCommands. [2018-07-18 11:22:56 +0200] information/ScriptGlobal: Dumping variables to file '/var/cache/icinga2/icinga2.vars' [2018-07-18 11:22:56 +0200] information/cli: Finished validating the configuration file(s).

* icinga2.log

[2018-07-18 10:48:35 +0200] information/cli: Icinga application loader (version: r2.9.0-1) [2018-07-18 10:48:35 +0200] information/cli: Loading configuration file(s). [2018-07-18 10:48:35 +0200] information/ConfigItem: Committing config item(s). [2018-07-18 10:48:35 +0200] information/ApiListener: My API identity: master1-local-domon.testing.mms-at-work.de [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 6 Services. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 1 InfluxdbWriter. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 2 FileLoggers. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 1 NotificationComponent. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 1 IcingaApplication. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 2 Hosts. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 1 ApiListener. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 1 CheckerComponent. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 3 Zones. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 2 Endpoints. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 1 ApiUser. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 1 IdoMysqlConnection. [2018-07-18 10:48:35 +0200] information/ConfigItem: Instantiated 213 CheckCommands. [2018-07-18 10:48:35 +0200] information/ScriptGlobal: Dumping variables to file '/var/cache/icinga2/icinga2.vars' [2018-07-18 10:48:35 +0200] information/ConfigItem: Triggering Start signal for config items [2018-07-18 10:48:35 +0200] information/ApiListener: 'api' started. [2018-07-18 10:48:35 +0200] information/ApiListener: Adding new listener on port '5665' [2018-07-18 10:48:35 +0200] information/CheckerComponent: 'checker' started. [2018-07-18 10:48:35 +0200] information/DbConnection: 'ido-mysql' started. [2018-07-18 10:48:35 +0200] information/NotificationComponent: 'notification' started. [2018-07-18 10:48:35 +0200] information/InfluxdbWriter: 'influxdb' started. [2018-07-18 10:48:35 +0200] information/ConfigItem: Activated all objects.

* debug.log

[2018-07-18 10:48:35 +0200] notice/WorkQueue: Spawning WorkQueue threads for 'ApiListener, RelayQueue' [2018-07-18 10:48:35 +0200] information/ApiListener: 'api' started. [2018-07-18 10:48:35 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 10:48:35 +0200] information/ApiListener: Adding new listener on port '5665' [2018-07-18 10:48:35 +0200] information/CheckerComponent: 'checker' started. [2018-07-18 10:48:35 +0200] information/DbConnection: 'ido-mysql' started. [2018-07-18 10:48:35 +0200] information/NotificationComponent: 'notification' started. [2018-07-18 10:48:35 +0200] information/InfluxdbWriter: 'influxdb' started. [2018-07-18 10:48:35 +0200] information/ConfigItem: Activated all objects. [2018-07-18 10:48:35 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 10:48:35 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 10:48:35 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 10:48:35 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 10:48:35 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 10:48:35 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 10:48:35 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 10:48:35 +0200] notice/WorkQueue: Stopped WorkQueue threads for 'DaemonCommand::Run' [2018-07-18 10:48:35 +0200] debug/IcingaApplication: In IcingaApplication::Main() [2018-07-18 10:48:35 +0200] notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 0ms; Threads: 4; Pool utilization: 0%

[2018-07-18 10:48:50 +0200] notice/ApiListener: New HTTP client [2018-07-18 10:48:50 +0200] debug/HttpRequest: line: GET /v1/objects/zones HTTP/1.1, tokens: 3 [2018-07-18 10:48:50 +0200] information/HttpServerConnection: Request: GET /v1/objects/zones (from [172.18.0.7]:33028, user: user) [2018-07-18 10:48:50 +0200] notice/WorkQueue: Spawning WorkQueue threads for 'HttpServerConnection' [2018-07-18 10:48:50 +0200] notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 0ms; Threads: 4; Pool utilization: 0% [2018-07-18 10:49:05 +0200] notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 0ms; Threads: 4; Pool utilization: 0% [2018-07-18 10:49:20 +0200] notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 0ms; Threads: 4; Pool utilization: 0% [2018-07-18 10:49:35 +0200] notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 0ms; Threads: 4; Pool utilization: 0% [2018-07-18 10:49:50 +0200] notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 0ms; Threads: 4; Pool utilization: 0%

Last lines are repeated infinitely.

## To check, same container and config with 2.8.4 which is working without a problem:
* icinga2.log

[2018-07-18 11:07:17 +0200] information/cli: Icinga application loader (version: r2.8.4-1) [2018-07-18 11:07:17 +0200] information/cli: Loading configuration file(s). [2018-07-18 11:07:17 +0200] information/ConfigItem: Committing config item(s). [2018-07-18 11:07:17 +0200] information/ApiListener: My API identity: master1-local-domon.testing.mms-at-work.de [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 1 ApiListener. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 3 Zones. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 2 Endpoints. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 2 FileLoggers. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 1 ApiUser. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 209 CheckCommands. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 1 IcingaApplication. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 2 Hosts. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 6 Services. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 1 CheckerComponent. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 1 InfluxdbWriter. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 1 NotificationComponent. [2018-07-18 11:07:17 +0200] information/ConfigItem: Instantiated 1 IdoMysqlConnection. [2018-07-18 11:07:17 +0200] information/ScriptGlobal: Dumping variables to file '/var/cache/icinga2/icinga2.vars' [2018-07-18 11:07:17 +0200] information/ConfigItem: Triggering Start signal for config items [2018-07-18 11:07:17 +0200] information/ApiListener: 'api' started. [2018-07-18 11:07:17 +0200] information/ApiListener: Adding new listener on port '5665' [2018-07-18 11:07:17 +0200] information/CheckerComponent: 'checker' started. [2018-07-18 11:07:17 +0200] information/InfluxdbWriter: 'influxdb' started. [2018-07-18 11:07:17 +0200] information/NotificationComponent: 'notification' started. [2018-07-18 11:07:17 +0200] information/DbConnection: 'ido-mysql' started. [2018-07-18 11:07:17 +0200] information/ConfigItem: Activated all objects.

* debug.log

[2018-07-18 11:07:17 +0200] notice/WorkQueue: Spawning WorkQueue threads for 'ApiListener, RelayQueue' [2018-07-18 11:07:17 +0200] information/CheckerComponent: 'checker' started. [2018-07-18 11:07:17 +0200] information/InfluxdbWriter: 'influxdb' started. [2018-07-18 11:07:17 +0200] information/NotificationComponent: 'notification' started. [2018-07-18 11:07:17 +0200] information/DbConnection: 'ido-mysql' started. [2018-07-18 11:07:17 +0200] information/ConfigItem: Activated all objects. [2018-07-18 11:07:17 +0200] notice/WorkQueue: Spawning WorkQueue threads for 'InfluxdbWriter, influxdb' [2018-07-18 11:07:17 +0200] notice/WorkQueue: Stopped WorkQueue threads for 'DaemonCommand::Run' [2018-07-18 11:07:17 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 11:07:17 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 11:07:17 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 11:07:17 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 11:07:17 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 11:07:17 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 11:07:17 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 11:07:17 +0200] notice/ApiListener: Relaying 'event::SetNextCheck' message [2018-07-18 11:07:17 +0200] debug/IcingaApplication: In IcingaApplication::Main() [2018-07-18 11:07:17 +0200] debug/ApiListener: Not connecting to Endpoint 'master1-local-domon.testing.mms-at-work.de' because that's us. [2018-07-18 11:07:17 +0200] notice/ApiListener: Current zone master: master1-local-domon.testing.mms-at-work.de [2018-07-18 11:07:17 +0200] notice/ApiListener: Connected endpoints: [2018-07-18 11:07:17 +0200] information/ApiListener: Reconnecting to endpoint 'master2-local-domon.testing.mms-at-work.de' via host 'master2-local-domon.testing.mms-at-work.de' and port '5665' [2018-07-18 11:07:17 +0200] critical/TcpSocket: getaddrinfo() failed with error code -2, "Name or service not known" [2018-07-18 11:07:17 +0200] critical/ApiListener: Cannot connect to host 'master2-local-domon.testing.mms-at-work.de' on port '5665' [2018-07-18 11:07:17 +0200] debug/ApiListener: Cannot connect to host 'master2-local-domon.testing.mms-at-work.de' on port '5665' Error: std::exception

    (0) libbase.so.2.8.4: <unknown function> (+0xf2397) [0x7f8e2b490397]
    (1) libbase.so.2.8.4: icinga::TcpSocket::Connect(icinga::String const&, icinga::String const&) (+0x3b9) [0x7f8e2b47d029]
    (2) libremote.so.2.8.4: icinga::ApiListener::AddConnection(boost::intrusive_ptr<icinga::Endpoint> const&) (+0x226) [0x7f8e2abe96b6]
    (3) libboost_thread-mt.so.1.53.0: <unknown function> (+0xd27a) [0x7f8e2bec327a]
    (4) libpthread.so.0: <unknown function> (+0x7e25) [0x7f8e28b8ce25]
    (5) libc.so.6: clone (+0x6d) [0x7f8e288b6bad]

[2018-07-18 11:07:17 +0200] information/ApiListener: Finished reconnecting to endpoint 'master2-local-domon.testing.mms-at-work.de' via host 'master2-local-domon.testing.mms-at-work.de' and port '5665' [2018-07-18 11:07:18 +0200] notice/ThreadPool: Pool #1: Pending tasks: 0; Average latency: 1ms; Threads: 4; Pool utilization: 0.0394906% [2018-07-18 11:07:22 +0200] notice/CheckerComponent: Pending checkables: 0; Idle checkables: 0; Checks/s: 0

[2018-07-18 11:07:26 +0200] notice/ApiListener: New JSON-RPC client [2018-07-18 11:07:26 +0200] notice/WorkQueue: Spawning WorkQueue threads for 'JsonRpcConnection, #0' [2018-07-18 11:07:26 +0200] debug/EndpointDbObject: update is_connected=1 for endpoint 'master2-local-domon.testing.mms-at-work.de' [2018-07-18 11:07:26 +0200] notice/WorkQueue: Spawning WorkQueue threads for 'IdoMysqlConnection, ido-mysql' [2018-07-18 11:07:26 +0200] notice/WorkQueue: Spawning WorkQueue threads for 'ApiListener, SyncQueue' [2018-07-18 11:07:26 +0200] information/ApiListener: Sending config updates for endpoint 'master2-local-domon.testing.mms-at-work.de' in zone 'master'. [2018-07-18 11:07:26 +0200] notice/JsonRpcConnection: Received 'icinga::Hello' message from 'master2-local-domon.testing.mms-at-work.de' [2018-07-18 11:07:26 +0200] information/ApiListener: Finished sending config file updates for endpoint 'master2-local-domon.testing.mms-at-work.de' in zone 'master'. [2018-07-18 11:07:26 +0200] information/ApiListener: Syncing runtime objects to endpoint 'master2-local-domon.testing.mms-at-work.de'. [2018-07-18 11:07:26 +0200] information/ApiListener: Finished syncing runtime objects to endpoint 'master2-local-domon.testing.mms-at-work.de'. [2018-07-18 11:07:26 +0200] information/ApiListener: Finished sending runtime config updates for endpoint 'master2-local-domon.testing.mms-at-work.de' in zone 'master'. [2018-07-18 11:07:26 +0200] information/ApiListener: Sending replay log for endpoint 'master2-local-domon.testing.mms-at-work.de' in zone 'master'. [2018-07-18 11:07:26 +0200] notice/JsonRpcConnection: Received 'config::Update' message from 'master2-local-domon.testing.mms-at-work.de'

chrostek commented 6 years ago 
gdb -p 20165
GNU gdb (Ubuntu 7.7.1-0ubuntu5~14.04.3) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 20165
Reading symbols from /usr/lib/x86_64-linux-gnu/icinga2/sbin/icinga2...Reading symbols from /usr/lib/debug/.build-id/cf/efcfd20a70c0107189abe17ec4cf6efff9e128.debug...done.
done.
Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libc-2.19.so...done.
done.
Loaded symbols for /lib/x86_64-linux-gnu/libc.so.6
Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libdl-2.19.so...done.
done.
Loaded symbols for /lib/x86_64-linux-gnu/libdl.so.2
Reading symbols from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.54.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.54.0
Reading symbols from /usr/lib/x86_64-linux-gnu/libboost_system.so.1.54.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libboost_system.so.1.54.0
Reading symbols from /usr/lib/x86_64-linux-gnu/libboost_program_options.so.1.54.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libboost_program_options.so.1.54.0
Reading symbols from /usr/lib/x86_64-linux-gnu/libboost_regex.so.1.54.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libboost_regex.so.1.54.0
Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libpthread-2.19.so...done.
done.
[New LWP 20178]
[New LWP 20177]
[New LWP 20170]
[New LWP 20169]
[New LWP 20168]
[New LWP 20167]
[New LWP 20166]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Loaded symbols for /lib/x86_64-linux-gnu/libpthread.so.0
Reading symbols from /lib/x86_64-linux-gnu/libssl.so.1.0.0...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libssl.so.1.0.0
Reading symbols from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
Reading symbols from /usr/lib/x86_64-linux-gnu/libyajl.so.2...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libyajl.so.2
Reading symbols from /usr/lib/x86_64-linux-gnu/libedit.so.2...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libedit.so.2
Reading symbols from /usr/lib/x86_64-linux-gnu/libstdc++.so.6...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libstdc++.so.6
Reading symbols from /lib/x86_64-linux-gnu/libm.so.6...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libm-2.19.so...done.
done.
Loaded symbols for /lib/x86_64-linux-gnu/libm.so.6
Reading symbols from /lib/x86_64-linux-gnu/libgcc_s.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libgcc_s.so.1
Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/ld-2.19.so...done.
done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /lib/x86_64-linux-gnu/librt.so.1...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/librt-2.19.so...done.
done.
Loaded symbols for /lib/x86_64-linux-gnu/librt.so.1
Reading symbols from /usr/lib/x86_64-linux-gnu/libicuuc.so.52...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libicuuc.so.52
Reading symbols from /usr/lib/x86_64-linux-gnu/libicui18n.so.52...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libicui18n.so.52
Reading symbols from /lib/x86_64-linux-gnu/libtinfo.so.5...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libtinfo.so.5
Reading symbols from /usr/lib/x86_64-linux-gnu/libicudata.so.52...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libicudata.so.52
Reading symbols from /lib/x86_64-linux-gnu/libnss_files.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libnss_files-2.19.so...done.
done.
Loaded symbols for /lib/x86_64-linux-gnu/libnss_files.so.2
Reading symbols from /lib/x86_64-linux-gnu/libnss_compat.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libnss_compat-2.19.so...done.
done.
Loaded symbols for /lib/x86_64-linux-gnu/libnss_compat.so.2
Reading symbols from /lib/x86_64-linux-gnu/libnsl.so.1...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libnsl-2.19.so...done.
done.
Loaded symbols for /lib/x86_64-linux-gnu/libnsl.so.1
Reading symbols from /lib/x86_64-linux-gnu/libnss_nis.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libnss_nis-2.19.so...done.
done.
Loaded symbols for /lib/x86_64-linux-gnu/libnss_nis.so.2
0x00007f619b6ddd4d in nanosleep () at ../sysdeps/unix/syscall-template.S:81
81      ../sysdeps/unix/syscall-template.S: Datei oder Verzeichnis nicht gefunden.
(gdb) thread apply all bt full

Thread 8 (Thread 0x7f619bb29700 (LWP 20166)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x00000000007c834b in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) [clone .local.16265] (
    this=this@entry=0xf69510 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+528>, m=...) at /usr/include/boost/thread/pthread/condition_variable.hpp:73
        guard = {m = 0x0}
        check_for_interruption = {thread_info = 0x229d610, m = 0xf69510 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+528>, set = true}
        res = <optimized out>
#2  0x0000000000a5937a in icinga::ThreadPool::WorkerThread::ThreadProc (this=0xf69628 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+808>, queue=...)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/base/threadpool.cpp:110
        lock = {m = 0xf694e8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+488>, is_locked = false}
        wi = {Callback = {<std::_Maybe_unary_or_binary_function> = {<std::unary_function> = {<No data fields>}, <No data fields>}, <std::_Function_base> = {_M_functor = {_M_unused = {
                  _M_object = 0xf69ea8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2984>, _M_const_object = 0xf69ea8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2984>,
                  _M_function_pointer = 0xf69ea8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2984>,
                  _M_member_pointer = (void (std::_Undefined_class::*)(std::_Undefined_class * const)) 0xf69ea8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2984>, this adjustment 140057167700481}, _M_pod_data = "\250\236\366\000\000\000\000\000\001\242\272\231a\177\000"}, _M_manager = 0x0},
            _M_invoker = 0x7f619aad72ae <char* std::string::_S_construct<char const*>(char const*, char const*, std::allocator<char> const&, std::forward_iterator_tag)+110>}, Timestamp = 0}
        st = <optimized out>
        et = <optimized out>
        latency = <optimized out>
        idbuf = <unvollständiger Typ>
        lock = {m = 0xf69ea8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2984>, is_locked = true}
#3  0x00007f619b20aa4a in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.54.0
No symbol table info available.
#4  0x00007f619a870184 in start_thread (arg=0x7f619bb29700) at pthread_create.c:312
        __res = <optimized out>
        pd = 0x7f619bb29700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140057200727808, -2254713775266350544, 0, 0, 140057200728512, 140057200727808, 2195103090436323888, 2195101067552471600},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007f619b71703d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

Thread 7 (Thread 0x7f619bae8700 (LWP 20167)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x00000000007c834b in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) [clone .local.16265] (
    this=this@entry=0xf69850 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+1360>, m=...) at /usr/include/boost/thread/pthread/condition_variable.hpp:73
        guard = {m = 0x0}
        check_for_interruption = {thread_info = 0x2280da0, m = 0xf69850 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+1360>, set = true}
        res = <optimized out>
#2  0x0000000000a5937a in icinga::ThreadPool::WorkerThread::ThreadProc (this=0xf69968 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+1640>, queue=...)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/base/threadpool.cpp:110
        lock = {m = 0xf69828 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+1320>, is_locked = false}
        wi = {Callback = {<std::_Maybe_unary_or_binary_function> = {<std::unary_function> = {<No data fields>}, <No data fields>}, <std::_Function_base> = {_M_functor = {_M_unused = {
                  _M_object = 0xf69b68 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2152>, _M_const_object = 0xf69b68 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2152>,
                  _M_function_pointer = 0xf69b68 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2152>,
                  _M_member_pointer = (void (std::_Undefined_class::*)(std::_Undefined_class * const)) 0xf69b68 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2152>, this adjustment 140057167700481}, _M_pod_data = "h\233\366\000\000\000\000\000\001\242\272\231a\177\000"}, _M_manager = 0x0},
            _M_invoker = 0x7f619aad72ae <char* std::string::_S_construct<char const*>(char const*, char const*, std::allocator<char> const&, std::forward_iterator_tag)+110>}, Timestamp = 0}
        st = <optimized out>
        et = <optimized out>
        latency = <optimized out>
        idbuf = <unvollständiger Typ>
---Type <return> to continue, or q <return> to quit---
        lock = {m = 0xf69b68 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2152>, is_locked = true}
#3  0x00007f619b20aa4a in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.54.0
No symbol table info available.
#4  0x00007f619a870184 in start_thread (arg=0x7f619bae8700) at pthread_create.c:312
        __res = <optimized out>
        pd = 0x7f619bae8700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140057200461568, -2254713775266350544, 0, 0, 140057200462272, 140057200461568, 2195103052318489136, 2195101067552471600},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007f619b71703d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

Thread 6 (Thread 0x7f619baa7700 (LWP 20168)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x00000000007c834b in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) [clone .local.16265] (
    this=this@entry=0xf69b90 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2192>, m=...) at /usr/include/boost/thread/pthread/condition_variable.hpp:73
        guard = {m = 0x0}
        check_for_interruption = {thread_info = 0x20efcf0, m = 0xf69b90 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2192>, set = true}
        res = <optimized out>
#2  0x0000000000a5937a in icinga::ThreadPool::WorkerThread::ThreadProc (this=0xf69ca8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2472>, queue=...)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/base/threadpool.cpp:110
        lock = {m = 0xf69b68 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2152>, is_locked = false}
        wi = {Callback = {<std::_Maybe_unary_or_binary_function> = {<std::unary_function> = {<No data fields>}, <No data fields>}, <std::_Function_base> = {_M_functor = {_M_unused = {
                  _M_object = 0xf69828 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+1320>, _M_const_object = 0xf69828 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+1320>,
                  _M_function_pointer = 0xf69828 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+1320>,
                  _M_member_pointer = (void (std::_Undefined_class::*)(std::_Undefined_class * const)) 0xf69828 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+1320>, this adjustment 140057167700481}, _M_pod_data = "(\230\366\000\000\000\000\000\001\242\272\231a\177\000"}, _M_manager = 0x0},
            _M_invoker = 0x7f619aad72ae <char* std::string::_S_construct<char const*>(char const*, char const*, std::allocator<char> const&, std::forward_iterator_tag)+110>}, Timestamp = 0}
        st = <optimized out>
        et = <optimized out>
        latency = <optimized out>
        idbuf = <unvollständiger Typ>
        lock = {m = 0xf69828 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+1320>, is_locked = true}
#3  0x00007f619b20aa4a in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.54.0
No symbol table info available.
#4  0x00007f619a870184 in start_thread (arg=0x7f619baa7700) at pthread_create.c:312
        __res = <optimized out>
        pd = 0x7f619baa7700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140057200195328, -2254713775266350544, 0, 0, 140057200196032, 140057200195328, 2195103018495621680, 2195101067552471600},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007f619b71703d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

Thread 5 (Thread 0x7f619ba66700 (LWP 20169)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x00000000007c834b in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) [clone .local.16265] (
    this=this@entry=0xf69ed0 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+3024>, m=...) at /usr/include/boost/thread/pthread/condition_variable.hpp:73
---Type <return> to continue, or q <return> to quit---
        guard = {m = 0x0}
        check_for_interruption = {thread_info = 0x229eb20, m = 0xf69ed0 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+3024>, set = true}
        res = <optimized out>
#2  0x0000000000a5937a in icinga::ThreadPool::WorkerThread::ThreadProc (this=0xf69fe8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+3304>, queue=...)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/base/threadpool.cpp:110
        lock = {m = 0xf69ea8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+2984>, is_locked = false}
        wi = {Callback = {<std::_Maybe_unary_or_binary_function> = {<std::unary_function> = {<No data fields>}, <No data fields>}, <std::_Function_base> = {_M_functor = {_M_unused = {
                  _M_object = 0xf694e8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+488>, _M_const_object = 0xf694e8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+488>,
                  _M_function_pointer = 0xf694e8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+488>,
                  _M_member_pointer = (void (std::_Undefined_class::*)(std::_Undefined_class * const)) 0xf694e8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+488>, this adjustment 140057167700481}, _M_pod_data = "\350\224\366\000\000\000\000\000\001\242\272\231a\177\000"}, _M_manager = 0x0},
            _M_invoker = 0x7f619aad72ae <char* std::string::_S_construct<char const*>(char const*, char const*, std::allocator<char> const&, std::forward_iterator_tag)+110>}, Timestamp = 0}
        st = <optimized out>
        et = <optimized out>
        latency = <optimized out>
        idbuf = <unvollständiger Typ>
        lock = {m = 0xf694e8 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+488>, is_locked = true}
#3  0x00007f619b20aa4a in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.54.0
No symbol table info available.
#4  0x00007f619a870184 in start_thread (arg=0x7f619ba66700) at pthread_create.c:312
        __res = <optimized out>
        pd = 0x7f619ba66700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140057199929088, -2254713775266350544, 0, 0, 140057199929792, 140057199929088, 2195102984672754224, 2195101067552471600},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007f619b71703d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

Thread 4 (Thread 0x7f619bb6a700 (LWP 20170)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
No locals.
#1  0x00000000007c7616 in do_wait_until (timeout=..., m=..., this=0xf69488 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+392>) at /usr/include/boost/thread/pthread/condition_variable.hpp:108
        check_for_interruption = {thread_info = 0x7f6180000c90, m = 0xf69488 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+392>, set = false}
        guard = {m = 0x7f619bb69d10}
        cond_res = <optimized out>
#2  boost::condition_variable::timed_wait(boost::unique_lock<boost::mutex>&, boost::posix_time::ptime const&) [clone .local.16018] (
    this=this@entry=0xf69488 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+392>, m=..., wait_until=...) at /usr/include/boost/thread/pthread/condition_variable_fwd.hpp:108
        timeout = {tv_sec = 1531906846, tv_nsec = 112668000}
#3  0x00000000007b3705 in timed_wait (wait_duration=..., m=..., this=0xf69488 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+392>)
    at /usr/include/boost/thread/pthread/condition_variable_fwd.hpp:123
No locals.
#4  icinga::ThreadPool::ManagerThreadProc() (this=0xf69300 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214>)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/base/threadpool.cpp:239
        lock = {m = 0xf69460 <_ZZN6icinga11Application5GetTPEvE2tp.90372.49214+352>, is_locked = false}
        total_utilization = 0
        total_pending = 0
        total_alive = 0
        total_avg_latency = 0
        now = <optimized out>
        idbuf = <unvollständiger Typ>
        lastStats = 1531906838,1111939
#5  0x00007f6199ba1a60 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#6  0x00007f619a870184 in start_thread (arg=0x7f619bb6a700) at pthread_create.c:312
        __res = <optimized out>
---Type <return> to continue, or q <return> to quit---
        pd = 0x7f619bb6a700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140057200994048, -2254713775266350544, 0, 0, 140057200994752, 140057200994048, 2195103124259191344, 2195101067552471600},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#7  0x00007f619b71703d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

Thread 3 (Thread 0x7f619697a700 (LWP 20177)):
#0  0x00007f619b717dad in accept () at ../sysdeps/unix/syscall-template.S:81
No locals.
#1  0x00000000007b7c5f in icinga::Socket::Accept() (this=<optimized out>) at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/base/socket.cpp:328
        addr = {ss_family = 14, __ss_align = 1,
          __ss_padding = "\020\060\004\002\000\000\000\000\200\000\000\000\000\000\000\000\016", '\000' <repeats 15 times>, "\034\000\000\000\000\000\000\000\310a\300\233a\177\000\000%\002\000\000\000\000\000\000\372]{\000\000\000\000\000\030\000\000\000\000\000\000\000\350\272\003pa\177\000\000@\273\003pa\177\000\000\001\000\000\000\000\000\000\000 \v\000pa\177\000\000\340\272i\233a\177\000"}
        addrlen = 128
        fd = <optimized out>
        __PRETTY_FUNCTION__ = "icinga::Socket::Ptr icinga::Socket::Accept()"
        __PRETTY_FUNCTION__ = "icinga::Socket::Ptr icinga::Socket::Accept()"
#2  0x00000000007b8247 in icinga::ApiListener::ListenerThreadProc(boost::intrusive_ptr<icinga::Socket> const&) (this=0x7f616c001b70, server=...)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/remote/apilistener.cpp:350
        client = {px = 0xe400000001}
        thread = {_M_id = {_M_thread = 140056400497712}}
#3  0x00000000006ca354 in operator() (__args#0=..., __object=0x7f616c001b70, this=0x229cbe0) at /usr/include/c++/4.8/functional:601
No locals.
#4  __call (this=0x229cbe0, __args=<optimized out>) at /usr/include/c++/4.8/functional:1296
        this = 0x229cbe0
#5  operator() (this=0x229cbe0) at /usr/include/c++/4.8/functional:1355
        this = 0x229cbe0
#6  _M_invoke (this=0x229cbe0) at /usr/include/c++/4.8/functional:1732
        this = 0x229cbe0
#7  operator() (this=0x229cbe0) at /usr/include/c++/4.8/functional:1720
        this = 0x229cbe0
#8  std::thread::_Impl<std::_Bind_simple<std::_Bind<std::_Mem_fn<void (icinga::ApiListener::*)(boost::intrusive_ptr<icinga::Socket> const&)> (icinga::ApiListener*, boost::intrusive_ptr<icinga::TcpSocket>)> ()> >::_M_run() [clone .local.10721] (this=0x229cbc8) at /usr/include/c++/4.8/thread:115
No locals.
#9  0x00007f6199ba1a60 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#10 0x00007f619a870184 in start_thread (arg=0x7f619697a700) at pthread_create.c:312
        __res = <optimized out>
        pd = 0x7f619697a700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140057115076352, -2254713775266350544, 0, 0, 140057115077056, 140057115076352, 2195092412610755120, 2195101067552471600},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#11 0x00007f619b71703d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

Thread 2 (Thread 0x7f6196939700 (LWP 20178)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
---Type <return> to continue, or q <return> to quit---
#1  0x00000000007c834b in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) [clone .local.16265] (this=this@entry=0x7f616c021c80, m=...)
    at /usr/include/boost/thread/pthread/condition_variable.hpp:73
        guard = {m = 0x0}
        check_for_interruption = {thread_info = 0x7f617c000c50, m = 0x7f616c021c80, set = false}
        res = <optimized out>
#2  0x00000000009ccf66 in icinga::CheckerComponent::CheckThreadProc (this=0x7f616c021bd0)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/checker/checkercomponent.cpp:113
        csi = {Object = {px = 0x7f6196938650}, NextCheck = 6,9197408881208953e-310}
        it = <optimized out>
        wait = <optimized out>
        checkable = {px = 0x3}
        check = <optimized out>
        lock = {m = 0x7f616c021c58, is_locked = false}
#3  0x00007f6199ba1a60 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#4  0x00007f619a870184 in start_thread (arg=0x7f6196939700) at pthread_create.c:312
        __res = <optimized out>
        pd = 0x7f6196939700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140057114810112, -2254713775266350544, 0, 0, 140057114810816, 140057114810112, 2195092378787887664, 2195101067552471600},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007f619b71703d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

Thread 1 (Thread 0x7f619bbf0780 (LWP 20165)):
#0  0x00007f619b6ddd4d in nanosleep () at ../sysdeps/unix/syscall-template.S:81
No locals.
#1  0x00007f619b70f014 in usleep (useconds=<optimized out>) at ../sysdeps/unix/sysv/linux/usleep.c:32
        ts = {tv_sec = 0, tv_nsec = 500000000}
#2  0x00000000005c481b in icinga::Utility::Sleep(double) (timeout=timeout@entry=2,5)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/base/utility.cpp:430
        micros = <optimized out>
#3  0x0000000000a5478d in icinga::Application::RunEventLoop (this=this@entry=0x7f616c0026f0)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/base/application.cpp:313
        now = <optimized out>
        timeDiff = <optimized out>
        lastLoop = 1531906842,617085
#4  0x0000000000a55a1f in icinga::IcingaApplication::Main (this=0x7f616c0026f0)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/icinga/icingaapplication.cpp:107
No locals.
#5  0x00000000007b4cf3 in icinga::Application::Run() (this=0x7f616c0026f0) at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/base/application.cpp:1014
        sa = {__sigaction_handler = {sa_handler = 0x7b4e50 <icinga::Application::SigUsr2Handler(int)>, sa_sigaction = 0x7b4e50 <icinga::Application::SigUsr2Handler(int)>}, sa_mask = {__val = {
              0 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0x0}
#6  0x00000000009855a1 in icinga::DaemonCommand::Run (this=<optimized out>, vm=..., ap=...)
    at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/lib/cli/daemoncommand.cpp:292
        configs = {<std::_Vector_base> = {_M_impl = {<std::allocator> = {<__gnu_cxx::new_allocator> = {<No data fields>}, <No data fields>}, _M_start = 0x2048600, _M_finish = 0x2048608,
              _M_end_of_storage = 0x2048608}}, <No data fields>}
        newItems = {<std::_Vector_base> = {_M_impl = {<std::allocator> = {<__gnu_cxx::new_allocator> = {<No data fields>}, <No data fields>}, _M_start = 0x229b080, _M_finish = 0x229b798,
              _M_end_of_storage = 0x229b880}}, <No data fields>}
        sa = {__sigaction_handler = {sa_handler = 0x5a7210 <SigHupHandler(int) [clone .340947]>, sa_sigaction = 0x5a7210 <SigHupHandler(int) [clone .340947]>}, sa_mask = {__val = {
              0 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0x0}
#7  0x0000000000981225 in Main () at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/icinga-app/icinga.cpp:573
        args = {<std::_Vector_base> = {_M_impl = {<std::allocator> = {<__gnu_cxx::new_allocator> = {<No data fields>}, <No data fields>}, _M_start = 0x0, _M_finish = 0x0,
              _M_end_of_storage = 0x0}}, <No data fields>}
        autocomplete = false
---Type <return> to continue, or q <return> to quit---
        cmdname = {m_Data = <unvollständiger Typ>}
        command = {px = 0x2041100}
        argc = 6
        autoindex = 0
        icingaGroup = {m_Data = <unvollständiger Typ>}
        visibleDesc = {m_caption = <unvollständiger Typ>, m_line_length = 80, m_min_description_length = 40, m_options = {<std::_Vector_base> = {
              _M_impl = {<std::allocator> = {<__gnu_cxx::new_allocator> = {<No data fields>}, <No data fields>}, _M_start = 0x2045f90, _M_finish = 0x2046050,
                _M_end_of_storage = 0x2046090}}, <No data fields>}, belong_to_group = {<std::_Bvector_base> = {
              _M_impl = {<std::allocator> = {<__gnu_cxx::new_allocator> = {<No data fields>}, <No data fields>}, _M_start = {<std::_Bit_iterator_base> = {<std::iterator> = {<No data fields>},
                    _M_p = 0x2044990, _M_offset = 0}, <No data fields>}, _M_finish = {<std::_Bit_iterator_base> = {<std::iterator> = {<No data fields>}, _M_p = 0x2044990,
                    _M_offset = 12}, <No data fields>}, _M_end_of_storage = 0x2044998}}, <No data fields>}, groups = {<std::_Vector_base> = {
              _M_impl = {<std::allocator> = {<__gnu_cxx::new_allocator> = {<No data fields>}, <No data fields>}, _M_start = 0x2045f70, _M_finish = 0x2045f80,
                _M_end_of_storage = 0x2045f80}}, <No data fields>}}
        positionalDesc = {m_names = {<std::_Vector_base> = {_M_impl = {<std::allocator> = {<__gnu_cxx::new_allocator> = {<No data fields>}, <No data fields>}, _M_start = 0x0, _M_finish = 0x0,
                _M_end_of_storage = 0x0}}, <No data fields>}, m_trailing = <unvollständiger Typ>}
        vm = <unvollständiger Typ>
        argv = 0x7ffde9962898
        icingaUser = {m_Data = <unvollständiger Typ>}
        hiddenDesc = {m_caption = <unvollständiger Typ>, m_line_length = 80, m_min_description_length = 40, m_options = {<std::_Vector_base> = {
              _M_impl = {<std::allocator> = {<__gnu_cxx::new_allocator> = {<No data fields>}, <No data fields>}, _M_start = 0x2045990, _M_finish = 0x20459c0,
                _M_end_of_storage = 0x20459d0}}, <No data fields>}, belong_to_group = {<std::_Bvector_base> = {
              _M_impl = {<std::allocator> = {<__gnu_cxx::new_allocator> = {<No data fields>}, <No data fields>}, _M_start = {<std::_Bit_iterator_base> = {<std::iterator> = {<No data fields>},
                    _M_p = 0x2045270, _M_offset = 0}, <No data fields>}, _M_finish = {<std::_Bit_iterator_base> = {<std::iterator> = {<No data fields>}, _M_p = 0x2045270,
                    _M_offset = 3}, <No data fields>}, _M_end_of_storage = 0x2045278}}, <No data fields>}, groups = {<std::_Vector_base> = {
              _M_impl = {<std::allocator> = {<__gnu_cxx::new_allocator> = {<No data fields>}, <No data fields>}, _M_start = 0x0, _M_finish = 0x0, _M_end_of_storage = 0x0}}, <No data fields>}}
        rc = 1
#8  0x00000000005a4257 in main (argc=6, argv=0x7ffde9962898) at /home/jenkins/workspace/icinga2-release/deb-ubuntu-trusty-1binary/arch/x86_64/icinga2/icinga-app/icinga.cpp:867
        rc = <optimized out>
(gdb)
dnsmichi commented 6 years ago

Ok, I just learned that Debian Jessie uses Systemd by default already, not Stretch. So the Debian problem only exists with Sysvinit and my tests were wrong.

BarbUk commented 6 years ago

@dnsmichi

We need more details on the specific setups, anything which has been modified from the default installation, e.g. zones.conf, enabled features, etc.

My vm is a debian 9.5 with sysVinit (no systemd). This is a default icinga2 installation with the following zones.conf

# cat /etc/icinga2/zones.conf 
/*
 * Generated by Icinga 2 node setup commands
 * on 2017-11-09 11:17:06 +0100
 */

object Endpoint NodeName {
}

object Zone ZoneName {
    endpoints = [ NodeName ]
}

object Zone "global-templates" {
  global = true
}

Non working process, started with /etc/init.d/icinga2 start

ps aux | grep [i]cinga2
nagios   24996  0.5  0.0 700124  6544 pts/0    S    11:33   0:01 /usr/lib/x86_64-linux-gnu/icinga2/sbin/icinga2 --no-stack-rlimit daemon -d -e /var/log/icinga2/icinga2.err
nagios   25006  4.7  0.4 1121824 143564 ?      Ssl  11:33   0:11 /usr/lib/x86_64-linux-gnu/icinga2/sbin/icinga2 --no-stack-rlimit daemon -d -e /var/log/icinga2/icinga2.err

Working process, started with icinga2 daemon -e /var/log/icinga2/icinga2.err

# ps aux | grep [i]cinga2
nagios    1560  134  1.0 4382928 355408 pts/0  Sl+  11:38   0:18 /usr/lib/x86_64-linux-gnu/icinga2/sbin/icinga2 --no-stack-rlimit daemon -e /var/log/icinga2/icinga2.err
nagios    1607  0.3  0.0 700124  6532 pts/0    S+   11:38   0:00 /usr/lib/x86_64-linux-gnu/icinga2/sbin/icinga2 --no-stack-rlimit daemon -e /var/log/icinga2/icinga2.err

gdb trace:

# gdb -p 9638
GNU gdb (Debian 7.12-6) 7.12.0.20161007-git
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 9638
[New LWP 9639]
[New LWP 9640]
[New LWP 9641]
[New LWP 9642]
[New LWP 9643]
[New LWP 9652]
[New LWP 9653]
[New LWP 9654]
[New LWP 9655]
[New LWP 9656]
[New LWP 9657]
[New LWP 9658]
[New LWP 9659]
[New LWP 9663]
[New LWP 9664]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007fa07611128d in nanosleep () at ../sysdeps/unix/syscall-template.S:84
84  ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) thread apply all bt full

Thread 16 (Thread 0x7fa072354700 (LWP 9664)):
#0  pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x000055fefc2f22db in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) (
    this=0x7fa0680036b8, m=...) at /usr/include/boost/thread/pthread/condition_variable.hpp:77
        guard = {m = 0x0}
        check_for_interruption = {thread_info = 0x7fa03c088fa0, m = 0x7fa0680036b8, set = true}
        the_mutex = 0x7fa0680036b8
        res = <optimized out>
#2  0x000055fefc32caab in icinga::WorkQueue::WorkerThreadProc() (this=0x7fa068003660)
    at ./lib/base/workqueue.cpp:280
        task = {Function = {_M_invoker = 0x0}, Priority = PriorityNormal, ID = -1}
        idbuf = <incomplete type>
        lock = {m = 0x7fa068003690, is_locked = false}
#3  0x00007fa0789e5116 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.62.0
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa072354700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa072354700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327087589120, -9173996681494900640, 0, 
                140327108698095, 0, 140327201681472, 9218744148300025952, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 15 (Thread 0x7fa078f79700 (LWP 9663)):
#0  pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x000055fefc2f22db in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) (
    this=0x7fa044003be0, m=...) at /usr/include/boost/thread/pthread/condition_variable.hpp:77
        guard = {m = 0x0}
        check_for_interruption = {thread_info = 0x7fa03c9e46b0, m = 0x7fa044003be0, set = true}
        the_mutex = 0x7fa044003be0
        res = <optimized out>
#2  0x000055fefc32caab in icinga::WorkQueue::WorkerThreadProc() (this=0x7fa044003b88)
---Type <return> to continue, or q <return> to quit---
    at ./lib/base/workqueue.cpp:280
        task = {Function = {_M_invoker = 0x0}, Priority = PriorityNormal, ID = -1}
        idbuf = <incomplete type>
        lock = {m = 0x7fa044003bb8, is_locked = false}
#3  0x00007fa0789e5116 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.62.0
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa078f79700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa078f79700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327200986880, -9173996681494900640, 0, 
                140327108694639, 140327200986880, 94553650733424, 9218757871257407584, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 14 (Thread 0x7fa078f38700 (LWP 9659)):
#0  0x00007fa07613867d in poll () at ../sysdeps/unix/syscall-template.S:84
No locals.
#1  0x000055fefc36896e in poll () at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
        __timeout = 500
        __nfds = 1
        __fds = 0x7fa05c21bb20
#2  icinga::Process::IOThreadProc(int) (tid=3) at ./lib/base/process.cpp:688
        timeout = 500
        rc = <optimized out>
        pfds = 0x7fa05c21bb20
        count = 1
        now = 1531907197.9020679
#3  0x00007fa0769cce6f in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa078f38700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa078f38700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327200720640, -9173996681494900640, 0, 
                140327108428847, 140327200720640, 94553650716944, 9218757907227758688, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
---Type <return> to continue, or q <return> to quit---
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 13 (Thread 0x7fa072db4700 (LWP 9658)):
#0  0x00007fa07613867d in poll () at ../sysdeps/unix/syscall-template.S:84
No locals.
#1  0x000055fefc36896e in poll () at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
        __timeout = 56099
        __nfds = 24
        __fds = 0x7fa0540cba00
#2  icinga::Process::IOThreadProc(int) (tid=2) at ./lib/base/process.cpp:688
        timeout = 56099.134922027588
        rc = <optimized out>
        pfds = 0x7fa0540cba00
        count = 24
        now = 1531907197.95768
#3  0x00007fa0769cce6f in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa072db4700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa072db4700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327098468096, -9173996681494900640, 0, 
                140327108428847, 140327098468096, 94553657822624, 9218744371638325344, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 12 (Thread 0x7fa072df5700 (LWP 9657)):
#0  0x00007fa07613867d in poll () at ../sysdeps/unix/syscall-template.S:84
No locals.
#1  0x000055fefc36896e in poll () at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
        __timeout = 500
        __nfds = 1
---Type <return> to continue, or q <return> to quit---
        __fds = 0x7fa04cd54f20
#2  icinga::Process::IOThreadProc(int) (tid=1) at ./lib/base/process.cpp:688
        timeout = 500
        rc = <optimized out>
        pfds = 0x7fa04cd54f20
        count = 1
        now = 1531907197.901396
#3  0x00007fa0769cce6f in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa072df5700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa072df5700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327098734336, -9173996681494900640, 0, 
                140327108428847, 140327098734336, 94553656618048, 9218744335667974240, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 11 (Thread 0x7fa072e36700 (LWP 9656)):
#0  0x00007fa07613867d in poll () at ../sysdeps/unix/syscall-template.S:84
No locals.
#1  0x000055fefc36896e in poll () at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
        __timeout = 56040
        __nfds = 34
        __fds = 0x7fa044d53220
#2  icinga::Process::IOThreadProc(int) (tid=0) at ./lib/base/process.cpp:688
        timeout = 56040.596008300781
        rc = <optimized out>
        pfds = 0x7fa044d53220
        count = 34
        now = 1531907197.980864
#3  0x00007fa0769cce6f in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa072e36700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa072e36700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327099000576, -9173996681494900640, 0, 
---Type <return> to continue, or q <return> to quit---
                140327108428847, 140327099000576, 94553658293760, 9218744576723013728, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 10 (Thread 0x7fa072e77700 (LWP 9655)):

#0  pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
No locals.
#1  0x000055fefc5862a4 in do_wait_until (timeout=..., m=..., this=0x7fa0500e2d28)
    at /usr/include/boost/thread/pthread/condition_variable.hpp:109
        guard = {m = 0x7fa072e76020}
        check_for_interruption = {thread_info = 0x7fa058277390, m = 0x7fa0500e2d28, 
          set = false}
        the_mutex = 0x7fa0500e2d28
        cond_res = <optimized out>
#2  timed_wait () at /usr/include/boost/thread/pthread/condition_variable_fwd.hpp:128
No locals.
#3  timed_wait (wait_duration=..., m=..., this=0x7fa0500e2d28)
    at /usr/include/boost/thread/pthread/condition_variable_fwd.hpp:152
        m = @0x7fa072e76020: {m = 0x7fa0500e2d00, is_locked = false}
        this = 0x7fa0500e2d28
#4  icinga::CheckerComponent::CheckThreadProc() (this=0x7fa0500e2c00)
    at ./lib/checker/checkercomponent.cpp:128
        csi = {Object = {px = 0x7fa04c75b990}, NextCheck = <optimized out>}
        it = <optimized out>
        wait = <optimized out>
        checkable = {px = 0x7fa0380fe320}
        check = <optimized out>
        lock = {m = 0x7fa0500e2d00, is_locked = false}
#5  0x00007fa0769cce6f in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#6  0x00007fa077a07494 in start_thread (arg=0x7fa072e77700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa072e77700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327099266816, -9173996681494900640, 0, 
                140737347817391, 140327099266816, 94553655278656, 9218744540752662624, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
---Type <return> to continue, or q <return> to quit---
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#7  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 9 (Thread 0x7fa072eb8700 (LWP 9654)):
#0  0x00007fa07613867d in poll () at ../sysdeps/unix/syscall-template.S:84
No locals.
#1  0x000055fefc352de0 in poll () at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
        __timeout = <optimized out>
        __nfds = 1
        __fds = 0x7fa072eb53a8
#2  icinga::Socket::Poll(bool, bool, timeval*) (this=<optimized out>, read=<optimized out>, 
    write=<optimized out>, timeout=0x0) at ./lib/base/socket.cpp:387
        rc = <optimized out>
        pfd = {fd = 16, events = 1, revents = 0}
        __PRETTY_FUNCTION__ = "bool icinga::Socket::Poll(bool, bool, timeval*)"
#3  0x000055fefc5780a6 in icinga::ExternalCommandListener::CommandPipeThread(icinga::String const&) (this=<optimized out>, commandPath=...) at ./lib/compat/externalcommandlistener.cpp:124
        buffer = "\300^\353r\240\177\000\000\f\000\000\000\000\000\000\000Command Pipe\000\177\000\000\a\000\000\000\240\177\001\001\061\000\000\000\062\000\000\000\062\000\000\000\060\000\000\000\060\000\000\000\060\000\000\000\060\000\000\000\060\000\000\000\060\000\000\000\060\000\000\000\220_\353r\240\177\000\000P_\353r\240\177\000\000\060\000\000\000\060\000\000\000\060b\353r\240\177\000\000\000\000\000\000\000\000\000\000\240\a\033v\240\177\000\000\306\377\377\377\000\000\000\000\260f\353r\240\177\000\000\000\000\000\000\000\000\000\000<C\nv\240\177\000\000\000\000\000\000\000\000\000Ƞa\353r\240\177\000\000\020b\353r\240\177\000\000\067\000\000\000\000\000\000\000\270_\353r\240\177\000\000\000\000\000\000\000\000\000\000"...
        rc = <optimized out>
        fd = <optimized out>
        fifo = {px = 0x7fa040111ce0}
        sock = {px = 0x7fa040001710}
        src = {Buffer = 0x0, Size = 0, MustRead = true, Eof = false}
        statbuf = {st_dev = 59, st_ino = 15102, st_nlink = 1, st_mode = 4528, st_uid = 116, 
          st_gid = 33, __pad0 = 0, st_rdev = 0, st_size = 0, st_blksize = 4096, st_blocks = 0, 
          st_atim = {tv_sec = 1517809722, tv_nsec = 143999615}, st_mtim = {
            tv_sec = 1517809722, tv_nsec = 143999615}, st_ctim = {tv_sec = 1531907105, 
            tv_nsec = 723346489}, __glibc_reserved = {0, 0, 0}}
        fifo_ok = <optimized out>
        __PRETTY_FUNCTION__ = "void icinga::ExternalCommandListener::CommandPipeThread(const icinga::String&)"
        mode = <optimized out>
---Type <return> to continue, or q <return> to quit---
#4  0x00007fa0769cce6f in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#5  0x00007fa077a07494 in start_thread (arg=0x7fa072eb8700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa072eb8700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327099533056, -9173996681494900640, 0, 
                140737347817407, 140327099533056, 94553656344192, 9218744506929795168, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#6  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 8 (Thread 0x7fa078ffb700 (LWP 9653)):
#0  0x00007fa077a103ed in accept () at ../sysdeps/unix/syscall-template.S:84
No locals.

#1  0x000055fefc353017 in icinga::Socket::Accept() (this=<optimized out>)
    at ./lib/base/socket.cpp:328
        addr = {ss_family = 3, 
          __ss_padding = "\000\000\240\177\000\000x /\374\376U\000\000(\227\237\367\377\177\000\000\000\000\000\000\000\000\000\000ѱ\240w\240\177\000\000\000SOAD$U\235\004\000\000\000\000\000\000\000\000SOAD$U\235\260\252\377x\240\177", '\000' <repeats 19 times>, "SOAD$U\235\240\250\027\375\376U\000\000\000\000\000\000\000\000\000\000@\000\000\000\000\000\000", 
          __ss_align = 140327195137448}
        addrlen = 128
        fd = <optimized out>
        __PRETTY_FUNCTION__ = "icinga::Socket::Ptr icinga::Socket::Accept()"

#2  0x000055fefc3febe6 in icinga::ApiListener::ListenerThreadProc(boost::intrusive_ptr<icinga::Socket> const&) (this=0x7fa0500c3a60, server=...) at ./lib/remote/apilistener.cpp:350
        client = {px = 0x0}
        thread = {_M_id = {_M_thread = 0}}
#3  0x000055fefc462736 in _ZSt13__invoke_implIvRKMN6icinga11ApiListenerEFvRKN5boost13intrusive_ptrINS0_6SocketEEEERPS1_JRNS3_INS0_9TcpSocketEEEEET_St21__invoke_memfun_derefOT0_OT1_DpOT2_.isra.3241 (__args#0=..., __f=
    @0x55fefdc31338: (void (ApiListener::*)(struct ApiListener *, const struct intrusive_ptr &)) 0x55fefc3feb30 <icinga::ApiListener::ListenerThreadProc(boost::intrusive_ptr<icinga::Socket> const&)>) at /usr/include/c++/6/functional:227
No locals.
#4  std::__invoke<void (icinga::ApiListener::* const&)(boost::intrusive_ptr<icinga::Socket> const&), icinga::ApiListener*&, boost::intrusive_ptr<icinga::TcpSocket>&>(void (icinga::ApiListener:---Type <return> to continue, or q <return> to quit---
:* const&)(boost::intrusive_ptr<icinga::Socket> const&), icinga::ApiListener*&, boost::intrusive_ptr<icinga::TcpSocket>&) () at /usr/include/c++/6/functional:251
        __fn = @0x55fefdc31338: (void (ApiListener::*)(struct ApiListener *, 
    const struct intrusive_ptr &)) 0x55fefc3feb30 <icinga::ApiListener::ListenerThreadProc(boost::intrusive_ptr<icinga::Socket> const&)>
#5  std::_Mem_fn_base<void (icinga::ApiListener::*)(boost::intrusive_ptr<icinga::Socket> const&), true>::operator()<icinga::ApiListener*&, boost::intrusive_ptr<icinga::TcpSocket>&>(icinga::ApiListener*&, boost::intrusive_ptr<icinga::TcpSocket>&) const ()
    at /usr/include/c++/6/functional:604
No locals.
#6  std::_Bind<std::_Mem_fn<void (icinga::ApiListener::*)(boost::intrusive_ptr<icinga::Socket> const&)> (icinga::ApiListener*, boost::intrusive_ptr<icinga::TcpSocket>)>::__call<void, , 0ul, 1ul>(std::tuple<>&&, std::_Index_tuple<0ul, 1ul>) () at /usr/include/c++/6/functional:934
No locals.
#7  std::_Bind<std::_Mem_fn<void (icinga::ApiListener::*)(boost::intrusive_ptr<icinga::Socket> const&)> (icinga::ApiListener*, boost::intrusive_ptr<icinga::TcpSocket>)>::operator()<, void>()
    () at /usr/include/c++/6/functional:993
No locals.
#8  std::_Bind_simple<std::_Bind<std::_Mem_fn<void (icinga::ApiListener::*)(boost::intrusive_ptr<icinga::Socket> const&)> (icinga::ApiListener*, boost::intrusive_ptr<icinga::TcpSocket>)> ()>::_M_invoke<>(std::_Index_tuple<>) () at /usr/include/c++/6/functional:1391
        this = 0x55fefdc31338
#9  std::_Bind_simple<std::_Bind<std::_Mem_fn<void (icinga::ApiListener::*)(boost::intrusive_ptr<icinga::Socket> const&)> (icinga::ApiListener*, boost::intrusive_ptr<icinga::TcpSocket>)> ()>::operator()() () at /usr/include/c++/6/functional:1380
        this = 0x55fefdc31338
#10 _M_run (this=0x55fefdc31330) at /usr/include/c++/6/thread:197
No locals.
#11 0x00007fa0769cce6f in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#12 0x00007fa077a07494 in start_thread (arg=0x7fa078ffb700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa078ffb700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327201519360, -9173996681494900640, 0, 
                140737347815535, 140327201519360, 94553650745664, 9218757801464189024, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#13 0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.
---Type <return> to continue, or q <return> to quit---

Thread 7 (Thread 0x7fa078fba700 (LWP 9652)):
#0  pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x000055fefc2f22db in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) (
    this=0x7fa0500c3e68, m=...) at /usr/include/boost/thread/pthread/condition_variable.hpp:77
        guard = {m = 0x0}
        check_for_interruption = {thread_info = 0x55fefd90c290, m = 0x7fa0500c3e68, set = true}
        the_mutex = 0x7fa0500c3e68
        res = <optimized out>
#2  0x000055fefc32caab in icinga::WorkQueue::WorkerThreadProc() (this=0x7fa0500c3e10)
    at ./lib/base/workqueue.cpp:280
        task = {Function = {_M_invoker = 0x0}, Priority = PriorityNormal, ID = -1}
        idbuf = <incomplete type>
        lock = {m = 0x7fa0500c3e40, is_locked = false}
#3  0x00007fa0789e5116 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.62.0
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa078fba700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa078fba700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327201253120, -9173996681494900640, 0, 
                140737347815327, 140327201253120, 94553650719632, 9218757837434540128, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 6 (Thread 0x7fa078ef7700 (LWP 9643)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
No locals.
#1  0x000055fefc33a23b in do_wait_until (timeout=..., m=..., 
    this=0x55fefcbd17f0 <icinga::Application::GetTP()::tp+400>)
    at /usr/include/boost/thread/pthread/condition_variable.hpp:109
        guard = {m = 0x7fa078ef6890}
        check_for_interruption = {thread_info = 0x7fa060000c60, 
          m = 0x55fefcbd17f0 <icinga::Application::GetTP()::tp+400>, set = false}
        the_mutex = 0x55fefcbd17f0 <icinga::Application::GetTP()::tp+400>
---Type <return> to continue, or q <return> to quit---
        cond_res = <optimized out>
#2  timed_wait (this=<optimized out>, m=..., abs_time=...)
    at /usr/include/boost/thread/pthread/condition_variable_fwd.hpp:128
No locals.
#3  timed_wait (wait_duration=..., m=..., 
    this=0x55fefcbd17f0 <icinga::Application::GetTP()::tp+400>)
    at /usr/include/boost/thread/pthread/condition_variable_fwd.hpp:152
        m = @0x7fa078ef6890: {m = 0x55fefcbd17c8 <icinga::Application::GetTP()::tp+360>, 
          is_locked = false}
        this = 0x55fefcbd17f0 <icinga::Application::GetTP()::tp+400>
#4  icinga::ThreadPool::ManagerThreadProc() (
    this=0x55fefcbd1660 <icinga::Application::GetTP()::tp>) at ./lib/base/threadpool.cpp:239
        lock = {m = 0x55fefcbd17c8 <icinga::Application::GetTP()::tp+360>, is_locked = false}
        total_utilization = 0
        total_pending = 0
        total_alive = 0
        total_avg_latency = 0
        now = <optimized out>

        idbuf = <incomplete type>
        lastStats = 1531907189.3549099
#5  0x00007fa0769cce6f in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#6  0x00007fa077a07494 in start_thread (arg=0x7fa078ef7700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa078ef7700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327200454400, -9173996681494900640, 0, 
                140737347819855, 140327200454400, 94553650742528, 9218757666172719200, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#7  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 5 (Thread 0x7fa073737700 (LWP 9642)):
#0  pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x000055fefc33c89b in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) (
    m=..., this=0x55fefcbd2238 <icinga::Application::GetTP()::tp+3032>)
    at /usr/include/boost/thread/pthread/condition_variable.hpp:77
---Type <return> to continue, or q <return> to quit---
        guard = {m = 0x0}
        check_for_interruption = {thread_info = 0x55fefd08aca0, 
          m = 0x55fefcbd2238 <icinga::Application::GetTP()::tp+3032>, set = true}
        the_mutex = 0x55fefcbd2238 <icinga::Application::GetTP()::tp+3032>
        res = <optimized out>
#2  icinga::ThreadPool::WorkerThread::ThreadProc(icinga::ThreadPool::Queue&) (
    this=0x55fefcbd2350 <icinga::Application::GetTP()::tp+3312>, queue=...)
    at ./lib/base/threadpool.cpp:110
        lock = {m = 0x55fefcbd2210 <icinga::Application::GetTP()::tp+2992>, is_locked = false}
        wi = {Callback = {
            _M_invoker = 0x55fefc56a320 <std::_Function_handler<void (), std::_Bind<std::_Mem_fn<void (icinga::CheckerComponent::*)(boost::intrusive_ptr<icinga::Checkable> const&)> (boost::intrusive_ptr<icinga::CheckerComponent>, boost::intrusive_ptr<icinga::Checkable>)> >::_M_invoke(std::_Any_data const&)>}, Timestamp = 1531907198.0027609}
        st = <optimized out>
        et = <optimized out>
        latency = <optimized out>
        idbuf = <incomplete type>
        lock = {m = 0x55fefcbd2210 <icinga::Application::GetTP()::tp+2992>, is_locked = true}
#3  0x00007fa0789e5116 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.62.0
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa073737700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa073737700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327108441856, -9173996681494900640, 0, 
                140737347819215, 140327108441856, 94553650746448, 9218741414016471136, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 4 (Thread 0x7fa073778700 (LWP 9641)):
#0  pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x000055fefc33c89b in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) (
    m=..., this=0x55fefcbd1ef8 <icinga::Application::GetTP()::tp+2200>)
    at /usr/include/boost/thread/pthread/condition_variable.hpp:77
        guard = {m = 0x0}
---Type <return> to continue, or q <return> to quit---
        check_for_interruption = {thread_info = 0x55fefd2c2730, 
          m = 0x55fefcbd1ef8 <icinga::Application::GetTP()::tp+2200>, set = true}
        the_mutex = 0x55fefcbd1ef8 <icinga::Application::GetTP()::tp+2200>
        res = <optimized out>
#2  icinga::ThreadPool::WorkerThread::ThreadProc(icinga::ThreadPool::Queue&) (
    this=0x55fefcbd2010 <icinga::Application::GetTP()::tp+2480>, queue=...)
    at ./lib/base/threadpool.cpp:110
        lock = {m = 0x55fefcbd1ed0 <icinga::Application::GetTP()::tp+2160>, is_locked = false}
        wi = {Callback = {
            _M_invoker = 0x55fefc56a320 <std::_Function_handler<void (), std::_Bind<std::_Mem_fn<void (icinga::CheckerComponent::*)(boost::intrusive_ptr<icinga::Checkable> const&)> (boost::intrusive_ptr<icinga::CheckerComponent>, boost::intrusive_ptr<icinga::Checkable>)> >::_M_invoke(std::_Any_data const&)>}, Timestamp = 1531907197.9968171}
        st = <optimized out>
        et = <optimized out>
        latency = <optimized out>

        idbuf = <incomplete type>
        lock = {m = 0x55fefcbd1ed0 <icinga::Application::GetTP()::tp+2160>, is_locked = true}
#3  0x00007fa0789e5116 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.62.0
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa073778700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa073778700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327108708096, -9173996681494900640, 0, 
                140737347819215, 140327108708096, 94553650745168, 9218741380193603680, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 3 (Thread 0x7fa078e75700 (LWP 9640)):
#0  pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x000055fefc33c89b in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) (
    m=..., this=0x55fefcbd1bb8 <icinga::Application::GetTP()::tp+1368>)
    at /usr/include/boost/thread/pthread/condition_variable.hpp:77
        guard = {m = 0x0}
        check_for_interruption = {thread_info = 0x55fefd3a93b0, 
---Type <return> to continue, or q <return> to quit---
          m = 0x55fefcbd1bb8 <icinga::Application::GetTP()::tp+1368>, set = true}
        the_mutex = 0x55fefcbd1bb8 <icinga::Application::GetTP()::tp+1368>
        res = <optimized out>
#2  icinga::ThreadPool::WorkerThread::ThreadProc(icinga::ThreadPool::Queue&) (
    this=0x55fefcbd1cd0 <icinga::Application::GetTP()::tp+1648>, queue=...)
    at ./lib/base/threadpool.cpp:110
        lock = {m = 0x55fefcbd1b90 <icinga::Application::GetTP()::tp+1328>, is_locked = false}
        wi = {Callback = {
            _M_invoker = 0x55fefc56a320 <std::_Function_handler<void (), std::_Bind<std::_Mem_fn<void (icinga::CheckerComponent::*)(boost::intrusive_ptr<icinga::Checkable> const&)> (boost::intrusive_ptr<icinga::CheckerComponent>, boost::intrusive_ptr<icinga::Checkable>)> >::_M_invoke(std::_Any_data const&)>}, Timestamp = 1531907197.985168}
        st = <optimized out>
        et = <optimized out>
        latency = <optimized out>
        idbuf = <incomplete type>
        lock = {m = 0x55fefcbd1b90 <icinga::Application::GetTP()::tp+1328>, is_locked = true}
#3  0x00007fa0789e5116 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.62.0
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa078e75700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa078e75700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327199921920, -9173996681494900640, 0, 
                140737347819215, 140327199921920, 94553650744288, 9218757735965937760, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 2 (Thread 0x7fa078eb6700 (LWP 9639)):
#0  pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x000055fefc33c89b in boost::condition_variable::wait(boost::unique_lock<boost::mutex>&) (
    m=..., this=0x55fefcbd1878 <icinga::Application::GetTP()::tp+536>)
    at /usr/include/boost/thread/pthread/condition_variable.hpp:77
        guard = {m = 0x0}

        check_for_interruption = {thread_info = 0x55fefd086040, 
          m = 0x55fefcbd1878 <icinga::Application::GetTP()::tp+536>, set = true}
---Type <return> to continue, or q <return> to quit---
        the_mutex = 0x55fefcbd1878 <icinga::Application::GetTP()::tp+536>
        res = <optimized out>
#2  icinga::ThreadPool::WorkerThread::ThreadProc(icinga::ThreadPool::Queue&) (
    this=0x55fefcbd1990 <icinga::Application::GetTP()::tp+816>, queue=...)
    at ./lib/base/threadpool.cpp:110
        lock = {m = 0x55fefcbd1850 <icinga::Application::GetTP()::tp+496>, is_locked = false}
        wi = {Callback = {
            _M_invoker = 0x55fefc56a320 <std::_Function_handler<void (), std::_Bind<std::_Mem_fn<void (icinga::CheckerComponent::*)(boost::intrusive_ptr<icinga::Checkable> const&)> (boost::intrusive_ptr<icinga::CheckerComponent>, boost::intrusive_ptr<icinga::Checkable>)> >::_M_invoke(std::_Any_data const&)>}, Timestamp = 1531907197.9830339}
        st = <optimized out>
        et = <optimized out>
        latency = <optimized out>
        idbuf = <incomplete type>
        lock = {m = 0x55fefcbd1850 <icinga::Application::GetTP()::tp+496>, is_locked = true}
#3  0x00007fa0789e5116 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.62.0
No symbol table info available.
#4  0x00007fa077a07494 in start_thread (arg=0x7fa078eb6700) at pthread_create.c:333
        __res = <optimized out>
        pd = 0x7fa078eb6700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140327200188160, -9173996681494900640, 0, 
                140737347819215, 140327200188160, 94553650743408, 9218757702143070304, 
                9218734155818881120}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 
              0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007fa076141acf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
No locals.

Thread 1 (Thread 0x7fa079004740 (LWP 9638)):
#0  0x00007fa07611128d in nanosleep () at ../sysdeps/unix/syscall-template.S:84
No locals.
#1  0x00007fa0761111da in __sleep (seconds=0) at ../sysdeps/posix/sleep.c:55
        save_errno = 2
        ts = {tv_sec = 0, tv_nsec = 916007179}
#2  0x000055fefc304ed6 in icinga::Utility::Sleep(double) () at ./lib/base/utility.cpp:428
        micros = 2500000
        timeout = 2.5

#3  icinga::Application::RunEventLoop() (this=this@entry=0x7fa06800ad10)
    at ./lib/base/application.cpp:313
---Type <return> to continue, or q <return> to quit---
        now = <optimized out>
        timeDiff = <optimized out>
        lastLoop = 1531907196.9296031
#4  0x000055fefc4a1884 in icinga::IcingaApplication::Main() (this=0x7fa06800ad10)
    at ./lib/icinga/icingaapplication.cpp:107
No locals.

#5  0x000055fefc30356c in icinga::Application::Run() (this=0x7fa06800ad10)
    at ./lib/base/application.cpp:1014
        sa = {__sigaction_handler = {
            sa_handler = 0x55fefc3036c0 <icinga::Application::SigUsr2Handler(int)>, 
            sa_sigaction = 0x55fefc3036c0 <icinga::Application::SigUsr2Handler(int)>}, 
          sa_mask = {__val = {0 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0x0}
#6  0x000055fefc4f519e in icinga::DaemonCommand::Run(boost::program_options::variables_map const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&) const (this=<optimized out>, vm=..., ap=...) at ./lib/cli/daemoncommand.cpp:292
        configs = {<No data fields>}
        newItems = {<No data fields>}
        sa = {__sigaction_handler = {sa_handler = 0x55fefc4d0770 <SigHupHandler>, 
            sa_sigaction = 0x55fefc4d0770 <SigHupHandler>}, sa_mask = {__val = {
              0 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0x0}
#7  0x000055fefc30857e in Main () at ./icinga-app/icinga.cpp:573
        args = {<No data fields>}
        argc = 6
        argv = 0x7ffff79fe178
        autocomplete = <optimized out>
        autoindex = 0
        icingaUser = {m_Data = <incomplete type>}

        icingaGroup = {m_Data = <incomplete type>}
        visibleDesc = {m_caption = <incomplete type>, m_line_length = 80, 
          m_min_description_length = 40, m_options = {<No data fields>}, 
          belong_to_group = {<No data fields>}, groups = {<No data fields>}}
        hiddenDesc = {m_caption = <incomplete type>, m_line_length = 80, 
          m_min_description_length = 40, m_options = {<No data fields>}, 
          belong_to_group = {<No data fields>}, groups = {<No data fields>}}
        positionalDesc = {m_names = {<No data fields>}, m_trailing = <incomplete type>}
        cmdname = {m_Data = <incomplete type>}
        command = {px = 0x55fefcc4a3f0}

        vm = <incomplete type>
        rc = 1
#8  0x000055fefc2b1349 in main (argc=6, argv=0x7ffff79fe178) at ./icinga-app/icinga.cpp:867
        rc = <optimized out>
mgollo commented 6 years ago

I have experienced this issue as well. I have a master running Debian Stretch and a Client running Jessie. After upgrading both, the cluster checks immediately showed a broken cluster. I couldn't see anything helpful in the logs. After downgrading the Jessie machine to 2.8.4 (the master still on 2.9.0), everything worked fine again. Tcpdump did show some packets being exchanged between the instances before the downgrade, but it didn't look as if these packages were properly handled on the Jessie machine.

dnsmichi commented 6 years ago

Short one-line update: It has to do something with daemonize / Daemonize() which only happens with sysvinit or manually. Currently investigating with @Al2Klimov and @Crunsher.

Icebird2000 commented 6 years ago

Also Gentoo is affected.

icinga2 --version

icinga2 - The Icinga 2 network monitoring daemon (version: r2.9.0-1)

Copyright (c) 2012-2018 Icinga Development Team (https://www.icinga.com/) License GPLv2+: GNU GPL version 2 or later http://gnu.org/licenses/gpl2.html This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law.

Application information: Installation root: /usr Sysconf directory: /etc Run directory: /var/run Local state directory: /var Package data directory: /usr/share/icinga2 State path: /var/lib/icinga2/icinga2.state Modified attributes path: /var/lib/icinga2/modified-attributes.conf Objects path: /var/cache/icinga2/icinga2.debug Vars path: /var/cache/icinga2/icinga2.vars PID path: /var/run/icinga2/icinga2.pid

System information: Platform: Gentoo Platform version: Unknown Kernel: Linux Kernel version: 4.14.52 Architecture: x86_64

Build information: Compiler: GNU 7.3.0 Build host: max

icinga2 feature list

Disabled features: compatlog debuglog elasticsearch gelf graphite opentsdb perfdata statusdata syslog Enabled features: api checker command ido-mysql influxdb livestatus mainlog notification

But if i start icinga2 without -d it works, but give me another strange error:

[2018-07-18 15:18:20 +0200] critical/TcpSocket: Invalid socket: Connection timed out [2018-07-18 15:18:20 +0200] critical/ApiListener: Cannot connect to host '21X.XX.XX.9' on port '5665' [2018-07-18 15:18:20 +0200] information/ApiListener: Finished reconnecting to endpoint 'server1' via host '21X.XX.XX.9' and port '5665'

Context: (0) Handling new API client connection

openssl version

OpenSSL 1.0.2o 27 Mar 2018

dnsmichi commented 6 years ago

@sidescraper that's a different issue tracked in #6442, please add your findings there.

Al2Klimov commented 6 years ago

7d7eaa8dd35c23ed8de9112343ece3b5b7bdbd73 is the first bad commit commit 7d7eaa8dd35c23ed8de9112343ece3b5b7bdbd73 Author: Gunnar Beutner gunnar.beutner@icinga.com Date: Tue Nov 21 12:12:58 2017 +0100

Replace boost::thread with std::thread

:040000 040000 2638f6328ca94a5f2f720dad9435400cc98d87d8 a30c36a111c1b982c68174e4ec24791cee897d71 M icinga-app :040000 040000 43d2b23a20b89fce2d096f50d5e31cbab32c9781 283f48c1d7b443f5be3a98382e49fda6c0f24fbb M lib

Al2Klimov commented 6 years ago 
icinga2 - The Icinga 2 network monitoring daemon (version: v2.8.0-52-g7d7eaa8)

Copyright (c) 2012-2017 Icinga Development Team (https://www.icinga.com/)
License GPLv2+: GNU GPL version 2 or later <http://gnu.org/licenses/gpl2.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Application information:
  Installation root: /opt/icinga2
  Sysconf directory: /opt/icinga2/etc
  Run directory: /opt/icinga2/var/run
  Local state directory: /opt/icinga2/var
  Package data directory: /opt/icinga2/share/icinga2
  State path: /opt/icinga2/var/lib/icinga2/icinga2.state
  Modified attributes path: /opt/icinga2/var/lib/icinga2/modified-attributes.conf
  Objects path: /opt/icinga2/var/cache/icinga2/icinga2.debug
  Vars path: /opt/icinga2/var/cache/icinga2/icinga2.vars
  PID path: /opt/icinga2/var/run/icinga2/icinga2.pid

System information:
  Platform: CentOS
  Platform version: 6.9 (Final)
  Kernel: Linux
  Kernel version: 2.6.32-696.30.1.el6.x86_64
  Architecture: x86_64

Build information:
  Compiler: GNU 4.8.2
  Build host: centos-6.9-x86_64
stearz commented 6 years ago

We have the same issue in Amazon Linux on AWS after upgrading from 2.8.4 to 2.9.0-1

gdb -p 341
GNU gdb (GDB) Amazon Linux (7.6.1-64.33.amzn1)
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-amazon-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 341
Reading symbols from /usr/lib64/icinga2/sbin/icinga2...Reading symbols from /usr/lib/debug/usr/lib64/icinga2/sbin/icinga2.debug...
warning: Skipping deprecated .gdb_index section in /usr/lib/debug/usr/lib64/icinga2/sbin/icinga2.debug.
Do "set use-deprecated-index-sections on" before the file is read
to use the section anyway.
done.
done.
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /usr/lib64/libboost_thread.so.1.53.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libboost_thread.so.1.53.0
Reading symbols from /usr/lib64/libboost_system.so.1.53.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libboost_system.so.1.53.0
Reading symbols from /usr/lib64/libboost_program_options.so.1.53.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libboost_program_options.so.1.53.0
Reading symbols from /usr/lib64/libboost_regex.so.1.53.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libboost_regex.so.1.53.0
Reading symbols from /lib64/libssl.so.10...(no debugging symbols found)...done.
Loaded symbols for /lib64/libssl.so.10
Reading symbols from /lib64/libcrypto.so.10...(no debugging symbols found)...done.
Loaded symbols for /lib64/libcrypto.so.10
Reading symbols from /usr/lib64/libedit.so.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libedit.so.0
Reading symbols from /lib64/libtinfo.so.5...(no debugging symbols found)...done.
Loaded symbols for /lib64/libtinfo.so.5
Reading symbols from /usr/lib64/libstdc++.so.6...Missing separate debuginfo for /usr/lib64/libstdc++.so.6
Try: yum --enablerepo='*debug*' install /usr/lib/debug/.build-id/0f/007cd9b5110f4ed296d5ec8f28c18f8866899d.debug
(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libstdc++.so.6
Reading symbols from /lib64/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libm.so.6
Reading symbols from /lib64/libgcc_s.so.1...Missing separate debuginfo for /lib64/libgcc_s.so.1
Try: yum --enablerepo='*debug*' install /usr/lib/debug/.build-id/43/b97f743bee26b9f2a3f2272776dc6ec16c8903.debug
(no debugging symbols found)...done.
Loaded symbols for /lib64/libgcc_s.so.1
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /lib64/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/librt.so.1
Reading symbols from /usr/lib64/libicuuc.so.50...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libicuuc.so.50
Reading symbols from /usr/lib64/libicui18n.so.50...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libicui18n.so.50
Reading symbols from /usr/lib64/libicudata.so.50...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libicudata.so.50
Reading symbols from /usr/lib64/libgssapi_krb5.so.2...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libgssapi_krb5.so.2
Reading symbols from /usr/lib64/libkrb5.so.3...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libkrb5.so.3
Reading symbols from /usr/lib64/libcom_err.so.2...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libcom_err.so.2
Reading symbols from /usr/lib64/libk5crypto.so.3...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libk5crypto.so.3
Reading symbols from /lib64/libz.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libz.so.1
Reading symbols from /lib64/libncurses.so.5...(no debugging symbols found)...done.
Loaded symbols for /lib64/libncurses.so.5
Reading symbols from /usr/lib64/libkrb5support.so.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libkrb5support.so.0
Reading symbols from /lib64/libkeyutils.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libkeyutils.so.1
Reading symbols from /lib64/libresolv.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libresolv.so.2
Reading symbols from /usr/lib64/libselinux.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libselinux.so.1
Reading symbols from /lib64/libnss_files.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libnss_files.so.2
0x00007f5a87f61c0d in recvmsg () from /lib64/libpthread.so.0
Missing separate debuginfos, use: debuginfo-install boost-program-options-1.53.2-14.23.amzn1.x86_64 boost-regex-1.53.2-14.23.amzn1.x86_64 boost-system-1.53.2-14.23.amzn1.x86_64 glibc-2.17-222.173.amzn1.x86_64 keyutils-libs-1.5.8-3.12.amzn1.x86_64 krb5-libs-1.15.1-8.43.amzn1.x86_64 libboost_thread1_53_0-1.53.0-0.x86_64 libcom_err-1.42.12-4.40.amzn1.x86_64 libedit-2.11-4.20080712cvs.1.6.amzn1.x86_64 libicu-50.1.2-11.12.amzn1.x86_64 libselinux-2.1.10-3.22.amzn1.x86_64 ncurses-libs-5.7-4.20090207.14.amzn1.x86_64 openssl-1.0.2k-12.109.amzn1.x86_64 zlib-1.2.8-7.18.amzn1.x86_64
(gdb) thread apply all bt full

Thread 1 (Thread 0x7f5a8a24e840 (LWP 341)):
#0  0x00007f5a87f61c0d in recvmsg () from /lib64/libpthread.so.0
No symbol table info available.
#1  0x0000000000c6144e in ProcessHandler () at /usr/src/debug/icinga2-2.9.0/lib/base/process.cpp:278
        io = {iov_base = 0x7fff5dfbe0a8, iov_len = 8}
        jrequest = {m_Data = <incomplete type>}
        command = {m_Data = <incomplete type>}
        jresponse = {m_Data = <incomplete type>}
        msg = {msg_name = 0x0, msg_namelen = 0, msg_iov = 0x7fff5dfbe110, msg_iovlen = 1, msg_control = 0x7fff5dfbe500, msg_controllen = 4096, msg_flags = 0}
        cbuf = "x=%\212Z\177\000\000P\315%\212Z\177\000\000\370\311%\212Z\177\000\000\017\342\004\212Z\177\000\000\000\000\000\000\000\000\000\000x=%\212Z\177\000\000\005", '\000' <repeats 15 times>, "\001\000\000\000\000\000\000\000\370\311%\212Z\177", '\000' <repeats 42 times>, "P\315%\212Z\177\000\000\260\345\373]\377\177\000\000\240\345\373]\377\177\000\000\017\213a\314\000\000\000\000'^|\211Z\177\000\000\377\377\377\377\000\000\000\000\364\327\004\212Z\177\000\000\030\242i\210Z\177\000\000\370\313h\210Z\177\000\000\n\000\000\000\000\000\000\000"...
        count = <optimized out>
        response = {m_Value = {which_ = 0, storage_ = {<boost::detail::aligned_storage::aligned_storage_imp> = {data_ = {buf = "\000\000\000\000\000\000\000", align_ = {<No data fields>}}}, <No data fields>}}}
        length = 0
        rc = <optimized out>
        mbuf = 0x7f5a87f4f220 <resbuf.9794> "`\200\274\002"
        request = {px = 0x0}
        mask = {__val = {18446744067267100671, 18446744073709551615 <repeats 15 times>}}
        rl = {rlim_cur = 16384, rlim_max = 16384}
        __PRETTY_FUNCTION__ = "void ProcessHandler()"
        __PRETTY_FUNCTION__ = "void ProcessHandler()"
#2  0x0000000000c62923 in StartSpawnProcessHelper () at /usr/src/debug/icinga2-2.9.0/lib/base/process.cpp:368
        controlFDs = {11, 12}
        __PRETTY_FUNCTION__ = "void StartSpawnProcessHelper()"
        pid = 0
        __PRETTY_FUNCTION__ = "void StartSpawnProcessHelper()"
#3  0x0000000000c64475 in icinga::Process::InitializeSpawnHelper () at /usr/src/debug/icinga2-2.9.0/lib/base/process.cpp:509
No locals.
#4  0x0000000000d946b5 in Main () at /usr/src/debug/icinga2-2.9.0/icinga-app/icinga.cpp:552
        args = {<> = {_M_impl = {<> = {<> = {<No data fields>}, <No data fields>}, _M_start = 0x12c1e58 <std::string::_Rep::_S_empty_rep_storage+24>, _M_finish = 0x0, 
              _M_end_of_storage = 0x7fff5dfc12df}}, <No data fields>}
        autocomplete = false
        cmdname = {m_Data = <incomplete type>}
        command = {px = 0x2bc1d80}
        argc = 8
        autoindex = 0
        icingaGroup = {m_Data = <incomplete type>}
        visibleDesc = {m_caption = <incomplete type>, m_line_length = 80, m_min_description_length = 40, m_options = {<> = {_M_impl = {<> = {<> = {<No data fields>}, <No data fields>}, _M_start = 0x2bc65a0, 
                _M_finish = 0x2bc6660, _M_end_of_storage = 0x2bc66a0}}, <No data fields>}, belong_to_group = {<> = {_M_impl = {<> = {<> = {<No data fields>}, <No data fields>}, 
                _M_start = {<> = {<> = {<No data fields>}, _M_p = 0x2bc5010, _M_offset = 0}, <No data fields>}, _M_finish = {<> = {<> = {<No data fields>}, _M_p = 0x2bc5010, _M_offset = 12}, <No data fields>}, 
                _M_end_of_storage = 0x2bc5018}}, <No data fields>}, groups = {<> = {_M_impl = {<> = {<> = {<No data fields>}, <No data fields>}, _M_start = 0x2bc6580, _M_finish = 0x2bc6590, 
                _M_end_of_storage = 0x2bc6590}}, <No data fields>}}
        positionalDesc = {m_names = {<> = {_M_impl = {<> = {<> = {<No data fields>}, <No data fields>}, _M_start = 0x0, _M_finish = 0x0, _M_end_of_storage = 0x0}}, <No data fields>}, 
          m_trailing = <incomplete type>}
        vm = <incomplete type>
        argv = 0x7fff5dfc1848
        icingaUser = {m_Data = <incomplete type>}
        hiddenDesc = {m_caption = <incomplete type>, m_line_length = 80, m_min_description_length = 40, m_options = {<> = {_M_impl = {<> = {<> = {<No data fields>}, <No data fields>}, _M_start = 0x2bc6020, 
                _M_finish = 0x2bc6050, _M_end_of_storage = 0x2bc6060}}, <No data fields>}, belong_to_group = {<> = {_M_impl = {<> = {<> = {<No data fields>}, <No data fields>}, 
                _M_start = {<> = {<> = {<No data fields>}, _M_p = 0x2bc5900, _M_offset = 0}, <No data fields>}, _M_finish = {<> = {<> = {<No data fields>}, _M_p = 0x2bc5900, _M_offset = 3}, <No data fields>}, 
                _M_end_of_storage = 0x2bc5908}}, <No data fields>}, groups = {<> = {_M_impl = {<> = {<> = {<No data fields>}, <No data fields>}, _M_start = 0x0, _M_finish = 0x0, 
                _M_end_of_storage = 0x0}}, <No data fields>}}
        rc = 1
#5  0x0000000000a06607 in main (argc=8, argv=0x7fff5dfc1848) at /usr/src/debug/icinga2-2.9.0/icinga-app/icinga.cpp:867
        rc = <optimized out>
(gdb)
dnsmichi commented 6 years ago

@Al2Klimov

I'm in the stage of

The icinga2 log is sometimes not updated.

debug.log

[2018-07-18 07:54:41 -0700] information/FileLogger: 'debug-file' started.
[2018-07-18 07:54:41 -0700] debug/ConfigItem: Activating object 'main-log' of type 'FileLogger' with priority -100
[2018-07-18 07:54:41 -0700] information/FileLogger: 'main-log' started.
[2018-07-18 07:54:41 -0700] debug/ConfigItem: Activating object 'app' of type 'IcingaApplication' with priority 0
[2018-07-18 07:54:41 -0700] debug/ConfigItem: Activating object 'director-global' of type 'Zone' with priority 0
[2018-07-18 07:54:41 -0700] debug/ConfigItem: Activating object 'global-templates' of type 'Zone' with priority 0
[2018-07-18 07:54:41 -0700] debug/ConfigItem: Activating object 'icinga2-debian8.vagrant.demo.icinga.com' of type 'Zone' with priority 0
[2018-07-18 07:54:41 -0700] debug/ConfigItem: Activating object 'master' of type 'Zone' with priority 0
[2018-07-18 07:54:41 -0700] debug/ConfigItem: Activating object 'root' of type 'ApiUser' with priority 0

The above is typical log entries when nothing works anymore.

In a local built dev environment on Debian 8 (vagrant base box).

apt-get -y install git cmake make ccache build-essential libssl-dev libboost-all-dev bison flex libmysqlclient-dev libpq-dev libyajl-dev  libedit-dev

ln -s /usr/bin/ccache /usr/local/bin/g++

groupadd icinga
groupadd icingacmd
useradd -c "icinga" -s /sbin/nologin -G icingacmd -g icinga icinga

git clone https://github.com/icinga/icinga2.git && cd icinga2

mkdir debug
cd debug
cmake .. -DCMAKE_BUILD_TYPE=Debug -DICINGA2_UNITY_BUILD=OFF -DCMAKE_INSTALL_PREFIX=/usr/local/icinga2 -DICINGA2_PLUGINDIR=/usr/local/sbin
cd ..

make -j2 install -C debug

chown -R icinga:icinga /usr/local/icinga2/var
/usr/local/icinga2/lib/icinga2/prepare-dirs /usr/local/icinga2/etc/sysconfig/icinga2
/usr/local/icinga2/sbin/icinga2 api setup
vim /usr/local/icinga2/etc/icinga2/conf.d/api-users.conf

/usr/local/icinga2/sbin/icinga2 node wizard
gdb --args /usr/local/icinga2/lib/icinga2/sbin/icinga2 daemon -d

set follow-fork-mode child

b fork

r

Try reverting the C++11 std::thread changes, if it really influences old systems with possibly old compilers.

peteeckel commented 6 years ago

I'm seeing the same exact same effect here on CentOS 6.10. Reverted to 2.8.4 for the time being.

Al2Klimov commented 6 years ago

Not sure if I was right with the "first bad commit". It seems something fooled me...

[root@centos-6 icinga2]# /opt/icinga2/sbin/icinga2 daemon -d
[2018-07-18 08:43:41 -0700] information/cli: Icinga application loader (version: v2.9.0-2-g4cc9e0d)
[2018-07-18 08:43:41 -0700] information/cli: Loading configuration file(s).
[2018-07-18 08:43:41 -0700] information/ConfigItem: Committing config item(s).
[2018-07-18 08:43:41 -0700] information/ApiListener: My API identity: centos-6.9-x86_64
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 213 CheckCommands.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 ApiListener.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 NotificationComponent.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 CheckerComponent.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 User.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 11 Services.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 UserGroup.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 3 ServiceGroups.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 3 TimePeriods.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 12 Notifications.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 3 Zones.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 ScheduledDowntime.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 2 HostGroups.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 Downtime.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 2 NotificationCommands.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 IcingaApplication.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 Host.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 Endpoint.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 FileLogger.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Instantiated 1 ApiUser.
[2018-07-18 08:43:41 -0700] information/ScriptGlobal: Dumping variables to file '/opt/icinga2/var/cache/icinga2/icinga2.vars'
[2018-07-18 08:43:41 -0700] information/ConfigObject: Restoring program state from file '/opt/icinga2/var/lib/icinga2/icinga2.state'
[2018-07-18 08:43:41 -0700] information/ConfigObject: Restored 262 objects. Loaded 0 new objects without state.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Triggering Start signal for config items
[2018-07-18 08:43:41 -0700] information/ApiListener: 'api' started.
[2018-07-18 08:43:41 -0700] information/ApiListener: Adding new listener on port '5665'
[2018-07-18 08:43:41 -0700] information/CheckerComponent: 'checker' started.
[2018-07-18 08:43:41 -0700] information/NotificationComponent: 'notification' started.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Activated all objects.
[root@centos-6 icinga2]# tail -f /opt/icinga2/var/log/icinga2/icinga2.log &
[2] 15846
[root@centos-6 icinga2]# [2018-07-18 08:41:30 -0700] information/Notification: Sending 'Problem' notification 'centos-6.9-x86_64!http!mail-icingaadmin' for user 'icingaadmin'
[2018-07-18 08:41:30 -0700] information/Notification: Completed sending 'Problem' notification 'centos-6.9-x86_64!http!mail-icingaadmin' for checkable 'centos-6.9-x86_64!http' and user 'icingaadmin'.
[2018-07-18 08:41:30 -0700] warning/PluginNotificationTask: Notification command for object 'centos-6.9-x86_64!http' (PID: 15767, arguments: '/opt/icinga2/etc/icinga2/scripts/mail-service-notification.sh' '-4' '127.0.0.1' '-6' '::1' '-b' '' '-c' '' '-d' '2018-07-18 08:41:30 -0700' '-e' 'http' '-l' 'centos-6.9-x86_64' '-n' 'centos-6.9-x86_64' '-o' 'connect to address 127.0.0.1 and port 80: Verbindungsaufbau abgelehnt
HTTP CRITICAL - Konnte TCP socket nicht öffnen' '-r' 'icinga@localhost' '-s' 'CRITICAL' '-t' 'PROBLEM' '-u' 'http' '-v' 'false') terminated with exit code 1, output: which: no mail in (/opt/rh/devtoolset-2/root/usr/bin:/usr/local/sbin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin)
mail not found in $PATH. Consider installing it.

[2018-07-18 08:41:56 -0700] information/Application: Received request to shut down.
[2018-07-18 08:41:56 -0700] information/Application: Shutting down...
[2018-07-18 08:41:56 -0700] information/ApiListener: 'api' stopped.
[2018-07-18 08:41:56 -0700] information/CheckerComponent: 'checker' stopped.

[root@centos-6 icinga2]# kill `cat /opt/icinga2/var/run/icinga2/icinga2.pid`
[root@centos-6 icinga2]# [2018-07-18 08:43:41 -0700] information/ApiListener: 'api' started.
[2018-07-18 08:43:41 -0700] information/ApiListener: Adding new listener on port '5665'
[2018-07-18 08:43:41 -0700] information/CheckerComponent: 'checker' started.
[2018-07-18 08:43:41 -0700] information/NotificationComponent: 'notification' started.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Activated all objects.
[2018-07-18 08:44:01 -0700] information/Application: Received request to shut down.
[2018-07-18 08:44:01 -0700] information/Application: Shutting down...
[2018-07-18 08:44:01 -0700] information/ApiListener: 'api' stopped.
[2018-07-18 08:44:01 -0700] information/CheckerComponent: 'checker' stopped.
[2018-07-18 08:43:41 -0700] information/ApiListener: 'api' started.
[2018-07-18 08:43:41 -0700] information/ApiListener: Adding new listener on port '5665'
[2018-07-18 08:43:41 -0700] information/CheckerComponent: 'checker' started.
[2018-07-18 08:43:41 -0700] information/NotificationComponent: 'notification' started.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Activated all objects.
[2018-07-18 08:44:01 -0700] information/Application: Received request to shut down.
[2018-07-18 08:44:01 -0700] information/Application: Shutting down...
[2018-07-18 08:44:01 -0700] information/ApiListener: 'api' stopped.
[2018-07-18 08:44:01 -0700] information/CheckerComponent: 'checker' stopped.
Al2Klimov commented 6 years ago

Please could all of you (and @dnsmichi) start the Icinga service (v2.9!) as usual and ensure that it doesn't log anything startup-related (the log file looks as if it was just been stopped – already strange enough):

[root@centos-6 icinga2]# tail /opt/icinga2/var/log/icinga2/icinga2.log
[2018-07-18 08:41:56 -0700] information/CheckerComponent: 'checker' stopped.
[2018-07-18 08:43:41 -0700] information/ApiListener: 'api' started.
[2018-07-18 08:43:41 -0700] information/ApiListener: Adding new listener on port '5665'
[2018-07-18 08:43:41 -0700] information/CheckerComponent: 'checker' started.
[2018-07-18 08:43:41 -0700] information/NotificationComponent: 'notification' started.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Activated all objects.
[2018-07-18 08:44:01 -0700] information/Application: Received request to shut down.
[2018-07-18 08:44:01 -0700] information/Application: Shutting down...
[2018-07-18 08:44:01 -0700] information/ApiListener: 'api' stopped.
[2018-07-18 08:44:01 -0700] information/CheckerComponent: 'checker' stopped.
[root@centos-6 icinga2]#

Then run this one:

strace -f -s 1024 -e trace=execve `pidof icinga2 |perl -pe 's/(\d+)/-p$1/g'`

I'm not asking you for the (possibly confidential) output, but are there lines like these ones?

Process 18212 attached
[pid 18212] execve("/usr/lib64/nagios/plugins/check_disk", ["/usr/lib64/nagios/plugins/check_disk", "-c", "10%", "-w", "20%", "-X", "none", "-X", "tmpfs", "-X", "sysfs", "-X", "proc", "-X", "configfs", "-X", "devtmpfs", "-X", "devfs", "-X", "mtmfs", "-X", "tracefs", "-X", "cgroup", "-X", "fuse.gvfsd-fuse", "-X", "fuse.gvfs-fuse-daemon", "-X", "fdescfs", "-X", "overlay", "-X", "nsfs", "-m", "-p", "/"], [/* 22 vars */]) = 0

If yes, please run tail again:

[root@centos-6 icinga2]# tail /opt/icinga2/var/log/icinga2/icinga2.log
[2018-07-18 08:41:56 -0700] information/CheckerComponent: 'checker' stopped.
[2018-07-18 08:43:41 -0700] information/ApiListener: 'api' started.
[2018-07-18 08:43:41 -0700] information/ApiListener: Adding new listener on port '5665'
[2018-07-18 08:43:41 -0700] information/CheckerComponent: 'checker' started.
[2018-07-18 08:43:41 -0700] information/NotificationComponent: 'notification' started.
[2018-07-18 08:43:41 -0700] information/ConfigItem: Activated all objects.
[2018-07-18 08:44:01 -0700] information/Application: Received request to shut down.
[2018-07-18 08:44:01 -0700] information/Application: Shutting down...
[2018-07-18 08:44:01 -0700] information/ApiListener: 'api' stopped.
[2018-07-18 08:44:01 -0700] information/CheckerComponent: 'checker' stopped.
[root@centos-6 icinga2]#

Even the same timestamp! (Srsly?!)

The stop the service (as usual) and run tail again:

[root@centos-6 icinga2]# tail /opt/icinga2/var/log/icinga2/icinga2.log
[2018-07-18 08:44:01 -0700] information/CheckerComponent: 'checker' stopped.
[2018-07-18 08:49:58 -0700] information/ApiListener: 'api' started.
[2018-07-18 08:49:58 -0700] information/ApiListener: Adding new listener on port '5665'
[2018-07-18 08:49:58 -0700] information/CheckerComponent: 'checker' started.
[2018-07-18 08:49:58 -0700] information/NotificationComponent: 'notification' started.
[2018-07-18 08:49:58 -0700] information/ConfigItem: Activated all objects.
[2018-07-18 09:00:36 -0700] information/Application: Received request to shut down.
[2018-07-18 09:00:36 -0700] information/Application: Shutting down...
[2018-07-18 09:00:36 -0700] information/ApiListener: 'api' stopped.
[2018-07-18 09:00:36 -0700] information/CheckerComponent: 'checker' stopped.
[root@centos-6 icinga2]#
Al2Klimov commented 6 years ago

If you can confirm this behavior, please react to the above comment with a "confused" smiley. Yes, srsly, I'd like to see if this is really black magic or if it's just me.

peteeckel commented 6 years ago

I just re-did the upgrade to 2.9.0 on a spare CentOS 6.10 machine, making sure that nothing is in /etc/sysconfig/icinga2.

No log whatsoever afterwards.

[root@orcus3 icinga2]# strace -f -s 1024 -e trace=execve `pidof icinga2 |perl -pe 's/(\d+)/-p$1/g'
Process 22578 attached with 9 threads
Process 22575 attached

That's all. Nothing else.

nbuchwitz commented 6 years ago

@Al2Klimov The strace doesn't produce any output, but I can confirm your observations regarding the log timestamps.

peteeckel commented 6 years ago

And indeed, when I stop Icinga 2 it writes to the log again that it's been stopped:

[root@orcus3 icinga2]# tail /var/log/icinga2/icinga2.log
[2018-07-18 16:02:29 +0000] information/WorkQueue: #8 (JsonRpcConnection, #0) items: 0, rate: 1.13333/s (68/min 342/5min 1025/15min);
[2018-07-18 16:05:49 +0000] information/ConfigObject: Dumping program state to file '/var/lib/icinga2/icinga2.state'
[2018-07-18 16:06:59 +0000] information/WorkQueue: #4 (ApiListener, RelayQueue) items: 0, rate:  0/s (0/min 0/5min 0/15min);
[2018-07-18 16:06:59 +0000] information/WorkQueue: #5 (ApiListener, SyncQueue) items: 0, rate: 0.0166667/s (1/min 1/5min 1/15min);
[2018-07-18 16:07:39 +0000] information/WorkQueue: #8 (JsonRpcConnection, #0) items: 0, rate: 1.13333/s (68/min 340/5min 1025/15min);
[2018-07-18 16:08:58 +0000] information/Application: Received request to shut down.
[2018-07-18 16:08:58 +0000] information/Application: Shutting down...
[2018-07-18 16:08:58 +0000] information/ApiListener: 'api' stopped.
[2018-07-18 16:08:58 +0000] information/CheckerComponent: 'checker' stopped.
[2018-07-18 16:08:58 +0000] information/ExternalCommandListener: 'command' stopped.
[root@orcus3 icinga2]# service icinga2 stop
Stopping Icinga 2: Done
[root@orcus3 icinga2]# tail /var/log/icinga2/icinga2.log
[2018-07-18 16:09:02 +0000] information/ApiListener: Adding new listener on port '5665'
[2018-07-18 16:09:02 +0000] information/ExternalCommandListener: 'command' started.
[2018-07-18 16:09:02 +0000] information/CheckerComponent: 'checker' started.
[2018-07-18 16:09:02 +0000] information/NotificationComponent: 'notification' started.
[2018-07-18 16:09:02 +0000] information/ConfigItem: Activated all objects.
[2018-07-18 16:20:17 +0000] information/Application: Received request to shut down.
[2018-07-18 16:20:17 +0000] information/Application: Shutting down...
[2018-07-18 16:20:17 +0000] information/ApiListener: 'api' stopped.
[2018-07-18 16:20:17 +0000] information/CheckerComponent: 'checker' stopped.
[2018-07-18 16:20:17 +0000] information/ExternalCommandListener: 'command' stopped.
chrostek commented 6 years ago

Same here with Ubuntu 14.04. Startup is logged in startup.log, nothing in icinga2.log Stop is logged to icinga2.log

dnsmichi commented 6 years ago

Tests

Can only be run with local configuration, if you are having command endpoint checks, this won't trigger it.

root@icinga2-debian8:~/icinga2# vim /usr/local/icinga2/etc/icinga2/icinga2.conf

// Disabled by the node setup CLI command on 2018-07-18 06:36:53 -0700
include_recursive "conf.d"

root@icinga2-debian8:~/icinga2# killall icinga2
root@icinga2-debian8:~/icinga2# /usr/local/icinga2/lib/icinga2/sbin/icinga2 daemon -d
[2018-07-18 12:15:03 -0700] information/cli: Icinga application loader (version: v2.9.0-5-g3c059aa; debug)
[2018-07-18 12:15:03 -0700] information/cli: Loading configuration file(s).
[2018-07-18 12:15:03 -0700] information/ConfigItem: Committing config item(s).
[2018-07-18 12:15:03 -0700] information/ApiListener: My API identity: icinga2-debian8.vagrant.demo.icinga.com
[2018-07-18 12:15:03 -0700] information/ConfigItem: Instantiated 213 CheckCommands.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Instantiated 1 ApiListener.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Instantiated 1 NotificationComponent.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Instantiated 1 CheckerComponent.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Instantiated 4 Zones.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Instantiated 1 IcingaApplication.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Instantiated 2 Endpoints.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Instantiated 2 FileLoggers.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Instantiated 1 ApiUser.
[2018-07-18 12:15:03 -0700] information/ScriptGlobal: Dumping variables to file '/usr/local/icinga2/var/cache/icinga2/icinga2.vars'
[2018-07-18 12:15:03 -0700] critical/Daemonize(): After fork in child
[2018-07-18 12:15:03 -0700] information/ConfigObject: Restoring program state from file '/usr/local/icinga2/var/lib/icinga2/icinga2.state'
[2018-07-18 12:15:03 -0700] information/ConfigObject: Restored 227 objects. Loaded 0 new objects without state.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Triggering Start signal for config items
[2018-07-18 12:15:03 -0700] information/FileLogger: 'debug-file' started.
[2018-07-18 12:15:03 -0700] information/FileLogger: 'main-log' started.
[2018-07-18 12:15:03 -0700] information/ApiListener: 'api' started.
[2018-07-18 12:15:03 -0700] information/ApiListener: Adding new listener on port '5665'
[2018-07-18 12:15:03 -0700] information/CheckerComponent: 'checker' started.
[2018-07-18 12:15:03 -0700] information/NotificationComponent: 'notification' started.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Activated all objects.
root@icinga2-debian8:~/icinga2# tail /usr/local/icinga2/var/log/icinga2/icinga2.log
[2018-07-18 07:54:41 -0700] information/NotificationComponent: 'notification' started.
[2018-07-18 07:54:41 -0700] information/ConfigItem: Activated all objects.
[2018-07-18 08:27:19 -0700] information/Application: We jumped forward in time: 1200.25 seconds
[2018-07-18 08:54:25 -0700] information/Application: We jumped forward in time: 1569.58 seconds
[2018-07-18 11:50:47 -0700] information/Application: We jumped forward in time: 10403.4 seconds
[2018-07-18 12:05:24 -0700] information/Application: We jumped backward in time: 21.7825 seconds
[2018-07-18 12:14:59 -0700] information/Application: Received request to shut down.
[2018-07-18 12:14:59 -0700] information/Application: Shutting down...
[2018-07-18 12:14:59 -0700] information/ApiListener: 'api' stopped.
[2018-07-18 12:14:59 -0700] information/CheckerComponent: 'checker' stopped.
root@icinga2-debian8:~/icinga2# strace -f -s 1024 -e trace=execve `pidof icinga2 |perl -pe 's/(\d+)/-p$1/g'`
Process 27570 attached with 13 threads
Process 27566 attached
Process 27596 attached
[pid 27596] execve("/usr/local/sbin/check_load", ["/usr/local/sbin/check_load", "-c", "10,6,4", "-w", "5,4,3"], [/* 21 vars */]) = -1 ENOENT (No such file or directory)
[pid 27596] +++ exited with 128 +++
Process 27597 attached
[pid 27597] execve("/usr/local/sbin/check_disk", ["/usr/local/sbin/check_disk", "-c", "10%", "-w", "20%", "-X", "none", "-X", "tmpfs", "-X", "sysfs", "-X", "proc", "-X", "configfs", "-X", "devtmpfs", "-X", "devfs", "-X", "mtmfs", "-X", "tracefs", "-X", "cgroup", "-X", "fuse.gvfsd-fuse", "-X", "fuse.gvfs-fuse-daemon", "-X", "fdescfs", "-X", "overlay", "-X", "nsfs", "-m", "-p", "/"], [/* 21 vars */]) = -1 ENOENT (No such file or directory)
[pid 27597] +++ exited with 128 +++
Process 27598 attached
[pid 27598] execve("/usr/local/sbin/check_ping", ["/usr/local/sbin/check_ping", "-4", "-H", "127.0.0.1", "-c", "200,15%", "-w", "100,5%"], [/* 21 vars */]) = -1 ENOENT (No such file or directory)
[pid 27598] +++ exited with 128 +++
Process 27599 attached
[pid 27599] execve("/usr/local/sbin/check_swap", ["/usr/local/sbin/check_swap", "-c", "25%", "-w", "50%"], [/* 21 vars */]) = -1 ENOENT (No such file or directory)
[pid 27599] +++ exited with 128 +++

tail again.

root@icinga2-debian8:~/icinga2# tail /usr/local/icinga2/var/log/icinga2/icinga2.log
[2018-07-18 12:15:03 -0700] information/FileLogger: 'main-log' started.
[2018-07-18 12:15:03 -0700] information/ApiListener: 'api' started.
[2018-07-18 12:15:03 -0700] information/ApiListener: Adding new listener on port '5665'
[2018-07-18 12:15:03 -0700] information/CheckerComponent: 'checker' started.
[2018-07-18 12:15:03 -0700] information/NotificationComponent: 'notification' started.
[2018-07-18 12:15:03 -0700] information/ConfigItem: Activated all objects.
[2018-07-18 12:19:21 -0700] information/Application: Received request to shut down.
[2018-07-18 12:19:21 -0700] information/Application: Shutting down...
[2018-07-18 12:19:21 -0700] information/ApiListener: 'api' stopped.
[2018-07-18 12:19:21 -0700] information/CheckerComponent: 'checker' stopped.

Kill it and tail again.

root@icinga2-debian8:~/icinga2# tail /usr/local/icinga2/var/log/icinga2/icinga2.log
[2018-07-18 12:21:54 -0700] warning/PluginCheckTask: Check command for object 'icinga2-debian8.vagrant.demo.icinga.com!http' (PID: 27655, arguments: '/usr/local/sbin/check_http' '-I' '127.0.0.1' '-u' '/') terminated with exit code 128, output: execvpe(/usr/local/sbin/check_http) failed: No such file or directory

[2018-07-18 12:21:55 -0700] warning/PluginCheckTask: Check command for object 'icinga2-debian8.vagrant.demo.icinga.com!swap' (PID: 27656, arguments: '/usr/local/sbin/check_swap' '-c' '25%' '-w' '50%') terminated with exit code 128, output: execvpe(/usr/local/sbin/check_swap) failed: No such file or directory

[2018-07-18 12:22:02 -0700] warning/PluginCheckTask: Check command for object 'icinga2-debian8.vagrant.demo.icinga.com!procs' (PID: 27657, arguments: '/usr/local/sbin/check_procs' '-c' '400' '-w' '250') terminated with exit code 128, output: execvpe(/usr/local/sbin/check_procs) failed: No such file or directory

[2018-07-18 12:22:05 -0700] information/Application: Received request to shut down.
[2018-07-18 12:22:06 -0700] information/Application: Shutting down...
[2018-07-18 12:22:06 -0700] information/ApiListener: 'api' stopped.
[2018-07-18 12:22:06 -0700] information/CheckerComponent: 'checker' stopped.

Ideas

The API is fully intact locally, answers with the correct scheduler information.

root@icinga2-debian8:~/icinga2# curl -k -s -u root:icinga 'https://localhost:5665/v1/objects/services?pretty=1&attrs=last_check&attrs=next_check'
...
        {
            "attrs": {
                "last_check": 1531942785.9487929344,
                "next_check": 1531942843.3488590717
            },
            "joins": {

            },
            "meta": {

            },
            "name": "icinga2-debian8.vagrant.demo.icinga.com!users",
            "type": "Service"
        }
    ]
}

It doesn't log the requests though.

Cluster connections

Why would the API connection work? If the master actively connects to the client, this should also work, and it does.

mbmif /usr/local/icinga2/etc/icinga2 (master *) # openssl s_client -cert pki/mbmif.int.netways.de.crt -key pki/mbmif.int.netways.de.key -CAfile pki/ca.crt -connect 192.168.33.21:5665
CONNECTED(00000003)
depth=1 CN = Icinga CA
verify return:1
depth=0 CN = icinga2-debian8.vagrant.demo.icinga.com
verify return:1
---
Certificate chain
 0 s:/CN=icinga2-debian8.vagrant.demo.icinga.com
   i:/CN=Icinga CA
 1 s:/CN=Icinga CA
   i:/CN=Icinga CA
---
Server certificate
-----BEGIN CERTIFICATE-----
....
subject=/CN=icinga2-debian8.vagrant.demo.icinga.com
issuer=/CN=Icinga CA
---
Acceptable client certificate CA names
/CN=Icinga CA
---
SSL handshake has read 4175 bytes and written 3916 bytes
---
New, TLSv1/SSLv3, Cipher is AES256-GCM-SHA384
Server public key is 4096 bit
Secure Renegotiation IS supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : AES256-GCM-SHA384
    Session-ID: 256C3CAC7F073901E7EE71C8E44560DE244418BEC90141FE9AFEDDDDD28C26F3
    Session-ID-ctx:
    Master-Key: 7300F1CEC18F19DA47F1DE980780FE70CD8233DD12CA8525820445FA932391BD3C2371796EF7FC48F43196422FBF0FFB
    TLS session ticket lifetime hint: 300 (seconds)
    TLS session ticket:
....

    Start Time: 1531943410
    Timeout   : 300 (sec)
    Verify return code: 0 (ok)
---
[2018-07-18 12:50:11 -0700] information/ApiListener: New client connection for identity 'mbmif.int.netways.de' from [192.168.33.1]:53086

[2018-07-18 12:50:21 -0700] warning/ApiListener: No data received on new API connection for identity 'mbmif.int.netways.de'. Ensure that the remote endpoints are properly configured in a cluster setup.
Context:
    (0) Handling new API client connection

I'm also able to simulate a cluster request, and will get plenty of messages on the master. Which in turn means that the API and Cluster is fully intact.

The client itself is not able to start the timers which would do the reconnect handling.

I've seen that in my test runs that the Api timer handlers are never called.

Timers?

While looking into std::thread, I've seen that Timers are now dynamically started. This may have an influence here, @gunnarbeutner maybe you have an idea?

67390236785cb5b79cfa55cffe75f5f8648c6bd7

FDs?

Could be a problem with file descriptors not being passed correctly. I do see that the process executes checks with strace, still there's nothing logged.

I remember having seen #4924 #5038 and #5048 yet I did not have time to dig into them, might be more visible now with other changes in 2.9.

Other Loggers

icinga2 feature enable syslog
service icinga2 restart

tail -f /var/log/messages

Can anyone confirm that logging works with that? For me, it does.

It is 22:00 CEST here, I'm leaving this for the next 10 hours.

peteeckel commented 6 years ago

This is getting stranger and stranger ...

I can confirm that enabling the syslog feature (and setting the severity in the SyslogLogger object to "information") indeed convinces icinga2 to write logs. At least after I restarted the syslog daemon, which for some reason stopped working while I was testing the icinga2 problem this afternoon.

But there's more, and this is where it gets really strange. The agent started communicating with the master and executing checks again. Works like a charm, as if nothing had happened. strace now gives tons of messages as well: 

[pid 25828] execve("/usr/lib64/nagios/plugins/check_procs", ["/usr/lib64/nagios/plugins/check_procs", "-c", "400", "-w", "250"], [/* 7 vars */]) = 0
[pid 25831] execve("/usr/lib64/nagios/plugins/check_cpu_proc.sh", ["/usr/lib64/nagios/plugins/check_cpu_proc.sh", "-p", "icinga2"], [/* 7 vars */]) = 0
[pid 25944] execve("/usr/lib64/nagios/plugins/check_disk", ["/usr/lib64/nagios/plugins/check_disk", "-c", "10%", "-w", "20%", "-X", "none", "-X", "tmpfs", "-X", "sysfs", "-X", "proc", "-X", "configfs", "-X", "devtmpfs", "-X", "devfs", "-X", "mtmfs", "-X", "tracefs", "-X", "cgroup", "-X", "fuse.gvfsd-fuse", "-X", "fuse.gvfs-fuse-daemon", "-X", "fdescfs", "-m"], [/* 7 vars */]) = 0
[pid 25947] execve("/usr/lib64/nagios/plugins/check_swap", ["/usr/lib64/nagios/plugins/check_swap", "-c", "25%", "-w", "50%"], [/* 7 vars */]) = 0
[pid 25949] execve("/usr/lib64/nagios/plugins/check_procs", ["/usr/lib64/nagios/plugins/check_procs", "-C", "auditd", "-c", "1:1", "-p", "1", "-u", "root", "-w", "1:9999"], [/* 7 vars */]) = 0
[pid 25952] execve("/usr/lib64/nagios/plugins/check_procs", ["/usr/lib64/nagios/plugins/check_procs", "-C", "restorecond", "-c", "1:1", "-p", "1", "-u", "root", "-w", "1:9999"], [/* 7 vars */]) = 0
[pid 25955] execve("/usr/lib64/nagios/plugins/check_ntp_peer", ["/usr/lib64/nagios/plugins/check_ntp_peer", "-H", "localhost"], [/* 7 vars */]) = 0
[pid 25958] execve("/usr/lib64/nagios/plugins/check_mem.pl", ["/usr/lib64/nagios/plugins/check_mem.pl", "-C", "-c", "90", "-u", "-w", "80"], [/* 7 vars */]) = 0
[pid 25962] execve("/usr/lib64/nagios/plugins/check_procs", ["/usr/lib64/nagios/plugins/check_procs", "-C", "rsyslogd", "-c", "1:1", "-p", "1", "-u", "root", "-w", "1:9999"], [/* 7 vars */]) = 0
[pid 25965] execve("/usr/lib64/nagios/plugins/check_users", ["/usr/lib64/nagios/plugins/check_users", "-c", "50", "-w", "20"], [/* 7 vars */]) = 0
[pid 25969] execve("/usr/lib64/nagios/plugins/check_procs", ["/usr/lib64/nagios/plugins/check_procs", "-C", "bareos-fd", "-c", "1:1", "-p", "1", "-u", "root", "-w", "1:9999"], [/* 7 vars */]) = 0
[pid 25973] execve("/usr/lib64/nagios/plugins/check_procs", ["/usr/lib64/nagios/plugins/check_procs", "-c", "400", "-w", "250"], [/* 7 vars */]) = 0
[pid 25976] execve("/usr/lib64/nagios/plugins/check_cpu_proc.sh", ["/usr/lib64/nagios/plugins/check_cpu_proc.sh", "-p", "icinga2"], [/* 7 vars */]) = 0
[pid 26089] execve("/usr/lib64/nagios/plugins/check_disk", ["/usr/lib64/nagios/plugins/check_disk", "-c", "10%", "-w", "20%", "-X", "none", "-X", "tmpfs", "-X", "sysfs", "-X", "proc", "-X", "configfs", "-X", "devtmpfs", "-X", "devfs", "-X", "mtmfs", "-X", "tracefs", "-X", "cgroup", "-X", "fuse.gvfsd-fuse", "-X", "fuse.gvfs-fuse-daemon", "-X", "fdescfs", "-m"], [/* 7 vars */]) = 0
[pid 26092] execve("/usr/lib64/nagios/plugins/check_swap", ["/usr/lib64/nagios/plugins/check_swap", "-c", "25%", "-w", "50%"], [/* 7 vars */]) = 0
[pid 26094] execve("/usr/lib64/nagios/plugins/check_procs", ["/usr/lib64/nagios/plugins/check_procs", "-C", "auditd", "-c", "1:1", "-p", "1", "-u", "root", "-w", "1:9999"], [/* 7 vars */]) = 0
[pid 26097] execve("/usr/lib64/nagios/plugins/check_procs", ["/usr/lib64/nagios/plugins/check_procs", "-C", "restorecond", "-c", "1:1", "-p", "1", "-u", "root", "-w", "1:9999"], [/* 7 vars */]) = 0
[pid 26100] execve("/usr/lib64/nagios/plugins/check_ntp_peer", ["/usr/lib64/nagios/plugins/check_ntp_peer", "-H", "localhost"], [/* 7 vars */]) = 0

In other words, something logging-related seems to be wrong. The idea that it might be something regarding file descriptors has some merits.

Another update: After I enabled logging to syslog, now the /var/log/icinga2/icinga2.log gets written as well.

vladimir-mencl-eresearch commented 6 years ago

Hi,

I think I'm experiencing the same issue here.

I'm running icinga-2.9.0-1 on Debian in a Docker container (built from debian:stretch).

When I run icinga2 daemon -d, it blocks in the same way as described in this issue.

Icingaweb reports Backend icinga is not running.

Surprisingly, when I poke the daemon to reload with:

kill -HUP $( cat /var/run/icinga2/icinga2.pid )

it starts working.

And also, when I instead start it without the daemon mode (icinga2 daemon), it works fine as well.

Hope this is helpful - would be happy to provide troubleshooting information too...

Cheers, Vlad

nbuchwitz commented 6 years ago

I can confirm: A reload of the daemon "repairs" the dead instance - will observe if it's permanent or only for a while...

BarbUk commented 6 years ago

Confirmed on debian 9.5 too.

Observing the process with strace, it seem locked in a loop:

[pid  7211] 08:34:19.286297 poll([{fd=7, events=POLLIN}, {fd=51, events=POLLIN}, {fd=52, events=POLLIN}, {fd=18, events=POLLIN}, {fd=55, events=POLLIN}, {fd=20, events=POLLIN}, {fd=22, events=POLLIN}, {fd=56, events=POLLIN}, {fd=25, events=POLLIN}, {fd=24, events=POLLIN}, {fd=27, events=POLLIN}, {fd=59, events=POLLIN}, {fd=30, events=POLLIN}, {fd=33, events=POLLIN}, {fd=29, events=POLLIN}, {fd=34, events=POLLIN}, {fd=38, events=POLLIN}, {fd=39, events=POLLIN}, {fd=42, events=POLLIN}, {fd=46, events=POLLIN}, {fd=49, events=POLLIN}, {fd=63, events=POLLIN}], 22, 56296 <unfinished ...>
[pid  7208] 08:34:19.286341 futex(0x7fb5fc0d6118, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  7193] 08:34:19.286358 <... futex resumed> ) = 1 <0.000093>
[pid  7193] 08:34:19.286377 futex(0x7fb5fc0d6118, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7208] 08:34:19.286401 <... futex resumed> ) = 0 <0.000049>
[pid  7193] 08:34:19.286415 <... futex resumed> ) = 1 <0.000031>
[pid  7208] 08:34:19.286427 futex(0x7fb5fc0d6118, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7193] 08:34:19.286443 futex(0x5633b6c1bbe4, FUTEX_WAIT_PRIVATE, 1225, NULL <unfinished ...>
[pid  7208] 08:34:19.286459 <... futex resumed> ) = 0 <0.000023>
[pid  7208] 08:34:19.286482 futex(0x7fb5fc0d6144, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 45387, {tv_sec=1531982059, tv_nsec=304474000}, 0xffffffff <unfinished ...>
[pid  7211] 08:34:19.290037 <... poll resumed> ) = 1 ([{fd=63, revents=POLLIN}]) <0.003699>
[pid  7211] 08:34:19.290081 read(63, "SSH OK - OpenSSH_6.7p1 Debian-5+deb8u4 (protocol 2.0) | time=0.002984s;;;0.000000;10.000000\n", 512) = 92 <0.000012>
[pid  7211] 08:34:19.290119 read(63, "", 512) = 0 <0.000011>
[pid  7211] 08:34:19.290162 sendto(12, "\"\0\0\0\0\0\0\0", 8, 0, NULL, 0) = 8 <0.000047>
[pid  7211] 08:34:19.290243 sendto(12, "{\"command\":\"waitpid\",\"pid\":7724.0}", 34, 0, NULL, 0) = 34 <0.000017>
[pid  7211] 08:34:19.290296 recvfrom(12, "{\"rc\":7724.0,\"status\":0.0}", 4096, 0, NULL, NULL) = 26 <0.000060>
[pid  7211] 08:34:19.290432 futex(0x5633b6c1bf24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x5633b6c1bf20, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1) = 1 <0.000016>
[pid  7194] 08:34:19.290471 <... futex resumed> ) = 0 <0.005124>
[pid  7211] 08:34:19.290486 close(63 <unfinished ...>
[pid  7194] 08:34:19.290510 futex(0x5633b6c1bef8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7211] 08:34:19.290527 <... close resumed> ) = 0 <0.000030>
[pid  7194] 08:34:19.290543 <... futex resumed> ) = 0 <0.000025>
[pid  7211] 08:34:19.290556 poll([{fd=7, events=POLLIN}, {fd=51, events=POLLIN}, {fd=52, events=POLLIN}, {fd=18, events=POLLIN}, {fd=55, events=POLLIN}, {fd=20, events=POLLIN}, {fd=22, events=POLLIN}, {fd=56, events=POLLIN}, {fd=25, events=POLLIN}, {fd=24, events=POLLIN}, {fd=27, events=POLLIN}, {fd=59, events=POLLIN}, {fd=30, events=POLLIN}, {fd=33, events=POLLIN}, {fd=29, events=POLLIN}, {fd=34, events=POLLIN}, {fd=38, events=POLLIN}, {fd=39, events=POLLIN}, {fd=42, events=POLLIN}, {fd=46, events=POLLIN}, {fd=49, events=POLLIN}], 21, 56292 <unfinished ...>
[pid  7194] 08:34:19.290655 futex(0x7fb5fc0c5564, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fb5fc0c5560, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1 <unfinished ...>
[pid  7205] 08:34:19.290696 <... futex resumed> ) = 0 <0.005567>
[pid  7194] 08:34:19.290721 <... futex resumed> ) = 1 <0.000056>
[pid  7205] 08:34:19.290736 futex(0x7fb5fc0c5538, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  7194] 08:34:19.290755 futex(0x7fb5fc0c5538, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7205] 08:34:19.290772 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000023>
[pid  7194] 08:34:19.290787 <... futex resumed> ) = 0 <0.000025>
[pid  7205] 08:34:19.290801 futex(0x7fb5fc0c5538, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7194] 08:34:19.290817 futex(0x7fb5fc0d6144, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x7fb5fc0d6118, 45388 <unfinished ...>
[pid  7205] 08:34:19.290834 <... futex resumed> ) = 0 <0.000023>
[pid  7208] 08:34:19.290848 <... futex resumed> ) = 0 <0.004357>
[pid  7194] 08:34:19.290863 <... futex resumed> ) = 1 <0.000037>
[pid  7205] 08:34:19.290888 futex(0x7fb5fc0c5564, FUTEX_WAIT_PRIVATE, 22169, NULL <unfinished ...>
[pid  7208] 08:34:19.290905 futex(0x7fb5fc0d6118, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000013>
[pid  7208] 08:34:19.290947 futex(0x7fb5fc0d6144, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 45389, {tv_sec=1531982059, tv_nsec=303937000}, 0xffffffff <unfinished ...>
[pid  7194] 08:34:19.290969 futex(0x7fb5f000440c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fb5f0004408, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1 <unfinished ...>
[pid  7216] 08:34:19.291005 <... futex resumed> ) = 0 <0.036913>
[pid  7194] 08:34:19.291024 <... futex resumed> ) = 1 <0.000045>
[pid  7216] 08:34:19.291038 futex(0x7fb5f00043e0, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  7194] 08:34:19.291057 futex(0x7fb5f00043e0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7216] 08:34:19.291074 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000025>
[pid  7194] 08:34:19.291090 <... futex resumed> ) = 0 <0.000024>
[pid  7216] 08:34:19.291103 futex(0x7fb5f00043e0, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000013>
[pid  7216] 08:34:19.291145 futex(0x7fb610000020, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  7194] 08:34:19.291162 futex(0x7fb610000020, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7216] 08:34:19.291177 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000021>
[pid  7194] 08:34:19.291191 <... futex resumed> ) = 0 <0.000022>
[pid  7216] 08:34:19.291205 futex(0x7fb610000020, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000012>
[pid  7194] 08:34:19.291235 futex(0x7fb5fc0c5564, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fb5fc0c5560, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1 <unfinished ...>
[pid  7216] 08:34:19.291254 futex(0x7fb5f000440c, FUTEX_WAIT_PRIVATE, 1021, NULL <unfinished ...>
[pid  7205] 08:34:19.291272 <... futex resumed> ) = 0 <0.000372>
[pid  7194] 08:34:19.291286 <... futex resumed> ) = 1 <0.000041>
[pid  7205] 08:34:19.291299 futex(0x7fb5fc0c5538, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  7194] 08:34:19.291316 futex(0x7fb5fc0c5538, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7205] 08:34:19.291335 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000025>
[pid  7194] 08:34:19.291350 <... futex resumed> ) = 0 <0.000025>
[pid  7205] 08:34:19.291363 futex(0x7fb5fc0c5538, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7194] 08:34:19.291379 futex(0x7fb61c003f64, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fb61c003f60, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1 <unfinished ...>
[pid  7205] 08:34:19.291396 <... futex resumed> ) = 0 <0.000023>
[pid  7217] 08:34:19.291409 <... futex resumed> ) = 0 <0.037464>
[pid  7217] 08:34:19.291429 futex(0x7fb61c003f38, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  7205] 08:34:19.291448 futex(0x7fb5fc0c5564, FUTEX_WAIT_PRIVATE, 22171, NULL <unfinished ...>
[pid  7194] 08:34:19.291465 <... futex resumed> ) = 1 <0.000074>
[pid  7194] 08:34:19.291486 futex(0x7fb61c003f38, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7217] 08:34:19.291513 <... futex resumed> ) = 0 <0.000072>
[pid  7194] 08:34:19.291527 <... futex resumed> ) = 1 <0.000032>
[pid  7217] 08:34:19.291540 futex(0x7fb61c003f38, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000014>
[pid  7194] 08:34:19.291631 mprotect(0x7fb610040000, 4096, PROT_READ|PROT_WRITE) = 0 <0.000017>
[pid  7194] 08:34:19.291707 futex(0x7fb5f000440c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fb5f0004408, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1 <unfinished ...>
[pid  7217] 08:34:19.291724 futex(0x7fb61c003f64, FUTEX_WAIT_PRIVATE, 513, NULL <unfinished ...>
[pid  7216] 08:34:19.291741 <... futex resumed> ) = 0 <0.000477>
[pid  7194] 08:34:19.291754 <... futex resumed> ) = 1 <0.000038>
[pid  7216] 08:34:19.291767 futex(0x7fb5f00043e0, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  7194] 08:34:19.291784 futex(0x7fb5f00043e0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7216] 08:34:19.291800 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000022>
[pid  7194] 08:34:19.291814 <... futex resumed> ) = 0 <0.000023>
[pid  7216] 08:34:19.291827 futex(0x7fb5f00043e0, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000012>
[pid  7194] 08:34:19.291855 futex(0x5633b6c1bf24, FUTEX_WAIT_PRIVATE, 1373, NULL <unfinished ...>
[pid  7216] 08:34:19.291879 futex(0x7fb5f000440c, FUTEX_WAIT_PRIVATE, 1023, NULL <unfinished ...>
[pid  7208] 08:34:19.304112 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out) <0.013141>
[pid  7208] 08:34:19.304220 futex(0x7fb5fc0d6118, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000088>
[pid  7208] 08:34:19.304446 futex(0x7fb5fc0d6144, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 45391, {tv_sec=1531982059, tv_nsec=304391000}, 0xffffffff) = -1 ETIMEDOUT (Connection timed out) <0.000111>
[pid  7208] 08:34:19.304699 futex(0x7fb5fc0d6118, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000056>
[pid  7208] 08:34:19.304844 futex(0x5633b6c1bf24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x5633b6c1bf20, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1) = 1 <0.000016>
[pid  7208] 08:34:19.304893 futex(0x7fb5fc0d6144, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 45393, {tv_sec=1531982059, tv_nsec=327883000}, 0xffffffff <unfinished ...>
[pid  7194] 08:34:19.304916 <... futex resumed> ) = 0 <0.013051>
[pid  7194] 08:34:19.304951 futex(0x5633b6c1bef8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000051>
[pid  7194] 08:34:19.305079 futex(0x7fb5fc0c5564, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fb5fc0c5560, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1 <unfinished ...>
[pid  7205] 08:34:19.305126 <... futex resumed> ) = 0 <0.013658>
[pid  7194] 08:34:19.305156 <... futex resumed> ) = 1 <0.000068>
[pid  7205] 08:34:19.305172 futex(0x7fb5fc0c5538, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  7194] 08:34:19.305191 futex(0x7fb5fc0c5538, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7205] 08:34:19.305208 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000023>
[pid  7194] 08:34:19.305223 <... futex resumed> ) = 0 <0.000025>
[pid  7205] 08:34:19.305237 futex(0x7fb5fc0c5538, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000013>
[pid  7205] 08:34:19.305306 futex(0x7fb5fc0c5564, FUTEX_WAIT_PRIVATE, 22173, NULL <unfinished ...>
[pid  7194] 08:34:19.305407 futex(0x7fb5fc0d6144, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x7fb5fc0d6118, 45394 <unfinished ...>
[pid  7208] 08:34:19.305441 <... futex resumed> ) = 0 <0.000528>
[pid  7194] 08:34:19.305459 <... futex resumed> ) = 1 <0.000043>
[pid  7208] 08:34:19.305473 futex(0x7fb5fc0d6118, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  7194] 08:34:19.305491 futex(0x7fb5fc0d6118, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  7208] 08:34:19.305507 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000022>
[pid  7194] 08:34:19.305522 <... futex resumed> ) = 0 <0.000024>
[pid  7208] 08:34:19.305535 futex(0x7fb5fc0d6118, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000013>
[pid  7194] 08:34:19.305565 futex(0x5633b6c1bf24, FUTEX_WAIT_PRIVATE, 1375, NULL <unfinished ...>

After reloading service icinga2 reload:

08:35:36.264335 recvmsg(11, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\252\0\0\0\0\0\0\0", iov_len=8}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, cmsg_data=[3, 4, 5]}], msg_controllen=32, msg_flags=0}, 0) = 8 <0.045991>
08:35:36.310397 recvfrom(11, "{\"adjustPriority\":true,\"arguments\":[\"/usr/lib/nagios/plugins/check_ping\",\"-4\",\"-H\",\"redacted\",\"-c\",\"200,25%\",\"-w\",\"150,20%\"],\"command\":\"spawn\",\"extraEnvironment\":{}}", 170, 0, NULL, NULL) = 170 <0.000008>
08:35:36.310508 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x2af64aaa3f10) = 10728 <0.000212>
08:35:36.310765 close(3strace: Process 10728 attached
)                = 0 <0.000011>
[pid 10069] 08:35:36.310794 close(4)    = 0 <0.000004>
[pid 10069] 08:35:36.310810 close(5 <unfinished ...>
[pid 10728] 08:35:36.310821 set_robust_list(0x2af64aaa3f20, 24 <unfinished ...>
[pid 10069] 08:35:36.310831 <... close resumed> ) = 0 <0.000015>
[pid 10728] 08:35:36.310838 <... set_robust_list resumed> ) = 0 <0.000012>
[pid 10069] 08:35:36.310864 sendto(11, "{\"errno\":0.0,\"rc\":10728.0}", 26, 0, NULL, 0 <unfinished ...>
[pid 10728] 08:35:36.310896 close(11 <unfinished ...>
[pid 10069] 08:35:36.310920 <... sendto resumed> ) = 26 <0.000037>
[pid 10069] 08:35:36.310930 recvmsg(11,  <unfinished ...>
[pid 10728] 08:35:36.310939 <... close resumed> ) = 0 <0.000031>
[pid 10728] 08:35:36.311052 setsid()    = 10728 <0.000006>
[pid 10728] 08:35:36.311116 dup2(3, 0)  = 0 <0.000005>
[pid 10728] 08:35:36.311326 dup2(4, 1)  = 1 <0.000004>
[pid 10728] 08:35:36.311342 dup2(5, 2)  = 2 <0.000003>
[pid 10728] 08:35:36.311353 close(3)    = 0 <0.000003>
[pid 10728] 08:35:36.311363 close(4)    = 0 <0.000006>
[pid 10728] 08:35:36.311379 close(5)    = 0 <0.000005>
[pid 10728] 08:35:36.311402 getpriority(PRIO_PROCESS, 0) = 20 <0.000004>
[pid 10728] 08:35:36.311416 setpriority(PRIO_PROCESS, 0, 5) = 0 <0.000006>
[pid 10728] 08:35:36.311431 getpriority(PRIO_PROCESS, 0) = 15 <0.000004>
[pid 10728] 08:35:36.311449 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000005>
[pid 10728] 08:35:36.311478 execve("/usr/lib/nagios/plugins/check_ping", ["/usr/lib/nagios/plugins/check_ping", "-4", "-H", "redacted", "-c", "200,25%", "-w", "150,20%"], [/* 20 vars */]) = 0 <0.000214>
widhalmt commented 6 years ago

The kill -HUP tricks also solves my problem with the broken IDO connection.

dnsmichi commented 6 years ago

Atm I'm doing the same as @Al2Klimov with bisecting and testing old git commits. This takes a while with compiling each in a VM - you can help and do the same with the instructions in https://github.com/Icinga/icinga2/issues/6445#issuecomment-405963068. This issue leads at least to two different things: a) broken timers b) log handling with broken fds.

dnsmichi commented 6 years ago

daemonize() lacks the TimerThreadProc(), I've compared both runs from their spawned threads while waiting for the compile.

  thread #5
    frame #0: 0x00007fff55d95a1e libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff55f5e589 libsystem_pthread.dylib`_pthread_cond_wait + 732
    frame #2: 0x0000000100abe2b4 icinga2`boost::condition_variable::do_wait_until(this=0x0000000101a11ff8, m=0x000070000e4b7b70, timeout=0x000070000e4b7a40) at condition_variable.hpp:128
    frame #3: 0x0000000100b2afbd icinga2`bool boost::condition_variable::timed_wait<boost::date_time::subsecond_duration<boost::posix_time::time_duration, 1000ll> >(this=0x0000000101a11ff8, m=0x000070000e4b7b70, wait_duration=0x000070000e4b7b40) at condition_variable_fwd.hpp:160
    frame #4: 0x0000000100b37055 icinga2`icinga::Timer::TimerThreadProc() at timer.cpp:295
    frame #5: 0x0000000100b3b931 icinga2`void* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, void (*)()> >(void*) [inlined] decltype(__f=0x00007fdfaf8269e8)()>(fp)(std::__1::forward<>(fp0))) std::__1::__invoke<void (*)()>(void (*&&)()) at type_traits:4323
    frame #6: 0x0000000100b3b920 icinga2`void* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, void (*)()> >(void*) [inlined] void std::__1::__thread_execute<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, void (*)()>(__t=0x00007fdfaf8269e0)()>&, std::__1::__tuple_indices<>) at thread:342
    frame #7: 0x0000000100b3b8fc icinga2`void* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, void (*)()> >(__vp=0x00007fdfaf8269e0) at thread:352
    frame #8: 0x00007fff55f5d661 libsystem_pthread.dylib`_pthread_body + 340
    frame #9: 0x00007fff55f5d50d libsystem_pthread.dylib`_pthread_start + 377
    frame #10: 0x00007fff55f5cbf9 libsystem_pthread.dylib`thread_start + 13
dnsmichi commented 6 years ago 
michi@mbmif ~/coding/icinga/icinga2 (master=) $ grep -r 'Timer::Ptr' lib/
lib//compat/checkresultreader.hpp:  Timer::Ptr m_ReadTimer;
lib//compat/statusdatawriter.hpp:   Timer::Ptr m_StatusTimer;
lib//compat/compatlogger.hpp:   Timer::Ptr m_RotationTimer;
lib//checker/checkercomponent.hpp:  Timer::Ptr m_ResultTimer;
lib//notification/notificationcomponent.hpp:    Timer::Ptr m_NotificationTimer;
lib//perfdata/graphitewriter.hpp:   Timer::Ptr m_ReconnectTimer;
lib//perfdata/elasticsearchwriter.hpp:  Timer::Ptr m_FlushTimer;
lib//perfdata/opentsdbwriter.hpp:   Timer::Ptr m_ReconnectTimer;
lib//perfdata/perfdatawriter.hpp:   Timer::Ptr m_RotationTimer;
lib//perfdata/gelfwriter.hpp:   Timer::Ptr m_ReconnectTimer;
lib//perfdata/influxdbwriter.hpp:   Timer::Ptr m_FlushTimer;
lib//db_ido/dbconnection.hpp:   Timer::Ptr m_CleanUpTimer;
lib//db_ido/dbconnection.hpp:   static Timer::Ptr m_ProgramStatusTimer;
lib//db_ido/dbconnection.cpp:Timer::Ptr DbConnection::m_ProgramStatusTimer;
lib//icinga/scheduleddowntime.cpp:static Timer::Ptr l_Timer;
lib//icinga/icingaapplication.cpp:static Timer::Ptr l_RetentionTimer;
lib//icinga/comment.cpp:static Timer::Ptr l_CommentsExpireTimer;
lib//icinga/clusterevents-check.cpp:Timer::Ptr ClusterEvents::m_LogTimer;
lib//icinga/clusterevents.hpp:  static Timer::Ptr m_LogTimer;
lib//icinga/timeperiod.cpp:static Timer::Ptr l_UpdateTimer;
lib//icinga/downtime.cpp:static Timer::Ptr l_DowntimesExpireTimer;
lib//icinga/downtime.cpp:static Timer::Ptr l_DowntimesStartTimer;
lib//db_ido_pgsql/idopgsqlconnection.hpp:   Timer::Ptr m_ReconnectTimer;
lib//db_ido_pgsql/idopgsqlconnection.hpp:   Timer::Ptr m_TxTimer;
lib//base/object.cpp:static Timer::Ptr l_ObjectCountTimer;
lib//base/timer.cpp:        OnTimerExpired(Timer::Ptr(this));
lib//base/timer.cpp:        Timer::Ptr ptimer = timer;
lib//base/streamlogger.hpp: Timer::Ptr m_FlushLogTimer;
lib//base/timer.hpp:    boost::signals2::signal<void(const Timer::Ptr&)> OnTimerExpired;
lib//base/workqueue.hpp:    Timer::Ptr m_StatusTimer;
lib//db_ido_mysql/idomysqlconnection.hpp:   Timer::Ptr m_ReconnectTimer;
lib//db_ido_mysql/idomysqlconnection.hpp:   Timer::Ptr m_TxTimer;
lib//remote/jsonrpcconnection.cpp:static Timer::Ptr l_JsonRpcConnectionTimeoutTimer;
lib//remote/jsonrpcconnection.cpp:static Timer::Ptr l_HeartbeatTimer;
lib//remote/apilistener.hpp:    Timer::Ptr m_Timer;
lib//remote/apilistener.hpp:    Timer::Ptr m_ReconnectTimer;
lib//remote/apilistener.hpp:    Timer::Ptr m_AuthorityTimer;
lib//remote/apilistener.hpp:    Timer::Ptr m_CleanupCertificateRequestsTimer;
lib//remote/httpserverconnection.cpp:static Timer::Ptr l_HttpServerConnectionTimeoutTimer;
lib//remote/consolehandler.cpp:static Timer::Ptr l_FrameCleanupTimer;
dnsmichi commented 6 years ago

Explains the logging: https://github.com/Icinga/icinga2/blob/master/lib/base/streamlogger.cpp#L75

dnsmichi commented 6 years ago

Seems like a race condition, new timers are initialized and started inside the object's Start() method. The TimerThreadProc() thread is started just once if not existing. This one time likely happens before daemonizing and then it gets killed away, l_AliveTimers is then still 1 not 0.

I'm testing a partial revert of 67390236785cb5b79cfa55cffe75f5f8648c6bd7 which starts the Timer thread during application startup and before the event loop again.

dnsmichi commented 6 years ago

Side note: We shouldn't implement daemonize() ourselves and always have to fiddle with threads before/after fork(). @Al2Klimov brought up the idea to implement a systemd-like wrapper which just forks before running 'icinga2 daemon', we will discuss that in a separate issue for 2.10+.

dnsmichi commented 6 years ago

@Al2Klimov in order to avoid the broken log timer flush, you can forcefully flush it every time. Full stop for everyone else, this is a performance killer.

diff --git a/lib/base/logger.cpp b/lib/base/logger.cpp
index 8c20231fb..4e31e2035 100644
--- a/lib/base/logger.cpp
+++ b/lib/base/logger.cpp
@@ -238,6 +238,10 @@ Log::~Log()

                if (entry.Severity >= logger->GetMinSeverity())
                        logger->ProcessLogEntry(entry);
+
+               //TODO: Debug
+               /* Always flush, don't depend on the timer. */
+               logger->Flush();
        }

        if (Logger::IsConsoleLogEnabled() && entry.Severity >= Logger::GetConsoleLogSeverity())
dnsmichi commented 6 years ago

I'm now working on macOS again, since I have nailed it down and compilation is faster than in a VM.

lldb doesn't allow to set follow-fork-mode child like gdb does, still this doesn't work reliably in my tests on the Debian VM, so I am back to adding some custom logging to see exactly what's going on.

This is the startup period, before the fork, one of the objects already calls Start() which initializes the timers.

mbmif /usr/local/icinga2 (master *) # icinga2 daemon -d
[2018-07-19 11:26:53 +0200] critical/Timer: TimerThreadProc started.
[2018-07-19 11:26:53 +0200] critical/Timer: TimerThreadProc started.
[2018-07-19 11:26:53 +0200] critical/Timer: TimerThreadProc started.
[2018-07-19 11:26:53 +0200] critical/Timer: Initializing TimerThreadProc, alive timers: 0
[2018-07-19 11:26:53 +0200] critical/Timer: TimerThreadProc started.
[2018-07-19 11:26:53 +0200] information/cli: Icinga application loader (version: v2.9.0; debug)
[2018-07-19 11:26:53 +0200] information/cli: Loading configuration file(s).
[2018-07-19 11:26:53 +0200] information/ConfigItem: Committing config item(s).
[2018-07-19 11:26:53 +0200] information/ApiListener: My API identity: mbmif.int.netways.de

Then somewhere fork() happens. Added a log entry there as well for debugging.

The second log line for TimerThreadProc is a patch of mine which forcefully initializes the Timer again. At this time, already 4 Timers have been spawned beforehand, and one of them has had started the timer thread.

[2018-07-19 11:26:53 +0200] information/ScriptGlobal: Dumping variables to file '/usr/local/icinga2/var/cache/icinga2/icinga2.vars'
[2018-07-19 11:26:53 +0200] critical/Daemonize(): After fork in child
[2018-07-19 11:26:53 +0200] critical/Timer: Initializing TimerThreadProc, alive timers: 4
[2018-07-19 11:26:53 +0200] information/ConfigObject: Restoring program state from file '/usr/local/icinga2/var/lib/icinga2/icinga2.state'
[2018-07-19 11:26:53 +0200] information/ConfigObject: Restored 558 objects. Loaded 1 new objects without state.
[2018-07-19 11:26:53 +0200] information/ConfigItem: Triggering Start signal for config items

Need to test a little more here.

matthewsaum commented 6 years ago

Hello All. I feel I should also mention this, as I don't see it anywhere else here. I have the exact same issue on SLES11SP4. Just adding to the list of affected OSs.

dnsmichi commented 6 years ago

I'm not inclined with changing the way daemonize() works for a bugfix release, the above linked PR is something for 2.10+. I'll prepare a PR which fixes the timer thread initialization.

dnsmichi commented 6 years ago

We've been discussing and working on the fix in parallel offline. I'll adopt the linked PR with some additional logging and comments.

Something like 

[2018-07-19 13:01:27 +0200] critical/Daemonize(): Child process with PID 98805 continues; re-initializing base.

is pretty helpful with daemonize() (as debug log, not critical).

dnsmichi commented 6 years ago

In addition to that, the TimerThreadProc start will also log something to the debug log, avoiding the typical gdb backtrace. If it is not logged you'll know that something is beyond repair.