Log fiber

[Serpentian]

The related issue is #107. The discussion starts with a description of how the task looks in my understanding. Then I provide my vision of API and behaviour, some insights at internals, open and frequent questions, alternatives, and what I want to do in the future.

Problems with how it works now

A lot of fibers work constantly in background of the vshard's routers and storages (discovery, failover, rebalancer, recovery etc). But there's no way to check their current activity and errors that occured during the fiber's execution other than manual grepping of the logs.

We need to introduce more convenient way of monitoring background fibers and their testing using luatest.

How it should work

The idea is to introduce the module, which is capable of saving logs, states and maybe current activity of the background fibers. The data of such module can be acessed via vshard.router.info() and vshard.storage.info():

tarantool> vshard.router.info()
---
...
fibers:
    vshard.failover._static_router:
        state: good
        activity: idle
        last_messages:
            - 31s I> All replicas are ok
            - 32s I> Failovering step is finished. Schedule next after 1.000000 seconds
            ....
...

The initial purpose of the module is monitoring. So, I think it should be disabled by default in order not to waste space and not to increase the execution time of the fiber step. Moreover, the user will not need all messages forever. I suppose we should introduce a way to configure the number of saved log messages.

API and behavior

The module (let's call it log_fiber) should fulfill such roles:

1. Saving current state of the fiber (fiber state)
2. Saving current activity of the fiber (fiber activity)
3. Saving user-defined number of log messages (fiber event)

I think that every instance (router or storage) should have this module right inside it as an attribute, and initialize or reconfigure it during vshard.router/storage.cfg().

The structure of the log_fiber can be like this:

<log_fiber> = {
    logs = {
        [fiber_name] = {
            state = <string, which shows whether all is good or not>,
            activity = <string, which shows what fiber is doing right now>
            messages = {
                <log_message> = {
                    time = number,
                    level = string,
                    data = string,
                },
            },
        },
    },
    is_enabled = <boolean>
    log_length = <the number of messages saved in 'logs'>
}

As logs[fiber_name].messages we can use heap, which is already written and used in ref's session_heap.

I won't talk about activity field and its API, as I'm not sure that we really need it (see 'Open questions' section).

Fiber state API

Essentially, state would be like vshard.storage.info().status - a simple string which tells whether all is good or bad. It can also be used in cartridge GUI, which could translate the states to colors indicating if there's any kind of error occured in a fiber.

As far as I can see, the only needed function is:

log_fiber:set_state(state)

It should extract the name of the fiber, from which it was invoked via fiber.self().name() and save the state to the storage (under the storage I mean an entry in logs table (see the [structure] (#api-and-behavior) of the module)), which is related to the corresponding fiber.

We could also need a way to get the state of the current fiber, which will do almost the same thing as set_state.

We should not save any state, if the log_fiber is disabled.

Fiber log message API

The module should also be a wrapper around the default log module, used in tarantool, so we should introduce the same API, log has:

log_fiber:error()
log_fiber:warn()
log_fiber:info()
log_fiber:verbose()
log_fiber:debug()

These methods does the following:

1. Get args (just as in the log, it can be formatted string, table (for json format), and any other type, which has __tostring).
2. Call log.info/warn/debug/etc.
3. Collect extra data: time via fiber.clock(), fiber's name, log level.
4. Save all info to logs[fiber_name].messages,

Actions 3-4 are performed only if the log_fiber is enabled and the level of the message is <= than the log_level of the log module.

Basic API

log_fiber:cfg()

log_fiber:cfg(vshard_cfg)

The function for configuring the log_fiber instance. We can introduce new option to vshard.router/storage.cfg(): log_vshard_fiber, which can have a boolean or non-negative number type. It will indicate the following:

• If the option is not set or it's value is false, then messages are just forwarded to the log module, no states are saved - the log_fiber instance is disabled.
• If it's true, then the instance is enabled and default log_length from consts is used.
• If it's a number, the instance is enabled too, but this number is used as log_length.

log_length represents the number of log messages saved for all fibers.

On reconfiguration from enabled state to disabled all logs will be dropped.

log_fiber:drop()

log_fiber:drop(fiber_name)

Drop all info about the fiber the name of which isfiber_name. Sometimes all info about the fiber is needed to be deleted without deleting info about all other ones (e.g. when discovery_mode is changed to off).

log_fiber:get_info()

log_fiber:get_info()

Get a table of all known data in the formatted way. By formatted I mean that the messages should be converted from table:

<log_message> = {
    time = number,
    level = string,
    data = string,
}

to a single string:

31s I> All replicas are ok
<time_ago> <log_level> <data>

See the example in 'How it should work' section.

Module API

log_fiber.new()

Creates the instance of the log_fiber.

Note: all of the above functions are the part of the log_fiber's index metatable, but log_fiber.new() is the function returned by the log_fiber module.

FAQ

log_level is not passed to log_fiber:cfg(). How will we get it?

Yes, we should not save the log message if the level of the message (debug, e.g.) is more than log_level of the log module (it's info e.g.). So we need a way to get log_level from somewhere.

I don't really want to get this option from the user's cfg table, passed to vshard.router/storage.cfg(), as at some day we will drop box.cfg() from the router and there will be only vshard's cfg table passed to vshard.router.cfg with no log_level in it.

We can easily access log_level from the log module with log.cfg.log_level. But in old versions there's no cfg in log, so we can access box.cfg.log_level if box is configured. Overwise, we'll use default log_level, which equals to info.

Open questions

Fiber activity

In addition to the state, we can also save, what the fiber is doing right now: idle, sending buckets etc. I don't think we'll need it and here's the reason why.

The problem out there is that the user will almost always see just the one activity: idle, which is related to the fact, that the console's fiber is executed in the same thread whith all other background fibers and there's not many fiber.yield() (both: explicit and implicit) during the execution of the single fiber step. Only in case of context swap during the step the user can catch the last activity, which was set before this yield.

log_fiber:set_state('first_one')
-- some code without any yields
log_fiber:set_state('second_one')
fiber.yield()

The user cannot get 'first_one' as the fiber doesn't stop its execution before set_state('second_one').

Please, correct me, if I'm wrong.

Fiber state

Basically, there will be two states for every fiber: everything is good or not. Do we really want to make several versions of good state: balanced/good/full e.g. It will lead to harder processing of these states in cartridge e.g.

Maybe we'll be enough with just three states: ok/error/unknown. The last one will represent the state of the fiber, which didn't even make its first step and which doesn't know, if there is some error.

Alternatives

Static log_fiber

We can make log_fiber module to be static and have all loggers to be saved right inside it, and not inside the router and storage instances as an attribute. We can use the last part of the fiber's name (e.g. _static_router) as the name for such loggers. Calling log_fiber.info(...) would extract the name of the corresponding logger from the part of fiber.self().name()and save all info to loggers[log_name].logs[fiber_name].messages/state.

I don't really see any need in implementing it in such way. It looks like unnecessary complication. Moreover, it will require renaming all storage's fibers to be not vshard.rebalancer but vshard.rebalancer.storage or complicating the extracting of the logger name in the log_fiber module.

[Serpentian]

@Gerold103, @olegrok

[Gerold103]

Log fiber

One of the main problems here is in the proposal name - you try to build the monitoring on top of fibers instead of services, modules. It stops working at the moment when something stops being a fiber. For example, take master_search_f fiber in router. It is a fiber only because we don't have box.watch subscriptions on 1.10. In new versions this fiber can be deleted, but we probably still might have some "process" of master discovery working just in netbox callbacks. Never having own context.

Or take rebalancer_f on the storage - we don't necessarily need it as a fiber. It works like once per 1000 years anyway. Its fiber could be deleted and another one could be created on timeout when needed. But between these events there wouldn't be any fiber. Hence whatever we bound to fibers won't survive this.

Or take discovery_f on router - the router has a cfg option to run discovery just once. Then the fiber is terminated. But the discovery process was finished. And still during work some buckets might become unknown, then re-discovered on demand without a dedicated fiber already.

In other words, I don't think we need to rely on having a fiber in any way.

So, I think it should be disabled by default in order not to waste space and not to increase the execution time of the fiber step.

What do you mean? Not have any info by default at all? Or only the last logs?

API and behavior
Saving current state of the fiber (fiber state)

Should better think in terms of a "service state" instead of a "fiber state". One fiber can potentially have many services, and some services can have no fiber at all.

Saving user-defined number of log messages (fiber event)
log_length represents the number of log messages saved for all fibers.
log_fiber:cfg(vshard_cfg)

I think at first it should be fine to have the number hardcoded in vshard.consts. We can expose it if anybody asks explicitly. In tests we still can increase it by changing the constant, but otherwise it should be small, like 5 or something else < 10. Should be just fine. Or maybe even zero tbh. As I was saying, the logs I don't know whether could be displayed anywhere in a user-friendly way. The user-unfriendly way is already there - look at the logs file. The most user-friendly way would be state of the service.

You still can try to add the logs though, I don't insist on dropping them. I just think it a bit complicates the main feature ("state"), which is in turn mainly motivated by tests, where we need to implement wait_rebalancer_state() function from storage_template.lua file but in luatest. Without this function we can't easily test rebalancer in luatest (we could grep logs like the current function does, but it is very ugly).

Another point about the logs is that the name is probably a bit unfortunate too. We don't need to just duplicate the log.info/debug/error/... output here. We can add there more steps or show not all of them. Maybe think of a log-like module not bound to a fiber?

As logs[fiber_name].messages we can use heap, which is already written and used in ref's session_heap.

What do you need heap for? The heap is used for sorting and quick push/pop operation of the max/min item. Here you just have time series data - new messages always come to the last place and old messages are always deleted from the first place. You can simply have a list like in vshard.rlist module. In vshard.router/storage.info() it will have to be copied into a table though. Otherwise people will be able to break it by doing vshard.router.info().some_service.logs[100] = 'broken' or similarly.

log_fiber:get_info()

The idea is to have a single info point - vshard.storage.info() for storage, vshard.router.info() for static router, router:info() for all other explicitly created routers. I wouldn't recommend to complicate it further.

log_level is not passed to log_fiber:cfg(). How will we get it?

As you yourself noted, the value can be taken from box.cfg.log_level on all versions and from log.cfg.log_level on new versions. Note, that box.cfg is not a table until box is configured first time. Sounds good to me. If you still want to do the logs part.

The user cannot get 'first_one' as the fiber doesn't stop its execution before set_state('second_one').

This is correct. But you are missing the fact that we won't show a copy of fiber:status(). We would show activity which can last long. For example, activity type sending buckets can last for hours. Activity type backoff lasts several seconds at least. Or there could be an activity collecting stats in rebalancer when it asks other instances about their bucket statistics to make a decision whether need to start rebalancing. At the same time the service status can be balanced. So it would be {state="balanced", activity="collecting stats"}. Stats collection happens regularly even when there is balance.

I would recommend to collect for each background service what kinds of activities they do and what states they have. Maybe indeed we will be able to just store a state. For tests it would probably be enough.

balanced/good/full e.g. It will lead to harder processing of these states in cartridge e.g.

The problem is that people don't know what rebalancer or any other service is doing right now - did it stop? does it still work? In tests we have the same problem. If the states would be just everything is good or not or ok/error/unknown then how would you define the state "rebalancer sent bucket routes and waits for them being applied"? - is it ok or error or unknown? If it is ok, then how to differentiate it from "everything is balanced"?

Another problem to think about, mostly related to tests. Assume the rebalancer state is 'balanced'. Now we change something and expect the rebalancer to perform rebalancing. It will end up in the same state 'balanced'. But from the outside by just looking at the state we can't tell whether it worked at all. It could be old 'balanced' or it could quickly go through 'applying routes' and back to 'balanced'. Maybe we also need a monotonic number like a "generation" which is updated on every change in 'state'/'activity'. Then we can tell if the services progresses.

@R-omk @olegrok, please, join.

[Serpentian]

In other words, I don't think we need to rely on having a fiber in any way.

I got you. Let's rely on services instead of fibers. In that case we should introduce the API for creating/deleting deleting services: service_log:register_service(), service_log:drop_service().

The user-unfriendly way is already there - look at the logs file.

I agree. I've already written the log-focused module and it's not very convenient to wait for some message to appear in it. But in these logs the user can at least see the reason of the error state. If we drop them, we should introduce 'more extensive' error state with the info about the happened error. I propose to add a new field to the info about the service. So, in code we'll report an error like that:

sevice_log.rebalancer:set_state('error')
service_log.rebalancer:set_error(err_msg)

The user will see:

...
services:
    rebalancer:
         state: "error",
         error: "error message"
...

What do you mean? Not have any info by default at all? Or only the last logs? (about enabling/disabling)

I wanted to expose option to vshard.cfg() in order to give the user the ability to control the number of saved messages and whether to save any logs and states at all. If we don't want to do it right now, I suppose we're going to enable it by default (the user will always see some info about background services). If we drop saving logs, it won't be very space-consuming to have it enabled always.

Another approach is not to enable/disable the module, but to pass some option straight to vshard.router/storage.info(). Some kind of debug mode. We can return info about services only in that case.

What do you need heap for?

Agree, we don't. It's an overhead for sorting of the messages.

The idea is to have a single info point - vshard.storage.info() for storage, vshard.router.info() for static router, router:info() for all other explicitly created routers. I wouldn't recommend to complicate it further.

I don't really think that it's a great idea to parse internal tables of the module right inside vshard.storage/router.info(). This approach breaks encapsulation of the module and leads to the duplication of the code. It seems pretty reasonable for me to have such method in service logger so we can use it like that:

local function router_info(router)
    local state = {
        replicasets = {},
        bucket = {
            available_ro = 0,
            available_rw = 0,
            unreachable = 0,
            unknown = 0,
        },
        alerts = {},
        status = consts.STATUS.GREEN,
        fibers = router.service_log:get_info(),
    }
...

As you yourself noted, the value can be taken from box.cfg.log_level on all versions and from log.cfg.log_level on new versions. Note, that box.cfg is not a table until box is configured first time. Sounds good to me. If you still want to do the logs part.

If we implement more extensive error state, we don't really need logs right inside vshard.router/storage.info(). The user can always see them in files (or any other log service), if he wants to. So we don't need log_level at all. Moreover, if we don't expose option to public API, there's no need for reconfiguration of the module at all (let's not expose to the module's metatable service_log:cfg()).

But you are missing the fact that we won't show a copy of fiber:status(). We would show activity which can last long.

I understood you. Moreover, almost any fiber yields implicitly pretty often due to http requests.
Even though this is not a copy of the fiber:status(), any background service doesn't do anything between fiber steps. So, I suppose that we still need idle activity.

---

The problem is that people don't know what rebalancer or any other service is doing right now - did it stop? does it still work? In tests we have the same problem. If the states would be just everything is good or not or ok/error/unknown then how would you define the state "rebalancer sent bucket routes and waits for them being applied"? - is it ok or error or unknown? If it is ok, then how to differentiate it from "everything is balanced"?

Actually, according to this paragraph concepts of the state and activity looks pretty jumbled.

did it stop? does it still work?

Aren't these ones should be reflected by the activity and not state.

"rebalancer sent bucket routes and waits for them being applied"

It looks like an activity. The state in that case shows was the last fiber iteration successful. And activity would be applying routes. Nobody really knows whether the current iteration of the fiber will be successful or not, I don't think we should show, what the fiber is doing right now in state. Otherwise, it doesn't really differ from an activity.

Essentially, state would be like vshard.storage.info().status - a simple string which tells whether all is good or bad.

First of all, we should define properly state and activity. I agree with your statement in #364, the state should just show whether any error happened during last fiber step. And activity should show what fiber is doing right now: idle/applying routes/sending buckets.

Moreover, state is not really a good name for that: its meaning is so close to activity in some contexts. Maybe we should call it status just like in vshard.storage.info().status

---

Now we change something and expect the rebalancer to perform rebalancing. It will end up in the same state 'balanced'. But from the outside by just looking at the state we can't tell whether it worked at all.

That's indeed is a problem. We can add a new monotonically increasing field state_idx to every service and return it alongside with state and activity.

---

In general it looks like we're moving forward the solution Alexey proposed as a first one in #107.

[Serpentian]

@Gerold103

I don't think that state of the fiber should define in any way what is going on right now (e.g. 'rebalancer sent bucket routes and waits for them being applied'). Let's call it status and this one'll be a string, which shows whether any error occured during the previous fiber step.

Default value for activity/status field is unknown. It's returned when the service haven't set any activity or status yet.

If we define status as I proposed, it'll be the same for every fiber: unknown/error/ok. And as I've already said we should probably save info about errors too. So I'm describing only activities.

Router:

    failover_f:
        activity:
            0. `unknown`
            1. `pinging replicas`
            2. `updating replicas priorities`
            3. `idling`
    P.S. There's no yields after ping round, so we should probably add explicit yield after every loop step 
    of updating repicas (or at least one). Otherwise, we won't be able to see the second activity. We can also
    just not show that activity.

    master_search_f:
        activity:
            0. `unknown`
            1. `locating masters`
            2. `idling`

    discovery_f:
        activity:
            0. `unknown`
            1. `discovering buckets`
            2. `updating route map`
            3. `idling`

Storage:

    collect_bucket_garbage_f:
        activity:
            0. `unknown`
            1. `turning SENT buckets to GARBAGE`
            2. `idling`
    P.S. AFAICS, dropping GARBAGE is done without yield. The user won't be able to see that activity.

    recovery_f:
        activity:
            0. `unknown`
            1. `recovering sending buckets`
            2. `recovering receiving buckets`
            3. `idling`

    rebalancer_f:
        activity:
            0. `unknown`
            1. `downloading states`
            2. `routes applying`
            3. `idling`
            
    rebalancer_applier_f:
        activity:
            0. `inactive`
            1. `waiting for workers to apply routes`
    
    rebalancer_worker_f:
        activity:
            0. `unknown`
            1. `sending bucket with bucket id %d to %s`
            2. `throttling`
    P.S. Let's say that the status is `ok` if by the end of the work no errors were set.

During one fiber step several errors can occur (e.g. in discovery_f first error will be from the map stage, second one - from the reduce stage, in recovery_f errors can occur during recovery of the sending and receiving buckets). What do we want to do in that case? One of possible solutions is to save all errors during one fiber steps. We can also just save the first or last one.

[Gerold103]

I got you. Let's rely on services instead of fibers. In that case we should introduce the API for creating/deleting deleting services: service_log:register_service(), service_log:drop_service().

You are still trying to bind it all to some singleton, it seems. Or I misunderstood. It would just complicate things. You have to "unregister" stuff from the singleton, and it is not always possible. For example, if the de-registration does anything non-trivial, it can raise a Lua exception and leave the state half-valid. Much easier when things are simple Lua objects whose deletion is just M.rebalancer_service = nil. Singletons generally are a bad practice, they introduce implicit dependency on some external global object. Besides, what will happen when multiple routers will try to register their services having the same names? Each router has "discovery" and "failover" - how will they register together from all routers?

:set_state() + :set_error()

Sounds fine, I don't mind.

Another approach is not to enable/disable the module, but to pass some option straight to vshard.router/storage.info(). Some kind of debug mode.

I don't mind returning full info always, but this approach is also fine. Except that the name would need to be better, because in future the info might be extended again and will need another key in this options table. Like vshard.storage.info({with_rebalancer=true}). Or we could go other way and introduce new functions like vshard.storage.info_rebalancer(). Or vshard.storage.info({with_services=true}) / vshard.storage.info_services() to show info about all services at once. I suggest to ask Mons and Vlad G. about the best way.

I don't really think that it's a great idea to parse internal tables of the module right inside vshard.storage/router.info()

I haven't said anything about what is done inside of router/storage.info() though. I only said that the result should include all the info, including about the background services. Or do it like suggested above after consulting Mons and Vlad G.

router.service_log:get_info(),

Sounds fine, I suppose. For sure you shouldn't extract anything manually from private members of this 'service_log' thing if you are doing it as a module.

any fiber yields implicitly pretty often due to http requests

We don't use HTTP in vshard at all though ...

any background service doesn't do anything between fiber steps. So, I suppose that we still need idle activity

We shouldn't think about fiber statuses. Like yes, sure, if 2 service states are passed without yields always, then the first one is not needed at all. But here relation to fiber statuses ends. A service can only be idle if it has literally nothing to do. Not now, and not in the nearest future, and all is fine, and no errors, no backoff state, etc. It is not the same as if the service has a fiber and the fiber is 'suspended' right now. All fibers except the current one are 'suspended' anyway. Such 'idle' metric would be set in all services always then, and would be useless. We might need 'idle' service state, but it shouldn't be == 'suspended' fiber status.

Let's call it status and this one'll be a string, which shows whether any error occured during the previous fiber step.

There is another problem. After an error happened, re-trying it might take several steps which would be successful and the last one would fail with the same error. For example, rebalancer. It can successfully collect stats, decide to rebalance, send routes, one storage throws an exception in rebalancer_apply_routes_f. There were several steps, only the last one failed, but I think we need to keep that error until the the rebalancing succeeds and the rebalancer enters 'idling' state or whatever it is called. Otherwise the error will be oscillating back and forth every few seconds making it hardly possible to use.

Luckily, it shouldn't be too hard to do. Most if not all of the services have their body defined like while (true) step1; step2; step3; success;. So you just have to keep the last happened error until reach "success" point.

failover_f

I would suggest to drop updating replicas priorities activity, because it won't be visible ever. And adding yields just for that makes little sense too - the state would be visible like 1-2ms tops, I don't think anybody would catch that.

discovery_f

If as updating route map you mean discovery_handle_buckets, then it won't be visible either. I suggest to drop this state/activity.

collect_bucket_garbage_f
AFAICS, dropping GARBAGE is done without yield. The user won't be able to see that activity

gc_bucket_drop_xc() has an explicit yield (fiber.sleep(0)) and implicit yields box.commit() in gc_bucket_in_space_xc(). The states I propose to call simpler: 'gc sent', 'gc garbage'.

rebalancer_worker_f

It is not a service. It is just a part of rebalancer applier, one of its fibers, there can be many workers per one storage. I suggest to drop it and keep all in rebalancer_applier_f.

sending bucket with bucket id %d to %s

We can also add progress bar, like "sending bucket %d to %s (%d<sent>/%d<total_to_send>)". Would give people an idea about how long the rebalancing is going to take for each replicaset.

e.g. in discovery_f first error will be from the map stage, second one - from the reduce stage

I think we will have to decide this case by case. Generally having the first error is more interesting. The other errors might be caused by the first one. In the case of discovery I think that on each iteration of the big while loop we have to expose the first happened error. And clear it only after all is discovered.

Another suggestion would be not to use _f suffix. The suffix means a callback function. For service names we would need something more suitable. Like gc, discovery, recovery, rebalancer, route_applier, master_search.

Another comment is that you seem to miss the "backoff" state. It is not same as "idling". The service has something to do, it just can't be done right now. For example, bucket gc can enter backoff state for consts.GC_BACKOFF_INTERVAL seconds if it got an error or not all buckets could be collected due to having refs. Or did you omit this state intentionally?

Last suggestion is to drop 'unknown' status. I can't imagine what a user is supposed to do with this really. Neither we in tests. If it is bad, then what is wrong exactly? If it is good, then why isn't it 'ok'? Might be better to start in 'ok' state to simplify things.

[Serpentian]

You are still trying to bind it all to some singleton, it seems.

I don't want a singleton, but I really want to have only one additional field in M (in case of storage) or router, which will be responsible for storing statuses, activities and errors of all services. It seems cleaner to me, but can be easily changed.

I don't mind returning full info always, but this approach is also fine.

Currently, I decided to go with with_services option as we shouldn't return info about services by default from vshard.storage/router.info(). If we do that, a lot of diff tests, which invokes any of these functions, will become flaky. I'll consult PMs about the preferable API ASAP.

I think we will have to decide this case by case. Generally having the first error is more interesting. The other errors might be caused by the first one. In the case of discovery I think that on each iteration of the big while loop we have to expose the first happened error. And clear it only after all is discovered.

Why don't we save the stack of all occurred errors until everything is good?

We can also add progress bar, like "sending bucket %d to %s (%d/%d<total_to_send>)". Would give people an idea about how long the rebalancing is going to take for each replicaset.

If we move all workers into routes_applier service, then we can't. There's only one activity field and possibly more than one worker. However. we can track full progress via the route dispenser. Do we need that?

Another suggestion would be not to use _f suffix.

I didn't plan to) It was just for convenience of reading.

Another comment is that you seem to miss the "backoff" state.

Added.

Might be better to start in 'ok' state to simplify things.

Sounds reasonable. unknown status is dropped, but the activity is still up there. We don't really know what the service is doing until it sets its activity.

[Serpentian]

Let's also move into PR #364, it's easier to avoid misunderstandings while discussing everything near to the code.

[R-omk]

As for the original idea with setting states, I see some association from the world of kubernetes, where objects can have such concepts as conditions, events, states, etc. https://maelvls.dev/kubernetes-conditions/