#31 Add the time it takes to make a compose to the tickets.
Merged 4 years ago by dustymabe. Opened 4 years ago by cverna.
releng/ cverna/compose-tracker compose_time  into  master

file modified
+5 -15
@@ -1,4 +1,4 @@ 

- FROM registry.fedoraproject.org/fedora:30

+ FROM registry.fedoraproject.org/fedora:31

  

  # set PYTHONUNBUFFERED env var to non-empty string so that our

  # periods with no newline get printed immediately to the screen
@@ -13,31 +13,21 @@ 

  RUN mkdir /work

  WORKDIR /work

  

+ 

+ ADD compose-tracker.toml /work/my_config.toml

  # Copy the fedora config for fedora-messaging and also generate a random UUID

  # https://fedora-messaging.readthedocs.io/en/latest/fedora-broker.html#getting-connected

  # Note this will mean that if there is more than one container running

  # using this image they will be reading from the same queue. Generally

  # I expect this to only be running in one place.

- RUN sed -e "s/[0-9a-f]\{8\}-[0-9a-f]\{4\}-[0-9a-f]\{4\}-[0-9a-f]\{4\}-[0-9a-f]\{12\}/$(uuidgen)/g" /etc/fedora-messaging/fedora.toml > /work/my_config.toml

- 

- # Set the Application Name

- RUN sed -i 's|Example Application|Compose Tracker: https://pagure.io/releng/compose-tracker|' /work/my_config.toml

+ RUN sed -i "s/[0-9a-f]\{8\}-[0-9a-f]\{4\}-[0-9a-f]\{4\}-[0-9a-f]\{4\}-[0-9a-f]\{12\}/$(uuidgen)/g"  /work/my_config.toml

  

  # Lower log levels to WARNING level

  #RUN sed -i 's/INFO/WARNING/' /work/my_config.toml

  

- # Set the log config of compose_tracker

- RUN sed -i 's/\[log_config\]/\[log_config\]\nlevel = "DEBUG"/' /work/my_config.toml

- 

- # Set the format for the log messages

- RUN sed -i 's/format =.*$/format = "%(asctime)s %(levelname)s %(name)s - %(message)s"/' /work/my_config.toml

- 

- # We only care about pungi.compose.status.change messages

- RUN sed -i 's/^routing_keys.*$/routing_keys = ["org.fedoraproject.prod.pungi.compose.status.change"]/' /work/my_config.toml

- 

  # Put compose-tracker into a location that can be imported

  ADD compose_tracker.py /usr/lib/python3.7/site-packages/

  

  # Call fedora-messaging CLI and tell it to use the ComposeTracker

  # class from the compose-tracker module.

- CMD fedora-messaging --conf /work/my_config.toml consume --callback=compose_tracker:Consumer

+ CMD fedora-messaging --conf /work/my_config.toml consume

file modified
+24 -2
@@ -1,6 +1,6 @@ 

  # compose-tracker

  

- Source code that parses pungi logs and opens issues against 

+ Source code that parses pungi logs and opens issues against

  https://pagure.io/releng/failed-composes

  

  # Deploying in Fedora
@@ -33,7 +33,7 @@ 

  oc new-build --strategy=docker https://pagure.io/releng/compose-tracker --to compose-tracker-img

  ```

  

- Export pagure token to use as an env var and then use 

+ Export pagure token to use as an env var and then use

  [kedge](https://github.com/kedgeproject/kedge)

  to get up and running in openshift:

  
@@ -41,3 +41,25 @@ 

  export PAGURE_TOKEN=<pagure_token>

  kedge apply -f kedge.yaml

  ```

+ 

+ # Development Environment

+ 

+ To run compose_tracker's tests on your local machine you need to create a virtual environment

+ 

+ ```

+ $ python -m venv .venv

+ $ source .venv/bin/activate

+ (.venv) $

+ ```

+ 

+ Then you can install the dependencies using the requirements.txt file

+ 

+ ```

+ (.venv) $ pip install -r requirements.txt

+ ```

+ 

