Icinga2: Director kickstart wizard querying the API results in TLS stream disconnected infinite loop

[nilmerg]

There's seemingly something broken with the cleanup of TLS connections. Launching the director's kickstart results for me in a huge log file. Just succeeded to reproduce this and got ~10 million times the following log message:

warning/TlsStream: TLS stream was disconnected.

Had to stop Icinga 2 so that my logfile stops growing after it reached 8gb 800mb.

Additional note: That's the icinga2.log I'm speaking about. Since debuglog is enabled, the figures above need to be doubled.

Current Behavior

Too much / Unnecessary log messages.

Possible Solution

Less log messages.

Steps to Reproduce (for bugs)

1. Configure the API (default settings)
2. Launch the director's kickstart
3. Restart php-fpm because the kickstart does not finish (see below)
4. Run a tail -f on the log and enjoy the view

Context

I guess I need to add that I suffer from https://github.com/Icinga/icingaweb2-module-director/issues/1543.

Your Environment

• Version used (icinga2 --version): v2.8.4-814-gebd9d45
• Operating System and version: CentOS Linux release 7.4.1708 (Core)
• Enabled features (icinga2 feature list): api command compatlog debuglog ido-mysql mainlog notification statusdata
• Icinga Web 2 version and modules (System - About): master@04913f369
• Director version: master@35815e0d

[dnsmichi]

Hm, this leads to the assumption that many connections are kept open, and never have been closed (should be visible with netstat). When FPM is shut down, it immediately disconnects the many of them.

[nilmerg]

That's while the kickstart is running. Does not grow/change in numbers when looked at longer.

# netstat -p | grep php-fpm
tcp        8      0 localhost:cslistener    localhost:54628         VERBUNDEN   13809/php-fpm: pool 
tcp        0      0 localhost.localdo:50200 ubuntu-hack-:cslistener VERBUNDEN   13809/php-fpm: pool 
tcp        0      0 localhost.localdo:50220 ubuntu-hack-:cslistener VERBUNDEN   13830/php-fpm: pool 
tcp        0      0 localhost.localdo:50212 ubuntu-hack-:cslistener VERBUNDEN   13867/php-fpm: pool 
tcp        0      0 localhost.localdo:50216 ubuntu-hack-:cslistener VERBUNDEN   13912/php-fpm: pool 
tcp        8      0 localhost:cslistener    localhost:54644         VERBUNDEN   13912/php-fpm: pool 
tcp        0      0 localhost:33382         localhost:5665          VERBUNDEN   13809/php-fpm: pool 
tcp        8      0 localhost:cslistener    localhost:54648         VERBUNDEN   13830/php-fpm: pool 
tcp        8      0 localhost:cslistener    localhost:54640         VERBUNDEN   13867/php-fpm: pool 
unix  3      [ ]         STREAM     VERBUNDEN     97926    13807/php-fpm: mast  
unix  3      [ ]         STREAM     VERBUNDEN     100973   13809/php-fpm: pool  
unix  3      [ ]         STREAM     VERBUNDEN     97925    13807/php-fpm: mast  
unix  3      [ ]         STREAM     VERBUNDEN     96024    13809/php-fpm: pool  
unix  3      [ ]         STREAM     VERBUNDEN     99221    13809/php-fpm: pool

[dnsmichi]

Wondering if this is a new problem, or does it exist with 2.8.4 as well?

[nilmerg]

I don't have a stable install available atm. Will try it on monday if noone jumps in earlier.

[dnsmichi]

I was able to reproduce it inside the standalone Vagrant box where the kickstart fails (even with Director v1.4.3). It doesn't happen with 2.8.4, just tested this. @lippserd is informed and we'll investigate further on Monday.

[dnsmichi]

Unfortunately icingacli director kickstart run --debug doesn't log anything so it is a hard guess what exactly is going on here on the client end. From a peek into the source, and a log watch, it queries /v1/objects/zones and /v1/objects/endpoints but for some reason, does not close the connection. Seems the cleanup thread for idle connections has some issues here, resulting in an endless disconnect loop.

