rgw: add abstraction for ops log destination and add file logger #43329

cfsnyder · 2021-09-28T11:43:01Z

Adds an OpsLogSink abstraction for ops log destinations. Also implements
this abstraction for a file logger since it's easier to use files vs.
sockets with containers.

Fixes: https://tracker.ceph.com/issues/48752
Signed-off-by: Cory Snyder csnyder@iland.com

mattbenjamin

I think this is cogently written. My main questions are about buffering options on the output file. Am I missing where that is handled?

mattbenjamin · 2021-09-28T12:54:50Z

src/rgw/librgw.cc

@@ -589,10 +588,17 @@ namespace rgw {

    // XXX ex-RGWRESTMgr_lib, mgr->set_logging(true)

+    OpsLogManifold* olog_manifold = new OpsLogManifold();


ok, I think this is a sane design

mattbenjamin · 2021-09-28T12:55:37Z

src/rgw/rgw_log.cc


-  bl.append(s);
+void OpsLogManifold::add_sink(OpsLogSink *sink)


for consistency and Stroustrupness, "OpsLogSink* sink"

mattbenjamin · 2021-09-28T12:57:17Z

src/rgw/rgw_log.cc

+int OpsLogFile::log_json(struct req_state* s, bufferlist& bl)
+{
+  lock.lock();
+  bl.write_stream(file);


when we do this, is the buffer being written out synchronously?

the socket version allows for a configurable amount of data to be in the socket buffer before being flushed--this is important for performance

@mattbenjamin Yeah that was a question that I intended to ask. For our use case, we don't want to lose these ops logs in the case of a process crash, so we prefer that they be written out synchronously. I can imagine that this might be less important for other users and that it might be desirable to have a knob to turn in order to control whether (and how much) buffering is used. Since you're confirming that this is important, I'll go ahead and work on that piece and update the PR.

these synchronous writes are unfortunately in conflict with the async refactoring project, where we're trying to eliminate all blocking waits from frontend threads. beast frontend requests run as coroutines, so when we can suspend that coroutine instead of blocking, that allows the thread to process other requests in the meantime

i'd eventually like to see this use something like libaio to make the file writes asynchronous

mattbenjamin · 2021-09-28T12:59:19Z

src/rgw/rgw_log.h

+  int log(struct req_state* s, struct rgw_log_entry& entry) override;
+};
+
+class JsonOpsLogSink : public OpsLogSink {


ok, that's expected

mattbenjamin · 2021-09-28T12:59:38Z

src/rgw/rgw_log.h

  ceph::Formatter *formatter;
-  ceph::mutex lock = ceph::make_mutex("OpsLogSocket");
+  ceph::mutex lock = ceph::make_mutex("JsonOpsLogSink");


I guess this is too...

I guess this may be where writing to the unix socket and attaching something to consume it and relay it to a file may have some advantage, but, it's still a valid choice

mattbenjamin · 2021-09-28T13:03:20Z

src/rgw/rgw_main.cc

@@ -518,12 +518,16 @@ int radosgw_Main(int argc, const char **argv)

  rgw::dmclock::SchedulerCtx sched_ctx{cct.get()};

-  OpsLogSocket *olog = NULL;
-
+  OpsLogManifold *olog = new OpsLogManifold();


OpsLogManifold seems like a verbose, but valid name :)

dang

Seems fine to me, once the buffering bits get in.

mattbenjamin · 2021-10-05T00:27:00Z

src/rgw/rgw_log.cc

-OpsLogSocket::~OpsLogSocket()
+void OpsLogFile::flush()
+{
+  std::scoped_lock flush_lock(flush_mutex);


can the log buffer append while the flush buffer is flushed?

I think iow that maybe you could get that behavior by introducing a flag and dropping this mutex during flush (apologies if I'm missing something)

The log_mutex is only held while swapping log_buffer and flush_buffer, so request threads can continue to append to the log buffer while the flush_buffer is actually being written out to disk. There should be minimal contention here between the loggers and the flusher. Let me know if I'm missing something, though! :)

ok, i see; this is basically fine, I think.

Adds an OpsLogSink abstraction for ops log destinations. Also implements this abstraction for a file logger since it's easier to use files vs. sockets with containers. Fixes: https://tracker.ceph.com/issues/48752 Signed-off-by: Cory Snyder <csnyder@iland.com>

mattbenjamin

can you set up an rgw suite run in teuthology?

mattbenjamin · 2021-10-05T12:07:24Z

src/rgw/rgw_log.cc

-OpsLogSocket::~OpsLogSocket()
+void OpsLogFile::flush()
+{
+  std::scoped_lock flush_lock(flush_mutex);


ok, i see; this is basically fine, I think.

cfsnyder · 2021-10-05T13:15:21Z

can you set up an rgw suite run in teuthology?

@mattbenjamin I haven't run teuthology suites myself yet. Any references or pointers on how to go about that?

mattbenjamin · 2021-10-05T13:22:17Z

hi @cfsnyder well, you need sepia (ceph test lab creds), and then you push your branch to ceph-ci.git, and then you request a teuthology run. There's detail here:
https://docs.ceph.com/en/octopus/dev/developer_guide/running-tests-using-teuth/
If you've never done this, we can try to see if others will help--I'll set the needs-qa flag.

mattbenjamin

approving, setting needs-qa

cfsnyder · 2021-10-05T13:48:08Z

hi @cfsnyder well, you need sepia (ceph test lab creds), and then you push your branch to ceph-ci.git, and then you request a teuthology run. There's detail here: https://docs.ceph.com/en/octopus/dev/developer_guide/running-tests-using-teuth/ If you've never done this, we can try to see if others will help--I'll set the needs-qa flag.

Thanks @mattbenjamin, I'll look into getting access to Sepia and figuring out how to do this for myself in the future. So far I've just been adding the needs-qa flag and letting Yuri handle that testing.

cfsnyder · 2021-10-26T12:14:04Z

Anything that I can do to get this included in a QA run so that it can be back-ported in time for the next Pacific release @mattbenjamin ?

mattbenjamin · 2021-10-26T12:30:47Z

Anything that I can do to get this included in a QA run so that it can be back-ported in time for the next Pacific release @mattbenjamin ?

I'll try to send one today

Matt

mattbenjamin · 2021-10-26T16:40:28Z

Ok, so I've re-reviewed this in view of @cbodley's comment regarding the in-progress async/non-blocking request processing refactor that we expect to land immanently in 2022. I do want the functionality that this PR offers, and I don't want to be anything less than welcoming of good and new work. But I think Casey has a point here, in that even the top-half/request threads are at least infrequently doing blocking operations and waiting for bottom-half flush operations to finalize. I would like to ask: is there a way we could potentially revise the i/o strategy to be explicitly non-blocking in the request path? I think ordinary non-blocking i/o, but also libaio or similar as Casey noted, would be sound ways to approach this. @cfsnyder is that something you could consider helping with?

mattbenjamin · 2021-10-26T16:45:48Z

@cbodley maybe the semantics of the existing ops-log path need some review discussion as well; iirc, the ops log socket is potentially lossy, if the receiver is unable to keep its queue under its max size. Maybe we could discuss all this more in the refactoring meeting? I think you've come to those, @cfsnyder?

mattbenjamin

per casey's feedback

mattbenjamin

per discussion in refactoring call, restoring approval

mattbenjamin · 2021-10-27T19:51:27Z

@cfsnyder wip-opslog-48752 created in ceph-ci; will start an rgw suite run when it's built

mattbenjamin · 2021-10-28T14:44:27Z

https://pulpito.ceph.com/mbenjamin-2021-10-28_10:36:16-rgw-wip-opslog-48752-distro-basic-smithi/

cfsnyder · 2021-10-29T14:56:27Z

@mattbenjamin I'm guessing the QA failures are unrelated to these changes but let me know if you think otherwise?

mattbenjamin · 2021-10-29T15:54:05Z

@cfsnyder I don't think any of the failures here are due to the ops-log change.
that said, @cbodley I haven't seen https://pulpito.ceph.com/mbenjamin-2021-10-28_10:36:16-rgw-wip-opslog-48752-distro-basic-smithi/6465138/ before; boto thinks ListBuckets needs to be re-tried? is this a client timeout?

mattbenjamin · 2021-10-29T16:19:46Z

ok, this passed; merging; opening a tracker issue for the new list-buckets failure on cleanup

wjwithagen · 2021-10-29T18:21:49Z

Clang/FreeBSD is not happy with this one:

/home/jenkins/workspace/ceph-master-compile/src/rgw/rgw_log.cc:391:16: error: no matching member function for call to 'wait'
    cond_flush.wait(lock);
    ~~~~~~~~~~~^~~~
/usr/include/c++/v1/__mutex_base:292:10: note: candidate function not viable: no known conversion from 'std::unique_lock<mutex_debug_impl<false>>' (aka 'std::unique_lock<ceph::mutex_debug_detail::mutex_debug_impl<false>>') to 'unique_lock<std::mutex> &' for 1st argument
    void wait(unique_lock<mutex>& __lk) _NOEXCEPT;
         ^
/usr/include/c++/v1/__mutex_base:403:21: note: candidate function template not viable: requires 2 arguments, but 1 was provided
condition_variable::wait(unique_lock<mutex>& __lk, _Predicate __pred)
                    ^
1 error generated.

Trying to fix, but keep running in all kinds of variations for this

cbodley · 2021-10-31T00:33:11Z

thanks @wjwithagen, #43751 should fix

github-actions bot added common rgw tests labels Sep 28, 2021

cfsnyder requested a review from mattbenjamin September 28, 2021 11:43

mattbenjamin reviewed Sep 28, 2021

View reviewed changes

mattbenjamin requested a review from dang September 28, 2021 13:04

dang reviewed Sep 28, 2021

View reviewed changes

cfsnyder force-pushed the wip-48752-generalize-ops-log-socket branch from cd07218 to 8e07cf1 Compare October 4, 2021 21:34

mattbenjamin reviewed Oct 5, 2021

View reviewed changes

cfsnyder force-pushed the wip-48752-generalize-ops-log-socket branch from 8e07cf1 to c4c9f39 Compare October 5, 2021 08:46

mattbenjamin reviewed Oct 5, 2021

View reviewed changes

mattbenjamin self-requested a review October 5, 2021 13:22

mattbenjamin approved these changes Oct 5, 2021

View reviewed changes

mattbenjamin added the needs-qa label Oct 5, 2021

mattbenjamin requested changes Oct 27, 2021

View reviewed changes

mattbenjamin self-requested a review October 27, 2021 19:48

mattbenjamin approved these changes Oct 27, 2021

View reviewed changes

mattbenjamin merged commit 852e9e7 into ceph:master Oct 29, 2021

cfsnyder mentioned this pull request Oct 29, 2021

pacific: rgw: add abstraction for ops log destination and add file logger #43740

Merged

rgw: add abstraction for ops log destination and add file logger #43329

rgw: add abstraction for ops log destination and add file logger #43329

cfsnyder commented Sep 28, 2021

mattbenjamin left a comment

mattbenjamin Sep 28, 2021

mattbenjamin Sep 28, 2021

mattbenjamin Sep 28, 2021

mattbenjamin Sep 28, 2021

cfsnyder Sep 28, 2021

cbodley Oct 6, 2021

mattbenjamin Sep 28, 2021

mattbenjamin Sep 28, 2021

mattbenjamin Sep 28, 2021

mattbenjamin Sep 28, 2021

dang left a comment

mattbenjamin Oct 5, 2021

mattbenjamin Oct 5, 2021

cfsnyder Oct 5, 2021

mattbenjamin Oct 5, 2021

mattbenjamin left a comment

mattbenjamin Oct 5, 2021

cfsnyder commented Oct 5, 2021

mattbenjamin commented Oct 5, 2021

mattbenjamin left a comment

cfsnyder commented Oct 5, 2021

cfsnyder commented Oct 26, 2021

mattbenjamin commented Oct 26, 2021

mattbenjamin commented Oct 26, 2021

mattbenjamin commented Oct 26, 2021

mattbenjamin left a comment

mattbenjamin left a comment

mattbenjamin commented Oct 27, 2021

mattbenjamin commented Oct 28, 2021

cfsnyder commented Oct 29, 2021

mattbenjamin commented Oct 29, 2021

mattbenjamin commented Oct 29, 2021

wjwithagen commented Oct 29, 2021

cbodley commented Oct 31, 2021

		@@ -589,10 +588,17 @@ namespace rgw {

		// XXX ex-RGWRESTMgr_lib, mgr->set_logging(true)

		OpsLogManifold* olog_manifold = new OpsLogManifold();


		bl.append(s);
		void OpsLogManifold::add_sink(OpsLogSink *sink)

rgw: add abstraction for ops log destination and add file logger #43329

rgw: add abstraction for ops log destination and add file logger #43329

Conversation

cfsnyder commented Sep 28, 2021

mattbenjamin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dang left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mattbenjamin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cfsnyder commented Oct 5, 2021

mattbenjamin commented Oct 5, 2021

mattbenjamin left a comment

Choose a reason for hiding this comment

cfsnyder commented Oct 5, 2021

cfsnyder commented Oct 26, 2021

mattbenjamin commented Oct 26, 2021

mattbenjamin commented Oct 26, 2021

mattbenjamin commented Oct 26, 2021

mattbenjamin left a comment

Choose a reason for hiding this comment

mattbenjamin left a comment

Choose a reason for hiding this comment

mattbenjamin commented Oct 27, 2021

mattbenjamin commented Oct 28, 2021

cfsnyder commented Oct 29, 2021

mattbenjamin commented Oct 29, 2021

mattbenjamin commented Oct 29, 2021

wjwithagen commented Oct 29, 2021

cbodley commented Oct 31, 2021