+ Finally you can run the tests

+ 

+ ```

+ (.venv) $ py.test test_consumer.py -v

+ ```

file added
+78
@@ -0,0 +1,78 @@ 

+ # A basic configuration for Fedora's message broker

+ #

+ # This file is in the TOML format.

+ amqp_url = "amqps://fedora:@rabbitmq.fedoraproject.org/%2Fpublic_pubsub"

+ callback = "compose_tracker:Consumer"

+ 

+ [tls]

+ ca_cert = "/etc/fedora-messaging/cacert.pem"

+ keyfile = "/etc/fedora-messaging/fedora-key.pem"

+ certfile = "/etc/fedora-messaging/fedora-cert.pem"

+ 

+ [client_properties]

+ app = "compose_tracker"

+ app_url = "https://pagure.io/releng/compose-tracker"

+ 

+ [exchanges."amq.topic"]

+ type = "topic"

+ durable = true

+ auto_delete = false

+ arguments = {}

+ 

+ # Queue names *must* be in the normal UUID format: run "uuidgen" and use the

+ # output as your queue name. If your queue is not exclusive, anyone can connect

+ # and consume from it, causing you to miss messages, so do not share your queue

+ # name. Any queues that are not auto-deleted on disconnect are garbage-collected

+ # after approximately one hour.

+ #

+ # If you require a stronger guarantee about delivery, please talk to Fedora's

+ # Infrastructure team.

+ [queues.00000000-0000-0000-0000-000000000000]

+ durable = false

+ auto_delete = true

+ exclusive = true

+ arguments = {}

+ 

+ [[bindings]]

+ queue = "00000000-0000-0000-0000-000000000000"

+ exchange = "amq.topic"

+ routing_keys = ["org.fedoraproject.prod.pungi.compose.status.change"]

+ 

+ [consumer_config]

+ composes_to_skip = ["IoT"]

+ 

+ [qos]

+ prefetch_size = 0

+ prefetch_count = 25

+ 

+ [log_config]

+ level = "DEBUG"

+ version = 1

+ disable_existing_loggers = true

+ 

+ [log_config.formatters.simple]

+ format = "%(asctime)s %(levelname)s %(name)s - %(message)s"

+ 

+ [log_config.handlers.console]

+ class = "logging.StreamHandler"

+ formatter = "simple"

+ stream = "ext://sys.stdout"

+ 

+ [log_config.loggers.fedora_messaging]

+ level = "INFO"

+ propagate = false

+ handlers = ["console"]

+ 

+ [log_config.loggers.twisted]

+ level = "INFO"

+ propagate = false

+ handlers = ["console"]

+ 

+ [log_config.loggers.pika]

+ level = "WARNING"

+ propagate = false

+ handlers = ["console"]

+ 

+ [log_config.root]

+ level = "ERROR"

+ handlers = ["console"]

file modified
+45 -16
@@ -6,16 +6,16 @@ 

  #  modify it under the terms of the GNU Lesser General Public

  #  License as published by the Free Software Foundation; either

  #  version 2 of the License, or (at your option) any later version.

- # 

+ #

  #  This library is distributed in the hope that it will be useful,

  #  but WITHOUT ANY WARRANTY; without even the implied warranty of

  #  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU

  #  Lesser General Public License for more details.

- # 

+ #

  #  You should have received a copy of the GNU Lesser General Public

  #  License along with this library. If not, see <http://www.gnu.org/licenses/>.

  

- import datetime

+ import datetime as dt

  import fedora_messaging.api

  import json

  import logging
@@ -25,9 +25,12 @@ 

  import sys

  import traceback

  

+ import fedora_messaging.api

+ import fedora_messaging.config

  from ogr import PagureService

  

- # Set local logging 

+ 

+ # Set local logging

  logger = logging.getLogger(__name__)

  logger.setLevel(logging.INFO)

  
@@ -42,7 +45,8 @@ 

  

  # We are processing the org.fedoraproject.prod.pungi.compose.status.change topic

  # https://apps.fedoraproject.org/datagrepper/raw?topic=org.fedoraproject.prod.pungi.compose.status.change&delta=100000