More on Monday, this will delay the release.

[mcktr]

It seems that the first attempt to close the TlsStream never succeeds because a lock is held.

gdb --args /tmp/icinga2/lib/icinga2/sbin/icinga2 daemon -x debug
(gdb) b tlsstream.cpp:387
Breakpoint 1 at 0x442ce0: file /srv/icinga2/lib/base/tlsstream.cpp, line 387.
(gdb) b tlsstream.cpp:404
Breakpoint 2 at 0x442d4a: file /srv/icinga2/lib/base/tlsstream.cpp, line 404.
(gdb) r

Run the director kickstart wizard and wait until timeout is reached.

[2018-07-08 18:46:19 +0200] information/HttpServerConnection: No messages for Http connection have been received in the last 10 seconds.
[2018-07-08 18:46:19 +0200] debug/HttpServerConnection: Http client disconnected
[Switching to Thread 0x7ffff7f93700 (LWP 28625)]

Thread 18 "icinga2" hit Breakpoint 5, icinga::TlsStream::CloseInternal (this=0x7fffc8000be0, inDestructor=inDestructor@entry=false)
    at /srv/icinga2/lib/base/tlsstream.cpp:387
387     if (m_Eof)
(gdb) info threads 
  Id   Target Id         Frame 
  1    Thread 0x7ffff7fdd740 (LWP 28598) "icinga2" 0x00007ffff50eb28d in nanosleep () at ../sysdeps/unix/syscall-template.S:84
  17   Thread 0x7ffff7f52700 (LWP 28624) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
* 18   Thread 0x7ffff7f93700 (LWP 28625) "icinga2" icinga::TlsStream::CloseInternal (this=0x7fffc8000be0, 
    inDestructor=inDestructor@entry=false) at /srv/icinga2/lib/base/tlsstream.cpp:387
  19   Thread 0x7ffff7fd4700 (LWP 28626) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  20   Thread 0x7ffff7f11700 (LWP 28627) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  21   Thread 0x7ffff7ed0700 (LWP 28628) "icinga2" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
  22   Thread 0x7ffff7e8f700 (LWP 28636) "icinga2" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
  27   Thread 0x7ffff7e4e700 (LWP 28641) "icinga2" 0x00007ffff69ea3ed in accept () at ../sysdeps/unix/syscall-template.S:84
  28   Thread 0x7ffff1f14700 (LWP 28642) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  29   Thread 0x7ffff0108700 (LWP 28643) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  31   Thread 0x7ffff0086700 (LWP 28662) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  32   Thread 0x7ffff0045700 (LWP 28663) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  33   Thread 0x7fffdae41700 (LWP 28664) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  34   Thread 0x7fffdae00700 (LWP 28665) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  35   Thread 0x7fffdadbf700 (LWP 28666) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  36   Thread 0x7fffdad7e700 (LWP 28667) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  37   Thread 0x7fffdad3d700 (LWP 28668) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  38   Thread 0x7fffdacfc700 (LWP 28669) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  39   Thread 0x7fffdacbb700 (LWP 28670) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
(gdb) c

Continued and waited a moment until I interrupted.

[2018-07-08 18:47:31 +0200] debug/IdoPgsqlConnection: Query: COMMIT
[2018-07-08 18:47:31 +0200] debug/IdoPgsqlConnection: Query: BEGIN
[2018-07-08 18:47:32 +0200] debug/IdoPgsqlConnection: Query: COMMIT
[2018-07-08 18:47:32 +0200] debug/IdoPgsqlConnection: Query: BEGIN
^C
(gdb) info threads 
  Id   Target Id         Frame 
