Rclone RC: New Operation to Receive Log Output

Dev Discussions
1

While exploring the RC API (especially via librclone), I've seen @ncw mention several times that librclone really needs a way to stream results back to a caller on-demand.

Would this approach be useful?

Proposal

  1. rclone RC accepts a Bool parameter named --rc-cache-log and, when true, rclone stores a running list of every log message that it WOULD have written to stdout or stderr for a given operation (copy, sync, etc.)

  2. A new API endpoint gets added: core/log. This would function like core/stats; it simply returns all the log messages that have been cached up to that point. Then, it clears the cache.

  3. Optionally, a core/reset-log endpoint could be added to clear the log message cache without sending the messages. And perhaps a --rc-cache-log-limit parameter to specify the maximum number of cached entries with a reasonable default, such as 1,000.

Advantages

  1. The logging system already supports JSON output, which is what the RC API requires. So the return of core/log would be an array of JSON objects, each of which is a log message exactly as it would have appeared in a Terminal when --use-json-log is passed.

  2. The on-demand nature of the core/log operation ensures that rclone does not waste time/resources broadcasting messages when the client doesn't care (maybe the UI isn't on screen, so we don't need to update a live list of log messages; we can delay getting them until the app is in the foreground again—an important consideration because 90% of a backup app's life is spent running in the background with no UI.)

  3. Because the behavior is opt-in, there is no effect on existing users or configs.

Disadvantages

  1. To be useful, any operation launched via librclone would have to be _async. But that's recommended anyway.

  2. Memory, obviously. Caching the log messages requires RAM. I don't know how quickly the footprint would grow because I don't know how much overhead is involved in the logging system. I also realize Go is a garbage-collected language and if, say, 10,000 messages all get marked for collection at once, I don't know what that performance hit is—I'm not very familiar with Go.

Alternatives

  1. Function Pointers. It looks like Go supports them, so I think the func RPC(method string, input string) (output string, status int) API in librclone could be expanded to accept a pointer to a function to be called with log output. But you give up the "on-demand" advantage and use resources at all times. If the client developer is dumb, you could also have log-handler functions that lag and tie up rclone in the process. You keep the memory footprint low, though.

  2. Websockets. If the RPC(...) method accepted a websocket address, you could chuck all the output to that. There's some security concerns, but I suppose you could upgrade to wss:// to solve that. Websockets would be pretty reliable if both ends are on the local machine; but this approach involves more overhead and developer work than function pointers or the original proposal. (Websockets are a pain to work with from C and librclone is quite pleasant in C currently.)

Anyone have thoughts on this before I take a swing in one direction or another?

2

I have fully understood all about it thanks to the way things have been explained here. Thanks!

3

Indeed!

I think a flag for this probably isn't necessary. We could turn it on in the rc if needed, or maybe it can be on all the time.

If there are multiple users of the log this won't work particularly well. Perhaps this needs an optional parameter - fetch logs from number N, and number each log.

Yes something like that would be needed.

All good!

The idea I've been mulling over in my mind is this...

We attach a logger to the ctx variable rclone passes about. When logs are required to be made we log them to the logger in the ctx. This would enable the API to attach its own logger and ultimately mean that any logs which were created for a given API request could be returned with that API request which would be neat.

However it would require adding a ctx parameter to all the logging statements. There are 1800 of these so it isn't a small undertaking! And many of them would be called where there isn't a ctx available so this would mean threading ctx through hundreds of functions.

So that would be good but hard work!

Its also somewhat orthogonal to your proposal - we could have both.

I don't think it would take a lot of RAM - maybe 1k per log message so 1M for 1,000.

This is essentially the ctx idea above, but you'd attach the function pointer to the ctx not pass it to every function.

I know very little about websockets and I don't want to tie the API to HTTP specific methods.

The log buffer should be a slice of something like

struct {
    logLevel LogLevel
    out string
    fields logrus.Fields
}

Might need the time in there too!

New ones should be chucked on the end with logEntries = append(logEntries, newLogEntry) and when it is too long, old ones should be cut off the front with logEntries = logEntries[1:]. Go deals well with this pattern. The total number of logs added should be counted up to make the index.

The actual code will need to be indirected through a function pointer which is initialised at runtime otherwise there will be circular imports. See fs.LogPrint for an example of this. The Actual code should probably be in fs/rc and it should override the fs.StoreLog method (say).

1 Like
4

@ncw Thanks for the input! The logger on ctx sounds promising, but that doesn’t solve the issue of getting output in real-time as librclone runs an _async task, does it?

When the RPC() call returns immediately after launching the job, there would not yet BE any log messages to return. And when the job finishes sometime (potentially DAYS later), the function has already returned.

So, unless I misunderstand, we have two options for making librclone report real-time output (log messages):

  1. Set up an API as proposed above, where the client calls in periodically to fetch available log messages.

  2. Have the client pass in, during the initial RPC() call, a pointer to a function that rclone should call each time there is a log message to be handled.

It sounds like always caching the last 1,000 entries (with an option to increase that limit) is fine—the expected memory use would be about 1MB.

What if the log messages were handled like transfers? Store the messages on a per-job or per-group basis and allow the client to fetch only those messages for a particular job/group?

As for concurrent users: I think the “per-job” approach solves most of this (how likely is it multiple clients are interested in the output of a single job?) but the core/log operation could also take a parameter to specify whether the cached messages are purged after being sent. This would allow clients to keep the messages around if they needed to stay in the cache for other clients, etc.

5

No it doesn't.

That would require the ctx propagation changes above.

Its probably more likely a single client submitting multiple jobs in parallel.

I see a core/log being useful to get logging out to users. The ctx changes could be done after and would provide a different benefit.

So I'm in favour of a simple implementation of core/log it would be useful.

6

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.