- EXAMPLE_MESSAGE_BODY = json.loads("""

+ EXAMPLE_MESSAGE_BODY = json.loads(

+     """

  {

      "status": "DOOMED",

      "release_type": "ga",
@@ -63,16 +67,16 @@ 

      def __init__(self):

          self.token = os.getenv('PAGURE_TOKEN')

          pagure_domain    = os.getenv('PAGURE_DOMAIN',    DEFAULT_PAGURE_DOMAIN)

-         pagure_namespace = os.getenv('PAGURE_NAMESPACE', DEFAULT_PAGURE_NAMESPACE) 

-         pagure_repo      = os.getenv('PAGURE_REPO',      DEFAULT_PAGURE_REPO) 

+         pagure_namespace = os.getenv('PAGURE_NAMESPACE', DEFAULT_PAGURE_NAMESPACE)

+         pagure_repo      = os.getenv('PAGURE_REPO',      DEFAULT_PAGURE_REPO)

  

          if self.token:

-             logger.info("Using detected token to talk to pagure.") 

+             logger.info("Using detected token to talk to pagure.")

              gitservice = PagureService(

                              token=self.token,

                              instance_url=pagure_domain)

          else:

-             logger.info("No pagure token was detected.") 

+             logger.info("No pagure token was detected.")

              logger.info("This script will run but won't be able to create new issues.")

              gitservice = PagureService(instance_url=pagure_domain)

  
@@ -84,7 +88,8 @@ 

                              namespace=pagure_namespace)

  

          # Used for printing out a value when the day has changed

-         self.date = datetime.date.today()

+         self.date = dt.date.today()

+         self.config = fedora_messaging.config.conf["consumer_config"]

  

      def get_supporting_text(self, lines):

          """ given a log file line determine if it has a koji task ID in it
@@ -152,7 +157,7 @@ 

          status = msg['status']

  

          # Print out a log statement if the day has changed

-         today = datetime.date.today()

+         today = dt.date.today()

          if today != self.date:

              self.date = today

              print('') # get to the next line
@@ -177,9 +182,10 @@ 

  

          # It was requested that we not file issues for IoT composes

          # https://pagure.io/releng/failed-composes/issue/39#comment-591054

-         if 'IoT' in msg['compose_id']:

-             logger.info("Skipping filing issues for IoT composes")

-             return

+         for compose in self.config["composes_to_skip"]:

+             if compose in msg["compose_id"]:

+                 logger.info(f"Skipping filing issues for {compose} composes")

+                 return

  

          # variable to hold description for issue

          content = "[pungi.global.log](%s)\n\n" % logfileurl
@@ -194,9 +200,22 @@ 

              lines = []

              pass

  

+         phases = {}

          for x in range(1, len(lines)):

-             line = lines[x-1][20:]   # trim date off log lines

-             nextline = lines[x][20:] # trim date off log lines

+             linedate = lines[x-1][:19] # keep only the date for each line

+             line = lines[x-1][20:]     # trim date off log lines

+             nextline = lines[x][20:]   # trim date off log lines

+ 

+             r = re.search('.*\[BEGIN\] ---------- PHASE: (\w+) .*', line)

+             if r:

+                 name = r.group(1)

+                 phases[name] = [dt.datetime.fromisoformat(linedate)]

+ 

+             r = re.search('.*\[DONE \] ---------- PHASE: (\w+) .*', line)

+             if r:

+                 name = r.group(1)

+                 phase = phases.get(name)

+                 phase.append(dt.datetime.fromisoformat(linedate))

  

              # If this is a [FAIL] line then we take it and the

              # next line and add them in markdown format. Also grab
@@ -214,6 +233,16 @@ 

                  content+= f'- Compose run failed because: {text}\n'

                  content+= "```\n%s\n```\n" % (line)

  

+         compose_start = dt.datetime.fromisoformat(lines[0][:19])

+         compose_end = dt.datetime.fromisoformat(lines[-1][:19])

+         content+= f"Compose Total time: {compose_end - compose_start}\n"

+         for p in phases:

+             if len(phases[p]) == 2:

+                 phase_start = phases[p][0]

+                 phase_end = phases[p][1]

+                 content+= f"Compose phase {p} time: {phase_end - phase_start}.\n"

+             else:

+                 content+= f"Compose phase {p}: FAILED.\n"

          logger.debug(content)

  

          # pull only part of the compose ID for the label to set

file modified
+7 -4
@@ -1,4 +1,7 @@ 

- requests==2.21.0

- fedora_messaging>=1.7.1

- libpagure>=0.22

- PyYAML==5.1.2

+ requests

+ fedora_messaging

+ ogr

+ PyYAML

+ # Development

+ pytest

+ pytest-mock

file added
+167
@@ -0,0 +1,167 @@ 

+ import copy

+ import json

+ import logging

+ 

+ import pytest

+ import fedora_messaging.api

+ import fedora_messaging.config

+ 

+ from compose_tracker import Consumer

+ 

+ 

+ EXAMPLE_MESSAGE_BODY = json.loads(

+     """

+ {

+     "status": "DOOMED",

+     "release_type": "ga",

+     "compose_label": null,

+     "compose_respin": 0,

+     "compose_date": "20190619",

+     "release_version": "Rawhide",

+     "location": "https://kojipkgs.fedoraproject.org/compose/rawhide/Fedora-Rawhide-20190619.n.0/compose",

+     "compose_type": "nightly",

+     "release_is_layered": false,

+     "release_name": "Fedora",

+     "release_short": "Fedora",

+     "compose_id": "Fedora-Rawhide-20190619.n.0"

+ }

+ """

+ )

+ 

+ EXAMPLE_PUNGI_LOG_DOOMED = """2020-02-04 06:15:09 [INFO    ] [BEGIN] ---------- PHASE: INIT ----------

+ 2020-02-04 06:15:19 [INFO    ] [DONE ] ---------- PHASE: INIT ----------

+ 2020-02-04 06:15:20 [INFO    ] [BEGIN] ---------- PHASE: WEAVER ----------

+ 2020-02-04 06:15:21 [INFO    ] [DONE ] ---------- PHASE: WEAVER ----------

+ 2020-02-04 06:15:21 [INFO    ] [BEGIN] ---------- PHASE: CREATEISO ----------

+ 2020-02-04 06:35:39 [ERROR   ] Compose run failed: ImageBuild task failed: 41350838. See /mnt/koji/compose/cloud/Fedora-Cloud-30-20200204.0/logs/aarch64-ppc64le-s390x-x86_64/imagebuild-Cloud-Cloud_Base-qcow2-raw-xz.aarch64-ppc64le-s390x-x86_64.log for more details.

+ 2020-02-04 06:35:39 [ERROR   ] Extended traceback in: /mnt/koji/compose/cloud/Fedora-Cloud-30-20200204.0/logs/global/traceback.global.log

+ """

+ 

+ EXAMPLE_PUNGI_LOG_INCOMPLETE = """2020-02-04 05:59:24 [INFO    ] [BEGIN] ---------- PHASE: OSTREE ----------

+ 2020-02-04 06:03:08 [ERROR   ] [FAIL] Ostree (variant Silverblue, arch x86_64) failed, but going on anyway.

+ 2020-02-04 06:03:08 [ERROR   ] Runroot task failed: 41350821. See /mnt/koji/compose/rawhide/Fedora-Rawhide-20200204.n.0/logs/x86_64/Silverblue/ostree-1/runroot.log for more details.

+ 2020-02-04 06:03:40 [ERROR   ] [FAIL] Ostree (variant Silverblue, arch ppc64le) failed, but going on anyway.

+ 2020-02-04 06:03:40 [ERROR   ] Runroot task failed: 41350822. See /mnt/koji/compose/rawhide/Fedora-Rawhide-20200204.n.0/logs/ppc64le/Silverblue/ostree-2/runroot.log for more details.

+ 2020-02-04 06:04:44 [INFO    ] [DONE ] ---------- PHASE: OSTREE ----------

+ """

+ 

+ 

+ def test_consumer_message_process(mocker, caplog):

+     "Test that we can successfully process a message"

+     mocker.patch("compose_tracker.PagureService")

+     req = mocker.patch("compose_tracker.requests.get", autospec=True)

+     text_mock = mocker.MagicMock()

+     text_mock.text.splitlines.return_value = EXAMPLE_PUNGI_LOG_DOOMED.splitlines()

+     req.return_value = text_mock

+     mocker.patch(

+         "compose_tracker.fedora_messaging.config.conf",

+         fedora_messaging.config.conf.load_config("compose-tracker.toml"),

+     )

+     con = Consumer()

+     msg = fedora_messaging.api.Message(

+         topic="org.fedoraproject.prod.pungi.compose.status.change", body=EXAMPLE_MESSAGE_BODY,

+     )

+     con.process(msg)

+     assert "Fedora-Rawhide-20190619.n.0 DOOMED" in caplog.text

+ 

+ 

+ def test_consumer_settings_ignore_compose(mocker, caplog):

+     "Test that we ignore the composes specified in the settings"

+     mocker.patch("compose_tracker.PagureService")

+     mocker.patch("compose_tracker.requests")

+     mocker.patch(

+         "compose_tracker.fedora_messaging.config.conf",

+         {"consumer_config": {"composes_to_skip": ["IoT"]}},

+     )

+     con = Consumer()

+     body = copy.copy(EXAMPLE_MESSAGE_BODY)

+     body["compose_id"] = "Fedora-IoT-20190619.n.0"

+     msg = fedora_messaging.api.Message(

+         topic="org.fedoraproject.prod.pungi.compose.status.change", body=body,

+     )

+     con.process(msg)

+     assert "Skipping filing issues for IoT composes" in caplog.text

+ 

+ 

+ def test_consumer_settings_ignore_compose_2_values(mocker, caplog):

+     "Test that we ignore the composes specified in the settings with 2 values"

+     mocker.patch("compose_tracker.PagureService")

+     mocker.patch("compose_tracker.requests")

+     mocker.patch(

+         "compose_tracker.fedora_messaging.config.conf",

+         {"consumer_config": {"composes_to_skip": ["IoT", "Rawhide"]}},

+     )

+     con = Consumer()

+     msg = fedora_messaging.api.Message(

+         topic="org.fedoraproject.prod.pungi.compose.status.change", body=EXAMPLE_MESSAGE_BODY,

+     )

+     con.process(msg)

+     assert "Skipping filing issues for Rawhide composes" in caplog.text

+ 

+ 

+ def test_consumer_ignore_good_composes(mocker, caplog):

+     "Test that we ignore the composes that finished correctly"

+     mocker.patch("compose_tracker.PagureService")

+     mocker.patch("compose_tracker.requests")

+     mocker.patch(

+         "compose_tracker.fedora_messaging.config.conf",

+         fedora_messaging.config.conf.load_config("compose-tracker.toml"),

+     )

+     con = Consumer()

+     body = copy.copy(EXAMPLE_MESSAGE_BODY)

+     body["status"] = "FINISHED"

+     msg = fedora_messaging.api.Message(

+         topic="org.fedoraproject.prod.pungi.compose.status.change", body=body,

+     )

+     con.process(msg)

+     assert "Fedora-Rawhide-20190619.n.0" not in caplog.text

+ 

+ 

+ def test_consumer_logfile_time_parsing(mocker, caplog):

+     "Test that the consumer correctly parses the time a compose takes"

+ 

+     mocker.patch("compose_tracker.PagureService")

+ 

+     # set logs at DEBUG and capture this level

+     caplog.set_level(logging.DEBUG)

+     mocker.patch("compose_tracker.logger.level", logging.DEBUG)

+ 

+     # mock the pungi.global.log file

+     req = mocker.patch("compose_tracker.requests.get", autospec=True)

+     text_mock = mocker.MagicMock()

+     text_mock.text.splitlines.return_value = EXAMPLE_PUNGI_LOG_DOOMED.splitlines()

+     req.return_value = text_mock

+ 

+     con = Consumer()

+     msg = fedora_messaging.api.Message(

+         topic="org.fedoraproject.prod.pungi.compose.status.change", body=EXAMPLE_MESSAGE_BODY,

+     )

+     con.process(msg)

+     assert "- Compose run failed because: - [41350838]" in caplog.text

+     assert "Compose Total time: 0:20:30" in caplog.text

+     assert "Compose phase INIT time: 0:00:10." in caplog.text

+     assert "Compose phase CREATEISO: FAILED." in caplog.text

+ 

+ 

+ def test_consumer_logfile_parsing_failures(mocker, caplog):

+     "Test that the consumer correctly parses the failures of a compose"

+ 

+     mocker.patch("compose_tracker.PagureService")

+ 

+     # set logs at DEBUG and capture this level

+     caplog.set_level(logging.DEBUG)

+     mocker.patch("compose_tracker.logger.level", logging.DEBUG)

+ 

+     # mock the pungi.global.log file

+     req = mocker.patch("compose_tracker.requests.get", autospec=True)

+     text_mock = mocker.MagicMock()

+     text_mock.text.splitlines.return_value = EXAMPLE_PUNGI_LOG_INCOMPLETE.splitlines()

+     req.return_value = text_mock

+ 

+     con = Consumer()

+     msg = fedora_messaging.api.Message(

+         topic="org.fedoraproject.prod.pungi.compose.status.change", body=EXAMPLE_MESSAGE_BODY,

+     )

+     con.process(msg)

+     assert "Ostree (variant Silverblue, arch x86_64) failed, but going on anyway." in caplog.text

+     assert "Ostree (variant Silverblue, arch ppc64le) failed, but going on anyway." in caplog.text

This commits add the total time of a compose and the time for each phases of a compose in the ticket created.

This is committed on top of #28 since it introduced the unit test framework

It looks like this test will start failing if we remove skipping of IoT from the configuration file. It feels like we should inject that value here like {"consumer_config": {"composes_to_skip": ["IoT"]}}, instead of relying on that setting in the config file

took FAILED is awkward. reword?

how about we say Compose phase {p} time: instead of "took"

why don't we move this back to the top and just add another variable.. so at the top we have:

linedate = lines[x-1][:19]
line = lines[x-1][20:]   # trim date off log lines
nextline = lines[x][20:] # trim date off log lines

and then you can use dt.datetime.fromisoformat(linedate) in the two calls above

@cverna - a few comments from me above ^^

nice work - and thanks for doing this.

Yes, I used at during development to make sure that the config file was valid and that I could access the value in it. But I agree it would be better to just mock it so I have changed it :-).

2 new commits added

  • Add the time it takes to make a compose to the tickets.
  • Skip tickets for specific composes.
4 years ago

2 new commits added

  • Add the time it takes to make a compose to the tickets.
  • Skip tickets for specific composes.
4 years ago

@dustymabe I have addressed your comments. Thanks for the review :smile:

@cverna - this LGTM

Since we are moving to Fedora 31 we need to "redeploy" the app to get a new imagestream.

What do you think about trying your hand at deploying this app to stage and then to prod openshift?
https://lists.fedoraproject.org/archives/list/infrastructure@lists.fedoraproject.org/message/DR53T4YLQ57DHWWY64EU3BOALIXALBFE/

@cverna - this LGTM
Since we are moving to Fedora 31 we need to "redeploy" the app to get a new imagestream.
What do you think about trying your hand at deploying this app to stage and then to prod openshift?
https://lists.fedoraproject.org/archives/list/infrastructure@lists.fedoraproject.org/message/DR53T4YLQ57DHWWY64EU3BOALIXALBFE/

Works for me :thumbsup:

can you merge this?

Nope I don't have the correct permissions.

Pull-Request has been merged by dustymabe

4 years ago

gave you write access to the repo too!