* 1    Thread 0x7ffff7fdd740 (LWP 28598) "icinga2" 0x00007ffff50eb28d in nanosleep () at ../sysdeps/unix/syscall-template.S:84
  17   Thread 0x7ffff7f52700 (LWP 28624) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  18   Thread 0x7ffff7f93700 (LWP 28625) "icinga2" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  19   Thread 0x7ffff7fd4700 (LWP 28626) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  20   Thread 0x7ffff7f11700 (LWP 28627) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  21   Thread 0x7ffff7ed0700 (LWP 28628) "icinga2" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
  22   Thread 0x7ffff7e8f700 (LWP 28636) "icinga2" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
  27   Thread 0x7ffff7e4e700 (LWP 28641) "icinga2" 0x00007ffff69ea3ed in accept () at ../sysdeps/unix/syscall-template.S:84
  28   Thread 0x7ffff1f14700 (LWP 28642) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  29   Thread 0x7ffff0108700 (LWP 28643) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  31   Thread 0x7ffff0086700 (LWP 28662) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  32   Thread 0x7ffff0045700 (LWP 28663) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  33   Thread 0x7fffdae41700 (LWP 28664) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  34   Thread 0x7fffdae00700 (LWP 28665) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  35   Thread 0x7fffdadbf700 (LWP 28666) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  36   Thread 0x7fffdad7e700 (LWP 28667) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  37   Thread 0x7fffdad3d700 (LWP 28668) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  38   Thread 0x7fffdacfc700 (LWP 28669) "icinga2" 0x00007ffff511c0c3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  39   Thread 0x7fffdacbb700 (LWP 28670) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  40   Thread 0x7ffff00c7700 (LWP 28700) "icinga2" pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185

As you can see the first breakpoint at tlsstream.cpp:387 is hit, but the second at tlsstream.cpp:404 not. You also see that Thread 18 hangs at __lll_lock_wait, I tracked the waiting lock down to httpserverconnection.cpp:345.

(gdb) thread 18
[Switching to thread 18 (Thread 0x7ffff7f93700 (LWP 28625))]
#0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
135 ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: Datei oder Verzeichnis nicht gefunden.
(gdb) bt
#0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x00007ffff69e3b95 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x7fffc8004480) at ../nptl/pthread_mutex_lock.c:80
#2  0x00005555559b8668 in boost::posix::pthread_mutex_lock (m=<optimized out>) at /usr/include/boost/thread/pthread/mutex.hpp:62
#3  boost::mutex::lock (this=<optimized out>) at /usr/include/boost/thread/pthread/mutex.hpp:116
#4  boost::unique_lock<boost::mutex>::lock (this=0x7ffff7f91c40) at /usr/include/boost/thread/lock_types.hpp:346
#5  0x0000555555a9b478 in boost::unique_lock<boost::mutex>::unique_lock (m_=..., this=0x7ffff7f91c40)
    at /usr/include/boost/thread/lock_types.hpp:124
#6  icinga::HttpServerConnection::DataAvailableHandler (this=0x7fffc80043e0)
    at /srv/icinga2/lib/remote/httpserverconnection.cpp:345
#7  0x00005555559f2d39 in boost::function1<void, boost::intrusive_ptr<icinga::Stream> const&>::operator() (a0=..., 
    this=<optimized out>) at /usr/include/boost/function/function_template.hpp:771
#8  boost::signals2::detail::call_with_tuple_args<boost::signals2::detail::void_type>::m_invoke<boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)>, 0u, boost::intrusive_ptr<icinga::Stream> const&>(boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)>&, boost::signals2::detail::unsigned_meta_array<0u>, std::tuple<boost::intrusive_ptr<icinga::Stream> const&> const&, boost::enable_if<boost::is_void<boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)>::result_type>, void>::type*) const (this=<optimized out>, args=..., func=...) at /usr/include/boost/signals2/detail/variadic_slot_invoker.hpp:105
#9  boost::signals2::detail::call_with_tuple_args<boost::signals2::detail::void_type>::operator()<boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)>, boost::intrusive_ptr<icinga::Stream> const&, 1ul>(boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)>&, std::tuple<boost::intrusive_ptr<icinga::Stream> const&> const&, mpl_::size_t<1ul>) const (
    this=<optimized out>, args=..., func=...) at /usr/include/boost/signals2/detail/variadic_slot_invoker.hpp:90
#10 boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>::operator()<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >(boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > const&) const (
    connectionBody=..., this=<optimized out>) at /usr/include/boost/signals2/detail/variadic_slot_invoker.hpp:133
