Print more log messages to enable tracking of SLIs

[ochosi]

In order to track service level indicators, we need to print more logs.

For the Koji Hub plugin, this means we print a message each time a request is received by the plugin. A second log message is printed once the task has been successfully created in Koji Hub's database. This also will allow us to measure the time it takes for Koji Hub to insert a task into its database.
Example messages:

[Tue Nov 15 19:43:05.996844 2022] [wsgi:error] [pid 17:tid 55] [remote 10.89.0.1:38666] 996 [INFO] m=None u=None p=17 r=?:? koji.plugins: Create osbuildImage task
[...]
[Tue Nov 15 19:43:06.003731 2022] [wsgi:error] [pid 17:tid 55] [remote 10.89.0.1:38666] 2022-11-15 19:43:06,003 [INFO] m=osbuildImage u=kojiadmin p=17 r=10.89.0.1:38666 koji.plugins: osbuildImage task 3 added to database

For the Koji Builder plugin we print a log message once a task has been received. We print a second log message once composer returns a compose id. This means the plugin completed one iteration successfully.

These logs are ingested into Splunk. In a dashboard we can then track the two subsequent requests and the duration between them.

As the newer version of pylint available in Fedora 37 that was just released fails with the current code base, I pinned the container so this can be addressed in a separate, subsequent PR.

[thozza]

Changes look good to me. I added one nitpick and have one more general comment, although I think that you were trying to keep the changes as minimal as possible.

Since you added the names logger in the hub plugin, I winder whether it wouldn't be better to rework the builder plugin to also get and use a logger with the same name, instead of using self.logger.info() directly... 🤔

[ochosi]

Changes look good to me. I added one nitpick and have one more general comment, although I think that you were trying to keep the changes as minimal as possible.

Indeed.

Since you added the names logger in the hub plugin, I winder whether it wouldn't be better to rework the builder plugin to also get and use a logger with the same name, instead of using self.logger.info() directly... thinking

That might make sense!
At the same time we are most likely the only ones ever interested in these logs and as far as I can tell they are unique enough to enable easy matching.

[thozza]

LGTM, although I would still use the named logger in the builder plugin just for the sake of consistency 😇

[teg]

Love this, thanks @ochosi !

Will this allow us to measure end to end success ratio in the builder (and the hub for that matter), i.e. not only that the build was started successfully but that it completed with success?

[ochosi]

Love this, thanks @ochosi !

Will this allow us to measure end to end success ratio in the builder (and the hub for that matter), i.e. not only that the build was started successfully but that it completed with success?

If a compose id is returned we assume that the compose worked, yes. There is no further evidence about the state of the compose in koji-osbuild, as far as I can tell. The rest would be in composer. We can hopefully somehow plot this side-by-side though, even if we cannot combine the metrics.

In the hub we can only measure if the (valid) requests that come in were correctly added to Koji's database, cause that's really all the hub plugin does. (It validates the json and then creates a task in the db.)

[ochosi]

I apologize for the many force pushes. I hope the PR is ok now.

[teg]

If a compose id is returned we assume that the compose worked, yes. There is no further evidence about the state of the compose in koji-osbuild, as far as I can tell. The rest would be in composer. We can hopefully somehow plot this side-by-side though, even if we cannot combine the metrics.

Well, there is

koji-osbuild/plugins/builder/osbuild.py

Line 722 in 741be47

self.logger.info("Compose result: %s", status.status)

, no? That would allow us to track the successful composes (rather than the successful starts). That's already logged though, so not relevant to this PR.

[ochosi]

Well, there is

koji-osbuild/plugins/builder/osbuild.py

Line 722 in 741be47

self.logger.info("Compose result: %s", status.status)

, no? That would allow us to track the successful composes (rather than the successful starts). That's already logged though, so not relevant to this PR.

Very true, that's already appearing in the Splunk logs. The idea of tracking the compose id as service level indicator separately is that we cannot guarantee that the compose will be successful. It seems interesting and worth tracking, but it is (as far as I understand this) not directly related to the plugin's functionality.
What we can track for the performance of the plugin itself is whether the builder plugin submits composes correctly to composer.

[gicmo]

👍

[teg]

Very true, that's already appearing in the Splunk logs.

Perfect :)

The idea of tracking the compose id as service level indicator separately is that we cannot guarantee that the compose will be successful. It seems interesting and worth tracking, but it is (as far as I understand this) not directly related to the plugin's functionality.
What we can track for the performance of the plugin itself is whether the builder plugin submits composes correctly to composer.

I think we should track both. If the "outer" SLI fails it will be down to either the "inner" one or composer so good to have the possibility of digging deeper. But I think the interesting thing to measure is the overall success rate, whether issues are due to the plugin or our dependencies.

[gicmo]

We also have a Retry adaptor on the http class, I was wondering if it might make sense to track the number of retries here too.

[ochosi]

We also have a Retry adaptor on the http class, I was wondering if it might make sense to track the number of retries here too.

That sounds like a very good idea. I wonder if the retries are already logged in some way or if we have to log them explicitly.

[teg]

We also have a Retry adaptor on the http class, I was wondering if it might make sense to track the number of retries here too.

That sounds like a very good idea. I wonder if the retries are already logged in some way or if we have to log them explicitly.

@diaasami was tracking retries at some point, not sure if these are the same ones though.

[diaasami]

@diaasami was tracking retries at some point.

Yes, these are still being tracked and the frequency has decreased a lot, we have a week without a single retry every few weeks.

not sure if these are the same ones though.

They are not, the retries in koji-osbuild are retries in the connection to composer, while the ones in the workers (that I added) are retries while authenticating or uploading the image to koji.