Fix: sessiond: bad fd used while rotating exiting app's buffers
Issue observed
--------------
From bug #1372:
We are observing seemingly random crashes in the LTTng consumer daemon
when tracing a C++ application with LTTng-UST. Our workload has a single
printf-like tracepoint, where each string is in the order of 1kb and the
total output is around 30MB/s.
LTTng is set up with a single session and channel enabling this
tracepoint, and we enabled rotation with a maximum size of 100MB or
every 30 seconds. We are periodically starting new traced processes and
the system runs close to 100% CPU load. This ran on an AWS
Graviton2 (ARM) instance with CentOS 7 and a 5.4 kernel, using LTTng-UST
2.13.5 and LTTng-tools 2.13.8.
The first reported error is a write to a bad file descriptor (-1),
apparently when waking up the metadata poll thread during a rotation.
Cause
-----
Inspecting the logs, we see that the metadata channel with key 574 has a
negative poll fd write end which causes the write in
consumer_metadata_wakeup_pipe to fail because of an invalid file
descriptor:
DBG1 - 15:12:13.
271001175 [6593/6605]: Waking up metadata poll thread (writing to pipe): channel name = 'metadata', channel key = 574 (in consumer_metadata_wakeup_pipe() at consumer.c:888)
DBG3 - 15:12:13.
271010093 [6593/6605]: write() fd = -1 (in consumer_metadata_wakeup_pipe() at consumer.c:892)
PERROR - 15:12:13.
271014655 [6593/6605]: Failed to write to UST metadata pipe while attempting to wake-up the metadata poll thread: Bad file descriptor (in consumer_metadata_wakeup_pipe() at consumer.c:907)
Error: Failed to dump the metadata cache
Error: Rotate channel failed
Meanwhile, a lot of applications seem to be unregistering. Notably, the
application associated with that metadata channel is being torn down.
Leading up to the use of a bad file descriptor, the chain of events is:
1) The "rotation" thread starts to issue "Consumer rotate channel" on
key 574 (@ `15:12:12.
865621802`), but blocks on the consumer socket
lock. We can deduce this from the fact that thread "6605" in the
consumer wakes up to process an unrelated command originating from the
same socket.
We don't see that command being issued by the session daemon, most
likely because it occurs just before the captured logs start. All
call sites that use this socket take the socket lock, issue their
command, wait for a reply, and release the socket lock.
2) The application unregisters (@ `15:12:13.
269722736`). The
`registry_session`, which owns the metadata contents, is destroyed
during `delete_ust_app_session` which is done directly as a consequence
of the app unregistration (through a deferred RCU call), see
`ust_app_unregister`.
This is problematic since the consumer will request the metadata during
the rotation of the metadata channel. In the logs, we can see that
the "close_metadata" command blocks on the consumer socket lock.
However, the problem occurs when the `manage-apps` acquires the lock
before the "rotation" thread. In this instance, the "close-metadata"
command is performed by the consumer daemon, closing the metadata
poll file descriptor.
3) As the "close_metadata" command completes, the rotation thread
successfully acquires the socket lock. It is not aware of the
unregistration of the application and of the subsequent tear-down of the
application, registry, and channels since it was already iterating on
the application's channels.
The consumer starts to process the channel rotation command (@
`15:12:13.
270633213`) which fails on the metadata poll fd.
Essentially, we must ensure that the lifetime of metadata
channel/streams exceeds any ongoing rotation, and prevent a rotation
from being launched when an application is being torn-down in per-PID
buffering mode.
The problem is fairly hard to reproduce as it requires threads to
wake-up in the problematic order described above. I don't have a
straight-forward reproducer for the moment.
Solution
--------
During the execution of a rotation on a per-pid session, the session
daemon iterates on all applications to rotate their data and metadata
channels.
The `ust_app` itself is correctly protected: it is owned by an RCU HT
(`ust_app_ht`) and the RCU read lock is acquired as required to protect
the lifetime of the storage of `ust_app`. However, there is no way to
lock an `ust_app` instance itself.
The rotation command assumes that if it finds the `ust_app`, it will be
able to rotate all of its channels. This isn't true: the `ust_app` can
be unregistered by the `manage-applications` thread which monitors the
application sockets for their deaths in order to teardown the
applications.
The `ust_app` doesn't directly own its channels; they are owned by an
`ust_app_session` which, itself, has a `lock` mutex. Also, the metadata
of the application is owned by the "session registry", which itself can
also be locked.
At a high-level, we want to ensure that the metadata isn't closed while
a rotation is being setup. The registry lock could provide this
guarantee. However, it currently needs to remain unlocked during the
setup of the rotation as it is used when providing the metadata to the
consumer daemon.
Taking the registry lock over the duration of the setup would result in
a deadlock like so:
- the consumer buffer consumption thread consumed a data buffer and attempts
a metadata sync,
- the command handling thread of the consumer daemon attempts to rotate
any stream that is already at its rotation position and locks on the
channel lock held by the consumption thread,
- the metadata sync launches a metadata request against the session
daemon which attempts to refresh the metadata contents through the
command socket,
- the command handling thread never services the metadata "refresh" sent
by the session daemon since it is locked against the same channel as
the buffer consumption thread, resulting in a deadlock.
Instead, a different approach is required: extending the lifetime of the
application's channels over the duration of the setup of a rotation.
To do so, the `ust_app` structure (which represents a registered
application) is now reference-counted. A reference is acquired over the
duration of the rotation's setup phase. This reference transitively
holds a reference the application's tracing buffers.
Note that taking a reference doesn't prevent applications from
unregistering; it simply defers the reclamation of their buffers to the
end of the rotation setup.
As the rotation completes its setup phase, the references to the
application (and thus, its tracing buffers) are released, allowing the
reclamation of all buffering ressources.
Note that the setup phase of the rotation doesn't last long so it
shouldn't significantly change the observable behaviour in terms of
memory usage. The setup phase mostly consists in sampling the
consumption/production positions of all buffers in order to establish a
switch-over point between the old and new files.
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I8dc1ee45dd00c85556dd70d34a3af4f3a4d4e7cb