#11 boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> >::dereference() const (this=0x7ffff7f91ed0) at /usr/include/boost/signals2/detail/slot_call_iterator.hpp:110
#12 boost::iterators::iterator_core_access::dereference<boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >(boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>, std::_List_iterator<boost::shar---Type <return> to continue, or q <return> to quit---
ed_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > const&) (f=...) at /usr/include/boost/iterator/iterator_facade.hpp:549
#13 boost::iterators::detail::iterator_facade_base<boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> >, boost::signals2::detail::void_type, boost::iterators::single_pass_traversal_tag, boost::signals2::detail::void_type&, long, false, false>::operator*() const (this=0x7ffff7f91ed0)
    at /usr/include/boost/iterator/iterator_facade.hpp:655
#14 boost::signals2::optional_last_value<void>::operator()<boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >(boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> >, boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> >) const (this=<optimized out>, first=..., last=...)
    at /usr/include/boost/signals2/optional_last_value.hpp:57
#15 boost::signals2::detail::combiner_invoker<void>::operator()<boost::signals2::optional_last_value<void>, boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >(boost::signals2::optional_last_value<void>&, boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2:---Type <return> to continue, or q <return> to quit---
:detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> >, boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Stream> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Stream> const&), boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)> >, boost::signals2::mutex> >) const (this=<optimized out>, combiner=..., first=..., last=...)
    at /usr/include/boost/signals2/detail/result_type_wrapper.hpp:64
#16 boost::signals2::detail::signal_impl<void (boost::intrusive_ptr<icinga::Stream> const&), boost::signals2::optional_last_value<void>, int, std::less<int>, boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)>, boost::function<void (boost::signals2::connection const&, boost::intrusive_ptr<icinga::Stream> const&)>, boost::signals2::mutex>::operator()(boost::intrusive_ptr<icinga::Stream> const&) (this=0x7fffc80008c0, args#0=...) at /usr/include/boost/signals2/detail/signal_template.hpp:247
#17 0x0000555555996b72 in boost::signals2::signal<void (boost::intrusive_ptr<icinga::Stream> const&), boost::signals2::optional_last_value<void>, int, std::less<int>, boost::function<void (boost::intrusive_ptr<icinga::Stream> const&)>, boost::function<void (boost::signals2::connection const&, boost::intrusive_ptr<icinga::Stream> const&)>, boost::signals2::mutex>::operator()(boost::intrusive_ptr<icinga::Stream> const&) (args#0=..., this=0x7fffc8000bf8) at /usr/include/boost/signals2/detail/signal_template.hpp:723
#18 icinga::Stream::SignalDataAvailable (this=0x7fffc8000be0) at /srv/icinga2/lib/base/stream.cpp:55
#19 0x0000555555996e15 in icinga::TlsStream::CloseInternal (this=0x7fffc8000be0, inDestructor=inDestructor@entry=false)
    at /srv/icinga2/lib/base/tlsstream.cpp:393
#20 0x0000555555996f47 in icinga::TlsStream::Close (this=<optimized out>) at /srv/icinga2/lib/base/tlsstream.cpp:382
#21 0x0000555555a8f245 in icinga::HttpServerConnection::Disconnect (this=this@entry=0x7fffc80043e0)
    at /srv/icinga2/lib/remote/httpserverconnection.cpp:94
#22 0x0000555555a8f559 in icinga::HttpServerConnection::CheckLiveness (this=0x7fffc80043e0)
    at /srv/icinga2/lib/remote/httpserverconnection.cpp:372
#23 icinga::HttpServerConnection::TimeoutTimerHandler () at /srv/icinga2/lib/remote/httpserverconnection.cpp:381
#24 0x00005555559f3e29 in boost::function1<void, boost::intrusive_ptr<icinga::Timer> const&>::operator() (a0=..., 
    this=<optimized out>) at /usr/include/boost/function/function_template.hpp:771
