Enhance vic-machine to stream a creation log to the VCH's datastore folder

[zjs]

Enhance vic-machine to stream a creation log to the VCH's datastore folder.

As a VCH is created, logs should be written to a file in the VCH's datastore folder.

[zjs]

See "Log Management" in #6124

[AngieCris]

confusions:

Firstly, where to put the creation log
if we want to stream it to VCH's datastore folder, once the vch creation fails, the VCH's datastore folder will be removed, and the log file will be gone as well. in this case, the client can only see the file if the creation succeeds, or if the creation hangs at somewhere before the vch datastore folder is removed. is that what we want?

Secondly, log it real time vs. upload the log file to datastore

1. log it real time
   this is only okay after the VCH's datastore folder is created. is it implementable tho? need to track when the datastore folder is created?
2. upload the local log vic-machine.log file to VCH's datastore folder
   simpler to implement. but again the log would be gone if creation fails

Thirdly, what to do with local log file
do we also want to keep the local creation log as well (vic-machine.log)?
If multiple VCH's are created, all of the logs would be in this single file. if log is streamed to VCH's datastore folder, that will be separate log for each VCH
also if VCH creation fails, the local log is still accessible, so we might want to keep that?

thoughts? @zjs @andrewtchin

[zjs]

Firstly, where to put the creation log?
if we want to stream it to VCH's datastore folder, once the vch creation fails, the VCH's datastore folder will be removed, and the log file will be gone as well. in this case, the client can only see the file if the creation succeeds, or if the creation hangs at somewhere before the vch datastore folder is removed. is that what we want?

I think we it in the VCH's datastore folder. When creation is initiated from the vic-machine CLI, I think it's fine if the log gets cleaned up when a failure occurs.

We'll want to suppress deletion of the log when creation is occurring via the API, but we can track that as a separate issue.

Using the VCH's folder does complicate things, but it simplifies others: we essentially piggyback on the existing RBAC functionality and avoid introducing new persistence requirements.

Secondly, log it real time vs. upload the log file to datastore
there're two ways of logging here:

1. log it real time
   • this is only okay after the VCH's datastore folder is created. is it implementable tho? need to track when the datastore folder is created?
2. upload the local log vic-machine.log file to VCH's datastore folder
   • simpler to implement. but again the log would be gone if creation fails

I think we want to log it in real time. One of the main use cases for this feature is for allowing users of the vSphere client plugin to monitor the creation process, both for VCHs they've created and for VCHs being created by other users (who may be using the vic-machine CLI). Eventually, we even want the log data to live-update in the UI.

You're right that it does complicate the design. Essentially, I think we'll need to buffer log data in-memory until we can write it to the datastore.

I'm not yet familiar with golang logging patterns/libraries, but in most logging libraries I've used there's a way to register some sort of listener/handler for log messages. Sometimes, libraries have some sort of pattern for holding log data in memory until a file is available to write to (e.g., between when the application starts, and when the configuration file is read which says where log data should be written to), so it may be possible to re-use existing functionality.

If we have to implement our own buffering, I think it looks a lot like a producer/consumer problem: calls to the log methods produce log events which need to queued for consumption, and the consumer gets registered and begins consuming once the datastore folder is available.

Thirdly, what to do with local log file
do we also want to keep the local creation log as well (vic-machine.log)?
If multiple VCH's are created, all of the logs would be in this single file. if log is streamed to VCH's datastore folder, that will be separate log for each VCH
also if VCH creation fails, the local log is still accessible, so we might want to keep that?

We want to keep the local creation log. I'd think about this issue as a adding functionality, not replacing anything.

[AngieCris]

Figuring out the design has taken me more time than expected (it took me a few days to get familiar with vic-machine workflow):

1. Multiple layers are involved:
   (1) the cmd layer is responsible for redirecting logs to streams (currently stdout and a local file stream vic-machine.log), and the redirection applies for all vic-machine commands (create, inspect, etc.).
   (2) the management layer is responsible for actually streaming the log real-time to the datastore folder.
2. Suppose the logs are redirected to a reader/writer stream, the writes to the writer stream happen at multiple layers too: the cmd layer and management layer, and it's propagated down. But reads from the correspondent reader stream only happen at management layer, and after the VCH datastore folder is up. So internal buffering is necessary to prevent blocking of concurrent reads and writes.
   Just like @zjs suggested (thanks a lot for the clarification), this is essentially a consumer/producer problem on a buffer of log bytes.
3. The log streaming should apply for all vic-machine commands (currently it does locally in vic-machine.log) so a new package under lib\install must be created to implement our own reader/writer streams with buffering. There could be scenarios where multiple vic-machine processes are running on the same VCH, so the reader/writer must be synchronized in some way

The design I came up with is like this:

1. Redirect vic-machine cmd logs to a writer stream in cmd, and pass the ReadWriter to management layer (as a separate argument all the way from cmd\create to lib\install\management
   It looks kind of ugly...but the redirection of log output happens at cmd level, so I think the ReadWriter stream must be created here, and the writer stream should be set up for log redirection in cmd. Since the read happens sometime later in management layer, it seems propagating the ReadWriter down is the only option. Seeking opinions @emlin
2. In VCH creation logic in management layer, after appliance is created and before image files are uploaded (to ensure the VCH datastore folder is up), upload the reader of the ReadWriter to VCH datastore via govmomi.
3. The writer in ReadWriter simply puts everything in an internal memory buffer no matter what (the logs are just KBs so should be okay to hold), and the reader will grab from the buffer when it's not empty (otherwise EOF).

Does this sound like a good design? (ping Emma for advice @emlin

[mdubya66]

Keep in mind that we support syslogs now as well. @hmahmood added that.

[AngieCris]

@hmahmood can you elaborate on how it works?