#25 boost::signals2::detail::call_with_tuple_args<boost::signals2::detail::void_type>::m_invoke<boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)>, 0u, boost::intrusive_ptr<icinga::Timer> const&>(boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)>&, boost::signals2::detail::unsigned_meta_array<0u>, std::tuple<boost::intrusive_ptr<icinga::Timer> const&> const&, boost::enable_if<boost::is_void<boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)>::result_type>, void>::type*) const
    (this=<optimized out>, args=..., func=...) at /usr/include/boost/signals2/detail/variadic_slot_invoker.hpp:105
#26 boost::signals2::detail::call_with_tuple_args<boost::signals2::detail::void_type>::operator()<boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)>, boost::intrusive_ptr<icinga::Timer> const&, 1ul>(boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)>&, std::tuple<boost::intrusive_ptr<icinga::Timer> const&> const&, mpl_::size_t<1ul>) const (this=<optimized out>, 
    args=..., func=...) at /usr/include/boost/signals2/detail/variadic_slot_invoker.hpp:90
#27 boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>::---Type <return> to continue, or q <return> to quit---
operator()<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >(boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > const&) const (connectionBody=..., 
    this=<optimized out>) at /usr/include/boost/signals2/detail/variadic_slot_invoker.hpp:133
#28 boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> >::dereference() const (this=0x7ffff7f92630) at /usr/include/boost/signals2/detail/slot_call_iterator.hpp:110
#29 boost::iterators::iterator_core_access::dereference<boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >(boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > const&) (f=...) at /usr/include/boost/iterator/iterator_facade.hpp:549
#30 boost::iterators::detail::iterator_facade_base<boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> >, boost::signals2::detail::void_type, boost::iterators::single_pass_traversal_tag, boost::signals2::detail::void_type&, long, false, false>::operator*() const (this=0x7ffff7f92630)
    at /usr/include/boost/iterator/iterator_facade.hpp:655
#31 boost::signals2::optional_last_value<void>::operator()<boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >(boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::varia---Type <return> to continue, or q <return> to quit---
dic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> >, boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> >) const (this=<optimized out>, first=..., last=...)
    at /usr/include/boost/signals2/optional_last_value.hpp:57
#32 boost::signals2::detail::combiner_invoker<void>::operator()<boost::signals2::optional_last_value<void>, boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >(boost::signals2::optional_last_value<void>&, boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> >, boost::signals2::detail::slot_call_iterator_t<boost::signals2::detail::variadic_slot_invoker<boost::signals2::detail::void_type, boost::intrusive_ptr<icinga::Timer> const&>, std::_List_iterator<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> > >, boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void (boost::intrusive_ptr<icinga::Timer> const&), boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)> >, boost::signals2::mutex> >) const (this=<optimized out>, combiner=..., first=..., last=...)
    at /usr/include/boost/signals2/detail/result_type_wrapper.hpp:64
#33 boost::signals2::detail::signal_impl<void (boost::intrusive_ptr<icinga::Timer> const&), boost::signals2::optional_last_value<void>, int, std::less<int>, boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)>, boost::function<void (boost::signals2::connection const&, boost::intrusive_ptr<icinga::Timer> const&)>, boost::signals2::mutex>::operator()(boost::intrusive_ptr<icinga::Timer> const&) (this=0x7fffc8005d40, args#0=...) at /usr/include/boost/signals2/detail/signal_template.hpp:247
#34 0x0000555555997712 in boost::signals2::signal<void (boost::intrusive_ptr<icinga::Timer> const&), boost::signals2::optional_last_value<void>, int, std::less<int>, boost::function<void (boost::intrusive_ptr<icinga::Timer> const&)>, boost::function<void (boost::signals2::connection const&, boost::intrusive_ptr<icinga::Timer> const&)>, boost::signals2::mutex>::operator()(boost::intrusive_ptr<icinga::Timer> const&) (args#0=..., this=0x7fffc8005d08) at /usr/include/boost/signals2/detail/signal_template.hpp:723
---Type <return> to continue, or q <return> to quit---
#35 icinga::Timer::Call (this=0x7fffc8005cf0) at /srv/icinga2/lib/base/timer.cpp:102
#36 0x0000555555962b6f in std::function<void ()>::operator()() const (this=0x7ffff7f929b0) at /usr/include/c++/6/functional:2127
#37 icinga::ThreadPool::WorkerThread::ThreadProc (this=0x5555561b3950 <icinga::Application::GetTP()::tp+1648>, queue=...)
    at /srv/icinga2/lib/base/threadpool.cpp:137
#38 0x00007ffff79bf116 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_thread.so.1.62.0
#39 0x00007ffff69e1494 in start_thread (arg=0x7ffff7f93700) at pthread_create.c:333
#40 0x00007ffff511bacf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
(gdb) f 6
#6  icinga::HttpServerConnection::DataAvailableHandler (this=0x7fffc80043e0)
    at /srv/icinga2/lib/remote/httpserverconnection.cpp:345
345         boost::mutex::scoped_lock lock(m_DataHandlerMutex);

So because of the hanging thread and the not closed TlsStream the log gets flooded with log TLS stream was disconnected. messages.

Possible solution:

Move the lock in TlsStream::CloseInternal over the SignalDataAvailable() call.

diff --git a/lib/base/tlsstream.cpp b/lib/base/tlsstream.cpp
index 33d72d465..dd94a6e26 100644
--- a/lib/base/tlsstream.cpp
+++ b/lib/base/tlsstream.cpp
@@ -389,6 +389,8 @@ void TlsStream::CloseInternal(bool inDestructor)

        m_Eof = true;

+       boost::mutex::scoped_lock lock(m_Mutex);
+
        if (!inDestructor)
                SignalDataAvailable();

@@ -396,8 +398,6 @@ void TlsStream::CloseInternal(bool inDestructor)

        Stream::Close();

-       boost::mutex::scoped_lock lock(m_Mutex);
-
        if (!m_SSL)
                return;

With this the thread does not hang and the TlsStream is successfully closed. Unfortunately I think this fixes only a symptom and not the root cause. The director kickstart is still broken.

I noticed, when I revert the changes from 3c7851107c254e80c65cd4f2b42c20b61dfa5146 that the director kickstart succeeds. So I think that the change to TlsStream::IsEof influence the result of the if condition at httpserverconnection.cpp:344.

https://github.com/Icinga/icinga2/blob/ebd9d45a9b02f0fc391102e514dfce3ef332e308/lib/remote/httpserverconnection.cpp#L340-L348

[Al2Klimov]

Hello @mcktr and thank you for both investigation and providing a possible solution!

However that fix seems not to close the connection at all. Instead the scoped lock constructor hangs forever and even when I press ^C ... Icinga don't shut down completely.

I'll try to find the actual root cause...

Btw. the log spam occurs only if I restart PHP-FPM after the following message has been logged:

[2018-07-09 11:19:34 +0200] information/HttpServerConnection: No messages for Http connection have been received in the last 10 seconds.

Best,
AK

[Al2Klimov]

The director seems not to close an HTTPS connection by itself so HttpServerConnection#CheckLiveness() does the cleanup. However TlsStream#CloseInternal() calls Stream#SignalDataAvailable() – which hangs – before SocketEvents#Unregister(). So the underlying socket gets never unregistered from the socket I/O engine which keeps polling. The socket is always "ready" and causes the data handler to be called repeatedly which causes the log spam.

Stream#SignalDataAvailable() effectively calls HttpServerConnection#DataAvailableHandler() which seems not to be able to acquire a scoped lock on HttpServerConnection#m_DataHandlerMutex because someone else has already locked it. The only other locker is HttpServerConnection#Disconnect() which hangs while calling HttpServerConnection#m_Stream->Close().

[dnsmichi]

Took the chance to finally upgrade my PHP on macOS with curl, openssl and 7.2, and let it run locally.

Preparations

Director

mysql -e "CREATE DATABASE director CHARACTER SET 'utf8';
   GRANT ALL ON director.* TO director@localhost IDENTIFIED BY 'director';"

Create resource.

Prepare and run migrations.

mbmif /usr/local/icingaweb2/etc/modules/director # vim config.ini

[db]
resource = "director"

icingacli director migration run --verbose
icingacli director migration pending --verbose

Prepare kickstart.ini

# cat /usr/local/icingaweb2/etc/modules/director/kickstart.ini
[config]
endpoint = mbmif.int.netways.de
host = 127.0.0.1
port = 5665
username = root
password = icinga

Tests

The CLI command keeps the HTTP connection open, thus not closing it. The bug only happens after our cleanup handler kicks in.

CLI

icingacli director kickstart run --verbose

Fixed

[2018-07-09 15:59:21 +0200] information/ApiListener: New client connection from [::ffff:127.0.0.1]:61191 (no client certificate)
[2018-07-09 15:59:21 +0200] information/HttpServerConnection: Request: GET /v1/objects/zones (from [::ffff:127.0.0.1]:61191, user: root)
[2018-07-09 15:59:21 +0200] information/HttpServerConnection: Request: GET /v1/objects/endpoints (from [::ffff:127.0.0.1]:61191, user: root)
[2018-07-09 15:59:21 +0200] information/ApiListener: New client connection from [::ffff:127.0.0.1]:61192 (no client certificate)
[2018-07-09 15:59:21 +0200] information/HttpServerConnection: Request: GET /v1/status (from [::ffff:127.0.0.1]:61192, user: root)
[2018-07-09 15:59:21 +0200] information/HttpServerConnection: Request: GET /v1/objects/zones (from [::ffff:127.0.0.1]:61192, user: root)
[2018-07-09 15:59:31 +0200] information/WorkQueue: #11 (HttpServerConnection) items: 0, rate: 0.1/s (6/min 6/5min 6/15min);
[2018-07-09 15:59:36 +0200] information/HttpServerConnection: No messages for Http connection have been received in the last 10 seconds.
[2018-07-09 15:59:36 +0200] information/ApiListener: New client connection from [::ffff:127.0.0.1]:61203 (no client certificate)
[2018-07-09 15:59:36 +0200] information/HttpServerConnection: Request: POST /v1/console/execute-script (from [::ffff:127.0.0.1]:61203, user: root)
[2018-07-09 15:59:36 +0200] information/HttpServerConnection: Request: GET /v1/objects/checkcommands (from [::ffff:127.0.0.1]:61203, user: root)
[2018-07-09 15:59:46 +0200] information/WorkQueue: #12 (HttpServerConnection) items: 0, rate: 0.1/s (6/min 6/5min 6/15min);
[2018-07-09 15:59:51 +0200] information/HttpServerConnection: No messages for Http connection have been received in the last 10 seconds.
[2018-07-09 15:59:51 +0200] information/ApiListener: New client connection from [::ffff:127.0.0.1]:61208 (no client certificate)
[2018-07-09 15:59:51 +0200] information/HttpServerConnection: Request: POST /v1/console/execute-script (from [::ffff:127.0.0.1]:61208, user: root)
[2018-07-09 15:59:51 +0200] information/HttpServerConnection: Request: GET /v1/objects/notificationcommands (from [::ffff:127.0.0.1]:61208, user: root)
[2018-07-09 16:00:01 +0200] information/WorkQueue: #13 (HttpServerConnection) items: 0, rate: 0.1/s (6/min 6/5min 6/15min);
[2018-07-09 16:00:06 +0200] information/HttpServerConnection: No messages for Http connection have been received in the last 10 seconds.
[2018-07-09 16:00:06 +0200] information/ApiListener: New client connection from [::ffff:127.0.0.1]:61216 (no client certificate)
[2018-07-09 16:00:06 +0200] information/HttpServerConnection: Request: POST /v1/console/execute-script (from [::ffff:127.0.0.1]:61216, user: root)
[2018-07-09 16:00:06 +0200] information/HttpServerConnection: Request: GET /v1/objects/eventcommands (from [::ffff:127.0.0.1]:61216, user: root)

In terms of the missing verbose logging for the kickstart CLI command, see icinga/icingaweb2-module-director#1563